Bugzilla (bugzilla.redhat.com) will be under maintenance for infrastructure upgrades and will not be available on July 31st between 12:30 AM - 05:30 AM UTC. We appreciate your understanding and patience. You can follow status.redhat.com for details.
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
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2016-01-13 14:38:02 UTC
oVirt Team: Infra
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
Add an attachment (proposed patch, testcase, etc.)


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.