Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1114924

Summary: Possible missing string terminator in ioprocess logging
Product: Red Hat Enterprise Virtualization Manager Reporter: Federico Simoncelli <fsimonce>
Component: vdsmAssignee: Saggi Mizrahi <smizrahi>
Status: CLOSED CURRENTRELEASE QA Contact: Pavel Stehlik <pstehlik>
Severity: high Docs Contact:
Priority: high    
Version: 3.5.0CC: amureini, bazulay, gklein, iheim, lpeer, oourfali, pstehlik, smizrahi, yeylon
Target Milestone: ---Keywords: Triaged
Target Release: 3.5.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard: infra
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2014-08-26 12:34:34 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:
Attachments:
Description Flags
vdsm-bz1114924.log.gz none

Description Federico Simoncelli 2014-07-01 09:40:14 UTC
Description of problem:
Possible missing string terminator in ioprocess logging. Some logging lines still contain garbage from previous logs.

I am temporarily filing this under the vdsm component because I couldn't find the appropriate one.

Version-Release number of selected component (if applicable):
python-ioprocess-0.5.0-2.el6_5.noarch
ioprocess-0.5.0-2.el6_5.x86_64

How reproducible:
100%

Steps to Reproduce:
1. use ioprocess (e.g. vdsm) with debug logging

Actual results:
Logging seems to contain garbage from the previous lines.

Expected results:
Logging should be clean.

Additional info:
Looking at lines 8, 9 and 10 it seems that string inside the parenthesis still contains garbage from a previous log (line 6). The same happens for line 14, 18, 20, 21, etc.
It seems that the string in the buffer used for the text inside the parenthesis is missing the terminator '\0'.

  1 OProcess::(_processLogs) Closing unrelated FDs...
  2 OProcess::(_processLogs) Closing unrelated fd no: 0 (pipe:[154531])
  3 OProcess::(_processLogs) Not closing FD 1 because it's in whitelist
  4 OProcess::(_processLogs) Not closing FD 2 because it's in whitelist
  5 OProcess::(_processLogs) Closing unrelated fd no: 3 (socket:[152767])
  6 OProcess::(_processLogs) Closing unrelated fd no: 4 (/var/log/vdsm/vdsm.log)
  7 OProcess::(_processLogs) Not closing FD 5 because it's the directory fd
  8 OProcess::(_processLogs) Closing unrelated fd no: 9 ([eventpoll]sm/vdsm.log)
  9 OProcess::(_processLogs) Closing unrelated fd no: 10 (socket:[152781]dsm.log)
 10 OProcess::(_processLogs) Closing unrelated fd no: 11 (socket:[152887]dsm.log)
 11 OProcess::(_processLogs) Closing unrelated fd no: 12 (/var/log/vdsm/mom.logg)
 12 OProcess::(_processLogs) Closing unrelated fd no: 13 (/proc/meminfo/mom.logg)
 13 OProcess::(_processLogs) Closing unrelated fd no: 14 (/proc/vmstato/mom.logg)
 14 OProcess::(_processLogs) Closing unrelated fd no: 15 (socket:[152836]om.logg)
 15 OProcess::(_processLogs) Closing unrelated fd no: 16 (/sys/kernel/mm/ksm/full_scans)
 16 OProcess::(_processLogs) Closing unrelated fd no: 17 (/sys/kernel/mm/ksm/pages_sharing)
 17 OProcess::(_processLogs) Closing unrelated fd no: 18 (pipe:[154528]m/ksm/pages_sharing)
 18 OProcess::(_processLogs) Closing unrelated fd no: 19 (/sys/kernel/mm/ksm/pages_unshared)
 19 OProcess::(_processLogs) Closing unrelated fd no: 20 (socket:[154526]ksm/pages_unshared)
 20 OProcess::(_processLogs) Closing unrelated fd no: 21 (pipe:[154528]6]ksm/pages_unshared)
 21 OProcess::(_processLogs) Closing unrelated fd no: 22 (/sys/kernel/mm/ksm/runes_unshared)
 22 OProcess::(_processLogs) Closing unrelated fd no: 23 (pipe:[154529]m/ksm/runes_unshared)
 23 OProcess::(_processLogs) Closing unrelated fd no: 24 (/sys/kernel/mm/ksm/pages_shareded)
 24 OProcess::(_processLogs) Closing unrelated fd no: 25 (/sys/kernel/mm/ksm/pages_to_scand)
 25 OProcess::(_processLogs) Closing unrelated fd no: 26 (/sys/kernel/mm/ksm/pages_volatile)
 26 OProcess::(_processLogs) Closing unrelated fd no: 27 (/sys/kernel/mm/ksm/sleep_millisecs)
 27 OProcess::(_processLogs) Closing unrelated fd no: 33 (socket:[152905]ksm/sleep_millisecs)
 28 OProcess::(_processLogs) Closing unrelated fd no: 34 (/proc/cpuinfo5]ksm/sleep_millisecs)
 29 OProcess::(_processLogs) Closing unrelated fd no: 35 (pipe:[152921]5]ksm/sleep_millisecs)
 30 OProcess::(_processLogs) Closing unrelated fd no: 38 (pipe:[152921]5]ksm/sleep_millisecs)
 31 OProcess::(_processLogs) Closing unrelated fd no: 39 (socket:[152936]ksm/sleep_millisecs)
 32 OProcess::(_processLogs) Not closing FD 40 because it's in whitelist
 33 OProcess::(_processLogs) Not closing FD 41 because it's in whitelist
 34 OProcess::(_processLogs) Closing unrelated fd no: 42 (pipe:[154530]6]ksm/sleep_millisecs)

