nginx report a timestamp on upstream_response_time

[Dani Bento]

Hello,

After some research, we simplify our configuration to only have an
header_filter_by_lua_file 'script.lua' with the following
code:

ngx.log(ngx.WARN, string.format("enter script"))
ngx.exit(502)

Making a siege -i -c 100 http://localhost/location we get some of the
reported upstream_response_time.

To verify if this could be some type of concurrency problem we put a
ngx.sleep(0.001) before the ngx.exit() call. Apparently, this change
removed all the wrong times in the upstream_response_time, giving
always the expected value.

Can be this a problem of the lua-nginx-module? Or some nginx race
condition?

Dani

On Wed, 11 Feb 2015 15:26:59 +0000
Maxim Dounin <mdounin at mdounin.ru> wrote:

> Hello!
> 
> On Wed, Feb 11, 2015 at 03:20:59PM +0000, Dani Bento wrote:
> 
> > Hello,
> > 
> > I was looking in ngx_http_upstream_response_time_variable.
> > 
> > I understand that if the state[i].status is not 0, the 
> > state[i].response_sec is used.
> > 
> > It is assumed that if a state doesn't have a peer it prints a ":"
> > before the next state (like the upstream_status_variable)
> > 
> > Our problem is that in the log we have:
> > 
> > [200 : 302] (for the status codes)
> > 
> > [0.02 : 1423667767.600] (for the upstream_response_time)
> 
> So the question remains: how this happens.
> 
> (Note though, that this can easily happen if you'll try to use the 
> $upstream_response_time variable before the request is finalized, 
> e.g., in add_header or in 3rd party modules.  But it shouldn't 
> happen during logging, as the request is expected to be finalized 
> at this time.)
> 



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