proxy: replace proxycmds stream with proxyreqs

delete the magic logging and require mcp.log_req* be used if you want
those types of entries to appear. keeps a separate data stream from
"proxyuser" just in case that's useful.

proxycmds wasn't able to get enough context to autogenerate useful log
lines, so I'd rather not have it in there at all.

doc/protocol.txt

@@ -1177,7 +1177,7 @@ The arguments are:
   address IP and port. Connection close events additionally supply a reason for
   closing the connection.
 
-- "proxycmds": Emits detailed timing logs about requests/responses being
+- "proxyreqs": Emits detailed timing logs about requests/responses being
   returned to a client while in proxy mode. The conditions which logs are
   written here may be influenced by configuration.
 

logger.c

@@ -304,33 +304,6 @@ static int _logger_parse_cce(logentry *e, char *scratch) {
 }
 
 #ifdef PROXY
-static void _logger_log_proxy_raw(logentry *e, const entry_details *d, const void *entry, va_list ap) {
-    struct timeval start = va_arg(ap, struct timeval);
-    char *cmd = va_arg(ap, char *);
-    unsigned short type = va_arg(ap, int);
-    unsigned short code = va_arg(ap, int);
-
-    struct logentry_proxy_raw *le = (void *)e->data;
-    struct timeval end;
-    gettimeofday(&end, NULL);
-    le->type = type;
-    le->code = code;
-    le->elapsed = (end.tv_sec - start.tv_sec) * 1000000 + (end.tv_usec - start.tv_usec);
-    memcpy(le->cmd, cmd, 9);
-    e->size = sizeof(struct logentry_proxy_raw);
-}
-
-static int _logger_parse_prx_raw(logentry *e, char *scratch) {
-    int total;
-    struct logentry_proxy_raw *le = (void *)e->data;
-
-    total = snprintf(scratch, LOGGER_PARSE_SCRATCH,
-            "ts=%d.%d gid=%llu type=proxy_raw elapsed=%lu cmd=%s type=%d code=%d\n",
-            (int) e->tv.tv_sec, (int) e->tv.tv_usec, (unsigned long long) e->gid,
-            le->elapsed, le->cmd, le->type, le->code);
-    return total;
-}
-
 // TODO (v2): the length caps here are all magic numbers. Haven't thought of
 // something yet that I like better.
 // Should at least make a define to the max log len (1024) and do some math
