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 re‐
16              quest.
17
18              The format is:
19
20                 %d %s %s
21                 |  |  |
22                 |  |  +- Backend display name
23                 |  +---- VCL name
24                 +------- Connection file descriptor
25
26              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
30       BackendClose - Backend connection closed
31              Logged when a backend connection is closed.
32
33              The format is:
34
35                 %d %s %s [ %s ]
36                 |  |  |    |
37                 |  |  |    +- Optional reason
38                 |  |  +------ "close" or "recycle"
39                 |  +--------- Backend display name
40                 +------------ Connection file descriptor
41
42       BackendOpen - Backend connection opened
43              Logged when a new backend connection is opened.
44
45              The format is:
46
47                 %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
57       BackendReuse - Backend connection put up for reuse
58              Logged when a backend connection is put up for reuse by a  later
59              connection.
60
61              The format is:
62
63                 %d %s
64                 |  |
65                 |  +- Backend display name
66                 +---- Connection file descriptor
67
68              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
72       BackendStart - Backend request start
73              Start  of  backend  processing.  Logs the backend IP address and
74              port number.
75
76              The format is:
77
78                 %s %s
79                 |  |
80                 |  +- Backend Port number
81                 +---- Backend IP4/6 address
82
83              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
87       Backend_health - Backend health check
88              The result of a backend health probe.
89
90              The format is:
91
92                 %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
105              Probe window bits are:
106
107                 '-': Could not connect
108                 '4': Good IPv4
109                 '6': Good IPv6
110                 'U': Good UNIX
111                 'x': Error Xmit
112                 'X': Good Xmit
113                 'r': Error Recv
114                 'R': Good Recv
115                 'H': Happy
116
117              When the backend is just created, the  window  bits  for  health
118              check  slots that haven't run yet appear as '-' like failures to
119              connect.
120
121       Begin - Marks the start of a VXID
122              The first record of a VXID transaction.
123
124              The format is:
125
126                 %s %d %s
127                 |  |  |
128                 |  |  +- Reason
129                 |  +---- Parent vxid
130                 +------- Type ("sess", "req" or "bereq")
131
132       BereqAcct - Backend request accounting
133              Contains byte counters from backend request processing.
134
135              The format is:
136
137                 %d %d %d %d %d %d
138                 |  |  |  |  |  |
139                 |  |  |  |  |  +- Total bytes received
140                 |  |  |  |  +---- Body bytes received
141                 |  |  |  +------- Header bytes received
142                 |  |  +---------- Total bytes transmitted
143                 |  +------------- Body bytes transmitted
144                 +---------------- Header bytes transmitted
145
146       BereqHeader - Backend request header
147              HTTP header contents.
148
149              The format is:
150
151                 %s: %s
152                 |   |
153                 |   +- Header value
154                 +----- Header name
155
156              NOTE: HTTP header fields are free form records and not  strictly
157              made  of  2  fields. Accessing a specific header with the prefix
158              notation helps treating the header value as a single string.
159
160       BereqMethod - Backend request method
161              The HTTP request method used.
162
163       BereqProtocol - Backend request protocol
164              The HTTP protocol version information.
165
166       BereqURL - Backend request URL
167              The HTTP request URL.
168
169       BereqUnset - Backend request unset header
170              HTTP header contents.
171
172              The format is:
173
174                 %s: %s
175                 |   |
176                 |   +- Header value
177                 +----- Header name
178
179              NOTE: HTTP header fields are free form records and not  strictly
180              made  of  2  fields. Accessing a specific header with the prefix
181              notation helps treating the header value as a single string.
182
183       BerespHeader - Backend response header
184              HTTP header contents.
185
186              The format is:
187
188                 %s: %s
189                 |   |
190                 |   +- Header value
191                 +----- Header name
192
193              NOTE: HTTP header fields are free form records and not  strictly
194              made  of  2  fields. Accessing a specific header with the prefix
195              notation helps treating the header value as a single string.
196
197       BerespProtocol - Backend response protocol
198              The HTTP protocol version information.
199
200       BerespReason - Backend response reason
201              The HTTP response reason string.
202
203       BerespStatus - Backend response status
204              The HTTP response status code.
205
206       BerespUnset - Backend response unset header
207              HTTP header contents.
208
209              The format is:
210
211                 %s: %s
212                 |   |
213                 |   +- Header value
214                 +----- Header name
215
216              NOTE: HTTP header fields are free form records and not  strictly
217              made  of  2  fields. Accessing a specific header with the prefix
218              notation helps treating the header value as a single string.
219
220       BogoHeader - Bogus HTTP received
221              Contains the first 20 characters of  received  HTTP  headers  we
222              could   not  make  sense  of.   Applies  to  both  req.http  and
223              beresp.http.
224
225       CLI - CLI communication
226              CLI communication between varnishd master and child process.
227
228       Debug - Debug messages
229              Debug messages can normally be ignored, but are sometimes  help‐
230              ful  during  trouble-shooting.   Most debug messages must be ex‐
231              plicitly enabled with parameters.
232
233              Debug messages may be added, changed or  removed  without  prior
234              notice and shouldn't be considered stable.
235
236              NB: This log record is masked by default.
237
238       ESI_xmlerror - ESI parser error or warning message
239              An  error  or warning was generated during parsing of an ESI ob‐
240              ject. The log record describes the problem encountered.
241
242       End - Marks the end of a VXID
243              The last record of a VXID transaction.
244
245       Error - Error messages
246              Error messages are stuff you probably want to know.
247
248       ExpBan - Object evicted due to ban
249              Logs the VXID when an object is banned.
250
251       ExpKill - Object expiry event
252              Logs events related to object expiry. The events are:
253
254              EXP_Rearm
255                     Logged when the expiry time of an object changes.
256
257              EXP_Inbox
258                     Logged when the expiry thread picks an  object  from  the
259                     inbox for processing.
260
261              EXP_Kill
262                     Logged  when  the  expiry thread kills an object from the
263                     inbox.
264
265              EXP_When
266                     Logged when the expiry thread moves an object on the bin‐
267                     heap.
268
269              EXP_Expired
270                     Logged when the expiry thread expires an object.
271
272              LRU_Cand
273                     Logged when an object is evaluated for LRU force expiry.
274
275              LRU    Logged when an object is force expired due to LRU.
276
277              LRU_Fail
278                     Logged when no suitable candidate object is found for LRU
279                     force expiry.
280
281              The format is:
282
283                 EXP_Rearm p=%p E=%f e=%f f=0x%x
284                 EXP_Inbox p=%p e=%f f=0x%x
285                 EXP_Kill p=%p e=%f f=0x%x
286                 EXP_When p=%p e=%f f=0x%x
287                 EXP_Expired x=%u t=%f
288                 LRU_Cand p=%p f=0x%x r=%d
289                 LRU x=%u
290                 LRU_Fail
291
292                 Legend:
293                 p=%p         Objcore pointer
294                 t=%f         Remaining TTL (s)
295                 e=%f         Expiry time (unix epoch)
296                 E=%f         Old expiry time (unix epoch)
297                 f=0x%x       Objcore flags
298                 r=%d         Objcore refcount
299                 x=%u         Object VXID
300
301       FetchError - Error while fetching object
302              Logs the error message of a failed fetch operation.
303
304              Error messages should be self-explanatory, yet the http  connec‐
305              tion (HTC) class of errors is reported with these symbols:
306
307                 • junk (-5): Received unexpected data
308
309                 • close (-4): Connection closed
310
311                 • timeout (-3): Timed out
312
313                 • overflow (-2): Buffer/workspace too small
314
315                 • eof (-1): Unexpected end of input
316
317                 • empty (0): Empty response
318
319more (1): More data required
320
321                 • complete (2): Data complete (no error)
322
323                 • idle (3): Connection was closed while idle
324
325              Notice that some HTC errors are never emitted.
326
327       Fetch_Body - Body fetched from backend
328              Ready to fetch body from backend.
329
330              The format is:
331
332                 %d %s %s
333                 |  |  |
334                 |  |  +---- 'stream' or '-'
335                 |  +------- Text description of body fetch mode
336                 +---------- Body fetch mode
337
338       Filters - Body filters
339              List of filters applied to the body
340
341       Gzip - G(un)zip performed on object
342              A  Gzip  record  is  emitted for each instance of gzip or gunzip
343              work performed. Worst case, an ESI transaction stored in gzip'ed
344              objects but delivered gunziped, will run into many of these.
345
346              The format is:
347
348                 %c %c %c %d %d %d %d %d
349                 |  |  |  |  |  |  |  |
350                 |  |  |  |  |  |  |  +- Bit length of compressed data
351                 |  |  |  |  |  |  +---- Bit location of 'last' bit
352                 |  |  |  |  |  +------- Bit location of first deflate block
353                 |  |  |  |  +---------- Bytes output
354                 |  |  |  +------------- Bytes input
355                 |  |  +---------------- 'E': ESI, '-': Plain object
356                 |  +------------------- 'F': Fetch, 'D': Deliver
357                 +---------------------- 'G': Gzip, 'U': Gunzip, 'u': Gunzip-test
358
359              Examples:
360
361                 U F E 182 159 80 80 1392
362                 G F E 159 173 80 1304 1314
363
364       H2RxBody - Received HTTP2 frame body
365              Binary data
366
367       H2RxHdr - Received HTTP2 frame header
368              Binary data
369
370       H2TxBody - Transmitted HTTP2 frame body
371              Binary data
372
373       H2TxHdr - Transmitted HTTP2 frame header
374              Binary data
375
376       Hash - Value added to hash
377              This value was added to the object lookup hash.
378
379              NB: This log record is masked by default.
380
381       Hit - Hit object in cache
382              Object looked up in cache.
383
384              The format is:
385
386                 %u %f %f %f [%u [%u]]
387                 |  |  |  |   |   |
388                 |  |  |  |   |   +- Content length
389                 |  |  |  |   +----- Fetched so far
390                 |  |  |  +--------- Keep period
391                 |  |  +------------ Grace period
392                 |  +--------------- Remaining TTL
393                 +------------------ VXID of the object
394
395       HitMiss - Hit for miss object in cache.
396              Hit-for-miss object looked up in cache.
397
398              The format is:
399
400                 %u %f
401                 |  |
402                 |  +- Remaining TTL
403                 +---- VXID of the object
404
405       HitPass - Hit for pass object in cache.
406              Hit-for-pass object looked up in cache.
407
408              The format is:
409
410                 %u %f
411                 |  |
412                 |  +- Remaining TTL
413                 +---- VXID of the object
414
415       HttpGarbage - Unparseable HTTP request
416              Logs the content of unparseable HTTP requests.
417
418       Length - Size of object body
419              Logs the size of a fetch object body.
420
421       Link - Links to a child VXID
422              Links this VXID to any child VXID it initiates.
423
424              The format is:
425
426                 %s %d %s
427                 |  |  |
428                 |  |  +- Reason
429                 |  +---- Child vxid
430                 +------- Child type ("req" or "bereq")
431
432       LostHeader - Failed attempt to set HTTP header
433              Logs  the  header  name of a failed HTTP header operation due to
434              resource exhaustion or configured limits.
435
436       Notice - Informational messages about request handling
437              Informational log messages on  events  occurred  during  request
438              handling.
439
440              The format is:
441
442                 %s: %s
443                 |   |
444                 |   +- Short description of the notice message
445                 +----- Manual page containing the detailed description
446
447              See  the  NOTICE  MESSAGES  section below or the individual VMOD
448              manual pages for detailed information of notice messages.
449
450       ObjHeader - Object header
451              HTTP header contents.
452
453              The format is:
454
455                 %s: %s
456                 |   |
457                 |   +- Header value
458                 +----- Header name
459
460              NOTE: HTTP header fields are free form records and not  strictly
461              made  of  2  fields. Accessing a specific header with the prefix
462              notation helps treating the header value as a single string.
463
464       ObjProtocol - Object protocol
465              The HTTP protocol version information.
466
467       ObjReason - Object reason
468              The HTTP response reason string.
469
470       ObjStatus - Object status
471              The HTTP response status code.
472
473       ObjUnset - Object unset header
474              HTTP header contents.
475
476              The format is:
477
478                 %s: %s
479                 |   |
480                 |   +- Header value
481                 +----- Header name
482
483              NOTE: HTTP header fields are free form records and not  strictly
484              made  of  2  fields. Accessing a specific header with the prefix
485              notation helps treating the header value as a single string.
486
487       PipeAcct - Pipe byte counts
488              Contains byte counters for pipe sessions.
489
490              The format is:
491
492                 %d %d %d %d
493                 |  |  |  |
494                 |  |  |  +------- Piped bytes to client
495                 |  |  +---------- Piped bytes from client
496                 |  +------------- Backend request headers
497                 +---------------- Client request headers
498
499       Proxy - PROXY protocol information
500              PROXY protocol information.
501
502              The format is:
503
504                 %d %s %d %s %d
505                 |  |  |  |  |
506                 |  |  |  |  +- server port
507                 |  |  |  +---- server ip
508                 |  |  +------- client port
509                 |  +---------- client ip
510                 +------------- PROXY protocol version
511
512                 All fields are "local" for PROXY local connections (command 0x0)
513
514       ProxyGarbage - Unparseable PROXY request
515              A PROXY protocol header was unparseable.
516
517       ReqAcct - Request handling byte counts
518              Contains byte counts for the request handling.  The  body  bytes
519              count  includes  transmission  overhead  (ie: chunked encoding).
520              ESI sub-requests show the body bytes this ESI fragment including
521              any subfragments contributed to the top level request.  The for‐
522              mat is:
523
524                 %d %d %d %d %d %d
525                 |  |  |  |  |  |
526                 |  |  |  |  |  +- Total bytes transmitted
527                 |  |  |  |  +---- Body bytes transmitted
528                 |  |  |  +------- Header bytes transmitted
529                 |  |  +---------- Total bytes received
530                 |  +------------- Body bytes received
531                 +---------------- Header bytes received
532
533       ReqHeader - Client request header
534              HTTP header contents.
535
536              The format is:
537
538                 %s: %s
539                 |   |
540                 |   +- Header value
541                 +----- Header name
542
543              NOTE: HTTP header fields are free form records and not  strictly
544              made  of  2  fields. Accessing a specific header with the prefix
545              notation helps treating the header value as a single string.
546
547       ReqMethod - Client request method
548              The HTTP request method used.
549
550       ReqProtocol - Client request protocol
551              The HTTP protocol version information.
552
553       ReqStart - Client request start
554              Start of request processing. Logs the client address, port  num‐
555              ber   and listener endpoint name (from the -a command-line argu‐
556              ment).
557
558              The format is:
559
560                 %s %s %s
561                 |  |  |
562                 |  |  +-- Listener name (from -a)
563                 |  +----- Client Port number (0 for Unix domain sockets)
564                 +-------- Client IP4/6 address (0.0.0.0 for UDS)
565
566       ReqURL - Client request URL
567              The HTTP request URL.
568
569       ReqUnset - Client request unset header
570              HTTP header contents.
571
572              The format is:
573
574                 %s: %s
575                 |   |
576                 |   +- Header value
577                 +----- Header name
578
579              NOTE: HTTP header fields are free form records and not  strictly
580              made  of  2  fields. Accessing a specific header with the prefix
581              notation helps treating the header value as a single string.
582
583       RespHeader - Client response header
584              HTTP header contents.
585
586              The format is:
587
588                 %s: %s
589                 |   |
590                 |   +- Header value
591                 +----- Header name
592
593              NOTE: HTTP header fields are free form records and not  strictly
594              made  of  2  fields. Accessing a specific header with the prefix
595              notation helps treating the header value as a single string.
596
597       RespProtocol - Client response protocol
598              The HTTP protocol version information.
599
600       RespReason - Client response reason
601              The HTTP response reason string.
602
603       RespStatus - Client response status
604              The HTTP response status code.
605
606       RespUnset - Client response unset header
607              HTTP header contents.
608
609              The format is:
610
611                 %s: %s
612                 |   |
613                 |   +- Header value
614                 +----- Header name
615
616              NOTE: HTTP header fields are free form records and not  strictly
617              made  of  2  fields. Accessing a specific header with the prefix
618              notation helps treating the header value as a single string.
619
620       SessClose - Client connection closed
621              SessClose is the last record for any client connection.
622
623              The format is:
624
625                 %s %f
626                 |  |
627                 |  +- How long the session was open
628                 +---- Why the connection closed
629
630       SessError - Client connection accept failed
631              Accepting a client connection has failed.
632
633              The format is:
634
635                 %s %s %s %d %d %s
636                 |  |  |  |  |  |
637                 |  |  |  |  |  +- Detailed error message
638                 |  |  |  |  +---- Error Number (errno) from accept(2)
639                 |  |  |  +------- File descriptor number
640                 |  |  +---------- Local TCP port / 0 for UDS
641                 |  +------------- Local IPv4/6 address / 0.0.0.0 for UDS
642                 +---------------- Socket name (from -a argument)
643
644       SessOpen - Client connection opened
645              The first record for a client connection, with  the  socket-end‐
646              points of the connection.
647
648              The format is:
649
650                 %s %d %s %s %s %f %d
651                 |  |  |  |  |  |  |
652                 |  |  |  |  |  |  +- File descriptor number
653                 |  |  |  |  |  +---- Session start time (unix epoch)
654                 |  |  |  |  +------- Local TCP port / 0 for UDS
655                 |  |  |  +---------- Local IPv4/6 address / 0.0.0.0 for UDS
656                 |  |  +------------- Socket name (from -a argument)
657                 |  +---------------- Remote TCP port / 0 for UDS
658                 +------------------- Remote IPv4/6 address / 0.0.0.0 for UDS
659
660       Storage - Where object is stored
661              Type and name of the storage backend the object is stored in.
662
663              The format is:
664
665                 %s %s
666                 |  |
667                 |  +- Name of storage backend
668                 +---- Type ("malloc", "file", "persistent" etc.)
669
670       TTL - TTL set on object
671              A  TTL  record is emitted whenever the ttl, grace or keep values
672              for an object is set as well as whether the object is  cacheable
673              or not.
674
675              The format is:
676
677                 %s %d %d %d %d [ %d %d %u %u ] %s
678                 |  |  |  |  |    |  |  |  |    |
679                 |  |  |  |  |    |  |  |  |    +- "cacheable" or "uncacheable"
680                 |  |  |  |  |    |  |  |  +------ Max-Age from Cache-Control header
681                 |  |  |  |  |    |  |  +--------- Expires header
682                 |  |  |  |  |    |  +------------ Date header
683                 |  |  |  |  |    +--------------- Age (incl Age: header value)
684                 |  |  |  |  +-------------------- Reference time for TTL
685                 |  |  |  +----------------------- Keep
686                 |  |  +-------------------------- Grace
687                 |  +----------------------------- TTL
688                 +-------------------------------- "RFC", "VCL" or "HFP"
689
690              The four optional fields are only present in "RFC" headers.
691
692              Examples:
693
694                 RFC 60 10 -1 1312966109 1312966109 1312966109 0 60 cacheable
695                 VCL 120 10 0 1312966111 uncacheable
696                 HFP 2 0 0 1312966113 uncacheable
697
698       Timestamp - Timing information
699              Contains timing information for the Varnish worker threads.
700
701              Time  stamps  are  issued by Varnish on certain events, and show
702              the absolute time of the event, the time spent since  the  start
703              of  the  work  unit, and the time spent since the last timestamp
704              was logged. See the TIMESTAMPS  section  below  for  information
705              about the individual time stamps.
706
707              The format is:
708
709                 %s: %f %f %f
710                 |   |  |  |
711                 |   |  |  +- Time since last timestamp
712                 |   |  +---- Time since start of work unit
713                 |   +------- Absolute time of event
714                 +----------- Event label
715
716       VCL_Error - VCL execution error message
717              Logs error messages generated during VCL execution.
718
719       VCL_Log - Log statement from VCL
720              User generated log messages insert from VCL through std.log()
721
722       VCL_acl - VCL ACL check results
723              ACLs with the +log flag emits this record with the result.
724
725              The format is:
726
727                 %s %s [%s [fixed: %s]]
728                 |  |   |          |
729                 |  |   |          +- Fixed entry (see vcc_acl_pedantic parameter)
730                 |  |   +------------ Matching entry (only for MATCH)
731                 |  +---------------- Name of the ACL
732                 +-------------------- MATCH or NO_MATCH
733
734              MATCH  denotes  an ACL match NO_MATCH denotes that a checked ACL
735              has not matched
736
737       VCL_call - VCL method called
738              Logs the VCL method name when a VCL method is called.
739
740       VCL_return - VCL method return value
741              Logs the VCL method terminating statement.
742
743       VCL_trace - VCL trace data
744              Logs VCL execution trace data.
745
746              The format is:
747
748                 %s %u %u.%u.%u
749                 |  |  |  |  |
750                 |  |  |  |  +- VCL program line position
751                 |  |  |  +---- VCL program line number
752                 |  |  +------- VCL program source index
753                 |  +---------- VCL trace point index
754                 +------------- VCL configname
755
756              NB: This log record is masked by default.
757
758       VCL_use - VCL in use
759              Records the name of the VCL being used.
760
761              The format is:
762
763                 %s [ %s %s ]
764                 |    |  |
765                 |    |  +- Name of label used to find it
766                 |    +---- "via"
767                 +--------- Name of VCL put in use
768
769       VSL - VSL API warnings and error message
770              Warnings and error messages generated by the VSL API while read‐
771              ing the shared memory log.
772
773       VdpAcct - Deliver filter accounting
774              Contains name of VDP and statistics.
775
776              The format is:
777
778                 %s %d %d
779                 |  |  |
780                 |  |  +- Total bytes produced
781                 |  +---- Number of calls made
782                 +------- Name of filter
783
784              NB: This log record is masked by default.
785
786       VfpAcct - Fetch filter accounting
787              Contains name of VFP and statistics.
788
789              The format is:
790
791                 %s %d %d
792                 |  |  |
793                 |  |  +- Total bytes produced
794                 |  +---- Number of calls made
795                 +------- Name of filter
796
797              NB: This log record is masked by default.
798
799       Witness - Lock order witness records
800              Diagnostic recording of locking order.
801
802       WorkThread - Logs thread start/stop events
803              Logs worker thread creation and termination events.
804
805              The format is:
806
807                 %p %s
808                 |  |
809                 |  +- [start|end]
810                 +---- Worker struct pointer
811
812              NB: This log record is masked by default.
813

