Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 2076545

Summary: Mailbox logs are too noisy, no way to silence them
Product: [oVirt] vdsm Reporter: Nir Soffer <nsoffer>
Component: GeneralAssignee: Nir Soffer <nsoffer>
Status: CLOSED CURRENTRELEASE QA Contact: sshmulev
Severity: medium Docs Contact:
Priority: unspecified    
Version: 4.50.0.11CC: ahadas, bugs, michal.skrivanek
Target Milestone: ovirt-4.5.0Flags: pm-rhel: ovirt-4.5?
michal.skrivanek: exception+
Target Release: 4.50.0.13   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: vdsm-4.50.0.13 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2022-04-28 09:26:34 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Storage RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Nir Soffer 2022-04-19 10:21:04 UTC 
This is a copy of
https://github.com/oVirt/vdsm/issues/135

The mailbox logs were always too noisy, but now with mailbox events they are even more noisy.

## Here mailbox logs from 10 seconds from the SPM host

2022-04-14 18:52:00,083+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=direct count=1 bs=4096 (cwd None) (commands:234)
2022-04-14 18:52:00,116+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n4096 bytes (4.1 kB, 4.0 KiB) copied, 0.00871619 s, 470 kB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:52:00,512+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None) (commands:234)
2022-04-14 18:52:00,550+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB, 1000 KiB) copied, 0.0116884 s, 87.6 MB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:52:01,060+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=direct count=1 bs=4096 (cwd None) (commands:234)
2022-04-14 18:52:01,075+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n4096 bytes (4.1 kB, 4.0 KiB) copied, 0.00743977 s, 551 kB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:52:01,576+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=direct count=1 bs=4096 (cwd None) (commands:234)
2022-04-14 18:52:01,603+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n4096 bytes (4.1 kB, 4.0 KiB) copied, 0.007399 s, 554 kB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:52:02,108+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=direct count=1 bs=4096 (cwd None) (commands:234)
2022-04-14 18:52:02,126+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n4096 bytes (4.1 kB, 4.0 KiB) copied, 0.00759692 s, 539 kB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:52:02,560+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None) (commands:234)
2022-04-14 18:52:02,591+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB, 1000 KiB) copied, 0.00508083 s, 202 MB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:52:03,101+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=direct count=1 bs=4096 (cwd None) (commands:234)
2022-04-14 18:52:03,136+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n4096 bytes (4.1 kB, 4.0 KiB) copied, 0.00810533 s, 505 kB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:52:03,637+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=direct count=1 bs=4096 (cwd None) (commands:234)
2022-04-14 18:52:03,670+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n4096 bytes (4.1 kB, 4.0 KiB) copied, 0.00832939 s, 492 kB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:52:04,172+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=direct count=1 bs=4096 (cwd None) (commands:234)
2022-04-14 18:52:04,208+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n4096 bytes (4.1 kB, 4.0 KiB) copied, 0.00851643 s, 481 kB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:52:04,601+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None) (commands:234)
2022-04-14 18:52:04,628+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB, 1000 KiB) copied, 0.00884631 s, 116 MB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:52:05,133+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=direct count=1 bs=4096 (cwd None) (commands:234)
2022-04-14 18:52:05,146+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n4096 bytes (4.1 kB, 4.0 KiB) copied, 0.000658489 s, 6.2 MB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:52:05,646+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=direct count=1 bs=4096 (cwd None) (commands:234)
2022-04-14 18:52:05,679+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n4096 bytes (4.1 kB, 4.0 KiB) copied, 0.00853014 s, 480 kB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:52:06,180+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=direct count=1 bs=4096 (cwd None) (commands:234)
2022-04-14 18:52:06,197+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n4096 bytes (4.1 kB, 4.0 KiB) copied, 0.0072806 s, 563 kB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:52:06,633+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None) (commands:234)
2022-04-14 18:52:06,671+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB, 1000 KiB) copied, 0.0120905 s, 84.7 MB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:52:07,184+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=direct count=1 bs=4096 (cwd None) (commands:234)
2022-04-14 18:52:07,219+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n4096 bytes (4.1 kB, 4.0 KiB) copied, 0.00786979 s, 520 kB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:52:07,720+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=direct count=1 bs=4096 (cwd None) (commands:234)
2022-04-14 18:52:07,739+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n4096 bytes (4.1 kB, 4.0 KiB) copied, 0.00746872 s, 548 kB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:52:08,240+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=direct count=1 bs=4096 (cwd None) (commands:234)
2022-04-14 18:52:08,274+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n4096 bytes (4.1 kB, 4.0 KiB) copied, 0.00803948 s, 509 kB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:52:08,683+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None) (commands:234)
2022-04-14 18:52:08,722+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB, 1000 KiB) copied, 0.0121663 s, 84.2 MB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:52:09,234+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=direct count=1 bs=4096 (cwd None) (commands:234)
2022-04-14 18:52:09,250+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n4096 bytes (4.1 kB, 4.0 KiB) copied, 0.0074819 s, 547 kB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:52:09,752+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=direct count=1 bs=4096 (cwd None) (commands:234)
2022-04-14 18:52:09,784+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n4096 bytes (4.1 kB, 4.0 KiB) copied, 0.0080576 s, 508 kB/s\n'; <rc> = 0 (commands:247)

