%{VSL:...}x formats are hard to use and not well documented

[rfc1036]

Expected Behavior

varnishncsa(1) documents that the %{VSL:tag:prefix[field]}x format can be used to extract specific fields from the VSL.

Current Behavior

I am unable to extract specific fields from VCL "TTL" tags. I wonder if this is caused by "TTL" not being "followed by a colon". But I am not sure of which VSL tags actually have prefixes followed by a colon, so it is not obvious to me when this functionality can be used. %{VSL:TTL[2]}x works, while %{VSL:TTL:RFC[2]}x does not.

Also, TTL tags may start with "VCL" instead of "RFC", but I never see the first ones logged.

Another related issue is that %{VSL:TTL}x only works in backend mode, while generally logging is enabled only for client mode. I have partially solved my use case by using %{VSL:Hit[2]}x instead in client mode, but it only works for cache hits.

Possible Solution

No response

Steps to Reproduce (for bugs)

varnishncsa -b -F '%{VCL_Log:ip}x %l %u %t "%r" %s %b "%{Referer}i" "%{User-agent}i" handling=%{Varnish:handling}x ttl=%{VSL:TTL:RFC[2]}x:%{VSL:TTL}x'

Will output lines like:

 - - [05/Oct/2025:01:58:49 +0200] "GET ... HTTP/1.1" 200 27189 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/114.0.0.0 Safari/537.36 Edg/114.0.1264.71" handling=- ttl=-:RFC 172800 10 0 1759622330 1759622330 1759622329 1759795129 172800 cacheable

This line shows that the TTL VSL tag is found, but it is not possible to extract a field.

Context

I am trying to augment the standard logs with information about when responses are coming from the cache or not and what is their TTL.

Varnish Cache version

varnishncsa (varnish-7.1.1 revision 7cee1c581bead20e88d101ab3d72afb29f14d87a)

Operating system

Debian 12

Source of binary packages used (if any)

http://deb.debian.org/

[walid-git]

I wonder if this is caused by "TTL" not being "followed by a colon".

Yes, your assumption is correct, and is even documented in the man page:

VSL:tag:record-prefix[field] .... The record prefix will limit the matches to those records that have this prefix as the first part of the record content fol‐ lowed by a colon.

Also, TTL tags may start with "VCL" instead of "RFC", but I never see the first ones logged.

TTL VCL ... appears when the TTL is set by your vcl (ex: set beresp.ttl = 30s), while TTL RFC .. is the TTL that varnish sets based on your backend response headers before any vcl processing.

In your case, if you're only interested in the RFC TTL, then I think that you can simply use VSL:TTL[2], as that would result in the same thing because TTL RFC logs always appear first before any other TTL tags, and since %{VSL:...}x returns the first match, you should always get it. Otherwise, it would be preferable to use std.log to log beresp.ttl at the end of vcl_backend_response and then capture it with %{VCL_Log:key}x.

[nigoroll]

See also 2a5345de14efee39838f87c57908fe10d02decc2: I would think we should either add the colon to all the "qualifyer" prefixes, or remove the check for colon

[nigoroll]

bugwash: match for either colon or space after the prefix

[walid-git]

@rfc1036 feel free to give https://github.com/varnishcache/varnish-cache/pull/4405 a try.