TIMESTAMPS

815       Timestamps  are inserted in the log on completing certain events during
816       the worker thread's task handling. The timestamps has a  label  showing
817       which  event  was completed. The reported fields show the absolute time
818       of the event, the time spent since the start of the task and  the  time
819       spent since the last timestamp was logged.
820
821       The  timestamps logged automatically by Varnish are inserted after com‐
822       pleting events that are expected to have delays  (e.g.  network  IO  or
823       spending  time  on a waitinglist). Timestamps can also be inserted from
824       VCL using the std.timestamp() function. If one is doing time  consuming
825       tasks in the VCL configuration, it's a good idea to log a timestamp af‐
826       ter completing that task. This keeps the timing information  in  subse‐
827       quent timestamps from including the time spent on the VCL event.
828
829   Request handling timestamps
830       Start  The   start  of  request  processing  (first  byte  received  or
831              restart).
832
833       Req    Complete client request received.
834
835       ReqBody
836              Client request body processed (discarded, cached  or  passed  to
837              the backend).
838
839       Waitinglist
840              Came off waitinglist.
841
842       Fetch  Fetch  processing  finished  (completely  fetched  or  ready for
843              streaming).
844
845       Process
846              Processing finished, ready to deliver the client response.
847
848       Resp   Delivery of response to the client finished.
849
850       Restart
851              Client request is being restarted.
852
853   Pipe handling timestamps
854       The following timestamps are client timestamps specific to pipe  trans‐
855       actions:
856
857       Pipe   Opened a pipe to the backend and forwarded the request.
858
859       PipeSess
860              The pipe session has finished.
861
862       The following timestamps change meaning in a pipe transaction:
863
864       Process
865              Processing finished, ready to begin the pipe delivery.
866
867   Backend fetch timestamps
868       Start  Start of the backend fetch processing.
869
870       Fetch  Came off vcl_backend_fetch ready to send the backend request.
871
872       Connected
873              Successfully established a backend connection, or selected a re‐
874              cycled connection from the pool.
875
876       Bereq  Backend request sent.
877
878       Beresp Backend response headers received.
879
880       Process
881              Processing finished, ready to fetch the response body.
882
883       BerespBody
884              Backend response body received.
885
886       Retry  Backend request is being retried.
887
888       Error  Backend request failed to vcl_backend_error.
889

