Bug 1275062 - Incorrect logging of ioprocess child process
Summary: Incorrect logging of ioprocess child process
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: ovirt-distribution
Classification: oVirt
Component: ioprocess
Version: ioprocess-0.15.0
Hardware: Unspecified
OS: Unspecified
unspecified
high
Target Milestone: ovirt-3.6.1
: ioprocess-0.15.0
Assignee: Yeela Kaplan
QA Contact: Jiri Belka
URL:
Whiteboard: infra
Depends On:
Blocks: 1273122 1286963
TreeView+ depends on / blocked
 
Reported: 2015-10-25 13:54 UTC by Nir Soffer
Modified: 2016-02-10 19:14 UTC (History)
1 user (show)

Fixed In Version: ioprocess-0.15.0-4
Clone Of:
Environment:
Last Closed: 2016-01-13 14:38:02 UTC
oVirt Team: Infra
Embargoed:
oourfali: ovirt-3.6.z?
rule-engine: planning_ack?
oourfali: devel_ack+
pstehlik: testing_ack+


Attachments (Terms of Use)
Output of "xzgrep 'DEBUG|' /var/log/vdsm/vdsm.log.* > bad-ioprocess.log" (585.29 KB, application/x-gzip)
2015-10-25 13:54 UTC, Nir Soffer
no flags Details


Links
System ID Private Priority Status Summary Last Updated
oVirt gerrit 47707 0 None None None Never

Description Nir Soffer 2015-10-25 13:54:10 UTC
Created attachment 1086217 [details]
Output of "xzgrep 'DEBUG|' /var/log/vdsm/vdsm.log.* > bad-ioprocess.log"

Description of problem:

Vdsm's ioprocess logs contains raw unprocessed data from ioprocess:

The string: "DEBUG|(null)|(372) Start request for method 'access' (waitTime=60)"

Is raw unprocessed data from ioprocess. it should have been splited
to "DEBUG", "(null)", and "(372) Start request for method 'access' (waitTime=60)", and the last part should have been logged with debug
log level.

We can see that the raw string is repeated in many logs:

ioprocess communication (22663)::DEBUG::2015-10-23 21:45:29,801::__init__::375::IOProcess::(_processLogs) (371) Start request for method 'lexists' (waiDEBUG|(null)|(372) Start request for method 'access' (waitTime=60)
ioprocess communication (22663)::DEBUG::2015-10-23 21:45:29,801::__init__::375::IOProcess::(_processLogs) (371) Start request for method 'lexists' (waiDEBUG|(null)|(372) Finished request for method 'access' (runTime=30)
ioprocess communication (22663)::DEBUG::2015-10-23 21:45:29,801::__init__::375::IOProcess::(_processLogs) (371) Start request for method 'lexists' (waiDEBUG|(null)|(372) Dequeuing request (slotsLeft=21)
ioprocess communication (22663)::DEBUG::2015-10-23 21:45:29,801::__init__::375::IOProcess::(_processLogs) (371) Start request for method 'lexists' (waiDEBUG|(null)|Queuing request (slotsLeft=20)
ioprocess communication (22663)::DEBUG::2015-10-23 21:45:29,801::__init__::375::IOProcess::(_processLogs) (371) Start request for method 'lexists' (waiDEBUG|(null)|(373) Start request for method 'access' (waitTime=59)
ioprocess communication (22663)::DEBUG::2015-10-23 21:45:29,802::__init__::375::IOProcess::(_processLogs) (371) Start request for method 'lexists' (waiDEBUG|(null)|(373) Finished request for method 'access' (runTime=36)
ioprocess communication (22663)::DEBUG::2015-10-23 21:45:29,802::__init__::375::IOProcess::(_processLogs) (371) Start request for method 'lexists' (waiDEBUG|(null)|(373) Dequeuing request (slotsLeft=21)
ioprocess communication (22663)::DEBUG::2015-10-23 21:45:29,802::__init__::375::IOProcess::(_processLogs) (371) Start request for method 'lexists' (waiDEBUG|(null)|Queuing request (slotsLeft=20)
ioprocess communication (22663)::DEBUG::2015-10-23 21:45:29,802::__init__::375::IOProcess::(_processLogs) (371) Start request for method 'lexists' (waiDEBUG|(null)|(374) Start request for method 'access' (waitTime=58)
ioprocess communication (22663)::DEBUG::2015-10-23 21:45:29,802::__init__::375::IOProcess::(_processLogs) (371) Start request for method 'lexists' (waiDEBUG|(null)|(374) Finished request for method 'access' (runTime=32)
ioprocess communication (22663)::DEBUG::2015-10-23 21:45:29,802::__init__::375::IOProcess::(_processLogs) (371) Start request for method 'lexists' (waiDEBUG|(null)|(374) Dequeuing request (slotsLeft=21)
ioprocess communication (22663)::DEBUG::2015-10-23 21:45:29,803::__init__::375::IOProcess::(_processLogs) (371) Start request for method 'lexists' (waiDEBUG|(null)|Queuing request (slotsLeft=20)
Version-Release number of selected component (if applicable):


How reproducible:
Always, after some time vmds is running.

Steps to Reproduce:
1. Enable ioprocess debug logs
2. Do some operations
3. Wait until bad logs appear, can take some time

Comment 1 Nir Soffer 2015-10-25 13:56:16 UTC
Setting to high, since corrupting the log make it harder to debug.

Comment 2 Yaniv Lavi 2015-10-29 12:52:59 UTC
In oVirt testing is done on single release by default. Therefore I'm removing the 4.0 flag. If you think this bug must be tested in 4.0 as well, please re-add the flag. Please note we might not have testing resources to handle the 4.0 clone.

Comment 3 Jiri Belka 2016-01-13 12:26:11 UTC
ok, ioprocess-0.15.0-5.el7ev.x86_64

# echo "DEBUG|(null)|(372) Start request for method 'access' (waitTime=60)" | egrep "DEBUG\|\([[:alnum:]]+\)\|\([[:digit:]]+\)"
DEBUG|(null)|(372) Start request for method 'access' (waitTime=60)
^^ example

[root@dell-r210ii-13 ~]# egrep "DEBUG\|\([[:alnum:]]+\)\|\([[:digit:]]+\)" /var/log/vdsm/vdsm.log
[root@dell-r210ii-13 ~]#

Comment 4 Sandro Bonazzola 2016-01-13 14:38:02 UTC
oVirt 3.6.1 has been released, closing current release


Note You need to log in before you can comment on or make changes to this bug.