1VSL(7)                                                                  VSL(7)
2
3
4

NAME

6       VSL - Varnish Shared Memory Logging
7

OVERVIEW

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
13   VSL tags
14       Backend - Backend selected
15              Logged  when  a  connection  is  selected for handling a backend
16              request.
17
18              The format is:
19
20                 %d %s %s
21                 |  |  |
22                 |  |  +- Backend display name
23                 |  +---- VCL name
24                 +------- Connection file descriptor
25
26       BackendClose - Backend connection closed
27              Logged when a backend connection is closed.
28
29              The format is:
30
31                 %d %s [ %s ]
32                 |  |    |
33                 |  |    +- Optional reason
34                 |  +------ Backend display name
35                 +--------- Connection file descriptor
36
37       BackendOpen - Backend connection opened
38              Logged when a new backend connection is opened.
39
40              The format is:
41
42                 %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
51       BackendReuse - Backend connection put up for reuse
52              Logged when a backend connection is put up for reuse by a  later
53              connection.
54
55              The format is:
56
57                 %d %s
58                 |  |
59                 |  +- Backend display name
60                 +---- Connection file descriptor
61
62       BackendStart - Backend request start
63              Start  of  backend  processing.  Logs the backend IP address and
64              port number.
65
66              The format is:
67
68                 %s %s
69                 |  |
70                 |  +- Backend Port number
71                 +---- Backend IP4/6 address
72
73       Backend_health - Backend health check
74              The result of a backend health probe.
75
76              The format is:
77
78                 %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
90              Probe window bits are:
91
92                 '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
101       Begin - Marks the start of a VXID
102              The first record of a VXID transaction.
103
104              The format is:
105
106                 %s %d %s
107                 |  |  |
108                 |  |  +- Reason
109                 |  +---- Parent vxid
110                 +------- Type ("sess", "req" or "bereq")
111
112       BereqAcct - Backend request accounting
113              Contains byte counters from backend request processing.
114
115              The format is:
116
117                 %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
126       BereqHeader - Backend request header
127              HTTP header contents.
128
129              The format is:
130
131                 %s: %s
132                 |   |
133                 |   +- Header value
134                 +----- Header name
135
136       BereqMethod - Backend request method
137              The HTTP request method used.
138
139       BereqProtocol - Backend request protocol
140              The HTTP protocol version information.
141
142       BereqURL - Backend request URL
143              The HTTP request URL.
144
145       BerespHeader - Backend response header
146              HTTP header contents.
147
148              The format is:
149
150                 %s: %s
151                 |   |
152                 |   +- Header value
153                 +----- Header name
154
155       BerespProtocol - Backend response protocol
156              The HTTP protocol version information.
157
158       BerespReason - Backend response response
159              The HTTP response string received.
160
161       BerespStatus - Backend response status
162              The HTTP status code received.
163
164       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
169       CLI - CLI communication
170              CLI communication between varnishd master and child process.
171
172       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
177              Debug messages may be added, changed or  removed  without  prior
178              notice and shouldn't be considered stable.
179
180       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
184       End - Marks the end of a VXID
185              The last record of a VXID transaction.
186
187       Error - Error messages
188              Error messages are stuff you probably want to know.
189
190       ExpBan - Object evicted due to ban
191              Logs the VXID when an object is banned.
192
193       ExpKill - Object expiry event
194              Logs events related to object expiry. The events are:
195
196              EXP_Rearm
197                     Logged when the expiry time of an object changes.
198
199              EXP_Inbox
200                     Logged when the expiry thread picks an  object  from  the
201                     inbox for processing.
202
203              EXP_Kill
204                     Logged  when  the  expiry thread kills an object from the
205                     inbox.
206
207              EXP_When
208                     Logged when the expiry thread moves an object on the bin‐
209                     heap.
210
211              EXP_Expired
212                     Logged when the expiry thread expires an object.
213
214              LRU_Cand
215                     Logged when an object is evaluated for LRU force expiry.
216
217              LRU    Logged when an object is force expired due to LRU.
218
219              LRU_Fail
220                     Logged when no suitable candidate object is found for LRU
221                     force expiry.
222
223              The format is:
224
225                 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
234                 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
243       FetchError - Error while fetching object
244              Logs the error message of a failed fetch operation.
245
246              Error messages should be self-explanatory, yet the http  connec‐
247              tion(HTC) class of errors is reported with these symbols:
248
249                 · junk (-5): Received unexpected data
250
251                 · close (-4): Connection closed
252
253                 · timeout (-3): Timed out
254
255                 · overflow (-2): Buffer/workspace too small
256
257                 · eof (-1): Unexpected end of input
258
259                 · empty (0): Empty response
260
261                 · more (1): More data required
262
263                 · complete (2): Data complete (no error)
264
265                 · idle (3): Connection was closed while idle
266
267              Notice that some HTC errors are never emitted.
268
269       Fetch_Body - Body fetched from backend
270              Ready to fetch body from backend.
271
272              The format is:
273
274                 %d (%s) %s
275                 |   |    |
276                 |   |    +---- 'stream' or '-'
277                 |   +--------- Text description of body fetch mode
278                 +------------- Body fetch mode
279
280       Filters - Body filters
281              List of filters applied to the body
282
283       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
288              The format is:
289
290                 %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
301              Examples:
302
303                 U F E 182 159 80 80 1392
304                 G F E 159 173 80 1304 1314
305
306       H2RxBody - Received HTTP2 frame body
307              Binary data
308
309       H2RxHdr - Received HTTP2 frame header
310              Binary data
311
312       H2TxBody - Transmitted HTTP2 frame body
313              Binary data
314
315       H2TxHdr - Transmitted HTTP2 frame header
316              Binary data
317
318       Hash - Value added to hash
319              This value was added to the object lookup hash.
320
321              NB: This log record is masked by default.
322
323       Hit - Hit object in cache
324              Object looked up in cache.
325
326              The format is:
327
328                 %u %f %f %f
329                 |  |  |  |
330                 |  |  |  +- Keep period
331                 |  |  +---- Grace period
332                 |  +------- Remaining TTL
333                 +---------- VXID of the object
334
335       HitMiss - Hit for miss object in cache.
336              Hit-for-miss object looked up in cache.
337
338              The format is:
339
340                 %u %f
341                 |  |
342                 |  +- Remaining TTL
343                 +---- VXID of the object
344
345       HitPass - Hit for pass object in cache.
346              Hit-for-pass object looked up in cache.
347
348              The format is:
349
350                 %u %f
351                 |  |
352                 |  +- Remaining TTL
353                 +---- VXID of the object
354
355       HttpGarbage - Unparseable HTTP request
356              Logs the content of unparseable HTTP requests.
357
358       Length - Size of object body
359              Logs the size of a fetch object body.
360
361       Link - Links to a child VXID
362              Links this VXID to any child VXID it initiates.
363
364              The format is:
365
366                 %s %d %s
367                 |  |  |
368                 |  |  +- Reason
369                 |  +---- Child vxid
370                 +------- Child type ("req" or "bereq")
371
372       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
376       ObjHeader - Object header
377              HTTP header contents.
378
379              The format is:
380
381                 %s: %s
382                 |   |
383                 |   +- Header value
384                 +----- Header name
385
386       ObjProtocol - Object protocol
387              The HTTP protocol version information.
388
389       ObjReason - Object response
390              The HTTP response string received.
391
392       ObjStatus - Object status
393              The HTTP status code received.
394
395       PipeAcct - Pipe byte counts
396              Contains byte counters for pipe sessions.
397
398              The format is:
399
400                 %d %d %d %d
401                 |  |  |  |
402                 |  |  |  +------- Piped bytes to client
403                 |  |  +---------- Piped bytes from client
404                 |  +------------- Backend request headers
405                 +---------------- Client request headers
406
407       Proxy - PROXY protocol information
408              PROXY protocol information.
409
410              The format is:
411
412                 %d %s %d %s %d
413                 |  |  |  |  |
414                 |  |  |  |  +- server port
415                 |  |  |  +---- server ip
416                 |  |  +------- client port
417                 |  +---------- client ip
418                 +------------- PROXY protocol version
419
420                 All fields are "local" for PROXY local connections (command 0x0)
421
422       ProxyGarbage - Unparseable PROXY request
423              A PROXY protocol header was unparseable.
424
425       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
432                 %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
441       ReqHeader - Client request header
442              HTTP header contents.
443
444              The format is:
445
446                 %s: %s
447                 |   |
448                 |   +- Header value
449                 +----- Header name
450
451       ReqMethod - Client request method
452              The HTTP request method used.
453
454       ReqProtocol - Client request protocol
455              The HTTP protocol version information.
456
457       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
462              The format is:
463
464                 %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
470       ReqURL - Client request URL
471              The HTTP request URL.
472
473       RespHeader - Client response header
474              HTTP header contents.
475
476              The format is:
477
478                 %s: %s
479                 |   |
480                 |   +- Header value
481                 +----- Header name
482
483       RespProtocol - Client response protocol
484              The HTTP protocol version information.
485
486       RespReason - Client response response
487              The HTTP response string received.
488
489       RespStatus - Client response status
490              The HTTP status code received.
491
492       SessClose - Client connection closed
493              SessClose is the last record for any client connection.
494
495              The format is:
496
497                 %s %f
498                 |  |
499                 |  +- How long the session was open
500                 +---- Why the connection closed
501
502       SessError - Client connection accept failed
503              Accepting a client connection has failed.
504
505              The format is:
506
507                 %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
516       SessOpen - Client connection opened
517              The first record for a client connection, with  the  socket-end‐
518              points of the connection.
519
520              The format is:
521
522                 %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
531       Storage - Where object is stored
532              Type and name of the storage backend the object is stored in.
533
534              The format is:
535
536                 %s %s
537                 |  |
538                 |  +- Name of storage backend
539                 +---- Type ("malloc", "file", "persistent" etc.)
540
541       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
546              The format is:
547
548                 %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
561              The four optional fields are only present in "RFC" headers.
562
563              Examples:
564
565                 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
569       Timestamp - Timing information
570              Contains timing information for the Varnish worker threads.
571
572              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
578              The format is:
579
580                 %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
587       VCL_Error - VCL execution error message
588              Logs error messages generated during VCL execution.
589
590       VCL_Log - Log statement from VCL
591              User generated log messages insert from VCL through std.log()
592
593       VCL_acl - VCL ACL check results
594              Logs VCL ACL evaluation results.
595
596       VCL_call - VCL method called
597              Logs the VCL method name when a VCL method is called.
598
599       VCL_return - VCL method return value
600              Logs the VCL method terminating statement.
601
602       VCL_trace - VCL trace data
603              Logs VCL execution trace data.
604
605              The format is:
606
607                 %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
615              NB: This log record is masked by default.
616
617       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
621       VfpAcct - Fetch filter accounting
622              Contains name of VFP and statistics.
623
624              The format is:
625
626                 %s %d %d
627                 |  |  |
628                 |  |  +- Total bytes produced
629                 |  +---- Number of calls made
630                 +------- Name of filter
631
632              NB: This log record is masked by default.
633
634       Witness - Lock order witness records
635              Diagnostic recording of locking order.
636
637       WorkThread - Logs thread start/stop events
638              Logs worker thread creation and termination events.
639
640              The format is:
641
642                 %p %s
643                 |  |
644                 |  +- [start|end]
645                 +---- Worker struct pointer
646
647              NB: This log record is masked by default.
648

