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 BereqUnset - Backend request unset 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 BerespHeader - Backend response header
184 HTTP header contents.
185 The format is:
187 %s: %s
189 | |
190 | +- Header value
191 +----- Header name
192 NOTE: HTTP header fields are free form records and not strictly
194 made of 2 fields. Accessing a specific header with the prefix
195 notation helps treating the header value as a single string.
196 BerespProtocol - Backend response protocol
198 The HTTP protocol version information.
199 BerespReason - Backend response reason
201 The HTTP response reason string.
202 BerespStatus - Backend response status
204 The HTTP response status code.
205 BerespUnset - Backend response unset header
207 HTTP header contents.
208 The format is:
210 %s: %s
212 | |
213 | +- Header value
214 +----- Header name
215 NOTE: HTTP header fields are free form records and not strictly
217 made of 2 fields. Accessing a specific header with the prefix
218 notation helps treating the header value as a single string.
219 BogoHeader - Bogus HTTP received
221 Contains the first 20 characters of received HTTP headers we
222 could not make sense of. Applies to both req.http and
223 beresp.http.
224 CLI - CLI communication
226 CLI communication between varnishd master and child process.
227 Debug - Debug messages
229 Debug messages can normally be ignored, but are sometimes help‐
230 ful during trouble-shooting. Most debug messages must be ex‐
231 plicitly enabled with parameters.
232 Debug messages may be added, changed or removed without prior
234 notice and shouldn't be considered stable.
235 NB: This log record is masked by default.
237 ESI_xmlerror - ESI parser error or warning message
239 An error or warning was generated during parsing of an ESI ob‐
240 ject. The log record describes the problem encountered.
241 End - Marks the end of a VXID
243 The last record of a VXID transaction.
244 Error - Error messages
246 Error messages are stuff you probably want to know.
247 ExpBan - Object evicted due to ban
249 Logs the VXID when an object is banned.
250 ExpKill - Object expiry event
252 Logs events related to object expiry. The events are:
253 EXP_Rearm
255 Logged when the expiry time of an object changes.
256 EXP_Inbox
258 Logged when the expiry thread picks an object from the
259 inbox for processing.
260 EXP_Kill
262 Logged when the expiry thread kills an object from the
263 inbox.
264 EXP_When
266 Logged when the expiry thread moves an object on the bin‐
267 heap.
268 EXP_Expired
270 Logged when the expiry thread expires an object.
271 LRU_Cand
273 Logged when an object is evaluated for LRU force expiry.
274 LRU Logged when an object is force expired due to LRU.
276 LRU_Fail
278 Logged when no suitable candidate object is found for LRU
279 force expiry.
280 The format is:
282 EXP_Rearm p=%p E=%f e=%f f=0x%x
284 EXP_Inbox p=%p e=%f f=0x%x
285 EXP_Kill p=%p e=%f f=0x%x
286 EXP_When p=%p e=%f f=0x%x
287 EXP_Expired x=%u t=%f
288 LRU_Cand p=%p f=0x%x r=%d
289 LRU x=%u
290 LRU_Fail
291 Legend:
293 p=%p Objcore pointer
294 t=%f Remaining TTL (s)
295 e=%f Expiry time (unix epoch)
296 E=%f Old expiry time (unix epoch)
297 f=0x%x Objcore flags
298 r=%d Objcore refcount
299 x=%u Object VXID
300 FetchError - Error while fetching object
302 Logs the error message of a failed fetch operation.
303 Error messages should be self-explanatory, yet the http connec‐
305 tion (HTC) class of errors is reported with these symbols:
306 • junk (-5): Received unexpected data
308 • close (-4): Connection closed
310 • timeout (-3): Timed out
312 • overflow (-2): Buffer/workspace too small
314 • eof (-1): Unexpected end of input
316 • empty (0): Empty response
318 • more (1): More data required
320 • complete (2): Data complete (no error)
322 • idle (3): Connection was closed while idle
324 Notice that some HTC errors are never emitted.
326 Fetch_Body - Body fetched from backend
328 Ready to fetch body from backend.
329 The format is:
331 %d %s %s
333 | | |
334 | | +---- 'stream' or '-'
335 | +------- Text description of body fetch mode
336 +---------- Body fetch mode
337 Filters - Body filters
339 List of filters applied to the body
340 Gzip - G(un)zip performed on object
342 A Gzip record is emitted for each instance of gzip or gunzip
343 work performed. Worst case, an ESI transaction stored in gzip'ed
344 objects but delivered gunziped, will run into many of these.
345 The format is:
347 %c %c %c %d %d %d %d %d
349 | | | | | | | |
350 | | | | | | | +- Bit length of compressed data
351 | | | | | | +---- Bit location of 'last' bit
352 | | | | | +------- Bit location of first deflate block
353 | | | | +---------- Bytes output
354 | | | +------------- Bytes input
355 | | +---------------- 'E': ESI, '-': Plain object
356 | +------------------- 'F': Fetch, 'D': Deliver
357 +---------------------- 'G': Gzip, 'U': Gunzip, 'u': Gunzip-test
358 Examples:
360 U F E 182 159 80 80 1392
362 G F E 159 173 80 1304 1314
363 H2RxBody - Received HTTP2 frame body
365 Binary data
366 H2RxHdr - Received HTTP2 frame header
368 Binary data
369 H2TxBody - Transmitted HTTP2 frame body
371 Binary data
372 H2TxHdr - Transmitted HTTP2 frame header
374 Binary data
375 Hash - Value added to hash
377 This value was added to the object lookup hash.
378 NB: This log record is masked by default.
380 Hit - Hit object in cache
382 Object looked up in cache.
383 The format is:
385 %u %f %f %f [%u [%u]]
387 | | | | | |
388 | | | | | +- Content length
389 | | | | +----- Fetched so far
390 | | | +--------- Keep period
391 | | +------------ Grace period
392 | +--------------- Remaining TTL
393 +------------------ VXID of the object
394 HitMiss - Hit for miss object in cache.
396 Hit-for-miss object looked up in cache.
397 The format is:
399 %u %f
401 | |
402 | +- Remaining TTL
403 +---- VXID of the object
404 HitPass - Hit for pass object in cache.
406 Hit-for-pass object looked up in cache.
407 The format is:
409 %u %f
411 | |
412 | +- Remaining TTL
413 +---- VXID of the object
414 HttpGarbage - Unparseable HTTP request
416 Logs the content of unparseable HTTP requests.
417 Length - Size of object body
419 Logs the size of a fetch object body.
420 Link - Links to a child VXID
422 Links this VXID to any child VXID it initiates.
423 The format is:
425 %s %d %s
427 | | |
428 | | +- Reason
429 | +---- Child vxid
430 +------- Child type ("req" or "bereq")
431 LostHeader - Failed attempt to set HTTP header
433 Logs the header name of a failed HTTP header operation due to
434 resource exhaustion or configured limits.
435 Notice - Informational messages about request handling
437 Informational log messages on events occurred during request
438 handling.
439 The format is:
441 %s: %s
443 | |
444 | +- Short description of the notice message
445 +----- Manual page containing the detailed description
446 See the NOTICE MESSAGES section below or the individual VMOD
448 manual pages for detailed information of notice messages.
449 ObjHeader - Object header
451 HTTP header contents.
452 The format is:
454 %s: %s
456 | |
457 | +- Header value
458 +----- Header name
459 NOTE: HTTP header fields are free form records and not strictly
461 made of 2 fields. Accessing a specific header with the prefix
462 notation helps treating the header value as a single string.
463 ObjProtocol - Object protocol
465 The HTTP protocol version information.
466 ObjReason - Object reason
468 The HTTP response reason string.
469 ObjStatus - Object status
471 The HTTP response status code.
472 ObjUnset - Object unset header
474 HTTP header contents.
475 The format is:
477 %s: %s
479 | |
480 | +- Header value
481 +----- Header name
482 NOTE: HTTP header fields are free form records and not strictly
484 made of 2 fields. Accessing a specific header with the prefix
485 notation helps treating the header value as a single string.
486 PipeAcct - Pipe byte counts
488 Contains byte counters for pipe sessions.
489 The format is:
491 %d %d %d %d
493 | | | |
494 | | | +------- Piped bytes to client
495 | | +---------- Piped bytes from client
496 | +------------- Backend request headers
497 +---------------- Client request headers
498 Proxy - PROXY protocol information
500 PROXY protocol information.
501 The format is:
503 %d %s %d %s %d
505 | | | | |
506 | | | | +- server port
507 | | | +---- server ip
508 | | +------- client port
509 | +---------- client ip
510 +------------- PROXY protocol version
511 All fields are "local" for PROXY local connections (command 0x0)
513 ProxyGarbage - Unparseable PROXY request
515 A PROXY protocol header was unparseable.
516 ReqAcct - Request handling byte counts
518 Contains byte counts for the request handling. The body bytes
519 count includes transmission overhead (ie: chunked encoding).
520 ESI sub-requests show the body bytes this ESI fragment including
521 any subfragments contributed to the top level request. The for‐
522 mat is:
523 %d %d %d %d %d %d
525 | | | | | |
526 | | | | | +- Total bytes transmitted
527 | | | | +---- Body bytes transmitted
528 | | | +------- Header bytes transmitted
529 | | +---------- Total bytes received
530 | +------------- Body bytes received
531 +---------------- Header bytes received
532 ReqHeader - Client request header
534 HTTP header contents.
535 The format is:
537 %s: %s
539 | |
540 | +- Header value
541 +----- Header name
542 NOTE: HTTP header fields are free form records and not strictly
544 made of 2 fields. Accessing a specific header with the prefix
545 notation helps treating the header value as a single string.
546 ReqMethod - Client request method
548 The HTTP request method used.
549 ReqProtocol - Client request protocol
551 The HTTP protocol version information.
552 ReqStart - Client request start
554 Start of request processing. Logs the client address, port num‐
555 ber and listener endpoint name (from the -a command-line argu‐
556 ment).
557 The format is:
559 %s %s %s
561 | | |
562 | | +-- Listener name (from -a)
563 | +----- Client Port number (0 for Unix domain sockets)
564 +-------- Client IP4/6 address (0.0.0.0 for UDS)
565 ReqURL - Client request URL
567 The HTTP request URL.
568 ReqUnset - Client request unset header
570 HTTP header contents.
571 The format is:
573 %s: %s
575 | |
576 | +- Header value
577 +----- Header name
578 NOTE: HTTP header fields are free form records and not strictly
580 made of 2 fields. Accessing a specific header with the prefix
581 notation helps treating the header value as a single string.
582 RespHeader - Client response header
584 HTTP header contents.
585 The format is:
587 %s: %s
589 | |
590 | +- Header value
591 +----- Header name
592 NOTE: HTTP header fields are free form records and not strictly
594 made of 2 fields. Accessing a specific header with the prefix
595 notation helps treating the header value as a single string.
596 RespProtocol - Client response protocol
598 The HTTP protocol version information.
599 RespReason - Client response reason
601 The HTTP response reason string.
602 RespStatus - Client response status
604 The HTTP response status code.
605 RespUnset - Client response unset header
607 HTTP header contents.
608 The format is:
610 %s: %s
612 | |
613 | +- Header value
614 +----- Header name
615 NOTE: HTTP header fields are free form records and not strictly
617 made of 2 fields. Accessing a specific header with the prefix
618 notation helps treating the header value as a single string.
619 SessClose - Client connection closed
621 SessClose is the last record for any client connection.
622 The format is:
624 %s %f
626 | |
627 | +- How long the session was open
628 +---- Why the connection closed
629 SessError - Client connection accept failed
631 Accepting a client connection has failed.
632 The format is:
634 %s %s %s %d %d %s
636 | | | | | |
637 | | | | | +- Detailed error message
638 | | | | +---- Error Number (errno) from accept(2)
639 | | | +------- File descriptor number
640 | | +---------- Local TCP port / 0 for UDS
641 | +------------- Local IPv4/6 address / 0.0.0.0 for UDS
642 +---------------- Socket name (from -a argument)
643 SessOpen - Client connection opened
645 The first record for a client connection, with the socket-end‐
646 points of the connection.
647 The format is:
649 %s %d %s %s %s %f %d
651 | | | | | | |
652 | | | | | | +- File descriptor number
653 | | | | | +---- Session start time (unix epoch)
654 | | | | +------- Local TCP port / 0 for UDS
655 | | | +---------- Local IPv4/6 address / 0.0.0.0 for UDS
656 | | +------------- Socket name (from -a argument)
657 | +---------------- Remote TCP port / 0 for UDS
658 +------------------- Remote IPv4/6 address / 0.0.0.0 for UDS
659 Storage - Where object is stored
661 Type and name of the storage backend the object is stored in.
662 The format is:
664 %s %s
666 | |
667 | +- Name of storage backend
668 +---- Type ("malloc", "file", "persistent" etc.)
669 TTL - TTL set on object
671 A TTL record is emitted whenever the ttl, grace or keep values
672 for an object is set as well as whether the object is cacheable
673 or not.
674 The format is:
676 %s %d %d %d %d [ %d %d %u %u ] %s
678 | | | | | | | | | |
679 | | | | | | | | | +- "cacheable" or "uncacheable"
680 | | | | | | | | +------ Max-Age from Cache-Control header
681 | | | | | | | +--------- Expires header
682 | | | | | | +------------ Date header
683 | | | | | +--------------- Age (incl Age: header value)
684 | | | | +-------------------- Reference time for TTL
685 | | | +----------------------- Keep
686 | | +-------------------------- Grace
687 | +----------------------------- TTL
688 +-------------------------------- "RFC", "VCL" or "HFP"
689 The four optional fields are only present in "RFC" headers.
691 Examples:
693 RFC 60 10 -1 1312966109 1312966109 1312966109 0 60 cacheable
695 VCL 120 10 0 1312966111 uncacheable
696 HFP 2 0 0 1312966113 uncacheable
697 Timestamp - Timing information
699 Contains timing information for the Varnish worker threads.
700 Time stamps are issued by Varnish on certain events, and show
702 the absolute time of the event, the time spent since the start
703 of the work unit, and the time spent since the last timestamp
704 was logged. See the TIMESTAMPS section below for information
705 about the individual time stamps.
706 The format is:
708 %s: %f %f %f
710 | | | |
711 | | | +- Time since last timestamp
712 | | +---- Time since start of work unit
713 | +------- Absolute time of event
714 +----------- Event label
715 VCL_Error - VCL execution error message
717 Logs error messages generated during VCL execution.
718 VCL_Log - Log statement from VCL
720 User generated log messages insert from VCL through std.log()
721 VCL_acl - VCL ACL check results
723 ACLs with the +log flag emits this record with the result.
724 The format is:
726 %s %s [%s [fixed: %s]]
728 | | | |
729 | | | +- Fixed entry (see vcc_acl_pedantic parameter)
730 | | +------------ Matching entry (only for MATCH)
731 | +---------------- Name of the ACL
732 +-------------------- MATCH or NO_MATCH
733 MATCH denotes an ACL match NO_MATCH denotes that a checked ACL
735 has not matched
736 VCL_call - VCL method called
738 Logs the VCL method name when a VCL method is called.
739 VCL_return - VCL method return value
741 Logs the VCL method terminating statement.
742 VCL_trace - VCL trace data
744 Logs VCL execution trace data.
745 The format is:
747 %s %u %u.%u.%u
749 | | | | |
750 | | | | +- VCL program line position
751 | | | +---- VCL program line number
752 | | +------- VCL program source index
753 | +---------- VCL trace point index
754 +------------- VCL configname
755 NB: This log record is masked by default.
757 VCL_use - VCL in use
759 Records the name of the VCL being used.
760 The format is:
762 %s [ %s %s ]
764 | | |
765 | | +- Name of label used to find it
766 | +---- "via"
767 +--------- Name of VCL put in use
768 VSL - VSL API warnings and error message
770 Warnings and error messages generated by the VSL API while read‐
771 ing the shared memory log.
772 VdpAcct - Deliver filter accounting
774 Contains name of VDP and statistics.
775 The format is:
777 %s %d %d
779 | | |
780 | | +- Total bytes produced
781 | +---- Number of calls made
782 +------- Name of filter
783 NB: This log record is masked by default.
785 VfpAcct - Fetch filter accounting
787 Contains name of VFP and statistics.
788 The format is:
790 %s %d %d
792 | | |
793 | | +- Total bytes produced
794 | +---- Number of calls made
795 +------- Name of filter
796 NB: This log record is masked by default.
798 Witness - Lock order witness records
800 Diagnostic recording of locking order.
801 WorkThread - Logs thread start/stop events
803 Logs worker thread creation and termination events.
804 The format is:
806 %p %s
808 | |
809 | +- [start|end]
810 +---- Worker struct pointer
811 NB: This log record is masked by default.
813
815 Timestamps are inserted in the log on completing certain events during
816 the worker thread's task handling. The timestamps has a label showing
817 which event was completed. The reported fields show the absolute time
818 of the event, the time spent since the start of the task and the time
819 spent since the last timestamp was logged.
820 The timestamps logged automatically by Varnish are inserted after com‐
822 pleting events that are expected to have delays (e.g. network IO or
823 spending time on a waitinglist). Timestamps can also be inserted from
824 VCL using the std.timestamp() function. If one is doing time consuming
825 tasks in the VCL configuration, it's a good idea to log a timestamp af‐
826 ter completing that task. This keeps the timing information in subse‐
827 quent timestamps from including the time spent on the VCL event.
828 Request handling timestamps
830 Start The start of request processing (first byte received or
831 restart).
832 Req Complete client request received.
834 ReqBody
836 Client request body processed (discarded, cached or passed to
837 the backend).
838 Waitinglist
840 Came off waitinglist.
841 Fetch Fetch processing finished (completely fetched or ready for
843 streaming).
844 Process
846 Processing finished, ready to deliver the client response.
847 Resp Delivery of response to the client finished.
849 Restart
851 Client request is being restarted.
852 Pipe handling timestamps
854 Pipe Opened a pipe to the backend and forwarded the request.
855 PipeSess
857 The pipe session has finished.
858 Backend fetch timestamps
860 Start Start of the backend fetch processing.
861 Fetch Came off vcl_backend_fetch ready to send the backend request.
863 Connected
865 Successfully established a backend connection, or selected a re‐
866 cycled connection from the pool.
867 Bereq Backend request sent.
869 Beresp Backend response headers received.
871 Process
873 Processing finished, ready to fetch the response body.
874 BerespBody
876 Backend response body received.
877 Retry Backend request is being retried.
879 Error Backend request failed to vcl_backend_error.
881
883 Notice messages contain informational messages about the handling of a
884 request. These can be exceptional circumstances encountered that causes
885 deviation from the normal handling. The messages are prefixed with vsl:
886 for core Varnish generated messages, and VMOD authors are encouraged to
887 use vmod_<name>: for their own notice messages. This matches the name
888 of the manual page where detailed descriptions of notice messages are
889 expected.
890 The core messages are described below.
892 Conditional fetch wait for streaming object
894 The backend answered 304 Not Modified on a conditional fetch using an
895 object that has not yet been fully fetched as the stale template ob‐
896 ject. This can only happen when the TTL of the object is less than the
897 time it takes to fetch it. The fetch is halted until the stale object
898 is fully fetched, upon which the new object is created as normal. While
899 waiting, any grace time on the stale object will be in effect.
900 High number of variants
902 Objects are primarily looked up from an index using the hash key com‐
903 puted from the hash_data() VCL function. When variants are involved,
904 that is to say when a backend response was stored with a Vary header, a
905 secondary lookup is performed but it is not indexed. As the number of
906 variants for a given key increases, this can slow cache lookups down,
907 and since this happens under a lock, this can greatly increase lock
908 contention, even more so for frequently requested objects. Variants
909 should therefore be used sparingly on cacheable responses, but since
910 they can originate from either VCL or origin servers, this notice
911 should help identify problematic resources.
912
914 This document was initially written by Poul-Henning Kamp, and later up‐
915 dated by Martin Blix Grydeland.
916
918 • varnishhist(1)
919 • varnishlog(1)
921 • varnishncsa(1)
923 • varnishtop(1)
925
927 This document is licensed under the same licence as Varnish itself. See
928 LICENCE for details.
929 • Copyright (c) 2006 Verdens Gang AS
931 • Copyright (c) 2006-2015 Varnish Software AS
933 VSL(7)