qemu-devel
[Top][All Lists]
Advanced

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

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


From: Robert Foley
Subject: Re: [PATCH 4/4] Added tests for close and change of logfile.
Date: Thu, 7 Nov 2019 14:38:47 -0500

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;
}

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.

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



reply via email to

[Prev in Thread] Current Thread [Next in Thread]