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.

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.