VSL Timeout and Varnishkafka

[Luca Toscano]

Hi all,

I am working on Varnishkafka (https://github.com/wikimedia/varnishkafka),
happily supporting Varnish 4 and its new VSL API. Varnishkafka allows a
user to insert the Start SLT_Timestamp or the Resp one into a logline,
formatted following a custom strftime string, and only recently I got some
reports of logs showing an empty value instead of the Resp timestamp. After
a bit of research, I discovered that some particular requests (mostly long
tar.gz downloads or Websocket Upgrade request) were missing the Resp
timestamp and showing the following lines (grabbed from varnishlog):

-   VSL            timeout
-   End            synth

I discovered from
https://www.varnish-cache.org/docs/trunk/reference/vsl.html that the VSL
tag is related to error/warnings using the VSL api, but nothing specific so
I tried to dig a bit more into the code:

-
https://github.com/varnishcache/varnish-cache/blob/4.1/lib/libvarnishapi/vsl_arg.c#L350
-
https://github.com/varnishcache/varnish-cache/blob/4.1/include/vapi/vapi_options.h#L80
-
https://github.com/varnishcache/varnish-cache/blob/4.1/lib/libvarnishapi/vsl.c#L103
-
https://github.com/varnishcache/varnish-cache/blob/4.1/lib/libvarnishapi/vsl_dispatch.c#L1342

I tried to simulate a backend fetch timeout with Varnish + Apache + PHP-FPM
running a simple script sleeping for minutes, but I wasn't able to
reproduce the VSL timeout (120 seconds by default as far as I understand).
I am probably missing something trivial but I don't really know how to
clearly identify where the issue comes from. My plan would be to add the
"-T" parameter support to Varnishkafka but I'd prefer to have some
explanation about what a VSL timeout is before proceeding.

Thanks a lot in advance!

Regards,

Luca
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20160621/2c75fab6/attachment.html>