From 9c06004f1b44e6f143d46ef8373569b1fb3f3d06 Mon Sep 17 00:00:00 2001 From: Walid Boudebouda Date: Fri, 11 Oct 2024 11:48:17 +0200 Subject: [PATCH 1/5] varnishncsa: Keep track of when req and beresp were received This is needed in order to differentiate between what was sent/received to/from the client/server and the changes made to [be]req/resp in VCL. It should be noted that this is the best approximation we can get as of today, as there is no reliable vsl tag to tell exactly when we have finished receiving a req/beresp, therefore we have to use vcl_recv and vcl_backend_response for now. --- bin/varnishncsa/varnishncsa.c | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/bin/varnishncsa/varnishncsa.c b/bin/varnishncsa/varnishncsa.c index 94af8374855..088089b794d 100644 --- a/bin/varnishncsa/varnishncsa.c +++ b/bin/varnishncsa/varnishncsa.c @@ -160,6 +160,7 @@ static struct ctx { const char *handling; const char *side; int64_t vxid; + int recv_compl; } CTX; static void parse_format(const char *format); @@ -971,6 +972,7 @@ dispatch_f(struct VSL_data *vsl, struct VSL_transaction * const pt[], } else continue; + CTX.recv_compl = 0; CTX.hitmiss = "-"; CTX.handling = "-"; CTX.vxid = t->vxid; @@ -1073,6 +1075,7 @@ dispatch_f(struct VSL_data *vsl, struct VSL_transaction * const pt[], break; case SLT_VCL_call: if (!strcasecmp(b, "recv")) { + CTX.recv_compl = 1; CTX.hitmiss = "-"; CTX.handling = "-"; } else if (!strcasecmp(b, "hit")) { @@ -1090,6 +1093,8 @@ dispatch_f(struct VSL_data *vsl, struct VSL_transaction * const pt[], wrong */ CTX.hitmiss = "miss"; CTX.handling = "synth"; + } else if (!strcasecmp(b, "backend_response")) { + CTX.recv_compl = 1; } break; case SLT_VCL_return: From 7b1a0e585195c8af42153e74604e14c15084292e Mon Sep 17 00:00:00 2001 From: Walid Boudebouda Date: Wed, 30 Oct 2024 10:39:12 +0100 Subject: [PATCH 2/5] varnishncsa: Change formats matching rules to better reflect reality With this change, [Be]resp/[Be]req formats should reflect better what was received/sent from/to the backend/client without taking irrelevant VCL changes into account. There is however still an exception for the changes performed by the core code before vcl_recv for req and before vcl_backend_response for beresp that cannot be distinguished from the original headers. Refs: #3528 --- bin/varnishncsa/varnishncsa.c | 89 ++++++++++++----- bin/varnishtest/tests/u00020.vtc | 163 +++++++++++++++++++++++++++++++ 2 files changed, 227 insertions(+), 25 deletions(-) create mode 100644 bin/varnishtest/tests/u00020.vtc diff --git a/bin/varnishncsa/varnishncsa.c b/bin/varnishncsa/varnishncsa.c index 088089b794d..c9c942062ed 100644 --- a/bin/varnishncsa/varnishncsa.c +++ b/bin/varnishncsa/varnishncsa.c @@ -163,8 +163,45 @@ static struct ctx { int recv_compl; } CTX; +enum format_policy { + FMTPOL_INTERNAL, + FMTPOL_REQ, + FMTPOL_RESP, +}; + static void parse_format(const char *format); +static unsigned +frag_needed(const struct fragment *frag, enum format_policy fp) +{ + unsigned is_first, want_first, want_frag; + + is_first = CTX.gen != frag->gen; + + switch (fp) { + case FMTPOL_INTERNAL: + want_first = 1; + want_frag = 1; + break; + case FMTPOL_REQ: + want_first = *CTX.side == 'c'; + want_frag = !CTX.recv_compl; + break; + case FMTPOL_RESP: + want_first = *CTX.side == 'b'; + want_frag = (*CTX.side == 'c') || !CTX.recv_compl; + break; + default: + WRONG("Invalid format policy"); + } + + if (!want_frag) + return (0); + if (want_first && !is_first) + return (0); + return (1); +} + static void openout(int append) { @@ -851,7 +888,7 @@ isprefix(const char *prefix, size_t len, const char *b, } static void -frag_fields(int force, const char *b, const char *e, ...) +frag_fields(enum format_policy fp, const char *b, const char *e, ...) { va_list ap; const char *p, *q; @@ -883,7 +920,7 @@ frag_fields(int force, const char *b, const char *e, ...) assert(p != NULL && q != NULL); if (p >= e || q <= p) continue; - if (frag->gen != CTX.gen || force) { + if (frag_needed(frag, fp)) { /* We only grab the same matching field once */ frag->gen = CTX.gen; frag->b = p; @@ -894,10 +931,11 @@ frag_fields(int force, const char *b, const char *e, ...) } static void -frag_line(int force, const char *b, const char *e, struct fragment *f) +frag_line(enum format_policy fp, const char *b, const char *e, + struct fragment *f) { - if (f->gen == CTX.gen && !force) + if (!frag_needed(f, fp)) /* We only grab the same matching record once */ return; @@ -915,7 +953,8 @@ frag_line(int force, const char *b, const char *e, struct fragment *f) } static void -process_hdr(const struct watch_head *head, const char *b, const char *e) +process_hdr(enum format_policy fp, const struct watch_head *head, const char *b, + const char *e) { struct watch *w; const char *p; @@ -924,7 +963,7 @@ process_hdr(const struct watch_head *head, const char *b, const char *e) CHECK_OBJ_NOTNULL(w, WATCH_MAGIC); if (!isprefix(w->key, w->keylen, b, e, &p)) continue; - frag_line(1, p, e, &w->frag); + frag_line(fp, p, e, &w->frag); } } @@ -943,9 +982,9 @@ process_vsl(const struct vsl_watch_head *head, enum VSL_tag_e tag, !isprefix(w->prefix, w->prefixlen, b, e, &p)) continue; if (w->idx == 0) - frag_line(0, p, e, &w->frag); + frag_line(FMTPOL_INTERNAL, p, e, &w->frag); else - frag_fields(0, p, e, w->idx, &w->frag, 0, NULL); + frag_fields(FMTPOL_INTERNAL, p, e, w->idx, &w->frag, 0, NULL); } } @@ -995,44 +1034,44 @@ dispatch_f(struct VSL_data *vsl, struct VSL_transaction * const pt[], skip = 1; break; case SLT_PipeAcct: - frag_fields(0, b, e, + frag_fields(FMTPOL_INTERNAL, b, e, 3, &CTX.frag[F_I], 4, &CTX.frag[F_O], 0, NULL); break; case SLT_BackendOpen: - frag_fields(1, b, e, + frag_fields(FMTPOL_INTERNAL, b, e, 3, &CTX.frag[F_h], 0, NULL); break; case SLT_ReqStart: - frag_fields(0, b, e, + frag_fields(FMTPOL_INTERNAL, b, e, 1, &CTX.frag[F_h], 0, NULL); break; case SLT_BereqMethod: case SLT_ReqMethod: - frag_line(0, b, e, &CTX.frag[F_m]); + frag_line(FMTPOL_REQ, b, e, &CTX.frag[F_m]); break; case SLT_BereqURL: case SLT_ReqURL: p = memchr(b, '?', e - b); if (p == NULL) p = e; - frag_line(0, b, p, &CTX.frag[F_U]); - frag_line(0, p, e, &CTX.frag[F_q]); + frag_line(FMTPOL_REQ, b, p, &CTX.frag[F_U]); + frag_line(FMTPOL_REQ, p, e, &CTX.frag[F_q]); break; case SLT_BereqProtocol: case SLT_ReqProtocol: - frag_line(0, b, e, &CTX.frag[F_H]); + frag_line(FMTPOL_REQ, b, e, &CTX.frag[F_H]); break; case SLT_BerespStatus: case SLT_RespStatus: - frag_line(1, b, e, &CTX.frag[F_s]); + frag_line(FMTPOL_RESP, b, e, &CTX.frag[F_s]); break; case SLT_BereqAcct: case SLT_ReqAcct: - frag_fields(0, b, e, + frag_fields(FMTPOL_INTERNAL, b, e, 3, &CTX.frag[F_I], 5, &CTX.frag[F_b], 6, &CTX.frag[F_O], @@ -1041,37 +1080,37 @@ dispatch_f(struct VSL_data *vsl, struct VSL_transaction * const pt[], case SLT_Timestamp: #define ISPREFIX(a, b, c, d) isprefix(a, strlen(a), b, c, d) if (ISPREFIX("Start:", b, e, &p)) { - frag_fields(0, p, e, 1, + frag_fields(FMTPOL_INTERNAL, p, e, 1, &CTX.frag[F_tstart], 0, NULL); } else if (ISPREFIX("Resp:", b, e, &p) || ISPREFIX("PipeSess:", b, e, &p) || ISPREFIX("BerespBody:", b, e, &p)) { - frag_fields(0, p, e, 1, + frag_fields(FMTPOL_INTERNAL, p, e, 1, &CTX.frag[F_tend], 0, NULL); } else if (ISPREFIX("Process:", b, e, &p) || ISPREFIX("Pipe:", b, e, &p) || ISPREFIX("Beresp:", b, e, &p)) { - frag_fields(0, p, e, 2, + frag_fields(FMTPOL_INTERNAL, p, e, 2, &CTX.frag[F_ttfb], 0, NULL); } break; case SLT_BereqHeader: case SLT_ReqHeader: - process_hdr(&CTX.watch_reqhdr, b, e); + process_hdr(FMTPOL_REQ, &CTX.watch_reqhdr, b, e); if (ISPREFIX("Authorization:", b, e, &p) && ISPREFIX("basic ", p, e, &p)) - frag_line(0, p, e, + frag_line(FMTPOL_REQ, p, e, &CTX.frag[F_auth]); else if (ISPREFIX("Host:", b, e, &p)) - frag_line(0, p, e, + frag_line(FMTPOL_REQ, p, e, &CTX.frag[F_host]); #undef ISPREFIX break; case SLT_BerespHeader: case SLT_RespHeader: - process_hdr(&CTX.watch_resphdr, b, e); + process_hdr(FMTPOL_RESP, &CTX.watch_resphdr, b, e); break; case SLT_VCL_call: if (!strcasecmp(b, "recv")) { @@ -1111,7 +1150,7 @@ dispatch_f(struct VSL_data *vsl, struct VSL_transaction * const pt[], strncmp(b, w->key, w->keylen)) continue; p = b + w->keylen; - frag_line(0, p, e, &w->frag); + frag_line(FMTPOL_INTERNAL, p, e, &w->frag); } break; default: diff --git a/bin/varnishtest/tests/u00020.vtc b/bin/varnishtest/tests/u00020.vtc new file mode 100644 index 00000000000..ade3fde25b9 --- /dev/null +++ b/bin/varnishtest/tests/u00020.vtc @@ -0,0 +1,163 @@ +varnishtest "new varnishncsa matching rules" + +# Test things we send to the backend + +server s1 { + rxreq + txresp +} -start + +varnish v1 -vcl+backend { + + sub vcl_backend_fetch { + set bereq.http.bereqhdr = "vbf-modified"; + set bereq.method = "HEAD"; + set bereq.url = "/vbf-url?q=vbfQuerry"; + set bereq.http.Authorization = "basic dmJmOnBhc3M="; + } + + sub vcl_backend_response { + set bereq.http.bereqhdr = "vbr-modified"; + set bereq.http.notsent = "notsent"; + set bereq.method = "CONNECT"; + set bereq.url = "/vbr-url?q=vbrQuerry"; + set bereq.http.Authorization = "basic dmJyOnBhc3M="; + } + +} -start + + +client c1 { + txreq -url "/client-url?q=clientQuerry" -hdr "bereqhdr: client-header" -hdr "Authorization:basic Y2xpZW50OnBhc3M=" + rxresp +} -run + +shell { + varnishncsa -n ${v1_name} -d -b -F '%H %{bereqhdr}i %{notsent}i %m %q %U %u' > ncsa_sb.txt + + cat >expected_sb.txt <<-EOF + HTTP/1.1 vbf-modified - HEAD ?q=vbfQuerry /vbf-url vbf + EOF + diff -u expected_sb.txt ncsa_sb.txt +} + +varnish v1 -stop + +# Test things we receive from the backend + +server s1 { + rxreq + txresp -status 202 -hdr "beresp: origin" +} -start + +varnish v1 -vcl+backend { + + sub vcl_backend_response { + set beresp.http.beresp = "vbr-updated"; + set beresp.status = 200; + } + +} -start + + +client c1 { + txreq + rxresp +} -run + + +shell { + varnishncsa -n ${v1_name} -d -b -F '%s %{beresp}o' > ncsa_rb.txt + + cat >expected_rb.txt <<-EOF + 202 origin + EOF + diff -u expected_rb.txt ncsa_rb.txt +} + +varnish v1 -stop + +# Test things we send to the client + +server s1 { + rxreq + txresp -status 202 -hdr "resp: origin" +} -start + +varnish v1 -vcl+backend { + + sub vcl_backend_response { + set beresp.http.resp = "vbr-updated"; + set beresp.status = 200; + } + + sub vcl_deliver { + set resp.http.resp = "deliver-updated"; + set resp.status = 201; + set resp.http.added = "deliver"; + } + +} -start + + +client c1 { + txreq + rxresp +} -run + +shell { + varnishncsa -n ${v1_name} -d -c -F '%s %{resp}o %{added}o' > ncsa_sc.txt + + cat >expected_sc.txt <<-EOF + 201 deliver-updated deliver + EOF + diff -u expected_sc.txt ncsa_sc.txt +} + +varnish v1 -stop + +# Test things we receive from the client + +server s1 { + rxreq + txresp +} -start + +varnish v1 -vcl+backend { + + sub vcl_recv { + set req.http.reqhdr = "recv-modified"; + set req.method = "HEAD"; + set req.url = "/recv-url?q=recvQuerry"; + set req.http.Authorization = "basic cmVjdjpwYXNz"; + set req.http.notreceived = "recv"; + } + + sub vcl_hash { + set req.http.reqhdr = "hash-modified"; + set req.method = "GET"; + set req.url = "/hash-url?q=hashQuerry"; + set req.http.Authorization = "basic aGFzaDpwYXNz"; + set req.http.notreceived = "hash"; + } + +} -start + + +client c1 { + txreq -req "POST" -url "/client-url?q=clientQuerry" \ + -hdr "reqhdr: client-header" \ + -hdr "Authorization:basic Y2xpZW50OnBhc3M=" + rxresp +} -run + + +shell { + varnishncsa -n ${v1_name} -d -c -F '%H %{reqhdr}i %{notreceived}i %m %q %U %u' > ncsa_rc.txt + + cat >expected_rc.txt <<-EOF + HTTP/1.1 client-header - POST ?q=clientQuerry /client-url client + EOF + diff -u expected_rc.txt ncsa_rc.txt +} +# TODO: Handle Unset From 0359cee7b36c49b18580ca46788bffa459650f73 Mon Sep 17 00:00:00 2001 From: Walid Boudebouda Date: Fri, 8 Nov 2024 11:03:10 +0100 Subject: [PATCH 3/5] varnishncsa: Make frag_line() smarter --- bin/varnishncsa/varnishncsa.c | 3 +++ 1 file changed, 3 insertions(+) diff --git a/bin/varnishncsa/varnishncsa.c b/bin/varnishncsa/varnishncsa.c index c9c942062ed..496e37a0495 100644 --- a/bin/varnishncsa/varnishncsa.c +++ b/bin/varnishncsa/varnishncsa.c @@ -939,6 +939,9 @@ frag_line(enum format_policy fp, const char *b, const char *e, /* We only grab the same matching record once */ return; + if (e == NULL) + e = b + strlen(b); + /* Skip leading space */ while (b < e && isspace(*b)) ++b; From b57dd5b66417c6a41ba893c2e558b35919e62c71 Mon Sep 17 00:00:00 2001 From: Walid Boudebouda Date: Fri, 11 Oct 2024 17:54:46 +0200 Subject: [PATCH 4/5] varnishncsa: Take [BE]{Req,Resp}Unset into account Fixes: #3528 --- bin/varnishncsa/varnishncsa.c | 21 +++++++++++++++++---- bin/varnishtest/tests/u00020.vtc | 31 ++++++++++++++++++------------- 2 files changed, 35 insertions(+), 17 deletions(-) diff --git a/bin/varnishncsa/varnishncsa.c b/bin/varnishncsa/varnishncsa.c index 496e37a0495..15e5eb09858 100644 --- a/bin/varnishncsa/varnishncsa.c +++ b/bin/varnishncsa/varnishncsa.c @@ -957,7 +957,7 @@ frag_line(enum format_policy fp, const char *b, const char *e, static void process_hdr(enum format_policy fp, const struct watch_head *head, const char *b, - const char *e) + const char *e, int unset) { struct watch *w; const char *p; @@ -966,7 +966,12 @@ process_hdr(enum format_policy fp, const struct watch_head *head, const char *b, CHECK_OBJ_NOTNULL(w, WATCH_MAGIC); if (!isprefix(w->key, w->keylen, b, e, &p)) continue; - frag_line(fp, p, e, &w->frag); + if (unset) { + frag_line(fp, CTX.missing_string, + NULL, + &w->frag); + } else + frag_line(fp, p, e, &w->frag); } } @@ -1101,7 +1106,7 @@ dispatch_f(struct VSL_data *vsl, struct VSL_transaction * const pt[], break; case SLT_BereqHeader: case SLT_ReqHeader: - process_hdr(FMTPOL_REQ, &CTX.watch_reqhdr, b, e); + process_hdr(FMTPOL_REQ, &CTX.watch_reqhdr, b, e, 0); if (ISPREFIX("Authorization:", b, e, &p) && ISPREFIX("basic ", p, e, &p)) frag_line(FMTPOL_REQ, p, e, @@ -1113,7 +1118,15 @@ dispatch_f(struct VSL_data *vsl, struct VSL_transaction * const pt[], break; case SLT_BerespHeader: case SLT_RespHeader: - process_hdr(FMTPOL_RESP, &CTX.watch_resphdr, b, e); + process_hdr(FMTPOL_RESP, &CTX.watch_resphdr, b, e, 0); + break; + case SLT_BereqUnset: + case SLT_ReqUnset: + process_hdr(FMTPOL_REQ, &CTX.watch_reqhdr, b, e, 1); + break; + case SLT_BerespUnset: + case SLT_RespUnset: + process_hdr(FMTPOL_RESP, &CTX.watch_resphdr, b, e, 1); break; case SLT_VCL_call: if (!strcasecmp(b, "recv")) { diff --git a/bin/varnishtest/tests/u00020.vtc b/bin/varnishtest/tests/u00020.vtc index ade3fde25b9..84a8c71c3a4 100644 --- a/bin/varnishtest/tests/u00020.vtc +++ b/bin/varnishtest/tests/u00020.vtc @@ -14,11 +14,13 @@ varnish v1 -vcl+backend { set bereq.method = "HEAD"; set bereq.url = "/vbf-url?q=vbfQuerry"; set bereq.http.Authorization = "basic dmJmOnBhc3M="; + unset bereq.http.unset; } sub vcl_backend_response { set bereq.http.bereqhdr = "vbr-modified"; set bereq.http.notsent = "notsent"; + set bereq.http.unset = "toolate"; set bereq.method = "CONNECT"; set bereq.url = "/vbr-url?q=vbrQuerry"; set bereq.http.Authorization = "basic dmJyOnBhc3M="; @@ -28,15 +30,15 @@ varnish v1 -vcl+backend { client c1 { - txreq -url "/client-url?q=clientQuerry" -hdr "bereqhdr: client-header" -hdr "Authorization:basic Y2xpZW50OnBhc3M=" + txreq -url "/client-url?q=clientQuerry" -hdr "bereqhdr: client-header" -hdr "unset: client" -hdr "Authorization:basic Y2xpZW50OnBhc3M=" rxresp } -run shell { - varnishncsa -n ${v1_name} -d -b -F '%H %{bereqhdr}i %{notsent}i %m %q %U %u' > ncsa_sb.txt + varnishncsa -n ${v1_name} -d -b -F '%H %{bereqhdr}i %{notsent}i %{unset}i %m %q %U %u' > ncsa_sb.txt cat >expected_sb.txt <<-EOF - HTTP/1.1 vbf-modified - HEAD ?q=vbfQuerry /vbf-url vbf + HTTP/1.1 vbf-modified - - HEAD ?q=vbfQuerry /vbf-url vbf EOF diff -u expected_sb.txt ncsa_sb.txt } @@ -47,7 +49,7 @@ varnish v1 -stop server s1 { rxreq - txresp -status 202 -hdr "beresp: origin" + txresp -status 202 -hdr "beresp: origin" -hdr "unset: origin" } -start varnish v1 -vcl+backend { @@ -55,6 +57,7 @@ varnish v1 -vcl+backend { sub vcl_backend_response { set beresp.http.beresp = "vbr-updated"; set beresp.status = 200; + unset beresp.http.unset; } } -start @@ -67,10 +70,10 @@ client c1 { shell { - varnishncsa -n ${v1_name} -d -b -F '%s %{beresp}o' > ncsa_rb.txt + varnishncsa -n ${v1_name} -d -b -F '%s %{beresp}o %{unset}o' > ncsa_rb.txt cat >expected_rb.txt <<-EOF - 202 origin + 202 origin origin EOF diff -u expected_rb.txt ncsa_rb.txt } @@ -81,7 +84,7 @@ varnish v1 -stop server s1 { rxreq - txresp -status 202 -hdr "resp: origin" + txresp -status 202 -hdr "resp: origin" -hdr "unset: origin" } -start varnish v1 -vcl+backend { @@ -95,6 +98,7 @@ varnish v1 -vcl+backend { set resp.http.resp = "deliver-updated"; set resp.status = 201; set resp.http.added = "deliver"; + unset resp.http.unset; } } -start @@ -106,10 +110,10 @@ client c1 { } -run shell { - varnishncsa -n ${v1_name} -d -c -F '%s %{resp}o %{added}o' > ncsa_sc.txt + varnishncsa -n ${v1_name} -d -c -F '%s %{resp}o %{unset}o %{added}o' > ncsa_sc.txt cat >expected_sc.txt <<-EOF - 201 deliver-updated deliver + 201 deliver-updated - deliver EOF diff -u expected_sc.txt ncsa_sc.txt } @@ -131,6 +135,7 @@ varnish v1 -vcl+backend { set req.url = "/recv-url?q=recvQuerry"; set req.http.Authorization = "basic cmVjdjpwYXNz"; set req.http.notreceived = "recv"; + unset req.http.unset; } sub vcl_hash { @@ -147,17 +152,17 @@ varnish v1 -vcl+backend { client c1 { txreq -req "POST" -url "/client-url?q=clientQuerry" \ -hdr "reqhdr: client-header" \ - -hdr "Authorization:basic Y2xpZW50OnBhc3M=" + -hdr "Authorization:basic Y2xpZW50OnBhc3M=" \ + -hdr "unset: client" rxresp } -run shell { - varnishncsa -n ${v1_name} -d -c -F '%H %{reqhdr}i %{notreceived}i %m %q %U %u' > ncsa_rc.txt + varnishncsa -n ${v1_name} -d -c -F '%H %{reqhdr}i %{notreceived}i %{unset}i %m %q %U %u' > ncsa_rc.txt cat >expected_rc.txt <<-EOF - HTTP/1.1 client-header - POST ?q=clientQuerry /client-url client + HTTP/1.1 client-header - client POST ?q=clientQuerry /client-url client EOF diff -u expected_rc.txt ncsa_rc.txt } -# TODO: Handle Unset From 5f515fb9378a8d4cd96c2c2663d0884d3003dfb7 Mon Sep 17 00:00:00 2001 From: Walid Boudebouda Date: Wed, 22 Jan 2025 11:50:38 +0100 Subject: [PATCH 5/5] varnishncsa: Document the new behavior of #4213 --- doc/sphinx/reference/varnishncsa.rst | 22 ++++++++++++++++++---- 1 file changed, 18 insertions(+), 4 deletions(-) diff --git a/doc/sphinx/reference/varnishncsa.rst b/doc/sphinx/reference/varnishncsa.rst index 6375f72887d..f734a361473 100644 --- a/doc/sphinx/reference/varnishncsa.rst +++ b/doc/sphinx/reference/varnishncsa.rst @@ -106,7 +106,8 @@ Supported formatters are: %{X}i The contents of request header X. If the header appears multiple times - in a single transaction, the last occurrence is used. + in a single transaction, the last occurrence is used in backend mode + and the first one in client mode. %l Remote logname. Always '-'. @@ -116,7 +117,8 @@ Supported formatters are: %{X}o The contents of response header X. If the header appears multiple - times in a single transaction, the last occurrence is used. + times in a single transaction, the last occurrence is used in client + mode and the first one in backend mode. %O In client mode, total bytes sent to client. In backend mode, total @@ -239,8 +241,20 @@ NOTES The %r formatter is equivalent to ``%m http://%{Host}i%U%q %H``. This differs from apache's %r behavior, equivalent to "%m %U%q %H". -Furthermore, when using the %r formatter, if the Host header appears -multiple times in a single transaction, the first occurrence is used. + +Note that request fields are collected on a first match basis in client mode +and last match basis in backend mode. Similarly, response fields are collected +on a first match basis in backend mode and last match basis in client mode. + +In other words, this means that requests are represented as they were received +from the client and as they were sent to the backend, while responses are +represented as they were sent to the client and as they were received from +the backend. + +Furthermore, these rules also apply for items that appear multiple times in a +transaction. For exampe, if a header appears multiple times in a client request, +the first occurence would be shown in client mode, while the last one would be +used in backend mode. EXAMPLE =======