Ejemplo n.º 1
0
//lint -e{818}
void
vtc_log(struct vtclog *vl, int lvl, const char *fmt, ...)
{
	double tx;

	CHECK_OBJ_NOTNULL(vl, VTCLOG_MAGIC);
	tx = VTIM_mono() - t0;
	AZ(pthread_mutex_lock(&vl->mtx));
	vl->act = 1;
	assert(lvl < (int)NLEAD);
	VSB_clear(vl->vsb);
	VSB_printf(vl->vsb, "%s %-4s %4.1f ",
	    lead[lvl < 0 ? 1: lvl], vl->id, tx);
	va_list ap;
	va_start(ap, fmt);
	(void)VSB_vprintf(vl->vsb, fmt, ap);
	va_end(ap);
	VSB_putc(vl->vsb, '\n');
	AZ(VSB_finish(vl->vsb));

	vtc_log_emit(vl, lvl);

	VSB_clear(vl->vsb);
	vl->act = 0;
	AZ(pthread_mutex_unlock(&vl->mtx));
	if (lvl > 0)
		return;
	if (lvl == 0)
		vtc_error = 1;
	if (pthread_self() != vtc_thread)
		pthread_exit(NULL);
}
Ejemplo n.º 2
0
void
vtc_loginit(char *buf, unsigned buflen)
{

	t0 = VTIM_mono();
	vtclog_buf = buf;
	vtclog_left = buflen;
	AZ(pthread_mutex_init(&vtclog_mtx, NULL));
	AZ(pthread_key_create(&log_key, NULL));
}
Ejemplo n.º 3
0
//lint -e{818}
void
vtc_hexdump(struct vtclog *vl, int lvl, const char *pfx,
    const unsigned char *str, int len)
{
	int nl = 1;
	unsigned l;
	double tx;

	CHECK_OBJ_NOTNULL(vl, VTCLOG_MAGIC);
	tx = VTIM_mono() - t0;
	assert(len >= 0);
	assert(lvl >= 0);
	assert(lvl < NLEAD);
	AZ(pthread_mutex_lock(&vl->mtx));
	vl->act = 1;
	VSB_clear(vl->vsb);
	if (pfx == NULL)
		pfx = "";
	if (str == NULL)
		VSB_printf(vl->vsb, "%s %-4s %4.1f %s| (null)",
		    lead[lvl], vl->id, tx, pfx);
	else {
		for (l = 0; l < len; l++, str++) {
			if (l > 512) {
				VSB_printf(vl->vsb, "...");
				break;
			}
			if (nl) {
				VSB_printf(vl->vsb, "%s %-4s %4.1f %s| ",
				    lead[lvl], vl->id, tx, pfx);
				nl = 0;
			}
			VSB_printf(vl->vsb, " %02x", *str);
			if ((l & 0xf) == 0xf) {
				VSB_printf(vl->vsb, "\n");
				nl = 1;
			}
		}
	}
	if (!nl)
		VSB_printf(vl->vsb, "\n");
	AZ(VSB_finish(vl->vsb));

	vtc_log_emit(vl, lvl);

	VSB_clear(vl->vsb);
	vl->act = 0;
	AZ(pthread_mutex_unlock(&vl->mtx));
	if (lvl == 0) {
		vtc_error = 1;
		if (pthread_self() != vtc_thread)
			pthread_exit(NULL);
	}
}
Ejemplo n.º 4
0
static void
tst_delta()
{
	double m_begin, m_end;
	double r_begin, r_end;
	const double ref = 1;
	int err = 0;

	r_begin = VTIM_real();
	m_begin = VTIM_mono();
	VTIM_sleep(ref);
	r_end = VTIM_real();
	m_end = VTIM_mono();

	err += tst_delta_check("VTIM_mono", m_begin, m_end, ref);
	err += tst_delta_check("VTIM_real", r_begin, r_end, ref);

	if (err) {
		printf("%d time delta test errrors\n", err);
		exit(4);
	}
}
Ejemplo n.º 5
0
static void
bench()
{
	double s, e, t;
	int i;

	t = 0;
	s = VTIM_real();
	for (i=0; i<100000; i++)
		t += VTIM_real();
	e = VTIM_real();
	printf("real: %fs / %d = %fns - tst val %f\n",
	    e - s, i, 1e9 * (e - s) / i, t);

	t = 0;
	s = VTIM_real();
	for (i=0; i<100000; i++)
		t += VTIM_mono();
	e = VTIM_real();
	printf("mono: %fs / %d = %fns - tst val %f\n",
	    e - s, i, 1e9 * (e - s) / i, t);
}
Ejemplo n.º 6
0
int
main(int argc, char **argv)
{
	int i;
	const char *colon, *ptag;
	const char *profile = "responsetime";
	pthread_t thr;
	int fnum = -1;
	struct profile cli_p = {0};
	cli_p.name = 0;

	VUT_Init(progname, argc, argv, &vopt_spec);
	AZ(pthread_cond_init(&timebend_cv, NULL));

	while ((i = getopt(argc, argv, vopt_spec.vopt_optstring)) != -1) {
		switch (i) {
		case 'h':
			/* Usage help */
			usage(0);
		case 'p':
			delay = strtod(optarg, NULL);
			if (delay <= 0)
				VUT_Error(1, "-p: invalid '%s'", optarg);
			break;
		case 'P':
			colon = strchr(optarg, ':');
			/* no colon, take the profile as a name */
			if (colon == NULL) {
				profile = optarg;
				break;
			}
			/* else it's a definition, we hope */
			if (colon == optarg + 1 &&
			    (*optarg == 'b' || *optarg == 'c')) {
				cli_p.VSL_arg = *optarg;
				ptag = colon + 1;
				colon = strchr(colon + 1, ':');
				if (colon == NULL)
					profile_error(optarg);
			} else {
				ptag = optarg;
				cli_p.VSL_arg = 'c';
			}

			assert(colon);
			if (sscanf(colon + 1, "%d:%d:%d", &cli_p.field,
			    &cli_p.hist_low, &cli_p.hist_high) != 3)
				profile_error(optarg);

			match_tag = VSL_Name2Tag(ptag, colon - ptag);
			if (match_tag < 0)
				VUT_Error(1,
				    "-P: '%s' is not a valid tag name",
				    optarg);
			cli_p.name = "custom";
			cli_p.tag = match_tag;
			profile = NULL;
			active_profile = &cli_p;

			break;
		case 'B':
			timebend = strtod(optarg, NULL);
			if (timebend == 0)
				VUT_Error(1,
				    "-B: being able to bend time does not"
				    " mean we can stop it"
				    " (invalid factor '%s')", optarg);
			if (timebend < 0)
				VUT_Error(1,
				    "-B: being able to bend time does not"
				    " mean we can make it go backwards"
				    " (invalid factor '%s')", optarg);
			break;
		default:
			if (!VUT_Arg(i, optarg))
				usage(1);
		}
	}

	if (optind != argc)
		usage(1);

	/* Check for valid grouping mode */
	assert(VUT.g_arg < VSL_g__MAX);
	if (VUT.g_arg != VSL_g_vxid && VUT.g_arg != VSL_g_request)
		VUT_Error(1, "Invalid grouping mode: %s"
		    " (only vxid and request are supported)",
		    VSLQ_grouping[VUT.g_arg]);

	if (profile) {
		for (active_profile = profiles; active_profile->name;
		     active_profile++) {
			if (strcmp(active_profile->name, profile) == 0)
				break;
		}
	}
	AN(active_profile);
	if (!active_profile->name)
		VUT_Error(1, "-P: No such profile '%s'", profile);

	assert(VUT_Arg(active_profile->VSL_arg, NULL));
	match_tag = active_profile->tag;
	fnum = active_profile->field;
	hist_low = active_profile->hist_low;
	hist_high = active_profile->hist_high;

	hist_range = hist_high - hist_low;
	hist_buckets = hist_range * HIST_RES;
	bucket_hit = calloc(sizeof *bucket_hit, hist_buckets);
	bucket_miss = calloc(sizeof *bucket_miss, hist_buckets);

	if (timebend > 0)
		t0 = VTIM_mono();

	format = malloc(4L * fnum);
	AN(format);
	for (i = 0; i < fnum - 1; i++)
		strcpy(format + 4 * i, "%*s ");
	strcpy(format + 4 * (fnum - 1), "%lf");

	log_ten = log(10.0);

	VUT_Setup();
	if (pthread_create(&thr, NULL, do_curses, NULL) != 0)
		VUT_Error(1, "pthread_create(): %s", strerror(errno));
	VUT.dispatch_f = accumulate;
	VUT.dispatch_priv = NULL;
	VUT.sighup_f = sighup;
	VUT_Main();
	end_of_file = 1;
	AZ(pthread_join(thr, NULL));
	VUT_Fini();
	exit(0);
}
Ejemplo n.º 7
0
static void *
do_curses(void *arg)
{
	int ch;
	(void)arg;

	initscr();
	raw();
	noecho();
	nonl();
	intrflush(stdscr, FALSE);
	curs_set(0);
	erase();
	while (!quit) {
		AZ(pthread_mutex_lock(&mtx));
		update();
		AZ(pthread_mutex_unlock(&mtx));

		timeout(delay * 1000);
		switch ((ch = getch())) {
		case ERR:
			break;
#ifdef KEY_RESIZE
		case KEY_RESIZE:
			erase();
			break;
#endif
		case '\014':	/* Ctrl-L */
		case '\024':	/* Ctrl-T */
			redrawwin(stdscr);
			refresh();
			break;
		case '\032':	/* Ctrl-Z */
			endwin();
			raise(SIGTSTP);
			break;
		case '\003':	/* Ctrl-C */
		case '\021':	/* Ctrl-Q */
		case 'Q':
		case 'q':
			raise(SIGINT);
			endwin();
			return (NULL);
		case '0':
		case '1':
		case '2':
		case '3':
		case '4':
		case '5':
		case '6':
		case '7':
		case '8':
		case '9':
			delay = 1 << (ch - '0');
			break;
		case '+':
			delay /= 2;
			if (delay < 1e-3)
				delay = 1e-3;
			break;
		case '-':
			delay *= 2;
			break;
		case '>':
		case '<':
			/* see below */
			break;
		default:
			beep();
			break;
		}

		if (ch == '<' || ch == '>') {
			AZ(pthread_mutex_lock(&mtx));
			vsl_to = vsl_t0 = vsl_ts;
			t0 = VTIM_mono();
			if (timebend == 0)
				timebend = 1;
			else if (ch == '<')
				timebend /= 2;
			else
				timebend *= 2;
			AZ(pthread_cond_broadcast(&timebend_cv));
			AZ(pthread_mutex_unlock(&mtx));
		}
	}
	endwin();
	return (NULL);
}
Ejemplo n.º 8
0
static int /*__match_proto__ (VSLQ_dispatch_f)*/
accumulate(struct VSL_data *vsl, struct VSL_transaction * const pt[],
    void *priv)
{
	int i, tag, skip, match, hit;
	unsigned u;
	double value = 0;
	struct VSL_transaction *tr;
	double t;
	const char *tsp;

	(void)vsl;
	(void)priv;

	for (tr = pt[0]; tr != NULL; tr = *++pt) {
		if (tr->reason == VSL_r_esi)
			/* Skip ESI requests */
			continue;

		hit = 0;
		skip = 0;
		match = 0;
		tsp = NULL;
		while (skip == 0) {
			i = VSL_Next(tr->c);
			if (i == -3) {
				/* overrun - need to skip forward */
				AZ(pthread_mutex_lock(&mtx));
				vsl_to = vsl_t0 = vsl_ts = 0;
				t0 = VTIM_mono();
				AZ(pthread_mutex_unlock(&mtx));
				break;
			}
			if (i != 1)
				break;

			/* get the value we want and register if it's a hit */
			tag = VSL_TAG(tr->c->rec.ptr);

			switch (tag) {
			case SLT_Hit:
				hit = 1;
				break;
			case SLT_VCL_return:
				if (!strcasecmp(VSL_CDATA(tr->c->rec.ptr),
				    "restart") ||
				    !strcasecmp(VSL_CDATA(tr->c->rec.ptr),
				    "retry"))
					skip = 1;
				break;
			case SLT_Timestamp:
				tsp = VSL_CDATA(tr->c->rec.ptr);
				/* FALLTHROUGH */
			default:
				if (tag != match_tag)
					break;

				if (active_profile->prefix &&
				    strncmp(VSL_CDATA(tr->c->rec.ptr),
				    active_profile->prefix,
				    strlen(active_profile->prefix)) != 0)
					break;

				i = sscanf(VSL_CDATA(tr->c->rec.ptr),
				    format, &value);
				if (i != 1)
					break;
				match = 1;
				break;
			}
		}

		if (skip || !match)
			continue;

		/* select bucket */
		i = HIST_RES * (log(value) / log_ten);
		if (i < hist_low * HIST_RES)
			i = hist_low * HIST_RES;
		if (i >= hist_high * HIST_RES)
			i = hist_high * HIST_RES - 1;
		i -= hist_low * HIST_RES;
		assert(i >= 0);
		assert(i < hist_buckets);

		AZ(pthread_mutex_lock(&mtx));

		/*
		 * only parse the last tsp seen in this transaction -
		 * it should be the latest.
		 */
		if (tsp)
			upd_vsl_ts(tsp);

		/* phase out old data */
		if (nhist == HIST_N) {
			u = rr_hist[next_hist];
			if (u >= hist_buckets) {
				u -= hist_buckets;
				assert(u < hist_buckets);
				assert(bucket_hit[u] > 0);
				bucket_hit[u]--;
			} else {
				assert(bucket_miss[u] > 0);
				bucket_miss[u]--;
			}
		} else {
			++nhist;
		}

		/* phase in new data */
		if (hit) {
			bucket_hit[i]++;
			rr_hist[next_hist] = i + hist_buckets;
		} else {
			bucket_miss[i]++;
			rr_hist[next_hist] = i;
		}
		if (++next_hist == HIST_N) {
			next_hist = 0;
		}
		AZ(pthread_mutex_unlock(&mtx));
	}

	if (vsl_ts < vsl_to)
		return (0);

	t = VTIM_mono();

	AZ(pthread_mutex_lock(&mtx));
	if (vsl_t0 == 0)
		vsl_to = vsl_t0 = vsl_ts;

	assert(t > t0);
	vsl_to = vsl_t0 + (t - t0) * timebend;

	if (vsl_ts > vsl_to) {
		double when = VTIM_real() + vsl_ts - vsl_to;
		struct timespec ts;
		ts.tv_nsec = (long)(modf(when, &t) * 1e9);
		ts.tv_sec = (long)t;
		i = pthread_cond_timedwait(&timebend_cv, &mtx, &ts);
		assert(i == 0 || i == ETIMEDOUT);
	}
	AZ(pthread_mutex_unlock(&mtx));

	return (0);
}
Ejemplo n.º 9
0
static enum fetch_step
vbf_stp_fetch(struct worker *wrk, struct busyobj *bo)
{
	struct http *hp, *hp2;
	char *b;
	uint16_t nhttp;
	unsigned l;
	struct vsb *vary = NULL;
	int varyl = 0;
	struct object *obj;
	ssize_t est = -1;

	CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
	CHECK_OBJ_NOTNULL(bo, BUSYOBJ_MAGIC);

	assert(wrk->handling == VCL_RET_DELIVER);

	/*
	 * The VCL variables beresp.do_g[un]zip tells us how we want the
	 * object processed before it is stored.
	 *
	 * The backend Content-Encoding header tells us what we are going
	 * to receive, which we classify in the following three classes:
	 *
	 *	"Content-Encoding: gzip"	--> object is gzip'ed.
	 *	no Content-Encoding		--> object is not gzip'ed.
	 *	anything else			--> do nothing wrt gzip
	 *
	 * XXX: BS_NONE/cl==0 should avoid gzip/gunzip
	 */

	/* We do nothing unless the param is set */
	if (!cache_param->http_gzip_support)
		bo->do_gzip = bo->do_gunzip = 0;

	bo->is_gzip = http_HdrIs(bo->beresp, H_Content_Encoding, "gzip");

	bo->is_gunzip = !http_GetHdr(bo->beresp, H_Content_Encoding, NULL);

	/* It can't be both */
	assert(bo->is_gzip == 0 || bo->is_gunzip == 0);

	/* We won't gunzip unless it is gzip'ed */
	if (bo->do_gunzip && !bo->is_gzip)
		bo->do_gunzip = 0;

	/* If we do gunzip, remove the C-E header */
	if (bo->do_gunzip)
		http_Unset(bo->beresp, H_Content_Encoding);

	/* We wont gzip unless it is ungziped */
	if (bo->do_gzip && !bo->is_gunzip)
		bo->do_gzip = 0;

	/* If we do gzip, add the C-E header */
	if (bo->do_gzip)
		http_SetHeader(bo->beresp, "Content-Encoding: gzip");

	/* But we can't do both at the same time */
	assert(bo->do_gzip == 0 || bo->do_gunzip == 0);

	if (bo->vbc != NULL)
		est = V1F_Setup_Fetch(bo);

	if (bo->do_gunzip || (bo->is_gzip && bo->do_esi)) {
		RFC2616_Weaken_Etag(bo->beresp);
		VFP_Push(bo, vfp_gunzip_pull, 0);
	}

	if (bo->do_esi && bo->do_gzip) {
		VFP_Push(bo, vfp_esi_gzip_pull, 0);
		RFC2616_Weaken_Etag(bo->beresp);
	} else if (bo->do_esi && bo->is_gzip && !bo->do_gunzip) {
		VFP_Push(bo, vfp_esi_gzip_pull, 0);
		RFC2616_Weaken_Etag(bo->beresp);
	} else if (bo->do_esi) {
		VFP_Push(bo, vfp_esi_pull, 0);
	} else if (bo->do_gzip) {
		VFP_Push(bo, vfp_gzip_pull, 0);
		RFC2616_Weaken_Etag(bo->beresp);
	} else if (bo->is_gzip && !bo->do_gunzip) {
		VFP_Push(bo, vfp_testgunzip_pull, 0);
	}

	if (bo->fetch_objcore->flags & OC_F_PRIVATE)
		AN(bo->uncacheable);

	/* No reason to try streaming a non-existing body */
	if (bo->htc.body_status == BS_NONE)
		bo->do_stream = 0;

	l = 0;

	/* Create Vary instructions */
	if (!(bo->fetch_objcore->flags & OC_F_PRIVATE)) {
		varyl = VRY_Create(bo, &vary);
		if (varyl > 0) {
			AN(vary);
			assert(varyl == VSB_len(vary));
			l += varyl;
		} else if (varyl < 0) {
			/*
			 * Vary parse error
			 * Complain about it, and make this a pass.
			 */
			VSLb(bo->vsl, SLT_Error,
			    "Illegal 'Vary' header from backend, "
			    "making this a pass.");
			bo->uncacheable = 1;
			AZ(vary);
		} else
			/* No vary */
			AZ(vary);
	}

	l += http_EstimateWS(bo->beresp,
	    bo->uncacheable ? HTTPH_R_PASS : HTTPH_A_INS, &nhttp);

	if (bo->uncacheable)
		bo->fetch_objcore->flags |= OC_F_PASS;

	if (bo->uncacheable ||
	    bo->exp.ttl+bo->exp.grace+bo->exp.keep < cache_param->shortlived)
		bo->storage_hint = TRANSIENT_STORAGE;

	AZ(bo->stats);
	bo->stats = &wrk->stats;
	AN(bo->fetch_objcore);
	obj = STV_NewObject(bo, bo->storage_hint, l, nhttp);
	if (obj == NULL) {
		/*
		 * Try to salvage the transaction by allocating a
		 * shortlived object on Transient storage.
		 */
		if (bo->exp.ttl > cache_param->shortlived)
			bo->exp.ttl = cache_param->shortlived;
		bo->exp.grace = 0.0;
		bo->exp.keep = 0.0;
		obj = STV_NewObject(bo, TRANSIENT_STORAGE, l, nhttp);
	}
	if (obj == NULL) {
		bo->stats = NULL;
		(void)VFP_Error(bo, "Could not get storage");
		VDI_CloseFd(&bo->vbc);
		return (F_STP_DONE);
	}
	CHECK_OBJ_NOTNULL(obj, OBJECT_MAGIC);

	bo->storage_hint = NULL;

	AZ(bo->fetch_obj);
	bo->fetch_obj = obj;

	if (bo->do_gzip || (bo->is_gzip && !bo->do_gunzip))
		obj->gziped = 1;

	if (vary != NULL) {
		obj->vary = (void *)WS_Copy(obj->http->ws,
		    VSB_data(vary), varyl);
		AN(obj->vary);
		(void)VRY_Validate(obj->vary);
		VSB_delete(vary);
	}

	obj->vxid = bo->vsl->wid;
	obj->response = bo->err_code;
	WS_Assert(bo->ws_o);

	/* Filter into object */
	hp = bo->beresp;
	hp2 = obj->http;

	hp2->logtag = HTTP_Obj;
	http_FilterResp(hp, hp2, bo->uncacheable ? HTTPH_R_PASS : HTTPH_A_INS);
	http_CopyHome(hp2);

	if (http_GetHdr(hp, H_Last_Modified, &b))
		obj->last_modified = VTIM_parse(b);
	else
		obj->last_modified = floor(bo->exp.t_origin);

	assert(WRW_IsReleased(wrk));

	/*
	 * Ready to fetch the body
	 */

	assert(bo->refcount >= 1);

	AZ(WS_Overflowed(bo->ws_o));
	if (bo->do_stream)
		HSH_Unbusy(&wrk->stats, obj->objcore);

	assert(bo->state == BOS_REQ_DONE);
	VBO_setstate(bo, BOS_FETCHING);

	switch (bo->htc.body_status) {
	case BS_NONE:
		break;
	case BS_ERROR:
		/* XXX: Why not earlier ? */
		bo->should_close |=
		    VFP_Error(bo, "error incompatible Transfer-Encoding");
		break;
	default:
		if (bo->vbc == NULL)
			(void)VFP_Error(bo, "Backend connection gone");
		else
			VFP_Fetch_Body(bo, est);
	}

	bo->stats = NULL;

	bo->t_body = VTIM_mono();

	if (bo->vbc != NULL) {
		if (bo->should_close)
			VDI_CloseFd(&bo->vbc);
		else
			VDI_RecycleFd(&bo->vbc);
		AZ(bo->vbc);
	}

	http_Teardown(bo->bereq);
	http_Teardown(bo->beresp);

	VSLb(bo->vsl, SLT_Fetch_Body, "%u(%s)",
	    bo->htc.body_status, body_status_2str(bo->htc.body_status));

	if (bo->state == BOS_FAILED) {
		wrk->stats.fetch_failed++;
	} else {
		assert(bo->state == BOS_FETCHING);

		VSLb(bo->vsl, SLT_Length, "%zd", obj->len);

		{
		/* Sanity check fetch methods accounting */
			ssize_t uu;
			struct storage *st;

			uu = 0;
			VTAILQ_FOREACH(st, &obj->store, list)
				uu += st->len;
			if (bo->do_stream)
				/* Streaming might have started freeing stuff */
				assert(uu <= obj->len);

			else
				assert(uu == obj->len);
		}
	}

	if (!bo->do_stream && bo->state != BOS_FAILED)
		HSH_Unbusy(&wrk->stats, obj->objcore);

	if (bo->state != BOS_FAILED && !(obj->objcore->flags & OC_F_PRIVATE)) {
		EXP_Insert(obj->objcore);
		AN(obj->objcore->ban);
	}

	HSH_Complete(obj->objcore);

	assert(bo->refcount >= 1);

	if (bo->state != BOS_FAILED)
		VBO_setstate(bo, BOS_FINISHED);

VSLb(bo->vsl, SLT_Debug, "YYY REF %d %d", bo->refcount, bo->fetch_obj->objcore->refcnt);
	return (F_STP_DONE);
}
Ejemplo n.º 10
0
//lint -e{818}
void
vtc_dump(struct vtclog *vl, int lvl, const char *pfx, const char *str, int len)
{
	int nl = 1, olen;
	unsigned l;
	double tx;

	CHECK_OBJ_NOTNULL(vl, VTCLOG_MAGIC);
	tx = VTIM_mono() - t0;
	assert(lvl >= 0);
	assert(lvl < NLEAD);
	AZ(pthread_mutex_lock(&vl->mtx));
	vl->act = 1;
	VSB_clear(vl->vsb);
	if (pfx == NULL)
		pfx = "";
	if (str == NULL)
		VSB_printf(vl->vsb, "%s %-4s %4.1f %s(null)\n",
		    lead[lvl], vl->id, tx, pfx);
	else {
		olen = len;
		if (len < 0)
			len = strlen(str);
		for (l = 0; l < len; l++, str++) {
			if (l > 1024 && olen != -2) {
				VSB_printf(vl->vsb, "...");
				break;
			}
			if (nl) {
				VSB_printf(vl->vsb, "%s %-4s %4.1f %s| ",
				    lead[lvl], vl->id, tx, pfx);
				nl = 0;
			}
			if (*str == '\r')
				VSB_printf(vl->vsb, "\\r");
			else if (*str == '\t')
				VSB_printf(vl->vsb, "\\t");
			else if (*str == '\n') {
				VSB_printf(vl->vsb, "\\n\n");
				nl = 1;
			} else if (*str < 0x20 || *str > 0x7e)
				VSB_printf(vl->vsb, "\\x%02x", (*str) & 0xff);
			else
				VSB_printf(vl->vsb, "%c", *str);
		}
	}
	if (!nl)
		VSB_printf(vl->vsb, "\n");
	AZ(VSB_finish(vl->vsb));

	vtc_log_emit(vl, lvl);

	VSB_clear(vl->vsb);
	vl->act = 0;
	AZ(pthread_mutex_unlock(&vl->mtx));
	if (lvl == 0) {
		vtc_error = 1;
		if (pthread_self() != vtc_thread)
			pthread_exit(NULL);
	}
}
Ejemplo n.º 11
0
void
V1F_fetch_body(struct worker *wrk, struct busyobj *bo)
{
	int cls;
	struct storage *st;
	ssize_t cl;
	struct http_conn *htc;
	struct object *obj;

	CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
	CHECK_OBJ_NOTNULL(bo, BUSYOBJ_MAGIC);
	htc = &bo->htc;
	CHECK_OBJ_ORNULL(bo->vbc, VBC_MAGIC);
	obj = bo->fetch_obj;
	CHECK_OBJ_NOTNULL(obj, OBJECT_MAGIC);
	CHECK_OBJ_NOTNULL(obj->http, HTTP_MAGIC);

	assert(bo->state == BOS_FETCHING);

	/*
	 * XXX: The busyobj needs a dstat, but it is not obvious which one
	 * XXX: it should be (own/borrowed).  For now borrow the wrk's.
	 */
	AZ(bo->stats);
	bo->stats = &wrk->stats;

	AN(bo->vfp);
	AZ(bo->vgz_rx);
	assert(VTAILQ_EMPTY(&obj->store));

	/* XXX: pick up estimate from objdr ? */
	cl = 0;
	cls = bo->should_close;
	switch (htc->body_status) {
	case BS_NONE:
		break;
	case BS_ZERO:
		break;
	case BS_LENGTH:
		cl = vbf_fetch_number(bo->h_content_length, 10);

		bo->vfp->begin(bo, cl);
		if (bo->state == BOS_FETCHING && cl > 0)
			cls |= vbf_fetch_straight(bo, htc, cl);
		if (bo->vfp->end(bo))
			assert(bo->state == BOS_FAILED);
		break;
	case BS_CHUNKED:
		bo->vfp->begin(bo, cl > 0 ? cl : 0);
		if (bo->state == BOS_FETCHING)
			cls |= vbf_fetch_chunked(bo, htc);
		if (bo->vfp->end(bo))
			assert(bo->state == BOS_FAILED);
		break;
	case BS_EOF:
		bo->vfp->begin(bo, cl > 0 ? cl : 0);
		if (bo->state == BOS_FETCHING)
			vbf_fetch_eof(bo, htc);
		cls = 1;
		if (bo->vfp->end(bo))
			assert(bo->state == BOS_FAILED);
		break;
	case BS_ERROR:
		cls |= VFP_Error(bo, "error incompatible Transfer-Encoding");
		break;
	default:
		INCOMPL();
	}
	bo->t_body = VTIM_mono();
	AZ(bo->vgz_rx);

	/*
	 * Trim or delete the last segment, if any
	 */

	st = VTAILQ_LAST(&bo->fetch_obj->store, storagehead);
	/* XXX: Temporary:  Only trim if we are not streaming */
	if (st != NULL && !bo->do_stream) {
		/* XXX: is any of this safe under streaming ? */
		if (st->len == 0) {
			VTAILQ_REMOVE(&bo->fetch_obj->store, st, list);
			STV_free(st);
		} else if (st->len < st->space) {
			STV_trim(st, st->len, 1);
		}
	}

	bo->vfp = NULL;

	VSLb(bo->vsl, SLT_Fetch_Body, "%u(%s) cls %d",
	    htc->body_status, body_status_2str(htc->body_status), cls);

	http_Teardown(bo->bereq);
	http_Teardown(bo->beresp);

	if (bo->vbc != NULL) {
		if (cls)
			VDI_CloseFd(&bo->vbc);
		else
			VDI_RecycleFd(&bo->vbc);
	}
	AZ(bo->vbc);

	if (bo->state == BOS_FAILED) {
		wrk->stats.fetch_failed++;
	} else {
		assert(bo->state == BOS_FETCHING);

		VSLb(bo->vsl, SLT_Length, "%zd", obj->len);

		{
		/* Sanity check fetch methods accounting */
			ssize_t uu;

			uu = 0;
			VTAILQ_FOREACH(st, &obj->store, list)
				uu += st->len;
			if (bo->do_stream)
				/* Streaming might have started freeing stuff */
				assert(uu <= obj->len);

			else
				assert(uu == obj->len);
		}
	}
	bo->stats = NULL;
}
Ejemplo n.º 12
0
int
V1F_fetch_hdr(struct worker *wrk, struct busyobj *bo, struct req *req)
{
	struct vbc *vc;
	struct http *hp;
	enum htc_status_e hs;
	int retry = -1;
	int i, first;
	struct http_conn *htc;

	CHECK_OBJ_NOTNULL(wrk, WORKER_MAGIC);
	CHECK_OBJ_ORNULL(req, REQ_MAGIC);
	CHECK_OBJ_NOTNULL(bo, BUSYOBJ_MAGIC);
	htc = &bo->htc;

	AN(bo->director);

	hp = bo->bereq;

	bo->vbc = VDI_GetFd(NULL, bo);
	if (bo->vbc == NULL) {
		VSLb(bo->vsl, SLT_FetchError, "no backend connection");
		return (-1);
	}
	vc = bo->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 (!http_GetHdr(bo->bereq, H_Host, NULL))
		VDI_AddHostHeader(bo->bereq, vc);

	(void)VTCP_blocking(vc->fd);	/* XXX: we should timeout instead */
	WRW_Reserve(wrk, &vc->fd, bo->vsl, bo->t_fetch);
	bo->t_send = VTIM_mono();
	(void)HTTP1_Write(wrk, hp, 0);	/* XXX: stats ? */

	/* Deal with any message-body the request might (still) have */
	i = 0;

	if (req != NULL) {
		i = HTTP1_IterateReqBody(req, vbf_iter_req_body, wrk);
		if (req->req_body_status == REQ_BODY_DONE)
			retry = -1;
		if (req->req_body_status == REQ_BODY_FAIL) {
			VSLb(bo->vsl, SLT_FetchError,
			    "req.body read error: %d (%s)",
			    errno, strerror(errno));
			req->doclose = SC_RX_BODY;
			retry = -1;
		}
	}

	if (WRW_FlushRelease(wrk) || i != 0) {
		VSLb(bo->vsl, SLT_FetchError, "backend write error: %d (%s)",
		    errno, strerror(errno));
		VDI_CloseFd(&bo->vbc);
		/* XXX: other cleanup ? */
		return (retry);
	}

	VSC_C_main->backend_req++;
	bo->t_sent = VTIM_mono();

	/* Receive response */

	HTTP1_Init(htc, bo->ws, vc->fd, vc->vsl,
	    cache_param->http_resp_size,
	    cache_param->http_resp_hdr_len);

	VTCP_set_read_timeout(vc->fd, vc->first_byte_timeout);

	first = 1;
	do {
		hs = HTTP1_Rx(htc);
		if (hs == HTTP1_OVERFLOW) {
			VSLb(bo->vsl, SLT_FetchError,
			    "http %sread error: overflow",
			    first ? "first " : "");
			VDI_CloseFd(&bo->vbc);
			/* XXX: other cleanup ? */
			return (-1);
		}
		if (hs == HTTP1_ERROR_EOF) {
			VSLb(bo->vsl, SLT_FetchError, "http %sread error: EOF",
			    first ? "first " : "");
			VDI_CloseFd(&bo->vbc);
			/* XXX: other cleanup ? */
			return (retry);
		}
		if (first) {
			retry = -1;
			first = 0;
			VTCP_set_read_timeout(vc->fd,
			    vc->between_bytes_timeout);
		}
	} while (hs != HTTP1_COMPLETE);
	bo->t_hdr = VTIM_mono();

	hp = bo->beresp;

	if (HTTP1_DissectResponse(hp, htc)) {
		VSLb(bo->vsl, SLT_FetchError, "http format error");
		VDI_CloseFd(&bo->vbc);
		/* XXX: other cleanup ? */
		return (-1);
	}
	return (0);
}