varnishncsa logs header values even if they have in fact been unset

[yched]

(Maybe somewhat related to #3527 ?)

In VCL :

set resp.http.X-My-Header = "not-actually-sent";
unset resp.http.X-My-Header;

Expected behavior :
varnishncsa -f "%{X-My-Header}o" --> nothing

Current behavior :
varnishncsa -f "%{X-My-Header}o" --> "not-actually-sent"

We use varnishncsa to collect request logs in ELK, it is impossible to distinguish requests where the header was present from those where it was actually unset before sending the response

[nigoroll]

notes from bugwash

• (15:06:02) phk: so maybe first step is to formulate that strategy and put it in the man-page ?
• (15:04:12) dridi: we should proceed carefully
• ^^^ sounds like we need different formatter options?
• (15:11:21) dridi: so we have 3 cases? (edit: first) match, last match, follow unset
• (15:11:57) martin: and document that last match is the default?

[dridi]

Bugwash redux:

• some patterns are first match, some are last match
• none of the patterns take unset into account
• we need to survey and document how each pattern behaves
• and then decide how to handle unset (new pattern? compat mode? TBD)

[bsdphk]

This ticket is not actionable at this point, moved to VIP status: https://github.com/varnishcache/varnish-cache/wiki/VIP32:-VSL-API-and-Unset-headers

[yched]

@bsdphk any hope for seeing this move forward ?

We get regularly bitten by this, where our varnishncsa-based trafic logs report a resp header as being present when it was in fact unset before the resp is delivered. Makes some very puzzling debugging moments ("I didn't receive the header" / "well, our logs say we did send it"), until you remember "ah right, it's because varnishncsa doesn't see unsets"

[dridi]

@walid-git will first survey varnishncsa format patterns and list the ones that are first- or last-match so we can assess the current situation.

[dridi]

Apologies, it took a long time, but we finally have both an inventory of how formats are currently collected and a proposal for better handling.

Let's start with the inventory:

Last match

• %{X}i
• %{X}o
• %s
• %h in -b mode

First match

• %b
• %D
• %H
• %h in -c mode (ReqStart)
• %I
• %m
• %O
• %q
• %t
• %T
• %u
• %U
• %{X}x

We looked at the meaning of the various formats and derived three categories. You may notice that some formats are missing from the lists above, they are either variations on the same format (like %{X}t) or neither a first nor last match, so there's a fourth category.

Here goes the proposal:

What we receive from a peer

Client rule: first match before vcl_recv.
Backend rule: first match before vcl_backend_response.

• %H in -c mode
• %{X}i in -c mode
• %m in -c mode
• %{X}o in -b mode
• %q in -c mode
• %s in -b mode
• %U in -c mode
• %u in -c mode

What we send to a peer

Client rule: last match.
Backend rule: last match before vcl_backend_response.
Common rule: evaluate unset.

• %H in -b mode
• %{X}i in -b mode
• %m in -b mode
• %{X}o in -c mode
• %q in -b mode
• %s in -c mode
• %U in -b mode
• %u in -b mode

What happens inside Varnish

Rule: first match. In many cases it should be synonymous to the only match.

• %b
• %D
• %h
• %I
• %O
• %t, %{X}t
• %T, %{X}T
• %{Varnish:handling}x
• %{Varnish:hitmiss}x
• %{Varnish:side}x
• %{Varnish:time_firstbyte}x
• %{Varnish:vxid}x
• %{VCL_Log:key}x
• %{VSL:tag:record-prefix[field]}x

Other

• %l (not evaluated)
• %r (synthesized, with a documented caveat that could be fixed with the rules above)
• %{Varnish:default_format}x (substituted before evaluation)

With these categories, we would mostly maintain the current behavior, and improve formats from the first two categories (the same formats, but from opposite sides).

[nigoroll]

I have not reviewed the formats in detail, but I agree to the overall concept first for "receive" and last for "send".

[nigoroll]

bugwash is in agreement with dridis proposal, @walid-git volunteered to have a go at a PR - thank you

[walid-git]

#4213