fellow_cache: Add panic formatter

CHANGES.rst

@@ -18,6 +18,10 @@ Version 1.0.0-rc3 (NEXT RELEASE)
 fellow
 ======
 
+* Fellow-specific panic output has been added, which is relatively
+  terse by default. The ``panic_flags`` tunable has been added to
+  increase verbosity where needed.
+
 * The ``.happy`` VCL variable of a fellow storage now returns ``true``
   only when it is open (has completed loading).
 

src/fellow_cache.c

@@ -6190,6 +6190,243 @@ fellow_cache_obj_delete(struct fellow_cache *fc,
 	buddy_return(rets);
 }
 
+#ifndef TEST_DRIVER
+
+#define FCPF_SEG 0x01
+#define FCPF_SEGLIST 0x02
+
+// uint16_t magic, otherwise copied from varnish-cache
+static int
+fc_dump_u16_struct(struct vsb *vsb, const void *ptr, uint16_t magic,
+    const char *fmt, ...)
+{
+	va_list ap;
+	const uint16_t *uptr;
+
+	AN(vsb);
+	va_start(ap, fmt);
+	VSB_vprintf(vsb, fmt, ap);
+	va_end(ap);
+	if (ptr == NULL) {
+		VSB_cat(vsb, " = NULL\n");
+		return (-1);
+	}
+	VSB_printf(vsb, " = %p {", ptr);
+	VSB_putc(vsb, '\n');
+	uptr = ptr;
+	if (*uptr != magic) {
+		VSB_printf(vsb, "  .magic = 0x%04x", *uptr);
+		VSB_printf(vsb, " EXPECTED: 0x%04x", magic);
+		VSB_putc(vsb, '\n');
+		VSB_cat(vsb, "}\n");
+		return (-3);
+	}
+	VSB_indent(vsb, 2);
+	return (0);
+}
+
+static void
+fellow_cache_res_panic(struct vsb *vsb, const struct fellow_cache_res *res)
+{
+	if (res->status == fcr_ok) {
+		VSB_printf(vsb, "fcr = { %s { r.integer = %d, r.ptr = %p}},\n",
+		    fellow_cache_res_s[res->status],
+		    res->r.integer, res->r.ptr);
+	}
+	else {
+		VSB_printf(vsb, "fcr = { %s error: %s },\n",
+		    fellow_cache_res_s[res->status], res->r.err);
+	}
+}
+
+static void
+fellow_cache_buddy_ptr_extent_panic(struct vsb *vsb,
+    struct buddy_ptr_extent alloc, const char *name)
+{
+	VSB_printf(vsb, "%s = {.ptr = %p, .size = %zu},\n",
+	    name, alloc.ptr, alloc.size);
+}
+
+static void
+fellow_cache_buddy_off_extent_panic(struct vsb *vsb,
+    struct buddy_off_extent fdr, const char *name)
+{
+	VSB_printf(vsb, "%s = {.off = %jd, .size = %zu},\n",
+	    name, fdr.off, fdr.size);
+}
+
+static void
+fellow_hash_panic(struct vsb *vsb, const union fh *h)
+{
+	VSB_printf(vsb, "fh[0..8] = %02x%02x%02x%02x%02x%02x%02x%02x,\n",
+	    h->sha256[0],
+	    h->sha256[1],
+	    h->sha256[2],
+	    h->sha256[3],
+	    h->sha256[4],
+	    h->sha256[5],
+	    h->sha256[6],
+	    h->sha256[7]);
+}
+
+static void
+fellow_disk_seg_panic(struct vsb *vsb, const struct fellow_disk_seg *fds,
+    const char *name)
+{
+	if (fc_dump_u16_struct(vsb, fds, FELLOW_DISK_SEG_MAGIC, "%s", name))
+		return;
+	VSB_printf(vsb, "fht = %u, segnum = %u,\n", fds->fht, fds->segnum);
+	fellow_cache_buddy_off_extent_panic(vsb, fds->seg, "seg");
+	fellow_hash_panic(vsb, fds->fh);
+	VSB_indent(vsb, -2);
+	VSB_cat(vsb, "},\n");
+}
+
+static void
+fellow_cache_seg_panic(struct vsb *vsb, const struct fellow_cache_seg *fcs,
+    const char *name)
+{
+	if (fc_dump_u16_struct(vsb, fcs, FELLOW_CACHE_SEG_MAGIC, "%s", name))
+		return;
+	VSB_printf(vsb, "state = %s, fcs_onlru = %d, fco_infdb = %d,\n",
+	    fcos_state_s[fcs->state], fcs->fcs_onlru, fcs->fco_infdb);
+	VSB_printf(vsb, "lcb_add = %d, lcb_remove = %d, fco_lru_mutate = %d,\n",
+	    fcs->lcb_add, fcs->lcb_remove, fcs->fco_lru_mutate);
+	VSB_printf(vsb, "refcnt = %u, fco = %p,\n", fcs->refcnt, fcs->fco);
+	fellow_disk_seg_panic(vsb, fcs->disk_seg, "disk_seg");
+	fellow_cache_buddy_ptr_extent_panic(vsb, fcs->alloc, "alloc");
+	VSB_printf(vsb, "union { .fcs_len = %zu, .fco_fdo = %p },\n",
+	    fcs->u.fcs_len, fcs->u.fco_fdo);
+	VSB_indent(vsb, -2);
+	VSB_cat(vsb, "},\n");
+}
+
+static void
+fellow_disk_seglist_panic(struct vsb *vsb,
+    const struct fellow_disk_seglist *fdsl, const char *name)
+{
+	if (PAN_dump_struct(vsb, fdsl, FELLOW_DISK_SEGLIST_MAGIC, "%s", name))
+		return;
+	VSB_printf(vsb, "version = %u, fht = %u, nsegs = %u, lsegs = %u,\n",
+	    fdsl->version, fdsl->fht, fdsl->nsegs, fdsl->lsegs);
+	fellow_hash_panic(vsb, fdsl->fh);
+	fellow_cache_buddy_off_extent_panic(vsb, fdsl->next, "next");
+	VSB_indent(vsb, -2);
+	VSB_cat(vsb, "},\n");
+}
+
+static void
+fellow_cache_seglist_panic_short(struct vsb *vsb,
+    const struct fellow_cache_seglist *fcsl, const char *name)
+{
+	off_t off = -1;
+
+	//lint --e{438}
+next:
+	if (PAN_dump_oneline(vsb, fcsl, FELLOW_CACHE_SEGLIST_MAGIC, "%s", name))
+		return;
+
+	if (fcsl->fdsl) {
+		VSB_printf(vsb,
+		    "fdsl_off = %jd, fcsl_lsegs = %u, fdsl_lsegs = %u, nsegs = %u },\n",
+		    off, fcsl->lsegs, fcsl->fdsl->lsegs, fcsl->fdsl->nsegs);
+		off = fcsl->fdsl->next.off;
+	}
+	else
+		VSB_printf(vsb, "lsegs = %u, fdsl = NULL,\n", fcsl->lsegs);
+	fcsl = fcsl->next;
+	goto next;
+}
+
+static void
+fellow_cache_seglist_panic(struct vsb *vsb,
+    const struct fellow_cache_seglist *fcsl, const char *name, unsigned flags)
+{
+	uint16_t u;
+
+	if (! (flags & FCPF_SEGLIST)) {
+		fellow_cache_seglist_panic_short(vsb, fcsl, name);
+		return;
+	}
+	//lint --e{438}
+next:
+	if (PAN_dump_struct(vsb, fcsl, FELLOW_CACHE_SEGLIST_MAGIC, "%s", name))
+		return;
+
+	VSB_printf(vsb, "lsegs = %u, fcsl_sz %zu, fdsl_sz = %zu, ",
+	    fcsl->lsegs, fcsl->fcsl_sz, fcsl->fdsl_sz);
+	fellow_disk_seglist_panic(vsb, fcsl->fdsl, "fdsl");
+	if ((flags & FCPF_SEG) && fcsl->fdsl) {
+		VSB_cat(vsb, "segs = [\n");
+		VSB_indent(vsb, 2);
+		for (u = 0; u < fcsl->fdsl->nsegs; u++)
+			fellow_cache_seg_panic(vsb, &fcsl->segs[u], "seg[]");
+		VSB_indent(vsb, -2);
+	}
+	VSB_indent(vsb, -2);
+	VSB_cat(vsb, "},\n");
+	fcsl = fcsl->next;
+	goto next;
+
+}
+#endif
+
+void
+fellow_cache_panic(struct vsb *vsb, const struct fellow_cache_obj *fco)
+{
+#ifdef TEST_DRIVER
+	(void) vsb;
+	(void) fco;
+#else
+	unsigned flags = 0;
+
+	if (PAN_dump_struct(vsb, fco, FELLOW_CACHE_OBJ_MAGIC, "fco"))
+		return;
+	if (fco->lru && fco->lru->fc && fco->lru->fc->tune)
+		flags = fco->lru->fc->tune->panic_flags;
+
+	VSB_printf(vsb,
+	    "logstate = %d, seglstate = %d, lru = %p, ntouched = %d,\n",
+	    fco->logstate, fco->seglstate, fco->lru, fco->ntouched);
+	fellow_cache_res_panic(vsb, &fco->fcr);
+	if (flags & FCPF_SEG)  {
+		fellow_cache_seg_panic(vsb, &fco->fdo_fcs, "fdo_fcs");
+		fellow_cache_seg_panic(vsb, &fco->aa_esidata_seg, "esidata");
+	}
+	fellow_cache_seglist_panic(vsb, fco->fcsl, "fcsl", flags);
+	VSB_indent(vsb, -2);
+	VSB_cat(vsb, "},\n");
+#endif
+}
+
+void
+fellow_busy_panic(struct vsb *vsb, const struct fellow_busy *fbo)
+{
+#ifdef TEST_DRIVER
+	(void) vsb;
+	(void) fbo;
+#else
+	unsigned u;
+
+	if (PAN_dump_struct(vsb, fbo, FELLOW_BUSY_MAGIC, "fbo"))
+		return;
+	VSB_printf(vsb,
+	    "sz_estimate = %zu, sz_returned = %zu, sz_increment = %zu,\n",
+	    fbo->sz_estimate, fbo->sz_returned, fbo->sz_increment);
+	VSB_printf(vsb, "sz_dskalloc = %zu, grown = %u, fbo_mem.size = %zu\n",
+	    fbo->sz_dskalloc, fbo->grown, fbo->fbo_mem.size);
+	VSB_printf(vsb, "region[%u] = [\n", fbo->nregion);
+	VSB_indent(vsb, 2);
+	for (u = 0; u < fbo->nregion; u++)
+		fellow_cache_buddy_off_extent_panic(vsb, fbo->region[u], "fdr");
+	VSB_indent(vsb, -2);
+	VSB_cat(vsb, "],\n");
+	VSB_printf(vsb, "io_outstanding = %u,\n", fbo->io_outstanding);
+	VSB_indent(vsb, -2);
+	VSB_cat(vsb, "},\n");
+#endif
+}
+
 struct fellow_cache_res
 fellow_cache_obj_getattr(struct fellow_cache *fc,
     struct fellow_cache_obj *fco,

src/fellow_cache.h

@@ -77,6 +77,10 @@ fellow_busy_obj_alloc(struct fellow_cache *fc,
 struct fellow_cache_res
 fellow_busy_obj_getspace(struct fellow_busy *fbo,
     size_t *sz, uint8_t **ptr);
+
+void fellow_cache_panic(struct vsb *vsb, const struct fellow_cache_obj *fco);
+void fellow_busy_panic(struct vsb *vsb, const struct fellow_busy *fbo);
+
 void fellow_busy_obj_extend(struct fellow_busy *fbo, size_t l);
 void fellow_busy_obj_trimstore(struct fellow_busy *fbo);
 

src/fellow_storage.c

@@ -3023,48 +3023,15 @@ sfe_ban_imm(struct sfe_resurrect_priv *sfer, const struct fellow_dle *e)
 	return (t);
 }
 
-#ifdef TODO
-void
-sfe_panic_st(struct vsb *vsb, const char *hd, const struct sfe *sfe)
-{
-	VSB_printf(vsb, "%s = %p {emb=%u, ptr=%p, len=%zu, space=%zu},\n",
-	hd, sfe, sfe->embedded, (void *)sfe->ptr, sfe->len, sfe->space);
-}
-
-void
+static void
 sfe_panic(struct vsb *vsb, const struct objcore *oc)
 {
-	struct obu *o;
-	struct sfe *st;
-
-	VSB_printf(vsb, "Buddy = %p,\n", oc->stobj->priv);
-	if (oc->stobj->priv == NULL)
-		return;
-	CAST_OBJ_NOTNULL(o, oc->stobj->priv, OBU_MAGIC);
 
-	sfe_panic_st(vsb, "Obj", o->objstore);
-
-#define OBJ_FIXATTR(U, l, sz) \
-	VSB_printf(vsb, "%s = ", #U); \
-	VSB_quote(vsb, (const void*)o->fa_##l, sz, VSB_QUOTE_HEX); \
-	VSB_printf(vsb, ",\n");
-
-#define OBJ_VARATTR(U, l) \
-	VSB_printf(vsb, "%s = {len=%u, ptr=%p},\n", \
-	    #U, o->va_##l##_len, o->va_##l);
-
-#define OBJ_AUXATTR(U, l)						\
-	do {								\
-		if (o->aa_##l != NULL) sfe_panic_st(vsb, #U, o->aa_##l);\
-	} while(0);
-
-#include "tbl/obj_attr.h"
-
-	VTAILQ_FOREACH(st, &o->list, list) {
-		sfe_panic_st(vsb, "Body", st);
-	}
+	VSB_printf(vsb, "priv2 = %ju, ", (uintmax_t)oc->stobj->priv2);
+	fellow_cache_panic(vsb, oc->stobj->priv);
+	if (oc->boc)
+		fellow_busy_panic(vsb, oc->boc->stevedore_priv);
 }
-#endif
 
 static VCL_BYTES v_matchproto_(stv_var_free_space)
 sfe_free_space(const struct stevedore *stv)
@@ -3143,7 +3110,7 @@ static const struct stevedore sfemem_stevedore = {
 	.baninfo        =	sfe_baninfo,
 	.banexport      =	sfe_banexport,
 
-//	.panic		=	sfe_panic,
+	.panic		=	sfe_panic,
 	.methods	=	&sfemem_methods,
 	.var_free_space =	sfe_free_space,
 	.var_used_space =	sfe_used_space,

src/tbl/fellow_tunables.h

@@ -77,6 +77,7 @@ TUNEFAIL(unsigned, ioerr_log, 0, 0, 1);
 TUNEFAIL(unsigned, allocerr_obj, 0, 0, 1);
 // mem error: 0=panic, 1=fail storage
 TUNEFAIL(unsigned, allocerr_log, 0, 0, 1);
+TUNE(unsigned, panic_flags, 0, 0, UINT_MAX);
 #undef TUNE
 #undef TUNEH
 #undef TUNEFAIL

src/vmod_slash.vcc

@@ -634,7 +634,8 @@ $Method STRING .tune(
 	[ ENUM { panic, purge } ioerr_obj ],
 	[ ENUM { panic, fail } ioerr_log ],
 	[ ENUM { panic, purge } allocerr_obj ],
-	[ ENUM { panic, fail } allocerr_log ])
+	[ ENUM { panic, fail } allocerr_log ],
+	[ INT		panic_flags ])
 
 Using the `xfellow.tune()`_ method, the following parameters of the
 fellow storage can be fine tuned:
@@ -1024,6 +1025,13 @@ fellow storage can be fine tuned:
   normal circumstances and instead wait for LRU to make room,
   ``panic`` is intended also for production use.
 
+* *panic_flags*
+
+  Used to increase verbosity of panic messages, read as a bit field.
+
+  0x01 : dump full fellow_cache_seg
+  0x02 : dump full fellow_cache_seglist / fellow_disk_seglist
+
 $Method STEVEDORE .storage()
 
 Return the the buddy storage. Can be used to set it for storing a
@@ -1069,7 +1077,8 @@ $Function STRING tune_fellow(
 	[ ENUM { panic, purge } ioerr_obj ],
 	[ ENUM { panic, fail } ioerr_log ],
 	[ ENUM { panic, purge } allocerr_obj ],
-	[ ENUM { panic, fail } allocerr_log ])
+	[ ENUM { panic, fail } allocerr_log ],
+	[ INT		panic_flags ])
 
 Tune the given globally defined fellow storage, for all other
 parameters see `xfellow.tune()`_.

src/vtc/fellow_b00062.vtc

-varnishtest "Test that we properly wait for certain 304 cases"
+varnishtest "Test that we properly wait for certain 304 cases & Generate Panics"
 
 server s1 {
 	rxreq
@@ -23,6 +23,16 @@ server s1 {
 	rxreq
 	expect req.http.if-modified-since == "Wed, 11 Sep 2013 13:36:55 GMT"
 	txresp -status 304
+
+	# IMS after restart
+	accept
+	rxreq
+	expect req.http.if-modified-since == "Wed, 11 Sep 2013 13:36:55 GMT"
+	non_fatal
+	txresp -hdr "Last-Modified: Wed, 12 Sep 2013 13:36:55 GMT" \
+	       -nolen -hdr "Content-Length: 1048576"
+	send_n 104857 "0123456789"
+	delay 10
 } -start
 
 varnish v1 \
@@ -32,6 +42,7 @@ varnish v1 \
     -arg "-sfellow=fellow,${tmpdir}/fellow_global.stv,100MB,1MB,64KB" \
 -vcl+backend {
 	import slash;
+	import vtc;
 	sub vcl_init {
 		slash.tune_fellow(storage.fellow, chunk_exponent=12);
 		slash.tune_fellow(storage.fellow, readahead=31);
@@ -42,6 +53,11 @@ varnish v1 \
 		set beresp.keep = 1d;
 		set beresp.http.was-304 = beresp.was_304;
 	}
+	sub vcl_deliver {
+		if (req.http.panic == "deliver") {
+			vtc.panic(req.http.panic);
+		}
+	}
 } -start
 
 client c1 {
@@ -97,3 +113,33 @@ client c1 {
 	expect resp.status == 200
 	expect resp.bodylen == 1048576
 } -run
+
+varnish v1 -cliok "param.set feature +no_coredump"
+
+client c1 {
+	txreq -hdr "panic: deliver"
+} -run
+
+varnish v1 -wait-stopped
+varnish v1 -cliok "panic.show"
+varnish v1 -cliok "panic.clear"
+
+varnish v1 -start
+
+client c1 {
+	txreq
+	delay 2
+} -start
+
+client c2 {
+	txreq -hdr "panic: deliver"
+} -start
+
+varnish v1 -wait-stopped
+varnish v1 -cliok "panic.show"
+varnish v1 -cliok "panic.clear"
+
+client c1 -wait
+client c2 -wait
+
+varnish v1 -expectexit 0x40