Bug 1114908

Summary: Excessive ioprocess logging in vdsm.log
Product: [Retired] oVirt Reporter: Federico Simoncelli <fsimonce>
Component: ioprocessAssignee: Saggi Mizrahi <smizrahi>
Status: CLOSED CURRENTRELEASE QA Contact: Jiri Belka <jbelka>
Severity: high Docs Contact:
Priority: unspecified    
Version: 3.5CC: amureini, bazulay, bugs, danken, gklein, iheim, mgoldboi, nsoffer, oourfali, rbalakri, smizrahi, ybronhei, yeylon
Target Milestone: ---   
Target Release: 3.5.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard: infra
Fixed In Version: ioprocess-0.10.0-1.el6_5.noarch Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
: 1124369 (view as bug list) Environment:
Last Closed: 2014-10-17 12:32:21 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Infra RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1124369    
Attachments:
Description Flags
vdsm-bz1114908.log.gz
none
output of "grep IOProcess vdsm.log" none

Description Federico Simoncelli 2014-07-01 09:06:29 UTC
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

Comment 1 Federico Simoncelli 2014-07-01 09:07:56 UTC
Created attachment 913710 [details]
vdsm-bz1114908.log.gz

Comment 2 Yaniv Bronhaim 2014-07-13 08:37:19 UTC
*** Bug 1118265 has been marked as a duplicate of this bug. ***

Comment 3 Yaniv Bronhaim 2014-07-13 15:41:45 UTC
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

Comment 4 Dan Kenigsberg 2014-07-25 13:30:55 UTC
Please packport patch to the 3.5 branch - it's a 3.5 bug.

Comment 5 Barak 2014-07-27 11:39:26 UTC
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 ?

Comment 6 Dan Kenigsberg 2014-07-28 08:42:59 UTC
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.

Comment 7 Barak 2014-07-28 11:31:25 UTC
I would still say it misses an appropriate "requires:" patch in the vdsm spec file.

Comment 8 Nir Soffer 2014-07-30 09:37:54 UTC
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.

Comment 9 Federico Simoncelli 2014-07-30 13:42:29 UTC
(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.

Comment 10 Jiri Belka 2014-09-24 09:41:39 UTC
ok, based on https://bugzilla.redhat.com/show_bug.cgi?id=1124369#c3

Comment 11 Sandro Bonazzola 2014-10-17 12:32:21 UTC
oVirt 3.5 has been released and should include the fix for this issue.

Comment 12 Red Hat Bugzilla 2023-09-14 02:10:50 UTC
The needinfo request[s] on this closed bug have been removed as they have been unresolved for 1000 days