refactor: Add file/line to tox-bootstrapd logging.

Also, allow trace logging in bootstrapd (disabled by default, but
enabled on the websockify docker image so we can debug things there).

Author: iphydf

other/bootstrap_daemon/docker/Dockerfile

@@ -40,7 +40,7 @@ RUN CC=clang cmake -B_build -H. \
       -DCMAKE_UNITY_BUILD=ON \
       -DCMAKE_BUILD_TYPE=Release \
       -DFULLY_STATIC=ON \
-      -DMIN_LOGGER_LEVEL=DEBUG \
+      -DMIN_LOGGER_LEVEL=TRACE \
       -DBUILD_TOXAV=OFF \
       -DBOOTSTRAP_DAEMON=ON && \
     cmake --build _build --target install

other/bootstrap_daemon/docker/build

@@ -0,0 +1,8 @@
+#!/bin/bash
+
+set -eux -o pipefail
+
+GIT_ROOT="$(git rev-parse --show-toplevel)"
+cd "$GIT_ROOT"
+
+docker build -t toxchat/bootstrap-node -f other/bootstrap_daemon/docker/Dockerfile .

other/bootstrap_daemon/docker/tox-bootstrapd.sha256

@@ -1 +1 @@
-9ec2993a28988bd147bf8f4f21a824c2fc5dbf7255e391b3ce517d337ebce5c1  /usr/local/bin/tox-bootstrapd
+a15af369870ab166f84554f04868ec27955304b2e9dea38f706ca5318f4ab6f4  /usr/local/bin/tox-bootstrapd

other/bootstrap_daemon/src/command_line_arguments.c

@@ -9,7 +9,7 @@
  */
 #include "command_line_arguments.h"
 
-#include "global.h"
+#include "global.h" // IWYU pragma: keep
 #include "log.h"
 
 #include "../../../toxcore/ccompat.h"
@@ -26,7 +26,7 @@ static void print_help(void)
     // 2 space indent
     // Make sure all lines fit into 80 columns
     // Make sure options are listed in alphabetical order
-    log_write(LOG_LEVEL_INFO,
+    LOG_WRITE(LOG_LEVEL_INFO,
               "Usage: tox-bootstrapd [OPTION]... --config=FILE_PATH\n"
               "\n"
               "Options:\n"
@@ -43,6 +43,7 @@ static void print_help(void)
               "                                  Default option when no --log-backend is\n"
               "                                  specified.\n"
               "                           stdout Writes log messages to stdout/stderr.\n"
+              "  --trace                Enable verbose network trace logging in toxcore.\n"
               "  --version              Print version information.\n");
 }
 
@@ -51,7 +52,7 @@ Cli_Status handle_command_line_arguments(
     bool *run_in_foreground)
 {
     if (argc < 2) {
-        log_write(LOG_LEVEL_ERROR, "Error: No arguments provided.\n\n");
+        LOG_WRITE(LOG_LEVEL_ERROR, "Error: No arguments provided.\n\n");
         print_help();
         return CLI_STATUS_ERROR;
     }
@@ -64,6 +65,7 @@ Cli_Status handle_command_line_arguments(
         {"help",        no_argument,       nullptr, 'h'},
         {"log-backend", required_argument, nullptr, 'l'}, // optional, defaults to syslog
         {"version",     no_argument,       nullptr, 'v'},
+        {"trace",       no_argument,       nullptr, 't'},
         {nullptr,       0,                 nullptr,  0 }
     };
 
@@ -99,24 +101,29 @@ Cli_Status handle_command_line_arguments(
                     *log_backend = LOG_BACKEND_STDOUT;
                     log_backend_set = true;
                 } else {
-                    log_write(LOG_LEVEL_ERROR, "Error: Invalid BACKEND value for --log-backend option passed: %s\n\n", optarg);
+                    LOG_WRITE(LOG_LEVEL_ERROR, "Error: Invalid BACKEND value for --log-backend option passed: %s\n\n", optarg);
                     print_help();
                     return CLI_STATUS_ERROR;
                 }
 
                 break;
 
             case 'v':
-                log_write(LOG_LEVEL_INFO, "Version: %lu\n", DAEMON_VERSION_NUMBER);
+                LOG_WRITE(LOG_LEVEL_INFO, "Version: %lu\n", DAEMON_VERSION_NUMBER);
                 return CLI_STATUS_DONE;
 
+            case 't':
+                LOG_WRITE(LOG_LEVEL_INFO, "Enabling trace logging in toxcore.\n");
+                log_enable_trace(true);
+                break;
+
             case '?':
-                log_write(LOG_LEVEL_ERROR, "Error: Unrecognized option %s\n\n", argv[optind - 1]);
+                LOG_WRITE(LOG_LEVEL_ERROR, "Error: Unrecognized option %s\n\n", argv[optind - 1]);
                 print_help();
                 return CLI_STATUS_ERROR;
 
             case ':':
-                log_write(LOG_LEVEL_ERROR, "Error: No argument provided for option %s\n\n", argv[optind - 1]);
+                LOG_WRITE(LOG_LEVEL_ERROR, "Error: No argument provided for option %s\n\n", argv[optind - 1]);
                 print_help();
                 return CLI_STATUS_ERROR;
         }
