SLT inventory
slimhazard edited this page May 6, 2019
·
1 revision
Related to VIP23, these are the results of a bit of grep-foo, applied to current master (May 6 2019), to get an overview of how log data is formatted by varnishd. The grep-foo of course may have missed some items.
Non-Timestamp VSL*() calls sorted by SLT_ tag, where the tag is identifiable in the code:
VSLb(bo->vsl, SLT_BackendClose, "%d %s", *PFD_Fd(pfd), VRT_BACKEND_string(bp->director));
VSLb(bo->vsl, SLT_BackendOpen, "%d %s %s %s %s %s", *fdp, VRT_BACKEND_string(bp->director), abuf2, pbuf2, abuf1, pbuf1);
VSLb(bo->vsl, SLT_BackendReuse, "%d %s", *PFD_Fd(pfd), VRT_BACKEND_string(bp->director));
VSL(SLT_Backend_health, 0, "%s %s %s %s %u %u %u %.6f %.6f %s", dir->vcl_name, chg ? "Went" : "Still", i ? "sick" : "healthy", bits, vt->good, vt->threshold, vt->window, vt->last, vt->avg, vt->resp_buf);
VSL(SLT_Begin, sp->vxid, "sess 0 %s", wa->acceptlsock->transport->name);
VSLb(req->vsl, SLT_Begin, "req %u esi", VXID(preq->vsl->wid));
VSLb(bo->vsl, SLT_Begin, "bereq %u %s", VXID(req->vsl->wid), how);
VSLb(bo->vsl, SLT_Begin, "bereq %u pipe", VXID(req->vsl->wid));
VSLb(vsl, SLT_Begin, "%s %u %s", typ, VXID(ovxid), why);
VSLb(req->vsl, SLT_Begin, "req %u rxreq", VXID(req->sp->vxid));
VSLb(req->vsl, SLT_Begin, "req %u rxreq", VXID(req->sp->vxid));
VSLb(bo->vsl, SLT_BereqAcct, "%ju %ju %ju %ju %ju %ju", (uintmax_t)bo->acct.bereq_hdrbytes, (uintmax_t)bo->acct.bereq_bodybytes, (uintmax_t)(bo->acct.bereq_hdrbytes + bo->acct.bereq_bodybytes), (uintmax_t)bo->acct.beresp_hdrbytes, (uintmax_t)bo->acct.beresp_bodybytes, (uintmax_t)(bo->acct.beresp_hdrbytes + bo->acct.beresp_bodybytes));
VSLb(hp->vsl, SLT_BogoHeader, "Header has ctrl char 0x%02x", *r);
VSLb(hp->vsl, SLT_BogoHeader, "Header too long: %.*s", (int)(q - p > 20 ? 20 : q - p), p);
VSLb(hp->vsl, SLT_BogoHeader, "1st header has white space: %.*s", (int)(q - p > 20 ? 20 : q - p), p);
VSLb(hp->vsl, SLT_BogoHeader, "Missing header name: %.*s", (int)(q - p > 20 ? 20 : q - p), p);
VSLb(hp->vsl, SLT_BogoHeader, "Illegal char 0x%02x in header name", *s);
VSLb(hp->vsl, SLT_BogoHeader, "Header without ':' %.*s", (int)(q - p > 20 ? 20 : q - p), p);
VSLb(hp->vsl, SLT_BogoHeader, "Too many headers: %.*s", (int)(q - p > 20 ? 20 : q - p), p);
VSLb(hp->vsl, SLT_BogoHeader, "Empty name");
VSLb(hp->vsl, SLT_BogoHeader, "Illegal header name (upper-case): %.*s", (int)(len > 20 ? 20 : len), b);
VSLb(hp->vsl, SLT_BogoHeader, "Illegal header name: %.*s", (int)(len > 20 ? 20 : len), b);
VSLb(hp->vsl, SLT_BogoHeader, "Illegal header value: %.*s", (int)(len > 20 ? 20 : len), b);
VSLb(hp->vsl, SLT_BogoHeader, "Header too large: %.20s", b);
VSLb(hp->vsl, SLT_BogoHeader, "Unknown pseudo-header: %.*s", (int)(len > 20 ? 20 : len), b);
VSLb(hp->vsl, SLT_BogoHeader, "Duplicate pseudo-header: %.*s", (int)(len > 20 ? 20 : len), b);
VSLb(h2->new_req->http->vsl, SLT_BogoHeader, "HPACK compression error/fini (%s)", VHD_Error(d->vhd_ret));
VSLb(hp->vsl, SLT_BogoHeader, "HPACK compression error (%s)", VHD_Error(d->vhd_ret));
VSL(SLT_CLI, 0, "Rd %s", VSB_data(cli->cmd));
VSL(SLT_CLI, 0, "Wr %03u %zd %s", cli->result, VSB_len(cli->sb), VSB_data(cli->sb));
VSL(SLT_CLI, 0, "EOF on CLI connection, worker stops");
VSL(SLT_Debug, 0, "XXX Accept thread dies %p", ps);
VSLb(&vsl, SLT_Debug, "lurker: sleep = %lf", dt);
VSLb(req->vsl, SLT_Debug, "VDP_push(%s)", vdp->name);
VSLb(wrk->vsl, SLT_Debug, "Fetch: Pass delivery abandoned");
VSLb(vc->wrk->vsl, SLT_Debug, "VFP_Open(%s)", vfe->vfp->name);
VSLb(req->vsl, SLT_Debug, "on waiting list <%p>", oh);
VSL(SLT_Debug, 0, "XXX Kill Pool %p", pp);
VSLb(req->vsl, SLT_Debug, "RANGE_FAIL %s", err);
VSLb(req->vsl, SLT_Debug, "vxid %u STP_%s sp %p vcl %p", req->vsl->wid, state, req->sp, req->vcl);
VSL(SLT_Debug, sp->vxid, "Clock step (now=%f < t_open=%f)", now, sp->t_open);
VSL(SLT_Debug, (id), __VA_ARGS__); \
VSL(SLT_Debug, 0, "Failing due to reqpoolfail (next= 0x%jx)", reqpoolfail);
VSL(SLT_Debug, 0, "Create worker thread failed %d %s", errno, vstrerror(errno));
VSLb(req->vsl, SLT_Debug, "H2 upgrade attempt");
VSLb(req->vsl, SLT_Debug, "H2 upgrade attempt has body");
VSLb(v1l->vsl, SLT_Debug, "Hit total send timeout, " "wrote = %zd/%zd; not retrying", i, v1l->liov);
VSLb(v1l->vsl, SLT_Debug, "Hit idle send timeout, wrote = %zd/%zd; retrying", i, v1l->liov);
VSLb(v1l->vsl, SLT_Debug, "Write error, retval = %zd, len = %zd, errno = %s", i, v1l->liov, vstrerror(errno));
VSLb(req->vsl, SLT_Debug, "HP {%d, \"%s\", \"%s\"} <%s>", hps->idx, hps->name, hps->val, hp->hd[u].b);
VSLb(h2->vsl, SLT_Debug, "H2: stream %u: %s", stream, h2e->txt);
VSLb(h2->vsl, SLT_Debug, "KILL st=%u state=%d sched=%d", r2->stream, r2->state, r2->scheduled);
VSLb(h2->vsl, SLT_Debug, "H2RXF %s", VSB_data(vsb));
VSLb(h2->vsl, SLT_Debug, "GOAWAY %s", h2->error->name);
VSLb(h2->vsl, SLT_Debug, "H2SETTING unknown setting 0x%04x=%08x (ignored)", x, y);
VSLb(h2->vsl, SLT_Debug, "H2SETTING invalid %s=0x%08x", s->name, y);
VSLb(h2->vsl, SLT_Debug, "H2SETTING %s=0x%08x", s->name, y);
VSLb(h2->vsl, SLT_Debug, "HPACK/FINI %s", h2e->name);
VSLb(h2->vsl, SLT_Debug, "Missing :method");
VSLb(h2->vsl, SLT_Debug, "Missing :path");
VSLb(h2->vsl, SLT_Debug, "H2: stream %u: Hit maximum number of " "concurrent streams", h2->rxf_stream);
VSLb(h2->vsl, SLT_Debug, "HPACK(hdr) %s", h2e->name);
VSLb(h2->vsl, SLT_Debug, "HPACK(cont) %s", h2e->name);
VSLb(req->vsl, SLT_Debug, "H2FAILREQ");
VSLb(h2->vsl, SLT_Debug, "H2: illegal stream (=%u)", h2->rxf_stream);
VSLb(h2->vsl, SLT_Debug, "H2: stream %u: Hit idle_send_timeout waiting " "for WINDOW_UPDATE", r2->stream);
VSLb(h2->vsl, SLT_Debug, "H2: stream %u: Hit send_timeout", r2->stream);
VSLb(h2->vsl, SLT_Debug, "H2: No frame (hs=%d)", hs);
VSLb(h2->vsl, SLT_Debug, "H2: Unknown frame type 0x%02x (ignored)", (uint8_t)h2->rxf_type);
VSLb(h2->vsl, SLT_Debug, "H2: Unknown flags 0x%02x on %s (ignored)", (uint8_t)h2->rxf_flags & ~h2f->flags, h2f->name);
VSLb(req->vsl, SLT_Debug, "H2CS %s", p);
VSLb(h2->vsl, SLT_Debug, "H2: Bad HTTP-Settings");
VSLb(h2->vsl, SLT_Debug, "H2: Upgrade: Error writing 101" " response: %s\n", vstrerror(errno));
VSLb(h2->vsl, SLT_Debug, "H2: No/Bad OU PRISM (hs=%d)", hs);
VSLb(h2->vsl, SLT_Debug, "H2: No Worker-threads");
VSLb(req->vsl, SLT_Debug, "H2 Prior Knowledge Upgrade");
VSLb(req->vsl, SLT_Debug, "H2 Optimistic Upgrade");
VSLb(h2->vsl, SLT_Debug, "H2: Got pu PRISM");
VSLb(h2->vsl, SLT_Debug, "H2: Empty Rx Workspace");
VSLb(h2->vsl, SLT_Debug, "H2 CLEANUP %s", h2->error->name);
VSLb(h2->vsl, SLT_Debug, "ST %u %d", r2->stream, r2->state);
VSL(SLT_Debug, 999, "PROXY_HDR %s", VSB_data(vsb2));
VSL(SLT_Debug, wp->fd, "epoll: spurious event");
VSL(SLT_Debug, 0, "Acceptor poll space increased by %zu to %zu", inc, vwp->npoll + inc);
VSL(SLT_Debug, wp->fd, "ADD");
VSL(SLT_Debug, vwp->pollfd[vwp->hpoll].fd, "DEL");
VSL(SLT_Debug, 0, "priv_task_free(%p)", ptr);
VSL(SLT_Debug, 0, "test_priv_task(%p) = %p (exists)", priv, priv->priv);
VSL(SLT_Debug, 0, "test_priv_task(%p) = %p (new)", priv, priv->priv);
VSL(SLT_Debug, 0, "test_priv_task(%p) = %p (update)", priv, priv->priv);
VSL(SLT_Debug, 0, "Object Event: %s 0x%jx", what, (intmax_t)(uintptr_t)oc);
VSL(SLT_Debug, 0, "Subscribed to Object Events");
VSL(SLT_Debug, 0, "Unsubscribed from Object Events");
VSL(SLT_Debug, 0, "%s: VCL_EVENT_WARM", VCL_Name(ctx->vcl));
VSL(SLT_Debug, 0, "%s: VCL_EVENT_COLD", VCL_Name(ctx->vcl));
VSLb(ctx->vsl, SLT_Debug, "perf size %jd rounds %jd time %.1fns check %jd", (intmax_t)size, (intmax_t)rounds, d, (uintmax_t)check);
VSLb(ctx->vsl, SLT_Debug, "SO_SNDBUF fd=%d old=%d new=%d actual=%d", fd, oldbuf, buflen, newbuf);
VSL(SLT_Debug, 0, "shard: " __VA_ARGS__); \
VSLb(ctx->vsl, SLT_Debug, "barrier_sync(\"%s\")", addr);
VSLb(vep->vc->wrk->vsl, SLT_ESI_xmlerror, "ERR after %zd %s", vep->o_last, p);
VSLb(vep->vc->wrk->vsl, SLT_ESI_xmlerror, "WARN after %zd %s", vep->o_last, p);
VSLb(vep->vc->wrk->vsl, SLT_ESI_xmlerror, "No ESI processing, " "first char not '<' but BOM." " (See feature esi_remove_bom)" );
VSLb(vep->vc->wrk->vsl, SLT_ESI_xmlerror, "No ESI processing, " "first char not '<'." " (See feature esi_disable_xml_check)" );
VSL(SLT_End, sp->vxid, "%s", "");
VSLbt(vsl, SLT_End, t);
VSL(SLT_Error, 0, "Kernel TCP Fast Open: sock=%d, ret=%d %s", ls->sock, i, vstrerror(errno));
VSL(SLT_Error, 0, "Kernel filtering: sock=%d, ret=%d %s", ls->sock, i, vstrerror(errno));
VSLb(req->vsl, SLT_Error, "ESI-corruption: Illegal Length %d %d\n", *p, (*p & 15));
VSLb(req->vsl, SLT_Error, "ESI corruption line %d 0x%02x [%s]\n", __LINE__, *ecx->p, ecx->p);
VSLb(bo->vsl, SLT_Error, "Illegal 'Vary' header from backend, " "making this a pass.");
VSLb(bo->vsl, SLT_Error, "Body cannot be fetched");
VSLb(bo->vsl, SLT_Error, "304 response but not conditional fetch");
VSLb(hp->vsl, SLT_Error, "out of workspace (%s)", hp->ws->id);
VSLb(to->vsl, SLT_Error, "Too many headers to Decode object (%u vs. %u)", vbe16dec(fm), to->shd);
VSL(SLT_Error, 0, "MALLOC ERROR: %s (%p)", s, p);
VSLb(req->vsl, SLT_Error, "Could not get storage");
VSLb(req->vsl, SLT_Error, "Failure to push processors");
VSLb(bo->vsl, SLT_Error, "Vary header name length exceeded");
VSLb(bo->vsl, SLT_Error, "Vary header maximum length exceeded");
VSLb(bo->vsl, SLT_Error, "Malformed Vary header");
VSLb(ctx->vsl, SLT_Error, "Note: Ignoring DURATION argument to return(pass);");
VSLb(req->vsl, SLT_Error, "Filter '...%s' not found", fl);
VSL(SLT_Error, 0, "Pool Herder: Queue does not move ql=%u dt=%f", pp->lqueue, VTIM_mono() - dqt);
VSLb(req->vsl, SLT_Error, "%s", msg);
VSLb(req->vsl, SLT_Error, "workspace_client overflow");
VSLb(ctx->vsl, SLT_Error, "workspace_dump: NULL");
VSLb(ctx->vsl, SLT_Error, "workspace_dump: off limit");
VSLb(vsl, SLT_ExpBan, "%u banned lookup", ObjGetXID(wrk, oc));
VSLb(vsl, SLT_ExpBan, "%u killed for lurker cutoff", ObjGetXID(wrk, oc));
VSLb(vsl, SLT_ExpBan, "%u banned by lurker", ObjGetXID(wrk, oc));
VSL(SLT_ExpKill, 0, "EXP_Rearm p=%p E=%.6f e=%.6f f=0x%x", oc, oc->timer_when, when, oc->flags);
VSLb(&ep->vsl, SLT_ExpKill, "EXP_Inbox flg=%x p=%p e=%.6f f=0x%x", flags, oc, oc->timer_when, oc->flags);
VSLb(&ep->vsl, SLT_ExpKill, "EXP_When p=%p e=%.6f f=0x%x", oc, oc->timer_when, flags);
VSLb(&ep->vsl, SLT_ExpKill, "EXP_expire p=%p e=%.6f f=0x%x", oc, oc->timer_when - now, oc->flags);
VSLb(&ep->vsl, SLT_ExpKill, "EXP_Expired x=%u t=%.0f", ObjGetXID(ep->wrk, oc), EXP_Ttl(NULL, oc) - now);
VSLb(wrk->vsl, SLT_ExpKill, "LRU reached nuke_limit");
VSLb(wrk->vsl, SLT_ExpKill, "LRU_Cand p=%p f=0x%x r=%d", oc, oc->flags, oc->refcnt);
VSLb(wrk->vsl, SLT_ExpKill, "LRU_Fail");
VSLb(wrk->vsl, SLT_ExpKill, "LRU x=%u", ObjGetXID(wrk, oc));
VSLb(bo->vsl, SLT_FetchError, "backend %s: unhealthy", VRT_BACKEND_string(bp->director));
VSLb(bo->vsl, SLT_FetchError, "backend %s: busy", VRT_BACKEND_string(bp->director));
VSLb(bo->vsl, SLT_FetchError, "out of workspace");
VSLb(bo->vsl, SLT_FetchError, "backend %s: fail errno %d (%s)", VRT_BACKEND_string(bp->director), err, vstrerror(err));
VSLb(bo->vsl, SLT_FetchError, "Timed out reusing backend connection");
VSLb(bo->vsl, SLT_FetchError, "Director %s returned no backend", d->vcl_name);
VSLb(bo->vsl, SLT_FetchError, "No backend");
VSLbv(vc->wrk->vsl, SLT_FetchError, fmt, ap);
VSLb(req->vsl, SLT_FetchError, "Had failed reading req.body before.");
VSLb(bo->vsl, SLT_FetchError, "req.body read error: %d (%s)", errno, vstrerror(errno));
VSLb(bo->vsl, SLT_FetchError, "backend write error: %d (%s)", errno, vstrerror(errno));
VSLb(bo->vsl, SLT_FetchError, "Received junk");
VSLb(bo->vsl, SLT_FetchError, "backend closed");
VSLb(bo->vsl, SLT_FetchError, "timeout");
VSLb(bo->vsl, SLT_FetchError, "overflow");
VSLb(bo->vsl, SLT_FetchError, "first byte timeout");
VSLb(bo->vsl, SLT_FetchError, "HTC %s (%d)", HTC_Status(hs), hs);
VSLb(bo->vsl, SLT_FetchError, "http format error");
VSLb(bo->vsl, SLT_FetchError, "overflow");
VSLb(vc->wrk->vsl, SLT_FetchError, "%s", vstrerror(errno));
VSLb(bo->vsl, SLT_Fetch_Body, "%u %s %s", bo->htc->body_status, body_status_2str(bo->htc->body_status), bo->do_stream ? "stream" : "-");
VSLb(vc->wrk->vsl, SLT_Filters, "%s", fl);
VSLb(req->vsl, SLT_Filters, "%s", fl);
VSLb(vg->vsl, SLT_Gzip, "Gunzip error: %d (%s)", i, vgz_msg(vg));
VSLb(vg->vsl, SLT_Gzip, "Gzip error: %d (%s)", i, vgz_msg(vg));
VSLb(vg->vsl, SLT_Gzip, "%s %jd %jd %jd %jd %jd", vg->id, (intmax_t)vg->vz.total_in, (intmax_t)vg->vz.total_out, (intmax_t)vg->vz.start_bit, (intmax_t)vg->vz.last_bit, (intmax_t)vg->vz.stop_bit);
VSLb(vg->vsl, SLT_Gzip, "G(un)zip error: %d (%s)", i, vgz_msg(vg));
VSLb_bin(h2->vsl, SLT_H2RxBody, len - 9, b + 9);
VSLb_bin(h2->vsl, SLT_H2RxHdr, 9, b);
VSLb_bin(h2->vsl, SLT_H2TxBody, len, ptr);
VSLb_bin(h2->vsl, SLT_H2TxHdr, 9, hdr);
VSLb(req->vsl, SLT_Hash, "%s", str);
VSLb(req->vsl, SLT_Hit, "%u %.6f %.6f %.6f", ObjGetXID(wrk, req->objcore), EXP_Dttl(req, req->objcore), req->objcore->grace, req->objcore->keep);
VSLb(req->vsl, SLT_HitMiss, "%u %.6f", xid, dttl);
VSLb(req->vsl, SLT_HitMiss, "%u %.6f", xid, dttl);
VSLb(req->vsl, SLT_HitPass, "%u %.6f", xid, dttl);
VSLb(req->vsl, SLT_HttpGarbage, "%.*s", (int)(req->htc->rxbuf_e - req->htc->rxbuf_b), req->htc->rxbuf_b);
VSLb(hp->vsl, SLT_HttpGarbage, "%.*s", (int)(htc->rxbuf_e - htc->rxbuf_b), htc->rxbuf_b);
VSLb(bo->vsl, SLT_Length, "%ju", (uintmax_t)ObjGetLen(bo->wrk, bo->fetch_objcore));
VSLb(preq->vsl, SLT_Link, "req %u esi", VXID(req->vsl->wid));
VSLb(req->vsl, SLT_Link, "bereq %u %s", VXID(bo->vsl->wid), how);
VSLb(req->vsl, SLT_Link, "bereq %u pipe", VXID(bo->vsl->wid));
VSLb(vsl, SLT_Link, "%s %u %s", typ, VXID(vxid), why);
VSL(SLT_Link, req->sp->vxid, "req %u rxreq", VXID(req->vsl->wid));
VSL(SLT_Link, req->sp->vxid, "req %u rxreq", VXID(req->vsl->wid));
VSLb(to->vsl, SLT_LostHeader, "%s", string);
VSLb(hp->vsl, SLT_LostHeader, "%s", hdr + 1);
VSLb(hp->vsl, SLT_LostHeader, "%s", hdr + 1);
VSLb(hp->vsl, SLT_LostHeader, "%s", hp->hd[u].b);
VSLb(to->vsl, SLT_LostHeader, "%s", hdr);
VSLbv(to->vsl, SLT_LostHeader, fmt, ap);
VSLb(to->vsl, SLT_LostHeader, "%s", fmt);
VSLb(to->vsl, SLT_LostHeader, "%s", fmt);
VSLb(ctx->vsl, SLT_LostHeader, "%s", hs->what + 1);
VSLb(ctx->vsl, SLT_LostHeader, "client.identity");
VSLb(ctx->vsl, SLT_LostHeader, "storage_hint");
VSLb(hp->vsl, SLT_LostHeader, "Too many headers: %.*s", (int)(len > 20 ? 20 : len), b);
VSLb(ctx->vsl, SLT_LostHeader, "%s", hs->what + 1);
VSLb(req->vsl, SLT_PipeAcct, "%ju %ju %ju %ju", (uintmax_t)a->req, (uintmax_t)a->bereq, (uintmax_t)a->in, (uintmax_t)a->out);
VSL(SLT_Proxy, req->sp->vxid, "1 %s %s %s %s", fld[1], fld[3], fld[2], fld[4]);
VSL(SLT_Proxy, req->sp->vxid, "2 local local local local");
VSL(SLT_Proxy, req->sp->vxid, "2 %s %s %s %s", hb, pb, ha, pa);
VSL(SLT_ProxyGarbage, req->sp->vxid, "PROXY1: Too few fields");
VSL(SLT_ProxyGarbage, req->sp->vxid, "PROXY1: Too many fields");
VSL(SLT_ProxyGarbage, req->sp->vxid, "PROXY1: Wrong TCP[46] field");
VSL(SLT_ProxyGarbage, req->sp->vxid, "PROXY1: Cannot resolve source address (%s)", gai_strerror(i));
VSL(SLT_ProxyGarbage, req->sp->vxid, "PROXY1: %s got wrong protocol (%d)", fld[0], res->ai_family);
VSL(SLT_ProxyGarbage, req->sp->vxid, "PROXY1: Cannot resolve destination address (%s)", gai_strerror(i));
VSL(SLT_ProxyGarbage, req->sp->vxid, "PROXY1: %s got wrong protocol (%d)", fld[0], res->ai_family);
VSL(SLT_ProxyGarbage, req->sp->vxid, "PROXY2: bad version (%d)", p[12] >> 4);
VSL(SLT_ProxyGarbage, req->sp->vxid, "PROXY2: bad command (%d)", p[12] & 0x0f);
VSL(SLT_ProxyGarbage, req->sp->vxid, "PROXY2: Ignoring UNSPEC|UNSPEC addresses");
VSL(SLT_ProxyGarbage, req->sp->vxid, "PROXY2: Ignoring short IPv4 addresses (%d)", l);
VSL(SLT_ProxyGarbage, req->sp->vxid, "PROXY2: Ignoring short IPv6 addresses (%d)", l);
VSL(SLT_ProxyGarbage, req->sp->vxid, "PROXY2: Ignoring unsupported protocol (0x%02x)", p[13]);
VSL(SLT_ProxyGarbage, req->sp->vxid, "PROXY2: CRC error");
VSL(SLT_ProxyGarbage, req->sp->vxid, "PROXY2: TLV %s", vpi->e);
VSL(SLT_ProxyGarbage, req->sp->vxid, "PROXY2: TLV overflows WS");
VSLb(req->vsl, SLT_ReqAcct, "%ju %ju %ju %ju %ju %ju", (uintmax_t)a->req_hdrbytes, (uintmax_t)a->req_bodybytes, (uintmax_t)(a->req_hdrbytes + a->req_bodybytes), (uintmax_t)a->resp_hdrbytes, (uintmax_t)a->resp_bodybytes, (uintmax_t)(a->resp_hdrbytes + a->resp_bodybytes));
VSLb(req->vsl, SLT_ReqStart, "%s %s %s", ci, cp, endpname);
VSLb(req->vsl, SLT_RespProtocol, "HTTP/1.1");
VSLb(req->vsl, SLT_RespProtocol, "HTTP/1.1");
VSLb(req->vsl, SLT_RespProtocol, "HTTP/2.0");
VSLb(req->vsl, SLT_RespProtocol, "HTTP/2.0");
VSLb(req->vsl, SLT_RespReason, "Internal Server Error");
VSLb(req->vsl, SLT_RespReason, "%s", reason);
VSLb(req->vsl, SLT_RespReason, "%s", http_Status2Reason(status, NULL));
VSLb(req->vsl, SLT_RespReason, "Internal Server Error");
VSLb(req->vsl, SLT_RespStatus, "500");
VSLb(req->vsl, SLT_RespStatus, "%03d", status);
VSLb(req->vsl, SLT_RespStatus, "%03d", status);
VSLb(req->vsl, SLT_RespStatus, "500");
VSL(SLT_SessClose, sp->vxid, "%s %.3f", sess_close_2str(reason, 0), now - sp->t_open);
VSL(SLT_SessError, 0, "%s %s %s %d %d %s", wa.acceptlsock->name, laddr, lport, ls->sock, i, vstrerror(i));
VSL(SLT_SessOpen, sp->vxid, "%s %s %s %s %s %.6f %d", raddr, rport, wa->acceptlsock->name, laddr, lport, sp->t_open, sp->fd);
VSLb(wrk->vsl, SLT_Storage, "%s %s", oc->stobj->stevedore->name, oc->stobj->stevedore->ident);
VSLb(bo->vsl, SLT_TTL, "RFC %.0f %.0f %.0f %.0f %.0f %.0f %.0f %u %s", *ttl, *grace, *keep, now, *t_origin, h_date, h_expires, max_age, bo->uncacheable ? "uncacheable" : "cacheable");
VSLb(ctx->vsl, SLT_TTL, "HFP %.0f %.0f %.0f %.0f uncacheable", oc->ttl, oc->grace, oc->keep, oc->t_origin);
VSLb(ctx->vsl, SLT_TTL, "VCL %.0f %.0f %.0f %.0f %s", \ oc->ttl, oc->grace, oc->keep, oc->t_origin, \ ctx->bo->uncacheable ? "uncacheable" : "cacheable");\
VSLb(ctx->vsl, SLT_TTL, "VCL %.0f %.0f %.0f %.0f %s", \ oc->ttl, oc->grace, oc->keep, oc->t_origin, \ ctx->bo->uncacheable ? "uncacheable" : "cacheable");\
VSLb(vsl, SLT_Timestamp, "%s: %.6f %.6f %.6f", event, now, now - first, now - *pprev);
VSLb(bo->vsl, SLT_VCL_Error, "Backend does not support pipe");
VSLb(preq->vsl, SLT_VCL_Error, "ESI depth limit reach (param max_esi_depth = %u)", cache_param->max_esi_depth);
VSLb(vc->wrk->vsl, SLT_VCL_Error, "Attempted ESI on partial (206) response");
VSLb(vc->wrk->vsl, SLT_VCL_Error, "Attempted ESI on partial (206) response");
VSLb(bo->vsl, SLT_VCL_Error, "Too many retries, delivering 503");
VSLb(bo->vsl, SLT_VCL_Error, "Too many retries, failing");
VSLb(req->vsl, SLT_VCL_Error, "Uncached req.body can only be consumed once.");
VSLb(req->vsl, SLT_VCL_Error, "Multiple attempts to access non-cached req.body");
VSLb(req->vsl, SLT_VCL_Error, "Too many restarts");
VSLb(req->vsl, SLT_VCL_Error, "Illegal return(vcl): %s", req->restarts ? "Not after restarts" : "Only from active VCL");
VSLb(req->vsl, SLT_VCL_Error, "vcl_recv{} returns pipe for ESI included object." " Doing pass.");
VSLb(req->vsl, SLT_VCL_Error, "vcl_recv{} returns pipe for HTTP/2 request." " Doing pass.");
VSLbv(ctx->vsl, SLT_VCL_Error, fmt, ap);
VSLb(ctx->vsl, SLT_VCL_Error, "ban(): Null argument");
VSLb(ctx->vsl, SLT_VCL_Error, "ban(): Out of Memory");
VSLb(ctx->vsl, SLT_VCL_Error, "ban(): %s", av[0]);
VSLb(ctx->vsl, SLT_VCL_Error, "ban(): No ban conditions found.");
VSLb(ctx->vsl, SLT_VCL_Error, "ban(): Expected comparison operator.");
VSLb(ctx->vsl, SLT_VCL_Error, "ban(): Expected second operand.");
VSLb(ctx->vsl, SLT_VCL_Error, "ban(): %s", err);
VSLb(ctx->vsl, SLT_VCL_Error, "ban(): %s", err);
VSLb(ctx->vsl, SLT_VCL_Error, "ban(): Expected && between conditions," " found \"%s\"", av[i]);
VSLb(ctx->vsl, SLT_VCL_Error, "req.body can only be cached in vcl_recv{}");
VSLb(ctx->vsl, SLT_VCL_Error, "Regexp matching returned %d", i);
VSLb(ctx->vsl, SLT_VCL_Error, "Regexp matching returned %d", i);
VSLb(ctx->vsl, SLT_VCL_Error, "Regexp matching returned %d", i);
VSLb(ctx->vsl, SLT_VCL_Error, "Ignoring attempt to reset beresp.uncacheable");
VSLb(ctx->vsl, SLT_VCL_Error, "std.late_100_continue() only valid in vcl_recv{}");
VSLb(ctx->vsl, SLT_VCL_Error, "vmod std.ip(): insufficient workspace");
VSLb(ctx->vsl, SLT_VCL_Log, "%s", p);
VSL(SLT_VCL_Log, 0, "%s", p);
VSLb(ctx->vsl, SLT_VCL_acl, "%s", msg);
VSL(SLT_VCL_acl, 0, "%s", msg);
VSLb(ctx.vsl, SLT_VCL_call, "%s", VCL_Method_Name(method));
VSLb(ctx.vsl, SLT_VCL_return, "%s", VCL_Return_Name(wrk->handling));
VSLb(ctx->vsl, SLT_VCL_trace, "%s %u %u.%u.%u", ctx->vcl->loaded_name, u, ctx->vcl->conf->ref[u].source, ctx->vcl->conf->ref[u].line, ctx->vcl->conf->ref[u].pos);
VSL(SLT_VCL_trace, 0, "%s %u %u.%u.%u", ctx->vcl->loaded_name, u, ctx->vcl->conf->ref[u].source, ctx->vcl->conf->ref[u].line, ctx->vcl->conf->ref[u].pos);
VSLb(bo->vsl, SLT_VCL_use, "%s", VCL_Name(bo->vcl));
VSLb(req->vsl, SLT_VCL_use, "%s", VCL_Name(req->vcl));
VSLb(ctx->req->vsl, SLT_VCL_use, "%s via %s", req->vcl->loaded_name, vcl->loaded_name);
VSLb(vc->wrk->vsl, SLT_VfpAcct, "%s %ju %ju", vfe->vfp->name, (uintmax_t)vfe->calls, (uintmax_t)vfe->bytes_out);
VSL(SLT_Witness, 0, "%s", q);
VSL(SLT_Witness, 0, "Unlock %s @ %s <%s>", il->w, r, q);
VSL(SLT_WorkThread, 0, "%p start", w);
VSL(SLT_WorkThread, 0, "%p end", w);
VSLb_ts*() calls:
VSLb_ts(bo->vsl, event, bo->t_first, &bo->t_prev, now);
VSLb_ts_busyobj(bo, "Bereq", W_TIM_real(wrk));
VSLb_ts_busyobj(bo, "Bereq", W_TIM_real(wrk));
VSLb_ts_busyobj(bo, "BerespBody", W_TIM_real(wrk));
VSLb_ts_busyobj(bo, "Beresp", now);
VSLb_ts_busyobj(bo, "Error", now);
VSLb_ts_busyobj(bo, "Retry", W_TIM_real(wrk));
VSLb_ts_busyobj(bo, "Start", bo->t_prev);
VSLb_ts_busyobj(bo, "Start", W_TIM_real(wrk));
VSLb_ts_busyobj(ctx->bo, label, VTIM_real());
VSLb_ts_req(ctx->req, label, VTIM_real());
VSLb_ts_req(ctx->req, "PipeSess", W_TIM_real(ctx->req->wrk));
VSLb_ts_req(ctx->req, "Pipe", W_TIM_real(ctx->req->wrk));
VSLb_ts_req(req, "Fetch", W_TIM_real(wrk));
VSLb_ts_req(req, "Process", now);
VSLb_ts_req(req, "Process", W_TIM_real(wrk));
VSLb_ts_req(req, "ReqBody", VTIM_real());
VSLb_ts_req(req, "Req", req->t_req);
VSLb_ts_req(req, "Req", req->t_req);
VSLb_ts_req(req, "Resp", W_TIM_real(wrk));
VSLb_ts_req(req, "Resp", W_TIM_real(wrk));
VSLb_ts_req(req, "Resp", W_TIM_real(wrk));
VSLb_ts_req(req, "Restart", W_TIM_real(wrk));
VSLb_ts_req(req, "Start", req->t_first);
VSLb_ts_req(req, "Start", req->t_first);
VSLb_ts_req(req, "Start", req->t_prev);
VSLb_ts_req(req, "Start", W_TIM_real(wrk));
VSLb_ts_req(req, "Waitinglist", W_TIM_real(wrk));
VSLb_ts(req->vsl, event, req->t_first, &req->t_prev, now);
Notice that none of the struct http logging appears in the code this way. The general logging for struct http is done by http_VSL_log() in cache_http.c, and the logging for SLT_*Unset (header unsetting) is done in a similar way in http_VSLH_del(). These are the SLT tags defined in include/tbl/vsl_tags_http.h, which are the following for each of Req, Resp, Bereq, Beresp and Obj:
*Method*URL*Protocol*Status*Reason*Header*Unset*Lost