Varnishncsa, Varnish:time_firstbyte, and nan

[Connor Walls]

Hello,

We use varnishncsa for logging all the requests that we serve - one of the fields we log is %{Varnish:time_firstbyte}x, measuring the "Time to the first byte from the backend arrived". Now, sometimes we see this value being reported as "nan". Initially I believe this to be the case whenever an object was being served from cache, however, it seems that that is not entirely the case. Here's an example of varnishncsa -F "%{Varnish:time_firstbyte}x %{Varnish:handling}x"

0.012956619 miss
0.009663820 pass
nan hit
nan miss
nan hit
0.223460436 pass
0.000072479 miss
0.000100851 hit
0.000062227 miss

So here I see passes and misses with a value (which I expect), hits with "nan" (which I expect), hits with a value (which I don't expect) and misses with "nan" (which I also don't expect). I would just like some clarification as to what it means when "nan" is logged, and under what scenarios this occurs? Could it be related to ESI processing or similar, where some parts of the request are served from cache and other parts aren't?

Thanks,
Connor Walls