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 Gzip - G(un)zip performed on object
281 A Gzip record is emitted for each instance of gzip or gunzip
282 work performed. Worst case, an ESI transaction stored in gzip'ed
283 objects but delivered gunziped, will run into many of these.
284 The format is:
286 %c %c %c %d %d %d %d %d
288 | | | | | | | |
289 | | | | | | | +- Bit length of compressed data
290 | | | | | | +---- Bit location of 'last' bit
291 | | | | | +------- Bit location of first deflate block
292 | | | | +---------- Bytes output
293 | | | +------------- Bytes input
294 | | +---------------- 'E': ESI, '-': Plain object
295 | +------------------- 'F': Fetch, 'D': Deliver
296 +---------------------- 'G': Gzip, 'U': Gunzip, 'u': Gunzip-test
297 Examples:
299 U F E 182 159 80 80 1392
301 G F E 159 173 80 1304 1314
302 H2RxBody - Received HTTP2 frame body
304 Binary data
305 H2RxHdr - Received HTTP2 frame header
307 Binary data
308 H2TxBody - Transmitted HTTP2 frame body
310 Binary data
311 H2TxHdr - Transmitted HTTP2 frame header
313 Binary data
314 Hash - Value added to hash
316 This value was added to the object lookup hash.
317 NB: This log record is masked by default.
319 Hit - Hit object in cache
321 Object looked up in cache.
322 The format is:
324 %u %f %f %f
326 | | | |
327 | | | +- Keep period
328 | | +---- Grace period
329 | +------- Remaining TTL
330 +---------- VXID of the object
331 HitMiss - Hit for miss object in cache.
333 Hit-for-miss object looked up in cache.
334 The format is:
336 %u %f
338 | |
339 | +- Remaining TTL
340 +---- VXID of the object
341 HitPass - Hit for pass object in cache.
343 Hit-for-pass object looked up in cache.
344 The format is:
346 %u %f
348 | |
349 | +- Remaining TTL
350 +---- VXID of the object
351 HttpGarbage - Unparseable HTTP request
353 Logs the content of unparseable HTTP requests.
354 Length - Size of object body
356 Logs the size of a fetch object body.
357 Link - Links to a child VXID
359 Links this VXID to any child VXID it initiates.
360 The format is:
362 %s %d %s
364 | | |
365 | | +- Reason
366 | +---- Child vxid
367 +------- Child type ("req" or "bereq")
368 LostHeader - Failed attempt to set HTTP header
370 Logs the header name of a failed HTTP header operation due to
371 resource exhaustion or configured limits.
372 ObjHeader - Object header
374 HTTP header contents.
375 The format is:
377 %s: %s
379 | |
380 | +- Header value
381 +----- Header name
382 ObjProtocol - Object protocol
384 The HTTP protocol version information.
385 ObjReason - Object response
387 The HTTP response string received.
388 ObjStatus - Object status
390 The HTTP status code received.
391 PipeAcct - Pipe byte counts
393 Contains byte counters for pipe sessions.
394 The format is:
396 %d %d %d %d
398 | | | |
399 | | | +------- Piped bytes to client
400 | | +---------- Piped bytes from client
401 | +------------- Backend request headers
402 +---------------- Client request headers
403 Proxy - PROXY protocol information
405 PROXY protocol information.
406 The format is:
408 %d %s %d %s %d
410 | | | | |
411 | | | | +- server port
412 | | | +---- server ip
413 | | +------- client port
414 | +---------- client ip
415 +------------- PROXY protocol version
416 All fields are "local" for PROXY local connections (command 0x0)
418 ProxyGarbage - Unparseable PROXY request
420 A PROXY protocol header was unparseable.
421 ReqAcct - Request handling byte counts
423 Contains byte counts for the request handling. The body bytes
424 count includes transmission overhead (ie: chunked encoding).
425 ESI sub-requests show the body bytes this ESI fragment including
426 any subfragments contributed to the top level request. The for‐
427 mat is:
428 %d %d %d %d %d %d
430 | | | | | |
431 | | | | | +- Total bytes transmitted
432 | | | | +---- Body bytes transmitted
433 | | | +------- Header bytes transmitted
434 | | +---------- Total bytes received
435 | +------------- Body bytes received
436 +---------------- Header bytes received
437 ReqHeader - Client request header
439 HTTP header contents.
440 The format is:
442 %s: %s
444 | |
445 | +- Header value
446 +----- Header name
447 ReqMethod - Client request method
449 The HTTP request method used.
450 ReqProtocol - Client request protocol
452 The HTTP protocol version information.
453 ReqStart - Client request start
455 Start of request processing. Logs the client address, port num‐
456 ber and listener endpoint name (from the -a command-line argu‐
457 ment).
458 The format is:
460 %s %s %s
462 | | |
463 | | +-- Listener name (from -a)
464 | +----- Client Port number (0 for Unix domain sockets)
465 +-------- Client IP4/6 address (0.0.0.0 for UDS)
466 ReqURL - Client request URL
468 The HTTP request URL.
469 RespHeader - Client response header
471 HTTP header contents.
472 The format is:
474 %s: %s
476 | |
477 | +- Header value
478 +----- Header name
479 RespProtocol - Client response protocol
481 The HTTP protocol version information.
482 RespReason - Client response response
484 The HTTP response string received.
485 RespStatus - Client response status
487 The HTTP status code received.
488 SessClose - Client connection closed
490 SessClose is the last record for any client connection.
491 The format is:
493 %s %f
495 | |
496 | +- How long the session was open
497 +---- Why the connection closed
498 SessOpen - Client connection opened
500 The first record for a client connection, with the socket-end‐
501 points of the connection.
502 The format is:
504 %s %d %s %s %s %d
506 | | | | | |
507 | | | | | +- File descriptor number
508 | | | | +---- Local TCP port
509 | | | +------- Local IPv4/6 address
510 | | +---------- Socket name (from -a argument)
511 | +------------- Remote TCP port
512 +---------------- Remote IPv4/6 address
513 Storage - Where object is stored
515 Type and name of the storage backend the object is stored in.
516 The format is:
518 %s %s
520 | |
521 | +- Name of storage backend
522 +---- Type ("malloc", "file", "persistent" etc.)
523 TTL - TTL set on object
525 A TTL record is emitted whenever the ttl, grace or keep values
526 for an object is set as well as whether the object is cacheable
527 or not.
528 The format is:
530 %s %d %d %d %d [ %d %d %u %u ] %s
532 | | | | | | | | | |
533 | | | | | | | | | +- "cacheable" or "uncacheable"
534 | | | | | | | | +------ Max-Age from Cache-Control header
535 | | | | | | | +--------- Expires header
536 | | | | | | +------------ Date header
537 | | | | | +--------------- Age (incl Age: header value)
538 | | | | +-------------------- Reference time for TTL
539 | | | +----------------------- Keep
540 | | +-------------------------- Grace
541 | +----------------------------- TTL
542 +-------------------------------- "RFC", "VCL" or "HFP"
543 The four optional fields are only present in "RFC" headers.
545 Examples:
547 RFC 60 10 -1 1312966109 1312966109 1312966109 0 60 cacheable
549 VCL 120 10 0 1312966111 uncacheable
550 HFP 2 0 0 1312966113 uncacheable
551 Timestamp - Timing information
553 Contains timing information for the Varnish worker threads.
554 Time stamps are issued by Varnish on certain events, and show
556 the absolute time of the event, the time spent since the start
557 of the work unit, and the time spent since the last timestamp
558 was logged. See the TIMESTAMPS section below for information
559 about the individual time stamps.
560 The format is:
562 %s: %f %f %f
564 | | | |
565 | | | +- Time since last timestamp
566 | | +---- Time since start of work unit
567 | +------- Absolute time of event
568 +----------- Event label
569 VCL_Error - VCL execution error message
571 Logs error messages generated during VCL execution.
572 VCL_Log - Log statement from VCL
574 User generated log messages insert from VCL through std.log()
575 VCL_acl - VCL ACL check results
577 Logs VCL ACL evaluation results.
578 VCL_call - VCL method called
580 Logs the VCL method name when a VCL method is called.
581 VCL_return - VCL method return value
583 Logs the VCL method terminating statement.
584 VCL_trace - VCL trace data
586 Logs VCL execution trace data.
587 The format is:
589 %s %u %u.%u.%u
591 | | | | |
592 | | | | +- VCL program line position
593 | | | +---- VCL program line number
594 | | +------- VCL program source index
595 | +---------- VCL trace point index
596 +------------- VCL configname
597 NB: This log record is masked by default.
599 VSL - VSL API warnings and error message
601 Warnings and error messages generated by the VSL API while read‐
602 ing the shared memory log.
603 VfpAcct - Fetch filter accounting
605 Contains name of VFP and statistics.
606 The format is:
608 %s %d %d
610 | | |
611 | | +- Total bytes produced
612 | +---- Number of calls made
613 +------- Name of filter
614 NB: This log record is masked by default.
616 Witness - Lock order witness records
618 Diagnostic recording of locking order.
619 WorkThread - Logs thread start/stop events
621 Logs worker thread creation and termination events.
622 The format is:
624 %p %s
626 | |
627 | +- [start|end]
628 +---- Worker struct pointer
629 NB: This log record is masked by default.
631
633 Timestamps are inserted in the log on completing certain events during
634 the worker thread's task handling. The timestamps has a label showing
635 which event was completed. The reported fields show the absolute time
636 of the event, the time spent since the start of the task and the time
637 spent since the last timestamp was logged.
638 The timestamps logged automatically by Varnish are inserted after com‐
640 pleting events that are expected to have delays (e.g. network IO or
641 spending time on a waitinglist). Timestamps can also be inserted from
642 VCL using the std.timestamp() method. If one is doing time consuming
643 tasks in the VCL configuration, it's a good idea to log a timestamp
644 after completing that task. This keeps the timing information in subse‐
645 quent timestamps from including the time spent on the VCL event.
646 Request handling timestamps
648 Start The start of request processing (first byte received or
649 restart).
650 Req Complete client request received.
652 ReqBody
654 Client request body processed (discarded, cached or passed to
655 the backend).
656 Waitinglist
658 Came off waitinglist.
659 Fetch Fetch processing finished (completely fetched or ready for
661 streaming).
662 Process
664 Processing finished, ready to deliver the client response.
665 Resp Delivery of response to the client finished.
667 Restart
669 Client request is being restarted.
670 Pipe handling timestamps
672 Pipe Opened a pipe to the backend and forwarded the request.
673 PipeSess
675 The pipe session has finished.
676 Backend fetch timestamps
678 Start Start of the backend fetch processing.
679 Bereq Backend request sent.
681 Beresp Backend response headers received.
683 BerespBody
685 Backend response body received.
686 Retry Backend request is being retried.
688 Error Backend request failed to vcl_backend_error.
690
692 This document was initially written by Poul-Henning Kamp, and later
693 updated by Martin Blix Grydeland.
694
696 · varnishhist(1)
697 · varnishlog(1)
699 · varnishncsa(1)
701 · varnishtop(1)
703
705 This document is licensed under the same licence as Varnish itself. See
706 LICENCE for details.
707 · Copyright (c) 2006 Verdens Gang AS
709 · Copyright (c) 2006-2015 Varnish Software AS
711 VSL(7)