Re: [Qemu-devel] Question about nonblocking stderr and lost logs

[Sam Bobroff]

On Fri, Dec 04, 2015 at 02:33:01PM +0800, Stefan Hajnoczi wrote:
> On Mon, Nov 30, 2015 at 04:34:47PM +1100, Sam Bobroff wrote:
> > Hi QEMU programmers,
> > 
> > While doing some experimental work on QEMU that has involved adding a lot of
> > new log messages (using qemu_log_mask()), I've discovered that under some
> > conditions a lot of my log messages go missing.
> > 
> > I've tracked the issue down to qemu_logfile being left at the default 
> > (stderr)
> > (so when not using -D) and according to strace what is happening is that the
> > debug messages are being passed to write() but write() is returning 
> > EWOULDBLOCK
> > and the messags are dropped.
> > 
> > This seems to be happening because stderr is being set non-blocking (which 
> > is a
> > bit odd to me), and it seems like NONBLOCK is being set as 
> > qmp_chardev_add() adds a
> > device for stdout (yes stdout, not stderr; perhaps file descriptors have 
> > been
> > dup'd by that point?).
> > 
> > Is this by design to prevent a slow console from blocking QEMU? If not, 
> > should
> > I delve further and try to prevent non-blocking being set on stderr?
> > 
> > (Unfortunately I don't have a replication for this using an unmodified QEMU 
> > but
> > I suspect I could find one if necessary.)
> 
> This sounds like a bug.  stderr should be blocking.
> 
> But it's specific to your QEMU build or your command-line.  Here are my
> results on an x86 host:
> 
> $ qemu-system-x86_64 -enable-kvm -m 1024 -cpu host \
>                      -drive if=virtio,cache=none,file=test.img,format=raw
> $ cat /proc/$(pgrep qemu)/fdinfo/2
> pos:  0
> flags:        0100002
> mnt_id:       22
> 
> The flags are O_RDWR | O_LARGEFILE.
> 
> O_NONBLOCK would have been 04000 (octal).
> 
> Please retry with qemu.git/master and post your QEMU command-line.
> 
> Stefan

Hi Stefan,

Thanks for checking this! I think I've worked out what's happening and it's a
bit complicated ;-)

It appears that the behaviour is not directly related to the command line or
build but rather the way the shell sets up the environment.

Here's a test very similar to yours using origin/master QEMU on my Debian
stable machine, with bash as my shell:

$ qemu-system-x86_64 -S -vga none -nographic
( In another virtual console: )
$ cat /proc/$(pgrep qemu)/fdinfo/2
pos:    0
flags:  0104002
mnt_id: 19

So I seem to have O_NONBLOCK set on stderr.

However, if I perform that test by backgrounding QEMU and using the same
console:
$ qemu-system-x86_64 -S -vga none -nographic &
[1] 4970
[1]+  Stopped                 qemu-system-x86_64 -S -nographic -vga none
$ cat /proc/$(pgrep qemu)/fdinfo/2
pos:    0
flags:  0100002
mnt_id: 19

Hmm!

After a bit of reading, it seems like this is caused by the fact that bash,
when there is no redirection, sets up fds 0, 1 and 2 by dup'ing a single file
descriptor. I found this surprising!

A small test program that sets O_NONBLOCK on fd 1 and checks for it on fd 2
seems to corroborate it:

#include <stdio.h>
#include <fcntl.h>
#include <assert.h>

int main() {
        int f1, f2;

        f1 = fcntl(1, F_GETFL, 0);
        f2 = fcntl(2, F_GETFL, 0);
        assert(!(f1 & O_NONBLOCK));
        assert(!(f2 & O_NONBLOCK));
        assert(!fcntl(1, F_SETFL, f1 | O_NONBLOCK));
        if (fcntl(2, F_GETFL, 0) & O_NONBLOCK)
                fprintf(stderr, "File descriptors are duplicates.\n");
        else
                fprintf(stderr, "File descriptors are separate.\n");
        return 0;
}

gcc -Wall foo.c
$ ./a.out
File descriptors are duplicates.
$ ./a.out > /dev/null
File descriptors are separate.

The nonblocking flag is always (?) being set on stdin and stdout during
qemu_chr_open_stdio(), but it doesn't affect stderr unless they are dup'd.

So this is probably not going to occur often, and certainly not when running
under libvirt or other tools. But if it is actually what is happening, I'm not
sure what to do about it. Any ideas?

Cheers,
Sam.