Using $upstream_response_time in add_header shows a dash

[Maxim Dounin]

Hello!

On Fri, Feb 05, 2021 at 03:38:16PM -0500, MarioIshac wrote:

> Hello all,
> 
> I have this example nginx.conf:
> https://gist.github.com/MarioIshac/e6971ab0b343da210de62ebb1c6e2f99 to
> reproduce the behavior.
> 
> I start nginx and an example upstream with:
> 
> python3 -u -m http.server 8001 > app.log 2>&1 & sudo nginx > nginx.log 2>&1
> 
> Upon hitting nginx with `curl -i localhost:8000`, I see these response
> headers:
> 
> X-Trip-Time: 0.001
> X-Addr: 127.0.0.1:8001
> X-Status: 200
> X-Process-Time: -
> 
> `cat app.log` shows that upstream was hit successfully, and `cat nginx.log`
> shows that nginx knows the $upstream_response_time at log time, as I get
> this log:
> 
> 127.0.0.1:8001 200 0.004
> 
> Why does nginx substitute the request time and relevant response metadata
> (like $upstream_status) at add_header time successfully, yet substitutes the
> upstream response time with a dash?
> 
> My goal with returning $upstream_response_time in a header is so the client
> can know how much of their request latency was due to their upload speeds
> vs. server processing time. 

That's because response headers are sent before the 
$upstream_response_time is known: it is only known when the 
response is fully received from the upstream server, including the 
response body, and this happens after the response headers are 
sent to the client.  If you want to return something in the 
response headers, consider the $upstream_header_time variable 
instead (http://nginx.org/r/$upstream_header_time).

-- 
Maxim Dounin
http://mdounin.ru/