Skip to content
Snippets Groups Projects
Commit 7f44a9de authored by Simon McVittie's avatar Simon McVittie
Browse files

tests: Add some coverage for our logging setup

parent 516b106c
No related branches found
No related tags found
1 merge request!521Further logging improvements
/*
* Copyright © 2022 Collabora Ltd.
* SPDX-License-Identifier: MIT
*/
#include "libglnx.h"
#include <steam-runtime-tools/steam-runtime-tools.h>
#include "steam-runtime-tools/log-internal.h"
#include "steam-runtime-tools/utils-internal.h"
static gboolean opt_allow_journal = FALSE;
static gboolean opt_divert_stdout = FALSE;
static gboolean opt_keep_prgname = FALSE;
static const GOptionEntry option_entries[] =
{
{ "allow-journal", 0, G_OPTION_FLAG_NONE, G_OPTION_ARG_NONE,
&opt_allow_journal, "Set OPTIONALLY_JOURNAL flag", NULL },
{ "divert-stdout", 0, G_OPTION_FLAG_NONE, G_OPTION_ARG_NONE,
&opt_divert_stdout, "Set DIVERT_STDOUT flag", NULL },
{ "keep-prgname", 0, G_OPTION_FLAG_NONE, G_OPTION_ARG_NONE,
&opt_keep_prgname, "Don't call g_set_prgname()", NULL },
{ NULL }
};
int
main (int argc,
char **argv)
{
g_autoptr(GError) error = NULL;
g_autoptr(GOptionContext) option_context = NULL;
glnx_autofd int original_stdout = -1;
glnx_autofd int original_stderr = -1;
const char *prgname = "srt-tests-logging-helper";
const char *env;
SrtLogFlags flags = SRT_LOG_FLAGS_NONE;
option_context = g_option_context_new ("MESSAGE");
g_option_context_add_main_entries (option_context, option_entries, NULL);
if (!g_option_context_parse (option_context, &argc, &argv, &error))
{
g_warning ("%s: %s\n", prgname, error->message);
return 1;
}
if (opt_allow_journal)
flags |= SRT_LOG_FLAGS_OPTIONALLY_JOURNAL;
if (opt_divert_stdout)
flags |= SRT_LOG_FLAGS_DIVERT_STDOUT;
if (opt_keep_prgname)
prgname = NULL;
if (!_srt_util_set_glib_log_handler (prgname, G_LOG_DOMAIN, flags,
&original_stdout, &original_stderr, &error))
{
g_warning ("%s: %s\n", g_get_prgname (), error->message);
return 1;
}
/* _srt_util_set_glib_log_handler() ensures the three standard fds are
* open, even if only pointing to /dev/null */
g_assert_no_errno (fcntl (STDIN_FILENO, F_GETFL, 0));
g_assert_no_errno (fcntl (STDOUT_FILENO, F_GETFL, 0));
g_assert_no_errno (fcntl (STDERR_FILENO, F_GETFL, 0));
g_message ("%s", argv[1]);
env = g_getenv ("SRT_LOG");
g_message ("SRT_LOG=%s", env ?: "(null)");
if (_srt_boolean_environment ("SRT_LOG_TO_JOURNAL", FALSE))
g_message ("SRT_LOG_TO_JOURNAL is true");
if (_srt_boolean_environment ("PRESSURE_VESSEL_LOG_INFO", FALSE))
g_message ("P_V_LOG_INFO is true");
if (_srt_boolean_environment ("PRESSURE_VESSEL_LOG_WITH_TIMESTAMP", FALSE))
g_message ("P_V_LOG_WITH_TIMESTAMP is true");
g_message ("flags: allow_journal=%d divert_stdout=%d keep_prgname=%d",
opt_allow_journal, opt_divert_stdout, opt_keep_prgname);
g_print ("stdout while running\n");
g_printerr ("stderr while running\n");
g_debug ("debug message");
g_info ("info message");
g_message ("notice message");
if ((original_stdout >= 0
&& !_srt_util_restore_saved_fd (original_stdout, STDOUT_FILENO, &error))
|| (original_stderr >= 0
&& !_srt_util_restore_saved_fd (original_stderr, STDERR_FILENO, &error)))
{
g_warning ("%s: %s\n", prgname, error->message);
return 1;
}
g_print ("original stdout\n");
g_printerr ("original stderr\n");
return 0;
}
......@@ -140,6 +140,15 @@ executable(
install_dir : tests_dir,
)
executable(
'logging-helper',
'logging-helper.c',
dependencies : [glib, libglnx_dep, libsteamrt_static_dep],
include_directories : project_include_dirs,
install : get_option('installed_tests'),
install_dir : tests_dir,
)
# A list of strings each of this form:
# test-name:any one-line shell command, which will include ${G_TEST_BUILDDIR}
# A typical example:
......
......@@ -25,8 +25,10 @@
#include <steam-runtime-tools/steam-runtime-tools.h>
#include <dlfcn.h>
#include <sys/resource.h>
#include <sys/time.h>
#include <syslog.h>
#include <glib.h>
#include <glib/gstdio.h>
......@@ -37,9 +39,17 @@
#include "steam-runtime-tools/utils-internal.h"
#include "test-utils.h"
typedef void *AutoLibraryHandle;
G_DEFINE_AUTO_CLEANUP_FREE_FUNC (AutoLibraryHandle, dlclose, NULL);
typedef int (*type_of_sd_journal_stream_fd) (const char *, int, int);
static const char *argv0 = NULL;
typedef struct
{
int unused;
gchar *srcdir;
gchar *builddir;
gchar *logging_helper;
} Fixture;
typedef struct
......@@ -52,6 +62,17 @@ setup (Fixture *f,
gconstpointer context)
{
G_GNUC_UNUSED const Config *config = context;
f->srcdir = g_strdup (g_getenv ("G_TEST_SRCDIR"));
f->builddir = g_strdup (g_getenv ("G_TEST_BUILDDIR"));
if (f->srcdir == NULL)
f->srcdir = g_path_get_dirname (argv0);
if (f->builddir == NULL)
f->builddir = g_path_get_dirname (argv0);
f->logging_helper = g_build_filename (f->builddir, "logging-helper", NULL);
}
static void
......@@ -59,6 +80,10 @@ teardown (Fixture *f,
gconstpointer context)
{
G_GNUC_UNUSED const Config *config = context;
g_free (f->srcdir);
g_free (f->builddir);
g_free (f->logging_helper);
}
static void
......@@ -592,6 +617,263 @@ test_hash_iter (Fixture *f,
g_test_message ("(key) -> %s", v);
}
typedef enum
{
LOGGING_TEST_BASIC = 0,
LOGGING_TEST_FLAGS,
LOGGING_TEST_FLAGS_OLD,
LOGGING_TEST_TO_JOURNAL,
LOGGING_TEST_TO_JOURNAL_OLD,
LOGGING_TEST_NOT_TO_JOURNAL,
LOGGING_TEST_DIFFABLE,
LOGGING_TEST_DIFFABLE_PID,
LOGGING_TEST_NO_AUTO_JOURNAL,
LOGGING_TEST_AUTO_JOURNAL,
N_LOGGING_TESTS
} LoggingTest;
typedef struct
{
gboolean close_stdin;
gboolean close_stdout;
gboolean close_stderr;
} ChildSetupData;
static void
child_setup (gpointer user_data)
{
ChildSetupData *data = user_data;
if (data == NULL)
_exit (1);
if (data->close_stdin)
close (STDIN_FILENO);
if (data->close_stdout)
close (STDOUT_FILENO);
if (data->close_stderr)
close (STDERR_FILENO);
}
static void
test_logging (Fixture *f,
gconstpointer context)
{
int i;
g_auto(AutoLibraryHandle) handle = NULL;
type_of_sd_journal_stream_fd sym = NULL;
glnx_autofd int journal_fd = -1;
handle = dlopen ("libsystemd.so.0", RTLD_NOW | RTLD_LOCAL | RTLD_NODELETE);
if (handle != NULL)
{
sym = (type_of_sd_journal_stream_fd) dlsym (handle, "sd_journal_stream_fd");
if (sym != NULL)
journal_fd = sym ("srt-utils-test", LOG_DEBUG, FALSE);
}
for (i = LOGGING_TEST_BASIC; i < N_LOGGING_TESTS; i++)
{
g_autoptr(GError) error = NULL;
g_auto(GStrv) envp = g_get_environ ();
GSpawnFlags spawn_flags = G_SPAWN_DEFAULT;
ChildSetupData child_setup_data = {};
g_autofree gchar *out = NULL;
g_autofree gchar *err = NULL;
int wait_status = -1;
const char *argv[10] = { NULL };
const char *title;
int argc = 0;
envp = g_environ_unsetenv (envp, "SRT_LOG");
envp = g_environ_unsetenv (envp, "G_MESSAGES_DEBUG");
envp = g_environ_unsetenv (envp, "SRT_LOG_TO_JOURNAL");
envp = g_environ_unsetenv (envp, "PRESSURE_VESSEL_LOG_INFO");
envp = g_environ_unsetenv (envp, "PRESSURE_VESSEL_LOG_WITH_TIMESTAMP");
argv[argc++] = f->logging_helper;
switch (i)
{
case LOGGING_TEST_BASIC:
default:
title = "Basic logging test";
break;
case LOGGING_TEST_FLAGS:
envp = g_environ_setenv (envp, "SRT_LOG",
"debug,info,timestamp,timing,journal",
TRUE);
argv[argc++] = "--divert-stdout";
argv[argc++] = "--keep-prgname";
child_setup_data.close_stdin = TRUE;
title = "Various flags set";
break;
case LOGGING_TEST_FLAGS_OLD:
envp = g_environ_setenv (envp, "PRESSURE_VESSEL_LOG_INFO", "1", TRUE);
envp = g_environ_setenv (envp, "PRESSURE_VESSEL_LOG_WITH_TIMESTAMP", "1", TRUE);
argv[argc++] = "--allow-journal";
title = "Old environment variables set";
break;
case LOGGING_TEST_TO_JOURNAL:
envp = g_environ_setenv (envp, "SRT_LOG", "journal", TRUE);
argv[argc++] = "--allow-journal";
argv[argc++] = "--divert-stdout";
title = "Diverting to Journal";
break;
case LOGGING_TEST_TO_JOURNAL_OLD:
envp = g_environ_setenv (envp, "SRT_LOG_TO_JOURNAL", "1", TRUE);
argv[argc++] = "--allow-journal";
title = "Diverting to Journal (old environment variable)";
break;
case LOGGING_TEST_NOT_TO_JOURNAL:
envp = g_environ_setenv (envp, "SRT_LOG", "journal", TRUE);
envp = g_environ_setenv (envp, "SRT_LOG_TO_JOURNAL", "0", TRUE);
argv[argc++] = "--allow-journal";
title = "Not diverting to Journal because SRT_LOG_TO_JOURNAL=0";
break;
case LOGGING_TEST_DIFFABLE:
envp = g_environ_setenv (envp, "SRT_LOG", "diffable", TRUE);
title = "Diffable";
break;
case LOGGING_TEST_DIFFABLE_PID:
envp = g_environ_setenv (envp, "SRT_LOG", "diffable,pid", TRUE);
title = "Diffable overridden by pid";
break;
case LOGGING_TEST_NO_AUTO_JOURNAL:
title = "Don't automatically redirect to Journal";
child_setup_data.close_stdout = TRUE;
spawn_flags |= G_SPAWN_STDERR_TO_DEV_NULL;
break;
case LOGGING_TEST_AUTO_JOURNAL:
argv[argc++] = "--allow-journal";
title = "Automatically redirect to Journal";
child_setup_data.close_stderr = TRUE;
spawn_flags |= G_SPAWN_STDOUT_TO_DEV_NULL;
break;
}
g_test_message ("Starting test: %s", title);
argv[argc++] = title;
argv[argc++] = NULL;
g_assert_cmpint (argc, <=, G_N_ELEMENTS (argv));
g_spawn_sync (NULL, (gchar **) argv, envp, spawn_flags,
child_setup, &child_setup_data,
(spawn_flags & G_SPAWN_STDOUT_TO_DEV_NULL) ? NULL : &out,
(spawn_flags & G_SPAWN_STDERR_TO_DEV_NULL) ? NULL : &err,
&wait_status, &error);
g_assert_no_error (error);
if (out != NULL)
g_test_message ("stdout: '''%s%s'''", out[0] == '\0' ? "" : "\\\n", out);
if (err != NULL)
g_test_message ("stderr: '''%s%s'''", err[0] == '\0' ? "" : "\\\n", err);
switch (i)
{
case LOGGING_TEST_BASIC:
g_assert_nonnull (strstr (err, "srt-tests-logging-helper["));
g_assert_nonnull (strstr (err, "]: N: Basic logging test"));
g_assert_nonnull (strstr (err, "stderr while running"));
g_assert_nonnull (strstr (err, "]: N: notice message"));
g_assert_nonnull (strstr (err, "original stderr"));
/* We didn't divert stderr */
g_assert_cmpstr (out, ==, "stdout while running\noriginal stdout\n");
break;
case LOGGING_TEST_FLAGS:
/* We're using timestamps and didn't reset the g_set_prgname() */
g_assert_nonnull (strstr (err, ": logging-helper["));
/* We enabled profiling */
g_assert_nonnull (strstr (err, "]: N: Enabled profiling"));
g_assert_nonnull (strstr (err, "]: N: Various flags set"));
/* We enabled debug and info messages */
g_assert_nonnull (strstr (err, "]: D: debug message"));
g_assert_nonnull (strstr (err, "]: I: info message"));
g_assert_nonnull (strstr (err, "]: N: notice message"));
/* SRT_LOG=journal didn't take effect because we didn't pass in
* the OPTIONALLY_JOURNAL flag */
/* We diverted stdout away and back */
g_assert_nonnull (strstr (err, "stdout while running"));
g_assert_cmpstr (out, ==, "original stdout\n");
break;
case LOGGING_TEST_FLAGS_OLD:
/* We're using timestamps */
g_assert_nonnull (strstr (err, ": srt-tests-logging-helper["));
g_assert_nonnull (strstr (err, "]: N: Old environment variables set"));
/* We enabled info messages */
g_assert_nonnull (strstr (err, "]: I: info message"));
g_assert_nonnull (strstr (err, "]: N: notice message"));
break;
case LOGGING_TEST_TO_JOURNAL:
/* SRT_LOG=journal sends logging to the Journal if possible.
* If the Journal isn't available, it'll fall back to stderr. */
if (journal_fd >= 0)
g_assert_null (strstr (err, "notice message"));
/* DIVERT_STDOUT|JOURNAL redirects stdout to the Journal. */
if (journal_fd >= 0)
g_assert_null (strstr (err, "stdout while running"));
g_assert_cmpstr (out, ==, "original stdout\n");
break;
case LOGGING_TEST_TO_JOURNAL_OLD:
/* SRT_LOG_TO_JOURNAL=1 sends logging to the Journal if possible.
* If the Journal isn't available, it'll fall back to stderr. */
if (journal_fd >= 0)
g_assert_null (strstr (err, "notice message"));
/* JOURNAL without DIVERT_STDOUT doesn't redirect stdout. */
g_assert_cmpstr (out, ==, "stdout while running\noriginal stdout\n");
break;
case LOGGING_TEST_NOT_TO_JOURNAL:
/* SRT_LOG_TO_JOURNAL=0 "wins" vs. SRT_LOG=journal */
g_assert_nonnull (strstr (err, "notice message"));
g_assert_cmpstr (out, ==, "stdout while running\noriginal stdout\n");
break;
case LOGGING_TEST_DIFFABLE:
/* SRT_LOG=diffable suppresses process IDs... */
g_assert_nonnull (strstr (err, "srt-tests-logging-helper[0]: N: Diffable"));
break;
case LOGGING_TEST_DIFFABLE_PID:
/* ... unless you specifically ask for them */
g_assert_null (strstr (err, "[0]"));
break;
case LOGGING_TEST_AUTO_JOURNAL:
case LOGGING_TEST_NO_AUTO_JOURNAL:
default:
/* We can't make any useful assertions here because we're not
* capturing the output, so these have to be a manual test.
* You should see "N: Automatically redirect to Journal"
* in the Journal. You should not see
* "N: Don't automatically redirect to Journal". */
break;
}
}
}
static void
test_recursive_list (Fixture *f,
gconstpointer context)
......@@ -832,6 +1114,7 @@ int
main (int argc,
char **argv)
{
argv0 = argv[0];
_srt_setenv_disable_gio_modules ();
_srt_tests_init (&argc, &argv, NULL);
......@@ -852,6 +1135,8 @@ main (int argc,
setup, test_gstring_replace, teardown);
g_test_add ("/utils/hash-iter", Fixture, NULL,
setup, test_hash_iter, teardown);
g_test_add ("/utils/logging", Fixture, NULL,
setup, test_logging, teardown);
g_test_add ("/utils/recursive_list", Fixture, NULL,
setup, test_recursive_list, teardown);
g_test_add ("/utils/rlimit", Fixture, NULL,
......
0% Loading or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment