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

[Robert Foley]

On Thu, 7 Nov 2019 at 15:12, Alex Bennée <address@hidden> wrote:
>
>
> > 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.
>

This makes sense, will remove the if (logfilename).

> > 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.
>

Interesting.  We had assumed it was just the way we were running the
test.  But it sounds like something about our particular setup.  I'm
using Ubuntu bionic on an aarch64 system.  Will look further.

Thanks,
-Rob Foley
On Thu, 7 Nov 2019 at 15:12, Alex Bennée <address@hidden> wrote:
>
>
> 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