Elukey has uploaded a new change for review.
https://gerrit.wikimedia.org/r/295652
Change subject: Add the -T VSL API timeout parameter plus the related formatter.
......................................................................
Add the -T VSL API timeout parameter plus the related formatter.
The Varnish workers use a buffer to write Log tags. When it gets full,
all the tags are flushed to the shmlog and anything using the VSL API
can read them. On a busy server it may happen that due to the buffer
flushed often, a Begin tag related to a request/response lands to
the shmlog but the rest is delayed (for example due to long processing).
If the delay is more than 120 seconds, the VSL API by default will return
all the available tags adding a special tag to notify the issue (VSL: timeout).
This change introduce the following improvements:
- the -T parameter to force a custom VSL timeout, rather than relying
on the default 120 seconds.
- a new formatter, %{VSL:*}x, able to log tags like VSL:timeout.
The new formatter is special since usually everything specified through fmtvar
matches a variable in the logs, namely something like "varname:". The VSL
tag does not follow this convention and puts a message directly instead.
The solution proposed is a tag flag that forces varnishkafka to use
the variable part specified in fmtvar only as string prefix, not counting the
":".
For example, a %{VSL:timeout}x formatter will instruct varnishkafka to search
a SLT_VSL tag with "timeout" as prefix in its payload.
Change-Id: I302922a6490d287e4d866481530d2807293706a8
---
M config.c
M varnishkafka.c
M varnishkafka.conf.example
M varnishkafka.h
4 files changed, 71 insertions(+), 12 deletions(-)
git pull
ssh://gerrit.wikimedia.org:29418/operations/software/varnish/varnishkafka
refs/changes/52/295652/1
diff --git a/config.c b/config.c
index 70d1cd4..dcc31c3 100644
--- a/config.c
+++ b/config.c
@@ -192,6 +192,9 @@
} else if (!strcmp(name, "varnish.arg.N")) {
conf.N_flag = 1;
conf.N_flag_path = strdup(val);
+ } else if (!strcmp(name, "varnish.arg.T")) {
+ conf.T_flag = 1;
+ conf.T_flag_seconds = strdup(val);
} else {
snprintf(errstr, errstr_size,
"Unknown configuration property \"%s\"\n", name);
diff --git a/varnishkafka.c b/varnishkafka.c
index 1ab6980..9b72950 100644
--- a/varnishkafka.c
+++ b/varnishkafka.c
@@ -793,7 +793,7 @@
const char *ptr, size_t len);
/* Optional tag->flags */
int tag_flags;
- } f[4+1]; /* increase size when necessary (max used size + 1) */
+ } f[5+1]; /* increase size when necessary (max used size + 1) */
/* Default string if no matching tag was found or all
* parsers failed, defaults to "-". */
@@ -900,6 +900,9 @@
.parser = parse_vcl_handling },
{ VSL_CLIENTMARKER, SLT_VCL_Log,
.fmtvar = "VCL_Log:*" },
+ { VSL_CLIENTMARKER, SLT_VSL,
+ .fmtvar = "VSL:*",
+ .tag_flags = TAG_F_MATCH_PREFIX },
} },
['n'] = { {
{ VSL_CLIENTMARKER, VSL_TAG__ONCE,
@@ -1516,7 +1519,9 @@
if (!(tag->spec & spec))
continue;
- if ((tag->var) && !(tag->flags & TAG_F_TIMESTAMP)){
+ if ((tag->var)
+ && !(tag->flags & TAG_F_TIMESTAMP)
+ && !(tag->flags & TAG_F_MATCH_PREFIX)) {
const char *t;
/* Get the occurence of ":" in ("Varname: value") */
@@ -1579,6 +1584,17 @@
} else {
continue;
}
+ } else if (tag->flags & TAG_F_MATCH_PREFIX) {
+ /* Skip the check if TAG_F_MATCH_PREFIX is used,
because 'var'
+ * contains a generic prefix match.
+ * One example is the VSL tag, that emits strings like
"timeout",
+ * clearly not following the usual "$VAR:" format.
+ */
+ if (!strncmp(ptr, tag->var, tag->varlen)) {
+ ptr2 = ptr;
+ len2 = len;
+ } else
+ continue;
} else {
ptr2 = ptr;
len2 = len;
@@ -1884,7 +1900,7 @@
conf.logname = strdup(lh->h_name);
/* Parse command line arguments */
- while ((c = getopt(argc, argv, "hS:N:Dq:n:")) != -1) {
+ while ((c = getopt(argc, argv, "hS:N:Dq:n:T:")) != -1) {
switch (c) {
case 'h':
usage(argv[0]);
@@ -1910,6 +1926,17 @@
/* name of varnishd instance to use */
conf.n_flag = 1;
conf.n_flag_name = strdup(optarg);
+ break;
+ case 'T':
+ /* Maximum (VSL) wait time between a Begin tag and a
End one.
+ * Varnish workers write log tags to a buffer that gets
flushed
+ * to the shmlog once full. It might happen that a Begin
+ * tag gets flushed to shmlog as part of a batch without
+ * its correspondent End tag (for example, due to long
requests).
+ * Consistency checks for the value postponed to
VSL_Arg later on.
+ */
+ conf.T_flag = 1;
+ conf.T_flag_seconds = strdup(optarg);
break;
default:
usage(argv[0]);
@@ -2021,6 +2048,15 @@
struct VSL_cursor *vsl_cursor;
conf.vsm = VSM_New();
+ if (conf.T_flag) {
+ if (VSL_Arg(conf.vsl, 'T', conf.T_flag_seconds) < 0) {
+ vk_log("VSL_T_arg", LOG_ERR, "Failed to set a %s
timeout for VSL log transactions: %s",
+ conf.T_flag_seconds,
VSL_Error(conf.vsl));
+ varnish_api_cleaning();
+ exit(1);
+ }
+ }
+
/* Check if the user wants to open a specific SHM File (-N) or
* a SHM file related to a specific varnishd instance (-n)
*/
diff --git a/varnishkafka.conf.example b/varnishkafka.conf.example
index d47dea5..7a531b4 100644
--- a/varnishkafka.conf.example
+++ b/varnishkafka.conf.example
@@ -65,16 +65,24 @@
# #
# #
# Additional formatter specials: #
-# %{<strftime-format>}t - format timestamp according to supplied #
-# strftime(3) compatible format string. #
-# If the format starts with 'end:' #
-# the SLT_Timestamp used is 'Resp' #
-# (end of the request processing), #
-# otherwise SLT_Timestamp 'Start' #
-# will be used. #
+# %{<strftime-format>}t - format timestamp according #
+# to supplied strftime(3) compatible #
+# format string. #
+# If the format starts with 'end:' #
+# the SLT_Timestamp used is 'Resp' #
+# (end of the request processing), #
+# otherwise SLT_Timestamp 'Start' #
+# will be used. #
# #
-# %{Varnish:xid}x - transaction id of client request. #
-# Same value as X-Varnish header #
+# %{Varnish:time_firstbyte} - Time to first byte from Varnish. #
+# #
+# %{Varnish:handling}x - VCL_call carrying "handling:". #
+# #
+# %{VCL_Log:var}x - VLC_Log starting with a "var:". #
+# Example: VCL_Log:hit #
+# %{VSL:prefix}x - VSL API warnings/errors starting #
+# with "prefix". #
+# Example: VSL:timeout #
# #
# #
# #
@@ -195,6 +203,13 @@
# -N: VSM filename to read logs from.
# varnish.arg.N = /this/is/a/path
+# -T: Max seconds that the VSL API waits between a Begin tag and a End one.
+# Varnish workers write log tags to a buffer that gets flushed
+# to the shmlog once full. It might happen that a Begin
+# tag gets flushed to shmlog as part of a batch without
+# its correspondent End tag (for example, due to long requests).
+# varnish.arg.T = 120
+
#######################################################################
# #
diff --git a/varnishkafka.h b/varnishkafka.h
index e07d576..3974c27 100644
--- a/varnishkafka.h
+++ b/varnishkafka.h
@@ -92,6 +92,9 @@
#define TAG_F_TIMESTAMP 1 /* var is a SLT_Timestamp formatter */
#define TAG_F_TIMESTAMP_END 1<<2 /* var contains the end prefix */
#define TAG_F_LAST 1<<3 /* If multiple, log last one not first one
*/
+#define TAG_F_MATCH_PREFIX 1<<4 /* var contains a string prefix to match
+ * (not following the $VAR: scheme)
+ */
};
/**
@@ -150,6 +153,8 @@
char* N_flag_path;
int n_flag;
char* n_flag_name;
+ int T_flag;
+ char* T_flag_seconds;
/* Sparsely populated with desired tags */
--
To view, visit https://gerrit.wikimedia.org/r/295652
To unsubscribe, visit https://gerrit.wikimedia.org/r/settings
Gerrit-MessageType: newchange
Gerrit-Change-Id: I302922a6490d287e4d866481530d2807293706a8
Gerrit-PatchSet: 1
Gerrit-Project: operations/software/varnish/varnishkafka
Gerrit-Branch: master
Gerrit-Owner: Elukey <ltosc...@wikimedia.org>
_______________________________________________
MediaWiki-commits mailing list
MediaWiki-commits@lists.wikimedia.org
https://lists.wikimedia.org/mailman/listinfo/mediawiki-commits
