Description of problem: By default the newly introduced ioprocess package is excessively verbose in logging. Version-Release number of selected component (if applicable): vdsm-4.16.0-6.git5d3ed2d.el6.x86_64 python-ioprocess-0.5.0-2.el6_5.noarch How reproducible: 100% Steps to Reproduce: 1. create storage domain 2. add storage domain 3. create disks Actual results: Excessive logging in vdsm.log Additional info: Thread-14::DEBUG::2014-07-01 08:17:17,051::__init__::225::IOProcess::(_processLogs) Not closiDEBUG|Receiving request...DEBUG|Message size is 166DEBUG|Marshaling message...DEBUG|Queuing request...DEBUG|Waiting for next request...DEBUG|Queuing request in the thread pool...DEBUG|Extracting request information...DEBUG|(2) Finding callback 'glob'...DEBUG|(2) Got request for method 'glob'DEBUG|(2) Building responseDEBUG|(2) Queuing responseDEBUG|Generating json...DEBUG|Sending response sized 73DEBUG|Receiving request... Thread-14::DEBUG::2014-07-01 08:17:17,051::__init__::225::IOProcess::(_processLogs) Not closiDEBUG|Receiving request...DEBUG|Message size is 166DEBUG|Marshaling message...DEBUG|Queuing request...DEBUG|Waiting for next request...DEBUG|Queuing request in the thread pool...DEBUG|Extracting request information...DEBUG|(2) Finding callback 'glob'...DEBUG|(2) Got request for method 'glob'DEBUG|(2) Building responseDEBUG|(2) Queuing responseDEBUG|Generating json...DEBUG|Sending response sized 73DEBUG|Receiving request...DEBUG|Message size is 148 Thread-14::DEBUG::2014-07-01 08:17:17,051::__init__::225::IOProcess::(_processLogs) Not closiDEBUG|Receiving request...DEBUG|Message size is 166DEBUG|Marshaling message...DEBUG|Queuing request...DEBUG|Waiting for next request...DEBUG|Queuing request in the thread pool...DEBUG|Extracting request information...DEBUG|(2) Finding callback 'glob'...DEBUG|(2) Got request for method 'glob'DEBUG|(2) Building responseDEBUG|(2) Queuing responseDEBUG|Generating json...DEBUG|Sending response sized 73DEBUG|Receiving request...DEBUG|Message size is 148DEBUG|Marshaling message... Thread-14::DEBUG::2014-07-01 08:17:17,051::__init__::225::IOProcess::(_processLogs) Not closiDEBUG|Receiving request...DEBUG|Message size is 166DEBUG|Marshaling message...DEBUG|Queuing request...DEBUG|Waiting for next request...DEBUG|Queuing request in the thread pool...DEBUG|Extracting request information...DEBUG|(2) Finding callback 'glob'...DEBUG|(2) Got request for method 'glob'DEBUG|(2) Building responseDEBUG|(2) Queuing responseDEBUG|Generating json...DEBUG|Sending response sized 73DEBUG|Receiving request...DEBUG|Message size is 148DEBUG|Marshaling message...DEBUG|Queuing request... Thread-14::DEBUG::2014-07-01 08:17:17,051::__init__::225::IOProcess::(_processLogs) Not closiDEBUG|Receiving request...DEBUG|Message size is 166DEBUG|Marshaling message...DEBUG|Queuing request...DEBUG|Waiting for next request...DEBUG|Queuing request in the thread pool...DEBUG|Extracting request information...DEBUG|(2) Finding callback 'glob'...DEBUG|(2) Got request for method 'glob'DEBUG|(2) Building responseDEBUG|(2) Queuing responseDEBUG|Generating json...DEBUG|Sending response sized 73DEBUG|Receiving request...DEBUG|Message size is 148DEBUG|Marshaling message...DEBUG|Queuing request...DEBUG|Queuing request in the thread pool... Thread-14::DEBUG::2014-07-01 08:17:17,052::__init__::225::IOProcess::(_processLogs) Not closiDEBUG|Receiving request...DEBUG|Message size is 166DEBUG|Marshaling message...DEBUG|Queuing request...DEBUG|Waiting for next request...DEBUG|Queuing request in the thread pool...DEBUG|Extracting request information...DEBUG|(2) Finding callback 'glob'...DEBUG|(2) Got request for method 'glob'DEBUG|(2) Building responseDEBUG|(2) Queuing responseDEBUG|Generating json...DEBUG|Sending response sized 73DEBUG|Receiving request...DEBUG|Message size is 148DEBUG|Marshaling message...DEBUG|Queuing request...DEBUG|Queuing request in the thread pool...DEBUG|Waiting for next request... Thread-14::DEBUG::2014-07-01 08:17:17,379::__init__::225::IOProcess::(_processLogs) Not closiDEBUG|Receiving request...DEBUG|Message size is 166DEBUG|Marshaling message...DEBUG|Queuing request...DEBUG|Waiting for next request...DEBUG|Queuing request in the thread pool...DEBUG|Extracting request information...DEBUG|(2) Finding callback 'glob'...DEBUG|(2) Got request for method 'glob'DEBUG|(2) Building responseDEBUG|(2) Queuing responseDEBUG|Generating json...DEBUG|Sending response sized 73DEBUG|Receiving request...DEBUG|Message size is 148DEBUG|Marshaling message...DEBUG|Queuing request...DEBUG|Queuing request in the thread pool...DEBUG|Waiting for next request...DEBUG|Receiving request...DEBUG|Message size is 146DEBUG|Extracting request information...DEBUG|Marshaling message...DEBUG|(3) Finding callback 'glob'...DEBUG|Queuing request...DEBUG|(3) Got request for method 'glob'DEBUGDEBUG|(3) Building response|DEBUG|Queuing request in the thread pool...DEBUG|(3) Queuing responseWaiting for next request...DEBUG|Extracting request information...DEBUG|(4) Finding callback 'glob'...DEBUG|Generating json...DEBUG|(4) Got request for method 'glob'DEBUG|Sending response sized 73DEBUG|Generating json...DEBUG|Sending response sized 73DEBUG|Receiving request...DEBUG|Message size is 166DEBUG|Marshaling message...DEBUG|Queuing request...DEBUG|Queuing request in the thread pool...DEBUG|Waiting for next request...DEBUG|Extracting request information...DEBUG|(5) Finding callback 'glob'...DEBUG|(5) Got request for method 'glob'DEBUG|(5) Building responseDEBUG|(5) Queuing responseDEBUG|Generating json...DEBUG|Sending response sized 73DEBUG|Receiving request...DEBUG|Message size is 148DEBUG|Marshaling message...DEBUG|Queuing request...DEBUG|Queuing request in the thread pool...DEBUG|Waiting for next request...DEBUG|Receiving request...DEBUG|Message size is 146DEBUG|Marshaling message... Thread-14::DEBUG::2014-07-01 08:17:17,380::__init__::225::IOProcess::(_processLogs) Not closiDEBUG|Receiving request...DEBUG|Message size is 166DEBUG|Marshaling message...DEBUG|Queuing request...DEBUG|Waiting for next request...DEBUG|Queuing request in the thread pool...DEBUG|Extracting request information...DEBUG|(2) Finding callback 'glob'...DEBUG|(2) Got request for method 'glob'DEBUG|(2) Building responseDEBUG|(2) Queuing responseDEBUG|Generating json...DEBUG|Sending response sized 73DEBUG|Receiving request...DEBUG|Message size is 148DEBUG|Marshaling message...DEBUG|Queuing request...DEBUG|Queuing request in the thread pool...DEBUG|Waiting for next request...DEBUG|Receiving request...DEBUG|Message size is 146DEBUG|Extracting request information...DEBUG|Marshaling message...DEBUG|(3) Finding callback 'glob'...DEBUG|Queuing request...DEBUG|(3) Got request for method 'glob'DEBUGDEBUG|(3) Building response|DEBUG|Queuing request in the thread pool...DEBUG|(3) Queuing responseWaiting for next request...DEBUG|Extracting request information...DEBUG|(4) Finding callback 'glob'...DEBUG|Generating json...DEBUG|(4) Got request for method 'glob'DEBUG|Sending response sized 73DEBUG|Generating json...DEBUG|Sending response sized 73DEBUG|Receiving request...DEBUG|Message size is 166DEBUG|Marshaling message...DEBUG|Queuing request...DEBUG|Queuing request in the thread pool...DEBUG|Waiting for next request...DEBUG|Extracting request information...DEBUG|(5) Finding callback 'glob'...DEBUG|(5) Got request for method 'glob'DEBUG|(5) Building responseDEBUG|(5) Queuing responseDEBUG|Generating json...DEBUG|Sending response sized 73DEBUG|Receiving request...DEBUG|Message size is 148DEBUG|Marshaling message...DEBUG|Queuing request...DEBUG|Queuing request in the thread pool...DEBUG|Waiting for next request...DEBUG|Receiving request...DEBUG|Message size is 146DEBUG|Marshaling message...DEBUG|Queuing request... Thread-14::DEBUG::2014-07-01 09:04:08,606::__init__::225::IOProcess::(_processLogs) Extracting request information...DEBUG|Receiving request... Thread-14::DEBUG::2014-07-01 09:04:08,607::__init__::225::IOProcess::(_processLogs) Message size is 169 Thread-14::DEBUG::2014-07-01 09:04:08,607::__init__::225::IOProcess::(_processLogs) Marshaling message... Thread-14::DEBUG::2014-07-01 09:04:08,607::__init__::225::IOProcess::(_processLogs) Queuing request... Thread-14::DEBUG::2014-07-01 09:04:08,607::__init__::225::IOProcess::(_processLogs) Waiting for next request... Thread-14::DEBUG::2014-07-01 09:04:08,608::__init__::225::IOProcess::(_processLogs) Queuing request in the thread pool... Thread-14::DEBUG::2014-07-01 09:04:08,608::__init__::225::IOProcess::(_processLogs) Extracting request information...DEBUG|Extracting request information... Thread-14::DEBUG::2014-07-01 09:04:08,608::__init__::225::IOProcess::(_processLogs) (1218) Finding callback 'statvfs'... Thread-14::DEBUG::2014-07-01 09:04:08,609::__init__::225::IOProcess::(_processLogs) (1218) Got request for method 'statvfs' Thread-14::DEBUG::2014-07-01 09:04:08,609::__init__::225::IOProcess::(_processLogs) (1218) Building response Thread-14::DEBUG::2014-07-01 09:04:08,610::__init__::225::IOProcess::(_processLogs) (1218) Queuing response Thread-14::DEBUG::2014-07-01 09:04:08,610::__init__::225::IOProcess::(_processLogs) Generating json... Thread-14::DEBUG::2014-07-01 09:04:08,610::__init__::225::IOProcess::(_processLogs) Sending response sized 324
Created attachment 913710 [details] vdsm-bz1114908.log.gz
*** Bug 1118265 has been marked as a duplicate of this bug. ***
I would do that and remove all g_debug prints from ioprocess.c but I guess there's nicer way to set the level of logs to forward vdsm and avoid those, or maybe you prefer to leave them
Please packport patch to the 3.5 branch - it's a 3.5 bug.
Dan, The patch is on ioprocess, I assume you mean that there needs to be appropriate "Requires:" statement in the spec file to require the new ioprocess version ?
No, I did not realize that the component is wrong (fixed it now). Please move this bug to ON_QA if it's available for test during 3.5 beta2.
I would still say it misses an appropriate "requires:" patch in the vdsm spec file.
Created attachment 922474 [details] output of "grep IOProcess vdsm.log" Still an issue in vdsm version on test day 2: - vdsm 4.16.1-0.gita4d9abf.fc19 - python-ioprocess-0.5.0-1.fc19.noarch ioprocess should log only 2 debug messages: - Starting a request - Ending a requst Anything else is irrelevant to debugging application issues in vdsm. The operation of ioprocess must be verified using tests and not by looking at the logs.
(In reply to Nir Soffer from comment #8) > Created attachment 922474 [details] > output of "grep IOProcess vdsm.log" > > Still an issue in vdsm version on test day 2: > - vdsm 4.16.1-0.gita4d9abf.fc19 > - python-ioprocess-0.5.0-1.fc19.noarch > > ioprocess should log only 2 debug messages: > - Starting a request > - Ending a requst > > Anything else is irrelevant to debugging application issues in vdsm. > The operation of ioprocess must be verified using tests and not by > looking at the logs. I think this was "expected" the python-ioprocess package you used is older than the one in the bz description. The issue should be fixed in ioprocess-0.6.1-1.fc19: http://koji.fedoraproject.org/koji/buildinfo?buildID=546014 * Sun Jul 20 2014 Saggi Mizrahi <smizrahi> 0.6.1-1 Reduced logging even for debug level We have bug 1124369 on vdsm that tracks the "require" spec changes.
ok, based on https://bugzilla.redhat.com/show_bug.cgi?id=1124369#c3
oVirt 3.5 has been released and should include the fix for this issue.
The needinfo request[s] on this closed bug have been removed as they have been unresolved for 1000 days