diff --git a/logger.c b/logger.c index f04726036..c34bd359f 100644 --- a/logger.c +++ b/logger.c @@ -6,7 +6,6 @@ #include #include #include -#include #include #if defined(__sun) @@ -347,6 +346,7 @@ static void _logger_log_proxy_req(logentry *e, const entry_details *d, const voi unsigned short type = va_arg(ap, int); unsigned short code = va_arg(ap, int); int status = va_arg(ap, int); + int flag = va_arg(ap, int); int conn_fd = va_arg(ap, int); char *detail = va_arg(ap, char *); int dlen = va_arg(ap, int); @@ -357,6 +357,7 @@ static void _logger_log_proxy_req(logentry *e, const entry_details *d, const voi le->type = type; le->code = code; le->status = status; + le->flag = flag; le->conn_fd = conn_fd; le->dlen = dlen; le->elapsed = elapsed; @@ -391,14 +392,26 @@ static void _logger_log_proxy_req(logentry *e, const entry_details *d, const voi e->size = sizeof(struct logentry_proxy_req) + reqlen + dlen + le->be_namelen + le->be_portlen; } +// FIXME: if I ever get better discipline around headers we can include the +// proxy header. Since proxy.h includes memcached.h we need to redefine things +// here. +#define RQUEUE_R_GOOD (1<<3) +#define RQUEUE_R_OK (1<<4) +#define RQUEUE_R_ANY (1<<5) static int _logger_parse_prx_req(logentry *e, char *scratch) { int total; struct logentry_proxy_req *le = (void *)e->data; + const char *rqu_res = "any"; + if (le->flag == RQUEUE_R_GOOD) { + rqu_res = "good"; + } else if (le->flag == RQUEUE_R_OK) { + rqu_res = "ok"; + } total = snprintf(scratch, LOGGER_PARSE_SCRATCH, - "ts=%lld.%d gid=%llu type=proxy_req elapsed=%lu type=%d code=%d status=%d cfd=%d be=%.*s:%.*s detail=%.*s req=%.*s\n", + "ts=%lld.%d gid=%llu type=proxy_req elapsed=%lu type=%d code=%d status=%d res=%s cfd=%d be=%.*s:%.*s detail=%.*s req=%.*s\n", (long long int) e->tv.tv_sec, (int) e->tv.tv_usec, (unsigned long long) e->gid, - le->elapsed, le->type, le->code, le->status, le->conn_fd, + le->elapsed, le->type, le->code, le->status, rqu_res, le->conn_fd, (int)le->be_namelen, le->data+le->reqlen+le->dlen, (int)le->be_portlen, le->data+le->reqlen+le->dlen+le->be_namelen, // fml. (int)le->dlen, le->data+le->reqlen, (int)le->reqlen, le->data diff --git a/logger.h b/logger.h index 03b81fc83..63c5530f1 100644 --- a/logger.h +++ b/logger.h @@ -129,6 +129,7 @@ struct logentry_conn_event { struct logentry_proxy_req { unsigned short type; unsigned short code; + uint8_t flag; int status; int conn_fd; uint32_t reqlen; diff --git a/proto_proxy.c b/proto_proxy.c index fcf1b9d2a..49448a3b5 100644 --- a/proto_proxy.c +++ b/proto_proxy.c @@ -1196,8 +1196,6 @@ mcp_resp_t *mcp_prep_bare_resobj(lua_State *L, LIBEVENT_THREAD *t) { void mcp_set_resobj(mcp_resp_t *r, mcp_request_t *rq, mcp_backend_t *be, LIBEVENT_THREAD *t) { memset(r, 0, sizeof(mcp_resp_t)); - r->buf = NULL; - r->blen = 0; r->thread = t; assert(r->thread != NULL); gettimeofday(&r->start, NULL); @@ -1224,20 +1222,7 @@ void mcp_set_resobj(mcp_resp_t *r, mcp_request_t *rq, mcp_backend_t *be, LIBEVEN } r->cmd = rq->pr.command; - - strncpy(r->be_name, be->name, MAX_NAMELEN+1); - strncpy(r->be_port, be->port, MAX_PORTLEN+1); - -} - -mcp_resp_t *mcp_prep_resobj(lua_State *L, mcp_request_t *rq, mcp_backend_t *be, LIBEVENT_THREAD *t) { - mcp_resp_t *r = lua_newuserdatauv(L, sizeof(mcp_resp_t), 0); - mcp_set_resobj(r, rq, be, t); - - luaL_getmetatable(L, "mcp.response"); - lua_setmetatable(L, -2); - - return r; + r->be = be; } void mcp_resp_set_elapsed(mcp_resp_t *r) { diff --git a/proxy.h b/proxy.h index 972e788af..303c93906 100644 --- a/proxy.h +++ b/proxy.h @@ -227,6 +227,13 @@ struct proxy_tunables { bool down; // backend is forced into a down/bad state. }; +struct proxy_logging { + unsigned int deadline; // log if slower than N us (user specifies ms) + unsigned int rate; // sampling + bool all_errors; // always log on an error case + char *detail; +}; + typedef STAILQ_HEAD(globalobj_head_s, mcp_globalobj_s) globalobj_head_t; typedef struct { lua_State *proxy_state; // main configuration vm @@ -382,7 +389,9 @@ struct mcp_backend_label_s { char label[MAX_LABELLEN+1]; size_t llen; // cache label length for small speedup in pool creation. int conncount; // number of sockets to make. + bool use_logging; struct proxy_tunables tunables; + struct proxy_logging logging; }; // lua object wrapper meant to own a malloc'ed conn structure @@ -435,13 +444,15 @@ struct mcp_backend_s { bool transferred; // if beconn has been shipped to owner thread. bool use_io_thread; // note if this backend is worker-local or not. bool stacked; // if backend already queued for syscalls. + bool use_logging; // if automatic logging is enabled. STAILQ_ENTRY(mcp_backend_s) beconn_next; // stack for connecting conns STAILQ_ENTRY(mcp_backend_s) be_next; // stack for backends iop_head_t iop_head; // stack of inbound requests. + struct proxy_logging logging; + struct proxy_tunables tunables; // this gets copied a few times for speed. char name[MAX_NAMELEN+1]; char port[MAX_PORTLEN+1]; char label[MAX_LABELLEN+1]; - struct proxy_tunables tunables; // this gets copied a few times for speed. struct mcp_backendconn_s be[]; }; typedef STAILQ_HEAD(be_head_s, mcp_backend_s) be_head_t; @@ -494,6 +505,7 @@ typedef struct { char *buf; // response line + potentially value. mc_resp *cresp; // client mc_resp object during extstore fetches. LIBEVENT_THREAD *thread; // cresp's owner thread needed for extstore cleanup. + mcp_backend_t *be; // backend that generated this response unsigned int blen; // total size of the value to read. struct timeval start; // time this object was created. long elapsed; // time elapsed once handled. @@ -502,8 +514,6 @@ typedef struct { uint8_t cmd; // from parser (pr.command) uint8_t extra; // ascii multiget hack for memory accounting. extra blen. enum mcp_resp_mode mode; // reply mode (for noreply fixing) - char be_name[MAX_NAMELEN+1]; - char be_port[MAX_PORTLEN+1]; } mcp_resp_t; // re-cast an io_pending_t into this more descriptive structure. @@ -600,7 +610,6 @@ void proxy_init_event_thread(proxy_event_thread_t *t, proxy_ctx_t *ctx, struct e void *proxy_event_thread(void *arg); void proxy_run_backend_queue(be_head_t *head); struct mcp_backendconn_s *proxy_choose_beconn(mcp_backend_t *be); -mcp_resp_t *mcp_prep_resobj(lua_State *L, mcp_request_t *rq, mcp_backend_t *be, LIBEVENT_THREAD *t); mcp_resp_t *mcp_prep_bare_resobj(lua_State *L, LIBEVENT_THREAD *t); void mcp_resp_set_elapsed(mcp_resp_t *r); io_pending_proxy_t *mcp_queue_rctx_io(mcp_rcontext_t *rctx, mcp_request_t *rq, mcp_backend_t *be, mcp_resp_t *r); @@ -787,7 +796,7 @@ int mcplib_funcgen_gc(lua_State *L); void mcp_funcgen_reference(lua_State *L); void mcp_funcgen_dereference(lua_State *L, mcp_funcgen_t *fgen); void mcp_rcontext_push_rqu_res(lua_State *L, mcp_rcontext_t *rctx, int handle); - +void mcplib_rqu_log(mcp_request_t *rq, mcp_resp_t *rs, int flag, int cfd); int mcplib_factory_command_new(lua_State *L); diff --git a/proxy_internal.c b/proxy_internal.c index 71fe0a32e..289e98b21 100644 --- a/proxy_internal.c +++ b/proxy_internal.c @@ -1718,10 +1718,6 @@ static inline int _mcplib_internal_run(LIBEVENT_THREAD *t, mcp_request_t *rq, mc } } - // in case someone logs this response it should make sense. - memcpy(r->be_name, "internal", strlen("internal")); - memcpy(r->be_port, "0", 1); - // TODO: r-> will need status/code/mode copied from resp. r->cresp = resp; r->thread = t; diff --git a/proxy_lua.c b/proxy_lua.c index 857f17679..af91d01d5 100644 --- a/proxy_lua.c +++ b/proxy_lua.c @@ -285,7 +285,56 @@ static int mcplib_backend_wrap_gc(lua_State *L) { } static int mcplib_backend_gc(lua_State *L) { - return 0; // no-op. + mcp_backend_label_t *be = lua_touserdata(L, 1); + if (be->logging.detail) + free(be->logging.detail); + + return 0; +} + +static int _mcplib_backend_log(lua_State *L, mcp_backend_label_t *be) { + be->use_logging = true; + + if (lua_getfield(L, -1, "deadline") != LUA_TNIL) { + int deadline = luaL_checkinteger(L, -1); + if (deadline < 0) { + proxy_lua_error(L, "backend log deadline must be >= 0"); + } + // convert to milliseconds. + be->logging.deadline = deadline * 1000; + } + lua_pop(L, 1); + + if (lua_getfield(L, -1, "rate") != LUA_TNIL) { + int rate = luaL_checkinteger(L, -1); + if (rate < 0) { + proxy_lua_error(L, "backend log sample rate must be >= 0"); + } + be->logging.rate = rate; + } + lua_pop(L, 1); + + if (lua_getfield(L, -1, "errors") != LUA_TNIL) { + luaL_checktype(L, -1, LUA_TBOOLEAN); + int errors = lua_toboolean(L, -1); + if (errors) { + be->logging.all_errors = true; + } else { + be->logging.all_errors = false; + } + } + lua_pop(L, 1); + + if (lua_getfield(L, -1, "tag") != LUA_TNIL) { + size_t tlen = 0; + const char *tag = luaL_checklstring(L, -1, &tlen); + be->logging.detail = malloc(tlen+1); + memcpy(be->logging.detail, tag, tlen); + be->logging.detail[tlen] = '\0'; + } + lua_pop(L, 1); + + return 0; } // backend label object; given to pools which then find or create backend @@ -298,15 +347,18 @@ static int mcplib_backend(lua_State *L) { size_t llen = 0; size_t nlen = 0; size_t plen = 0; - proxy_ctx_t *ctx = PROXY_GET_CTX(L); - mcp_backend_label_t *be = lua_newuserdatauv(L, sizeof(mcp_backend_label_t), 0); - memset(be, 0, sizeof(*be)); const char *label; const char *name; const char *port; + proxy_ctx_t *ctx = PROXY_GET_CTX(L); + mcp_backend_label_t *be = lua_newuserdatauv(L, sizeof(mcp_backend_label_t), 0); + memset(be, 0, sizeof(*be)); // copy global defaults for tunables. memcpy(&be->tunables, &ctx->tunables, sizeof(be->tunables)); be->conncount = 1; // one connection per backend as default. + // set the metatable early so the GC handler can free partial allocations + luaL_getmetatable(L, "mcp.backend"); + lua_setmetatable(L, -2); // set metatable to userdata. if (lua_istable(L, 1)) { @@ -455,6 +507,14 @@ static int mcplib_backend(lua_State *L) { } lua_pop(L, 1); + if (lua_getfield(L, 1, "log") != LUA_TNIL) { + if (lua_istable(L, -1)) { + _mcplib_backend_log(L, be); + } else { + proxy_lua_error(L, "backend log option must be a table"); + } + } + lua_pop(L, 1); } else { label = luaL_checklstring(L, 1, &llen); name = luaL_checklstring(L, 2, &nlen); @@ -486,8 +546,6 @@ static int mcplib_backend(lua_State *L) { if (lua_istable(L, 1)) { lua_pop(L, 3); // drop label, name, port. } - luaL_getmetatable(L, "mcp.backend"); - lua_setmetatable(L, -2); // set metatable to userdata. return 1; // return be object. } @@ -530,12 +588,21 @@ static mcp_backend_wrap_t *_mcplib_make_backendconn(lua_State *L, mcp_backend_la proxy_lua_error(L, "out of memory allocating backend connection"); return NULL; } + bew->be = be; strncpy(be->name, bel->name, MAX_NAMELEN+1); strncpy(be->port, bel->port, MAX_PORTLEN+1); strncpy(be->label, bel->label, MAX_LABELLEN+1); memcpy(&be->tunables, &bel->tunables, sizeof(bel->tunables)); + memcpy(&be->logging, &bel->logging, sizeof(bel->logging)); + be->use_logging = bel->use_logging; + // TODO: check for errors. + // not really going to happen and if it does the tag just blanks out.. + if (bel->logging.detail) { + be->logging.detail = strdup(bel->logging.detail); + } + be->conncount = bel->conncount; STAILQ_INIT(&be->iop_head); @@ -1397,15 +1464,28 @@ static int mcplib_log_req(lua_State *L) { rtype = rs->resp.type; rcode = rs->resp.code; rstatus = rs->status; - rname = rs->be_name; - rport = rs->be_port; + if (rs->be) { + rname = rs->be->name; + rport = rs->be->port; + } else { + rname = "internal"; + rport = "0"; + } elapsed = rs->elapsed; } size_t dlen = 0; const char *detail = luaL_optlstring(L, 3, NULL, &dlen); int cfd = luaL_optinteger(L, 4, 0); + uint8_t flag = RQUEUE_R_ANY; + if (rstatus == MCMC_OK) { + if (rcode != MCMC_CODE_END) { + flag = RQUEUE_R_GOOD; + } else { + flag = RQUEUE_R_OK; + } + } - logger_log(l, LOGGER_PROXY_REQ, NULL, rq->pr.request, rq->pr.reqlen, elapsed, rtype, rcode, rstatus, cfd, detail, dlen, rname, rport); + logger_log(l, LOGGER_PROXY_REQ, NULL, rq->pr.request, rq->pr.reqlen, elapsed, rtype, rcode, rstatus, flag, cfd, detail, dlen, rname, rport); return 0; } @@ -1432,6 +1512,45 @@ static uint32_t _mcp_nextrand(uint32_t *s) { return result; } +void mcplib_rqu_log(mcp_request_t *rq, mcp_resp_t *rs, int flag, int cfd) { + LIBEVENT_THREAD *t = rs->thread; + logger *l = t->l; + + long elapsed = 0; + + int rtype = rs->resp.type; + int rcode = rs->resp.code; + int rstatus = rs->status; + elapsed = rs->elapsed; + + bool do_log = false; + struct proxy_logging *pl = &rs->be->logging; + if (pl->all_errors && rstatus != MCMC_OK) { + do_log = true; + } else if (pl->deadline > 0 && elapsed > pl->deadline) { + do_log = true; + } else if (pl->rate > 0) { + // slightly biased random-to-rate without adding a loop, which is + // completely fine for this use case. + uint32_t rnd = (uint64_t)_mcp_nextrand(t->proxy_rng) * (uint64_t)pl->rate >> 32; + if (rnd == 0) { + do_log = true; + } + } + + if (do_log) { + char *rname = rs->be->name; + char *rport = rs->be->port; + size_t dlen = 0; + const char *detail = rs->be->logging.detail; + + if (detail) { + dlen = strlen(detail); + } + + logger_log(l, LOGGER_PROXY_REQ, NULL, rq->pr.request, rq->pr.reqlen, elapsed, rtype, rcode, rstatus, flag, cfd, detail, dlen, rname, rport); + } +} // (milliseconds, sample_rate, allerrors, request, resp, "detail") static int mcplib_log_reqsample(lua_State *L) { @@ -1459,8 +1578,13 @@ static int mcplib_log_reqsample(lua_State *L) { rtype = rs->resp.type; rcode = rs->resp.code; rstatus = rs->status; - rname = rs->be_name; - rport = rs->be_port; + if (rs->be) { + rname = rs->be->name; + rport = rs->be->port; + } else { + rname = "internal"; + rport = "0"; + } elapsed = rs->elapsed; } size_t dlen = 0; @@ -1480,9 +1604,17 @@ static int mcplib_log_reqsample(lua_State *L) { do_log = true; } } + uint8_t flag = RQUEUE_R_ANY; + if (rstatus == MCMC_OK) { + if (rcode != MCMC_CODE_END) { + flag = RQUEUE_R_GOOD; + } else { + flag = RQUEUE_R_OK; + } + } if (do_log) { - logger_log(l, LOGGER_PROXY_REQ, NULL, rq->pr.request, rq->pr.reqlen, elapsed, rtype, rcode, rstatus, cfd, detail, dlen, rname, rport); + logger_log(l, LOGGER_PROXY_REQ, NULL, rq->pr.request, rq->pr.reqlen, elapsed, rtype, rcode, rstatus, flag, cfd, detail, dlen, rname, rport); } return 0; diff --git a/proxy_luafgen.c b/proxy_luafgen.c index 7b1b280fe..22d54ef88 100644 --- a/proxy_luafgen.c +++ b/proxy_luafgen.c @@ -1082,6 +1082,10 @@ int mcp_process_rqueue_return(mcp_rcontext_t *rctx, int handle, mcp_resp_t *res) } } + if (res->be && res->be->use_logging) { + mcplib_rqu_log(rqu->rq, res, flag, rctx->conn_fd); + } + if (rqu->cb_ref) { lua_settop(rctx->Lc, 0); lua_rawgeti(rctx->Lc, LUA_REGISTRYINDEX, rqu->cb_ref); @@ -1115,6 +1119,7 @@ int mcp_process_rqueue_return(mcp_rcontext_t *rctx, int handle, mcp_resp_t *res) // we settop _before_ calling cb's and // _before_ setting up for a coro resume. } + rqu->flags |= flag; return rqu->flags; } @@ -1148,10 +1153,7 @@ void mcp_run_rcontext_handle(mcp_rcontext_t *rctx, int handle) { if (rqu->obj_type == RQUEUE_TYPE_POOL) { mcp_request_t *rq = rqu->rq; mcp_backend_t *be = mcplib_pool_proxy_call_helper(rqu->obj, MCP_PARSER_KEY(rq->pr), rq->pr.klen); - // FIXME: queue requires conn because we're stacking objects - // into the connection for later submission, which means we - // absolutely cannot queue things once *c becomes invalid. - // need to assert/block this from happening. + mcp_set_resobj(rqu->res_obj, rq, be, rctx->fgen->thread); io_pending_proxy_t *p = mcp_queue_rctx_io(rctx, rq, be, rqu->res_obj); p->return_cb = proxy_return_rqu_cb; diff --git a/proxy_network.c b/proxy_network.c index c68b476b0..5c9ee76bf 100644 --- a/proxy_network.c +++ b/proxy_network.c @@ -171,6 +171,13 @@ static void _proxy_event_handler_dequeue(proxy_event_thread_t *t) { } static void _cleanup_backend(mcp_backend_t *be) { + if (be->use_logging) { + if (be->logging.detail) { + free(be->logging.detail); + be->logging.detail = NULL; + } + } + for (int x = 0; x < be->conncount; x++) { struct mcp_backendconn_s *bec = &be->be[x]; // remove any pending events. diff --git a/t/proxyfuncgen.lua b/t/proxyfuncgen.lua index 4667aba26..2481b5cd6 100644 --- a/t/proxyfuncgen.lua +++ b/t/proxyfuncgen.lua @@ -49,7 +49,21 @@ function mcp_config_pools() local b2z = mcp.pool({b2}) local b3z = mcp.pool({b3}) local b4z = mcp.pool({b4}) - local p = {p = {b1z, b2z, b3z}, b = b4z} + + local blog = srv({ + label = "blog", + host = "127.0.0.1", + port = "12015", + log = { + rate = 5, + errors = true, + deadline = 250, + tag = "fastlog" + } + }) + blogz = mcp.pool({blog}) + + local p = {p = {b1z, b2z, b3z}, b = b4z, pl = blogz} --return mcp.pool(b1z, { iothread = false }) return p @@ -617,6 +631,7 @@ end function mcp_config_routes(p) local b_pool = p.b + local pl = p.pl p = p.p local single = new_direct_factory({ p = p[1], name = "single" }) -- use the typically unused backend. @@ -629,6 +644,7 @@ function mcp_config_routes(p) local fastgoodint = new_basic_factory({ list = p, wait = 2, name = "fastgoodint" }, fastgoodint_factory_gen) local blocker = new_blocker_factory({ blocker = b_pool, list = p, name = "blocker" }) local logall = new_basic_factory({ list = p, name = "logall" }, logall_factory_gen) + local fastlog = new_direct_factory({ p = pl, name = "fastlog" }) local summary = new_basic_factory({ list = p, name = "summary" }, summary_factory_gen) local waitfor = new_basic_factory({ list = p, name = "waitfor" }, waitfor_factory_gen) local failover = new_basic_factory({ list = p, name = "failover" }, failover_factory_gen) @@ -652,6 +668,7 @@ function mcp_config_routes(p) ["fastgoodint"] = fastgoodint, ["blocker"] = blocker, ["logall"] = logall, + ["fastlog"] = fastlog, ["summary"] = summary, ["waitfor"] = waitfor, ["failover"] = failover, diff --git a/t/proxyfuncgen.t b/t/proxyfuncgen.t index 285bc6b67..dd3bb035c 100644 --- a/t/proxyfuncgen.t +++ b/t/proxyfuncgen.t @@ -21,7 +21,7 @@ if (!supports_proxy()) { # Set up the listeners _before_ starting the proxy. # the fourth listener is only occasionally used. -my $t = Memcached::ProxyTest->new(servers => [12011, 12012, 12013, 12014]); +my $t = Memcached::ProxyTest->new(servers => [12011, 12012, 12013, 12014, 12015]); my $p_srv = new_memcached('-o proxy_config=./t/proxyfuncgen.lua -t 1'); my $ps = $p_srv->sock; @@ -31,6 +31,7 @@ $t->set_c($ps); $t->accept_backends(); { # Comment out unused sections when debugging. + test_logging(); test_pipeline(); test_split(); test_basic(); @@ -47,6 +48,29 @@ $t->accept_backends(); done_testing(); +sub test_logging { + subtest 'log error' => sub { + my $w = $p_srv->new_sock; + print $w "watch proxyreqs\n"; + is(<$w>, "OK\r\n", 'watcher enabled'); + + $t->c_send("mg fastlog/a t\r\n"); + $t->be_recv_c([4]); + $t->be_send([4], "SERVER_ERROR busted\r\n"); + $t->c_recv_be(); + + my $l2 = scalar <$w>; + like($l2, qr/detail=fastlog/, 'got logreq line'); + like($l2, qr/cfd=/, 'client file descriptor present'); + unlike($l2, qr/cfd=0/, 'client file descriptor is nonzero'); + + $t->clear(); + }; + + # test sampling when not error + # test always log when slow/fast +} + # This kind of testing is difficult to do from integration level test suites # like this, but do what we can. sub test_errors { diff --git a/t/proxyinternal.lua b/t/proxyinternal.lua index a2aa3aed3..2611a52bd 100644 --- a/t/proxyinternal.lua +++ b/t/proxyinternal.lua @@ -24,7 +24,13 @@ function mcp_config_routes(zones) if string.find(k, "^/sub/") then return rctx:enqueue_and_wait(r, hsub) else - return rctx:enqueue_and_wait(r, h) + if k == "log" then + local res = rctx:enqueue_and_wait(r, h) + mcp.log_req(r, res, "testing") + return res + else + return rctx:enqueue_and_wait(r, h) + end end end end}) diff --git a/t/proxyinternal.t b/t/proxyinternal.t index 09e820934..93bc0cf1f 100644 --- a/t/proxyinternal.t +++ b/t/proxyinternal.t @@ -217,6 +217,16 @@ subtest 'watch deletions' => sub { "meta-delete command logged with correct size"); }; +subtest 'log' => sub { + my $watcher = $p_srv->new_sock; + print $watcher "watch proxyreqs\n"; + is(<$watcher>, "OK\r\n", "watcher enabled"); + + print $ps "mg log v\r\n"; + is(scalar <$ps>, "EN\r\n", "miss received"); + like(<$watcher>, qr/detail=testing/, "got log line"); +}; + done_testing(); END { diff --git a/t/proxyunits.t b/t/proxyunits.t index a61914fe4..c5cbc3927 100644 --- a/t/proxyunits.t +++ b/t/proxyunits.t @@ -1127,7 +1127,7 @@ check_sanity($ps); is(scalar <$be>, $cmd, "got passthru for log"); print $be "END\r\n"; is(scalar <$ps>, "END\r\n", "got END from log test"); - like(<$watcher>, qr/ts=(\S+) gid=\d+ type=proxy_req elapsed=\d+ type=105 code=17 status=0 cfd=\d+ be=127.0.0.1:11411 detail=logreqtest req=get \/logreqtest\/a/, "found request log entry"); + like(<$watcher>, qr/ts=(\S+) gid=\d+ type=proxy_req elapsed=\d+ type=105 code=17 status=0 res=ok cfd=\d+ be=127.0.0.1:11411 detail=logreqtest req=get \/logreqtest\/a/, "found request log entry"); # test log_req with nil res (should be 0's in places) # log_reqsample() @@ -1145,7 +1145,7 @@ check_sanity($ps); sleep 0.3; print $be "END\r\n"; is(scalar <$ps>, "END\r\n", "got END from log test"); - like(<$watcher>, qr/ts=(\S+) gid=\d+ type=proxy_req elapsed=\d+ type=105 code=17 status=0 cfd=\d+ be=127.0.0.1:11411 detail=logsampletest req=get \/logreqstest\/b/, "only got b request from log sample"); + like(<$watcher>, qr/ts=(\S+) gid=\d+ type=proxy_req elapsed=\d+ type=105 code=17 status=0 res=ok cfd=\d+ be=127.0.0.1:11411 detail=logsampletest req=get \/logreqstest\/b/, "only got b request from log sample"); } # Test out of spec commands from client