VARNISHNCSA(1)

💅 VARNISHNCSA 💅

okay bestie, buckle up, we're reading a manpage from the General Commands Manual section and it's literally varnishncsa — the girlies who make Varnish logs look like Apache logs. she's iconic, she's useful, she's giving log-format main character energy. let's go 🎀

---

✨ NAME ✨

varnishncsa — Display Varnish logs in Apache / NCSA combined log format

---

🌸 SYNOPSIS 🌸

varnishncsa [-a] [-b] [-c] [-C] [-d] [-D] [-E] [-F <format>] [-f
<formatfile>] [-g <request|vxid>] [-h] [-j] [-k <num>] [-L <limit>] [-n
<workdir>] [-P <file>] [-Q <file>] [-q <query>] [-r <filename>] [-R
<limit[/duration]>] [-t <seconds|off>] [-V] [-w <filename>]

---

👑 DESCRIPTION 👑

so the varnishncsa utility reads varnishd(1) shared memory logs and serves them to you in the Apache / NCSA "combined" log format. it's giving "I want my Varnish logs to look like nginx but make it Apache" and honestly? valid.

every log line she produces is based on a single Request type transaction gathered from the shared memory log. then that Request transaction gets scanned for the relevant parts so she can output one (1) log line. if you want to filter which log lines show up, use the query language to select the applicable transactions. non-request transactions? ignored. not her problem. 💅

the following options are available, and yes, we're doing all of them, no skipping:

• -a — when you're writing output to a file, this makes it append instead of overwriting. heads up: this option does absolutely nothing without -w. no -w, no vibes.
• -b — log backend requests. if -c is not specified, then only backend requests will trigger log lines. backend-only era.
• -c — log client requests. this is the default, she's the baseline. if -b is specified, then you need -c to also log client requests.
• -C — do all regular expression and string matching caseless. uppercase girls, lowercase girls, same thing here.
• -d — process log records at the head of the log and exit. she dips immediately after.
• -D — daemonize. bye bestie, you're a background process now.
• -E — show ESI requests, implies client mode.
• -F <format> — set the output log format string.
• -f <formatfile> — read output format from a file. she'll read a single line from the specified file, and use that line as the format. one line, that's it.
• -g <request|vxid> — the grouping of the log records. the default is to group by vxid.
• -h — print program usage and exit. help me help you.
• -j — make format-specifier replacements JSON-compatible. when escaping characters, use JSON-style \uXXXX escape sequences instead of C-style \xXX sequences. empty strings get replaced with "" instead of "-", and empty integers get replaced with null. use -F or -f in combination with -j to write JSON logs.
• -k <num> — process this number of matching log transactions before exiting.
• -L <limit> — sets the upper limit of incomplete transactions kept before the oldest transaction is force completed. a warning record is synthesized when this happens. this setting keeps an upper bound on the memory usage of running queries. defaults to 1000 transactions.
• -n <workdir> — specify the varnish working directory of the instance to attach to. see varnishd(1) -n option documentation for additional information and defaults.
• -P <file> — write the process' PID to the specified file.
• -Q <file> — specifies the file containing the VSL query to use. when multiple -Q or -q options are specified, all queries are considered as if the 'or' operator was used to combine them.
• -q <query> — specifies the VSL query to use. when multiple -q or -Q options are specified, all queries are considered as if the 'or' operator was used to combine them. (yes, same energy as -Q, just inline instead of from a file 🫶)
• -r <filename> — read log in binary file format from this file. the file can be created with varnishlog -w filename. if the filename is -, logs are read from the standard input. and cannot work as a daemon.
• -R <limit[/duration]> — restrict the output to the specified limit. transactions exceeding the limit will be suppressed. the limit is specified as the maximum number of transactions (with respect to the chosen grouping method) and an optional time period. if no duration is specified, a default of s is used. the duration field can be formatted as in VCL (e.g. -R 10/2m) or as a simple time period without the prefix (e.g. -R 5/m). when in -g raw grouping mode, this setting can not be used alongside -i, -I, -x or -X, and we advise using -q instead.
• -t <seconds|off> — timeout before returning error on initial VSM connection. if set, the VSM connection is retried every 0.5 seconds for this many seconds. if zero, the connection is attempted only once and will fail immediately if unsuccessful. if set to "off", the connection will not fail, allowing the utility to start and wait indefinitely for the Varnish instance to appear. defaults to 5 seconds.
• -V — print version information and exit.
• -w <filename> — redirect output to file. the file will be overwritten unless the -a option was specified. if the application receives a SIGHUP in daemon mode the file will be reopened allowing the old one to be rotated away. this option is required when running in daemon mode. if the filename is -, varnishncsa writes to the standard output and cannot work as a daemon.
• --optstring — print the optstring parameter to getopt(3) to help writing wrapper scripts. for the script girlies 🧚