## Here is one second of logs during extend:

2022-04-14 18:55:43,296+0300 DEBUG (periodic/1) [storage.spm.messages.extend] new extend msg created: domain: bafd0f16-9aba-4f9f-ba90-46d3b8a29157, volume: cdb268ff-9455-4692-997d-ad5f35ee33e1 (mailbox:135)
2022-04-14 18:55:43,343+0300 DEBUG (mailbox-hsm) [storage.mailbox.hsmmailmonitor] HSM_MailMonitor - start: 0, end: 64, len: 4096, message(1/63): b'1xtndW\x91\xa2\xb8\xd3F\x90\xba\x9fO\xba\x9a\x16\x0f\xfd\xba\xe13\xee5_\xad}\x99\x92FU\x94\xffh\xb2\xcd0000000000001e0000000000000' (mailbox:432)
2022-04-14 18:55:43,344+0300 DEBUG (mailbox-hsm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/outbox iflag=direct,fullblock bs=4096 count=1 skip=1 (cwd None) (commands:234)
2022-04-14 18:55:43,365+0300 DEBUG (mailbox-hsm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n4096 bytes (4.1 kB, 4.0 KiB) copied, 0.00046536 s, 8.8 MB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:55:43,366+0300 INFO  (mailbox-hsm) [storage.mailbox.hsmmailmonitor] HSM_MailMonitor sending mail to SPM - ['/usr/bin/dd', 'of=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox', 'iflag=fullblock', 'oflag=direct', 'conv=notrunc', 'bs=4096', 'count=1', 'seek=1'] (mailbox:393)
2022-04-14 18:55:43,366+0300 DEBUG (mailbox-hsm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd of=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=fullblock oflag=direct conv=notrunc bs=4096 count=1 seek=1 (cwd None) (commands:234)
2022-04-14 18:55:43,394+0300 DEBUG (mailbox-hsm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n4096 bytes (4.1 kB, 4.0 KiB) copied, 0.000316367 s, 12.9 MB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:55:43,394+0300 INFO  (mailbox-hsm) [storage.mailbox.hsmmailmonitor] HSM_MailMonitor sending event ba208024-1ca8-44af-a6bb-0cbc7c355970 to SPM (mailbox:537)
2022-04-14 18:55:43,394+0300 DEBUG (mailbox-hsm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd of=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=fullblock oflag=direct conv=notrunc bs=4096 count=1 (cwd None) (commands:234)
2022-04-14 18:55:43,418+0300 DEBUG (mailbox-hsm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n4096 bytes (4.1 kB, 4.0 KiB) copied, 0.00527916 s, 776 kB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:55:43,644+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=direct count=1 bs=4096 (cwd None) (commands:234)
2022-04-14 18:55:43,661+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n4096 bytes (4.1 kB, 4.0 KiB) copied, 0.000518707 s, 7.9 MB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:55:43,662+0300 INFO  (mailbox-spm) [storage.MailBox.SpmMailMonitor] Received event: ba208024-1ca8-44af-a6bb-0cbc7c355970 (mailbox:866)
2022-04-14 18:55:43,662+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None) (commands:234)
2022-04-14 18:55:43,695+0300 DEBUG (mailbox-spm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB, 1000 KiB) copied, 0.0108624 s, 94.3 MB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:55:43,695+0300 DEBUG (mailbox-spm) [storage.MailBox.SpmMailMonitor] SPM_MailMonitor: Mailbox 1 validated, checking mail (mailbox:703)
2022-04-14 18:55:43,695+0300 DEBUG (mailbox-spm) [storage.MailBox.SpmMailMonitor] SPM_MailMonitor: processing request: b'1xtndW\x91\xa2\xb8\xd3F\x90\xba\x9fO\xba\x9a\x16\x0f\xfd\xba\xe13\xee5_\xad}\x99\x92FU\x94\xffh\xb2\xcd0000000000001e0000000000000' (mailbox:740)
2022-04-14 18:55:43,750+0300 DEBUG (mailbox-spm/0) [storage.threadpool] Number of running tasks: 1 (threadPool:85)
2022-04-14 18:55:43,750+0300 INFO  (mailbox-spm/0) [storage.threadpool.workerthread] START task 4deeed70-f946-4a0b-b94b-d8b63fa7c56a (cmd=<function runTask at 0x7f5129b4dea0>, args=(functools.partial(<bound method SPM_Extend_Message.processRequest of <class 'vdsm.storage.mailbox.SPM_Extend_Message'>>, <vdsm.storage.sp.StoragePool object at 0x7f50f0561940>), 64, b'1xtndW\x91\xa2\xb8\xd3F\x90\xba\x9fO\xba\x9a\x16\x0f\xfd\xba\xe13\xee5_\xad}\x99\x92FU\x94\xffh\xb2\xcd0000000000001e0000000000000')) (threadPool:146)
2022-04-14 18:55:43,750+0300 DEBUG (mailbox-spm/0) [storage.taskmanager.task] (Task='98841b95-8693-4556-9868-15cf8d29d25f') moving from state preparing -> state preparing (task:624)
2022-04-14 18:55:43,750+0300 DEBUG (mailbox-spm/0) [storage.spm.messages.extend] processRequest, payload:b'1xtndW\x91\xa2\xb8\xd3F\x90\xba\x9fO\xba\x9a\x16\x0f\xfd\xba\xe13\xee5_\xad}\x99\x92FU\x94\xffh\xb2\xcd0000000000001e0000000000000' (mailbox:158)
2022-04-14 18:55:43,750+0300 INFO  (mailbox-spm/0) [storage.spm.messages.extend] processRequest: extending volume cdb268ff-9455-4692-997d-ad5f35ee33e1 in domain bafd0f16-9aba-4f9f-ba90-46d3b8a29157 (pool d8f140d8-0de0-45dd-8c5a-b27aafba7683) to size 7680 (mailbox:173)
2022-04-14 18:55:43,750+0300 DEBUG (mailbox-spm/0) [storage.storagedomain] Extending thinly-provisioned LV for volume cdb268ff-9455-4692-997d-ad5f35ee33e1 to 7680 MB (blockSD:1597)
2022-04-14 18:55:43,751+0300 DEBUG (mailbox-spm/0) [common.commands] /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /usr/sbin/lvm vgs --devices /dev/mapper/0QEMU_QEMU_HARDDISK_data-fc-01,/dev/mapper/0QEMU_QEMU_HARDDISK_data-fc-02,/dev/mapper/0QEMU_QEMU_HARDDISK_data-fc-03,/dev/mapper/36001405351b21217d814266b5354d710,/dev/mapper/3600140536effe53a1e242a991f0d44d0,/dev/mapper/360014054f26c2d5c5b74814a0c0cbabb,/dev/mapper/3600140563a17d65f8dd44ad9b84bff97,/dev/mapper/3600140577ea494a9b544084bdf67f5e1,/dev/mapper/36001405789e8ab39498483ea5858c779,/dev/mapper/360014057c4191f0d8f547a6a69180ef1,/dev/mapper/36001405c75ad03669294f4ab344b0028,/dev/mapper/36001405ef11fb3ca9824a5dbc12f0931,/dev/mapper/36001405fa8e8698bae84578baae9c182 --config 'devices {  preferred_names=["^/dev/mapper/"]  ignore_suspended_devices=1  write_cache_state=0  disable_after_error_count=3    hints="none"  obtain_device_list_from_udev=0 } global {  prioritise_write_locks=1  wait_for_locks=1  use_lvmpolld=1 } backup {  retain_min=50  retain_days=0 }' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name bafd0f16-9aba-4f9f-ba90-46d3b8a29157 (cwd None) (commands:154)
2022-04-14 18:55:43,838+0300 DEBUG (mailbox-spm/0) [common.commands] SUCCESS: <err> = b''; <rc> = 0 (commands:186)
2022-04-14 18:55:43,839+0300 DEBUG (mailbox-spm/0) [common.commands] /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /usr/sbin/lvm lvs --devices /dev/mapper/0QEMU_QEMU_HARDDISK_data-fc-01,/dev/mapper/0QEMU_QEMU_HARDDISK_data-fc-02,/dev/mapper/0QEMU_QEMU_HARDDISK_data-fc-03 --config 'devices {  preferred_names=["^/dev/mapper/"]  ignore_suspended_devices=1  write_cache_state=0  disable_after_error_count=3    hints="none"  obtain_device_list_from_udev=0 } global {  prioritise_write_locks=1  wait_for_locks=1  use_lvmpolld=1 } backup {  retain_min=50  retain_days=0 }' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags bafd0f16-9aba-4f9f-ba90-46d3b8a29157 (cwd None) (commands:154)
2022-04-14 18:55:43,938+0300 DEBUG (mailbox-hsm) [storage.misc.exccmd] /usr/bin/taskset --cpu-list 0-1 /usr/bin/dd if=/rhev/data-center/d8f140d8-0de0-45dd-8c5a-b27aafba7683/mastersd/dom_md/outbox iflag=direct,fullblock bs=4096 count=1 skip=1 (cwd None) (commands:234)
2022-04-14 18:55:43,959+0300 DEBUG (mailbox-hsm) [storage.misc.exccmd] SUCCESS: <err> = b'1+0 records in\n1+0 records out\n4096 bytes (4.1 kB, 4.0 KiB) copied, 0.000279828 s, 14.6 MB/s\n'; <rc> = 0 (commands:247)
2022-04-14 18:55:43,973+0300 DEBUG (mailbox-spm/0) [common.commands] SUCCESS: <err> = b''; <rc> = 0 (commands:186)
2022-04-14 18:55:43,973+0300 DEBUG (mailbox-spm/0) [storage.lvm] lvs reloaded (lvm:718)
2022-04-14 18:55:43,973+0300 INFO  (mailbox-spm/0) [storage.lvm] Extending LV bafd0f16-9aba-4f9f-ba90-46d3b8a29157/cdb268ff-9455-4692-997d-ad5f35ee33e1 to 7680 megabytes (lvm:1616)
2022-04-14 18:55:43,974+0300 DEBUG (mailbox-spm/0) [common.commands] /usr/bin/taskset --cpu-list 0-1 /usr/bin/sudo -n /usr/sbin/lvm lvextend --devices /dev/mapper/0QEMU_QEMU_HARDDISK_data-fc-01,/dev/mapper/0QEMU_QEMU_HARDDISK_data-fc-02,/dev/mapper/0QEMU_QEMU_HARDDISK_data-fc-03 --config 'devices {  preferred_names=["^/dev/mapper/"]  ignore_suspended_devices=1  write_cache_state=0  disable_after_error_count=3    hints="none"  obtain_device_list_from_udev=0 } global {  prioritise_write_locks=1  wait_for_locks=1  use_lvmpolld=1 } backup {  retain_min=50  retain_days=0 }' --autobackup n --driverloaded n --size 7680m bafd0f16-9aba-4f9f-ba90-46d3b8a29157/cdb268ff-9455-4692-997d-ad5f35ee33e1 (cwd None) (commands:154)

## Issues:

- Logging command arguments in INFO level, when the actual command is
  already logged in DEBUG level
- Logging events send/receive in INFO level - this is implementation 
  detail, needed only for debugging
- Mailbox commands are logged using storage.misc.execcmd instead of
  storge.mailbox, so it is not possible to silence only the mailbox
  commands, that run every 0.5 seconds.
- No easy way to silence mailbox logs, if you enable DEBUG level logs
  for "storage", you get also DEBUG logs for "storage.mailbox"
Comment 2 Sandro Bonazzola 2022-04-28 09:26:34 UTC 
This bugzilla is included in oVirt 4.5.0 release, published on April 20th 2022.

Since the problem described in this bug report should be resolved in oVirt 4.5.0 release, it has been closed with a resolution of CURRENT RELEASE.

If the solution does not work for you, please open a new bug report.