diff --git a/README.md b/README.md index a9cabee..b57eeb0 100644 --- a/README.md +++ b/README.md @@ -43,7 +43,7 @@ only makes sense if you trust your DoH provider. ## Build -Depends on `c-ares (>=1.11.0)`, `libcurl (>=7.64.0)`, `libev (>=4.25)`. +Depends on `c-ares (>=1.11.0)`, `libcurl (>=7.65.0)`, `libev (>=4.25)`. On Debian-derived systems those are libc-ares-dev, libcurl4-{openssl,nss,gnutls}-dev and libev-dev respectively. @@ -159,40 +159,55 @@ Just run it as a daemon and point traffic at it. Commandline flags are: ``` Usage: ./https_dns_proxy [-a ] [-p ] - [-d] [-u ] [-g ] [-b ] - [-i ] [-4] [-r ] - [-t ] [-l ] [-c ] - [-x] [-q] [-s ] [-v]+ [-V] [-h] + [-b ] [-i ] [-4] + [-r ] [-t ] [-x] [-q] [-C ] [-c ] + [-d] [-u ] [-g ] + [-v]+ [-l ] [-s ] [-F ] [-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) - -d Daemonize. - -u user Optional user to drop to if launched as root. - -g group Optional group to drop to if launched as root. + DNS server + -a listen_addr Local IPv4/v6 address to bind to. (Default: 127.0.0.1) + -p listen_port Local port to bind to. (Default: 5053) + + DNS client -b dns_servers Comma-separated IPv4/v6 addresses and ports (addr:port) of DNS servers to resolve resolver host (e.g. dns.google). When specifying a port for IPv6, enclose the address in []. - (8.8.8.8,1.1.1.1,8.8.4.4,1.0.0.1,145.100.185.15,145.100.185.16,185.49.141.37) + (Default: 8.8.8.8,1.1.1.1,8.8.4.4,1.0.0.1,145.100.185.15,145.100.185.16,185.49.141.37) -i polling_interval Optional polling interval of DNS servers. (Default: 120, Min: 5, Max: 3600) -4 Force IPv4 hostnames for DNS resolvers non IPv6 networks. - -r resolver_url The HTTPS path to the resolver URL. Default: https://dns.google/dns-query + + HTTPS client + -r resolver_url The HTTPS path to the resolver URL. (Default: https://dns.google/dns-query) -t proxy_server Optional HTTP proxy. e.g. socks5://127.0.0.1:1080 Remote name resolution will be used if the protocol supports it (http, https, socks4a, socks5h), otherwise initial DNS resolution will still be done via the bootstrap DNS servers. - -l logfile Path to file to log to. ("-") - -c dscp_codepoint Optional DSCP codepoint[0-63] to set on upstream DNS server - connections. -x Use HTTP/1.1 instead of HTTP/2. Useful with broken - or limited builds of libcurl. (false) - -q Use HTTP/3 (QUIC) only. (false) - -s statistic_interval Optional statistic printout interval. - (Default: 0, Disabled: 0, Min: 1, Max: 3600) + or limited builds of libcurl. + -q Use HTTP/3 (QUIC) only. + -m max_idle_time Maximum idle time in seconds allowed for reusing a HTTPS connection. + (Default: 118, Min: 0, Max: 3600) + -C ca_path Optional file containing CA certificates. + -c dscp_codepoint Optional DSCP codepoint to set on upstream HTTPS server + connections. (Min: 0, Max: 63) + + Process + -d Daemonize. + -u user Optional user to drop to if launched as root. + -g group Optional group to drop to if launched as root. + + Logging -v Increase logging verbosity. (Default: error) Levels: fatal, stats, error, warning, info, debug Request issues are logged on warning level. + -l logfile Path to file to log to. (Default: standard output) + -s statistic_interval Optional statistic printout interval. + (Default: 0, Disabled: 0, Min: 1, Max: 3600) + -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, Disabled: 0, Min: 100, Max: 100000) -V Print version and exit. -h Print help and exit. ``` diff --git a/development_build_with_http3.sh b/development_build_with_http3.sh index efe1aa1..39833c6 100755 --- a/development_build_with_http3.sh +++ b/development_build_with_http3.sh @@ -7,33 +7,38 @@ echo "WARNING !!!" echo echo "Use only for development and testing!" echo "It is highly highly not recommended, to use in production!" -echo "This script was based on: https://github.com/curl/curl/blob/curl-7_82_0/docs/HTTP3.md" +echo "This script was based on: https://github.com/curl/curl/blob/curl-8_12_1/docs/HTTP3.md" +echo +echo "Extra packages suggested to be installed: autoconf libtool" echo sleep 5 +set -x + INSTALL_DIR=$PWD/custom_curl/install mkdir -p $INSTALL_DIR cd custom_curl ### -git clone --depth 1 -b openssl-3.0.0+quic https://github.com/quictls/openssl +git clone --depth 1 -b openssl-3.1.4+quic https://github.com/quictls/openssl cd openssl ./config enable-tls1_3 --prefix=$INSTALL_DIR make -j build_libs make install_dev cd .. -git clone --depth 1 -b v0.3.0 https://github.com/ngtcp2/nghttp3 +git clone --depth 1 -b v1.1.0 https://github.com/ngtcp2/nghttp3 cd nghttp3 +git submodule update --init autoreconf -fi ./configure --prefix=$INSTALL_DIR --enable-lib-only make -j make install cd .. -git clone --depth 1 -b v0.3.1 https://github.com/ngtcp2/ngtcp2 +git clone --depth 1 -b v1.2.0 https://github.com/ngtcp2/ngtcp2 cd ngtcp2 autoreconf -fi ./configure PKG_CONFIG_PATH=$INSTALL_DIR/lib64/pkgconfig:$INSTALL_DIR/lib64/pkgconfig LDFLAGS="-Wl,-rpath,$INSTALL_DIR/lib64" --prefix=$INSTALL_DIR --enable-lib-only --with-openssl @@ -41,7 +46,7 @@ make -j make install cd .. -git clone --depth 1 -b v1.47.0 https://github.com/nghttp2/nghttp2 +git clone --depth 1 -b v1.64.0 https://github.com/nghttp2/nghttp2 cd nghttp2 autoreconf -fi ./configure PKG_CONFIG_PATH=$INSTALL_DIR/lib64/pkgconfig:$INSTALL_DIR/lib64/pkgconfig LDFLAGS="-Wl,-rpath,$INSTALL_DIR/lib64" --prefix=$INSTALL_DIR --enable-lib-only --with-openssl @@ -49,7 +54,7 @@ make -j make install cd .. -git clone --depth 1 -b curl-7_82_0 https://github.com/curl/curl +git clone --depth 1 -b curl-8_12_1 https://github.com/curl/curl cd curl autoreconf -fi LDFLAGS="-Wl,-rpath,$INSTALL_DIR/lib64" ./configure --with-openssl=$INSTALL_DIR --with-nghttp2=$INSTALL_DIR --with-nghttp3=$INSTALL_DIR --with-ngtcp2=$INSTALL_DIR --prefix=$INSTALL_DIR @@ -60,5 +65,5 @@ cd .. ### cd .. -cmake -D CUSTOM_LIBCURL_INSTALL_PATH=$INSTALL_DIR . +cmake -D CUSTOM_LIBCURL_INSTALL_PATH=$INSTALL_DIR -D CMAKE_BUILD_TYPE=Debug . make -j diff --git a/src/dns_poller.c b/src/dns_poller.c index 1b21331..ce5cdd2 100644 --- a/src/dns_poller.c +++ b/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)); diff --git a/src/https_client.c b/src/https_client.c index 8b274e8..db50cac 100644 --- a/src/https_client.c +++ b/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; @@ -76,14 +81,20 @@ static curl_socket_t opensocket_callback(void *clientp, curlsocktype purpose, struct curl_sockaddr *addr) { GET_PTR(https_client_t, client, clientp); + if (client->connections >= HTTPS_SOCKET_LIMIT) { + ELOG("curl needed more socket, than the number of maximum sockets: %d", HTTPS_SOCKET_LIMIT); + return CURL_SOCKET_BAD; + } + curl_socket_t sock = socket(addr->family, addr->socktype, addr->protocol); - if (sock != -1) { - DLOG("curl opened socket: %d", sock); - } else { + if (sock == -1) { ELOG("Could not open curl socket %d:%s", errno, strerror(errno)); return CURL_SOCKET_BAD; } + DLOG("curl opened socket: %d", sock); + client->connections++; + if (client->stat) { stat_connection_opened(client->stat); } @@ -112,13 +123,14 @@ static int closesocket_callback(void __attribute__((unused)) *clientp, curl_sock { GET_PTR(https_client_t, client, clientp); - if (close(sock) == 0) { - DLOG("curl closed socket: %d", sock); - } else { + if (close(sock) != 0) { ELOG("Could not close curl socket %d:%s", errno, strerror(errno)); return 1; } + DLOG("curl closed socket: %d", sock); + client->connections--; + if (client->stat) { stat_connection_closed(client->stat); } @@ -265,7 +277,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?? } } } @@ -293,30 +304,22 @@ static void https_fetch_ctx_init(https_client_t *client, ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_DEBUGFUNCTION, https_curl_debug); ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_DEBUGDATA, ctx); } - if (logging_debug_enabled() || client->stat || client->opt->dscp) { - ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_OPENSOCKETFUNCTION, opensocket_callback); - ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_OPENSOCKETDATA, client); - } - if (logging_debug_enabled() || client->stat) { - ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_CLOSESOCKETFUNCTION, closesocket_callback); - ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_CLOSESOCKETDATA, client); - } + ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_OPENSOCKETFUNCTION, opensocket_callback); + ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_OPENSOCKETDATA, client); + ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_CLOSESOCKETFUNCTION, closesocket_callback); + ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_CLOSESOCKETDATA, client); ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_URL, url); ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_HTTPHEADER, client->header_list); ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_POSTFIELDSIZE, datalen); ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_POSTFIELDS, data); ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_WRITEFUNCTION, &write_buffer); ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_WRITEDATA, ctx); -#ifdef CURLOPT_MAXAGE_CONN - ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_TCP_KEEPALIVE, 1L); - ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_TCP_KEEPIDLE, 50L); - ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_TCP_KEEPINTVL, 50L); - ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_MAXAGE_CONN, 300L); -#endif + ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_MAXAGE_CONN, client->opt->max_idle_time); + ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_PIPEWAIT, client->opt->use_http_version > 1); 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); - ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_TIMEOUT, 10 /* seconds */); + ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_TIMEOUT, client->connections > 0 ? 5 : 10 /* seconds */); // We know Google supports this, so force it. ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_SSLVERSION, CURL_SSLVERSION_TLSv1_2); ASSERT_CURL_EASY_SETOPT(ctx, CURLOPT_ERRORBUFFER, ctx->curl_errbuf); // zeroed by calloc @@ -329,8 +332,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 +514,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,35 +553,46 @@ static void check_multi_info(https_client_t *c) { cur = cur->next; } } + else { + ELOG("Unhandled curl message: %d", msg->msg); // unlikely + } } } static void sock_cb(struct ev_loop __attribute__((unused)) *loop, struct ev_io *w, int revents) { GET_PTR(https_client_t, c, w->data); + int ignore = 0; CURLMcode code = curl_multi_socket_action( 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) { + &ignore); + 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, struct ev_timer *w, int __attribute__((unused)) revents) { GET_PTR(https_client_t, c, w->data); + int ignore = 0; CURLMcode code = curl_multi_socket_action(c->curlm, CURL_SOCKET_TIMEOUT, 0, - &c->still_running); + &ignore); 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); } static struct ev_io * get_io_event(struct ev_io io_events[], curl_socket_t sock) { - for (int i = 0; i < MAX_TOTAL_CONNECTIONS; i++) { + for (int i = 0; i < HTTPS_SOCKET_LIMIT; i++) { if (io_events[i].fd == sock) { return &io_events[i]; } @@ -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 < HTTPS_SOCKET_LIMIT; 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 sockets: %d", HTTPS_SOCKET_LIMIT); + 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) @@ -634,14 +665,15 @@ void https_client_init(https_client_t *c, options_t *opt, "Content-Type: " DOH_CONTENT_TYPE); c->fetches = NULL; c->timer.data = c; - for (int i = 0; i < MAX_TOTAL_CONNECTIONS; i++) { + for (int i = 0; i < HTTPS_SOCKET_LIMIT; i++) { c->io_events[i].data = c; } c->opt = opt; c->stat = stat; ASSERT_CURL_MULTI_SETOPT(c->curlm, CURLMOPT_PIPELINING, CURLPIPE_HTTP1 | CURLPIPE_MULTIPLEX); - ASSERT_CURL_MULTI_SETOPT(c->curlm, CURLMOPT_MAX_TOTAL_CONNECTIONS, MAX_TOTAL_CONNECTIONS); + ASSERT_CURL_MULTI_SETOPT(c->curlm, CURLMOPT_MAX_TOTAL_CONNECTIONS, HTTPS_CONNECTION_LIMIT); + ASSERT_CURL_MULTI_SETOPT(c->curlm, CURLMOPT_MAX_HOST_CONNECTIONS, HTTPS_CONNECTION_LIMIT); ASSERT_CURL_MULTI_SETOPT(c->curlm, CURLMOPT_SOCKETDATA, c); ASSERT_CURL_MULTI_SETOPT(c->curlm, CURLMOPT_SOCKETFUNCTION, multi_sock_cb); ASSERT_CURL_MULTI_SETOPT(c->curlm, CURLMOPT_TIMERDATA, c); diff --git a/src/https_client.h b/src/https_client.h index b673ed4..7c5ea08 100644 --- a/src/https_client.h +++ b/src/https_client.h @@ -6,7 +6,10 @@ #include "options.h" #include "stat.h" -#define MAX_TOTAL_CONNECTIONS 8 +enum { + HTTPS_SOCKET_LIMIT = 12, + HTTPS_CONNECTION_LIMIT = 8, +}; // Callback type for receiving data when a transfer finishes. typedef void (*https_response_cb)(void *data, char *buf, size_t buflen); @@ -35,8 +38,8 @@ typedef struct { struct https_fetch_ctx *fetches; ev_timer timer; - ev_io io_events[MAX_TOTAL_CONNECTIONS]; - int still_running; + ev_io io_events[HTTPS_SOCKET_LIMIT]; + int connections; options_t *opt; stat_t *stat; diff --git a/src/logging.c b/src/logging.c index bfee931..a85a45f 100644 --- a/src/logging.c +++ b/src/logging.c @@ -6,13 +6,19 @@ #include // 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,37 +30,63 @@ 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); } @@ -62,16 +94,16 @@ void logging_cleanup(void) { } 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 diff --git a/src/logging.h b/src/logging.h index 32c6744..cd110d6 100644 --- a/src/logging.h +++ b/src/logging.h @@ -11,11 +11,11 @@ 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); @@ -23,6 +23,9 @@ 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, ...); diff --git a/src/main.c b/src/main.c index 950eb3e..7f39301 100644 --- a/src/main.c +++ b/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); diff --git a/src/options.c b/src/options.c index d62a2d9..9c9add9 100644 --- a/src/options.c +++ b/src/options.c @@ -47,13 +47,15 @@ void options_init(struct Options *opt) { opt->resolver_url = "https://dns.google/dns-query"; opt->curl_proxy = NULL; opt->use_http_version = DEFAULT_HTTP_VERSION; + opt->max_idle_time = 118; 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:vxqm:s:C:F:hV")) != -1) { switch (c) { case 'a': // listen_addr opt->listen_addr = optarg; @@ -106,12 +108,18 @@ int options_parse_args(struct Options *opt, int argc, char **argv) { return -1; } break; + case 'm': + opt->max_idle_time = atoi(optarg); + break; case 's': // stats interval opt->stats_interval = atoi(optarg); break; 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 @@ -173,10 +181,20 @@ int options_parse_args(struct Options *opt, int argc, char **argv) { printf("DNS servers polling interval must be between 5 and 3600.\n"); return -1; } + if (opt->max_idle_time < 0 || + opt->max_idle_time > 3600) { + printf("Maximum idle time must be between 0 and 3600.\n"); + return -1; + } if (opt->stats_interval < 0 || opt->stats_interval > 3600) { 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; } @@ -184,54 +202,65 @@ void options_show_usage(int __attribute__((unused)) argc, char **argv) { struct Options defaults; options_init(&defaults); printf("Usage: %s [-a ] [-p ]\n", argv[0]); - printf(" [-d] [-u ] [-g ] [-b ]\n"); - printf(" [-i ] [-4] [-r ]\n"); - printf(" [-t ] [-l ] [-c ]\n"); - printf(" [-x] [-q] [-s ] [-v]+ [-V] [-h]\n\n"); - printf(" -a listen_addr Local IPv4/v6 address to bind to. (%s)\n", + printf(" [-b ] [-i ] [-4]\n"); + printf(" [-r ] [-t ] [-x] [-q] [-C ] [-c ]\n"); + printf(" [-d] [-u ] [-g ] \n"); + printf(" [-v]+ [-l ] [-s ] [-F ] [-V] [-h]\n"); + printf("\n DNS server\n"); + printf(" -a listen_addr Local IPv4/v6 address to bind to. (Default: %s)\n", defaults.listen_addr); - printf(" -p listen_port Local port to bind to. (%d)\n", + printf(" -p listen_port Local port to bind to. (Default: %d)\n", defaults.listen_port); - printf(" -d Daemonize.\n"); - printf(" -u user Optional user to drop to if launched as root.\n"); - printf(" -g group Optional group to drop to if launched as root.\n"); + printf("\n DNS client\n"); printf(" -b dns_servers Comma-separated IPv4/v6 addresses and ports (addr:port)\n"); printf(" of DNS servers to resolve resolver host (e.g. dns.google).\n"\ " When specifying a port for IPv6, enclose the address in [].\n"\ - " (%s)\n", + " (Default: %s)\n", defaults.bootstrap_dns); printf(" -i polling_interval Optional polling interval of DNS servers.\n"\ " (Default: %d, Min: 5, Max: 3600)\n", defaults.bootstrap_dns_polling_interval); printf(" -4 Force IPv4 hostnames for DNS resolvers non IPv6 networks.\n"); - printf(" -r resolver_url The HTTPS path to the resolver URL. Default: %s\n", + printf("\n HTTPS client\n"); + printf(" -r resolver_url The HTTPS path to the resolver URL. (Default: %s)\n", defaults.resolver_url); printf(" -t proxy_server Optional HTTP proxy. e.g. socks5://127.0.0.1:1080\n"); printf(" Remote name resolution will be used if the protocol\n"); printf(" supports it (http, https, socks4a, socks5h), otherwise\n"); printf(" initial DNS resolution will still be done via the\n"); printf(" bootstrap DNS servers.\n"); - printf(" -l logfile Path to file to log to. (\"%s\")\n", - defaults.logfile); - printf(" -c dscp_codepoint Optional DSCP codepoint[0-63] to set on upstream DNS server\n"); - printf(" connections.\n"); printf(" -x Use HTTP/1.1 instead of HTTP/2. Useful with broken\n" - " or limited builds of libcurl. (false)\n"); - printf(" -q Use HTTP/3 (QUIC) only. (false)\n"); - printf(" -s statistic_interval Optional statistic printout interval.\n"\ - " (Default: %d, Disabled: 0, Min: 1, Max: 3600)\n", - defaults.stats_interval); - printf(" -C path Optional file containing CA certificates.\n"); + " or limited builds of libcurl.\n"); + printf(" -q Use HTTP/3 (QUIC) only.\n"); + printf(" -m max_idle_time Maximum idle time in seconds allowed for reusing a HTTPS connection.\n"\ + " (Default: %d, Min: 0, Max: 3600)\n", + defaults.max_idle_time); + printf(" -C ca_path Optional file containing CA certificates.\n"); + printf(" -c dscp_codepoint Optional DSCP codepoint to set on upstream HTTPS server\n"); + printf(" connections. (Min: 0, Max: 63)\n"); + printf("\n Process\n"); + printf(" -d Daemonize.\n"); + printf(" -u user Optional user to drop to if launched as root.\n"); + printf(" -g group Optional group to drop to if launched as root.\n"); + printf("\n Logging\n"); 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(" -l logfile Path to file to log to. (Default: standard output)\n"); + printf(" -s statistic_interval Optional statistic printout interval.\n"\ + " (Default: %d, Disabled: 0, Min: 1, Max: 3600)\n", + defaults.stats_interval); + 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, Disabled: 0, 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); } } diff --git a/src/options.h b/src/options.h index 5127562..9f6b3dc 100644 --- a/src/options.h +++ b/src/options.h @@ -46,11 +46,16 @@ struct Options { // 3 = Use only HTTP/3 QUIC int use_http_version; + int max_idle_time; + // Print statistic interval int stats_interval; // 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; diff --git a/src/ring_buffer.c b/src/ring_buffer.c new file mode 100644 index 0000000..0de09ea --- /dev/null +++ b/src/ring_buffer.c @@ -0,0 +1,92 @@ +#include +#include // NOLINT(llvmlibc-restrict-system-libc-headers) +#include // NOLINT(llvmlibc-restrict-system-libc-headers) +#include // NOLINT(llvmlibc-restrict-system-libc-headers) + +#include "ring_buffer.h" + +struct ring_buffer +{ + char ** storage; + uint32_t size; + uint32_t next; // next slot to use in storage + uint8_t full; +} __attribute__((packed)) __attribute__((aligned(32))); + +void ring_buffer_init(struct ring_buffer **rbp, uint32_t size) +{ + *rbp = NULL; + if (size < 1) { + return; + } + struct ring_buffer *rb = (struct ring_buffer *)calloc(1, sizeof(struct ring_buffer)); + if (!rb) { + return; + } + rb->storage = (char**)calloc(size, sizeof(char*)); + if (!rb->storage) { + free((void*) rb); + return; + } + rb->size = size; + *rbp = rb; +} + +void ring_buffer_free(struct ring_buffer **rbp) +{ + struct ring_buffer *rb = *rbp; + if (!rb->storage) { + return; + } + for (uint32_t i = 0; i < rb->size; i++) { + if (rb->storage[i]) { + free(rb->storage[i]); + } + } + free((void*) rb->storage); + free((void*) rb); + *rbp = NULL; +} + +void ring_buffer_dump(struct ring_buffer *rb, FILE * file) +{ + if (!rb->storage) { + return; + } + if (rb->next == 0 && !rb->full) { + return; // empty + } + + uint32_t current = rb->full ? rb->next : 0; + do + { + // NOLINTNEXTLINE(clang-analyzer-security.insecureAPI.DeprecatedOrUnsafeBufferHandling) + (void)fprintf(file, "%s\n", rb->storage[current]); + + if (++current == rb->size) { + current = 0; + } + } + while (current != rb->next); + (void)fflush(file); +} + +void ring_buffer_push_back(struct ring_buffer *rb, char* data, uint32_t size) +{ + if (!rb->storage) { + return; + } + + if (rb->storage[rb->next]) { + free(rb->storage[rb->next]); + } + rb->storage[rb->next] = (char*)malloc(size + 1); + // NOLINTNEXTLINE(clang-analyzer-security.insecureAPI.DeprecatedOrUnsafeBufferHandling) + memcpy(rb->storage[rb->next], data, size); + rb->storage[rb->next][size] = '\0'; + + if (++rb->next == rb->size) { + rb->next = 0; + rb->full = 1; + } +} diff --git a/src/ring_buffer.h b/src/ring_buffer.h new file mode 100755 index 0000000..2815377 --- /dev/null +++ b/src/ring_buffer.h @@ -0,0 +1,21 @@ +#ifndef _FR_H_ +#define _FR_H_ + +#ifdef __cplusplus +extern "C" { +#endif + +#include + +struct ring_buffer; + +void ring_buffer_init(struct ring_buffer **rbp, uint32_t size); +void ring_buffer_free(struct ring_buffer **rbp); +void ring_buffer_dump(struct ring_buffer *rb, FILE * file); +void ring_buffer_push_back(struct ring_buffer *rb, char* data, uint32_t size); + +#ifdef __cplusplus +} +#endif + +#endif // _FR_H_ diff --git a/tests/robot/functional_tests.robot b/tests/robot/functional_tests.robot index f4279af..7d11f3b 100644 --- a/tests/robot/functional_tests.robot +++ b/tests/robot/functional_tests.robot @@ -36,7 +36,7 @@ Start Proxy With Valgrind @{default_args} = Create List --track-fds=yes --time-stamp=yes --log-file=valgrind-%p.log --suppressions=valgrind.supp ... --gen-suppressions=all --tool=memcheck --leak-check=full --leak-resolution=high ... --show-leak-kinds=all --track-origins=yes --keep-stacktraces=alloc-and-free - ... ${BINARY_PATH} -v -v -v -4 -p ${PORT} + ... ${BINARY_PATH} -v -v -v -F 100 -4 -p ${PORT} # using flight recorder with smallest possible buffer size to test memory leak @{proces_args} = Combine Lists ${default_args} ${args} ${proxy} = Start Process valgrind @{proces_args} ... stderr=STDOUT alias=proxy @@ -49,7 +49,9 @@ Start Proxy With Valgrind Stop Proxy Send Signal To Process SIGINT ${proxy} ${result} = Wait For Process ${proxy} timeout=15 secs + Log ${result.rc} Log ${result.stdout} + Log ${result.stderr} FOR ${log} ${times} IN &{expected_logs} Should Contain X Times ${result.stdout} ${log} ${times} END