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 BackendClose - Backend connection closed
15 Logged when a backend connection is closed.
16 The format is:
18 %d %s %s [ %s ]
20 | | | |
21 | | | +- Optional reason
22 | | +------ "close" or "recycle"
23 | +--------- Backend display name
24 +------------ Connection file descriptor
25 BackendOpen - Backend connection opened
27 Logged when a new backend connection is opened.
28 The format is:
30 %d %s %s %s %s %s %s
32 | | | | | | |
33 | | | | | | +- "connect" or "reuse"
34 | | | | | +---- Local port
35 | | | | +------- Local address
36 | | | +---------- Remote port
37 | | +------------- Remote address
38 | +---------------- Backend display name
39 +------------------- Connection file descriptor
40 Backend_health - Backend health check
42 The result of a backend health probe.
43 The format is:
45 %s %s %s %s %u %u %u %f %f %s
47 | | | | | | | | | |
48 | | | | | | | | | +- Probe HTTP response / error information
49 | | | | | | | | +---- Average response time
50 | | | | | | | +------- Response time
51 | | | | | | +---------- Probe window size
52 | | | | | +------------- Probe threshold level
53 | | | | +---------------- Number of good probes in window
54 | | | +------------------- Probe window bits
55 | | +---------------------- "healthy" or "sick"
56 | +------------------------- "Back", "Still" or "Went"
57 +---------------------------- Backend name
58 Probe window bits are:
60 '-': Could not connect
62 '4': Good IPv4
63 '6': Good IPv6
64 'U': Good UNIX
65 'x': Error Xmit
66 'X': Good Xmit
67 'r': Error Recv
68 'R': Good Recv
69 'H': Happy
70 When the backend is just created, the window bits for health
72 check slots that haven't run yet appear as '-' like failures to
73 connect.
74 Begin - Marks the start of a VXID
76 The first record of a VXID transaction.
77 The format is:
79 %s %d %s [%u]
81 | | | |
82 | | | +- Task sub-level
83 | | +----- Reason
84 | +-------- Parent vxid
85 +----------- Type ("sess", "req" or "bereq")
86 BereqAcct - Backend request accounting
88 Contains byte counters from backend request processing.
89 The format is:
91 %d %d %d %d %d %d
93 | | | | | |
94 | | | | | +- Total bytes received
95 | | | | +---- Body bytes received
96 | | | +------- Header bytes received
97 | | +---------- Total bytes transmitted
98 | +------------- Body bytes transmitted
99 +---------------- Header bytes transmitted
100 BereqHeader - Backend request header
102 HTTP header contents.
103 The format is:
105 %s: %s
107 | |
108 | +- Header value
109 +----- Header name
110 NOTE: HTTP header fields are free form records and not strictly
112 made of 2 fields. Accessing a specific header with the prefix
113 notation helps treating the header value as a single string.
114 BereqMethod - Backend request method
116 The HTTP request method used.
117 BereqProtocol - Backend request protocol
119 The HTTP protocol version information.
120 BereqURL - Backend request URL
122 The HTTP request URL.
123 BereqUnset - Backend request unset header
125 HTTP header contents.
126 The format is:
128 %s: %s
130 | |
131 | +- Header value
132 +----- Header name
133 NOTE: HTTP header fields are free form records and not strictly
135 made of 2 fields. Accessing a specific header with the prefix
136 notation helps treating the header value as a single string.
137 BerespHeader - Backend response header
139 HTTP header contents.
140 The format is:
142 %s: %s
144 | |
145 | +- Header value
146 +----- Header name
147 NOTE: HTTP header fields are free form records and not strictly
149 made of 2 fields. Accessing a specific header with the prefix
150 notation helps treating the header value as a single string.
151 BerespProtocol - Backend response protocol
153 The HTTP protocol version information.
154 BerespReason - Backend response reason
156 The HTTP response reason string.
157 BerespStatus - Backend response status
159 The HTTP response status code.
160 BerespUnset - Backend response unset header
162 HTTP header contents.
163 The format is:
165 %s: %s
167 | |
168 | +- Header value
169 +----- Header name
170 NOTE: HTTP header fields are free form records and not strictly
172 made of 2 fields. Accessing a specific header with the prefix
173 notation helps treating the header value as a single string.
174 BogoHeader - Bogus HTTP received
176 Contains the first 20 characters of received HTTP headers we
177 could not make sense of. Applies to both req.http and
178 beresp.http.
179 CLI - CLI communication
181 CLI communication between varnishd master and child process.
182 Debug - Debug messages
184 Debug messages can normally be ignored, but are sometimes help‐
185 ful during trouble-shooting. Most debug messages must be ex‐
186 plicitly enabled with parameters.
187 Debug messages may be added, changed or removed without prior
189 notice and shouldn't be considered stable.
190 NB: This log record is masked by default.
192 ESI_xmlerror - ESI parser error or warning message
194 An error or warning was generated during parsing of an ESI ob‐
195 ject. The log record describes the problem encountered.
196 End - Marks the end of a VXID
198 The last record of a VXID transaction.
199 Error - Error messages
201 Error messages are stuff you probably want to know.
202 ExpBan - Object evicted due to ban
204 Logs the VXID when an object is banned.
205 ExpKill - Object expiry event
207 Logs events related to object expiry. The events are:
208 EXP_Rearm
210 Logged when the expiry time of an object changes.
211 EXP_Inbox
213 Logged when the expiry thread picks an object from the
214 inbox for processing.
215 EXP_Kill
217 Logged when the expiry thread kills an object from the
218 inbox.
219 EXP_When
221 Logged when the expiry thread moves an object on the bin‐
222 heap.
223 EXP_Expired
225 Logged when the expiry thread expires an object.
226 LRU_Cand
228 Logged when an object is evaluated for LRU force expiry.
229 LRU Logged when an object is force expired due to LRU.
231 LRU_Fail
233 Logged when no suitable candidate object is found for LRU
234 force expiry.
235 The format is:
237 EXP_Rearm p=%p E=%f e=%f f=0x%x
239 EXP_Inbox p=%p e=%f f=0x%x
240 EXP_Kill p=%p e=%f f=0x%x
241 EXP_When p=%p e=%f f=0x%x
242 EXP_Expired x=%u t=%f
243 LRU_Cand p=%p f=0x%x r=%d
244 LRU x=%u
245 LRU_Fail
246 Legend:
248 p=%p Objcore pointer
249 t=%f Remaining TTL (s)
250 e=%f Expiry time (unix epoch)
251 E=%f Old expiry time (unix epoch)
252 f=0x%x Objcore flags
253 r=%d Objcore refcount
254 x=%u Object VXID
255 FetchError - Error while fetching object
257 Logs the error message of a failed fetch operation.
258 Error messages should be self-explanatory, yet the http connec‐
260 tion (HTC) class of errors is reported with these symbols:
261 • junk (-5): Received unexpected data
263 • close (-4): Connection closed
265 • timeout (-3): Timed out
267 • overflow (-2): Buffer/workspace too small
269 • eof (-1): Unexpected end of input
271 • empty (0): Empty response
273 • more (1): More data required
275 • complete (2): Data complete (no error)
277 • idle (3): Connection was closed while idle
279 Notice that some HTC errors are never emitted.
281 Fetch_Body - Body fetched from backend
283 Ready to fetch body from backend.
284 The format is:
286 %d %s %s
288 | | |
289 | | +---- 'stream' or '-'
290 | +------- Text description of body fetch mode
291 +---------- Body fetch mode
292 Filters - Body filters
294 List of filters applied to the body
295 Gzip - G(un)zip performed on object
297 A Gzip record is emitted for each instance of gzip or gunzip
298 work performed. Worst case, an ESI transaction stored in gzip'ed
299 objects but delivered gunziped, will run into many of these.
300 The format is:
302 %c %c %c %d %d %d %d %d
304 | | | | | | | |
305 | | | | | | | +- Bit length of compressed data
306 | | | | | | +---- Bit location of 'last' bit
307 | | | | | +------- Bit location of first deflate block
308 | | | | +---------- Bytes output
309 | | | +------------- Bytes input
310 | | +---------------- 'E': ESI, '-': Plain object
311 | +------------------- 'F': Fetch, 'D': Deliver
312 +---------------------- 'G': Gzip, 'U': Gunzip, 'u': Gunzip-test
313 Examples:
315 U F E 182 159 80 80 1392
317 G F E 159 173 80 1304 1314
318 H2RxBody - Received HTTP2 frame body
320 Binary data
321 H2RxHdr - Received HTTP2 frame header
323 Binary data
324 H2TxBody - Transmitted HTTP2 frame body
326 Binary data
327 H2TxHdr - Transmitted HTTP2 frame header
329 Binary data
330 Hash - Value added to hash
332 This value was added to the object lookup hash.
333 NB: This log record is masked by default.
335 Hit - Hit object in cache
337 Object looked up in cache.
338 The format is:
340 %u %f %f %f [%u [%u]]
342 | | | | | |
343 | | | | | +- Content length
344 | | | | +----- Fetched so far
345 | | | +--------- Keep period
346 | | +------------ Grace period
347 | +--------------- Remaining TTL
348 +------------------ VXID of the object
349 HitMiss - Hit for miss object in cache.
351 Hit-for-miss object looked up in cache.
352 The format is:
354 %u %f
356 | |
357 | +- Remaining TTL
358 +---- VXID of the object
359 HitPass - Hit for pass object in cache.
361 Hit-for-pass object looked up in cache.
362 The format is:
364 %u %f
366 | |
367 | +- Remaining TTL
368 +---- VXID of the object
369 HttpGarbage - Unparseable HTTP request
371 Logs the content of unparseable HTTP requests.
372 Length - Size of object body
374 Logs the size of a fetch object body.
375 Link - Links to a child VXID
377 Links this VXID to any child VXID it initiates.
378 The format is:
380 %s %d %s [%u]
382 | | | |
383 | | | +- Child task sub-level
384 | | +----- Reason
385 | +-------- Child vxid
386 +----------- Child type ("sess", "req" or "bereq")
387 LostHeader - Failed attempt to set HTTP header
389 Logs the header name of a failed HTTP header operation due to
390 resource exhaustion or configured limits.
391 Notice - Informational messages about request handling
393 Informational log messages on events occurred during request
394 handling.
395 The format is:
397 %s: %s
399 | |
400 | +- Short description of the notice message
401 +----- Manual page containing the detailed description
402 See the NOTICE MESSAGES section below or the individual VMOD
404 manual pages for detailed information of notice messages.
405 ObjHeader - Object header
407 HTTP header contents.
408 The format is:
410 %s: %s
412 | |
413 | +- Header value
414 +----- Header name
415 NOTE: HTTP header fields are free form records and not strictly
417 made of 2 fields. Accessing a specific header with the prefix
418 notation helps treating the header value as a single string.
419 ObjProtocol - Object protocol
421 The HTTP protocol version information.
422 ObjReason - Object reason
424 The HTTP response reason string.
425 ObjStatus - Object status
427 The HTTP response status code.
428 ObjUnset - Object unset header
430 HTTP header contents.
431 The format is:
433 %s: %s
435 | |
436 | +- Header value
437 +----- Header name
438 NOTE: HTTP header fields are free form records and not strictly
440 made of 2 fields. Accessing a specific header with the prefix
441 notation helps treating the header value as a single string.
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 ReqUnset - Client request unset 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 RespHeader - Client response header
540 HTTP header contents.
541 The format is:
543 %s: %s
545 | |
546 | +- Header value
547 +----- Header name
548 NOTE: HTTP header fields are free form records and not strictly
550 made of 2 fields. Accessing a specific header with the prefix
551 notation helps treating the header value as a single string.
552 RespProtocol - Client response protocol
554 The HTTP protocol version information.
555 RespReason - Client response reason
557 The HTTP response reason string.
558 RespStatus - Client response status
560 The HTTP response status code.
561 RespUnset - Client response unset header
563 HTTP header contents.
564 The format is:
566 %s: %s
568 | |
569 | +- Header value
570 +----- Header name
571 NOTE: HTTP header fields are free form records and not strictly
573 made of 2 fields. Accessing a specific header with the prefix
574 notation helps treating the header value as a single string.
575 SessClose - Client connection closed
577 SessClose is the last record for any client connection.
578 The format is:
580 %s %f
582 | |
583 | +- How long the session was open
584 +---- Why the connection closed
585 SessError - Client connection accept failed
587 Accepting a client connection has failed.
588 The format is:
590 %s %s %s %d %d %s
592 | | | | | |
593 | | | | | +- Detailed error message
594 | | | | +---- Error Number (errno) from accept(2)
595 | | | +------- File descriptor number
596 | | +---------- Local TCP port / 0 for UDS
597 | +------------- Local IPv4/6 address / 0.0.0.0 for UDS
598 +---------------- Socket name (from -a argument)
599 SessOpen - Client connection opened
601 The first record for a client connection, with the socket-end‐
602 points of the connection.
603 The format is:
605 %s %d %s %s %s %f %d
607 | | | | | | |
608 | | | | | | +- File descriptor number
609 | | | | | +---- Session start time (unix epoch)
610 | | | | +------- Local TCP port / 0 for UDS
611 | | | +---------- Local IPv4/6 address / 0.0.0.0 for UDS
612 | | +------------- Socket name (from -a argument)
613 | +---------------- Remote TCP port / 0 for UDS
614 +------------------- Remote IPv4/6 address / 0.0.0.0 for UDS
615 Storage - Where object is stored
617 Type and name of the storage backend the object is stored in.
618 The format is:
620 %s %s
622 | |
623 | +- Name of storage backend
624 +---- Type ("malloc", "file", "persistent" etc.)
625 TTL - TTL set on object
627 A TTL record is emitted whenever the ttl, grace or keep values
628 for an object is set as well as whether the object is cacheable
629 or not.
630 The format is:
632 %s %d %d %d %d [ %d %d %u %u ] %s
634 | | | | | | | | | |
635 | | | | | | | | | +- "cacheable" or "uncacheable"
636 | | | | | | | | +------ Max-Age from Cache-Control header
637 | | | | | | | +--------- Expires header
638 | | | | | | +------------ Date header
639 | | | | | +--------------- Age (incl Age: header value)
640 | | | | +-------------------- Reference time for TTL
641 | | | +----------------------- Keep
642 | | +-------------------------- Grace
643 | +----------------------------- TTL
644 +-------------------------------- "RFC", "VCL" or "HFP"
645 The four optional fields are only present in "RFC" headers.
647 Examples:
649 RFC 60 10 -1 1312966109 1312966109 1312966109 0 60 cacheable
651 VCL 120 10 0 1312966111 uncacheable
652 HFP 2 0 0 1312966113 uncacheable
653 Timestamp - Timing information
655 Contains timing information for the Varnish worker threads.
656 Time stamps are issued by Varnish on certain events, and show
658 the absolute time of the event, the time spent since the start
659 of the work unit, and the time spent since the last timestamp
660 was logged. See the TIMESTAMPS section below for information
661 about the individual time stamps.
662 The format is:
664 %s: %f %f %f
666 | | | |
667 | | | +- Time since last timestamp
668 | | +---- Time since start of work unit
669 | +------- Absolute time of event
670 +----------- Event label
671 VCL_Error - VCL execution error message
673 Logs error messages generated during VCL execution.
674 VCL_Log - Log statement from VCL
676 User generated log messages insert from VCL through std.log()
677 VCL_acl - VCL ACL check results
679 ACLs with the +log flag emits this record with the result.
680 The format is:
682 %s %s [%s [fixed: %s]]
684 | | | |
685 | | | +- Fixed entry (see acl +pedantic flag)
686 | | +------------ Matching entry (only for MATCH)
687 | +---------------- Name of the ACL
688 +-------------------- MATCH or NO_MATCH
689 MATCH denotes an ACL match NO_MATCH denotes that a checked ACL
691 has not matched
692 VCL_call - VCL method called
694 Logs the VCL method name when a VCL method is called.
695 VCL_return - VCL method return value
697 Logs the VCL method terminating statement.
698 VCL_trace - VCL trace data
700 Logs VCL execution trace data.
701 The format is:
703 %s %u %u.%u.%u
705 | | | | |
706 | | | | +- VCL program line position
707 | | | +---- VCL program line number
708 | | +------- VCL program source index
709 | +---------- VCL trace point index
710 +------------- VCL configname
711 NB: This log record is masked by default.
713 VCL_use - VCL in use
715 Records the name of the VCL being used.
716 The format is:
718 %s [ %s %s ]
720 | | |
721 | | +- Name of label used to find it
722 | +---- "via"
723 +--------- Name of VCL put in use
724 VSL - VSL API warnings and error message
726 Warnings and error messages generated by the VSL API while read‐
727 ing the shared memory log.
728 VdpAcct - Deliver filter accounting
730 Contains name of VDP and statistics.
731 The format is:
733 %s %d %d
735 | | |
736 | | +- Total bytes produced
737 | +---- Number of calls made
738 +------- Name of filter
739 NB: This log record is masked by default.
741 VfpAcct - Fetch filter accounting
743 Contains name of VFP and statistics.
744 The format is:
746 %s %d %d
748 | | |
749 | | +- Total bytes produced
750 | +---- Number of calls made
751 +------- Name of filter
752 NB: This log record is masked by default.
754 Witness - Lock order witness records
756 Diagnostic recording of locking order.
757 WorkThread - Logs thread start/stop events
759 Logs worker thread creation and termination events.
760 The format is:
762 %p %s
764 | |
765 | +- [start|end]
766 +---- Worker struct pointer
767 NB: This log record is masked by default.
769
771 Timestamps are inserted in the log on completing certain events during
772 the worker thread's task handling. The timestamps has a label showing
773 which event was completed. The reported fields show the absolute time
774 of the event, the time spent since the start of the task and the time
775 spent since the last timestamp was logged.
776 The timestamps logged automatically by Varnish are inserted after com‐
778 pleting events that are expected to have delays (e.g. network IO or
779 spending time on a waitinglist). Timestamps can also be inserted from
780 VCL using the std.timestamp() function. If one is doing time consuming
781 tasks in the VCL configuration, it's a good idea to log a timestamp af‐
782 ter completing that task. This keeps the timing information in subse‐
783 quent timestamps from including the time spent on the VCL event.
784 Request handling timestamps
786 Start The start of request processing (first byte received or
787 restart).
788 Req Complete client request received.
790 ReqBody
792 Client request body processed (discarded, cached or passed to
793 the backend).
794 Waitinglist
796 Came off waitinglist.
797 Fetch Fetch processing finished (completely fetched or ready for
799 streaming).
800 Process
802 Processing finished, ready to deliver the client response.
803 Resp Delivery of response to the client finished.
805 Restart
807 Client request is being restarted.
808 Pipe handling timestamps
810 The following timestamps are client timestamps specific to pipe trans‐
811 actions:
812 Pipe Opened a pipe to the backend and forwarded the request.
814 PipeSess
816 The pipe session has finished.
817 The following timestamps change meaning in a pipe transaction:
819 Process
821 Processing finished, ready to begin the pipe delivery.
822 Backend fetch timestamps
824 Start Start of the backend fetch processing.
825 Fetch Came off vcl_backend_fetch ready to send the backend request.
827 Connected
829 Successfully established a backend connection, or selected a re‐
830 cycled connection from the pool.
831 Bereq Backend request sent.
833 Beresp Backend response headers received.
835 Process
837 Processing finished, ready to fetch the response body.
838 BerespBody
840 Backend response body received.
841 Retry Backend request is being retried.
843 Error Backend request failed to vcl_backend_error.
845
847 Notice messages contain informational messages about the handling of a
848 request. These can be exceptional circumstances encountered that causes
849 deviation from the normal handling. The messages are prefixed with vsl:
850 for core Varnish generated messages, and VMOD authors are encouraged to
851 use vmod_<name>: for their own notice messages. This matches the name
852 of the manual page where detailed descriptions of notice messages are
853 expected.
854 The core messages are described below.
856 Conditional fetch wait for streaming object
858 The backend answered 304 Not Modified on a conditional fetch using an
859 object that has not yet been fully fetched as the stale template ob‐
860 ject. This can only happen when the TTL of the object is less than the
861 time it takes to fetch it. The fetch is halted until the stale object
862 is fully fetched, upon which the new object is created as normal. While
863 waiting, any grace time on the stale object will be in effect.
864 High number of variants
866 Objects are primarily looked up from an index using the hash key com‐
867 puted from the hash_data() VCL function. When variants are involved,
868 that is to say when a backend response was stored with a Vary header, a
869 secondary lookup is performed but it is not indexed. As the number of
870 variants for a given key increases, this can slow cache lookups down,
871 and since this happens under a lock, this can greatly increase lock
872 contention, even more so for frequently requested objects. Variants
873 should therefore be used sparingly on cacheable responses, but since
874 they can originate from either VCL or origin servers, this notice
875 should help identify problematic resources.
876
878 This document was initially written by Poul-Henning Kamp, and later up‐
879 dated by Martin Blix Grydeland.
880
882 • varnishhist(1)
883 • varnishlog(1)
885 • varnishncsa(1)
887 • varnishtop(1)
889
891 This document is licensed under the same licence as Varnish itself. See
892 LICENCE for details.
893 • Copyright (c) 2006 Verdens Gang AS
895 • Copyright (c) 2006-2015 Varnish Software AS
897 VSL(7)