Skip to content

Commit f6c1da3

Browse files
MrObviousaarond10
authored andcommitted
https_client: log recoverable connection errors at INFO instead of WARNING
Follow-up to aarond10#210 (reset-timer fix). Submitted as a separate change since this is a logging-policy question rather than a behavior fix, and should not hold up the reset-timer fix if there is disagreement on log levels. CURLE_OPERATION_TIMEDOUT, CURLE_HTTP2, CURLE_HTTP2_STREAM, CURLE_GOT_NOTHING, and CURLE_SEND_ERROR are all connection-reuse hiccups that the reset-timer path (see aarond10#210) already recovers from automatically without any user-visible impact. On resolvers whose edge cycles persistent connections periodically (observed with Quad9, not seen with Cloudflare), this is a routine, expected, self-healing condition - not a warning-worthy event - yet it was logged at WARNING twice per occurrence. On flash- and memory-constrained routers running at default verbosity, this produces a steady stream of log noise for a condition the proxy is already handling correctly on its own. This logs the same information at INFO instead of WARNING specifically for the recoverable error codes above, matching the existing INFO-level "Client reset timer started" message already used for this recovery path. Genuinely unexpected failures are unchanged and still log at WARNING. Tested on the same production router as aarond10#210 - confirmed curl-16 spam disappears from default-verbosity logs while the reset-timer recovery (and its own INFO-level messages, visible at raised verbosity) continues to function.
1 parent 7f1c94f commit f6c1da3

1 file changed

Lines changed: 15 additions & 4 deletions

File tree

src/https_client.c

Lines changed: 15 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -347,6 +347,11 @@ static int https_fetch_ctx_process_response(https_client_t *client,
347347
long long_resp = 0;
348348
char *str_resp = NULL;
349349
int faulty_response = 1;
350+
// Set for connection-reuse hiccups that the reset-timer path already
351+
// recovers from automatically - these are routine, not warning-worthy,
352+
// and logging them at WARNING just spams flash-constrained routers with
353+
// an expected condition. Genuinely unexpected failures still log at WARNING.
354+
int recoverable = 0;
350355

351356
switch (curl_result_code) {
352357
case CURLE_OK:
@@ -363,11 +368,17 @@ static int https_fetch_ctx_process_response(https_client_t *client,
363368
case CURLE_SEND_ERROR:
364369
// These all indicate a stale/broken (often reused HTTP/2) connection,
365370
// not a one-off content error - same recovery path as a timeout.
371+
recoverable = 1;
366372
if (!ev_is_active(&client->reset_timer)) {
367373
ILOG_REQ("Client reset timer started");
368374
ev_timer_start(client->loop, &client->reset_timer);
369375
}
370-
__attribute__((fallthrough));
376+
ILOG_REQ("curl request failed with %d: %s (recoverable, reset timer will recycle connection)",
377+
curl_result_code, curl_easy_strerror(curl_result_code));
378+
if (ctx->curl_errbuf[0] != 0) {
379+
ILOG_REQ("curl error message: %s", ctx->curl_errbuf);
380+
}
381+
break;
371382
default:
372383
WLOG_REQ("curl request failed with %d: %s", curl_result_code, curl_easy_strerror(curl_result_code));
373384
if (ctx->curl_errbuf[0] != 0) {
@@ -385,8 +396,8 @@ static int https_fetch_ctx_process_response(https_client_t *client,
385396
curl_off_t uploaded_bytes = 0;
386397
if (curl_easy_getinfo(ctx->curl, CURLINFO_SIZE_UPLOAD_T, &uploaded_bytes) == CURLE_OK &&
387398
uploaded_bytes > 0) {
388-
WLOG_REQ("Connecting and sending request to resolver was successful, "
389-
"but no response was sent back");
399+
LOG(recoverable ? LOG_INFO : LOG_WARNING, "%04hX: Connecting and sending request to resolver was successful, "
400+
"but no response was sent back", ctx->id);
390401
if (client->opt->use_http_version == 1) {
391402
// for example Unbound DoH servers does not support HTTP/1.x, only HTTP/2
392403
WLOG("Resolver may not support current HTTP/%s protocol version",
@@ -398,7 +409,7 @@ static int https_fetch_ctx_process_response(https_client_t *client,
398409
// that have been opened a long time ago (if CURLOPT_MAXAGE_CONN can not be increased
399410
// it is 118 seconds)
400411
// also: when no internet connection, this floods the log for every failed request
401-
WLOG_REQ("No response (probably connection has been closed or timed out)");
412+
LOG(recoverable ? LOG_INFO : LOG_WARNING, "%04hX: No response (probably connection has been closed or timed out)", ctx->id);
402413
}
403414
} else {
404415
WLOG_REQ("curl response code: %d, content length: %zu", long_resp, ctx->buflen);

0 commit comments

Comments
 (0)