Debugging varnish

50 %
50 %
Information about Debugging varnish

Published on November 3, 2016

Author: Varnish_software

Source: slideshare.net

1. Varnish Debugging

2. Martin Blix Grydeland Senior Developer WHO AM I?

3. VCL debugging

4. VCL debugging ● Code not reached, wrong logic or expectations ● varnishlog is the answer ● varnishncsa is not

5. varnishlog $ varnishlog -g request - Begin req 459063 rxreq - Timestamp Start: 1474493939.499338 0.000000 0.000000 - Timestamp Req: 1474493939.499338 0.000000 0.000000 - ReqStart 1.2.3.4 38780 - ReqMethod GET - ReqURL / - ReqProtocol HTTP/1.1 - ReqHeader Host: example.com - ReqHeader Accept: */* - ReqHeader Accept-Encoding: gzip - ReqHeader User-Agent: Mozilla/5.0 (X11; Linux x86_64) ... - ReqHeader Connection: close - ReqHeader X-Forwarded-For: 1.2.3.4 - VCL_call RECV - VCL_return hash - VCL_call HASH - VCL_return lookup - VCL_call MISS ...

6. varnishlog examples ● [5-9]xx responses: o varnishlog -q 'RespStatus >= 500' ● Misses: o varnishlog -q 'VCL_call ~ MISS' ● Timing details: o varnishlog -i Timestamp ● Requests taking more than 5 seconds:

7. Transactions Session Request Request BeReq ESI-SubReq BeReq -g <session|request|vxid|raw> The grouping of the log records. The default is to group by vxid.

8. Debugging with varnishlog ● man vsl ● printf debugging (std.log / std.syslog) ● Enable tracing (param.set vsl_mask +VCL_trace) ● Reproduce with varnishtest

9. Timestamps Timestamp - Timing information Contains timing information for the Varnish worker threads. The format is: %s: %f %f %f | | | | | | | +- Time since last timestamp | | +---- Time since start of work unit | +------- Absolute time of event +----------- Event label

10. Timestamped events Requests: Start The start of request processing (first byte received or restart). Req Complete client request received. ReqBody Client request body processed (discarded, cached or passed to the backend). Waitinglist Came off waitinglist. Fetch Fetch processing finished (completely fetched or ready for streaming). Process Processing finished, ready to deliver the client response. Resp Delivery of response to the client finished. Restart Client request is being restarted. Backend requests: Start Start of the backend fetch processing. Bereq Backend request sent. Beresp Backend response headers received. BerespBody Backend response body received. Retry Backend request is being retried. Error Backend request failed to vcl_backend_error.

11. varnishtest - example varnishtest "Hello world" server s1 { rxreq expect req.http.msg == "hello" txresp -body "world" } -start varnish v1 -vcl+backend { sub vcl_recv { set req.http.msg = "hello"; } } -start client c1 { txreq rxresp expect resp.status == 200 expect resp.body == "world" } -run [vagrant@centos-7-amd64 ~]$ varnishtest -v example.vtc … **** s1 0.4 EXPECT req.http.msg (hello) == "hello" match … *** c1 0.4 expect **** c1 0.4 EXPECT resp.status (200) == "200" match *** c1 0.4 expect **** c1 0.4 EXPECT resp.body (world) == "world" match … # top TEST example.vtc passed (1.494)

12. support@

13. https://github.com/varnish/varnishgather ● Reduce round trip time ● Versions ● varnishlog ● varnishstat ● VCL ● varnishadm panic.show ● syslog

14. DON'T PANIC

15. Stability ● Crash, panic or something else ● Check varnishadm panic.show and syslog ● File a bug or get your hands dirty

16. Getting your hands dirty ● Not for the faint of heart ● The panic dump ● Install debugging symbols and allow coredumps ● thread apply all bt full ● My approach: backtracking ○ Defensive programming

17. THE END

Add a comment