Comment 1 Federico Simoncelli 2014-07-01 09:42:55 UTC
Created attachment 913717 [details]
vdsm-bz1114924.log.gz

Comment 2 Federico Simoncelli 2014-08-01 10:47:58 UTC
Version-Release number of selected component (if applicable):
python-ioprocess-0.6.1-1.el6.noarch
ioprocess-0.6.1-1.el6.x86_64

I don't think this is the expected behavior:

Thread-14::DEBUG::2014-08-01 10:44:26,550::__init__::232::IOProcess::(_processLogs) (1303) Got request for method 'statvfs'DEBUG|(1303) Queuing responseDEBUG|Extracting request information...DEBUG|(1304) Got reque
st for method 'statvfs'DEBUG|(1304) Queuing responseDEBUG|(1301) Queuing responseDEBUG|Extracting request information...DEBUG|(1306) Got request for method 'statvfs'DEBUG|(1306) Queuing responseDEBUG|(1309) Queuin
g responseDEBUG|(1311) Queuing responseDEBUG|Extracting request information...DEBUG|(1312) Got request for method 'statvfs'DEBUG|(1312) Queuing responseDEBUG|(1313) Queuing responseDEBUG|Extracting request informa
tion...DEBUG|(1314) Got request for method 'statvfs'DEBUG|(1314) Queuing responseDEBUG|Extracting request information...DEBUG|(1315) Got request for method 'statvfs'DEBUG|(1315) Queuing responseDEBUG|(1316) Queuin
g responseDEBUG|(1319) Queuing responseDEBUG|(1321) Queuing responseDEBUG|(1322) Queuing responseDEBUG|(1331) Queuing responseDEBUG|Extracting request information...DEBUG|(1333) Got request for method 'statvfs'DEB
UG|(1333) Queuing responseDEBUG|Extracting request information...DEBUG|(1334) Got request for method 'statvfs'DEBUG|(1334) Queuing responseDEBUG|(1336) Queuing responseDEBUG|(1337) Queuing responseDEBUG|(1343) Que
uing responseDEBUG|(1345) Queuing responseDEBUG|(1347) Queuing responseDEBUG|(1351) Queuing responseDEBUG|(1352) Queuing responseDEBUG|(1355) Queuing responseDEBUG|(1357) Queuing responseDEBUG|Extracting request i
nformation...DEBUG|(1359) Got request for method 'access'DEBUG|(1359) Queuing responseDEBUG|Extracting request information...DEBUG|(1360) Got request for method 'access'DEBUG|(1360) Queuing responseDEBUG|(1362) Qu
euing responseDEBUG|(1361) Queuing responseDEBUG|Receiving request...

It's probably a side-effect of the missing terminator.

Comment 3 Saggi Mizrahi 2014-08-26 12:34:34 UTC
This was merged in http://gerrit.ovirt.org/#/c/30977/
and is already in ioprocess 0.10.0.