On 12/06/2012 10:41 AM, Laine Stump wrote: > On 12/06/2012 07:34 AM, Daniel P. Berrange wrote: >> On Thu, Dec 06, 2012 at 07:29:12AM -0500, Laine Stump wrote: >>> On 12/06/2012 06:34 AM, Michal Privoznik wrote: >>>> If the debugging is enabled, the virCommand subsystem catches debug >>>> messages in the command output as well. In that case, we can't assume >>>> the string corresponding to command's stdout will start with specific >>>> prefix. But the prefix can be moved deeper in the string. This bug >>>> shows itself when parsing dnsmasq output: >>>> >>>> 2012-12-06 11:18:11.445+0000: 18491: error : >>>> dnsmasqCapsSetFromBuffer:664 : internal error cannot parse >>>> /usr/sbin/dnsmasq version number in '2012-12-06 11:11:02.232+0000: >>>> 18492: debug : virFileClose:72 : Closed fd 22' >>>> >>>> We can clearly see that the output of dnsmasq --version >>>> doesn't start with expected "Dnsmasq version " string but a libvirt >>>> debug output. >>> This is a bug in virCommand, and should also affect >>> qemuCapsParseHelpStr(). Is there no way to fix it at the source, rather >>> than working around it like this? >> Well the debug logging messages should be going to stderr, >> while the code should be parsing stdout. It sounds like >> something caused the logging messages on stderr to get >> mixed together with stdout. Ensuring that mix does not >> happen is likely the correct fix. > It turns out that fix is correct and works in this case (I had > redirected both because, not having access to every version of dnsmasq, > I couldn't know for certain that all versions sent the output of help > and version to stdout). But the fact remains that there is libvirtd > stderr leaking into the stderr output of the application being called, > and that's wrong. This behavior will cause problems if, for example, > libvirtd execs some program that does have useful output on stderr - > libvirtd's debug output will be mixed in. (Note that "qemu -device > virtio-net-pci,?", for example, sends its useful output to stderr.) > > Aside from that, didn't we previously determine that any kind of logging > in the child process prior to exec'ing the other binary was dangerous? Looking at this in more detail, it seems that there have been previous patches to attempt and quiet the log messages from virFileClose() in a child process (see d581313 and dfd458). VIR_MASS_CLOSE() (which is called by virFork()), in particular was created to avoid logging a VIR_WARN() in the case of close() returning EBADF. But it doesn't supress the other VIR_DEBUG() log outputs, which are arguably even *less* important than the VIR_WARN(). Based on this, I think it's proper to change the call in virFork() from VIR_MASS_CLOSE() to VIR_LOG_CLOSE(), which logs nothing. Opinions? (I'm also wondering if virFork() should be given info about whether or not stderr is being captured, and if so set the log priority to VIR_LOG_ERROR instead of virLogGetDefaultPriority(). Or is there maybe a way to maintain the original stderr fd until right before the exec?) -- libvir-list mailing list libvir-list@xxxxxxxxxx https://www.redhat.com/mailman/listinfo/libvir-list