diff --git a/doc/configuration.txt b/doc/configuration.txt index e7819b65c..583df4773 100644 --- a/doc/configuration.txt +++ b/doc/configuration.txt @@ -17840,6 +17840,34 @@ ipv4() : ipv4 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 000000000..b57251912 --- /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 382dd86d5..3135b7300 100644 --- a/src/stream.c +++ b/src/stream.c @@ -3849,12 +3849,38 @@ static int smp_fetch_cur_tunnel_timeout(const struct arg *args, struct sample *s 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 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 }, }};