1VSL(7) VSL(7)
2
6 VSL - Varnish Shared Memory Logging
7
9 This document describes the format and content of all the Varnish
10 shared memory logging tags. These tags are used by the varnishlog(1),
11 varnishtop(1), etc. logging tools supplied with Varnish.
12 VSL tags
14 Backend - Backend selected
15 Logged when a connection is selected for handling a backend re‐
16 quest.
17 The format is:
19 %d %s %s
21 | | |
22 | | +- Backend display name
23 | +---- VCL name
24 +------- Connection file descriptor
25 NOTE: This tag is currently not in use in the Varnish log. It
27 is mentioned here to document legacy versions of the log, or re‐
28 served for possible use in future versions.
29 BackendClose - Backend connection closed
31 Logged when a backend connection is closed.
32 The format is:
34 %d %s %s [ %s ]
36 | | | |
37 | | | +- Optional reason
38 | | +------ "close" or "recycle"
39 | +--------- Backend display name
40 +------------ Connection file descriptor
41 BackendOpen - Backend connection opened
43 Logged when a new backend connection is opened.
44 The format is:
46 %d %s %s %s %s %s %s
48 | | | | | | |
49 | | | | | | +- "connect" or "reuse"
50 | | | | | +---- Local port
51 | | | | +------- Local address
52 | | | +---------- Remote port
53 | | +------------- Remote address
54 | +---------------- Backend display name
55 +------------------- Connection file descriptor
56 BackendReuse - Backend connection put up for reuse
58 Logged when a backend connection is put up for reuse by a later
59 connection.
60 The format is:
62 %d %s
64 | |
65 | +- Backend display name
66 +---- Connection file descriptor
67 NOTE: This tag is currently not in use in the Varnish log. It
69 is mentioned here to document legacy versions of the log, or re‐
70 served for possible use in future versions.
71 BackendStart - Backend request start
73 Start of backend processing. Logs the backend IP address and
74 port number.
75 The format is:
77 %s %s
79 | |
80 | +- Backend Port number
81 +---- Backend IP4/6 address
82 NOTE: This tag is currently not in use in the Varnish log. It
84 is mentioned here to document legacy versions of the log, or re‐
85 served for possible use in future versions.
86 Backend_health - Backend health check
88 The result of a backend health probe.
89 The format is:
91 %s %s %s %s %u %u %u %f %f %s
93 | | | | | | | | | |
94 | | | | | | | | | +- Probe HTTP response / error information
95 | | | | | | | | +---- Average response time
96 | | | | | | | +------- Response time
97 | | | | | | +---------- Probe window size
98 | | | | | +------------- Probe threshold level
99 | | | | +---------------- Number of good probes in window
100 | | | +------------------- Probe window bits
101 | | +---------------------- "healthy" or "sick"
102 | +------------------------- "Back", "Still" or "Went"
103 +---------------------------- Backend name
104 Probe window bits are:
106 '-': Could not connect
108 '4': Good IPv4
109 '6': Good IPv6
110 'U': Good UNIX
111 'x': Error Xmit
112 'X': Good Xmit
113 'r': Error Recv
114 'R': Good Recv
115 'H': Happy
116 When the backend is just created, the window bits for health
118 check slots that haven't run yet appear as '-' like failures to
119 connect.
120 Begin - Marks the start of a VXID
122 The first record of a VXID transaction.
123 The format is:
125 %s %d %s
127 | | |
128 | | +- Reason
129 | +---- Parent vxid
130 +------- Type ("sess", "req" or "bereq")
131 BereqAcct - Backend request accounting
133 Contains byte counters from backend request processing.
134 The format is:
136 %d %d %d %d %d %d
138 | | | | | |
139 | | | | | +- Total bytes received
140 | | | | +---- Body bytes received
141 | | | +------- Header bytes received
142 | | +---------- Total bytes transmitted
143 | +------------- Body bytes transmitted
144 +---------------- Header bytes transmitted
145 BereqHeader - Backend request header
147 HTTP header contents.
148 The format is:
150 %s: %s
152 | |
153 | +- Header value
154 +----- Header name
155 NOTE: HTTP header fields are free form records and not strictly
157 made of 2 fields. Accessing a specific header with the prefix
158 notation helps treating the header value as a single string.
159 BereqMethod - Backend request method
161 The HTTP request method used.
162 BereqProtocol - Backend request protocol
164 The HTTP protocol version information.
165 BereqURL - Backend request URL
167 The HTTP request URL.
168 BerespHeader - Backend response header
170 HTTP header contents.
171 The format is:
173 %s: %s
175 | |
176 | +- Header value
177 +----- Header name
178 NOTE: HTTP header fields are free form records and not strictly
180 made of 2 fields. Accessing a specific header with the prefix
181 notation helps treating the header value as a single string.
182 BerespProtocol - Backend response protocol
184 The HTTP protocol version information.
185 BerespReason - Backend response reason
187 The HTTP response reason string.
188 BerespStatus - Backend response status
190 The HTTP response status code.
191 BogoHeader - Bogus HTTP received
193 Contains the first 20 characters of received HTTP headers we
194 could not make sense of. Applies to both req.http and
195 beresp.http.
196 CLI - CLI communication
198 CLI communication between varnishd master and child process.
199 Debug - Debug messages
201 Debug messages can normally be ignored, but are sometimes help‐
202 ful during trouble-shooting. Most debug messages must be ex‐
203 plicitly enabled with parameters.
204 Debug messages may be added, changed or removed without prior
206 notice and shouldn't be considered stable.
207 NB: This log record is masked by default.
209 ESI_xmlerror - ESI parser error or warning message
211 An error or warning was generated during parsing of an ESI ob‐
212 ject. The log record describes the problem encountered.
213 End - Marks the end of a VXID
215 The last record of a VXID transaction.
216 Error - Error messages
218 Error messages are stuff you probably want to know.
219 ExpBan - Object evicted due to ban
221 Logs the VXID when an object is banned.
222 ExpKill - Object expiry event
224 Logs events related to object expiry. The events are:
225 EXP_Rearm
227 Logged when the expiry time of an object changes.
228 EXP_Inbox
230 Logged when the expiry thread picks an object from the
231 inbox for processing.
232 EXP_Kill
234 Logged when the expiry thread kills an object from the
235 inbox.
236 EXP_When
238 Logged when the expiry thread moves an object on the bin‐
239 heap.
240 EXP_Expired
242 Logged when the expiry thread expires an object.
243 LRU_Cand
245 Logged when an object is evaluated for LRU force expiry.
246 LRU Logged when an object is force expired due to LRU.
248 LRU_Fail
250 Logged when no suitable candidate object is found for LRU
251 force expiry.
252 The format is:
254 EXP_Rearm p=%p E=%f e=%f f=0x%x
256 EXP_Inbox p=%p e=%f f=0x%x
257 EXP_Kill p=%p e=%f f=0x%x
258 EXP_When p=%p e=%f f=0x%x
259 EXP_Expired x=%u t=%f
260 LRU_Cand p=%p f=0x%x r=%d
261 LRU x=%u
262 LRU_Fail
263 Legend:
265 p=%p Objcore pointer
266 t=%f Remaining TTL (s)
267 e=%f Expiry time (unix epoch)
268 E=%f Old expiry time (unix epoch)
269 f=0x%x Objcore flags
270 r=%d Objcore refcount
271 x=%u Object VXID
272 FetchError - Error while fetching object
274 Logs the error message of a failed fetch operation.
275 Error messages should be self-explanatory, yet the http connec‐
277 tion (HTC) class of errors is reported with these symbols:
278 • junk (-5): Received unexpected data
280 • close (-4): Connection closed
282 • timeout (-3): Timed out
284 • overflow (-2): Buffer/workspace too small
286 • eof (-1): Unexpected end of input
288 • empty (0): Empty response
290 • more (1): More data required
292 • complete (2): Data complete (no error)
294 • idle (3): Connection was closed while idle
296 Notice that some HTC errors are never emitted.
298 Fetch_Body - Body fetched from backend
300 Ready to fetch body from backend.
301 The format is:
303 %d %s %s
305 | | |
306 | | +---- 'stream' or '-'
307 | +------- Text description of body fetch mode
308 +---------- Body fetch mode
309 Filters - Body filters
311 List of filters applied to the body
312 Gzip - G(un)zip performed on object
314 A Gzip record is emitted for each instance of gzip or gunzip
315 work performed. Worst case, an ESI transaction stored in gzip'ed
316 objects but delivered gunziped, will run into many of these.
317 The format is:
319 %c %c %c %d %d %d %d %d
321 | | | | | | | |
322 | | | | | | | +- Bit length of compressed data
323 | | | | | | +---- Bit location of 'last' bit
324 | | | | | +------- Bit location of first deflate block
325 | | | | +---------- Bytes output
326 | | | +------------- Bytes input
327 | | +---------------- 'E': ESI, '-': Plain object
328 | +------------------- 'F': Fetch, 'D': Deliver
329 +---------------------- 'G': Gzip, 'U': Gunzip, 'u': Gunzip-test
330 Examples:
332 U F E 182 159 80 80 1392
334 G F E 159 173 80 1304 1314
335 H2RxBody - Received HTTP2 frame body
337 Binary data
338 H2RxHdr - Received HTTP2 frame header
340 Binary data
341 H2TxBody - Transmitted HTTP2 frame body
343 Binary data
344 H2TxHdr - Transmitted HTTP2 frame header
346 Binary data
347 Hash - Value added to hash
349 This value was added to the object lookup hash.
350 NB: This log record is masked by default.
352 Hit - Hit object in cache
354 Object looked up in cache.
355 The format is:
357 %u %f %f %f
359 | | | |
360 | | | +- Keep period
361 | | +---- Grace period
362 | +------- Remaining TTL
363 +---------- VXID of the object
364 HitMiss - Hit for miss object in cache.
366 Hit-for-miss object looked up in cache.
367 The format is:
369 %u %f
371 | |
372 | +- Remaining TTL
373 +---- VXID of the object
374 HitPass - Hit for pass object in cache.
376 Hit-for-pass object looked up in cache.
377 The format is:
379 %u %f
381 | |
382 | +- Remaining TTL
383 +---- VXID of the object
384 HttpGarbage - Unparseable HTTP request
386 Logs the content of unparseable HTTP requests.
387 Length - Size of object body
389 Logs the size of a fetch object body.
390 Link - Links to a child VXID
392 Links this VXID to any child VXID it initiates.
393 The format is:
395 %s %d %s
397 | | |
398 | | +- Reason
399 | +---- Child vxid
400 +------- Child type ("req" or "bereq")
401 LostHeader - Failed attempt to set HTTP header
403 Logs the header name of a failed HTTP header operation due to
404 resource exhaustion or configured limits.
405 Notice - Informational messages about request handling
407 Informational log messages on events occurred during request
408 handling.
409 The format is:
411 %s: %s
413 | |
414 | +- Short description of the notice message
415 +----- Manual page containing the detailed description
416 See the NOTICE MESSAGES section below or the individual VMOD
418 manual pages for detailed information of notice messages.
419 ObjHeader - Object header
421 HTTP header contents.
422 The format is:
424 %s: %s
426 | |
427 | +- Header value
428 +----- Header name
429 NOTE: HTTP header fields are free form records and not strictly
431 made of 2 fields. Accessing a specific header with the prefix
432 notation helps treating the header value as a single string.
433 ObjProtocol - Object protocol
435 The HTTP protocol version information.
436 ObjReason - Object reason
438 The HTTP response reason string.
439 ObjStatus - Object status
441 The HTTP response status code.
442 PipeAcct - Pipe byte counts
444 Contains byte counters for pipe sessions.
445 The format is:
447 %d %d %d %d
449 | | | |
450 | | | +------- Piped bytes to client
451 | | +---------- Piped bytes from client
452 | +------------- Backend request headers
453 +---------------- Client request headers
454 Proxy - PROXY protocol information
456 PROXY protocol information.
457 The format is:
459 %d %s %d %s %d
461 | | | | |
462 | | | | +- server port
463 | | | +---- server ip
464 | | +------- client port
465 | +---------- client ip
466 +------------- PROXY protocol version
467 All fields are "local" for PROXY local connections (command 0x0)
469 ProxyGarbage - Unparseable PROXY request
471 A PROXY protocol header was unparseable.
472 ReqAcct - Request handling byte counts
474 Contains byte counts for the request handling. The body bytes
475 count includes transmission overhead (ie: chunked encoding).
476 ESI sub-requests show the body bytes this ESI fragment including
477 any subfragments contributed to the top level request. The for‐
478 mat is:
479 %d %d %d %d %d %d
481 | | | | | |
482 | | | | | +- Total bytes transmitted
483 | | | | +---- Body bytes transmitted
484 | | | +------- Header bytes transmitted
485 | | +---------- Total bytes received
486 | +------------- Body bytes received
487 +---------------- Header bytes received
488 ReqHeader - Client request header
490 HTTP header contents.
491 The format is:
493 %s: %s
495 | |
496 | +- Header value
497 +----- Header name
498 NOTE: HTTP header fields are free form records and not strictly
500 made of 2 fields. Accessing a specific header with the prefix
501 notation helps treating the header value as a single string.
502 ReqMethod - Client request method
504 The HTTP request method used.
505 ReqProtocol - Client request protocol
507 The HTTP protocol version information.
508 ReqStart - Client request start
510 Start of request processing. Logs the client address, port num‐
511 ber and listener endpoint name (from the -a command-line argu‐
512 ment).
513 The format is:
515 %s %s %s
517 | | |
518 | | +-- Listener name (from -a)
519 | +----- Client Port number (0 for Unix domain sockets)
520 +-------- Client IP4/6 address (0.0.0.0 for UDS)
521 ReqURL - Client request URL
523 The HTTP request URL.
524 RespHeader - Client response header
526 HTTP header contents.
527 The format is:
529 %s: %s
531 | |
532 | +- Header value
533 +----- Header name
534 NOTE: HTTP header fields are free form records and not strictly
536 made of 2 fields. Accessing a specific header with the prefix
537 notation helps treating the header value as a single string.
538 RespProtocol - Client response protocol
540 The HTTP protocol version information.
541 RespReason - Client response reason
543 The HTTP response reason string.
544 RespStatus - Client response status
546 The HTTP response status code.
547 SessClose - Client connection closed
549 SessClose is the last record for any client connection.
550 The format is:
552 %s %f
554 | |
555 | +- How long the session was open
556 +---- Why the connection closed
557 SessError - Client connection accept failed
559 Accepting a client connection has failed.
560 The format is:
562 %s %s %s %d %d %s
564 | | | | | |
565 | | | | | +- Detailed error message
566 | | | | +---- Error Number (errno) from accept(2)
567 | | | +------- File descriptor number
568 | | +---------- Local TCP port / 0 for UDS
569 | +------------- Local IPv4/6 address / 0.0.0.0 for UDS
570 +---------------- Socket name (from -a argument)
571 SessOpen - Client connection opened
573 The first record for a client connection, with the socket-end‐
574 points of the connection.
575 The format is:
577 %s %d %s %s %s %f %d
579 | | | | | | |
580 | | | | | | +- File descriptor number
581 | | | | | +---- Session start time (unix epoch)
582 | | | | +------- Local TCP port / 0 for UDS
583 | | | +---------- Local IPv4/6 address / 0.0.0.0 for UDS
584 | | +------------- Socket name (from -a argument)
585 | +---------------- Remote TCP port / 0 for UDS
586 +------------------- Remote IPv4/6 address / 0.0.0.0 for UDS
587 Storage - Where object is stored
589 Type and name of the storage backend the object is stored in.
590 The format is:
592 %s %s
594 | |
595 | +- Name of storage backend
596 +---- Type ("malloc", "file", "persistent" etc.)
597 TTL - TTL set on object
599 A TTL record is emitted whenever the ttl, grace or keep values
600 for an object is set as well as whether the object is cacheable
601 or not.
602 The format is:
604 %s %d %d %d %d [ %d %d %u %u ] %s
606 | | | | | | | | | |
607 | | | | | | | | | +- "cacheable" or "uncacheable"
608 | | | | | | | | +------ Max-Age from Cache-Control header
609 | | | | | | | +--------- Expires header
610 | | | | | | +------------ Date header
611 | | | | | +--------------- Age (incl Age: header value)
612 | | | | +-------------------- Reference time for TTL
613 | | | +----------------------- Keep
614 | | +-------------------------- Grace
615 | +----------------------------- TTL
616 +-------------------------------- "RFC", "VCL" or "HFP"
617 The four optional fields are only present in "RFC" headers.
619 Examples:
621 RFC 60 10 -1 1312966109 1312966109 1312966109 0 60 cacheable
623 VCL 120 10 0 1312966111 uncacheable
624 HFP 2 0 0 1312966113 uncacheable
625 Timestamp - Timing information
627 Contains timing information for the Varnish worker threads.
628 Time stamps are issued by Varnish on certain events, and show
630 the absolute time of the event, the time spent since the start
631 of the work unit, and the time spent since the last timestamp
632 was logged. See the TIMESTAMPS section below for information
633 about the individual time stamps.
634 The format is:
636 %s: %f %f %f
638 | | | |
639 | | | +- Time since last timestamp
640 | | +---- Time since start of work unit
641 | +------- Absolute time of event
642 +----------- Event label
643 VCL_Error - VCL execution error message
645 Logs error messages generated during VCL execution.
646 VCL_Log - Log statement from VCL
648 User generated log messages insert from VCL through std.log()
649 VCL_acl - VCL ACL check results
651 Logs VCL ACL evaluation results.
652 The format is:
654 %s [%s [%s [fixed: %s]]]
656 | | | |
657 | | | +- Fixed entry (see vcc_acl_pedantic parameter)
658 | | +------------ Matching entry (only for MATCH)
659 | +---------------- Name of the ACL for MATCH or NO_MATCH
660 +-------------------- MATCH, NO_MATCH or NO_FAM
661 MATCH denotes an ACL match NO_MATCH denotes that a checked ACL
663 has not matched NO_FAM denotes a missing address family and
664 should not occur.
665 VCL_call - VCL method called
667 Logs the VCL method name when a VCL method is called.
668 VCL_return - VCL method return value
670 Logs the VCL method terminating statement.
671 VCL_trace - VCL trace data
673 Logs VCL execution trace data.
674 The format is:
676 %s %u %u.%u.%u
678 | | | | |
679 | | | | +- VCL program line position
680 | | | +---- VCL program line number
681 | | +------- VCL program source index
682 | +---------- VCL trace point index
683 +------------- VCL configname
684 NB: This log record is masked by default.
686 VCL_use - VCL in use
688 Records the name of the VCL being used.
689 The format is:
691 %s [ %s %s ]
693 | | |
694 | | +- Name of label used to find it
695 | +---- "via"
696 +--------- Name of VCL put in use
697 VSL - VSL API warnings and error message
699 Warnings and error messages generated by the VSL API while read‐
700 ing the shared memory log.
701 VdpAcct - Deliver filter accounting
703 Contains name of VDP and statistics.
704 The format is:
706 %s %d %d
708 | | |
709 | | +- Total bytes produced
710 | +---- Number of calls made
711 +------- Name of filter
712 NB: This log record is masked by default.
714 VfpAcct - Fetch filter accounting
716 Contains name of VFP and statistics.
717 The format is:
719 %s %d %d
721 | | |
722 | | +- Total bytes produced
723 | +---- Number of calls made
724 +------- Name of filter
725 NB: This log record is masked by default.
727 Witness - Lock order witness records
729 Diagnostic recording of locking order.
730 WorkThread - Logs thread start/stop events
732 Logs worker thread creation and termination events.
733 The format is:
735 %p %s
737 | |
738 | +- [start|end]
739 +---- Worker struct pointer
740 NB: This log record is masked by default.
742
744 Timestamps are inserted in the log on completing certain events during
745 the worker thread's task handling. The timestamps has a label showing
746 which event was completed. The reported fields show the absolute time
747 of the event, the time spent since the start of the task and the time
748 spent since the last timestamp was logged.
749 The timestamps logged automatically by Varnish are inserted after com‐
751 pleting events that are expected to have delays (e.g. network IO or
752 spending time on a waitinglist). Timestamps can also be inserted from
753 VCL using the std.timestamp() function. If one is doing time consuming
754 tasks in the VCL configuration, it's a good idea to log a timestamp af‐
755 ter completing that task. This keeps the timing information in subse‐
756 quent timestamps from including the time spent on the VCL event.
757 Request handling timestamps
759 Start The start of request processing (first byte received or
760 restart).
761 Req Complete client request received.
763 ReqBody
765 Client request body processed (discarded, cached or passed to
766 the backend).
767 Waitinglist
769 Came off waitinglist.
770 Fetch Fetch processing finished (completely fetched or ready for
772 streaming).
773 Process
775 Processing finished, ready to deliver the client response.
776 Resp Delivery of response to the client finished.
778 Restart
780 Client request is being restarted.
781 Pipe handling timestamps
783 Pipe Opened a pipe to the backend and forwarded the request.
784 PipeSess
786 The pipe session has finished.
787 Backend fetch timestamps
789 Start Start of the backend fetch processing.
790 Fetch Came off vcl_backend_fetch ready to send the backend request.
792 Connected
794 Successfully established or reused a backend connection.
795 Bereq Backend request sent.
797 Beresp Backend response headers received.
799 Process
801 Processing finished, ready to fetch the response body.
802 BerespBody
804 Backend response body received.
805 Retry Backend request is being retried.
807 Error Backend request failed to vcl_backend_error.
809
811 Notice messages contain informational messages about the handling of a
812 request. These can be exceptional circumstances encountered that causes
813 deviation from the normal handling. The messages are prefixed with vsl:
814 for core Varnish generated messages, and VMOD authors are encouraged to
815 use vmod_<name>: for their own notice messages. This matches the name
816 of the manual page where detailed descriptions of notice messages are
817 expected.
818 The core messages are described below.
820 Conditional fetch wait for streaming object
822 The backend answered 304 Not Modified on a conditional fetch using an
823 object that has not yet been fully fetched as the stale template ob‐
824 ject. This can only happen when the TTL of the object is less than the
825 time it takes to fetch it. The fetch is halted until the stale object
826 is fully fetched, upon which the new object is created as normal. While
827 waiting, any grace time on the stale object will be in effect.
828 High number of variants
830 Objects are primarily looked up from an index using the hash key com‐
831 puted from the hash_data() VCL function. When variants are involved,
832 that is to say when a backend response was stored with a Vary header, a
833 secondary lookup is performed but it is not indexed. As the number of
834 variants for a given key increases, this can slow cache lookups down,
835 and since this happens under a lock, this can greatly increase lock
836 contention, even more so for frequently requested objects. Variants
837 should therefore be used sparingly on cacheable responses, but since
838 they can originate from either VCL or origin servers, this notice
839 should help identify problematic resources.
840
842 This document was initially written by Poul-Henning Kamp, and later up‐
843 dated by Martin Blix Grydeland.
844
846 • varnishhist(1)
847 • varnishlog(1)
849 • varnishncsa(1)
851 • varnishtop(1)
853
855 This document is licensed under the same licence as Varnish itself. See
856 LICENCE for details.
857 • Copyright (c) 2006 Verdens Gang AS
859 • Copyright (c) 2006-2015 Varnish Software AS
861 VSL(7)