nginx report a timestamp on upstream_response_time

[Maxim Dounin]

Hello!

On Tue, Feb 10, 2015 at 11:54:57AM +0000, Dani Bento wrote:

> Hello,
> 
> We are using nginx 1.6.2 and we found in our logs a strange behavior
> when connecting to an upstream.
> 
> We found that in ngx_http_upstream.c:1213 we have:
> 
> u->state->response_sec = tp->sec;
> u->state->response_msec = tp->msec;
> 
> which gave to the last state the current ngx time (ngx_timeofday()).
> 
> For some reason, the ngx_http_upstream_finalize_request(), where those
> values are updated to the correct value, doesn't run (we observe that
> most of the times, but not all the times, it happens after a 302 given
> by then upstream).
> 
> This is a normal behavior? If yes, have we any way to avoid those pikes
> in the logs?

No, this is not normal, ngx_http_upstream_finalize_request() is 
expected to be called before request logging.  If this doesn't 
happen in your case, it would be good to trace the problem.

Just in case, some debugging hints can be found at 
http://wiki.nginx.org/Debugging.

-- 
Maxim Dounin
http://nginx.org/