Re: [PATCH 4/4] Added tests for close and change of logfile.

[Alex Bennée]

Robert Foley <address@hidden> writes:

> Thanks for providing the stack trace.
>
> We debugged this and it seems to come about because of an interesting
> circumstance.  We added our new tests after a pre-existing test,
> parse_path(), which runs into an issue, a dangling pointer, which
> could lead to a double free.  There were no other tests after the test
> that ran into the issue, so the double free was not exposed until we
> added our test which called qemu_set_log_filename().
>
> Upon entry to qemu_set_log_filename() it frees logfilename.   In the
> case where we get an error, we return out without setting the
> logfilename to NULL.
> And on next call into this function we will end up with a double free.
>
> For a fix, we could put this at the beginning of qemu_set_log_filename().
> if (logfilename) {
>     g_free(logfilename);
>     logfilename = NULL;
> }

g_free(logfilename) should be safe against NULL. However we need to
ensure that logfilename is NULL'ed after it so we don't see the double
free.

> We were curious to understand why we did not see it in our own
> testing.  Although we did run make check before our first post, we did
> not see this issue.  The docker tests seem to use something like
> MALLOC_CHECK_, which catches memory issues like this.   We will be
> sure to run the docker tests as well in the future.

I was just running in my normal checkout - it could depend on how glibc
was built for your system though. Mine is Debian Buster.

