Bug 1275062 – Incorrect logging of ioprocess child process

Bug 1275062 - Incorrect logging of ioprocess child process

Summary:	Incorrect logging of ioprocess child process

Status:	CLOSED CURRENTRELEASE

Aliases:	None

Product:	ovirt-distribution
Classification:	oVirt
Component:	ioprocess (Show other bugs)
Sub Component:
Version:	ioprocess-0.15.0
Hardware:	Unspecified Unspecified

Priority	unspecified Severity high (vote)
Target Milestone:	ovirt-3.6.1
Target Release:	ioprocess-0.15.0
Assigned To:	Yeela Kaplan
QA Contact:	Jiri Belka
Docs Contact:

URL:
Whiteboard:	infra
Keywords:

Depends On:
Blocks:	1273122 1286963
	Show dependency tree / graph

Reported:	2015-10-25 09:54 EDT by Nir Soffer
Modified:	2016-02-10 14:14 EST (History)
CC List:	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:	---

Flags:	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
Add an attachment (proposed patch, testcase, etc.)

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

Groups: 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.