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/dns_poller.c

@@ -35,7 +35,7 @@ static void sock_state_cb(void *data, int fd, int read, int write) {
   // reserve and start new event on unused slot
   io_event_ptr = get_io_event(d, 0);
   if (!io_event_ptr) {
-    FLOG("c-ares needed more event, than nameservers count: %d", d->io_events_count);
+    FLOG("c-ares needed more IO event handler, than the number of provided nameservers: %d", d->io_events_count);
   }
   DLOG("Reserved new io event: %p", io_event_ptr);
   // NOLINTNEXTLINE(clang-analyzer-security.insecureAPI.DeprecatedOrUnsafeBufferHandling)
@@ -75,9 +75,9 @@ static void ares_cb(void *arg, int status, int __attribute__((unused)) timeouts,
   ev_tstamp interval = 5;  // retry by default after some time
 
   if (status != ARES_SUCCESS) {
-    WLOG("DNS lookup failed: %s", ares_strerror(status));
+    WLOG("DNS lookup of '%s' failed: %s", d->hostname, ares_strerror(status));
   } else if (!h || h->h_length < 1) {
-    WLOG("No hosts.");
+    WLOG("No hosts found for '%s'", d->hostname);
   } else {
     interval = d->polling_interval;
     d->cb(d->hostname, d->cb_data, get_addr_listing(h->h_addr_list, h->h_addrtype));

src/https_client.c

@@ -50,6 +50,11 @@ DOH_MAX_RESPONSE_SIZE = 65535
     FLOG("Unexpected NULL pointer for " #var_name "(" #type ")"); \
   }
 
+static void https_fetch_ctx_cleanup(https_client_t *client,
+                                    struct https_fetch_ctx *prev,
+                                    struct https_fetch_ctx *ctx,
+                                    int curl_result_code);
+
 static size_t write_buffer(void *buf, size_t size, size_t nmemb, void *userp) {
   GET_PTR(struct https_fetch_ctx, ctx, userp);
   size_t write_size = size * nmemb;
@@ -265,7 +270,6 @@ static void https_set_request_version(https_client_t *client,
     } else if (client->opt->use_http_version == 2) {
       ELOG("Try to run application with -x argument! Falling back to HTTP/1.1 version.");
       client->opt->use_http_version = 1;
-      // TODO: consider CURLMOPT_PIPELINING setting??
     }
   }
 }
@@ -313,6 +317,7 @@ static void https_fetch_ctx_init(https_client_t *client,
   ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_TCP_KEEPINTVL, 50L);
   ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_MAXAGE_CONN, 300L);
 #endif
+  // FIXME: consider adding usage of: CURLOPT_PIPEWAIT
   ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_USERAGENT, "https_dns_proxy/0.3");
   ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_FOLLOWLOCATION, 0);
   ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_NOSIGNAL, 0);
@@ -329,8 +334,13 @@ static void https_fetch_ctx_init(https_client_t *client,
   }
   CURLMcode multi_code = curl_multi_add_handle(client->curlm, ctx->curl);
   if (multi_code != CURLM_OK) {
-    FLOG_REQ("curl_multi_add_handle error %d: %s",
-             multi_code, curl_multi_strerror(multi_code));
+    ELOG_REQ("curl_multi_add_handle error %d: %s", multi_code, curl_multi_strerror(multi_code));
+    if (multi_code == CURLM_ABORTED_BY_CALLBACK) {
+      WLOG_REQ("Resetting HTTPS client to recover from faulty state!");
+      https_client_reset(client);
+    } else {
+      https_fetch_ctx_cleanup(client, NULL, client->fetches, -1);  // dropping current failed request
+    }
   }
 }
 
@@ -506,10 +516,10 @@ static void https_fetch_ctx_cleanup(https_client_t *client,
   }
   int drop_reply = 0;
   if (curl_result_code < 0) {
-    WLOG_REQ("Request was aborted.");
+    WLOG_REQ("Request was aborted");
     drop_reply = 1;
   } else if (https_fetch_ctx_process_response(client, ctx, curl_result_code) != 0) {
-    ILOG_REQ("Response was faulty, skipping DNS reply.");
+    ILOG_REQ("Response was faulty, skipping DNS reply");
     drop_reply = 1;
   }
   if (drop_reply) {
@@ -545,6 +555,9 @@ static void check_multi_info(https_client_t *c) {
         cur = cur->next;
       }
     }
+    else {
+      ELOG("Unhandled curl message: %d", msg->msg);  // unlikely
+    }
   }
 }
 
@@ -555,10 +568,16 @@ static void sock_cb(struct ev_loop __attribute__((unused)) *loop,
       c->curlm, w->fd, (revents & EV_READ ? CURL_CSELECT_IN : 0) |
                        (revents & EV_WRITE ? CURL_CSELECT_OUT : 0),
       &c->still_running);
-  if (code != CURLM_OK) {
+  if (code == CURLM_OK) {
+    check_multi_info(c);
+  }
+  else {
     FLOG("curl_multi_socket_action error %d: %s", code, curl_multi_strerror(code));
+    if (code == CURLM_ABORTED_BY_CALLBACK) {
+      WLOG("Resetting HTTPS client to recover from faulty state!");
+      https_client_reset(c);
+    }
   }
-  check_multi_info(c);
 }
 
 static void timer_cb(struct ev_loop __attribute__((unused)) *loop,
@@ -567,7 +586,7 @@ static void timer_cb(struct ev_loop __attribute__((unused)) *loop,
   CURLMcode code = curl_multi_socket_action(c->curlm, CURL_SOCKET_TIMEOUT, 0,
                                             &c->still_running);
   if (code != CURLM_OK) {
-    FLOG("curl_multi_socket_action error %d: %s", code, curl_multi_strerror(code));
+    ELOG("curl_multi_socket_action error %d: %s", code, curl_multi_strerror(code));
   }
   check_multi_info(c);
 }
@@ -581,6 +600,15 @@ static struct ev_io * get_io_event(struct ev_io io_events[], curl_socket_t sock)
   return NULL;
 }
 
+static void dump_io_events(struct ev_io io_events[]) {
+  for (int i = 0; i < MAX_TOTAL_CONNECTIONS; i++) {
+    ILOG("IO event #%d: fd=%d, events=%d/%s%s",
+         i+1, io_events[i].fd, io_events[i].events,
+         (io_events[i].events & EV_READ ? "R" : ""),
+         (io_events[i].events & EV_WRITE ? "W" : ""));
+  }
+}
+
 static int multi_sock_cb(CURL *curl, curl_socket_t sock, int what,
                          void *userp, void __attribute__((unused)) *sockp) {
   GET_PTR(https_client_t, c, userp);
@@ -600,7 +628,10 @@ static int multi_sock_cb(CURL *curl, curl_socket_t sock, int what,
   // reserve and start new event on unused slot
   io_event_ptr = get_io_event(c->io_events, 0);
   if (!io_event_ptr) {
-    FLOG("curl needed more event, than max connections: %d", MAX_TOTAL_CONNECTIONS);
+    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);
   // NOLINTNEXTLINE(clang-analyzer-security.insecureAPI.DeprecatedOrUnsafeBufferHandling)

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);