Bug 1275062
| Summary: | Incorrect logging of ioprocess child process | ||||||
|---|---|---|---|---|---|---|---|
| Product: | [oVirt] ovirt-distribution | Reporter: | Nir Soffer <nsoffer> | ||||
| Component: | ioprocess | Assignee: | Yeela Kaplan <ykaplan> | ||||
| ioprocess sub component: | General | QA Contact: | Jiri Belka <jbelka> | ||||
| Status: | CLOSED CURRENTRELEASE | Docs Contact: | |||||
| Severity: | high | ||||||
| Priority: | unspecified | CC: | oourfali | ||||
| Version: | ioprocess-0.15.0 | Flags: | oourfali:
ovirt-3.6.z?
rule-engine: planning_ack? oourfali: devel_ack+ pstehlik: testing_ack+ |
||||
| Target Milestone: | ovirt-3.6.1 | ||||||
| Target Release: | ioprocess-0.15.0 | ||||||
| Hardware: | Unspecified | ||||||
| OS: | Unspecified | ||||||
| Whiteboard: | infra | ||||||
| Fixed In Version: | ioprocess-0.15.0-4 | Doc Type: | Bug Fix | ||||
| Doc Text: | Story Points: | --- | |||||
| Clone Of: | Environment: | ||||||
| Last Closed: | 2016-01-13 14:38:02 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: | 1273122, 1286963 | ||||||
| Attachments: |
|
||||||
Setting to high, since corrupting the log make it harder to debug. 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. 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 ~]# oVirt 3.6.1 has been released, closing current release |
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