NOTICE MESSAGES

891       Notice messages contain informational messages about the handling of  a
892       request. These can be exceptional circumstances encountered that causes
893       deviation from the normal handling. The messages are prefixed with vsl:
894       for core Varnish generated messages, and VMOD authors are encouraged to
895       use vmod_<name>: for their own notice messages. This matches  the  name
896       of  the  manual page where detailed descriptions of notice messages are
897       expected.
898
899       The core messages are described below.
900
901   Conditional fetch wait for streaming object
902       The backend answered 304 Not Modified on a conditional fetch  using  an
903       object  that  has  not yet been fully fetched as the stale template ob‐
904       ject. This can only happen when the TTL of the object is less than  the
905       time  it  takes to fetch it. The fetch is halted until the stale object
906       is fully fetched, upon which the new object is created as normal. While
907       waiting, any grace time on the stale object will be in effect.
908
909   High number of variants
910       Objects  are  primarily looked up from an index using the hash key com‐
911       puted from the hash_data() VCL function. When  variants  are  involved,
912       that is to say when a backend response was stored with a Vary header, a
913       secondary lookup is performed but it is not indexed. As the  number  of
914       variants  for  a given key increases, this can slow cache lookups down,
915       and since this happens under a lock, this  can  greatly  increase  lock
916       contention,  even  more  so  for frequently requested objects. Variants
917       should therefore be used sparingly on cacheable  responses,  but  since
918       they  can  originate  from  either  VCL  or origin servers, this notice
919       should help identify problematic resources.
920

HISTORY

922       This document was initially written by Poul-Henning Kamp, and later up‐
923       dated by Martin Blix Grydeland.
924

SEE ALSO

926varnishhist(1)
927
928varnishlog(1)
929
930varnishncsa(1)
931
932varnishtop(1)
933
935       This document is licensed under the same licence as Varnish itself. See
936       LICENCE for details.
937
938       • Copyright (c) 2006 Verdens Gang AS
939
940       • Copyright (c) 2006-2015 Varnish Software AS
941
942
943
944
945                                                                        VSL(7)
Impressum