@@ -127,7 +134,7 @@ Cli_Status handle_command_line_arguments(
     }
 
     if (!cfg_file_path_set) {
-        log_write(LOG_LEVEL_ERROR, "Error: The required --config option wasn't specified\n\n");
+        LOG_WRITE(LOG_LEVEL_ERROR, "Error: The required --config option wasn't specified\n\n");
         print_help();
         return CLI_STATUS_ERROR;
     }

other/bootstrap_daemon/src/config.c

@@ -15,6 +15,12 @@
 
 #define INVALID_BACKEND ((LOG_BACKEND)-1u)
 static LOG_BACKEND current_backend = INVALID_BACKEND;
+static bool log_toxcore_trace = false;
+
+void log_enable_trace(bool enable)
+{
+    log_toxcore_trace = enable;
+}
 
 bool log_open(LOG_BACKEND backend)
 {
@@ -58,22 +64,27 @@ bool log_close(void)
     return true;
 }
 
-bool log_write(LOG_LEVEL level, const char *format, ...)
+bool log_write(LOG_LEVEL level, const char *category, const char *file, int line, const char *format, ...)
 {
     if (current_backend == INVALID_BACKEND) {
         return false;
     }
 
+    if (level == LOG_LEVEL_TRACE && !log_toxcore_trace) {
+        // By default, no trace logging.
+        return true;
+    }
+
     va_list args;
     va_start(args, format);
 
     switch (current_backend) {
         case LOG_BACKEND_STDOUT:
-            log_backend_stdout_write(level, format, args);
+            log_backend_stdout_write(level, category, file, line, format, args);
             break;
 
         case LOG_BACKEND_SYSLOG:
-            log_backend_syslog_write(level, format, args);
+            log_backend_syslog_write(level, category, file, line, format, args);
             break;
     }
 

other/bootstrap_daemon/src/log.c

@@ -20,11 +20,18 @@ typedef enum LOG_BACKEND {
 } LOG_BACKEND;
 
 typedef enum LOG_LEVEL {
+    LOG_LEVEL_TRACE,
     LOG_LEVEL_INFO,
     LOG_LEVEL_WARNING,
     LOG_LEVEL_ERROR
 } LOG_LEVEL;
 
+/**
+ * Enables or disables logging of trace messages from toxcore.
+ * @param enable true to enable, false to disable.
+ */
+void log_enable_trace(bool enable);
+
 /**
  * Initializes logger.
  * @param backend Specifies which backend to use.
@@ -45,6 +52,13 @@ bool log_close(void);
  * @param ... Zero or more arguments, similar to printf function.
  * @return true on success, false if log is closed.
  */
-bool log_write(LOG_LEVEL level, const char *format, ...) GNU_PRINTF(2, 3);
+bool log_write(LOG_LEVEL level, const char *category, const char *file, int line, const char *format, ...) GNU_PRINTF(5, 6);
+
+enum {
+    LOG_PATH_PREFIX = sizeof(__FILE__) - sizeof("log.h")
+};
+
+#define LOG_WRITEC(level, category, ...) log_write(level, category, &__FILE__[LOG_PATH_PREFIX], __LINE__, __VA_ARGS__)
+#define LOG_WRITE(level, ...) LOG_WRITEC(level, "tox.bootstrap", __VA_ARGS__)
 
 #endif // C_TOXCORE_OTHER_BOOTSTRAP_DAEMON_SRC_LOG_H

other/bootstrap_daemon/src/log.h

@@ -11,12 +11,15 @@
 
 #include <stdarg.h>
 #include <stdio.h>
+#include <sys/time.h>
 
+#include "../../../toxcore/ccompat.h"
 #include "log.h"
 
 static FILE *log_backend_stdout_level(LOG_LEVEL level)
 {
     switch (level) {
+        case LOG_LEVEL_TRACE: // intentional fallthrough
         case LOG_LEVEL_INFO:
             return stdout;
 
@@ -28,8 +31,36 @@ static FILE *log_backend_stdout_level(LOG_LEVEL level)
     return stdout;
 }
 
-void log_backend_stdout_write(LOG_LEVEL level, const char *format, va_list args)
+static const char *log_level_string(LOG_LEVEL level)
 {
-    vfprintf(log_backend_stdout_level(level), format, args);
-    fflush(log_backend_stdout_level(level));
+    switch (level) {
+        case LOG_LEVEL_TRACE:
+            return "Debug";
+
+        case LOG_LEVEL_INFO:
+            return "Info";
+
+        case LOG_LEVEL_WARNING:
+            return "Warning";
+
+        case LOG_LEVEL_ERROR:
+            return "Critical"; // Qt-compatible.
+    }
+
+    return "Debug"; // Just in case. Shouldn't happen.
+}
+
+// Output bootstrap node log messages in the standard Tox log format:
+// [15:02:46.433 UTC] (tox.bootstrap) config.c:444 : Info: Successfully added bootstrap node ...
+void log_backend_stdout_write(LOG_LEVEL level, const char *category, const char *file, int line, const char *format, va_list args)
+{
+    struct timeval tv = {0};
+    gettimeofday(&tv, nullptr);
+
+    FILE *stream = log_backend_stdout_level(level);
+    fprintf(stream, "[%02d:%02d:%02d.%03d UTC] (%s) %s:%d : %s: ",
+            (int)(tv.tv_sec / 3600 % 24), (int)(tv.tv_sec / 60 % 60), (int)(tv.tv_sec % 60), (int)(tv.tv_usec / 1000),
+            category, file, line, log_level_string(level));
+    vfprintf(stream, format, args);
+    fflush(stream);
 }

other/bootstrap_daemon/src/log_backend_stdout.c

@@ -15,6 +15,6 @@
 #include "../../../toxcore/attributes.h"
 #include "log.h"
 
-void log_backend_stdout_write(LOG_LEVEL level, const char *format, va_list args) GNU_PRINTF(2, 0);
+void log_backend_stdout_write(LOG_LEVEL level, const char *category, const char *file, int line, const char *format, va_list args) GNU_PRINTF(2, 0);
 
 #endif  // C_TOXCORE_OTHER_BOOTSTRAP_DAEMON_SRC_LOG_BACKEND_STDOUT_H

other/bootstrap_daemon/src/log_backend_stdout.h

@@ -33,6 +33,9 @@ void log_backend_syslog_close(void)
 static int log_backend_syslog_level(LOG_LEVEL level)
 {
     switch (level) {
+        case LOG_LEVEL_TRACE:
+            return LOG_DEBUG;
+
         case LOG_LEVEL_INFO:
             return LOG_INFO;
 
@@ -46,8 +49,13 @@ static int log_backend_syslog_level(LOG_LEVEL level)
     return LOG_INFO;
 }
 
-void log_backend_syslog_write(LOG_LEVEL level, const char *format, va_list args)
+void log_backend_syslog_write(LOG_LEVEL level, const char *category, const char *file, int line, const char *format, va_list args)
 {
+    if (level == LOG_LEVEL_TRACE) {
+        // Don't write trace messages to syslog.
+        return;
+    }
+
     va_list args2;
 
     va_copy(args2, args);