Bug 1275062 - Incorrect logging of ioprocess child process
Incorrect logging of ioprocess child process
Status: CLOSED CURRENTRELEASE
Product: ovirt-distribution
Classification: oVirt
Component: ioprocess (Show other bugs)
ioprocess-0.15.0
Unspecified Unspecified
unspecified Severity high (vote)
: ovirt-3.6.1
: ioprocess-0.15.0
Assigned To: Yeela Kaplan
Jiri Belka
infra
:
Depends On:
Blocks: 1273122 1286963
  Show dependency treegraph
 
Reported: 2015-10-25 09:54 EDT by Nir Soffer
Modified: 2016-02-10 14:14 EST (History)
1 user (show)

See Also:
Fixed In Version: ioprocess-0.15.0-4
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2016-01-13 09:38:02 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: Infra
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---
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 09:54 EDT, Nir Soffer
no flags Details


External Trackers
Tracker ID Priority Status Summary Last Updated
oVirt gerrit 47707 None None None Never

  None (edit)
Description Nir Soffer 2015-10-25 09:54:10 EDT
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 09:56:16 EDT
Setting to high, since corrupting the log make it harder to debug.
Comment 2 Yaniv Lavi 2015-10-29 08:52:59 EDT
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 07:26:11 EST
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 09:38:02 EST
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.