From cf3a59aee502bf7519179584f0567c85814a8218 Mon Sep 17 00:00:00 2001 From: Mattias Axelsson Date: Fri, 5 Apr 2024 15:53:46 +0200 Subject: [PATCH 1/2] Allow log be directed to stdout instead of syslog * Allow log be directed to stdout instead of syslog * Add timestamp to stdout log lines * Move documentation to source code --- app/Makefile | 5 +- app/dockerdwrapperwithcompose.c | 167 +++++++++++++++----------------- app/log.c | 93 ++++++++++++++++++ app/log.h | 26 +++++ app/sd_disk_storage.c | 35 +++---- 5 files changed, 217 insertions(+), 109 deletions(-) create mode 100644 app/log.c create mode 100644 app/log.h diff --git a/app/Makefile b/app/Makefile index 525d90f..c24ceb4 100644 --- a/app/Makefile +++ b/app/Makefile @@ -1,5 +1,5 @@ -PROG1 = dockerdwrapperwithcompose -OBJS1 = $(PROG1).o sd_disk_storage.o +PROG1 = dockerdwrapper +OBJS1 = $(PROG1).o log.o sd_disk_storage.o PKGS = gio-2.0 glib-2.0 axparameter axstorage CFLAGS += $(shell PKG_CONFIG_PATH=$(PKG_CONFIG_PATH) pkg-config --cflags $(PKGS)) @@ -15,6 +15,7 @@ all: $(PROG1) $(PROG1): $(OBJS1) $(CC) $(CFLAGS) $(LDFLAGS) $^ $(LIBS) $(LDLIBS) -o $@ +$(PROG1).o log.o: log.h $(PROG1).o sd_disk_storage.o: sd_disk_storage.h clean: diff --git a/app/dockerdwrapperwithcompose.c b/app/dockerdwrapperwithcompose.c index 294e9f6..262f9e2 100644 --- a/app/dockerdwrapperwithcompose.c +++ b/app/dockerdwrapperwithcompose.c @@ -18,13 +18,12 @@ #include #include #include -#include #include #include #include #include -#include #include +#include "log.h" #include "sd_disk_storage.h" #define APP_DIRECTORY "/usr/local/packages/" APP_NAME @@ -144,16 +143,15 @@ get_parameter_value(const char *parameter_name) char *parameter_value = NULL; if (ax_parameter == NULL) { - syslog(LOG_ERR, "Error when creating axparameter: %s", error->message); + log_error("Error when creating axparameter: %s", error->message); goto end; } if (!ax_parameter_get( ax_parameter, parameter_name, ¶meter_value, &error)) { - syslog(LOG_ERR, - "Failed to fetch parameter value of %s. Error: %s", - parameter_name, - error->message); + log_error("Failed to fetch parameter value of %s. Error: %s", + parameter_name, + error->message); free(parameter_value); parameter_value = NULL; @@ -189,7 +187,7 @@ migrate_from_old_sdcard_setup(const char *new_dir) // The new directory must be created and empty. GDir *dir = g_dir_open(new_dir, 0, NULL); if (dir == NULL) { - syslog(LOG_ERR, "Failed to open %s", new_dir); + log_error("Failed to open %s", new_dir); return false; } // Get name to first entry in directory, NULL if empty, . and .. are omitted @@ -198,23 +196,18 @@ migrate_from_old_sdcard_setup(const char *new_dir) g_dir_close(dir); if (directory_not_empty) { - syslog(LOG_ERR, - "Target directory %s is not empty. Will not move files.", - new_dir); + log_error("Target directory %s is not empty. Will not move files.", + new_dir); return false; } // Move data from the old directory const char *move_command = g_strdup_printf("mv %s/data/* %s/.", old_top_dir, new_dir); - syslog(LOG_INFO, "Run move cmd: \"%s\"", move_command); + log_info("Run move cmd: \"%s\"", move_command); int res = system(move_command); if (res != 0) { - syslog(LOG_ERR, - "Failed to move %s to %s, error: %d", - old_top_dir, - new_dir, - res); + log_error("Failed to move %s to %s, error: %d", old_top_dir, new_dir, res); return false; } @@ -222,7 +215,7 @@ migrate_from_old_sdcard_setup(const char *new_dir) const char *remove_command = g_strdup_printf("rm -rf %s", old_top_dir); res = system(remove_command); if (res != 0) { - syslog(LOG_ERR, "Failed to remove %s, error: %d", old_top_dir, res); + log_error("Failed to remove %s, error: %d", old_top_dir, res); } return res == 0; @@ -241,9 +234,8 @@ get_filesystem_of_path(const char *path) struct stat sd_card_stat; int stat_result = stat(path, &sd_card_stat); if (stat_result != 0) { - syslog(LOG_ERR, - "Cannot store data on the SD card, no storage exists at %s", - path); + log_error("Cannot store data on the SD card, no storage exists at %s", + path); return NULL; } @@ -290,44 +282,41 @@ setup_sdcard(const char *data_root) int res = system(create_droot_command); if (res != 0) { - syslog(LOG_ERR, - "Failed to create data_root folder at: %s. Error code: %d", - data_root, - res); + log_error("Failed to create data_root folder at: %s. Error code: %d", + data_root, + res); return false; } // Confirm that the SD card is usable sd_file_system = get_filesystem_of_path(data_root); if (sd_file_system == NULL) { - syslog(LOG_ERR, - "Couldn't identify the file system of the SD card at %s", - data_root); + log_error("Couldn't identify the file system of the SD card at %s", + data_root); return false; } if (strcmp(sd_file_system, "vfat") == 0 || strcmp(sd_file_system, "exfat") == 0) { - syslog(LOG_ERR, - "The SD card at %s uses file system %s which does not support " - "Unix file permissions. Please reformat to a file system that " - "support Unix file permissions, such as ext4 or xfs.", - data_root, - sd_file_system); + log_error("The SD card at %s uses file system %s which does not support " + "Unix file permissions. Please reformat to a file system that " + "support Unix file permissions, such as ext4 or xfs.", + data_root, + sd_file_system); return false; } if (access(data_root, F_OK) == 0 && access(data_root, W_OK) != 0) { - syslog(LOG_ERR, - "The application user does not have write permissions to the SD " - "card directory at %s. Please change the directory permissions or " - "remove the directory.", - data_root); + log_error( + "The application user does not have write permissions to the SD " + "card directory at %s. Please change the directory permissions or " + "remove the directory.", + data_root); return false; } if (!migrate_from_old_sdcard_setup(data_root)) { - syslog(LOG_ERR, "Failed to migrate data from old data-root"); + log_error("Failed to migrate data from old data-root"); return false; } @@ -352,14 +341,13 @@ prepare_data_root(const char *sd_card_area) { if (is_parameter_yes("SDCardSupport")) { if (!sd_card_area) { - syslog( - LOG_ERR, + log_error( "SD card was requested, but no SD card is available at the moment."); return NULL; } char *data_root = g_strdup_printf("%s/data", sd_card_area); if (!setup_sdcard(data_root)) { - syslog(LOG_ERR, "Failed to setup SD card."); + log_error("Failed to setup SD card."); free(data_root); return NULL; } @@ -396,23 +384,20 @@ get_and_verify_tls_selection(bool *use_tls_ret) bool key_exists = access(key_path, F_OK) == 0; if (!ca_exists || !cert_exists || !key_exists) { - syslog(LOG_ERR, "One or more TLS certificates missing."); + log_error("One or more TLS certificates missing."); } if (!ca_exists) { - syslog(LOG_ERR, - "Cannot start using TLS, no CA certificate found at %s", - ca_path); + log_error("Cannot start using TLS, no CA certificate found at %s", + ca_path); } if (!cert_exists) { - syslog(LOG_ERR, - "Cannot start using TLS, no server certificate found at %s", - cert_path); + log_error("Cannot start using TLS, no server certificate found at %s", + cert_path); } if (!key_exists) { - syslog(LOG_ERR, - "Cannot start using TLS, no server key found at %s", - key_path); + log_error("Cannot start using TLS, no server key found at %s", + key_path); } if (!ca_exists || !cert_exists || !key_exists) { @@ -459,19 +444,19 @@ static bool read_settings(struct settings *settings, const struct app_state *app_state) { if (!get_and_verify_tls_selection(&settings->use_tls)) { - syslog(LOG_ERR, "Failed to verify tls selection"); + log_error("Failed to verify tls selection"); return false; } if (!get_tcp_socket_selection(&settings->use_tcp_socket)) { - syslog(LOG_ERR, "Failed to get tcp socket selection"); + log_error("Failed to get tcp socket selection"); return false; } if (!get_ipc_socket_selection(&settings->use_ipc_socket)) { - syslog(LOG_ERR, "Failed to get ipc socket selection"); + log_error("Failed to get ipc socket selection"); return false; } if (!(settings->data_root = prepare_data_root(app_state->sd_card_area))) { - syslog(LOG_ERR, "Failed to set up dockerd data root"); + log_error("Failed to set up dockerd data root"); return false; } return true; @@ -508,9 +493,9 @@ start_dockerd(const struct settings *settings, struct app_state *app_state) g_strlcpy(msg, "Starting dockerd", msg_len); if (!use_ipc_socket && !use_tcp_socket) { - syslog(LOG_ERR, - "At least one of IPC socket or TCP socket must be set to \"yes\". " - "dockerd will not be started."); + log_error( + "At least one of IPC socket or TCP socket must be set to \"yes\". " + "dockerd will not be started."); goto end; } @@ -560,8 +545,7 @@ start_dockerd(const struct settings *settings, struct app_state *app_state) args_offset += g_snprintf( args + args_offset, args_len - args_offset, " --data-root %s", data_root); - // Log startup information to syslog. - syslog(LOG_INFO, "%s", msg); + log_info("%s", msg); args_split = g_strsplit(args, " ", 0); result = g_spawn_async(NULL, @@ -573,10 +557,9 @@ start_dockerd(const struct settings *settings, struct app_state *app_state) &dockerd_process_pid, &error); if (!result) { - syslog(LOG_ERR, - "Starting dockerd failed: execv returned: %d, error: %s", - result, - error->message); + log_error("Starting dockerd failed: execv returned: %d, error: %s", + result, + error->message); goto end; } @@ -585,8 +568,8 @@ start_dockerd(const struct settings *settings, struct app_state *app_state) dockerd_process_pid, dockerd_process_exited_callback, app_state); if (!is_process_alive(dockerd_process_pid)) { - syslog(LOG_ERR, - "Starting dockerd failed: Process died unexpectedly during startup"); + log_error( + "Starting dockerd failed: Process died unexpectedly during startup"); quit_program(EX_SOFTWARE); goto end; } @@ -624,11 +607,10 @@ stop_dockerd(void) goto end; } - syslog(LOG_INFO, "Sending SIGTERM to dockerd."); + log_info("Sending SIGTERM to dockerd."); bool sigterm_successfully_sent = kill(dockerd_process_pid, SIGTERM) == 0; if (!sigterm_successfully_sent) { - syslog( - LOG_ERR, "Failed to send SIGTERM to child. Error: %s", strerror(errno)); + log_error("Failed to send SIGTERM to child. Error: %s", strerror(errno)); errno = 0; } @@ -645,10 +627,9 @@ stop_dockerd(void) // SIGTERM failed, let's try SIGKILL killed = kill(dockerd_process_pid, SIGKILL) == 0; - if (!killed) { - syslog( - LOG_ERR, "Failed to send SIGKILL to child. Error: %s", strerror(errno)); - } + if (!killed) + log_error("Failed to send SIGKILL to child. Error: %s", strerror(errno)); + end: return killed; } @@ -664,7 +645,7 @@ dockerd_process_exited_callback(GPid pid, struct app_state *app_state = app_state_void_ptr; GError *error = NULL; if (!g_spawn_check_wait_status(status, &error)) { - syslog(LOG_ERR, "Dockerd process exited with error: %d", status); + log_error("Dockerd process exited with error: %d", status); g_clear_error(&error); } @@ -695,7 +676,7 @@ parameter_changed_callback(const gchar *name, for (size_t i = 0; i < sizeof(ax_parameters) / sizeof(ax_parameters[0]); ++i) { if (strcmp(parname, ax_parameters[i]) == 0) { - syslog(LOG_INFO, "%s changed to: %s", ax_parameters[i], value); + log_info("%s changed to: %s", ax_parameters[i], value); g_main_loop_quit(loop); // Trigger a restart of dockerd from main() } } @@ -708,7 +689,7 @@ setup_axparameter(void) GError *error = NULL; AXParameter *ax_parameter = ax_parameter_new(APP_NAME, &error); if (ax_parameter == NULL) { - syslog(LOG_ERR, "Error when creating AXParameter: %s", error->message); + log_error("Error when creating AXParameter: %s", error->message); goto end; } @@ -721,10 +702,9 @@ setup_axparameter(void) free(parameter_path); if (geresult == FALSE) { - syslog(LOG_ERR, - "Could not register %s callback. Error: %s", - ax_parameters[i], - error->message); + log_error("Could not register %s callback. Error: %s", + ax_parameters[i], + error->message); goto end; } } @@ -749,14 +729,27 @@ sd_card_callback(const char *sd_card_area, void *app_state_void_ptr) g_main_loop_quit(loop); // Trigger a restart of dockerd from main() } +// Stop the application and start it from an SSH prompt with +// $ ./dockerdwrapper --stdout +// in order to get log messages written to console rather than to syslog. +static void +parse_command_line(int argc, char **argv, struct log_settings *log_settings) +{ + log_settings->destination = (argc == 2 && strcmp(argv[1], "--stdout") == 0) ? + log_dest_stdout : + log_dest_syslog; +} + int -main(void) +main(int argc, char **argv) { struct app_state app_state = {0}; + struct log_settings log_settings = {0}; AXParameter *ax_parameter = NULL; - openlog(NULL, LOG_PID, LOG_USER); - syslog(LOG_INFO, "Started logging."); + parse_command_line(argc, argv, &log_settings); + + log_init(&log_settings); loop = g_main_loop_new(NULL, FALSE); @@ -769,7 +762,7 @@ main(void) // Setup ax_parameter ax_parameter = setup_axparameter(); if (ax_parameter == NULL) { - syslog(LOG_ERR, "Error in setup_axparameter"); + log_error("Error in setup_axparameter"); quit_program(EX_SOFTWARE); } @@ -780,7 +773,7 @@ main(void) g_main_loop_run(loop); if (!stop_dockerd()) - syslog(LOG_WARNING, "Failed to shut down dockerd."); + log_warning("Failed to shut down dockerd."); } g_main_loop_unref(loop); diff --git a/app/log.c b/app/log.c new file mode 100644 index 0000000..34a0f9a --- /dev/null +++ b/app/log.c @@ -0,0 +1,93 @@ +#include "log.h" +#include +#include +#include + +static int +log_level_to_syslog_priority(GLogLevelFlags log_level) +{ + if (log_level == G_LOG_LEVEL_NON_FATAL_ERROR) + log_level = G_LOG_LEVEL_ERROR; + + switch (log_level) { + case G_LOG_LEVEL_DEBUG: + return LOG_INFO; // ... since LOG_DEBUG doesn't show up in syslog + case G_LOG_LEVEL_INFO: + return LOG_INFO; + case G_LOG_LEVEL_WARNING: + return LOG_WARNING; + case G_LOG_LEVEL_ERROR: + return LOG_ERR; + case G_LOG_LEVEL_CRITICAL: + return LOG_CRIT; + default: + return LOG_NOTICE; + } +} + +// String representation has been chosen to match that of dockerd +static const char * +log_level_to_string(GLogLevelFlags log_level) +{ + if (log_level == G_LOG_LEVEL_NON_FATAL_ERROR) + log_level = G_LOG_LEVEL_ERROR; + + switch (log_level) { + case G_LOG_LEVEL_DEBUG: + return "DEBU"; + case G_LOG_LEVEL_INFO: + return "INFO"; + case G_LOG_LEVEL_WARNING: + return "WARN"; + case G_LOG_LEVEL_ERROR: + return "ERRO"; + case G_LOG_LEVEL_CRITICAL: + return "CRIT"; + default: + return "?"; + } +} + +static bool +log_threshold_met(GLogLevelFlags log_level, const struct log_settings *settings) +{ + return settings->debug || (log_level & ~G_LOG_LEVEL_DEBUG); +} + +static void +log_to_syslog(__attribute__((unused)) const char *log_domain, + GLogLevelFlags log_level, + const char *message, + gpointer settings_void_ptr) +{ + if (log_threshold_met(log_level, settings_void_ptr)) + syslog(log_level_to_syslog_priority(log_level), "%s", message); +} + +// Timestamp format and log level have been chosen to match that of dockerd +static void +log_to_stdout(__attribute__((unused)) const char *log_domain, + GLogLevelFlags log_level, + const char *message, + gpointer settings_void_ptr) +{ + if (log_threshold_met(log_level, settings_void_ptr)) { + GDateTime *now = g_date_time_new_now_local(); + g_autofree char *now_text = g_date_time_format(now, "%Y-%m-%dT%T.%f000%:z"); + g_date_time_unref(now); + printf("%s[%s] %s\n", log_level_to_string(log_level), now_text, message); + } +} + +void +log_init(struct log_settings *settings) +{ + if (settings->destination == log_dest_syslog) + openlog(NULL, LOG_PID, LOG_USER); + + g_log_set_handler( + NULL, + G_LOG_FLAG_FATAL | G_LOG_FLAG_RECURSION | G_LOG_LEVEL_MASK, + settings->destination == log_dest_syslog ? log_to_syslog : log_to_stdout, + settings); +} diff --git a/app/log.h b/app/log.h new file mode 100644 index 0000000..efd7b5f --- /dev/null +++ b/app/log.h @@ -0,0 +1,26 @@ +#pragma once +#include + +enum log_destination { log_dest_stdout, log_dest_syslog }; + +struct log_settings { + enum log_destination destination; + bool debug; +}; + +// Set up g_log to log to either stdout or syslog. +// The log destination cannot be changed after this call, but the debug level +// can be adjusted at any time by changing the 'debug' member of the struct. A +// pointer to the log_settings struct will be passed to g_log_set_handler(), so +// the struct must live until the process exits. +void log_init(struct log_settings *settings); + +// Replacement for G_LOG_LEVEL_ERROR, which is fatal. +#define G_LOG_LEVEL_NON_FATAL_ERROR (1 << G_LOG_LEVEL_USER_SHIFT) + +#define log_debug(format, ...) g_debug(format, ##__VA_ARGS__) +#define log_info(format, ...) g_info(format, ##__VA_ARGS__) +#define log_warning(format, ...) g_warning(format, ##__VA_ARGS__) + +#define log_error(format, ...) \ + g_log(G_LOG_DOMAIN, G_LOG_LEVEL_NON_FATAL_ERROR, format, ##__VA_ARGS__) diff --git a/app/sd_disk_storage.c b/app/sd_disk_storage.c index 35e1c24..def45a7 100644 --- a/app/sd_disk_storage.c +++ b/app/sd_disk_storage.c @@ -1,9 +1,7 @@ #include "sd_disk_storage.h" #include -#include -#include -#include #include +#include "log.h" struct sd_disk_storage { SdDiskCallback callback; @@ -18,7 +16,7 @@ event_status_or_log(gchar *storage_id, AXStorageStatusEventId event) GError *error = NULL; bool value = ax_storage_get_status(storage_id, event, &error); if (error) { - syslog(LOG_WARNING, "Could not read ax_storage status: %s", error->message); + log_warning("Could not read ax_storage status: %s", error->message); g_clear_error(&error); } return value; @@ -32,7 +30,7 @@ setup_cb(AXStorage *handle, gpointer storage_void_ptr, GError *error) storage->handle = handle; if (error) { - syslog(LOG_WARNING, "setup_cb error: %s", error->message); + log_warning("setup_cb error: %s", error->message); g_clear_error(&error); storage->callback(NULL, storage->user_data); return; @@ -40,7 +38,7 @@ setup_cb(AXStorage *handle, gpointer storage_void_ptr, GError *error) g_autofree char *path = ax_storage_get_path(handle, &error); if (!path) { - syslog(LOG_WARNING, "Failed to get storage path: %s", error->message); + log_warning("Failed to get storage path: %s", error->message); g_clear_error(&error); storage->callback(NULL, storage->user_data); return; @@ -53,7 +51,7 @@ static void release_cb(gpointer, GError *error) { if (error) - syslog(LOG_WARNING, "Error while releasing storage: %s", error->message); + log_warning("Error while releasing storage: %s", error->message); } static void @@ -62,7 +60,7 @@ release(struct sd_disk_storage *storage) GError *error = NULL; if (storage->handle) { if (!ax_storage_release_async(storage->handle, release_cb, NULL, &error)) { - syslog(LOG_WARNING, "Failed to release storage: %s", error->message); + log_warning("Failed to release storage: %s", error->message); g_clear_error(&error); } storage->handle = NULL; @@ -78,9 +76,8 @@ release_and_unsubscribe(struct sd_disk_storage *storage) if (storage->subscription_id) { if (!ax_storage_unsubscribe(storage->subscription_id, &error)) { - syslog(LOG_WARNING, - "Failed to unsubscribe to storage events: %s", - error->message); + log_warning("Failed to unsubscribe to storage events: %s", + error->message); g_clear_error(&error); } storage->subscription_id = 0; @@ -101,7 +98,7 @@ subscribe_cb(gchar *storage_id, gpointer storage_void_ptr, GError *error) struct sd_disk_storage *storage = storage_void_ptr; if (error) { - syslog(LOG_WARNING, "subscribe_cb error: %s", error->message); + log_warning("subscribe_cb error: %s", error->message); g_clear_error(&error); storage->callback(NULL, storage->user_data); } @@ -113,7 +110,7 @@ subscribe_cb(gchar *storage_id, gpointer storage_void_ptr, GError *error) if (event_status_or_log(storage_id, AX_STORAGE_WRITABLE_EVENT)) { if (!ax_storage_setup_async(storage_id, setup_cb, storage, &error)) { - syslog(LOG_WARNING, "ax_storage_setup_async error: %s", error->message); + log_warning("ax_storage_setup_async error: %s", error->message); g_clear_error(&error); storage->callback(NULL, storage->user_data); } @@ -131,10 +128,9 @@ subscribe(struct sd_disk_storage *storage, const char *storage_id) found = true; if (!(storage->subscription_id = ax_storage_subscribe( node->data, subscribe_cb, storage, &error))) { - syslog(LOG_ERR, - "Failed to subscribe to events of %s: %s", - (char *)node->data, - error->message); + log_error("Failed to subscribe to events of %s: %s", + (char *)node->data, + error->message); g_clear_error(&error); return false; } @@ -143,9 +139,8 @@ subscribe(struct sd_disk_storage *storage, const char *storage_id) } g_list_free(devices); if (!found) - syslog(LOG_INFO, - "No storage with id %s found", - storage_id); // Not an error if products doesn't have SD card slot + log_info("No storage with id %s found", + storage_id); // Not an error if products doesn't have SD card slot return true; } From 67edfd19a56ae7a0bacc0d39a635345f2bcd940f Mon Sep 17 00:00:00 2001 From: Mattias Axelsson Date: Fri, 5 Apr 2024 15:56:31 +0200 Subject: [PATCH 2/2] Update Makefile --- app/Makefile | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/app/Makefile b/app/Makefile index c24ceb4..9f370cf 100644 --- a/app/Makefile +++ b/app/Makefile @@ -1,4 +1,4 @@ -PROG1 = dockerdwrapper +PROG1 = dockerdwrapperwithcompose OBJS1 = $(PROG1).o log.o sd_disk_storage.o PKGS = gio-2.0 glib-2.0 axparameter axstorage