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 '4': Good IPv4
108 '6': Good IPv6
109 'U': Good UNIX
110 'x': Error Xmit
111 'X': Good Xmit
112 'r': Error Recv
113 'R': Good Recv
114 'H': Happy
115 Begin - Marks the start of a VXID
117 The first record of a VXID transaction.
118 The format is:
120 %s %d %s
122 | | |
123 | | +- Reason
124 | +---- Parent vxid
125 +------- Type ("sess", "req" or "bereq")
126 BereqAcct - Backend request accounting
128 Contains byte counters from backend request processing.
129 The format is:
131 %d %d %d %d %d %d
133 | | | | | |
134 | | | | | +- Total bytes received
135 | | | | +---- Body bytes received
136 | | | +------- Header bytes received
137 | | +---------- Total bytes transmitted
138 | +------------- Body bytes transmitted
139 +---------------- Header bytes transmitted
140 BereqHeader - Backend request header
142 HTTP header contents.
143 The format is:
145 %s: %s
147 | |
148 | +- Header value
149 +----- Header name
150 NOTE: HTTP header fields are free form records and not strictly
152 made of 2 fields. Accessing a specific header with the prefix
153 notation helps treating the header value as a single string.
154 BereqMethod - Backend request method
156 The HTTP request method used.
157 BereqProtocol - Backend request protocol
159 The HTTP protocol version information.
160 BereqURL - Backend request URL
162 The HTTP request URL.
163 BerespHeader - Backend response header
165 HTTP header contents.
166 The format is:
168 %s: %s
170 | |
171 | +- Header value
172 +----- Header name
173 NOTE: HTTP header fields are free form records and not strictly
175 made of 2 fields. Accessing a specific header with the prefix
176 notation helps treating the header value as a single string.
177 BerespProtocol - Backend response protocol
179 The HTTP protocol version information.
180 BerespReason - Backend response reason
182 The HTTP response reason string.
183 BerespStatus - Backend response status
185 The HTTP response status code.
186 BogoHeader - Bogus HTTP received
188 Contains the first 20 characters of received HTTP headers we
189 could not make sense of. Applies to both req.http and
190 beresp.http.
191 CLI - CLI communication
193 CLI communication between varnishd master and child process.
194 Debug - Debug messages
196 Debug messages can normally be ignored, but are sometimes help‐
197 ful during trouble-shooting. Most debug messages must be ex‐
198 plicitly enabled with parameters.
199 Debug messages may be added, changed or removed without prior
201 notice and shouldn't be considered stable.
202 NB: This log record is masked by default.
204 ESI_xmlerror - ESI parser error or warning message
206 An error or warning was generated during parsing of an ESI ob‐
207 ject. The log record describes the problem encountered.
208 End - Marks the end of a VXID
210 The last record of a VXID transaction.
211 Error - Error messages
213 Error messages are stuff you probably want to know.
214 ExpBan - Object evicted due to ban
216 Logs the VXID when an object is banned.
217 ExpKill - Object expiry event
219 Logs events related to object expiry. The events are:
220 EXP_Rearm
222 Logged when the expiry time of an object changes.
223 EXP_Inbox
225 Logged when the expiry thread picks an object from the
226 inbox for processing.
227 EXP_Kill
229 Logged when the expiry thread kills an object from the
230 inbox.
231 EXP_When
233 Logged when the expiry thread moves an object on the bin‐
234 heap.
235 EXP_Expired
237 Logged when the expiry thread expires an object.
238 LRU_Cand
240 Logged when an object is evaluated for LRU force expiry.
241 LRU Logged when an object is force expired due to LRU.
243 LRU_Fail
245 Logged when no suitable candidate object is found for LRU
246 force expiry.
247 The format is:
249 EXP_Rearm p=%p E=%f e=%f f=0x%x
251 EXP_Inbox p=%p e=%f f=0x%x
252 EXP_Kill p=%p e=%f f=0x%x
253 EXP_When p=%p e=%f f=0x%x
254 EXP_Expired x=%u t=%f
255 LRU_Cand p=%p f=0x%x r=%d
256 LRU x=%u
257 LRU_Fail
258 Legend:
260 p=%p Objcore pointer
261 t=%f Remaining TTL (s)
262 e=%f Expiry time (unix epoch)
263 E=%f Old expiry time (unix epoch)
264 f=0x%x Objcore flags
265 r=%d Objcore refcount
266 x=%u Object VXID
267 FetchError - Error while fetching object
269 Logs the error message of a failed fetch operation.
270 Error messages should be self-explanatory, yet the http connec‐
272 tion (HTC) class of errors is reported with these symbols:
273 • junk (-5): Received unexpected data
275 • close (-4): Connection closed
277 • timeout (-3): Timed out
279 • overflow (-2): Buffer/workspace too small
281 • eof (-1): Unexpected end of input
283 • empty (0): Empty response
285 • more (1): More data required
287 • complete (2): Data complete (no error)
289 • idle (3): Connection was closed while idle
291 Notice that some HTC errors are never emitted.
293 Fetch_Body - Body fetched from backend
295 Ready to fetch body from backend.
296 The format is:
298 %d %s %s
300 | | |
301 | | +---- 'stream' or '-'
302 | +------- Text description of body fetch mode
303 +---------- Body fetch mode
304 Filters - Body filters
306 List of filters applied to the body
307 Gzip - G(un)zip performed on object
309 A Gzip record is emitted for each instance of gzip or gunzip
310 work performed. Worst case, an ESI transaction stored in gzip'ed
311 objects but delivered gunziped, will run into many of these.
312 The format is:
314 %c %c %c %d %d %d %d %d
316 | | | | | | | |
317 | | | | | | | +- Bit length of compressed data
318 | | | | | | +---- Bit location of 'last' bit
319 | | | | | +------- Bit location of first deflate block
320 | | | | +---------- Bytes output
321 | | | +------------- Bytes input
322 | | +---------------- 'E': ESI, '-': Plain object
323 | +------------------- 'F': Fetch, 'D': Deliver
324 +---------------------- 'G': Gzip, 'U': Gunzip, 'u': Gunzip-test
325 Examples:
327 U F E 182 159 80 80 1392
329 G F E 159 173 80 1304 1314
330 H2RxBody - Received HTTP2 frame body
332 Binary data
333 H2RxHdr - Received HTTP2 frame header
335 Binary data
336 H2TxBody - Transmitted HTTP2 frame body
338 Binary data
339 H2TxHdr - Transmitted HTTP2 frame header
341 Binary data
342 Hash - Value added to hash
344 This value was added to the object lookup hash.
345 NB: This log record is masked by default.
347 Hit - Hit object in cache
349 Object looked up in cache.
350 The format is:
352 %u %f %f %f
354 | | | |
355 | | | +- Keep period
356 | | +---- Grace period
357 | +------- Remaining TTL
358 +---------- VXID of the object
359 HitMiss - Hit for miss object in cache.
361 Hit-for-miss object looked up in cache.
362 The format is:
364 %u %f
366 | |
367 | +- Remaining TTL
368 +---- VXID of the object
369 HitPass - Hit for pass object in cache.
371 Hit-for-pass object looked up in cache.
372 The format is:
374 %u %f
376 | |
377 | +- Remaining TTL
378 +---- VXID of the object
379 HttpGarbage - Unparseable HTTP request
381 Logs the content of unparseable HTTP requests.
382 Length - Size of object body
384 Logs the size of a fetch object body.
385 Link - Links to a child VXID
387 Links this VXID to any child VXID it initiates.
388 The format is:
390 %s %d %s
392 | | |
393 | | +- Reason
394 | +---- Child vxid
395 +------- Child type ("req" or "bereq")
396 LostHeader - Failed attempt to set HTTP header
398 Logs the header name of a failed HTTP header operation due to
399 resource exhaustion or configured limits.
400 Notice - Informational messages about request handling
402 Informational log messages on events occured during request han‐
403 dling.
404 The format is:
406 %s: %s
408 | |
409 | +- Short description of the notice message
410 +----- Manual page containing the detailed description
411 See the NOTICE MESSAGES section below or the individual VMOD
413 manual pages for detailed information of notice messages.
414 ObjHeader - Object header
416 HTTP header contents.
417 The format is:
419 %s: %s
421 | |
422 | +- Header value
423 +----- Header name
424 NOTE: HTTP header fields are free form records and not strictly
426 made of 2 fields. Accessing a specific header with the prefix
427 notation helps treating the header value as a single string.
428 ObjProtocol - Object protocol
430 The HTTP protocol version information.
431 ObjReason - Object reason
433 The HTTP response reason string.
434 ObjStatus - Object status
436 The HTTP response status code.
437 PipeAcct - Pipe byte counts
439 Contains byte counters for pipe sessions.
440 The format is:
442 %d %d %d %d
444 | | | |
445 | | | +------- Piped bytes to client
446 | | +---------- Piped bytes from client
447 | +------------- Backend request headers
448 +---------------- Client request headers
449 Proxy - PROXY protocol information
451 PROXY protocol information.
452 The format is:
454 %d %s %d %s %d
456 | | | | |
457 | | | | +- server port
458 | | | +---- server ip
459 | | +------- client port
460 | +---------- client ip
461 +------------- PROXY protocol version
462 All fields are "local" for PROXY local connections (command 0x0)
464 ProxyGarbage - Unparseable PROXY request
466 A PROXY protocol header was unparseable.
467 ReqAcct - Request handling byte counts
469 Contains byte counts for the request handling. The body bytes
470 count includes transmission overhead (ie: chunked encoding).
471 ESI sub-requests show the body bytes this ESI fragment including
472 any subfragments contributed to the top level request. The for‐
473 mat is:
474 %d %d %d %d %d %d
476 | | | | | |
477 | | | | | +- Total bytes transmitted
478 | | | | +---- Body bytes transmitted
479 | | | +------- Header bytes transmitted
480 | | +---------- Total bytes received
481 | +------------- Body bytes received
482 +---------------- Header bytes received
483 ReqHeader - Client request header
485 HTTP header contents.
486 The format is:
488 %s: %s
490 | |
491 | +- Header value
492 +----- Header name
493 NOTE: HTTP header fields are free form records and not strictly
495 made of 2 fields. Accessing a specific header with the prefix
496 notation helps treating the header value as a single string.
497 ReqMethod - Client request method
499 The HTTP request method used.
500 ReqProtocol - Client request protocol
502 The HTTP protocol version information.
503 ReqStart - Client request start
505 Start of request processing. Logs the client address, port num‐
506 ber and listener endpoint name (from the -a command-line argu‐
507 ment).
508 The format is:
510 %s %s %s
512 | | |
513 | | +-- Listener name (from -a)
514 | +----- Client Port number (0 for Unix domain sockets)
515 +-------- Client IP4/6 address (0.0.0.0 for UDS)
516 ReqURL - Client request URL
518 The HTTP request URL.
519 RespHeader - Client response header
521 HTTP header contents.
522 The format is:
524 %s: %s
526 | |
527 | +- Header value
528 +----- Header name
529 NOTE: HTTP header fields are free form records and not strictly
531 made of 2 fields. Accessing a specific header with the prefix
532 notation helps treating the header value as a single string.
533 RespProtocol - Client response protocol
535 The HTTP protocol version information.
536 RespReason - Client response reason
538 The HTTP response reason string.
539 RespStatus - Client response status
541 The HTTP response status code.
542 SessClose - Client connection closed
544 SessClose is the last record for any client connection.
545 The format is:
547 %s %f
549 | |
550 | +- How long the session was open
551 +---- Why the connection closed
552 SessError - Client connection accept failed
554 Accepting a client connection has failed.
555 The format is:
557 %s %s %s %d %d %s
559 | | | | | |
560 | | | | | +- Detailed error message
561 | | | | +---- Error Number (errno) from accept(2)
562 | | | +------- File descriptor number
563 | | +---------- Local TCP port / 0 for UDS
564 | +------------- Local IPv4/6 address / 0.0.0.0 for UDS
565 +---------------- Socket name (from -a argument)
566 SessOpen - Client connection opened
568 The first record for a client connection, with the socket-end‐
569 points of the connection.
570 The format is:
572 %s %d %s %s %s %d
574 | | | | | |
575 | | | | | +- File descriptor number
576 | | | | +---- Local TCP port / 0 for UDS
577 | | | +------- Local IPv4/6 address / 0.0.0.0 for UDS
578 | | +---------- Socket name (from -a argument)
579 | +------------- Remote TCP port / 0 for UDS
580 +---------------- Remote IPv4/6 address / 0.0.0.0 for UDS
581 Storage - Where object is stored
583 Type and name of the storage backend the object is stored in.
584 The format is:
586 %s %s
588 | |
589 | +- Name of storage backend
590 +---- Type ("malloc", "file", "persistent" etc.)
591 TTL - TTL set on object
593 A TTL record is emitted whenever the ttl, grace or keep values
594 for an object is set as well as whether the object is cacheable
595 or not.
596 The format is:
598 %s %d %d %d %d [ %d %d %u %u ] %s
600 | | | | | | | | | |
601 | | | | | | | | | +- "cacheable" or "uncacheable"
602 | | | | | | | | +------ Max-Age from Cache-Control header
603 | | | | | | | +--------- Expires header
604 | | | | | | +------------ Date header
605 | | | | | +--------------- Age (incl Age: header value)
606 | | | | +-------------------- Reference time for TTL
607 | | | +----------------------- Keep
608 | | +-------------------------- Grace
609 | +----------------------------- TTL
610 +-------------------------------- "RFC", "VCL" or "HFP"
611 The four optional fields are only present in "RFC" headers.
613 Examples:
615 RFC 60 10 -1 1312966109 1312966109 1312966109 0 60 cacheable
617 VCL 120 10 0 1312966111 uncacheable
618 HFP 2 0 0 1312966113 uncacheable
619 Timestamp - Timing information
621 Contains timing information for the Varnish worker threads.
622 Time stamps are issued by Varnish on certain events, and show
624 the absolute time of the event, the time spent since the start
625 of the work unit, and the time spent since the last timestamp
626 was logged. See the TIMESTAMPS section below for information
627 about the individual time stamps.
628 The format is:
630 %s: %f %f %f
632 | | | |
633 | | | +- Time since last timestamp
634 | | +---- Time since start of work unit
635 | +------- Absolute time of event
636 +----------- Event label
637 VCL_Error - VCL execution error message
639 Logs error messages generated during VCL execution.
640 VCL_Log - Log statement from VCL
642 User generated log messages insert from VCL through std.log()
643 VCL_acl - VCL ACL check results
645 Logs VCL ACL evaluation results.
646 The format is:
648 %s [%s [%s [fixed: %s]]]
650 | | | |
651 | | | +- Fixed entry (see vcc_acl_pedantic parameter)
652 | | +------------ Matching entry (only for MATCH)
653 | +---------------- Name of the ACL for MATCH or NO_MATCH
654 +-------------------- MATCH, NO_MATCH or NO_FAM
655 MATCH denotes an ACL match NO_MATCH denotes that a checked ACL
657 has not matched NO_FAM denotes a missing address family and
658 should not occur.
659 VCL_call - VCL method called
661 Logs the VCL method name when a VCL method is called.
662 VCL_return - VCL method return value
664 Logs the VCL method terminating statement.
665 VCL_trace - VCL trace data
667 Logs VCL execution trace data.
668 The format is:
670 %s %u %u.%u.%u
672 | | | | |
673 | | | | +- VCL program line position
674 | | | +---- VCL program line number
675 | | +------- VCL program source index
676 | +---------- VCL trace point index
677 +------------- VCL configname
678 NB: This log record is masked by default.
680 VCL_use - VCL in use
682 Records the name of the VCL being used.
683 The format is:
685 %s [ %s %s ]
687 | | |
688 | | +- Name of label used to find it
689 | +---- "via"
690 +--------- Name of VCL put in use
691 VSL - VSL API warnings and error message
693 Warnings and error messages generated by the VSL API while read‐
694 ing the shared memory log.
695 VfpAcct - Fetch filter accounting
697 Contains name of VFP and statistics.
698 The format is:
700 %s %d %d
702 | | |
703 | | +- Total bytes produced
704 | +---- Number of calls made
705 +------- Name of filter
706 NB: This log record is masked by default.
708 Witness - Lock order witness records
710 Diagnostic recording of locking order.
711 WorkThread - Logs thread start/stop events
713 Logs worker thread creation and termination events.
714 The format is:
716 %p %s
718 | |
719 | +- [start|end]
720 +---- Worker struct pointer
721 NB: This log record is masked by default.
723
725 Timestamps are inserted in the log on completing certain events during
726 the worker thread's task handling. The timestamps has a label showing
727 which event was completed. The reported fields show the absolute time
728 of the event, the time spent since the start of the task and the time
729 spent since the last timestamp was logged.
730 The timestamps logged automatically by Varnish are inserted after com‐
732 pleting events that are expected to have delays (e.g. network IO or
733 spending time on a waitinglist). Timestamps can also be inserted from
734 VCL using the std.timestamp() function. If one is doing time consuming
735 tasks in the VCL configuration, it's a good idea to log a timestamp af‐
736 ter completing that task. This keeps the timing information in subse‐
737 quent timestamps from including the time spent on the VCL event.
738 Request handling timestamps
740 Start The start of request processing (first byte received or
741 restart).
742 Req Complete client request received.
744 ReqBody
746 Client request body processed (discarded, cached or passed to
747 the backend).
748 Waitinglist
750 Came off waitinglist.
751 Fetch Fetch processing finished (completely fetched or ready for
753 streaming).
754 Process
756 Processing finished, ready to deliver the client response.
757 Resp Delivery of response to the client finished.
759 Restart
761 Client request is being restarted.
762 Pipe handling timestamps
764 Pipe Opened a pipe to the backend and forwarded the request.
765 PipeSess
767 The pipe session has finished.
768 Backend fetch timestamps
770 Start Start of the backend fetch processing.
771 Bereq Backend request sent.
773 Beresp Backend response headers received.
775 BerespBody
777 Backend response body received.
778 Retry Backend request is being retried.
780 Error Backend request failed to vcl_backend_error.
782
784 Notice messages contain informational messages about the handling of a
785 request. These can be exceptional circumstances encountered that causes
786 deviation from the normal handling. The messages are prefixed with vsl
787 for core Varnish generated messages, and VMOD authors are encouraged to
788 use vmod_<name> for their own notice messages. This matches the name of
789 the manual page where detailed descriptions of notice messages are ex‐
790 pected.
791 The core messages are described below.
793 Conditional fetch wait for streaming object
795 The backend answered 304 Not Modified on a conditional fetch using an
796 object that has not yet been fully fetched as the stale template ob‐
797 ject. This can only happen when the TTL of the object is less than the
798 time it takes to fetch it. The fetch is halted until the stale object
799 is fully fetched, upon which the new object is created as normal. While
800 waiting, any grace time on the stale object will be in effect.
801
803 This document was initially written by Poul-Henning Kamp, and later up‐
804 dated by Martin Blix Grydeland.
805
807 • varnishhist(1)
808 • varnishlog(1)
810 • varnishncsa(1)
812 • varnishtop(1)
814
816 This document is licensed under the same licence as Varnish itself. See
817 LICENCE for details.
818 • Copyright (c) 2006 Verdens Gang AS
820 • Copyright (c) 2006-2015 Varnish Software AS
822 VSL(7)