REGTESTS: log: check which log-format tags escape control characters

It is not obvious which log-format construct protects the log against
control characters coming from the request, and "+E" is easily believed
to be the one, while it is in fact the RFC5424 structured-data escaping
and only covers '"', '\' and ']' (see rfc5424_escape_map).

The test logs one same captured header value, containing a raw ESC and a
']', through three different tags, and shows that:

  smp |A?[31m]B|        %[capture.req.hdr(0)]      nothing escaped
  esc |A?[31m\]B|       %{+E}[capture.req.hdr(0)]  ']' escaped, not the ESC
  hdr |{A#1B[31m]B}|    %hr                        ESC encoded as "#1B"

Only %hr and %r, which use hdr_encode_map and url_encode_map, encode the
0x00-0x1f and 0x7f-0xff ranges. A sample expression emits them verbatim
whatever the options, so a config using %[...] to log request data puts
control characters in the logs and in the rings.

The dump is read with "show events -s" so that a control character which
made it to the ring shows up as a '?', which avoids embedding one into
this file. The test does not depend on the delimiter fix from the two
previous commits since it does not use "-0".

diff --git a/reg-tests/log/log_escaping.vtc b/reg-tests/log/log_escaping.vtc
new file mode 100644 (file)
index 0000000..340ed60
--- /dev/null
+++ b/reg-tests/log/log_escaping.vtc
@@ -0,0 +1,93 @@
+varnishtest "Check which log-format tags escape control characters"
+feature ignore_unknown_macro
+
+# All three frontends log the very same captured header value, which contains a
+# raw ESC (0x1b) and a ']', but each uses a different log-format tag:
+#
+#   %[capture.req.hdr(0)]        sample expression, no escaping at all
+#   %{+E}[capture.req.hdr(0)]    same, with the "+E" option
+#   %hr                          legacy captured-headers tag
+#
+# "+E" is the RFC5424 structured-data escaping, which only covers '"', '\' and
+# ']' (see rfc5424_escape_map): it escapes the ']' but leaves the ESC intact.
+# Only %hr, which uses hdr_encode_map, encodes the control character, as "#1B".
+#
+# The dump is read with "show events -s" so that a control character which
+# reached the ring shows up as a '?' without having to embed one in this file.
+
+haproxy h1 -conf {
+    global
+    .if feature(THREAD)
+        thread-groups 1
+    .endif
+
+    ring myring
+        size 16384
+        format raw
+
+    defaults common
+        mode http
+        timeout connect "${HAPROXY_TEST_TIMEOUT-5s}"
+        timeout client  "${HAPROXY_TEST_TIMEOUT-5s}"
+        timeout server  "${HAPROXY_TEST_TIMEOUT-5s}"
+        log ring@myring local0
+
+    frontend fe_smp from common
+        bind "fd@${fe_smp}"
+        capture request header x len 64
+        log-format "smp |%[capture.req.hdr(0)]|"
+        http-request return status 200
+
+    frontend fe_esc from common
+        bind "fd@${fe_esc}"
+        capture request header x len 64
+        log-format "esc |%{+E}[capture.req.hdr(0)]|"
+        http-request return status 200
+
+    frontend fe_hdr from common
+        bind "fd@${fe_hdr}"
+        capture request header x len 64
+        log-format "hdr |%hr|"
+        http-request return status 200
+} -start
+
+client c1 -connect ${h1_fe_smp_sock} {
+    txreq -url "/" -hdr "x: A\x1b[31m]B"
+    rxresp
+    expect resp.status == 200
+} -run
+
+client c2 -connect ${h1_fe_esc_sock} {
+    txreq -url "/" -hdr "x: A\x1b[31m]B"
+    rxresp
+    expect resp.status == 200
+} -run
+
+client c3 -connect ${h1_fe_hdr_sock} {
+    txreq -url "/" -hdr "x: A\x1b[31m]B"
+    rxresp
+    expect resp.status == 200
+} -run
+
+delay 0.2
+
+# The ESC went to the ring unmodified, hence the '?' left by "-s", and the ']'
+# was not escaped either since nothing sits between the 'm' and the ']'.
+haproxy h1 -cli {
+    send "show events myring -s"
+    expect ~ "smp \\|A\\?\\[31m\\]B\\|"
+}
+
+# "+E" inserted one character (a '\') in front of the ']', but the ESC is still
+# a control character, so "+E" is not what protects against those.
+haproxy h1 -cli {
+    send "show events myring -s"
+    expect ~ "esc \\|A\\?\\[31m.\\]B\\|"
+}
+
+# %hr encoded the ESC itself as "#1B", which is printable and therefore comes
+# out of "-s" untouched. The ']' is not part of hdr_encode_map and stays as-is.
+haproxy h1 -cli {
+    send "show events myring -s"
+    expect ~ "hdr \\|\\{A#1B\\[31m\\]B\\}\\|"
+}