>
> On Thu, 7 Nov 2019 at 12:26, Alex Bennée <address@hidden> wrote:
>>
>>
>> Alex Bennée <address@hidden> writes:
>>
>> > Robert Foley <address@hidden> writes:
>> >
>> >> One test ensures that the logfile handle is still valid even if
>> >> the logfile is changed during logging.
>> >> The other test validates that the logfile handle remains valid under
>> >> the logfile lock even if the logfile is closed.
>>
>> Also this doesn't see to work:
>>
>> 17:24:31 [alex@zen:~/l/q/b/all] review/rcu-logfile|… 2 + ./tests/test-logging
>> /logging/parse_range: OK
>> /logging/parse_path: OK
>> /logging/logfile_write_path: free(): double free detected in tcache 2
>> fish: “./tests/test-logging” terminated by signal SIGABRT (Abort)
>>
>> in gdb
>>
>> Starting program: /home/alex/lsrc/qemu.git/builds/all/tests/test-logging
>> [Thread debugging using libthread_db enabled]
>> Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
>> [New Thread 0x7ffff6f38700 (LWP 28960)]
>> /logging/parse_range: OK
>> /logging/parse_path: OK
>> /logging/logfile_write_path: free(): double free detected in tcache 2
>>
>> Thread 1 "test-logging" received signal SIGABRT, Aborted.
>> __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
>> 50      ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
>> (gdb) bt
>> #0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
>> #1  0x00007ffff7587535 in __GI_abort () at abort.c:79
>> #2  0x00007ffff75de508 in __libc_message (action=action@entry=do_abort, 
>> fmt=fmt@entry=0x7ffff76e928d "%s\n") at ../sysdeps/posix/libc_fatal.c:181
>> #3  0x00007ffff75e4c1a in malloc_printerr (str=str@entry=0x7ffff76eaf58 
>> "free(): double free detected in tcache 2") at malloc.c:5341
>> #4  0x00007ffff75e66fd in _int_free (av=0x7ffff7720c40 <main_arena>, 
>> p=0x5555555cac40, have_lock=<optimized out>) at malloc.c:4193
>> #5  0x00005555555614a8 in qemu_set_log_filename (filename=0x5555555cb110 
>> "/tmp/qemu-test-logging.RO35A0/qemu_test_log_write0.log", 
>> errp=0x7fffffffdef0) at /home/alex/lsrc/qemu.git/util/log.c:148
>> #6  0x000055555555d8be in test_logfile_write (data=0x5555555c7370) at 
>> /home/alex/lsrc/qemu.git/tests/test-logging.c:127
>> #7  0x00007ffff7cdc15a in test_case_run (tc=0x5555555c9c60) at 
>> ../../../glib/gtestutils.c:2318
>> #8  g_test_run_suite_internal (suite=suite@entry=0x5555555c8a40, 
>> path=path@entry=0x0) at ../../../glib/gtestutils.c:2403
>> #9  0x00007ffff7cdc014 in g_test_run_suite_internal 
>> (suite=suite@entry=0x5555555c8a20, path=path@entry=0x0) at 
>> ../../../glib/gtestutils.c:2415
>> #10 0x00007ffff7cdc412 in g_test_run_suite (suite=0x5555555c8a20) at 
>> ../../../glib/gtestutils.c:2490
>> #11 0x00007ffff7cdc431 in g_test_run () at ../../../glib/gtestutils.c:1755
>> #12 0x000055555555ce07 in main (argc=<optimized out>, argv=<optimized out>) 
>> at /home/alex/lsrc/qemu.git/tests/test-logging.c:212
>>
>>
>> >>
>> >> Signed-off-by: Robert Foley <address@hidden>
>> >> ---
>> >>  tests/test-logging.c | 74 ++++++++++++++++++++++++++++++++++++++++++++
>> >>  1 file changed, 74 insertions(+)
>> >>
>> >> diff --git a/tests/test-logging.c b/tests/test-logging.c
>> >> index a12585f70a..a3190ff92c 100644
>> >> --- a/tests/test-logging.c
>> >> +++ b/tests/test-logging.c
>> >> @@ -108,6 +108,76 @@ static void test_parse_path(gconstpointer data)
>> >>      error_free_or_abort(&err);
>> >>  }
>> >>
>> >> +static void test_logfile_write(gconstpointer data)
>> >> +{
>> >> +    QemuLogFile *logfile;
>> >> +    gchar const *dir = data;
>> >> +    Error *err = NULL;
>> >> +    gchar *file_path;
>> >> +    gchar *file_path1;
>> >
>> >   with g_autofree char *file_path you can avoid the free down bellow.
>> >
>> >> +    FILE *orig_fd;
>> >> +
>> >> +    file_path = g_build_filename(dir, "qemu_test_log_write0.log", NULL);
>> >> +    file_path1 = g_build_filename(dir, "qemu_test_log_write1.log", NULL);
>> >> +
>> >> +    /*
>> >> +     * Test that even if an open file handle is changed,
>> >> +     * our handle remains valid due to RCU.
>> >> +     */
>> >> +    qemu_set_log_filename(file_path, &err);
>> >> +    g_assert(!err);
>> >> +    rcu_read_lock();
>> >> +    logfile = atomic_rcu_read(&qemu_logfile);
>> >> +    orig_fd = logfile->fd;
>> >> +    g_assert(logfile && logfile->fd);
>> >> +    fprintf(logfile->fd, "%s 1st write to file\n", __func__);
>> >> +    fflush(logfile->fd);
>> >> +
>> >> +    /* Change the logfile and ensure that the handle is still valid. */
>> >> +    qemu_set_log_filename(file_path1, &err);
>> >> +    g_assert(!err);
>> >
>> > Maybe better would be:
>> >
>> >   logfile2 = atomic_rcu_read(&qemu_logfile);
>> >   g_assert(logfile->fd == orig_fd);
>> >   g_assert(logfile2->fd != logfile->fd);
>> >   fprintf(logfile2->fd, "%s 2nd write to file\n", __func__);
>> >   fflush(logfile2->fd);
>> >
>> > <snip>
>> >> +    g_assert(logfile->fd == orig_fd);
>> >> +    fprintf(logfile->fd, "%s 2nd write to file\n", __func__);
>> >> +    fflush(logfile->fd);
>> >> +    rcu_read_unlock();
>> >> +
>> >> +    g_free(file_path);
>> >> +    g_free(file_path1);
>> >> +}
>> >> +
>> >> +static void test_logfile_lock(gconstpointer data)
>> >> +{
>> >> +    FILE *logfile;
>> >> +    gchar const *dir = data;
>> >> +    Error *err = NULL;
>> >> +    gchar *file_path;
>> >
>> > g_autofree
>> >
>> >> +
>> >> +    file_path = g_build_filename(dir, "qemu_test_logfile_lock0.log", 
>> >> NULL);
>> >> +
>> >> +    /*
>> >> +     * Test the use of the logfile lock, such
>> >> +     * that even if an open file handle is closed,
>> >> +     * our handle remains valid for use due to RCU.
>> >> +     */
>> >> +    qemu_set_log_filename(file_path, &err);
>> >> +    logfile = qemu_log_lock();
>> >> +    g_assert(logfile);
>> >> +    fprintf(logfile, "%s 1st write to file\n", __func__);
>> >> +    fflush(logfile);
>> >> +
>> >> +    /*
>> >> +     * Initiate a close file and make sure our handle remains
>> >> +     * valid since we still have the logfile lock.
>> >> +     */
>> >> +    qemu_log_close();
>> >> +    fprintf(logfile, "%s 2nd write to file\n", __func__);
>> >> +    fflush(logfile);
>> >> +    qemu_log_unlock(logfile);
>> >> +
>> >> +    g_assert(!err);
>> >> +    g_free(file_path);
>> >> +}
>> >> +
>> >>  /* Remove a directory and all its entries (non-recursive). */
>> >>  static void rmdir_full(gchar const *root)
>> >>  {
>> >> @@ -134,6 +204,10 @@ int main(int argc, char **argv)
>> >>
>> >>      g_test_add_func("/logging/parse_range", test_parse_range);
>> >>      g_test_add_data_func("/logging/parse_path", tmp_path, 
>> >> test_parse_path);
>> >> +    g_test_add_data_func("/logging/logfile_write_path",
>> >> +                         tmp_path, test_logfile_write);
>> >> +    g_test_add_data_func("/logging/logfile_lock_path",
>> >> +                         tmp_path, test_logfile_lock);
>> >>
>> >>      rc = g_test_run();
>>
>>
>> --
>> Alex Bennée


--
Alex Bennée