---

🌈 MODES 🌈

the default mode of varnishncsa is "client mode". in this mode, the log will be similar to what a web server would produce in the absence of varnish. client mode can be explicitly selected by using -c.

if the -b switch is specified, varnishncsa will operate in "backend mode". in this mode, requests generated by varnish to the backends will be logged. unless -c is also specified, client requests received by varnish will be ignored. rude? a little. intentional? yes.

when running varnishncsa in both backend and client mode, it is strongly advised to include the format specifier %{Varnish:side}x to distinguish between backend and client requests. do not skip this, bestie, you will simply not know who's who.

client requests that results in a pipe (ie. return(pipe) in vcl), will not generate logging in backend mode. this is because varnish is not generating requests, but blindly passes on bytes in both directions. however, a varnishncsa instance running in normal mode can see this case by using the formatter %{Varnish:handling}x, which will be 'pipe'. 👀

in backend mode, some of the fields in the format string get different meanings. most notably, the byte counting formatters (%b, %I, %O) considers varnish to be the client. yes, the roles flip. it's giving plot twist.

it is possible to keep two varnishncsa instances running, one in backend mode, and one in client mode, logging to different files. twin flames fr fr 🫶

💅 FORMAT 💅

So bestie, this is where you tell varnishncsa what to actually write down. If you don't specify a format, it just uses the default one, which is:

%h %l %u %t "%r" %s %b "%{Referer}i" "%{User-agent}i"

Escape sequences \n and \t? Yeah, those work. Use them. Live your life. ✨

Now the main character list — every formatter that's supported:

• %b — In client mode, this is the size of the response in bytes, HTTP headers not included. In backend mode, it's how many bytes we got back from the backend, headers again excluded. And in CLF format it does the cute thing where it prints a '-' instead of a 0 when nothing was sent. 💀
• %D — In client mode: how long it took to serve the request, in microseconds. In backend mode: the time from when the request was sent until the entire body had been received. Same thing as %{us}T, basically.
• %H — The request protocol. If we don't know it, it defaults to HTTP/1.0. 🤷
• %h — Remote host. Defaults to '-' if we don't know it. In backend mode this is the IP of the backend server. 👀
• %I — In client mode: total bytes received from the client. In backend mode: total bytes sent to the backend. Flip-flop energy but okay.
• %{X[:first|last]}i — The contents of request header X, before any VCL processing on the client side, and before vcl_backend_response on the backend side. If that header shows up multiple times in one transaction, the last occurrence is used in backend mode and the first one in client mode. 👑
  • If you add the optional :first or :last, VCL processing is taken into account, and the matching rule becomes first match or last match respectively. When you use :last, headers that were unset still get captured.
