Mailing List Archive: varnishncsa %s in backend mode: 304 logged as 200

varnishncsa %s in backend mode: 304 logged as 200

Oct 31, 2019, 9:16 AM

Post #1 of 3 (638 views)

Hi,

we want to get a better understanding how well our varnish setup is
performing. We've got two varnishncsa running, one with '-b' and one
without, and each with their own logformat configuration. Each of
those configurations contains "status":%s. Varnish version is
varnish-6.2.1.

If varnish successfully revalidates a stored response, i would expect
the backend log to show a status of 304, and the client log a status
of 200, but in reality, the vanishncsa running with "-b" also reports
a status of 200.

Just to make sure, I've watched with tcpdump what's going on, and
varnish does really receive a 304 from the backend. The client sends

GET /test/5db010a2-07a5-4119-b90b-ed7328c42231 HTTP/1.1
Host: cachetest.backend
[...]

and receives from varnish:

HTTP/1.1 200 OK
Cache-Control: max-age=3600
Date: Thu, 31 Oct 2019 14:43:19 GMT
Etag: "ASKCUMEWOGYQIAS"
[...]

The same request between varnish and the backend:

GET /test/5db010a2-07a5-4119-b90b-ed7328c42231 HTTP/1.1
Host: cachetest.backend
If-None-Match: "ASKCUMEWOGYQIAS"
[...]

HTTP/1.1 304 Not Modified
Cache-Control: max-age=3600
Date: Thu, 31 Oct 2019 14:43:19 GMT
Etag: "ASKCUMEWOGYQIAS"
Connection: close

Is there another statement for the varnishncsa log format that shows
the "real" backend HTTP status? Does this work as intended, or is this
a bug?

Rainer
_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

Re: varnishncsa %s in backend mode: 304 logged as 200 [ In reply to ]

guillaume at varnish-software

Oct 31, 2019, 9:48 AM

Post #2 of 3 (638 views)

Permalink

Hi,

Varnish automatically transforms the 304 response into the object it
represents, this is why you are seeing the 200 (but it could be pretty much
any status that you are revalidating).
If you want to check for 304s, you can do something like this:

sub vcl_backend_response {
if (beresp.was_304) {
std.log("true_status: 304");
} else {
std.log("true_status: " + beresp.status);
}
}

and then use %{VSL:VCL_Log:true_status}x in the varnishncsa format line to
retrieve it
--
Guillaume Quintard

On Thu, Oct 31, 2019 at 9:17 AM Rainer Canavan <
rainer.canavan+varnish@sevenval.com> wrote:

> Hi,
>
> we want to get a better understanding how well our varnish setup is
> performing. We've got two varnishncsa running, one with '-b' and one
> without, and each with their own logformat configuration. Each of
> those configurations contains "status":%s. Varnish version is
> varnish-6.2.1.
>
> If varnish successfully revalidates a stored response, i would expect
> the backend log to show a status of 304, and the client log a status
> of 200, but in reality, the vanishncsa running with "-b" also reports
> a status of 200.
>
> Just to make sure, I've watched with tcpdump what's going on, and
> varnish does really receive a 304 from the backend. The client sends
>
> GET /test/5db010a2-07a5-4119-b90b-ed7328c42231 HTTP/1.1
> Host: cachetest.backend
> [...]
>
> and receives from varnish:
>
> HTTP/1.1 200 OK
> Cache-Control: max-age=3600
> Date: Thu, 31 Oct 2019 14:43:19 GMT
> Etag: "ASKCUMEWOGYQIAS"
> [...]
>
> The same request between varnish and the backend:
>
> GET /test/5db010a2-07a5-4119-b90b-ed7328c42231 HTTP/1.1
> Host: cachetest.backend
> If-None-Match: "ASKCUMEWOGYQIAS"
> [...]
>
> HTTP/1.1 304 Not Modified
> Cache-Control: max-age=3600
> Date: Thu, 31 Oct 2019 14:43:19 GMT
> Etag: "ASKCUMEWOGYQIAS"
> Connection: close
>
> Is there another statement for the varnishncsa log format that shows
> the "real" backend HTTP status? Does this work as intended, or is this
> a bug?
>
> Rainer
> _______________________________________________
> varnish-misc mailing list
> varnish-misc@varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>

Re: varnishncsa %s in backend mode: 304 logged as 200 [ In reply to ]

rainer.canavan+varnish at sevenval

Oct 31, 2019, 10:14 AM

Post #3 of 3 (638 views)

Permalink

On Thu, Oct 31, 2019 at 5:48 PM Guillaume Quintard <
guillaume@varnish-software.com> wrote:
>
> Hi,
>
> Varnish automatically transforms the 304 response into the object it
represents, this is why you are seeing the 200 (but it could be pretty much
any status that you are revalidating).
> If you want to check for 304s, you can do something like this:
>
> sub vcl_backend_response {
> if (beresp.was_304) {
> std.log("true_status: 304");
> } else {
> std.log("true_status: " + beresp.status);
> }
> }
>
> and then use %{VSL:VCL_Log:true_status}x in the varnishncsa format line
to retrieve it

Thanks, that construct logs exactly what I wanted.

Rainer