On Wed, Dec 16, 2015 at 11:53:16AM +1100, Sam Bobroff wrote:
> 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?The program may crash/terminate before stderr becomes writeable after EAGAIN. I prefer a reliable, blocking stderr so re-open seems like a good idea. Stefan
signature.asc
Description: PGP signature