• %l — Remote logname. It is always '-'. That's it. That's the whole job. 🎀
• %m — Request method. Defaults to '-' if we don't know it.
• %{X[:first|last]}o — The contents of response header X, as it was delivered in client mode, and before VCL processing in backend mode. If the header appears multiple times in a single transaction, the last occurrence is used in client mode and the first one in backend mode. (Yes, it's the mirror of the request one, slay.) ✨
  • If you add the optional :first or :last, VCL processing will be taken into account, and the matching rule becomes first match or last match respectively. When using :last, unset headers will still be captured.
• %O — In client mode: total bytes sent to the client. In backend mode: total bytes received from the backend.
• %q — The query string. Defaults to an empty string if it's not there. 🌸
• %r — The first line of the request. It's synthesized from other fields, so ngl it might not be the request verbatim. Go read the NOTES section for the tea. ☕
• %s — Status sent to the client. In backend mode, the status received from the backend.
• %t — In client mode: the time the request was received, in HTTP date/time format. In backend mode: the time the request was sent.
• %{X}t — In client mode: the time the request was received, in the format X specifies. In backend mode: the time the request was sent. The time spec format is the same as strftime(3), with these extra little extensions:
  • %{sec}: number of seconds since the Epoch
  • %{msec}: number of milliseconds since the Epoch
  • %{usec}: number of milliseconds since the Epoch
  • %{msec_frac}: millisecond fraction
  • %{usec_frac}: microsecond fraction

Okay so these extensions cannot be combined with each other or with strftime(3) inside the same specification. Use multiple %{X}t specifications instead. Fr fr, don't try to be cute about it. 🙈

• %T — In client mode: time taken to serve the request, in seconds. In backend mode: time from when the request was sent until the entire body had been received. Equivalent to %{s}T.
• %{X}T — In client mode: time taken to serve the request, in the format X specifies. In backend mode: time from when the request was sent until the entire body had been received. The time specification format can be one of: s (same as %T), or ms or us (same as %D).
• %U — The request URL without the query string. Defaults to '-' if we don't know it.
• %u — Remote user from auth.
• %{X}x — Extended variables. The supported ones are:
  • Varnish:default_format — The log format used when neither the -f nor -F options are specified. Handy for appending/prepending with other formatters. 🫶
  • Varnish:time_firstbyte — Time from when request processing starts until the first byte is sent to the client, in seconds. For backend mode: time from when the request was sent to the backend until the entire header had been received.
  • Varnish:hitmiss — In client mode, one of the 'hit' or 'miss' strings, depending on whether the request was a cache hit or a miss. Pipe, pass and synth all count as misses. In backend mode, this field is blank. 😶
  • Varnish:handling — In client mode, one of the 'hit', 'hitmiss', 'hitpass', 'miss', 'pass', 'pipe' or 'synth' strings, showing how the request was handled. In backend mode, this field is blank.
  • Varnish:side — Backend or client side. One of two values, 'b' or 'c', depending on where the request was made. In pure backend or client mode, this field will be constant.
  • Varnish:vxid — The VXID of the varnish transaction. 👑
  • VCL_Log:key — The value set by std.log("key:value") in VCL.
  • VSL:tag:record-prefix[field] — The value of the VSL entry for the given tag-record prefix-field combination. Tag is mandatory, the other components are optional.
    • The record prefix limits matches to those records that have this prefix as the first part of the record content, followed by a colon.
    • The field, if present, treats the log record as a white space separated list of fields, and only the *n*th part of the record gets matched against. Fields start counting at 1 and run up to 255.
    • Defaults to '-' when the tag isn't seen, the record prefix doesn't match, or the field is out of bounds. If a tag appears multiple times in a single transaction, the first occurrence is used.

---

🚨 SIGNALS 🚨

• SIGHUP — Rotate the log file (peep the -w option) in daemon mode, abort the loop, and die gracefully when running in the foreground. Dramatic exit, honestly iconic. 💅
• SIGUSR1 — Flush any outstanding transactions. Get that data out the door. 🚪

---

📝 NOTES 📝

The %r formatter is equivalent to %m http://%{Host}i%U%q %H. That is different from the Apache HTTP Server %r behavior, which is equivalent to %m %U%q %H. Don't get it twisted. 💀

Also note that request fields are collected on a first match basis in client mode and a last match basis in backend mode. Similarly, response fields are collected on a first match basis in backend mode and a last match basis in client mode. Yes, they're opposites. It's giving mirror universe. 🪞

In other words: request headers are logged as they were received from the client and as they were sent to the backend, while response headers are logged as they were sent to the client and as they were received from the backend.

And furthermore, these rules also apply to items that appear multiple times in a transaction. For example, if a header appears multiple times in a client request, the first occurrence is logged in client mode, while in backend mode the last occurrence is logged.

Prior to 7.7, the formats %{X}i and %{X}o used to include header fields populated from VCL. Consider %{VCL_Log:key}x instead to capture data from VCL transactions. 📌

---

🌈 EXAMPLE 🌈

Log the second field of the Begin record, corresponding to the VXID of the parent transaction:

varnishncsa -F "%{VSL:Begin[2]}x"

Log the entire Timestamp record associated with the processing length:

varnishncsa -F "%{VSL:Timestamp:Process}x"

Log in JSON, using the -j flag to make sure the output is valid JSON for all inputs:

varnishncsa -j -F '{"size": %b, "time": "%t", "ua": "%{User-Agent}i"}'

Log the first and last values of a request header that is modified multiple times in VCL:

varnishncsa -F "%{x-custom-header:first}i %{x-custom-header:last}i"

---

👀 SEE ALSO 👀

varnishd(1) varnishlog(1) varnishstat(1) vsl-query(7) vsl(7)

---

📜 HISTORY 📜

The varnishncsa utility was developed by Poul-Henning Kamp in cooperation with Verdens Gang AS and Varnish Software AS. This manual page was initially written by Dag-Erling Smørgrav < <des@des.no> >, and later updated by Martin Blix Grydeland and Pål Hermunn Johansen. Shoutout to the whole squad, honestly. 🫶

---

⚖️ COPYRIGHT ⚖️

This document is licensed under the same licence as Varnish itself. See LICENCE for details.

• Copyright (c) 2006 Verdens Gang AS
• Copyright (c) 2006-2016 Varnish Software AS

---

and that's the whole page bestie!! 💖 this was VARNISHNCSA(1), go forth and log responsibly, mwah 🎀✨