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

[Alex Bennée]

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