logfile issue

[Robert Foley]

We hit an issue when trying to change the log file from the monitor
console.  The root of the issue here is that the qemu_logfile handle
is not thread safe.  So when we try to close the file, we end up with
a seg fault.  The full analysis is below along with some possible
solutions.
Will plan to post a patch soon, but any comments or opinions on our
proposed solution would be appreciated.  Thanks.

The version of QEMU we are using is: master as of about Oct 15,
9020e9526cd08c4dc99d54dba48730de2908c970.

This is what we did to reproduce the issue.
First we enable logging and select the log file.
(qemu) log in_asm,out_asm,op
(qemu) logfile asm.out

Then we start this command in the guest.  This just keeps the guest
performing operations that result in logging to be constantly
generated.
$ for i in {0..1000}; do ls -l; done

Next we switch to the monitor console and change the file.
(qemu) logfile asm_new.log

This action causes a seg fault.  Please see the stack trace (below).

The code, which changes the log file unconditionally
(qemu_set_log_filename()), closes the qemu_logfile, sets it to NULL,
and then opens the new file.
Since the file handle is still in use, we end up with a seg fault when
the code which is trying to log ends up using a NULL file handle.

We are considering a few solutions.

A straightforward solution would be to simply prevent the file from
being changed while logging is enabled.  In other words, force the
user to first disable logging before changing the log file.
This solution seems to cover the general case.  However, if a user
were to disable logging and change the log file in quick succession,
we would still be subject to a similar race.  A log call could still
make it through the logging enable check and proceed to use a file
handle that gets changed to NULL.

Another option is to add a mutex to prevent the qemu_logfile handle
from being changed while it is in use.  This certainly works and has
the advantage of being fairly straightforward.  Also we are thinking
that since the mutex would only be used when logging is enabled it has
the advantage of not having an effect on the normal case performance.
Another option is to implement a simple atomic ref count and prevent
the file from being changed while there are outstanding references.

We are leaning towards the mutex option, and plan to post a patch
soon, but would appreciate comments or opinions on this solution.

Thanks,
Rob Foley

stack trace
==========================================
Thread 10 "qemu-system-aar" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0xffff113f9d90 (LWP 9493)] __flockfile
(stream=0x0) at ../sysdeps/pthread/flockfile.c:27
27 ../sysdeps/pthread/flockfile.c: No such file or directory.
(gdb) bt
#0  __flockfile (stream=0x0) at ../sysdeps/pthread/flockfile.c:27
#1  0x0000aaaae0fac8b8 in qemu_flockfile (f=<optimized out>) at
/home/rob/qemu/qemu_unchanged/include/sysemu/os-posix.h:87
#2  qemu_log_lock () at /home/rob/qemu/qemu_unchanged/include/qemu/log.h:57
#3  translator_loop (ops=0xaaaae17f1348 <aarch64_translator_ops>,
db=0xffff113f9088, db@entry=0xffff113f9098,
cpu=cpu@entry=0xaaab0a52bc50,
    tb=tb@entry=0xffff4c92d000 <code_gen_buffer+814927796>,
max_insns=max_insns@entry=512) at
/home/rob/qemu/qemu_unchanged/accel/tcg/translator.c:121
#4  0x0000aaaae10c1c18 in gen_intermediate_code
(cpu=cpu@entry=0xaaab0a52bc50, tb=tb@entry=0xffff4c92d000
<code_gen_buffer+814927796>, max_insns=max_insns@entry=512)
    at /home/rob/qemu/qemu_unchanged/target/arm/translate.c:11320
#5  0x0000aaaae0fab248 in tb_gen_code (cpu=0xaaab0a52bc50,
cpu@entry=0xffffabe2a000, pc=187650897458448, cs_base=65536,
flags=43690, cflags=-16252928, cflags@entry=524288)
    at /home/rob/qemu/qemu_unchanged/accel/tcg/translate-all.c:1738
#6  0x0000aaaae0fa8e74 in tb_find (cf_mask=524288, tb_exit=0,
last_tb=0xffff4c92cc40 <code_gen_buffer+814926836>,
cpu=0xffffabe2a000)
    at /home/rob/qemu/qemu_unchanged/accel/tcg/cpu-exec.c:408
#7  cpu_exec (cpu=0xffffabe2a000, cpu@entry=0xaaab0a52bc50) at
/home/rob/qemu/qemu_unchanged/accel/tcg/cpu-exec.c:730
#8  0x0000aaaae0f6de24 in tcg_cpu_exec (cpu=0xaaab0a52bc50) at
/home/rob/qemu/qemu_unchanged/cpus.c:1454
#9  0x0000aaaae0f70908 in qemu_tcg_cpu_thread_fn (arg=0xaaab0a52bc50)
at /home/rob/qemu/qemu_unchanged/cpus.c:1762
#10 0x0000aaaae145bd38 in qemu_thread_start (args=<optimized out>) at
/home/rob/qemu/qemu_unchanged/util/qemu-thread-posix.c:519
#11 0x0000ffffabe0a088 in start_thread (arg=0xffffcc20410f) at
pthread_create.c:463
#12 0x0000ffffabd7a4ec in thread_start () at
../sysdeps/unix/sysv/linux/aarch64/clone.S:78