@@ -383,7 +356,6 @@ static int _logger_parse_prx_req(logentry *e, char *scratch) {
     int total;
     struct logentry_proxy_req *le = (void *)e->data;
 
-    // TODO: encode detail / req
     total = snprintf(scratch, LOGGER_PARSE_SCRATCH,
             "ts=%d.%d gid=%llu type=proxy_req elapsed=%lu type=%d code=%d status=%d be=%.*s:%.*s detail=%.*s req=%.*s\n",
             (int) e->tv.tv_sec, (int) e->tv.tv_usec, (unsigned long long) e->gid,
@@ -435,8 +407,7 @@ static const entry_details default_entries[] = {
     [LOGGER_PROXY_CONFIG] = {512, LOG_PROXYEVENTS, _logger_log_text, _logger_parse_text,
         "type=proxy_conf status=%s"
     },
-    [LOGGER_PROXY_RAW] = {512, LOG_PROXYCMDS, _logger_log_proxy_raw, _logger_parse_prx_raw, NULL},
-    [LOGGER_PROXY_REQ] = {1024, LOG_PROXYUSER, _logger_log_proxy_req, _logger_parse_prx_req, NULL},
+    [LOGGER_PROXY_REQ] = {1024, LOG_PROXYREQS, _logger_log_proxy_req, _logger_parse_prx_req, NULL},
     [LOGGER_PROXY_ERROR] = {512, LOG_PROXYEVENTS, _logger_log_text, _logger_parse_text,
         "type=proxy_error msg=%s"
     },

logger.h

@@ -115,13 +115,6 @@ struct logentry_conn_event {
     struct sockaddr_in6 addr;
 };
 #ifdef PROXY
-struct logentry_proxy_raw {
-    unsigned short type;
-    unsigned short code;
-    long elapsed; // elapsed time in usec
-    char cmd[8];
-};
-
 struct logentry_proxy_req {
     unsigned short type;
     unsigned short code;
@@ -159,7 +152,7 @@ struct _logentry {
 #define LOG_EVICTIONS  (1<<6) /* details of evicted items */
 #define LOG_STRICT     (1<<7) /* block worker instead of drop */
 #define LOG_RAWCMDS    (1<<9) /* raw ascii commands */
-#define LOG_PROXYCMDS  (1<<10) /* command logs from proxy */
+#define LOG_PROXYREQS  (1<<10) /* command logs from proxy */
 #define LOG_PROXYEVENTS (1<<11) /* error log stream from proxy */
 #define LOG_PROXYUSER (1<<12) /* user generated logs from proxy */
 

proto_proxy.c

@@ -496,7 +496,7 @@ static void _set_noreply_mode(mc_resp *resp, mcp_resp_t *r) {
         case RESP_MODE_METAQUIET:
             if (r->resp.code == MCMC_CODE_MISS) {
                 resp->skip = true;
-            } else if (r->cmd[1] != 'g' && r->resp.code == MCMC_CODE_OK) {
+            } else if (r->cmd != CMD_MG && r->resp.code == MCMC_CODE_OK) {
                 // FIXME (v2): mcmc's parser needs to help us out a bit more
                 // here.
                 // This is a broken case in the protocol though; quiet mode
@@ -530,7 +530,6 @@ int proxy_run_coroutine(lua_State *Lc, mc_resp *resp, io_pending_proxy_t *p, con
         int type = lua_type(Lc, 1);
         if (type == LUA_TUSERDATA) {
             mcp_resp_t *r = luaL_checkudata(Lc, 1, "mcp.response");
-            LOGGER_LOG(NULL, LOG_PROXYCMDS, LOGGER_PROXY_RAW, NULL, r->start, r->cmd, r->resp.type, r->resp.code);
             _set_noreply_mode(resp, r);
             if (r->buf) {
                 // response set from C.
@@ -806,7 +805,6 @@ static void mcp_queue_io(conn *c, mc_resp *resp, int coro_ref, lua_State *Lc) {
     memset(r, 0, sizeof(mcp_resp_t));
     r->buf = NULL;
     r->blen = 0;
-    r->start = rq->start; // need to inherit the original start time.
     // Set noreply mode.
     // TODO (v2): the response "inherits" the request's noreply mode, which isn't
     // strictly correct; we should inherit based on the request that spawned
@@ -829,15 +827,7 @@ static void mcp_queue_io(conn *c, mc_resp *resp, int coro_ref, lua_State *Lc) {
         r->mode = RESP_MODE_NORMAL;
     }
 
-    int x;
-    int end = rq->pr.reqlen-2 > RESP_CMD_MAX ? RESP_CMD_MAX : rq->pr.reqlen-2;
-    for (x = 0; x < end; x++) {
-        if (rq->pr.request[x] == ' ') {
-            break;
-        }
-        r->cmd[x] = rq->pr.request[x];
-    }
-    r->cmd[x] = '\0';
+    r->cmd = rq->pr.command;
 
     luaL_getmetatable(Lc, "mcp.response");
     lua_setmetatable(Lc, -2);

proto_text.c

@@ -2291,8 +2291,8 @@ static void process_watch_command(conn *c, token_t *tokens, const size_t ntokens
                 f |= LOG_SYSEVENTS;
             } else if ((strcmp(tokens[x].value, "connevents") == 0)) {
                 f |= LOG_CONNEVENTS;
-            } else if ((strcmp(tokens[x].value, "proxycmds") == 0)) {
-                f |= LOG_PROXYCMDS;
+            } else if ((strcmp(tokens[x].value, "proxyreqs") == 0)) {
+                f |= LOG_PROXYREQS;
             } else if ((strcmp(tokens[x].value, "proxyevents") == 0)) {
                 f |= LOG_PROXYEVENTS;
             } else if ((strcmp(tokens[x].value, "proxyuser") == 0)) {

proxy.h

@@ -364,12 +364,11 @@ enum mcp_resp_mode {
 #define RESP_CMD_MAX 8
 typedef struct {
     mcmc_resp_t resp;
-    struct timeval start; // start time inherited from paired request
     char *buf; // response line + potentially value.
     size_t blen; // total size of the value to read.
     int status; // status code from mcmc_read()
     int bread; // amount of bytes read into value so far.
-    char cmd[RESP_CMD_MAX+1]; // until we can reverse CMD_*'s to strings directly.
+    uint8_t cmd; // from parser (pr.command)
     enum mcp_resp_mode mode; // reply mode (for noreply fixing)
     char be_name[MAX_NAMELEN+1];
     char be_port[MAX_PORTLEN+1];

proxy_await.c

@@ -97,7 +97,6 @@ static void mcp_queue_await_io(conn *c, lua_State *Lc, mcp_request_t *rq, int aw
     // reserve one uservalue for a lua-supplied response.
     mcp_resp_t *r = lua_newuserdatauv(Lc, sizeof(mcp_resp_t), 1);
     memset(r, 0, sizeof(mcp_resp_t));
-    r->start = rq->start;
     // Set noreply mode.
     // TODO (v2): the response "inherits" the request's noreply mode, which isn't
     // strictly correct; we should inherit based on the request that spawned
@@ -120,15 +119,7 @@ static void mcp_queue_await_io(conn *c, lua_State *Lc, mcp_request_t *rq, int aw
         r->mode = RESP_MODE_NORMAL;
     }
 
-    int x;
-    int end = rq->pr.reqlen-2 > RESP_CMD_MAX ? RESP_CMD_MAX : rq->pr.reqlen-2;
-    for (x = 0; x < end; x++) {
-        if (rq->pr.request[x] == ' ') {
-            break;
-        }
-        r->cmd[x] = rq->pr.request[x];
-    }
-    r->cmd[x] = '\0';
+    r->cmd = rq->pr.command;
 
     luaL_getmetatable(Lc, "mcp.response");
     lua_setmetatable(Lc, -2);