MINOR: stream: add "last_rule_file" and "last_rule_line" samples
These two sample fetch methods report respectively the file name and the
line number where was located the last rule that was final. This is aimed
at being used on log-format lines to help admins figure what rule in the
configuration gave a final verdict, and help understand the condition
that led to the action.
For example, it's now possible to log the last matched rule by adding
this to the log-format:
... lr=%[last_rule_file]:%[last_rule_line]
A regtest is provided to test various combinations of final rules, some
even on top of each other from different rulesets.
diff --git a/doc/configuration.txt b/doc/configuration.txt
index e7819b6..583df47 100644
--- a/doc/configuration.txt
+++ b/doc/configuration.txt
@@ -17840,6 +17840,34 @@
ipv6(<ipv6>) : ipv6
Returns an ipv6.
+last_rule_file: string
+ This returns the name of the configuration file containing the last final
+ rule that was matched during stream analysis. A final rule is one that
+ terminates the evaluation of the rule set (like an "accept", "deny" or
+ "redirect"). This works for TCP request and response rules acting on the
+ "content" rulesets, and on HTTP rules from "http-request", "http-response"
+ and "http-after-response" rule sets. The legacy "redirect" rulesets are not
+ supported (such information is not stored there), and neither "tcp-request
+ connection" nor "tcp-request session" rulesets are supported because the
+ information is stored at the stream level and streams do not exist during
+ these rules. The main purpose of this function is to be able to report in
+ logs where was the rule that gave the final verdict, in order to help
+ figure why a request was denied for example. See also "last_rule_line".
+
+last_rule_line: integer
+ This returns the line number in the configuration file where is located the
+ last final rule that was matched during stream analysis. A final rule is one
+ that terminates the evaluation of the rule set (like an "accept", "deny" or
+ "redirect"). This works for TCP request and response rules acting on the
+ "content" rulesets, and on HTTP rules from "http-request", "http-response"
+ and "http-after-response" rule sets. The legacy "redirect" rulesets are not
+ supported (such information is not stored there), and neither "tcp-request
+ connection" nor "tcp-request session" rulesets are supported because the
+ information is stored at the stream level and streams do not exist during
+ these rules. The main purpose of this function is to be able to report in
+ logs where was the rule that gave the final verdict, in order to help
+ figure why a request was denied for example. See also "last_rule_file".
+
lat_ns_avg : integer
Returns the average number of nanoseconds spent between the moment the task
handling the stream is woken up and the moment it is effectively called. This
diff --git a/reg-tests/log/last_rule.vtc b/reg-tests/log/last_rule.vtc
new file mode 100644
index 0000000..b572519
--- /dev/null
+++ b/reg-tests/log/last_rule.vtc
@@ -0,0 +1,165 @@
+varnishtest "Verify logging of last final rule"
+feature ignore_unknown_macro
+
+#REQUIRE_VERSION=2.6
+
+server s1 {
+ rxreq
+ txresp
+} -repeat 15 -start
+
+syslog Slg_1 -level info {
+ recv
+ # /trqacc1
+ expect ~ "[^:\\[ ]\\[${h1_pid}\\]: .* lr=.*/h1/cfg:30"
+ recv
+ expect ~ "[^:\\[ ]\\[${h1_pid}\\]: .* lr=.*/h1/cfg:31"
+ recv
+ expect ~ "[^:\\[ ]\\[${h1_pid}\\]: .* lr=.*/h1/cfg:32"
+ recv
+ # /trsacc1
+ expect ~ "[^:\\[ ]\\[${h1_pid}\\]: .* lr=.*/h1/cfg:36"
+ recv
+ expect ~ "[^:\\[ ]\\[${h1_pid}\\]: .* lr=.*/h1/cfg:37"
+ recv
+ expect ~ "[^:\\[ ]\\[${h1_pid}\\]: .* lr=.*/h1/cfg:38"
+ recv
+ # /hrqvar
+ expect ~ "[^:\\[ ]\\[${h1_pid}\\]: .* lr=.*-:-"
+ recv
+ expect ~ "[^:\\[ ]\\[${h1_pid}\\]: .* lr=.*/h1/cfg:41"
+ recv
+ expect ~ "[^:\\[ ]\\[${h1_pid}\\]: .* lr=.*/h1/cfg:42"
+ recv
+ expect ~ "[^:\\[ ]\\[${h1_pid}\\]: .* lr=.*/h1/cfg:43"
+ recv
+ expect ~ "[^:\\[ ]\\[${h1_pid}\\]: .* lr=.*/h1/cfg:44"
+ recv
+ # /hrsacc1
+ expect ~ "[^:\\[ ]\\[${h1_pid}\\]: .* lr=.*/h1/cfg:46"
+ recv
+ expect ~ "[^:\\[ ]\\[${h1_pid}\\]: .* lr=.*/h1/cfg:47"
+ recv
+ expect ~ "[^:\\[ ]\\[${h1_pid}\\]: .* lr=.*/h1/cfg:48"
+ recv
+ expect ~ "[^:\\[ ]\\[${h1_pid}\\]: .* lr=.*/h1/cfg:49"
+} -start
+
+haproxy h1 -conf {
+ global
+ nbthread 1
+
+ defaults
+ mode http
+ option httplog
+ option http-server-close
+ timeout connect "${HAPROXY_TEST_TIMEOUT-5s}"
+ timeout client "${HAPROXY_TEST_TIMEOUT-5s}"
+ timeout server "${HAPROXY_TEST_TIMEOUT-5s}"
+
+ frontend fe1
+ bind "fd@${fe_1}"
+ log ${Slg_1_addr}:${Slg_1_port} local0
+ log-format "ci:%cp [%tr] lr=%[last_rule_file]:%[last_rule_line]"
+ default_backend be
+
+ backend be
+ # handle these URLs:
+ # /trqacc1, /trqrej1, /trqrej2, /trsacc1, /trsrej1, /trsrej2
+ # /hrqvar, /hrqacc1, /hrqred1, /hrqrej1, /hrqrej2,
+ # /hrsacc1, /hrsred1, /hrsrej1, /hrsrej2
+
+ tcp-response inspect-delay 10s
+ tcp-request content set-var(txn.path) path # must have no effect
+ tcp-request content accept if { var(txn.path) -m beg /trqacc1 /hrqrej1 }
+ tcp-request content reject if { var(txn.path) -m beg /trqrej1 }
+ tcp-request content reject if { var(txn.path) -m beg /trqrej2 }
+
+ tcp-response content reject unless WAIT_END
+ tcp-response content set-var(txn.foo) var(txn.path) # must have no effect
+ tcp-response content accept if { var(txn.path) -m beg /trsacc1 /hrsrej1 }
+ tcp-response content reject if { var(txn.path) -m beg /trsrej1 }
+ tcp-response content reject if { var(txn.path) -m beg /trsrej2 }
+
+ http-request set-var(txn.bar) var(txn.path) if { path_beg /hrqvar } # must have no effect
+ http-request allow if { var(txn.path) -m beg /hrqacc1 /hrsrej2 }
+ http-request redirect location / if { var(txn.path) -m beg /hrqred1 }
+ http-request deny if { var(txn.path) -m beg /hrqrej1 } # accepted by tcp-rq above
+ http-request deny if { var(txn.path) -m beg /hrqrej2 }
+
+ http-response allow if { var(txn.path) -m beg /hrsacc1 }
+ http-response redirect location / if { var(txn.path) -m beg /hrsred1 }
+ http-response deny if { var(txn.path) -m beg /hrsrej1 } # accepted by tcp-rs above
+ http-response deny if { var(txn.path) -m beg /hrsrej2 } # accepted by http-rq above
+ http-response deny if { var(txn.path) -m beg /hrsrej3 }
+
+ server app1 ${s1_addr}:${s1_port}
+} -start
+
+client c1 -connect ${h1_fe_1_sock} {
+ txreq -url /trqacc1
+ rxresp
+
+ txreq -url /trqrej1
+ expect_close
+} -run
+
+# The following client are started in background and synchronized
+client c2 -connect ${h1_fe_1_sock} {
+ txreq -url /trqrej2
+ expect_close
+} -run
+
+client c3 -connect ${h1_fe_1_sock} {
+ txreq -url /trsacc1
+ rxresp
+ expect resp.status == 200
+
+ txreq -url /trsrej1
+ expect_close
+} -run
+
+client c4 -connect ${h1_fe_1_sock} {
+ txreq -url /trsrej2
+ expect_close
+} -run
+
+client c5 -connect ${h1_fe_1_sock} {
+ txreq -url /hrqvar
+ rxresp
+ expect resp.status == 200
+
+ txreq -url /hrqacc1
+ rxresp
+ expect resp.status == 200
+
+ txreq -url /hrqred1
+ rxresp
+ expect resp.status == 302
+
+ txreq -url /hrqrej1
+ rxresp
+ expect resp.status == 403
+
+ txreq -url /hrqrej2
+ rxresp
+ expect resp.status == 403
+
+ txreq -url /hrsacc1
+ rxresp
+ expect resp.status == 200
+
+ txreq -url /hrsred1
+ rxresp
+ expect resp.status == 302
+
+ txreq -url /hrsrej1
+ rxresp
+ expect resp.status == 502
+
+ txreq -url /hrsrej2
+ rxresp
+ expect resp.status == 502
+} -run
+
+syslog Slg_1 -wait
diff --git a/src/stream.c b/src/stream.c
index 382dd86..3135b73 100644
--- a/src/stream.c
+++ b/src/stream.c
@@ -3849,12 +3849,38 @@
return 1;
}
+static int smp_fetch_last_rule_file(const struct arg *args, struct sample *smp, const char *km, void *private)
+{
+ smp->flags = SMP_F_VOL_TXN;
+ smp->data.type = SMP_T_STR;
+ if (!smp->strm || !smp->strm->last_rule_file)
+ return 0;
+
+ smp->flags |= SMP_F_CONST;
+ smp->data.u.str.area = (char *)smp->strm->last_rule_file;
+ smp->data.u.str.data = strlen(smp->strm->last_rule_file);
+ return 1;
+}
+
+static int smp_fetch_last_rule_line(const struct arg *args, struct sample *smp, const char *km, void *private)
+{
+ smp->flags = SMP_F_VOL_TXN;
+ smp->data.type = SMP_T_SINT;
+ if (!smp->strm || !smp->strm->last_rule_line)
+ return 0;
+
+ smp->data.u.sint = smp->strm->last_rule_line;
+ return 1;
+}
+
/* Note: must not be declared <const> as its list will be overwritten.
* Please take care of keeping this list alphabetically sorted.
*/
static struct sample_fetch_kw_list smp_kws = {ILH, {
{ "cur_server_timeout", smp_fetch_cur_server_timeout, 0, NULL, SMP_T_SINT, SMP_USE_BKEND, },
{ "cur_tunnel_timeout", smp_fetch_cur_tunnel_timeout, 0, NULL, SMP_T_SINT, SMP_USE_BKEND, },
+ { "last_rule_file", smp_fetch_last_rule_file, 0, NULL, SMP_T_STR, SMP_USE_INTRN, },
+ { "last_rule_line", smp_fetch_last_rule_line, 0, NULL, SMP_T_SINT, SMP_USE_INTRN, },
{ NULL, NULL, 0, 0, 0 },
}};