From 238e22b64508afa97cde56c2addd3833a18c1d58 Mon Sep 17 00:00:00 2001 From: Hans de Goede Date: Wed, 13 Feb 2019 14:39:42 +0100 Subject: [PATCH 1/3] logging: Improve logging format This commit adds 2 improvemens to the ply_trace logging format: 1) It prefixes the log messages with timestamps (since system boot) 2) Previously function-names where right aligned / left padded to 45 characters. But they were prefixed with a [file:line] prefix which does not have a fixed width, making the column aligment for the actual messages fail resulting in hard to read logs. This commit fixes 2. by printing " file:line:func" to a prefix-buffer and then left-aligning / right padding this prefix buffer to 75 chars. The resulting logged lines now look like this: 00:00:01.741 main.c:1928:check_logging : checking if console messages should be redirected and logged 00:00:01.741 main.c:1937:check_logging : logging will be enabled! Signed-off-by: Hans de Goede --- src/libply/ply-logger.h | 15 +++++++++++++-- 1 file changed, 13 insertions(+), 2 deletions(-) diff --git a/src/libply/ply-logger.h b/src/libply/ply-logger.h index 53d1ad9d..0015c0cf 100644 --- a/src/libply/ply-logger.h +++ b/src/libply/ply-logger.h @@ -25,6 +25,7 @@ #include #include #include +#include #include typedef struct _ply_logger ply_logger_t; @@ -88,11 +89,21 @@ bool ply_logger_is_tracing_enabled (ply_logger_t *logger); _old_errno = errno; \ if (ply_logger_is_tracing_enabled (logger)) \ { \ + struct timespec timespec = { 0, 0 }; \ + char buf[128]; \ + clock_gettime (CLOCK_MONOTONIC, ×pec); \ ply_logger_flush (logger); \ + snprintf (buf, sizeof(buf), \ + "%02d:%02d:%02d.%03d %s:%d:%s", \ + (int)(timespec.tv_sec / 3600), \ + (int)((timespec.tv_sec / 60) % 60), \ + (int)(timespec.tv_sec % 60), \ + (int)(timespec.tv_nsec / 1000000), \ + __FILE__, __LINE__, __func__); \ errno = _old_errno; \ ply_logger_inject (logger, \ - "[%s:%d] %45.45s:" format "\n", \ - __FILE__, __LINE__, __func__, ## args); \ + "%-75.75s: " format "\n", \ + buf, ## args); \ ply_logger_flush (logger); \ errno = _old_errno; \ } \ From d0e26e24d97e5f7f5715b5eb16730d907e21476c Mon Sep 17 00:00:00 2001 From: Hans de Goede Date: Wed, 16 Jan 2019 12:27:01 +0100 Subject: [PATCH 2/3] logging: Minor log-message fixes This fixes 2 minor issues with our log-messages: 1. ply_trace adds a "\n" itself, so there is no need to pass one extra. 2. Correct spelling of quitting Signed-off-by: Hans de Goede --- src/libply-splash-graphics/ply-animation.c | 4 ++-- src/libply/ply-utils.c | 2 +- src/main.c | 2 +- src/plugins/renderers/drm/plugin.c | 2 +- 4 files changed, 5 insertions(+), 5 deletions(-) diff --git a/src/libply-splash-graphics/ply-animation.c b/src/libply-splash-graphics/ply-animation.c index 323d9edc..9b6d8ce2 100644 --- a/src/libply-splash-graphics/ply-animation.c +++ b/src/libply-splash-graphics/ply-animation.c @@ -261,11 +261,11 @@ ply_animation_add_frames (ply_animation_t *animation) number_of_frames = ply_array_get_size (animation->frames); if (number_of_frames == 0) { - ply_trace ("%s directory had no files starting with %s\n", + ply_trace ("%s directory had no files starting with %s", animation->image_dir, animation->frames_prefix); goto out; } else { - ply_trace ("animation has %d frames\n", number_of_frames); + ply_trace ("animation has %d frames", number_of_frames); } load_finished = true; diff --git a/src/libply/ply-utils.c b/src/libply/ply-utils.c index 4ff7b1b9..0cadae96 100644 --- a/src/libply/ply-utils.c +++ b/src/libply/ply-utils.c @@ -656,7 +656,7 @@ ply_open_module (const char *module_path) RTLD_NODELETE | RTLD_NOW | RTLD_LOCAL); if (handle == NULL) { - ply_trace ("Could not load module \"%s\": %s\n", module_path, dlerror ()); + ply_trace ("Could not load module \"%s\": %s", module_path, dlerror ()); if (errno == 0) errno = ELIBACC; } diff --git a/src/main.c b/src/main.c index ddc18832..9adff3a0 100644 --- a/src/main.c +++ b/src/main.c @@ -1123,7 +1123,7 @@ load_devices (state_t *state, static void quit_splash (state_t *state) { - ply_trace ("quiting splash"); + ply_trace ("quitting splash"); if (state->boot_splash != NULL) { ply_trace ("freeing splash"); ply_boot_splash_free (state->boot_splash); diff --git a/src/plugins/renderers/drm/plugin.c b/src/plugins/renderers/drm/plugin.c index 0151f473..88c9d978 100644 --- a/src/plugins/renderers/drm/plugin.c +++ b/src/plugins/renderers/drm/plugin.c @@ -1100,7 +1100,7 @@ get_preferred_mode (drmModeConnector *connector) for (i = 0; i < connector->count_modes; i++) if (connector->modes[i].type & DRM_MODE_TYPE_PREFERRED) { - ply_trace ("Found preferred mode %dx%d at index %d\n", + ply_trace ("Found preferred mode %dx%d at index %d", connector->modes[i].hdisplay, connector->modes[i].vdisplay, i); return &connector->modes[i]; From a1920e8af9530b3504811ef04c0400cf7b53da3c Mon Sep 17 00:00:00 2001 From: Hans de Goede Date: Wed, 16 Jan 2019 12:51:05 +0100 Subject: [PATCH 3/3] ply-boot-splash: Do not add ply_boot_splash_update_progress timeout multiple times Before this commit when freeing the splash, the following would be logged: multiple matching timeouts found for removal multiple matching timeouts found for removal This is caused by us adding the ply_boot_splash_update_progress timeout handler to the event loop 3 times: 1 on first show, 2 on second show with a different mode, 3 on becoming idle. This commit fixes the 2nd add by stopping the timer when changing modes and the 3th add by not calling ply_boot_splash_update_progress to update the progress, as that will re-add itself. Instead this commit directly calls plugin_interface->on_boot_progress from ply_boot_splash_become_idle. Signed-off-by: Hans de Goede --- src/libply-splash-core/ply-boot-splash.c | 12 ++++++++++-- 1 file changed, 10 insertions(+), 2 deletions(-) diff --git a/src/libply-splash-core/ply-boot-splash.c b/src/libply-splash-core/ply-boot-splash.c index 54c76965..9549eccc 100644 --- a/src/libply-splash-core/ply-boot-splash.c +++ b/src/libply-splash-core/ply-boot-splash.c @@ -476,6 +476,11 @@ ply_boot_splash_show (ply_boot_splash_t *splash, } else if (splash->mode != PLY_BOOT_SPLASH_MODE_INVALID) { splash->plugin_interface->hide_splash_screen (splash->plugin, splash->loop); + if (splash->plugin_interface->on_boot_progress != NULL) { + ply_event_loop_stop_watching_for_timeout (splash->loop, + (ply_event_loop_timeout_handler_t) + ply_boot_splash_update_progress, splash); + } } ply_trace ("showing splash screen"); @@ -671,9 +676,12 @@ ply_boot_splash_become_idle (ply_boot_splash_t *splash, { assert (splash->idle_trigger == NULL); - if (splash->progress != NULL) { + if (splash->plugin_interface->on_boot_progress != NULL && + splash->progress != NULL) { ply_progress_set_percentage (splash->progress, 1.0); - ply_boot_splash_update_progress (splash); + splash->plugin_interface->on_boot_progress (splash->plugin, + ply_progress_get_time (splash->progress), + 1.0); } ply_trace ("telling splash to become idle");