static void
wsl(struct worker *wrk, enum VSL_tag_e tag, int id, const char *fmt, va_list ap)
{
char *p;
unsigned n, mlen;
txt t;
AN(fmt);
mlen = cache_param->shm_reclen;
if (strchr(fmt, '%') == NULL) {
t.b = TRUST_ME(fmt);
t.e = strchr(t.b, '\0');
WSLR(wrk, tag, id, t);
} else {
assert(wrk->wlp < wrk->wle);
/* Wrap if we cannot fit a full size record */
if (VSL_END(wrk->wlp, mlen) >= wrk->wle)
WSL_Flush(wrk, 1);
p = VSL_DATA(wrk->wlp);
n = vsnprintf(p, mlen, fmt, ap);
if (n > mlen)
n = mlen; /* we truncate long fields */
vsl_hdr(tag, wrk->wlp, n, id);
wrk->wlp = VSL_END(wrk->wlp, n);
assert(wrk->wlp < wrk->wle);
wrk->wlr++;
}
if (cache_param->diag_bitmap & 0x10000)
WSL_Flush(wrk, 0);
}
void
WSLR(struct worker *wrk, enum VSL_tag_e tag, int id, txt t)
{
unsigned l, mlen;
Tcheck(t);
mlen = cache_param->shm_reclen;
/* Truncate */
l = Tlen(t);
if (l > mlen) {
l = mlen;
t.e = t.b + l;
}
assert(wrk->wlp < wrk->wle);
/* Wrap if necessary */
if (VSL_END(wrk->wlp, l) >= wrk->wle)
WSL_Flush(wrk, 1);
assert (VSL_END(wrk->wlp, l) < wrk->wle);
memcpy(VSL_DATA(wrk->wlp), t.b, l);
vsl_hdr(tag, wrk->wlp, l, id);
wrk->wlp = VSL_END(wrk->wlp, l);
assert(wrk->wlp < wrk->wle);
wrk->wlr++;
if (cache_param->diag_bitmap & 0x10000)
WSL_Flush(wrk, 0);
}
void
VDI_RecycleFd(struct worker *wrk, struct vbc **vbp)
{
struct backend *bp;
struct vbc *vc;
CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
AN(vbp);
vc = *vbp;
*vbp = NULL;
CHECK_OBJ_NOTNULL(vc, VBC_MAGIC);
CHECK_OBJ_NOTNULL(vc->backend, BACKEND_MAGIC);
assert(vc->fd >= 0);
bp = vc->backend;
WSL(wrk, SLT_BackendReuse, vc->vsl_id, "%s", bp->display_name);
/*
* Flush the shmlog, so that another session reusing this backend
* will log chronologically later than our use of it.
*/
WSL_Flush(wrk, 0);
Lck_Lock(&bp->mtx);
VSC_C_main->backend_recycle++;
VTAILQ_INSERT_HEAD(&bp->connlist, vc, list);
VBE_DropRefLocked(bp);
}
void
VDI_CloseFd(struct worker *wrk, struct vbc **vbp)
{
struct backend *bp;
struct vbc *vc;
CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
AN(vbp);
vc = *vbp;
*vbp = NULL;
CHECK_OBJ_NOTNULL(vc, VBC_MAGIC);
CHECK_OBJ_NOTNULL(vc->backend, BACKEND_MAGIC);
assert(vc->fd >= 0);
bp = vc->backend;
WSL(wrk, SLT_BackendClose, vc->vsl_id, "%s", bp->display_name);
/* Checkpoint log to flush all info related to this connection
before the OS reuses the FD */
WSL_Flush(wrk, 0);
VTCP_close(&vc->fd);
VBE_DropRefConn(bp);
vc->backend = NULL;
VBE_ReleaseConn(vc);
}
void
CNT_Session(struct sess *sp)
{
int done;
struct worker *w;
CHECK_OBJ_NOTNULL(sp, SESS_MAGIC);
w = sp->wrk;
CHECK_OBJ_NOTNULL(w, WORKER_MAGIC);
/*
* Possible entrance states
*/
assert(
sp->step == STP_FIRST ||
sp->step == STP_START ||
sp->step == STP_LOOKUP ||
sp->step == STP_RECV);
/*
* Whenever we come in from the acceptor we need to set blocking
* mode, but there is no point in setting it when we come from
* ESI or when a parked sessions returns.
* It would be simpler to do this in the acceptor, but we'd rather
* do the syscall in the worker thread.
*/
if (sp->step == STP_FIRST || sp->step == STP_START)
TCP_blocking(sp->fd);
for (done = 0; !done; ) {
assert(sp->wrk == w);
/*
* This is a good place to be paranoid about the various
* pointers still pointing to the things we expect.
*/
CHECK_OBJ_NOTNULL(sp, SESS_MAGIC);
CHECK_OBJ_ORNULL(sp->obj, OBJECT_MAGIC);
CHECK_OBJ_NOTNULL(sp->wrk, WORKER_MAGIC);
CHECK_OBJ_ORNULL(w->nobjhead, OBJHEAD_MAGIC);
WS_Assert(w->ws);
switch (sp->step) {
#define STEP(l,u) \
case STP_##u: \
if (params->diag_bitmap & 0x01) \
cnt_diag(sp, #u); \
done = cnt_##l(sp); \
break;
#include "steps.h"
#undef STEP
default:
WRONG("State engine misfire");
}
WS_Assert(w->ws);
CHECK_OBJ_ORNULL(w->nobjhead, OBJHEAD_MAGIC);
}
WSL_Flush(w, 0);
AZ(w->wfd);
}
static void *
exp_timer(struct sess *sp, void *priv)
{
struct objcore *oc;
struct object *o;
double t;
struct objcore_head *lru;
(void)priv;
AZ(sleep(10)); /* XXX: Takes time for VCL to arrive */
VCL_Get(&sp->vcl);
t = TIM_real();
while (1) {
Lck_Lock(&exp_mtx);
oc = binheap_root(exp_heap);
CHECK_OBJ_ORNULL(oc, OBJCORE_MAGIC);
if (oc == NULL || oc->timer_when > t) { /* XXX: > or >= ? */
Lck_Unlock(&exp_mtx);
WSL_Flush(sp->wrk, 0);
WRK_SumStat(sp->wrk);
AZ(sleep(1));
VCL_Refresh(&sp->vcl);
t = TIM_real();
continue;
}
o = oc->obj;
CHECK_OBJ_NOTNULL(o, OBJECT_MAGIC);
CHECK_OBJ_NOTNULL(o->objhead, OBJHEAD_MAGIC);
assert(oc->flags & OC_F_ONLRU);
assert(oc->timer_idx != BINHEAP_NOIDX);
binheap_delete(exp_heap, oc->timer_idx);
assert(oc->timer_idx == BINHEAP_NOIDX);
lru = STV_lru(o->objstore);
AN(lru);
VTAILQ_REMOVE(lru, o->objcore, lru_list);
oc->flags &= ~OC_F_ONLRU;
{ /* Sanity checking */
struct objcore *oc2 = binheap_root(exp_heap);
if (oc2 != NULL) {
assert(oc2->timer_idx != BINHEAP_NOIDX);
assert(oc2->timer_when >= oc->timer_when);
}
}
VSL_stats->n_expired++;
Lck_Unlock(&exp_mtx);
WSL(sp->wrk, SLT_ExpKill, 0, "%u %d",
o->xid, (int)(o->ttl - t));
HSH_Deref(sp->wrk, &o);
}
}
static void
cnt_diag(struct sess *sp, const char *state)
{
if (sp->wrk != NULL) {
WSP(sp, SLT_Debug, "thr %p STP_%s sp %p obj %p vcl %p",
pthread_self(), state, sp, sp->wrk->obj, sp->vcl);
WSL_Flush(sp->wrk, 0);
} else {
VSL(SLT_Debug, sp->vsl_id,
"thr %p STP_%s sp %p obj %p vcl %p",
pthread_self(), state, sp, sp->wrk->obj, sp->vcl);
}
}
void
SES_ReleaseReq(struct sess *sp)
{
struct sesspool *pp;
CHECK_OBJ_NOTNULL(sp, SESS_MAGIC);
pp = sp->sesspool;
CHECK_OBJ_NOTNULL(pp, SESSPOOL_MAGIC);
AN(pp->pool);
CHECK_OBJ_NOTNULL(sp->req, REQ_MAGIC);
MPL_AssertSane(sp->req);
WSL_Flush(sp->req->vsl, 0);
MPL_Free(pp->mpl_req, sp->req);
sp->req = NULL;
}
enum pipe_status
PIE_Session(struct pipe *dp)
{
enum pipe_status status = PIPE_CONTINUE;
struct worker *w;
CHECK_OBJ_NOTNULL(dp, PIPE_MAGIC);
CAST_OBJ_NOTNULL(w, dp->wrk, WORKER_MAGIC);
for (;status == PIPE_CONTINUE;) {
assert(dp->wrk == w);
if (params->diag_bitmap & 0x00080000)
WSL(dp->wrk, SLT_PipeSM, dp->vc.vc_fd, "%s",
pie_stepstr[dp->step]);
#ifdef VARNISH_DEBUG
dp->stephist[dp->stephist_cur++] = dp->step;
if (dp->stephist_cur >= STEPHIST_MAX)
dp->stephist_cur = 0;
#endif
switch (dp->step) {
#define PIPESTEP(l,u) \
case PIE_##u: \
status = pie_##l(dp); \
break;
#include "pipesteps.h"
#undef PIPESTEP
default:
WRONG("Drainpipe state engine misfire");
}
assert(dp->wrk == w);
if (params->diag_bitmap & 0x00080000)
WSL(dp->wrk, SLT_PipeSM, dp->vc.vc_fd, "%s",
pie_statusstr[status]);
}
WSL_Flush(w, 0);
return (status);
}
static int
cnt_done(struct sess *sp)
{
double dh, dp, da;
int i;
CHECK_OBJ_NOTNULL(sp, SESS_MAGIC);
CHECK_OBJ_ORNULL(sp->vcl, VCL_CONF_MAGIC);
AZ(sp->obj);
AZ(sp->vbe);
sp->director = NULL;
sp->restarts = 0;
if (sp->vcl != NULL && sp->esis == 0) {
if (sp->wrk->vcl != NULL)
VCL_Rel(&sp->wrk->vcl);
sp->wrk->vcl = sp->vcl;
sp->vcl = NULL;
}
sp->t_end = TIM_real();
sp->wrk->lastused = sp->t_end;
if (sp->xid == 0) {
sp->t_req = sp->t_end;
sp->t_resp = sp->t_end;
}
dp = sp->t_resp - sp->t_req;
da = sp->t_end - sp->t_resp;
dh = sp->t_req - sp->t_open;
WSL(sp->wrk, SLT_ReqEnd, sp->id, "%u %.9f %.9f %.9f %.9f %.9f",
sp->xid, sp->t_req, sp->t_end, dh, dp, da);
sp->xid = 0;
sp->t_open = sp->t_end;
sp->t_resp = NAN;
WSL_Flush(sp->wrk, 0);
/* If we did an ESI include, don't mess up our state */
if (sp->esis > 0)
return (1);
sp->t_req = NAN;
if (sp->fd >= 0 && sp->doclose != NULL) {
/*
* This is an orderly close of the connection; ditch nolinger
* before we close, to get queued data transmitted.
*/
TCP_linger(sp->fd, 0);
vca_close_session(sp, sp->doclose);
}
if (sp->fd < 0) {
SES_Charge(sp);
VSL_stats->sess_closed++;
sp->wrk = NULL;
SES_Delete(sp);
return (1);
}
/* Reset the workspace to the session-watermark */
WS_Reset(sp->ws, sp->ws_ses);
i = HTC_Reinit(sp->htc);
if (i == 1) {
VSL_stats->sess_pipeline++;
sp->step = STP_START;
return (0);
}
if (Tlen(sp->htc->rxbuf)) {
VSL_stats->sess_readahead++;
sp->step = STP_WAIT;
return (0);
}
if (params->session_linger > 0) {
VSL_stats->sess_linger++;
sp->step = STP_WAIT;
return (0);
}
VSL_stats->sess_herd++;
SES_Charge(sp);
sp->wrk = NULL;
vca_return_session(sp);
return (1);
}
int
FetchHdr(struct sess *sp, int need_host_hdr)
{
struct vbc *vc;
struct worker *wrk;
struct http *hp;
int retry = -1;
int i;
struct http_conn *htc;
CHECK_OBJ_NOTNULL(sp, SESS_MAGIC);
CHECK_OBJ_NOTNULL(sp->wrk, WORKER_MAGIC);
wrk = sp->wrk;
CHECK_OBJ_NOTNULL(wrk->busyobj, BUSYOBJ_MAGIC);
htc = &wrk->busyobj->htc;
AN(sp->req->director);
AZ(sp->req->obj);
if (sp->req->objcore != NULL) { /* pass has no objcore */
CHECK_OBJ_NOTNULL(sp->req->objcore, OBJCORE_MAGIC);
AN(sp->req->objcore->flags & OC_F_BUSY);
}
hp = wrk->busyobj->bereq;
sp->wrk->busyobj->vbc = VDI_GetFd(NULL, sp);
if (sp->wrk->busyobj->vbc == NULL) {
WSP(sp, SLT_FetchError, "no backend connection");
return (-1);
}
vc = sp->wrk->busyobj->vbc;
if (vc->recycled)
retry = 1;
/*
* Now that we know our backend, we can set a default Host:
* header if one is necessary. This cannot be done in the VCL
* because the backend may be chosen by a director.
*/
if (need_host_hdr)
VDI_AddHostHeader(sp->wrk, vc);
(void)VTCP_blocking(vc->fd); /* XXX: we should timeout instead */
WRW_Reserve(wrk, &vc->fd);
(void)http_Write(wrk, vc->vsl_id, hp, 0); /* XXX: stats ? */
/* Deal with any message-body the request might have */
i = FetchReqBody(sp);
if (WRW_FlushRelease(wrk) || i > 0) {
WSP(sp, SLT_FetchError, "backend write error: %d (%s)",
errno, strerror(errno));
VDI_CloseFd(sp->wrk, &sp->wrk->busyobj->vbc);
/* XXX: other cleanup ? */
return (retry);
}
/* Checkpoint the vsl.here */
WSL_Flush(wrk, 0);
/* XXX is this the right place? */
VSC_C_main->backend_req++;
/* Receive response */
HTC_Init(htc, wrk->ws, vc->fd, vc->vsl_id,
cache_param->http_resp_size,
cache_param->http_resp_hdr_len);
VTCP_set_read_timeout(vc->fd, vc->first_byte_timeout);
i = HTC_Rx(htc);
if (i < 0) {
WSP(sp, SLT_FetchError, "http first read error: %d %d (%s)",
i, errno, strerror(errno));
VDI_CloseFd(sp->wrk, &sp->wrk->busyobj->vbc);
/* XXX: other cleanup ? */
/* Retryable if we never received anything */
return (i == -1 ? retry : -1);
}
VTCP_set_read_timeout(vc->fd, vc->between_bytes_timeout);
while (i == 0) {
i = HTC_Rx(htc);
if (i < 0) {
WSP(sp, SLT_FetchError,
"http first read error: %d %d (%s)",
i, errno, strerror(errno));
VDI_CloseFd(sp->wrk, &sp->wrk->busyobj->vbc);
/* XXX: other cleanup ? */
return (-1);
}
}
hp = wrk->busyobj->beresp;
if (http_DissectResponse(wrk, htc, hp)) {
WSP(sp, SLT_FetchError, "http format error");
VDI_CloseFd(sp->wrk, &sp->wrk->busyobj->vbc);
/* XXX: other cleanup ? */
return (-1);
}
return (0);
}
static int
cnt_done(struct sess *sp)
{
double dh, dp, da;
int i;
struct worker *wrk;
CHECK_OBJ_NOTNULL(sp, SESS_MAGIC);
wrk = sp->wrk;
CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
CHECK_OBJ_ORNULL(sp->vcl, VCL_CONF_MAGIC);
AZ(wrk->obj);
AZ(wrk->busyobj);
sp->director = NULL;
sp->restarts = 0;
wrk->busyobj = NULL;
SES_Charge(sp);
/* If we did an ESI include, don't mess up our state */
if (sp->esi_level > 0)
return (1);
if (sp->vcl != NULL) {
if (wrk->vcl != NULL)
VCL_Rel(&wrk->vcl);
wrk->vcl = sp->vcl;
sp->vcl = NULL;
}
sp->t_end = W_TIM_real(wrk);
WSP(sp, SLT_Debug, "PHK req %.9f resp %.9f end %.9f open %.9f",
sp->t_req, sp->t_resp, sp->t_end, sp->t_open);
if (sp->xid == 0) {
// sp->t_req = sp->t_end;
sp->t_resp = sp->t_end;
} else {
dp = sp->t_resp - sp->t_req;
da = sp->t_end - sp->t_resp;
dh = sp->t_req - sp->t_open;
/* XXX: Add StatReq == StatSess */
/* XXX: Workaround for pipe */
if (sp->fd >= 0) {
WSP(sp, SLT_Length, "%ju",
(uintmax_t)sp->req_bodybytes);
}
WSP(sp, SLT_ReqEnd, "%u %.9f %.9f %.9f %.9f %.9f",
sp->xid, sp->t_req, sp->t_end, dh, dp, da);
}
sp->xid = 0;
WSL_Flush(wrk, 0);
sp->t_open = sp->t_end;
sp->t_resp = NAN;
sp->req_bodybytes = 0;
sp->t_req = NAN;
sp->hash_always_miss = 0;
sp->hash_ignore_busy = 0;
if (sp->fd >= 0 && sp->doclose != NULL) {
/*
* This is an orderly close of the connection; ditch nolinger
* before we close, to get queued data transmitted.
*/
// XXX: not yet (void)VTCP_linger(sp->fd, 0);
SES_Close(sp, sp->doclose);
}
if (sp->fd < 0) {
wrk->stats.sess_closed++;
SES_Delete(sp, NULL);
return (1);
}
if (wrk->stats.client_req >= cache_param->wthread_stats_rate)
WRK_SumStat(wrk);
/* Reset the workspace to the session-watermark */
WS_Reset(sp->ws, sp->ws_ses);
WS_Reset(wrk->ws, NULL);
i = HTC_Reinit(sp->htc);
if (i == 1) {
wrk->stats.sess_pipeline++;
sp->step = STP_START;
return (0);
}
if (Tlen(sp->htc->rxbuf)) {
wrk->stats.sess_readahead++;
sp->step = STP_WAIT;
return (0);
}
if (cache_param->session_linger > 0) {
wrk->stats.sess_linger++;
sp->step = STP_WAIT;
return (0);
}
wrk->stats.sess_herd++;
Pool_Wait(sp);
return (1);
}
void
CNT_Session(struct sess *sp)
{
int done;
struct worker *wrk;
CHECK_OBJ_NOTNULL(sp, SESS_MAGIC);
wrk = sp->wrk;
CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
/*
* Possible entrance states
*/
assert(
sp->step == STP_FIRST ||
sp->step == STP_START ||
sp->step == STP_LOOKUP ||
sp->step == STP_RECV);
AZ(wrk->obj);
AZ(wrk->objcore);
/*
* Whenever we come in from the acceptor or waiter, we need to set
* blocking mode, but there is no point in setting it when we come from
* ESI or when a parked sessions returns.
* It would be simpler to do this in the acceptor or waiter, but we'd
* rather do the syscall in the worker thread.
* On systems which return errors for ioctl, we close early
*/
if ((sp->step == STP_FIRST || sp->step == STP_START) &&
VTCP_blocking(sp->fd)) {
if (errno == ECONNRESET)
SES_Close(sp, "remote closed");
else
SES_Close(sp, "error");
sp->step = STP_DONE;
}
/*
* NB: Once done is set, we can no longer touch sp!
*/
for (done = 0; !done; ) {
assert(sp->wrk == wrk);
/*
* This is a good place to be paranoid about the various
* pointers still pointing to the things we expect.
*/
CHECK_OBJ_NOTNULL(sp, SESS_MAGIC);
CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
CHECK_OBJ_ORNULL(wrk->obj, OBJECT_MAGIC);
CHECK_OBJ_ORNULL(wrk->nobjhead, OBJHEAD_MAGIC);
WS_Assert(wrk->ws);
switch (sp->step) {
#define STEP(l,u) \
case STP_##u: \
if (cache_param->diag_bitmap & 0x01) \
cnt_diag(sp, #u); \
done = cnt_##l(sp); \
break;
#include "tbl/steps.h"
#undef STEP
default:
WRONG("State engine misfire");
}
WS_Assert(wrk->ws);
CHECK_OBJ_ORNULL(wrk->nobjhead, OBJHEAD_MAGIC);
}
WSL_Flush(wrk, 0);
AZ(wrk->obj);
AZ(wrk->objcore);
#define ACCT(foo) AZ(wrk->acct_tmp.foo);
#include "tbl/acct_fields.h"
#undef ACCT
assert(WRW_IsReleased(wrk));
}