Fixes 14

README.md

@@ -162,7 +162,8 @@ Usage: ./https_dns_proxy [-a <listen_addr>] [-p <listen_port>]
         [-d] [-u <user>] [-g <group>] [-b <dns_servers>]
         [-i <polling_interval>] [-4] [-r <resolver_url>]
         [-t <proxy_server>] [-l <logfile>] [-c <dscp_codepoint>]
-        [-x] [-q] [-s <statistic_interval>] [-v]+ [-V] [-h]
+        [-x] [-q] [-s <statistic_interval>] [-F <log_limit>]
+        [-v]+ [-V] [-h]
 
   -a listen_addr         Local IPv4/v6 address to bind to. (127.0.0.1)
   -p listen_port         Local port to bind to. (5053)
@@ -190,9 +191,13 @@ Usage: ./https_dns_proxy [-a <listen_addr>] [-p <listen_port>]
   -q                     Use HTTP/3 (QUIC) only. (false)
   -s statistic_interval  Optional statistic printout interval.
                          (Default: 0, Disabled: 0, Min: 1, Max: 3600)
+  -C path                Optional file containing CA certificates.
   -v                     Increase logging verbosity. (Default: error)
                          Levels: fatal, stats, error, warning, info, debug
                          Request issues are logged on warning level.
