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.
27 It is mentioned here to document legacy versions of the log,
28 or 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.
78 It is mentioned here to document legacy versions of the log,
79 or 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 BereqMethod - Backend request method
146 The HTTP request method used.
147 BereqProtocol - Backend request protocol
149 The HTTP protocol version information.
150 BereqURL - Backend request URL
152 The HTTP request URL.
153 BerespHeader - Backend response header
155 HTTP header contents.
156 The format is:
158 %s: %s
160 | |
161 | +- Header value
162 +----- Header name
163 BerespProtocol - Backend response protocol
165 The HTTP protocol version information.
166 BerespReason - Backend response response
168 The HTTP response string received.
169 BerespStatus - Backend response status
171 The HTTP status code received.
172 BogoHeader - Bogus HTTP received
174 Contains the first 20 characters of received HTTP headers we
175 could not make sense of. Applies to both req.http and
176 beresp.http.
177 CLI - CLI communication
179 CLI communication between varnishd master and child process.
180 Debug - Debug messages
182 Debug messages can normally be ignored, but are sometimes help‐
183 ful during trouble-shooting. Most debug messages must be
184 explicitly enabled with parameters.
185 Debug messages may be added, changed or removed without prior
187 notice and shouldn't be considered stable.
188 NB: This log record is masked by default.
190 ESI_xmlerror - ESI parser error or warning message
192 An error or warning was generated during parsing of an ESI
193 object. The log record describes the problem encountered.
194 End - Marks the end of a VXID
196 The last record of a VXID transaction.
197 Error - Error messages
199 Error messages are stuff you probably want to know.
200 ExpBan - Object evicted due to ban
202 Logs the VXID when an object is banned.
203 ExpKill - Object expiry event
205 Logs events related to object expiry. The events are:
206 EXP_Rearm
208 Logged when the expiry time of an object changes.
209 EXP_Inbox
211 Logged when the expiry thread picks an object from the
212 inbox for processing.
213 EXP_Kill
215 Logged when the expiry thread kills an object from the
216 inbox.
217 EXP_When
219 Logged when the expiry thread moves an object on the bin‐
220 heap.
221 EXP_Expired
223 Logged when the expiry thread expires an object.
224 LRU_Cand
226 Logged when an object is evaluated for LRU force expiry.
227 LRU Logged when an object is force expired due to LRU.
229 LRU_Fail
231 Logged when no suitable candidate object is found for LRU
232 force expiry.
233 The format is:
235 EXP_Rearm p=%p E=%f e=%f f=0x%x
237 EXP_Inbox p=%p e=%f f=0x%x
238 EXP_Kill p=%p e=%f f=0x%x
239 EXP_When p=%p e=%f f=0x%x
240 EXP_Expired x=%u t=%f
241 LRU_Cand p=%p f=0x%x r=%d
242 LRU x=%u
243 LRU_Fail
244 Legend:
246 p=%p Objcore pointer
247 t=%f Remaining TTL (s)
248 e=%f Expiry time (unix epoch)
249 E=%f Old expiry time (unix epoch)
250 f=0x%x Objcore flags
251 r=%d Objcore refcount
252 x=%u Object VXID
253 FetchError - Error while fetching object
255 Logs the error message of a failed fetch operation.
256 Error messages should be self-explanatory, yet the http connec‐
258 tion(HTC) class of errors is reported with these symbols:
259 · junk (-5): Received unexpected data
261 · close (-4): Connection closed
263 · timeout (-3): Timed out
265 · overflow (-2): Buffer/workspace too small
267 · eof (-1): Unexpected end of input
269 · empty (0): Empty response
271 · more (1): More data required
273 · complete (2): Data complete (no error)
275 · idle (3): Connection was closed while idle
277 Notice that some HTC errors are never emitted.
279 Fetch_Body - Body fetched from backend
281 Ready to fetch body from backend.
282 The format is:
284 %d (%s) %s
286 | | |
287 | | +---- 'stream' or '-'
288 | +--------- Text description of body fetch mode
289 +------------- Body fetch mode
290 Filters - Body filters
292 List of filters applied to the body
293 Gzip - G(un)zip performed on object
295 A Gzip record is emitted for each instance of gzip or gunzip
296 work performed. Worst case, an ESI transaction stored in gzip'ed
297 objects but delivered gunziped, will run into many of these.
298 The format is:
300 %c %c %c %d %d %d %d %d
302 | | | | | | | |
303 | | | | | | | +- Bit length of compressed data
304 | | | | | | +---- Bit location of 'last' bit
305 | | | | | +------- Bit location of first deflate block
306 | | | | +---------- Bytes output
307 | | | +------------- Bytes input
308 | | +---------------- 'E': ESI, '-': Plain object
309 | +------------------- 'F': Fetch, 'D': Deliver
310 +---------------------- 'G': Gzip, 'U': Gunzip, 'u': Gunzip-test
311 Examples:
313 U F E 182 159 80 80 1392
315 G F E 159 173 80 1304 1314
316 H2RxBody - Received HTTP2 frame body
318 Binary data
319 H2RxHdr - Received HTTP2 frame header
321 Binary data
322 H2TxBody - Transmitted HTTP2 frame body
324 Binary data
325 H2TxHdr - Transmitted HTTP2 frame header
327 Binary data
328 Hash - Value added to hash
330 This value was added to the object lookup hash.
331 NB: This log record is masked by default.
333 Hit - Hit object in cache
335 Object looked up in cache.
336 The format is:
338 %u %f %f %f
340 | | | |
341 | | | +- Keep period
342 | | +---- Grace period
343 | +------- Remaining TTL
344 +---------- VXID of the object
345 HitMiss - Hit for miss object in cache.
347 Hit-for-miss object looked up in cache.
348 The format is:
350 %u %f
352 | |
353 | +- Remaining TTL
354 +---- VXID of the object
355 HitPass - Hit for pass object in cache.
357 Hit-for-pass object looked up in cache.
358 The format is:
360 %u %f
362 | |
363 | +- Remaining TTL
364 +---- VXID of the object
365 HttpGarbage - Unparseable HTTP request
367 Logs the content of unparseable HTTP requests.
368 Length - Size of object body
370 Logs the size of a fetch object body.
371 Link - Links to a child VXID
373 Links this VXID to any child VXID it initiates.
374 The format is:
376 %s %d %s
378 | | |
379 | | +- Reason
380 | +---- Child vxid
381 +------- Child type ("req" or "bereq")
382 LostHeader - Failed attempt to set HTTP header
384 Logs the header name of a failed HTTP header operation due to
385 resource exhaustion or configured limits.
386 ObjHeader - Object header
388 HTTP header contents.
389 The format is:
391 %s: %s
393 | |
394 | +- Header value
395 +----- Header name
396 ObjProtocol - Object protocol
398 The HTTP protocol version information.
399 ObjReason - Object response
401 The HTTP response string received.
402 ObjStatus - Object status
404 The HTTP status code received.
405 PipeAcct - Pipe byte counts
407 Contains byte counters for pipe sessions.
408 The format is:
410 %d %d %d %d
412 | | | |
413 | | | +------- Piped bytes to client
414 | | +---------- Piped bytes from client
415 | +------------- Backend request headers
416 +---------------- Client request headers
417 Proxy - PROXY protocol information
419 PROXY protocol information.
420 The format is:
422 %d %s %d %s %d
424 | | | | |
425 | | | | +- server port
426 | | | +---- server ip
427 | | +------- client port
428 | +---------- client ip
429 +------------- PROXY protocol version
430 All fields are "local" for PROXY local connections (command 0x0)
432 ProxyGarbage - Unparseable PROXY request
434 A PROXY protocol header was unparseable.
435 ReqAcct - Request handling byte counts
437 Contains byte counts for the request handling. The body bytes
438 count includes transmission overhead (ie: chunked encoding).
439 ESI sub-requests show the body bytes this ESI fragment including
440 any subfragments contributed to the top level request. The for‐
441 mat is:
442 %d %d %d %d %d %d
444 | | | | | |
445 | | | | | +- Total bytes transmitted
446 | | | | +---- Body bytes transmitted
447 | | | +------- Header bytes transmitted
448 | | +---------- Total bytes received
449 | +------------- Body bytes received
450 +---------------- Header bytes received
451 ReqHeader - Client request header
453 HTTP header contents.
454 The format is:
456 %s: %s
458 | |
459 | +- Header value
460 +----- Header name
461 ReqMethod - Client request method
463 The HTTP request method used.
464 ReqProtocol - Client request protocol
466 The HTTP protocol version information.
467 ReqStart - Client request start
469 Start of request processing. Logs the client address, port num‐
470 ber and listener endpoint name (from the -a command-line argu‐
471 ment).
472 The format is:
474 %s %s %s
476 | | |
477 | | +-- Listener name (from -a)
478 | +----- Client Port number (0 for Unix domain sockets)
479 +-------- Client IP4/6 address (0.0.0.0 for UDS)
480 ReqURL - Client request URL
482 The HTTP request URL.
483 RespHeader - Client response header
485 HTTP header contents.
486 The format is:
488 %s: %s
490 | |
491 | +- Header value
492 +----- Header name
493 RespProtocol - Client response protocol
495 The HTTP protocol version information.
496 RespReason - Client response response
498 The HTTP response string received.
499 RespStatus - Client response status
501 The HTTP status code received.
502 SessClose - Client connection closed
504 SessClose is the last record for any client connection.
505 The format is:
507 %s %f
509 | |
510 | +- How long the session was open
511 +---- Why the connection closed
512 SessError - Client connection accept failed
514 Accepting a client connection has failed.
515 The format is:
517 %s %s %s %d %d %s
519 | | | | | |
520 | | | | | +- Detailed error message
521 | | | | +---- Error Number (errno) from accept(2)
522 | | | +------- File descriptor number
523 | | +---------- Local TCP port / 0 for UDS
524 | +------------- Local IPv4/6 address / 0.0.0.0 for UDS
525 +---------------- Socket name (from -a argument)
526 SessOpen - Client connection opened
528 The first record for a client connection, with the socket-end‐
529 points of the connection.
530 The format is:
532 %s %d %s %s %s %d
534 | | | | | |
535 | | | | | +- File descriptor number
536 | | | | +---- Local TCP port / 0 for UDS
537 | | | +------- Local IPv4/6 address / 0.0.0.0 for UDS
538 | | +---------- Socket name (from -a argument)
539 | +------------- Remote TCP port / 0 for UDS
540 +---------------- Remote IPv4/6 address / 0.0.0.0 for UDS
541 Storage - Where object is stored
543 Type and name of the storage backend the object is stored in.
544 The format is:
546 %s %s
548 | |
549 | +- Name of storage backend
550 +---- Type ("malloc", "file", "persistent" etc.)
551 TTL - TTL set on object
553 A TTL record is emitted whenever the ttl, grace or keep values
554 for an object is set as well as whether the object is cacheable
555 or not.
556 The format is:
558 %s %d %d %d %d [ %d %d %u %u ] %s
560 | | | | | | | | | |
561 | | | | | | | | | +- "cacheable" or "uncacheable"
562 | | | | | | | | +------ Max-Age from Cache-Control header
563 | | | | | | | +--------- Expires header
564 | | | | | | +------------ Date header
565 | | | | | +--------------- Age (incl Age: header value)
566 | | | | +-------------------- Reference time for TTL
567 | | | +----------------------- Keep
568 | | +-------------------------- Grace
569 | +----------------------------- TTL
570 +-------------------------------- "RFC", "VCL" or "HFP"
571 The four optional fields are only present in "RFC" headers.
573 Examples:
575 RFC 60 10 -1 1312966109 1312966109 1312966109 0 60 cacheable
577 VCL 120 10 0 1312966111 uncacheable
578 HFP 2 0 0 1312966113 uncacheable
579 Timestamp - Timing information
581 Contains timing information for the Varnish worker threads.
582 Time stamps are issued by Varnish on certain events, and show
584 the absolute time of the event, the time spent since the start
585 of the work unit, and the time spent since the last timestamp
586 was logged. See the TIMESTAMPS section below for information
587 about the individual time stamps.
588 The format is:
590 %s: %f %f %f
592 | | | |
593 | | | +- Time since last timestamp
594 | | +---- Time since start of work unit
595 | +------- Absolute time of event
596 +----------- Event label
597 VCL_Error - VCL execution error message
599 Logs error messages generated during VCL execution.
600 VCL_Log - Log statement from VCL
602 User generated log messages insert from VCL through std.log()
603 VCL_acl - VCL ACL check results
605 Logs VCL ACL evaluation results.
606 VCL_call - VCL method called
608 Logs the VCL method name when a VCL method is called.
609 VCL_return - VCL method return value
611 Logs the VCL method terminating statement.
612 VCL_trace - VCL trace data
614 Logs VCL execution trace data.
615 The format is:
617 %s %u %u.%u.%u
619 | | | | |
620 | | | | +- VCL program line position
621 | | | +---- VCL program line number
622 | | +------- VCL program source index
623 | +---------- VCL trace point index
624 +------------- VCL configname
625 NB: This log record is masked by default.
627 VCL_use - VCL in use
629 Records the name of the VCL being used.
630 The format is:
632 %s [ %s %s ]
634 | | |
635 | | +- Name of label used to find it
636 | +---- "via"
637 +--------- Name of VCL put in use
638 VSL - VSL API warnings and error message
640 Warnings and error messages generated by the VSL API while read‐
641 ing the shared memory log.
642 VfpAcct - Fetch filter accounting
644 Contains name of VFP and statistics.
645 The format is:
647 %s %d %d
649 | | |
650 | | +- Total bytes produced
651 | +---- Number of calls made
652 +------- Name of filter
653 NB: This log record is masked by default.
655 Witness - Lock order witness records
657 Diagnostic recording of locking order.
658 WorkThread - Logs thread start/stop events
660 Logs worker thread creation and termination events.
661 The format is:
663 %p %s
665 | |
666 | +- [start|end]
667 +---- Worker struct pointer
668 NB: This log record is masked by default.
670
672 Timestamps are inserted in the log on completing certain events during
673 the worker thread's task handling. The timestamps has a label showing
674 which event was completed. The reported fields show the absolute time
675 of the event, the time spent since the start of the task and the time
676 spent since the last timestamp was logged.
677 The timestamps logged automatically by Varnish are inserted after com‐
679 pleting events that are expected to have delays (e.g. network IO or
680 spending time on a waitinglist). Timestamps can also be inserted from
681 VCL using the std.timestamp() method. If one is doing time consuming
682 tasks in the VCL configuration, it's a good idea to log a timestamp
683 after completing that task. This keeps the timing information in subse‐
684 quent timestamps from including the time spent on the VCL event.
685 Request handling timestamps
687 Start The start of request processing (first byte received or
688 restart).
689 Req Complete client request received.
691 ReqBody
693 Client request body processed (discarded, cached or passed to
694 the backend).
695 Waitinglist
697 Came off waitinglist.
698 Fetch Fetch processing finished (completely fetched or ready for
700 streaming).
701 Process
703 Processing finished, ready to deliver the client response.
704 Resp Delivery of response to the client finished.
706 Restart
708 Client request is being restarted.
709 Pipe handling timestamps
711 Pipe Opened a pipe to the backend and forwarded the request.
712 PipeSess
714 The pipe session has finished.
715 Backend fetch timestamps
717 Start Start of the backend fetch processing.
718 Bereq Backend request sent.
720 Beresp Backend response headers received.
722 BerespBody
724 Backend response body received.
725 Retry Backend request is being retried.
727 Error Backend request failed to vcl_backend_error.
729
731 This document was initially written by Poul-Henning Kamp, and later
732 updated by Martin Blix Grydeland.
733
735 · varnishhist(1)
736 · varnishlog(1)
738 · varnishncsa(1)
740 · varnishtop(1)
742
744 This document is licensed under the same licence as Varnish itself. See
745 LICENCE for details.
746 · Copyright (c) 2006 Verdens Gang AS
748 · Copyright (c) 2006-2015 Varnish Software AS
750 VSL(7)