Bug 351043

Summary: Invalid XML output when tracing into forked child processes
Product: [Developer tools] valgrind Reporter: Matt Blythe <mblythester>
Component: memcheckAssignee: Julian Seward <jseward>
Status: REPORTED ---    
Severity: normal CC: andykras, ivosh
Priority: NOR    
Version: 3.10.0   
Target Milestone: ---   
Platform: Compiled Sources   
OS: Linux   
Latest Commit: Version Fixed In:
Sentry Crash Report:
Attachments: fork.patch brought forward to valgrind 3.11

Description Matt Blythe 2015-08-06 20:27:39 UTC
When running valgrind with XML output on a program that forks itself, the XML file that is produced is invalid.  Specifically, there are more </valgrindoutput> closing tags than there are opening tags.

This is essentially a duplicate of bug 336976, except I tried adding a '%p' to the logfile name, and it didn't have any effect.  (I would have re-opened that bug, but it looks like only the original reporter can do that?)

Looking through the other valgrind bugs, this may also be related to bugs 162848 or 253308.

Here's the source file that I'm using (I'm calling it test.cpp):

//==== start C++ source ====
#include <unistd.h>
int main(){
  fork();
  int *ptr = new int;
  *ptr = 42;
  delete ptr;
  *ptr = 0;
  return 0;
}
//==== end C++ source ====

Reproducible: Always

Steps to Reproduce:
1. g++ -o test -g test.cc
2. valgrind --xml=yes --xml-file=out_%p.xml ./test
3. examine the produced out*.xml file

Actual Results:  
Here's the file that valgrind produced for me (in a single file, out_15543.xml):
<?xml version="1.0"?>

<valgrindoutput>

<protocolversion>4</protocolversion>
<protocoltool>memcheck</protocoltool>

<preamble>
  <line>Memcheck, a memory error detector</line>
  <line>Copyright (C) 2002-2013, and GNU GPL'd, by Julian Seward et al.</line>
  <line>Using Valgrind-3.10.1 and LibVEX; rerun with -h for copyright info</line>
  <line>Command: ./test</line>
</preamble>

<pid>15543</pid>
<ppid>9636</ppid>
<tool>memcheck</tool>

<args>
  <vargv>
    <exe>/path/to/valgrind/bin/valgrind</exe>
    <arg>--xml=yes</arg>
    <arg>--xml-file=out_%p.xml</arg>
  </vargv>
  <argv>
    <exe>./test</exe>
  </argv>
</args>

<status>
  <state>RUNNING</state>
  <time>00:00:00:00.005 </time>
</status>

<error>
  <unique>0x7</unique>
  <tid>1</tid>
  <kind>InvalidWrite</kind>
  <what>Invalid write of size 4</what>
  <stack>
    <frame>
      <ip>0x4006B2</ip>
      <obj>/home/mblythe/valgrind_bug/test</obj>
      <fn>main</fn>
      <dir>/home/mblythe/valgrind_bug</dir>
      <file>test.cc</file>
      <line>8</line>
    </frame>
  </stack>
  <auxwhat>Address 0x514c040 is 0 bytes inside a block of size 4 free'd</auxwhat>
  <stack>
    <frame>
      <ip>0x4A08021</ip>
      <obj>/path/to/valgrind/lib/valgrind/vgpreload_memcheck-amd64-linux.so</obj>
      <fn>operator delete(void*)</fn>
      <dir>/tmp/valgrind-3.10.1/coregrind/m_replacemalloc</dir>
      <file>vg_replace_malloc.c</file>
      <line>507</line>
    </frame>
    <frame>
      <ip>0x4006AD</ip>
      <obj>/home/mblythe/valgrind_bug/test</obj>
      <fn>main</fn>
      <dir>/home/mblythe/valgrind_bug</dir>
      <file>test.cc</file>
      <line>7</line>
    </frame>
  </stack>
</error>

<error>
  <unique>0x7</unique>
  <tid>1</tid>
  <kind>InvalidWrite</kind>
  <what>Invalid write of size 4</what>
  <stack>
    <frame>
      <ip>0x4006B2</ip>
      <obj>/home/mblythe/valgrind_bug/test</obj>
      <fn>main</fn>
      <dir>/home/mblythe/valgrind_bug</dir>
      <file>test.cc</file>
      <line>8</line>
    </frame>
  </stack>
  <auxwhat>Address 0x514c040 is 0 bytes inside a block of size 4 free'd</auxwhat>
  <stack>
    <frame>
      <ip>0x4A08021</ip>
      <obj>/path/to/valgrind/lib/valgrind/vgpreload_memcheck-amd64-linux.so</obj>
      <fn>operator delete(void*)</fn>
      <dir>/tmp/valgrind-3.10.1/coregrind/m_replacemalloc</dir>
      <file>vg_replace_malloc.c</file>
      <line>507</line>
    </frame>
    <frame>
      <ip>0x4006AD</ip>
      <obj>/home/mblythe/valgrind_bug/test</obj>
      <fn>main</fn>
      <dir>/home/mblythe/valgrind_bug</dir>
      <file>test.cc</file>
      <line>7</line>
    </frame>
  </stack>
</error>


<status>
  <state>FINISHED</state>
  <time>00:00:00:01.024 </time>
</status>

<errorcounts>
  <pair>
    <count>1</count>
    <unique>0x7</unique>
  </pair>
</errorcounts>

<suppcounts>
  <pair>
    <count>7</count>
    <name>dl-hack3</name>
  </pair>
</suppcounts>

</valgrindoutput>


<status>
  <state>FINISHED</state>
  <time>00:00:00:01.032 </time>
</status>

<errorcounts>
  <pair>
    <count>1</count>
    <unique>0x7</unique>
  </pair>
</errorcounts>

<suppcounts>
  <pair>
    <count>7</count>
    <name>dl-hack3</name>
  </pair>
</suppcounts>

</valgrindoutput>



Expected Results:  
There should have been 2 files produced, one for the parent process, and one for the child process.  Each file should be valid XML.

Alternatively, if there is no '%p' in the --xml-file option, I would expect a single, valid XML file with multiple <valgrindoutput> sections, each one with the details of valgrind from a different process.
Comment 1 Andrew Kraslavsky 2016-01-25 20:45:07 UTC
I hit the same issue and observed that it applies to both --log-file and --xml-file and that the issue exists in valgrind version 3.11.

I brought the patch at the link below forward to version 3.11 and it seems to address the issue.

https://chromium.googlesource.com/chromium/src/tools/valgrind/+/77eb74bd17f76978be25436f17025a29ba3b9a1f/fork.patch

I'm not sure the valgrind developers would accept this patch as is because it seems just a tiny bit messy in incidental ways (e.g. print_preamble() declaration probably belongs in a header file, VG_(reopen_fd) may not really belong in m_main.c, etc...) but the basic notion of closing the original file and opening a new on in the child side atfork function seems sound.

In any case, I will attach the revised version of the patch I applied to my local valgrind v3.11 build to this bug report.
Comment 2 Andrew Kraslavsky 2016-01-25 20:47:28 UTC
Created attachment 96840 [details]
fork.patch brought forward to valgrind 3.11
Comment 3 Ivo Raisr 2017-01-31 22:06:49 UTC
This is probably fixed with the fix for bug 162848.
Please report if Valgrind built from latest sources works for you.