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

[Sam Bobroff]

On Mon, Dec 14, 2015 at 03:29:49PM +0800, Stefan Hajnoczi wrote:
> On Mon, Dec 14, 2015 at 04:19:50PM +1100, Sam Bobroff wrote:
> > On Thu, Dec 10, 2015 at 04:37:22PM +0800, Stefan Hajnoczi wrote:
> > > On Mon, Dec 07, 2015 at 02:22:18PM +1100, Sam Bobroff wrote:
> > > > 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?
> > > 
> > > This is unfortunate.  I wonder if opening /proc/fd/<n> is just a dup or
> > > if it actually creates separate file status flags.
> > 
> > Calling open() always creates a new "file description" (which contains file
> > status flags), so it's certainly a way to approach this.
> > 
> > I've testing doing this if we're going to use stderr as the qemu_logfile:
> > 
> >     dup2(open("/proc/self/fd/2", O_WRONLY), 2)
> > 
> > ... in do_qemu_set_log() and it fixes the issue, however...
> 
> Thanks for trying it out.  Will you send a patch?
>
> > * Doing the dup2() causes it to fix any other fprintf()s to stderr, but
> >   I feel bad for changing the fd that's inside the stderr "FILE *" 
> > "underneath
> >   it". Would it be better to do the following...
> >     qemu_logfile = fopen("/proc/self/fd/2", "a")
> >   ... even though that will leave other fprintf()s unfixed. (I think that is
> >   probably OK.)
> > * We could also unconditionally do the dup2(), maybe early in main().
> 
> This is probably the cleanest way to solve the problem.  Early on during
> startup QEMU can "undup" stderr and never worry about it again.

OK.

> > * I'm not sure which platforms other than modern Linux support
> >   /proc/self/fd/<n>. (Just fixing it for Linux seems a lot better than
> >   nothing.)
> 
> This workaround is platform-specific but still useful (on Linux).
> 
> > * We could print a warning if stderr is nonblocking and we can't work around
> >   it. This seems like a good idea even if don't fix it for Linux.
> 
> This is good when the workaround is not possible.

OK, I'll include this too.

> > * We could also handle it by converting the qemu_log_mask calls from 
> > fprintf()
> >   to sprintf() + write(), as we'd then be able to handle EAGAIN correctly. 
> > This
> >   doesn't feel any cleaner to me.
> 
> I agree.  Bypassing fprintf() doesn't help since the fd is still
> O_NONBLOCK.

That wasn't exactly what I was trying to say, what I meant was that it *would*
help but that I don't think it's a good solution. I'll explain (sorry if I'm
over-explaining!):

The problem with fprintf() is that it may write "some" bytes and then return
failure, so it's impossible to handle the EAGAIN case correctly even if we
wanted to: we can't know where to continue writing. IMHO, this seems like it
could be considered a bug in fprintf().

Because write() always indicates how many bytes were written, we could manually
block on EAGAIN and resume writing at the correct place. But this would be
slower, require a local buffer (that may need to be resized sometimes) and more
complex code, so I don't think it's a good fix.  Although, it would be much more
portable and it would work.

Would you like me to post a patch for the re-open approach or explore the
sprintf()/write() idea?

Cheers,
Sam.