nginx report a timestamp on upstream_response_time

[Dani Bento]

Hello,

We are using LUA header filter to process some headers and decide if
the request should continue or stop (or redirect), using
ngx.exit().

Can it be a failure on ngx.exit LUA call? We will try to trace the
process to be sure where the problem resides.

Dani

On Tue, 10 Feb 2015 15:25:39 +0000
Maxim Dounin <mdounin at mdounin.ru> wrote:

> 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.
> 



-- 
Dani Bento
Direção de Internet e Tecnologia
DTS/DVS
tlm: +351 91 429 72 81
dani at telecom.pt