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 BackendClose - Backend connection closed
27 Logged when a backend connection is closed.
28 The format is:
30 %d %s [ %s ]
32 | | |
33 | | +- Optional reason
34 | +------ Backend display name
35 +--------- Connection file descriptor
36 BackendOpen - Backend connection opened
38 Logged when a new backend connection is opened.
39 The format is:
41 %d %s %s %s %s %s
43 | | | | | |
44 | | | | | +- Local port
45 | | | | +---- Local address
46 | | | +------- Remote port
47 | | +---------- Remote address
48 | +------------- Backend display name
49 +---------------- Connection file descriptor
50 BackendReuse - Backend connection put up for reuse
52 Logged when a backend connection is put up for reuse by a later
53 connection.
54 The format is:
56 %d %s
58 | |
59 | +- Backend display name
60 +---- Connection file descriptor
61 BackendStart - Backend request start
63 Start of backend processing. Logs the backend IP address and
64 port number.
65 The format is:
67 %s %s
69 | |
70 | +- Backend Port number
71 +---- Backend IP4/6 address
72 Backend_health - Backend health check
74 The result of a backend health probe.
75 The format is:
77 %s %s %s %u %u %u %f %f %s
79 | | | | | | | | |
80 | | | | | | | | +- Probe HTTP response / error information
81 | | | | | | | +---- Average response time
82 | | | | | | +------- Response time
83 | | | | | +---------- Probe window size
84 | | | | +------------- Probe threshold level
85 | | | +---------------- Number of good probes in window
86 | | +------------------- Probe window bits
87 | +---------------------- Status message
88 +------------------------- Backend name
89 Probe window bits are:
91 '4': Good IPv4
93 '6': Good IPv6
94 'U': Good UNIX
95 'x': Error Xmit
96 'X': Good Xmit
97 'r': Error Recv
98 'R': Good Recv
99 'H': Happy
100 Begin - Marks the start of a VXID
102 The first record of a VXID transaction.
103 The format is:
105 %s %d %s
107 | | |
108 | | +- Reason
109 | +---- Parent vxid
110 +------- Type ("sess", "req" or "bereq")
111 BereqAcct - Backend request accounting
113 Contains byte counters from backend request processing.
114 The format is:
116 %d %d %d %d %d %d
118 | | | | | |
119 | | | | | +- Total bytes received
120 | | | | +---- Body bytes received
121 | | | +------- Header bytes received
122 | | +---------- Total bytes transmitted
123 | +------------- Body bytes transmitted
124 +---------------- Header bytes transmitted
125 BereqHeader - Backend request header
127 HTTP header contents.
128 The format is:
130 %s: %s
132 | |
133 | +- Header value
134 +----- Header name
135 BereqMethod - Backend request method
137 The HTTP request method used.
138 BereqProtocol - Backend request protocol
140 The HTTP protocol version information.
141 BereqURL - Backend request URL
143 The HTTP request URL.
144 BerespHeader - Backend response header
146 HTTP header contents.
147 The format is:
149 %s: %s
151 | |
152 | +- Header value
153 +----- Header name
154 BerespProtocol - Backend response protocol
156 The HTTP protocol version information.
157 BerespReason - Backend response response
159 The HTTP response string received.
160 BerespStatus - Backend response status
162 The HTTP status code received.
163 BogoHeader - Bogus HTTP received
165 Contains the first 20 characters of received HTTP headers we
166 could not make sense of. Applies to both req.http and
167 beresp.http.
168 CLI - CLI communication
170 CLI communication between varnishd master and child process.
171 Debug - Debug messages
173 Debug messages can normally be ignored, but are sometimes help‐
174 ful during trouble-shooting. Most debug messages must be
175 explicitly enabled with parameters.
176 Debug messages may be added, changed or removed without prior
178 notice and shouldn't be considered stable.
179 ESI_xmlerror - ESI parser error or warning message
181 An error or warning was generated during parsing of an ESI
182 object. The log record describes the problem encountered.
183 End - Marks the end of a VXID
185 The last record of a VXID transaction.
186 Error - Error messages
188 Error messages are stuff you probably want to know.
189 ExpBan - Object evicted due to ban
191 Logs the VXID when an object is banned.
192 ExpKill - Object expiry event
194 Logs events related to object expiry. The events are:
195 EXP_Rearm
197 Logged when the expiry time of an object changes.
198 EXP_Inbox
200 Logged when the expiry thread picks an object from the
201 inbox for processing.
202 EXP_Kill
204 Logged when the expiry thread kills an object from the
205 inbox.
206 EXP_When
208 Logged when the expiry thread moves an object on the bin‐
209 heap.
210 EXP_Expired
212 Logged when the expiry thread expires an object.
213 LRU_Cand
215 Logged when an object is evaluated for LRU force expiry.
216 LRU Logged when an object is force expired due to LRU.
218 LRU_Fail
220 Logged when no suitable candidate object is found for LRU
221 force expiry.
222 The format is:
224 EXP_Rearm p=%p E=%f e=%f f=0x%x
226 EXP_Inbox p=%p e=%f f=0x%x
227 EXP_Kill p=%p e=%f f=0x%x
228 EXP_When p=%p e=%f f=0x%x
229 EXP_Expired x=%u t=%f
230 LRU_Cand p=%p f=0x%x r=%d
231 LRU x=%u
232 LRU_Fail
233 Legend:
235 p=%p Objcore pointer
236 t=%f Remaining TTL (s)
237 e=%f Expiry time (unix epoch)
238 E=%f Old expiry time (unix epoch)
239 f=0x%x Objcore flags
240 r=%d Objcore refcount
241 x=%u Object VXID
242 FetchError - Error while fetching object
244 Logs the error message of a failed fetch operation.
245 Error messages should be self-explanatory, yet the http connec‐
247 tion(HTC) class of errors is reported with these symbols:
248 · junk (-5): Received unexpected data
250 · close (-4): Connection closed
252 · timeout (-3): Timed out
254 · overflow (-2): Buffer/workspace too small
256 · eof (-1): Unexpected end of input
258 · empty (0): Empty response
260 · more (1): More data required
262 · complete (2): Data complete (no error)
264 · idle (3): Connection was closed while idle
266 Notice that some HTC errors are never emitted.
268 Fetch_Body - Body fetched from backend
270 Ready to fetch body from backend.
271 The format is:
273 %d (%s) %s
275 | | |
276 | | +---- 'stream' or '-'
277 | +--------- Text description of body fetch mode
278 +------------- Body fetch mode
279 Filters - Body filters
281 List of filters applied to the body
282 Gzip - G(un)zip performed on object
284 A Gzip record is emitted for each instance of gzip or gunzip
285 work performed. Worst case, an ESI transaction stored in gzip'ed
286 objects but delivered gunziped, will run into many of these.
287 The format is:
289 %c %c %c %d %d %d %d %d
291 | | | | | | | |
292 | | | | | | | +- Bit length of compressed data
293 | | | | | | +---- Bit location of 'last' bit
294 | | | | | +------- Bit location of first deflate block
295 | | | | +---------- Bytes output
296 | | | +------------- Bytes input
297 | | +---------------- 'E': ESI, '-': Plain object
298 | +------------------- 'F': Fetch, 'D': Deliver
299 +---------------------- 'G': Gzip, 'U': Gunzip, 'u': Gunzip-test
300 Examples:
302 U F E 182 159 80 80 1392
304 G F E 159 173 80 1304 1314
305 H2RxBody - Received HTTP2 frame body
307 Binary data
308 H2RxHdr - Received HTTP2 frame header
310 Binary data
311 H2TxBody - Transmitted HTTP2 frame body
313 Binary data
314 H2TxHdr - Transmitted HTTP2 frame header
316 Binary data
317 Hash - Value added to hash
319 This value was added to the object lookup hash.
320 NB: This log record is masked by default.
322 Hit - Hit object in cache
324 Object looked up in cache.
325 The format is:
327 %u %f %f %f
329 | | | |
330 | | | +- Keep period
331 | | +---- Grace period
332 | +------- Remaining TTL
333 +---------- VXID of the object
334 HitMiss - Hit for miss object in cache.
336 Hit-for-miss object looked up in cache.
337 The format is:
339 %u %f
341 | |
342 | +- Remaining TTL
343 +---- VXID of the object
344 HitPass - Hit for pass object in cache.
346 Hit-for-pass object looked up in cache.
347 The format is:
349 %u %f
351 | |
352 | +- Remaining TTL
353 +---- VXID of the object
354 HttpGarbage - Unparseable HTTP request
356 Logs the content of unparseable HTTP requests.
357 Length - Size of object body
359 Logs the size of a fetch object body.
360 Link - Links to a child VXID
362 Links this VXID to any child VXID it initiates.
363 The format is:
365 %s %d %s
367 | | |
368 | | +- Reason
369 | +---- Child vxid
370 +------- Child type ("req" or "bereq")
371 LostHeader - Failed attempt to set HTTP header
373 Logs the header name of a failed HTTP header operation due to
374 resource exhaustion or configured limits.
375 ObjHeader - Object header
377 HTTP header contents.
378 The format is:
380 %s: %s
382 | |
383 | +- Header value
384 +----- Header name
385 ObjProtocol - Object protocol
387 The HTTP protocol version information.
388 ObjReason - Object response
390 The HTTP response string received.
391 ObjStatus - Object status
393 The HTTP status code received.
394 PipeAcct - Pipe byte counts
396 Contains byte counters for pipe sessions.
397 The format is:
399 %d %d %d %d
401 | | | |
402 | | | +------- Piped bytes to client
403 | | +---------- Piped bytes from client
404 | +------------- Backend request headers
405 +---------------- Client request headers
406 Proxy - PROXY protocol information
408 PROXY protocol information.
409 The format is:
411 %d %s %d %s %d
413 | | | | |
414 | | | | +- server port
415 | | | +---- server ip
416 | | +------- client port
417 | +---------- client ip
418 +------------- PROXY protocol version
419 All fields are "local" for PROXY local connections (command 0x0)
421 ProxyGarbage - Unparseable PROXY request
423 A PROXY protocol header was unparseable.
424 ReqAcct - Request handling byte counts
426 Contains byte counts for the request handling. The body bytes
427 count includes transmission overhead (ie: chunked encoding).
428 ESI sub-requests show the body bytes this ESI fragment including
429 any subfragments contributed to the top level request. The for‐
430 mat is:
431 %d %d %d %d %d %d
433 | | | | | |
434 | | | | | +- Total bytes transmitted
435 | | | | +---- Body bytes transmitted
436 | | | +------- Header bytes transmitted
437 | | +---------- Total bytes received
438 | +------------- Body bytes received
439 +---------------- Header bytes received
440 ReqHeader - Client request header
442 HTTP header contents.
443 The format is:
445 %s: %s
447 | |
448 | +- Header value
449 +----- Header name
450 ReqMethod - Client request method
452 The HTTP request method used.
453 ReqProtocol - Client request protocol
455 The HTTP protocol version information.
456 ReqStart - Client request start
458 Start of request processing. Logs the client address, port num‐
459 ber and listener endpoint name (from the -a command-line argu‐
460 ment).
461 The format is:
463 %s %s %s
465 | | |
466 | | +-- Listener name (from -a)
467 | +----- Client Port number (0 for Unix domain sockets)
468 +-------- Client IP4/6 address (0.0.0.0 for UDS)
469 ReqURL - Client request URL
471 The HTTP request URL.
472 RespHeader - Client response header
474 HTTP header contents.
475 The format is:
477 %s: %s
479 | |
480 | +- Header value
481 +----- Header name
482 RespProtocol - Client response protocol
484 The HTTP protocol version information.
485 RespReason - Client response response
487 The HTTP response string received.
488 RespStatus - Client response status
490 The HTTP status code received.
491 SessClose - Client connection closed
493 SessClose is the last record for any client connection.
494 The format is:
496 %s %f
498 | |
499 | +- How long the session was open
500 +---- Why the connection closed
501 SessError - Client connection accept failed
503 Accepting a client connection has failed.
504 The format is:
506 %s %s %s %d %d %s
508 | | | | | |
509 | | | | | +- Detailed error message
510 | | | | +---- Error Number (errno) from accept(2)
511 | | | +------- File descriptor number
512 | | +---------- Local TCP port / 0 for UDS
513 | +------------- Local IPv4/6 address / 0.0.0.0 for UDS
514 +---------------- Socket name (from -a argument)
515 SessOpen - Client connection opened
517 The first record for a client connection, with the socket-end‐
518 points of the connection.
519 The format is:
521 %s %d %s %s %s %d
523 | | | | | |
524 | | | | | +- File descriptor number
525 | | | | +---- Local TCP port / 0 for UDS
526 | | | +------- Local IPv4/6 address / 0.0.0.0 for UDS
527 | | +---------- Socket name (from -a argument)
528 | +------------- Remote TCP port / 0 for UDS
529 +---------------- Remote IPv4/6 address / 0.0.0.0 for UDS
530 Storage - Where object is stored
532 Type and name of the storage backend the object is stored in.
533 The format is:
535 %s %s
537 | |
538 | +- Name of storage backend
539 +---- Type ("malloc", "file", "persistent" etc.)
540 TTL - TTL set on object
542 A TTL record is emitted whenever the ttl, grace or keep values
543 for an object is set as well as whether the object is cacheable
544 or not.
545 The format is:
547 %s %d %d %d %d [ %d %d %u %u ] %s
549 | | | | | | | | | |
550 | | | | | | | | | +- "cacheable" or "uncacheable"
551 | | | | | | | | +------ Max-Age from Cache-Control header
552 | | | | | | | +--------- Expires header
553 | | | | | | +------------ Date header
554 | | | | | +--------------- Age (incl Age: header value)
555 | | | | +-------------------- Reference time for TTL
556 | | | +----------------------- Keep
557 | | +-------------------------- Grace
558 | +----------------------------- TTL
559 +-------------------------------- "RFC", "VCL" or "HFP"
560 The four optional fields are only present in "RFC" headers.
562 Examples:
564 RFC 60 10 -1 1312966109 1312966109 1312966109 0 60 cacheable
566 VCL 120 10 0 1312966111 uncacheable
567 HFP 2 0 0 1312966113 uncacheable
568 Timestamp - Timing information
570 Contains timing information for the Varnish worker threads.
571 Time stamps are issued by Varnish on certain events, and show
573 the absolute time of the event, the time spent since the start
574 of the work unit, and the time spent since the last timestamp
575 was logged. See the TIMESTAMPS section below for information
576 about the individual time stamps.
577 The format is:
579 %s: %f %f %f
581 | | | |
582 | | | +- Time since last timestamp
583 | | +---- Time since start of work unit
584 | +------- Absolute time of event
585 +----------- Event label
586 VCL_Error - VCL execution error message
588 Logs error messages generated during VCL execution.
589 VCL_Log - Log statement from VCL
591 User generated log messages insert from VCL through std.log()
592 VCL_acl - VCL ACL check results
594 Logs VCL ACL evaluation results.
595 VCL_call - VCL method called
597 Logs the VCL method name when a VCL method is called.
598 VCL_return - VCL method return value
600 Logs the VCL method terminating statement.
601 VCL_trace - VCL trace data
603 Logs VCL execution trace data.
604 The format is:
606 %s %u %u.%u.%u
608 | | | | |
609 | | | | +- VCL program line position
610 | | | +---- VCL program line number
611 | | +------- VCL program source index
612 | +---------- VCL trace point index
613 +------------- VCL configname
614 NB: This log record is masked by default.
616 VSL - VSL API warnings and error message
618 Warnings and error messages generated by the VSL API while read‐
619 ing the shared memory log.
620 VfpAcct - Fetch filter accounting
622 Contains name of VFP and statistics.
623 The format is:
625 %s %d %d
627 | | |
628 | | +- Total bytes produced
629 | +---- Number of calls made
630 +------- Name of filter
631 NB: This log record is masked by default.
633 Witness - Lock order witness records
635 Diagnostic recording of locking order.
636 WorkThread - Logs thread start/stop events
638 Logs worker thread creation and termination events.
639 The format is:
641 %p %s
643 | |
644 | +- [start|end]
645 +---- Worker struct pointer
646 NB: This log record is masked by default.
648
650 Timestamps are inserted in the log on completing certain events during
651 the worker thread's task handling. The timestamps has a label showing
652 which event was completed. The reported fields show the absolute time
653 of the event, the time spent since the start of the task and the time
654 spent since the last timestamp was logged.
655 The timestamps logged automatically by Varnish are inserted after com‐
657 pleting events that are expected to have delays (e.g. network IO or
658 spending time on a waitinglist). Timestamps can also be inserted from
659 VCL using the std.timestamp() method. If one is doing time consuming
660 tasks in the VCL configuration, it's a good idea to log a timestamp
661 after completing that task. This keeps the timing information in subse‐
662 quent timestamps from including the time spent on the VCL event.
663 Request handling timestamps
665 Start The start of request processing (first byte received or
666 restart).
667 Req Complete client request received.
669 ReqBody
671 Client request body processed (discarded, cached or passed to
672 the backend).
673 Waitinglist
675 Came off waitinglist.
676 Fetch Fetch processing finished (completely fetched or ready for
678 streaming).
679 Process
681 Processing finished, ready to deliver the client response.
682 Resp Delivery of response to the client finished.
684 Restart
686 Client request is being restarted.
687 Pipe handling timestamps
689 Pipe Opened a pipe to the backend and forwarded the request.
690 PipeSess
692 The pipe session has finished.
693 Backend fetch timestamps
695 Start Start of the backend fetch processing.
696 Bereq Backend request sent.
698 Beresp Backend response headers received.
700 BerespBody
702 Backend response body received.
703 Retry Backend request is being retried.
705 Error Backend request failed to vcl_backend_error.
707
709 This document was initially written by Poul-Henning Kamp, and later
710 updated by Martin Blix Grydeland.
711
713 · varnishhist(1)
714 · varnishlog(1)
716 · varnishncsa(1)
718 · varnishtop(1)
720
722 This document is licensed under the same licence as Varnish itself. See
723 LICENCE for details.
724 · Copyright (c) 2006 Verdens Gang AS
726 · Copyright (c) 2006-2015 Varnish Software AS
728 VSL(7)