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
16 request.
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
28 reserved 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 ]
36 | | |
37 | | +- Optional reason
38 | +------ Backend display name
39 +--------- Connection file descriptor
40 BackendOpen - Backend connection opened
42 Logged when a new backend connection is opened.
43 The format is:
45 %d %s %s %s %s %s
47 | | | | | |
48 | | | | | +- Local port
49 | | | | +---- Local address
50 | | | +------- Remote port
51 | | +---------- Remote address
52 | +------------- Backend display name
53 +---------------- Connection file descriptor
54 BackendReuse - Backend connection put up for reuse
56 Logged when a backend connection is put up for reuse by a later
57 connection.
58 The format is:
60 %d %s
62 | |
63 | +- Backend display name
64 +---- Connection file descriptor
65 BackendStart - Backend request start
67 Start of backend processing. Logs the backend IP address and
68 port number.
69 The format is:
71 %s %s
73 | |
74 | +- Backend Port number
75 +---- Backend IP4/6 address
76 NOTE: This tag is currently not in use in the Varnish log. It
78 is mentioned here to document legacy versions of the log, or
79 reserved for possible use in future versions.
80 Backend_health - Backend health check
82 The result of a backend health probe.
83 The format is:
85 %s %s %s %s %u %u %u %f %f %s
87 | | | | | | | | | |
88 | | | | | | | | | +- Probe HTTP response / error information
89 | | | | | | | | +---- Average response time
90 | | | | | | | +------- Response time
91 | | | | | | +---------- Probe window size
92 | | | | | +------------- Probe threshold level
93 | | | | +---------------- Number of good probes in window
94 | | | +------------------- Probe window bits
95 | | +---------------------- "healthy" or "sick"
96 | +------------------------- "Back", "Still" or "Went"
97 +---------------------------- Backend name
98 Probe window bits are:
100 '4': Good IPv4
102 '6': Good IPv6
103 'U': Good UNIX
104 'x': Error Xmit
105 'X': Good Xmit
106 'r': Error Recv
107 'R': Good Recv
108 'H': Happy
109 Begin - Marks the start of a VXID
111 The first record of a VXID transaction.
112 The format is:
114 %s %d %s
116 | | |
117 | | +- Reason
118 | +---- Parent vxid
119 +------- Type ("sess", "req" or "bereq")
120 BereqAcct - Backend request accounting
122 Contains byte counters from backend request processing.
123 The format is:
125 %d %d %d %d %d %d
127 | | | | | |
128 | | | | | +- Total bytes received
129 | | | | +---- Body bytes received
130 | | | +------- Header bytes received
131 | | +---------- Total bytes transmitted
132 | +------------- Body bytes transmitted
133 +---------------- Header bytes transmitted
134 BereqHeader - Backend request header
136 HTTP header contents.
137 The format is:
139 %s: %s
141 | |
142 | +- Header value
143 +----- Header name
144 NOTE: HTTP header fields are free form records and not strictly
146 made of 2 fields. Accessing a specific header with the prefix
147 notation helps treating the header value as a single string.
148 BereqMethod - Backend request method
150 The HTTP request method used.
151 BereqProtocol - Backend request protocol
153 The HTTP protocol version information.
154 BereqURL - Backend request URL
156 The HTTP request URL.
157 BerespHeader - Backend response header
159 HTTP header contents.
160 The format is:
162 %s: %s
164 | |
165 | +- Header value
166 +----- Header name
167 NOTE: HTTP header fields are free form records and not strictly
169 made of 2 fields. Accessing a specific header with the prefix
170 notation helps treating the header value as a single string.
171 BerespProtocol - Backend response protocol
173 The HTTP protocol version information.
174 BerespReason - Backend response reason
176 The HTTP response reason string.
177 BerespStatus - Backend response status
179 The HTTP response status code.
180 BogoHeader - Bogus HTTP received
182 Contains the first 20 characters of received HTTP headers we
183 could not make sense of. Applies to both req.http and
184 beresp.http.
185 CLI - CLI communication
187 CLI communication between varnishd master and child process.
188 Debug - Debug messages
190 Debug messages can normally be ignored, but are sometimes help‐
191 ful during trouble-shooting. Most debug messages must be
192 explicitly enabled with parameters.
193 Debug messages may be added, changed or removed without prior
195 notice and shouldn't be considered stable.
196 NB: This log record is masked by default.
198 ESI_xmlerror - ESI parser error or warning message
200 An error or warning was generated during parsing of an ESI
201 object. The log record describes the problem encountered.
202 End - Marks the end of a VXID
204 The last record of a VXID transaction.
205 Error - Error messages
207 Error messages are stuff you probably want to know.
208 ExpBan - Object evicted due to ban
210 Logs the VXID when an object is banned.
211 ExpKill - Object expiry event
213 Logs events related to object expiry. The events are:
214 EXP_Rearm
216 Logged when the expiry time of an object changes.
217 EXP_Inbox
219 Logged when the expiry thread picks an object from the
220 inbox for processing.
221 EXP_Kill
223 Logged when the expiry thread kills an object from the
224 inbox.
225 EXP_When
227 Logged when the expiry thread moves an object on the bin‐
228 heap.
229 EXP_Expired
231 Logged when the expiry thread expires an object.
232 LRU_Cand
234 Logged when an object is evaluated for LRU force expiry.
235 LRU Logged when an object is force expired due to LRU.
237 LRU_Fail
239 Logged when no suitable candidate object is found for LRU
240 force expiry.
241 The format is:
243 EXP_Rearm p=%p E=%f e=%f f=0x%x
245 EXP_Inbox p=%p e=%f f=0x%x
246 EXP_Kill p=%p e=%f f=0x%x
247 EXP_When p=%p e=%f f=0x%x
248 EXP_Expired x=%u t=%f
249 LRU_Cand p=%p f=0x%x r=%d
250 LRU x=%u
251 LRU_Fail
252 Legend:
254 p=%p Objcore pointer
255 t=%f Remaining TTL (s)
256 e=%f Expiry time (unix epoch)
257 E=%f Old expiry time (unix epoch)
258 f=0x%x Objcore flags
259 r=%d Objcore refcount
260 x=%u Object VXID
261 FetchError - Error while fetching object
263 Logs the error message of a failed fetch operation.
264 Error messages should be self-explanatory, yet the http connec‐
266 tion (HTC) class of errors is reported with these symbols:
267 · junk (-5): Received unexpected data
269 · close (-4): Connection closed
271 · timeout (-3): Timed out
273 · overflow (-2): Buffer/workspace too small
275 · eof (-1): Unexpected end of input
277 · empty (0): Empty response
279 · more (1): More data required
281 · complete (2): Data complete (no error)
283 · idle (3): Connection was closed while idle
285 Notice that some HTC errors are never emitted.
287 Fetch_Body - Body fetched from backend
289 Ready to fetch body from backend.
290 The format is:
292 %d %s %s
294 | | |
295 | | +---- 'stream' or '-'
296 | +------- Text description of body fetch mode
297 +---------- Body fetch mode
298 Filters - Body filters
300 List of filters applied to the body
301 Gzip - G(un)zip performed on object
303 A Gzip record is emitted for each instance of gzip or gunzip
304 work performed. Worst case, an ESI transaction stored in gzip'ed
305 objects but delivered gunziped, will run into many of these.
306 The format is:
308 %c %c %c %d %d %d %d %d
310 | | | | | | | |
311 | | | | | | | +- Bit length of compressed data
312 | | | | | | +---- Bit location of 'last' bit
313 | | | | | +------- Bit location of first deflate block
314 | | | | +---------- Bytes output
315 | | | +------------- Bytes input
316 | | +---------------- 'E': ESI, '-': Plain object
317 | +------------------- 'F': Fetch, 'D': Deliver
318 +---------------------- 'G': Gzip, 'U': Gunzip, 'u': Gunzip-test
319 Examples:
321 U F E 182 159 80 80 1392
323 G F E 159 173 80 1304 1314
324 H2RxBody - Received HTTP2 frame body
326 Binary data
327 H2RxHdr - Received HTTP2 frame header
329 Binary data
330 H2TxBody - Transmitted HTTP2 frame body
332 Binary data
333 H2TxHdr - Transmitted HTTP2 frame header
335 Binary data
336 Hash - Value added to hash
338 This value was added to the object lookup hash.
339 NB: This log record is masked by default.
341 Hit - Hit object in cache
343 Object looked up in cache.
344 The format is:
346 %u %f %f %f
348 | | | |
349 | | | +- Keep period
350 | | +---- Grace period
351 | +------- Remaining TTL
352 +---------- VXID of the object
353 HitMiss - Hit for miss object in cache.
355 Hit-for-miss object looked up in cache.
356 The format is:
358 %u %f
360 | |
361 | +- Remaining TTL
362 +---- VXID of the object
363 HitPass - Hit for pass object in cache.
365 Hit-for-pass object looked up in cache.
366 The format is:
368 %u %f
370 | |
371 | +- Remaining TTL
372 +---- VXID of the object
373 HttpGarbage - Unparseable HTTP request
375 Logs the content of unparseable HTTP requests.
376 Length - Size of object body
378 Logs the size of a fetch object body.
379 Link - Links to a child VXID
381 Links this VXID to any child VXID it initiates.
382 The format is:
384 %s %d %s
386 | | |
387 | | +- Reason
388 | +---- Child vxid
389 +------- Child type ("req" or "bereq")
390 LostHeader - Failed attempt to set HTTP header
392 Logs the header name of a failed HTTP header operation due to
393 resource exhaustion or configured limits.
394 Notice - Informational messages about request handling
396 Informational log messages on events occured during request han‐
397 dling.
398 The format is:
400 %s: %s
402 | |
403 | +- Short description of the notice message
404 +----- Manual page containing the detailed description
405 See the NOTICE MESSAGES section below or the individual VMOD
407 manual pages for detailed information of notice messages.
408 ObjHeader - Object header
410 HTTP header contents.
411 The format is:
413 %s: %s
415 | |
416 | +- Header value
417 +----- Header name
418 NOTE: HTTP header fields are free form records and not strictly
420 made of 2 fields. Accessing a specific header with the prefix
421 notation helps treating the header value as a single string.
422 ObjProtocol - Object protocol
424 The HTTP protocol version information.
425 ObjReason - Object reason
427 The HTTP response reason string.
428 ObjStatus - Object status
430 The HTTP response status code.
431 PipeAcct - Pipe byte counts
433 Contains byte counters for pipe sessions.
434 The format is:
436 %d %d %d %d
438 | | | |
439 | | | +------- Piped bytes to client
440 | | +---------- Piped bytes from client
441 | +------------- Backend request headers
442 +---------------- Client request headers
443 Proxy - PROXY protocol information
445 PROXY protocol information.
446 The format is:
448 %d %s %d %s %d
450 | | | | |
451 | | | | +- server port
452 | | | +---- server ip
453 | | +------- client port
454 | +---------- client ip
455 +------------- PROXY protocol version
456 All fields are "local" for PROXY local connections (command 0x0)
458 ProxyGarbage - Unparseable PROXY request
460 A PROXY protocol header was unparseable.
461 ReqAcct - Request handling byte counts
463 Contains byte counts for the request handling. The body bytes
464 count includes transmission overhead (ie: chunked encoding).
465 ESI sub-requests show the body bytes this ESI fragment including
466 any subfragments contributed to the top level request. The for‐
467 mat is:
468 %d %d %d %d %d %d
470 | | | | | |
471 | | | | | +- Total bytes transmitted
472 | | | | +---- Body bytes transmitted
473 | | | +------- Header bytes transmitted
474 | | +---------- Total bytes received
475 | +------------- Body bytes received
476 +---------------- Header bytes received
477 ReqHeader - Client request header
479 HTTP header contents.
480 The format is:
482 %s: %s
484 | |
485 | +- Header value
486 +----- Header name
487 NOTE: HTTP header fields are free form records and not strictly
489 made of 2 fields. Accessing a specific header with the prefix
490 notation helps treating the header value as a single string.
491 ReqMethod - Client request method
493 The HTTP request method used.
494 ReqProtocol - Client request protocol
496 The HTTP protocol version information.
497 ReqStart - Client request start
499 Start of request processing. Logs the client address, port num‐
500 ber and listener endpoint name (from the -a command-line argu‐
501 ment).
502 The format is:
504 %s %s %s
506 | | |
507 | | +-- Listener name (from -a)
508 | +----- Client Port number (0 for Unix domain sockets)
509 +-------- Client IP4/6 address (0.0.0.0 for UDS)
510 ReqURL - Client request URL
512 The HTTP request URL.
513 RespHeader - Client response header
515 HTTP header contents.
516 The format is:
518 %s: %s
520 | |
521 | +- Header value
522 +----- Header name
523 NOTE: HTTP header fields are free form records and not strictly
525 made of 2 fields. Accessing a specific header with the prefix
526 notation helps treating the header value as a single string.
527 RespProtocol - Client response protocol
529 The HTTP protocol version information.
530 RespReason - Client response reason
532 The HTTP response reason string.
533 RespStatus - Client response status
535 The HTTP response status code.
536 SessClose - Client connection closed
538 SessClose is the last record for any client connection.
539 The format is:
541 %s %f
543 | |
544 | +- How long the session was open
545 +---- Why the connection closed
546 SessError - Client connection accept failed
548 Accepting a client connection has failed.
549 The format is:
551 %s %s %s %d %d %s
553 | | | | | |
554 | | | | | +- Detailed error message
555 | | | | +---- Error Number (errno) from accept(2)
556 | | | +------- File descriptor number
557 | | +---------- Local TCP port / 0 for UDS
558 | +------------- Local IPv4/6 address / 0.0.0.0 for UDS
559 +---------------- Socket name (from -a argument)
560 SessOpen - Client connection opened
562 The first record for a client connection, with the socket-end‐
563 points of the connection.
564 The format is:
566 %s %d %s %s %s %d
568 | | | | | |
569 | | | | | +- File descriptor number
570 | | | | +---- Local TCP port / 0 for UDS
571 | | | +------- Local IPv4/6 address / 0.0.0.0 for UDS
572 | | +---------- Socket name (from -a argument)
573 | +------------- Remote TCP port / 0 for UDS
574 +---------------- Remote IPv4/6 address / 0.0.0.0 for UDS
575 Storage - Where object is stored
577 Type and name of the storage backend the object is stored in.
578 The format is:
580 %s %s
582 | |
583 | +- Name of storage backend
584 +---- Type ("malloc", "file", "persistent" etc.)
585 TTL - TTL set on object
587 A TTL record is emitted whenever the ttl, grace or keep values
588 for an object is set as well as whether the object is cacheable
589 or not.
590 The format is:
592 %s %d %d %d %d [ %d %d %u %u ] %s
594 | | | | | | | | | |
595 | | | | | | | | | +- "cacheable" or "uncacheable"
596 | | | | | | | | +------ Max-Age from Cache-Control header
597 | | | | | | | +--------- Expires header
598 | | | | | | +------------ Date header
599 | | | | | +--------------- Age (incl Age: header value)
600 | | | | +-------------------- Reference time for TTL
601 | | | +----------------------- Keep
602 | | +-------------------------- Grace
603 | +----------------------------- TTL
604 +-------------------------------- "RFC", "VCL" or "HFP"
605 The four optional fields are only present in "RFC" headers.
607 Examples:
609 RFC 60 10 -1 1312966109 1312966109 1312966109 0 60 cacheable
611 VCL 120 10 0 1312966111 uncacheable
612 HFP 2 0 0 1312966113 uncacheable
613 Timestamp - Timing information
615 Contains timing information for the Varnish worker threads.
616 Time stamps are issued by Varnish on certain events, and show
618 the absolute time of the event, the time spent since the start
619 of the work unit, and the time spent since the last timestamp
620 was logged. See the TIMESTAMPS section below for information
621 about the individual time stamps.
622 The format is:
624 %s: %f %f %f
626 | | | |
627 | | | +- Time since last timestamp
628 | | +---- Time since start of work unit
629 | +------- Absolute time of event
630 +----------- Event label
631 VCL_Error - VCL execution error message
633 Logs error messages generated during VCL execution.
634 VCL_Log - Log statement from VCL
636 User generated log messages insert from VCL through std.log()
637 VCL_acl - VCL ACL check results
639 Logs VCL ACL evaluation results.
640 The format is:
642 %s [%s [%s]]
644 | | |
645 | | +- Matching entry (only for MATCH)
646 | +----- Name of the ACL for MATCH or NO_MATCH
647 +--------- MATCH, NO_MATCH or NO_FAM
648 MATCH denotes an ACL match NO_MATCH denotes that a checked ACL
650 has not matched NO_FAM denotes a missing address family and
651 should not occur.
652 VCL_call - VCL method called
654 Logs the VCL method name when a VCL method is called.
655 VCL_return - VCL method return value
657 Logs the VCL method terminating statement.
658 VCL_trace - VCL trace data
660 Logs VCL execution trace data.
661 The format is:
663 %s %u %u.%u.%u
665 | | | | |
666 | | | | +- VCL program line position
667 | | | +---- VCL program line number
668 | | +------- VCL program source index
669 | +---------- VCL trace point index
670 +------------- VCL configname
671 NB: This log record is masked by default.
673 VCL_use - VCL in use
675 Records the name of the VCL being used.
676 The format is:
678 %s [ %s %s ]
680 | | |
681 | | +- Name of label used to find it
682 | +---- "via"
683 +--------- Name of VCL put in use
684 VSL - VSL API warnings and error message
686 Warnings and error messages generated by the VSL API while read‐
687 ing the shared memory log.
688 VfpAcct - Fetch filter accounting
690 Contains name of VFP and statistics.
691 The format is:
693 %s %d %d
695 | | |
696 | | +- Total bytes produced
697 | +---- Number of calls made
698 +------- Name of filter
699 NB: This log record is masked by default.
701 Witness - Lock order witness records
703 Diagnostic recording of locking order.
704 WorkThread - Logs thread start/stop events
706 Logs worker thread creation and termination events.
707 The format is:
709 %p %s
711 | |
712 | +- [start|end]
713 +---- Worker struct pointer
714 NB: This log record is masked by default.
716
718 Timestamps are inserted in the log on completing certain events during
719 the worker thread's task handling. The timestamps has a label showing
720 which event was completed. The reported fields show the absolute time
721 of the event, the time spent since the start of the task and the time
722 spent since the last timestamp was logged.
723 The timestamps logged automatically by Varnish are inserted after com‐
725 pleting events that are expected to have delays (e.g. network IO or
726 spending time on a waitinglist). Timestamps can also be inserted from
727 VCL using the std.timestamp() function. If one is doing time consuming
728 tasks in the VCL configuration, it's a good idea to log a timestamp
729 after completing that task. This keeps the timing information in subse‐
730 quent timestamps from including the time spent on the VCL event.
731 Request handling timestamps
733 Start The start of request processing (first byte received or
734 restart).
735 Req Complete client request received.
737 ReqBody
739 Client request body processed (discarded, cached or passed to
740 the backend).
741 Waitinglist
743 Came off waitinglist.
744 Fetch Fetch processing finished (completely fetched or ready for
746 streaming).
747 Process
749 Processing finished, ready to deliver the client response.
750 Resp Delivery of response to the client finished.
752 Restart
754 Client request is being restarted.
755 Pipe handling timestamps
757 Pipe Opened a pipe to the backend and forwarded the request.
758 PipeSess
760 The pipe session has finished.
761 Backend fetch timestamps
763 Start Start of the backend fetch processing.
764 Bereq Backend request sent.
766 Beresp Backend response headers received.
768 BerespBody
770 Backend response body received.
771 Retry Backend request is being retried.
773 Error Backend request failed to vcl_backend_error.
775
777 Notice messages contain informational messages about the handling of a
778 request. These can be exceptional circumstances encountered that causes
779 deviation from the normal handling. The messages are prefixed with vsl
780 for core Varnish generated messages, and VMOD authors are encouraged to
781 use vmod_<name> for their own notice messages. This matches the name of
782 the manual page where detailed descriptions of notice messages are
783 expected.
784 The core messages are described below.
786 Conditional fetch wait for streaming object
788 The backend answered 304 Not Modified on a conditional fetch using an
789 object that has not yet been fully fetched as the stale template
790 object. This can only happen when the TTL of the object is less than
791 the time it takes to fetch it. The fetch is halted until the stale
792 object is fully fetched, upon which the new object is created as nor‐
793 mal. While waiting, any grace time on the stale object will be in
794 effect.
795
797 This document was initially written by Poul-Henning Kamp, and later
798 updated by Martin Blix Grydeland.
799
801 · varnishhist(1)
802 · varnishlog(1)
804 · varnishncsa(1)
806 · varnishtop(1)
808
810 This document is licensed under the same licence as Varnish itself. See
811 LICENCE for details.
812 · Copyright (c) 2006 Verdens Gang AS
814 · Copyright (c) 2006-2015 Varnish Software AS
816 VSL(7)