proxy: logging improvements + lua mcp.log()

adds watch commands for:
proxycmds - internal raw timing log (tbd?)
proxyevents - config updates, internal errors, etc
proxyuser - logs generated by mcp.log()

logger.c

@@ -54,7 +54,7 @@ static int logger_thread_poll_watchers(int force_poll, int watcher);
 static void _logger_log_text(logentry *e, const entry_details *d, const void *entry, va_list ap) {
     int reqlen = d->reqlen;
     int total = vsnprintf((char *) e->data, reqlen, d->format, ap);
-    if (total >= reqlen || total <= 0) {
+    if (total <= 0) {
         fprintf(stderr, "LOGGER: Failed to vsnprintf a text entry: (total) %d\n", total);
     }
     e->size = total + 1; // null byte
@@ -367,13 +367,17 @@ static const entry_details default_entries[] = {
     },
 #endif
 #ifdef PROXY
-    [LOGGER_PROXY_CONFIG] = {512, LOG_SYSEVENTS, _logger_log_text, _logger_parse_text,
+    [LOGGER_PROXY_CONFIG] = {512, LOG_PROXYEVENTS, _logger_log_text, _logger_parse_text,
         "type=proxy_conf status=%s"
     },
-    [LOGGER_PROXY_RAW] = {512, LOG_RAWCMDS, _logger_log_proxy_raw, _logger_parse_prx_raw, NULL},
-    [LOGGER_PROXY_ERROR] = {512, LOG_SYSEVENTS, _logger_log_text, _logger_parse_text,
+    [LOGGER_PROXY_RAW] = {512, LOG_PROXYCMDS, _logger_log_proxy_raw, _logger_parse_prx_raw, NULL},
+    [LOGGER_PROXY_ERROR] = {512, LOG_PROXYEVENTS, _logger_log_text, _logger_parse_text,
         "type=proxy_error msg=%s"
     },
+    [LOGGER_PROXY_USER] = {512, LOG_PROXYUSER, _logger_log_text, _logger_parse_text,
+        "type=proxy_user msg=%s"
+    },
+
 #endif
 };
 

logger.h

@@ -35,6 +35,7 @@ enum log_entry_type {
     LOGGER_PROXY_CONFIG,
     LOGGER_PROXY_RAW,
     LOGGER_PROXY_ERROR,
+    LOGGER_PROXY_USER,
 #endif
 };
 
@@ -144,6 +145,9 @@ 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_PROXYEVENTS (1<<11) /* error log stream from proxy */
+#define LOG_PROXYUSER (1<<12) /* user generated logs from proxy */
 
 typedef struct _logger {
     struct _logger *prev;

proto_proxy.c

@@ -618,7 +618,7 @@ static void *_proxy_config_thread(void *arg) {
     pthread_mutex_lock(&ctx->config_lock);
     while (1) {
         pthread_cond_wait(&ctx->config_cond, &ctx->config_lock);
-        LOGGER_LOG(NULL, LOG_SYSEVENTS, LOGGER_PROXY_CONFIG, NULL, "start");
+        LOGGER_LOG(NULL, LOG_PROXYEVENTS, LOGGER_PROXY_CONFIG, NULL, "start");
         STAT_INCR(ctx, config_reloads, 1);
         lua_State *L = ctx->proxy_state;
         lua_settop(L, 0); // clear off any crud that could have been left on the stack.
@@ -634,7 +634,7 @@ static void *_proxy_config_thread(void *arg) {
         if (proxy_load_config(ctx) != 0) {
             // Failed to load. log and wait for a retry.
             STAT_INCR(ctx, config_reload_fails, 1);
-            LOGGER_LOG(NULL, LOG_SYSEVENTS, LOGGER_PROXY_CONFIG, NULL, "failed");
+            LOGGER_LOG(NULL, LOG_PROXYEVENTS, LOGGER_PROXY_CONFIG, NULL, "failed");
             continue;
         }
 
@@ -660,11 +660,11 @@ static void *_proxy_config_thread(void *arg) {
             // Code load bailed.
             if (ctx->worker_failed) {
                 STAT_INCR(ctx, config_reload_fails, 1);
-                LOGGER_LOG(NULL, LOG_SYSEVENTS, LOGGER_PROXY_CONFIG, NULL, "failed");
+                LOGGER_LOG(NULL, LOG_PROXYEVENTS, LOGGER_PROXY_CONFIG, NULL, "failed");
                 continue;
             }
         }
-        LOGGER_LOG(NULL, LOG_SYSEVENTS, LOGGER_PROXY_CONFIG, NULL, "done");
+        LOGGER_LOG(NULL, LOG_PROXYEVENTS, LOGGER_PROXY_CONFIG, NULL, "done");
     }
 
     return NULL;
@@ -1916,7 +1916,7 @@ static int proxy_run_coroutine(lua_State *Lc, mc_resp *resp, io_pending_proxy_t
         int type = lua_type(Lc, -1);
         if (type == LUA_TUSERDATA) {
             mcp_resp_t *r = luaL_checkudata(Lc, -1, "mcp.response");
-            LOGGER_LOG(NULL, LOG_RAWCMDS, LOGGER_PROXY_RAW, NULL, r->start, r->cmd, r->resp.type, r->resp.code);
+            LOGGER_LOG(NULL, LOG_PROXYCMDS, LOGGER_PROXY_RAW, NULL, r->start, r->cmd, r->resp.type, r->resp.code);
             if (r->buf) {
                 // response set from C.
                 // FIXME (v2): write_and_free() ? it's a bit wrong for here.
@@ -1987,7 +1987,7 @@ static int proxy_run_coroutine(lua_State *Lc, mc_resp *resp, io_pending_proxy_t
         }
     } else {
         P_DEBUG("%s: Failed to run coroutine: %s\n", __func__, lua_tostring(Lc, -1));
-        LOGGER_LOG(NULL, LOG_SYSEVENTS, LOGGER_PROXY_ERROR, NULL, lua_tostring(Lc, -1));
+        LOGGER_LOG(NULL, LOG_PROXYEVENTS, LOGGER_PROXY_ERROR, NULL, lua_tostring(Lc, -1));
         proxy_out_errstring(resp, "lua failure");
     }
 
@@ -4096,6 +4096,15 @@ static int mcplib_open_dist_jump_hash(lua_State *L) {
 
 /*** END jump consistent hash library ***/
 
+/*** START lua interface to logger ***/
+
+static int mcplib_log(lua_State *L) {
+    LIBEVENT_THREAD *t = lua_touserdata(L, lua_upvalueindex(MCP_THREAD_UPVALUE));
+    const char *msg = luaL_checkstring(L, -1);
+    LOGGER_LOG(t->l, LOG_PROXYUSER, LOGGER_PROXY_USER, NULL, msg);
+    return 0;
+}
+
 /*** START lua interface to user stats ***/
 
 // mcp.add_stat(index, name)
@@ -4540,6 +4549,7 @@ int proxy_register_libs(LIBEVENT_THREAD *t, void *ctx) {
         {"add_stat", mcplib_add_stat},
         {"stat", mcplib_stat},
         {"await", mcplib_await},
+        {"log", mcplib_log},
         {"backend_connect_timeout", mcplib_backend_connect_timeout},
         {"backend_retry_timeout", mcplib_backend_retry_timeout},
         {"backend_read_timeout", mcplib_backend_read_timeout},

proto_text.c

@@ -2291,6 +2291,12 @@ 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, "proxyevents") == 0)) {
+                f |= LOG_PROXYEVENTS;
+            } else if ((strcmp(tokens[x].value, "proxyuser") == 0)) {
+                f |= LOG_PROXYUSER;
             } else {
                 out_string(c, "ERROR");
                 return;

t/startfile.lua

@@ -131,6 +131,8 @@ function failover_factory(zones, local_zone)
     return function(r)
         local res = near_zone(r)
         if res:hit() == false then
+            -- example for mcp.log... Don't do this though :)
+            mcp.log("failed to find " .. r:key() .. " in zone: " .. local_zone)
             for _, zone in pairs(far_zones) do
                 res = zone(r)
                 if res:hit() then