TIMESTAMPS

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
656       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
664   Request handling timestamps
665       Start  The  start  of  request  processing  (first  byte  received   or
666              restart).
667
668       Req    Complete client request received.
669
670       ReqBody
671              Client  request  body  processed (discarded, cached or passed to
672              the backend).
673
674       Waitinglist
675              Came off waitinglist.
676
677       Fetch  Fetch processing  finished  (completely  fetched  or  ready  for
678              streaming).
679
680       Process
681              Processing finished, ready to deliver the client response.
682
683       Resp   Delivery of response to the client finished.
684
685       Restart
686              Client request is being restarted.
687
688   Pipe handling timestamps
689       Pipe   Opened a pipe to the backend and forwarded the request.
690
691       PipeSess
692              The pipe session has finished.
693
694   Backend fetch timestamps
695       Start  Start of the backend fetch processing.
696
697       Bereq  Backend request sent.
698
699       Beresp Backend response headers received.
700
701       BerespBody
702              Backend response body received.
703
704       Retry  Backend request is being retried.
705
706       Error  Backend request failed to vcl_backend_error.
707

HISTORY

709       This  document  was  initially  written by Poul-Henning Kamp, and later
710       updated by Martin Blix Grydeland.
711

SEE ALSO

713       · varnishhist(1)
714
715       · varnishlog(1)
716
717       · varnishncsa(1)
718
719       · varnishtop(1)
720
722       This document is licensed under the same licence as Varnish itself. See
723       LICENCE for details.
724
725       · Copyright (c) 2006 Verdens Gang AS
726
727       · Copyright (c) 2006-2015 Varnish Software AS
728
729
730
731
732                                                                        VSL(7)
Impressum