+  -F log_limit           Flight recorder: storing desired amount of logs from all levels
+                         in memory and dumping them on fatal error or on SIGUSR2 signal.
+                         (Default: 0, Min: 100, Max: 100000)
   -V                     Print version and exit.
   -h                     Print help and exit.
 ```

src/https_client.c

@@ -630,6 +630,7 @@ static int multi_sock_cb(CURL *curl, curl_socket_t sock, int what,
   if (!io_event_ptr) {
     ELOG("curl needed more IO event handler, than the number of maximum connections: %d", MAX_TOTAL_CONNECTIONS);
     dump_io_events(c->io_events);
+    logging_flight_recorder_dump();
     return -1;
   }
   DLOG("Reserved new io event: %p", io_event_ptr);

src/logging.c

@@ -6,13 +6,19 @@
 #include <unistd.h>        // NOLINT(llvmlibc-restrict-system-libc-headers)
 
 #include "logging.h"
+#include "ring_buffer.h"
 
-/* logs of this severity or higher are flushed immediately after write */
+// logs of this severity or higher are flushed immediately after write
 #define LOG_FLUSH_LEVEL LOG_WARNING
+enum {
+LOG_LINE_SIZE = 2048  // Log line should be at least 100
+};
 
-static FILE *logfile = NULL;     // NOLINT(cppcoreguidelines-avoid-non-const-global-variables)
-static int loglevel = LOG_ERROR; // NOLINT(cppcoreguidelines-avoid-non-const-global-variables)
-static ev_timer logging_timer;   // NOLINT(cppcoreguidelines-avoid-non-const-global-variables)
+static FILE *logfile = NULL;                         // NOLINT(cppcoreguidelines-avoid-non-const-global-variables)
+static int loglevel = LOG_ERROR;                     // NOLINT(cppcoreguidelines-avoid-non-const-global-variables)
+static ev_timer logging_timer;                       // NOLINT(cppcoreguidelines-avoid-non-const-global-variables)
+static ev_signal sigusr2;                            // NOLINT(cppcoreguidelines-avoid-non-const-global-variables)
+static struct ring_buffer * flight_recorder = NULL;  // NOLINT(cppcoreguidelines-avoid-non-const-global-variables)
 
 static const char * const SeverityStr[] = {
   "[D]",
@@ -24,54 +30,80 @@ static const char * const SeverityStr[] = {
 };
 
 void logging_timer_cb(struct ev_loop __attribute__((unused)) *loop,
-                             ev_timer __attribute__((unused)) *w,
-                             int __attribute__((unused)) revents) {
+    ev_timer __attribute__((unused)) *w,
+    int __attribute__((unused)) revents) {
   if (logfile) {
     (void)fflush(logfile);
   }
 }
 
-void logging_flush_init(struct ev_loop *loop) {
-  // NOLINTNEXTLINE(clang-analyzer-security.insecureAPI.DeprecatedOrUnsafeBufferHandling)
-  ev_timer_init(&logging_timer, logging_timer_cb, 0, 10);
+void logging_flight_recorder_dump(void) {
+  if (flight_recorder) {
+    ILOG("Flight recorder dump");  // will be also at the end of the dump :)
+    ring_buffer_dump(flight_recorder, logfile);
+  } else {
+    ILOG("Flight recorder is disabled");
+  }
+}
+
+static void logging_flight_recorder_dump_cb(struct ev_loop __attribute__((unused)) *loop,
+    ev_signal __attribute__((__unused__)) *w,
+    int __attribute__((__unused__)) revents) {
+  logging_flight_recorder_dump();
+}
+
+void logging_events_init(struct ev_loop *loop) {
   /* don't start timer if we will never write messages that are not flushed */
-  if (loglevel >= LOG_FLUSH_LEVEL) {
-    return;
+  if (loglevel < LOG_FLUSH_LEVEL) {
+    DLOG("starting periodic log flush timer");
+    // NOLINTNEXTLINE(clang-analyzer-security.insecureAPI.DeprecatedOrUnsafeBufferHandling)
+    ev_timer_init(&logging_timer, logging_timer_cb, 0, 10);
+    ev_timer_start(loop, &logging_timer);
   }
-  DLOG("starting periodic log flush timer");
-  ev_timer_start(loop, &logging_timer);
+
+  DLOG("starting SIGUSR2 handler");
+  ev_signal_init(&sigusr2, logging_flight_recorder_dump_cb, SIGUSR2);
+  ev_signal_start(loop, &sigusr2);
 }
 
-void logging_flush_cleanup(struct ev_loop *loop) {
+void logging_events_cleanup(struct ev_loop *loop) {
   ev_timer_stop(loop, &logging_timer);
+  ev_signal_stop(loop, &sigusr2);
 }
 
-void logging_init(int fd, int level) {
+void logging_init(int fd, int level, uint32_t flight_recorder_size) {
   if (logfile) {
     (void)fclose(logfile);
   }
   logfile = fdopen(fd, "a");
   loglevel = level;
+
+  ring_buffer_init(&flight_recorder, flight_recorder_size);
 }
 
 void logging_cleanup(void) {
+  if (flight_recorder) {
+    ring_buffer_free(&flight_recorder);
+    flight_recorder = NULL;
+  }
+
   if (logfile) {
     (void)fclose(logfile);
   }
   logfile = NULL;
 }
 
 int logging_debug_enabled(void) {
-  return loglevel <= LOG_DEBUG;
+  return loglevel <= LOG_DEBUG || flight_recorder;
 }
 
 // NOLINTNEXTLINE(misc-no-recursion) because of severity check
 void _log(const char *file, int line, int severity, const char *fmt, ...) {
-  if (severity < loglevel) {
+  if (severity < loglevel && !flight_recorder) {
     return;
   }
   if (severity < 0 || severity >= LOG_MAX) {
-    FLOG("Unknown log severity: %d\n", severity);
+    FLOG("Unknown log severity: %d", severity);
   }
   if (!logfile) {
     logfile = fdopen(STDOUT_FILENO, "w");
@@ -80,23 +112,50 @@ void _log(const char *file, int line, int severity, const char *fmt, ...) {
   struct timeval tv;
   gettimeofday(&tv, NULL);
 
+  char buff[LOG_LINE_SIZE];
+  uint32_t buff_pos = 0;
+
   // NOLINTNEXTLINE(clang-analyzer-security.insecureAPI.DeprecatedOrUnsafeBufferHandling)
-  (void)fprintf(logfile, "%s %8"PRIu64".%06"PRIu64" %s:%d ", SeverityStr[severity],
-          (uint64_t)tv.tv_sec,
-          (uint64_t)tv.tv_usec, file, line);
+  int chars = snprintf(buff, LOG_LINE_SIZE, "%s %8"PRIu64".%06"PRIu64" %s:%d ",
+                       SeverityStr[severity], (uint64_t)tv.tv_sec, (uint64_t)tv.tv_usec, file, line);
+  if (chars < 0 || chars >= LOG_LINE_SIZE/2) {
+    abort();  // must be impossible
+  }
+  buff_pos += chars;
 
   va_list args;
   va_start(args, fmt);
-  (void)vfprintf(logfile, fmt, args);
+  // NOLINTNEXTLINE(clang-analyzer-security.insecureAPI.DeprecatedOrUnsafeBufferHandling)
+  chars = vsnprintf(buff + buff_pos, LOG_LINE_SIZE - buff_pos, fmt, args);
   va_end(args);
 
+  if (chars < 0) {
+    abort();  // must be impossible
+  }
+  buff_pos += chars;
+  if (buff_pos >= LOG_LINE_SIZE) {
+    buff_pos = LOG_LINE_SIZE - 1;
+    buff[buff_pos - 1] = '$'; // indicate truncation
+  }
+
+  if (flight_recorder) {
+    ring_buffer_push_back(flight_recorder, buff, buff_pos);
+  }
+
+  if (severity < loglevel) {
+    return;
+  }
+
   // NOLINTNEXTLINE(clang-analyzer-security.insecureAPI.DeprecatedOrUnsafeBufferHandling)
-  (void)fprintf(logfile, "\n");
+  (void)fprintf(logfile, "%s\n", buff);
 
   if (severity >= LOG_FLUSH_LEVEL) {
     (void)fflush(logfile);
   }
   if (severity == LOG_FATAL) {
+    if (flight_recorder) {
+      ring_buffer_dump(flight_recorder, logfile);
+    }
 #ifdef DEBUG
     abort();
 #else

src/logging.h

@@ -11,18 +11,21 @@ extern "C" {
 
 // Initializes logging.
 // Writes logs to descriptor 'fd' for log levels above or equal to 'level'.
-void logging_init(int fd, int level);
+void logging_init(int fd, int level, unsigned flight_recorder_size);
 
 // Initialize periodic timer to flush logs.
-void logging_flush_init(struct ev_loop *loop);
-void logging_flush_cleanup(struct ev_loop *loop);
+void logging_events_init(struct ev_loop *loop);
+void logging_events_cleanup(struct ev_loop *loop);
 
 // Cleans up and flushes open logs.
 void logging_cleanup(void);
 
 // Returns 1 if debug logging is enabled.
 int logging_debug_enabled(void);
 
+// Dump flight recorder.
+void logging_flight_recorder_dump(void);
+
 // Internal. Don't use.
 void _log(const char *file, int line, int severity, const char *fmt, ...);
 

src/main.c

@@ -213,7 +213,7 @@ int main(int argc, char *argv[]) {
     exit(1);
   }
 
-  logging_init(opt.logfd, opt.loglevel);
+  logging_init(opt.logfd, opt.loglevel, opt.flight_recorder_size);
 
   ILOG("Version: %s", options_sw_version());
   ILOG("Built: " __DATE__ " " __TIME__);
@@ -294,7 +294,7 @@ int main(int argc, char *argv[]) {
   ev_signal_init(&sigterm, signal_shutdown_cb, SIGTERM);
   ev_signal_start(loop, &sigterm);
 
-  logging_flush_init(loop);
+  logging_events_init(loop);
 
   dns_poller_t dns_poller;
   char hostname[255] = {0};  // Domain names shouldn't exceed 253 chars.
@@ -320,7 +320,7 @@ int main(int argc, char *argv[]) {
   }
   curl_slist_free_all(app.resolv);
 
-  logging_flush_cleanup(loop);
+  logging_events_cleanup(loop);
   ev_signal_stop(loop, &sigterm);
   ev_signal_stop(loop, &sigint);
   ev_signal_stop(loop, &sigpipe);

src/options.c

@@ -49,11 +49,12 @@ void options_init(struct Options *opt) {
   opt->use_http_version = DEFAULT_HTTP_VERSION;
   opt->stats_interval = 0;
   opt->ca_info = NULL;
+  opt->flight_recorder_size = 0;
 }
 
 int options_parse_args(struct Options *opt, int argc, char **argv) {
   int c = 0;
-  while ((c = getopt(argc, argv, "a:c:p:du:g:b:i:4r:e:t:l:vxqs:C:hV")) != -1) {
+  while ((c = getopt(argc, argv, "a:c:p:du:g:b:i:4r:e:t:l:vxqs:C:F:hV")) != -1) {
     switch (c) {
     case 'a': // listen_addr
       opt->listen_addr = optarg;
@@ -112,6 +113,9 @@ int options_parse_args(struct Options *opt, int argc, char **argv) {
     case 'C': // CA info
       opt->ca_info = optarg;
       break;
+    case 'F': // Flight recorder size
+      opt->flight_recorder_size = atoi(optarg);
+      break;
     case '?':
       printf("Unknown option '-%c'\n", c);
       // fallthrough
@@ -177,6 +181,11 @@ int options_parse_args(struct Options *opt, int argc, char **argv) {
     printf("Statistic interval must be between 0 and 3600.\n");
     return -1;
   }
+  if (opt->flight_recorder_size != 0 &&
+      (opt->flight_recorder_size < 100 || opt->flight_recorder_size > 100000)) {
+    printf("Flight recorder limit must be between 100 and 100000.\n");
+    return -1;
+  }
   return 0;
 }
 
@@ -187,7 +196,8 @@ void options_show_usage(int __attribute__((unused)) argc, char **argv) {
   printf("        [-d] [-u <user>] [-g <group>] [-b <dns_servers>]\n");
   printf("        [-i <polling_interval>] [-4] [-r <resolver_url>]\n");
   printf("        [-t <proxy_server>] [-l <logfile>] [-c <dscp_codepoint>]\n");
-  printf("        [-x] [-q] [-s <statistic_interval>] [-v]+ [-V] [-h]\n\n");
+  printf("        [-x] [-q] [-s <statistic_interval>] [-F <log_limit>]\n");
+  printf("        [-v]+ [-V] [-h]\n\n");
   printf("  -a listen_addr         Local IPv4/v6 address to bind to. (%s)\n",
          defaults.listen_addr);
   printf("  -p listen_port         Local port to bind to. (%d)\n",
@@ -225,13 +235,17 @@ void options_show_usage(int __attribute__((unused)) argc, char **argv) {
   printf("  -v                     Increase logging verbosity. (Default: error)\n");
   printf("                         Levels: fatal, stats, error, warning, info, debug\n");
   printf("                         Request issues are logged on warning level.\n");
+  printf("  -F log_limit           Flight recorder: storing desired amount of logs from all levels\n"\
+         "                         in memory and dumping them on fatal error or on SIGUSR2 signal.\n"
+         "                         (Default: %u, Min: 100, Max: 100000)\n",
+         defaults.flight_recorder_size);
   printf("  -V                     Print version and exit.\n");
   printf("  -h                     Print help and exit.\n");
   options_cleanup(&defaults);
 }
 
 void options_cleanup(struct Options *opt) {
-  if (opt->logfd > 0) {
+  if (opt->logfd != STDOUT_FILENO && opt->logfd > 0) {
     close(opt->logfd);
   }
 }

src/options.h

@@ -51,6 +51,9 @@ struct Options {
 
   // Path to a file containing CA certificates
   const char *ca_info;
+
+  // Number of logs to be kept by flight recorder
+  uint32_t flight_recorder_size;
 } __attribute__((aligned(128)));
 typedef struct Options options_t;