Bug 1060510
| Summary: | [vdsm] [log] Some vdsm loggers are filtered out of vdsm.log | ||||||
|---|---|---|---|---|---|---|---|
| Product: | [Retired] oVirt | Reporter: | Gadi Ickowicz <gickowic> | ||||
| Component: | vdsm | Assignee: | Dima Kuznetsov <dkuznets> | ||||
| Status: | CLOSED CURRENTRELEASE | QA Contact: | Pavel Stehlik <pstehlik> | ||||
| Severity: | high | Docs Contact: | |||||
| Priority: | unspecified | ||||||
| Version: | 3.4 | CC: | acathrow, bazulay, gickowic, gklein, iheim, mgoldboi, nlevinki, oourfali, ybronhei, yeylon | ||||
| Target Milestone: | --- | Keywords: | Regression | ||||
| Target Release: | 3.4.1 | ||||||
| Hardware: | Unspecified | ||||||
| OS: | Unspecified | ||||||
| Whiteboard: | infra | ||||||
| Fixed In Version: | Doc Type: | Bug Fix | |||||
| Doc Text: | Story Points: | --- | |||||
| Clone Of: | Environment: | ||||||
| Last Closed: | 2014-05-08 13:35:34 UTC | Type: | Bug | ||||
| Regression: | --- | Mount Type: | --- | ||||
| Documentation: | --- | CRM: | |||||
| Verified Versions: | Category: | --- | |||||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||
| Embargoed: | |||||||
| Attachments: |
|
||||||
Can you please open a bug per log item you think should not be filtered. Otherwise this bug will not converge, it's too generic I think that when logging level is at DEBUG, I expect every call to logging that is seen in vdsm code to be logged. However, this is currently not happening. The reason for this is explained in gerrit patch 23924 http://gerrit.ovirt.org/#/c/23924/) This is an automated message. Re-targeting all non-blocker bugs still open on 3.4.0 to 3.4.1. This is an automated message oVirt 3.4.1 has been released: * should fix your issue * should be available at your local mirror within two days. If problems still persist, please make note of it in this bug report. |
Created attachment 858205 [details] vdsm logs Description of problem: Some VDSM loggers are not logging messages to vdsm log even though logging level is DEBUG. For example, messages regarding sanlock hostId/cluster lock are not visible in the log: Thread-66931::INFO::2014-01-30 15:27:40,171::logUtils::44::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='36263611-ae52-4e2d-90cb-0b5629f99555', hostID=1, msd Thread-66931::INFO::2014-01-30 15:27:40,173::sp::133::Storage.StoragePool::(setBackend) updating pool 36263611-ae52-4e2d-90cb-0b5629f99555 backend from type NoneType instance 0x Thread-66931::INFO::2014-01-30 15:27:40,174::sp::618::Storage.StoragePool::(connect) Connect host #1 to the storage pool 36263611-ae52-4e2d-90cb-0b5629f99555 with master domain: Thread-66931::DEBUG::2014-01-30 15:27:40,175::iscsi::393::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds Thread-66931::DEBUG::2014-01-30 15:27:40,175::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None) Thread-66931::DEBUG::2014-01-30 15:27:40,221::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None) Thread-66931::DEBUG::2014-01-30 15:27:40,830::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0 Thread-66931::DEBUG::2014-01-30 15:27:40,840::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] i Thread-66931::DEBUG::2014-01-30 15:27:41,196::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0 Thread-66931::DEBUG::2014-01-30 15:27:41,198::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with LvMetadataRW backend Thread-66931::DEBUG::2014-01-30 15:27:41,201::blockSD::336::Storage.Misc.excCmd::(readlines) '/bin/dd iflag=direct skip=0 bs=2048 if=/dev/454354bd-d1df-49d4-b509-b2110286c3d5/me Thread-66931::DEBUG::2014-01-30 15:27:41,212::blockSD::336::Storage.Misc.excCmd::(readlines) SUCCESS: <err> = '1+0 records in\n1+0 records out\n2048 bytes (2.0 kB) copied, 0.000 Thread-66931::DEBUG::2014-01-30 15:27:41,212::misc::287::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '2048 bytes (2.0 kB) copied, 0.00067146 s, 3. Thread-66931::DEBUG::2014-01-30 15:27:41,212::persistentDict::234::Storage.PersistentDict::(refresh) read lines (LvMetadataRW)=[] Thread-66931::WARNING::2014-01-30 15:27:41,212::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is Thread-66931::DEBUG::2014-01-30 15:27:41,213::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with VGTagMetadataRW backend Thread-66931::DEBUG::2014-01-30 15:27:41,215::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] i Thread-66931::DEBUG::2014-01-30 15:27:41,495::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0 Thread-66931::DEBUG::2014-01-30 15:27:41,497::persistentDict::234::Storage.PersistentDict::(refresh) read lines (VGTagMetadataRW)=['LEASETIMESEC=60', 'VERSION=3', 'TYPE=ISCSI', Thread-66931::INFO::2014-01-30 15:27:41,499::sd::374::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 454354bd-d1df-49d4-b509-b2110286c3d5_imageNS alread Thread-66931::INFO::2014-01-30 15:27:41,499::sd::382::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 454354bd-d1df-49d4-b509-b2110286c3d5_volumeNS alrea Thread-66931::INFO::2014-01-30 15:27:41,499::blockSD::456::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 454354bd-d1df-49d4-b509-b2110286c3d5_lvmActiva Thread-66931::DEBUG::2014-01-30 15:27:41,499::sp::1366::Storage.StoragePool::(setMasterDomain) Master domain 454354bd-d1df-49d4-b509-b2110286c3d5 verified, version 1 Thread-66931::DEBUG::2014-01-30 15:27:41,502::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] i Thread-66931::DEBUG::2014-01-30 15:27:41,783::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0 Thread-66931::DEBUG::2014-01-30 15:27:41,785::persistentDict::234::Storage.PersistentDict::(refresh) read lines (VGTagMetadataRW)=['LEASETIMESEC=60', 'VERSION=3', 'TYPE=ISCSI', Thread-66931::INFO::2014-01-30 15:27:41,786::domainMonitor::99::Storage.DomainMonitor::(startMonitoring) Start monitoring 454354bd-d1df-49d4-b509-b2110286c3d5 Thread-66931::DEBUG::2014-01-30 15:27:41,787::sp::1395::Storage.StoragePool::(updateMonitoringThreads) Storage Pool `36263611-ae52-4e2d-90cb-0b5629f99555` started monitoring dom Thread-66933::DEBUG::2014-01-30 15:27:41,787::domainMonitor::165::Storage.DomainMonitorThread::(_monitorLoop) Starting domain monitor for 454354bd-d1df-49d4-b509-b2110286c3d5 Thread-66933::DEBUG::2014-01-30 15:27:41,790::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgck --config " devices { preferred_names = [\\"^/dev/mapper/\\"] Thread-66931::DEBUG::2014-01-30 15:27:41,803::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] i Thread-66933::DEBUG::2014-01-30 15:27:42,007::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0 Thread-66933::DEBUG::2014-01-30 15:27:42,028::blockSD::605::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/454354bd-d1df-49d4-b509-b2110286c3d5/metadata bs=40 Thread-66933::DEBUG::2014-01-30 15:27:42,045::blockSD::605::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0. Thread-66933::DEBUG::2014-01-30 15:27:42,048::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] i Thread-66931::DEBUG::2014-01-30 15:27:42,075::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0 Thread-66931::DEBUG::2014-01-30 15:27:42,077::persistentDict::234::Storage.PersistentDict::(refresh) read lines (VGTagMetadataRW)=['LEASETIMESEC=60', 'VERSION=3', 'TYPE=ISCSI', Thread-66931::DEBUG::2014-01-30 15:27:42,079::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] i Thread-66933::DEBUG::2014-01-30 15:27:42,318::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0 Thread-66933::DEBUG::2014-01-30 15:27:42,326::domainMonitor::247::Storage.DomainMonitorThread::(_monitorDomain) Domain 454354bd-d1df-49d4-b509-b2110286c3d5 changed its status to Thread-66934::DEBUG::2014-01-30 15:27:42,328::misc::884::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Emitting event Thread-66934::DEBUG::2014-01-30 15:27:42,328::misc::894::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Calling registered method `contEIOVms` Thread-66934::DEBUG::2014-01-30 15:27:42,330::misc::904::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Event emitted Thread-66935::INFO::2014-01-30 15:27:42,341::clientIF::126::vds::(contEIOVms) vmContainerLock acquired Thread-66931::DEBUG::2014-01-30 15:27:42,406::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0 Thread-66931::WARNING::2014-01-30 15:27:42,411::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt/blockSD/454354bd-d1df-49d4-b509-b2110286c3d5/images alre Thread-66931::WARNING::2014-01-30 15:27:42,411::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt/blockSD/454354bd-d1df-49d4-b509-b2110286c3d5/dom_md alre Thread-66931::INFO::2014-01-30 15:27:42,412::sp::1104::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/blockSD/454354bd-d1df-49d4-b509-b2110286c3d5 to /r Thread-66931::INFO::2014-01-30 15:27:42,412::sp::1104::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/blockSD/454354bd-d1df-49d4-b509-b2110286c3d5 to /r Thread-66931::DEBUG::2014-01-30 15:27:42,417::storage_mailbox::86::Storage.Misc.excCmd::(_mboxExecCmd) '/bin/dd if=/rhev/data-center/36263611-ae52-4e2d-90cb-0b5629f99555/masters Thread-66931::DEBUG::2014-01-30 15:27:42,708::storage_mailbox::86::Storage.Misc.excCmd::(_mboxExecCmd) SUCCESS: <err> = '8+0 records in\n8+0 records out\n4096 bytes (4.1 kB) cop Thread-66931::INFO::2014-01-30 15:27:42,709::storage_mailbox::387::Storage.MailBox.HsmMailMonitor::(_sendMail) HSM_MailMonitor sending mail to SPM - ['/bin/dd', 'of=/rhev/data-c Thread-66931::DEBUG::2014-01-30 15:27:42,753::storage_mailbox::86::Storage.Misc.excCmd::(_mboxExecCmd) '/bin/dd of=/rhev/data-center/36263611-ae52-4e2d-90cb-0b5629f99555/masters Thread-66931::DEBUG::2014-01-30 15:27:43,764::storage_mailbox::86::Storage.Misc.excCmd::(_mboxExecCmd) SUCCESS: <err> = '8+0 records in\n8+0 records out\n4096 bytes (4.1 kB) cop Thread-66931::DEBUG::2014-01-30 15:27:43,765::storage_mailbox::209::Storage.Mailbox.HSM::(__init__) HSM_MailboxMonitor created for pool 36263611-ae52-4e2d-90cb-0b5629f99555 Thread-66931::DEBUG::2014-01-30 15:27:43,766::sp::460::Storage.StoragePool::(__createMailboxMonitor) HSM mailbox ready for pool 36263611-ae52-4e2d-90cb-0b5629f99555 on master do Thread-66931::INFO::2014-01-30 15:27:43,767::logUtils::47::dispatcher::(wrapper) Run and protect: connectStoragePool, Return response: True Version-Release number of selected component (if applicable): 4.14.0-21.git54cc674.el6 How reproducible: 100% Actual results: Not all logs that are called from vdsm code are visible in vdsm log Expected results: If logging is set to DEBUG vdsm log should show all logs Additional info: