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

TIMESTAMPS

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

NOTICE MESSAGES

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

HISTORY

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

SEE ALSO

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