From 2623ed4af53e8e8190d14c6215d9b3c39144e58d Mon Sep 17 00:00:00 2001 From: dormando Date: Tue, 14 Feb 2023 19:24:53 -0800 Subject: proxy: add read buffer data to backend errors Errors like "trailing data" or "missingend" or etc are only useful if you're in a debugger and can break and inspect. This adds detail in uriencoding into the log message when applicable. --- logger.c | 62 +++++++++++++++++++++++++++++++++++++++++++++++++++++++-- logger.h | 9 +++++++++ proxy_network.c | 5 +++-- t/proxyunits.t | 26 ++++++++++++++++++++++++ 4 files changed, 98 insertions(+), 4 deletions(-) diff --git a/logger.c b/logger.c index 79f4ed1..3cd7493 100644 --- a/logger.c +++ b/logger.c @@ -371,6 +371,64 @@ static int _logger_parse_prx_req(logentry *e, char *scratch) { ); return total; } + +#define MAX_RBUF_READ 100 +static void _logger_log_proxy_errbe(logentry *e, const entry_details *d, const void *entry, va_list ap) { + char *errmsg = va_arg(ap, char *); + char *be_name = va_arg(ap, char *); + char *be_port = va_arg(ap, char *); + int be_depth = va_arg(ap, int); + char *be_rbuf = va_arg(ap, char *); + int be_rbuflen = va_arg(ap, int); + + struct logentry_proxy_errbe *le = (void *)e->data; + le->be_depth = be_depth; + le->errlen = strlen(errmsg); + if (be_name && be_port) { + le->be_namelen = strlen(be_name); + le->be_portlen = strlen(be_port); + } + + le->be_rbuflen = be_rbuflen; + if (be_rbuflen > MAX_RBUF_READ) { + le->be_rbuflen = MAX_RBUF_READ; + } + + char *data = le->data; + memcpy(data, errmsg, le->errlen); + data += le->errlen; + memcpy(data, be_name, le->be_namelen); + data += le->be_namelen; + memcpy(data, be_port, le->be_portlen); + data += le->be_portlen; + memcpy(data, be_rbuf, le->be_rbuflen); + data += le->be_rbuflen; + + e->size = sizeof(struct logentry_proxy_errbe) + (data - le->data); +} + +static int _logger_parse_prx_errbe(logentry *e, char *scratch) { + int total; + char rbuf[MAX_RBUF_READ * 3]; // x 3 for worst case URI encoding. + struct logentry_proxy_errbe *le = (void *)e->data; + char *data = le->data; + char *errmsg = data; + data += le->errlen; + char *be_name = data; + data += le->be_namelen; + char *be_port = data; + data += le->be_portlen; + char *be_rbuf = data; + + uriencode(be_rbuf, rbuf, le->be_rbuflen, MAX_RBUF_READ * 3); + total = snprintf(scratch, LOGGER_PARSE_SCRATCH, + "ts=%lld.%d gid=%llu type=proxy_backend error=%.*s name=%.*s port=%.*s depth=%d rbuf=%s\n", + (long long int)e->tv.tv_sec, (int)e->tv.tv_usec, (unsigned long long) e->gid, + (int)le->errlen, errmsg, (int)le->be_namelen, be_name, + (int)le->be_portlen, be_port, le->be_depth, rbuf); + + return total; +} #endif /* Should this go somewhere else? */ @@ -419,8 +477,8 @@ static const entry_details default_entries[] = { [LOGGER_PROXY_USER] = {512, LOG_PROXYUSER, _logger_log_text, _logger_parse_text, "type=proxy_user msg=%s" }, - [LOGGER_PROXY_BE_ERROR] = {512, LOG_PROXYEVENTS, _logger_log_text, _logger_parse_text, - "type=proxy_backend error=%s name=%s port=%s" + [LOGGER_PROXY_BE_ERROR] = {512, LOG_PROXYEVENTS, _logger_log_proxy_errbe, _logger_parse_prx_errbe, + NULL }, #endif diff --git a/logger.h b/logger.h index 1d261de..4e8f1bb 100644 --- a/logger.h +++ b/logger.h @@ -126,6 +126,15 @@ struct logentry_proxy_req { long elapsed; char data[]; }; + +struct logentry_proxy_errbe { + size_t errlen; + size_t be_namelen; + size_t be_portlen; + size_t be_rbuflen; + int be_depth; + char data[]; +}; #endif /* end intermediary structures */ diff --git a/proxy_network.c b/proxy_network.c index a80284c..71c1a0c 100644 --- a/proxy_network.c +++ b/proxy_network.c @@ -1196,6 +1196,7 @@ static int _reset_bad_backend(mcp_backend_t *be, enum proxy_be_failures err) { io_pending_proxy_t *io = NULL; // Can't use STAILQ_FOREACH() since return_io_pending() free's the current // io. STAILQ_FOREACH_SAFE maybe? + int depth = be->depth; while (!STAILQ_EMPTY(&be->io_head)) { io = STAILQ_FIRST(&be->io_head); STAILQ_REMOVE_HEAD(&be->io_head, io_next); @@ -1209,6 +1210,8 @@ static int _reset_bad_backend(mcp_backend_t *be, enum proxy_be_failures err) { STAILQ_INIT(&be->io_head); be->io_next = NULL; // also reset the write offset. + LOGGER_LOG(NULL, LOG_PROXYEVENTS, LOGGER_PROXY_BE_ERROR, NULL, proxy_be_failure_text[err], be->name, be->port, depth, be->rbuf, be->rbufused); + // reset buffer to blank state. be->rbufused = 0; mcmc_disconnect(be->client); @@ -1232,8 +1235,6 @@ static int _reset_bad_backend(mcp_backend_t *be, enum proxy_be_failures err) { be->can_write = true; } - LOGGER_LOG(NULL, LOG_PROXYEVENTS, LOGGER_PROXY_BE_ERROR, NULL, proxy_be_failure_text[err], be->name, be->port); - return 0; } diff --git a/t/proxyunits.t b/t/proxyunits.t index 4c487d1..0a7476f 100644 --- a/t/proxyunits.t +++ b/t/proxyunits.t @@ -82,6 +82,32 @@ for my $be (@mbe) { $mbe[0] = $be; } +{ + # Test a log line with detailed data from backend failures. + my $be = $mbe[0]; + my $w = $p_srv->new_sock; + print $w "watch proxyevents\n"; + is(<$w>, "OK\r\n", "watcher enabled"); + + print $ps "get /b/c\r\n"; + is(scalar <$be>, "get /b/c\r\n", "get passthrough"); + # Set off a "trailing data" error + print $be "VALUE /b/c 0 2\r\nok\r\nEND\r\ngarbage"; + + is(scalar <$ps>, "VALUE /b/c 0 2\r\n", "got value back"); + is(scalar <$ps>, "ok\r\n", "got data back"); + is(scalar <$ps>, "END\r\n", "got end string"); + + like(<$w>, qr/ts=(\S+) gid=\d+ type=proxy_backend error=trailingdata name=127.0.0.1 port=\d+ depth=0 rbuf=garbage/, "got backend error log line"); + + # re-accept the backend. + $be = $mocksrvs[0]->accept(); + $be->autoflush(1); + like(<$be>, qr/version/, "received version command"); + print $be "VERSION 1.0.0-mock\r\n"; + $mbe[0] = $be; +} + #diag "ready for main tests"; # Target a single backend, validating basic syntax. # Should test all command types. -- cgit v1.2.1