nginx report a timestamp on upstream_response_time

[Dani Bento]

I was searching in the nginx tree for response_sec/msec fields and
the only place where I found them was in src/http/ngx_http_upstream.c

This fields are updated at ngx_http_upstream.c

1189 ngx_http_upstream_connect(...)

1197     if (u->state && u->state->response_sec) {
1198         tp = ngx_timeofday();
1199         u->state->response_sec = tp->sec - u->state->response_sec;
1200         u->state->response_msec = tp->msec -u->state->response_msec;
1201     }

(...)

3408 ngx_http_upstream_finalize_request(...)

3427     if (u->state && u->state->response_sec) {
3428         tp = ngx_timeofday();
3429         u->state->response_sec = tp->sec - u->state->response_sec;
3430         u->state->response_msec = tp->msec -u->state->response_msec;
3431 
3432         if (u->pipe && u->pipe->read_length) {
3433		 u->state->response_length = u->pipe->read_length;
3434         } 
3435     }

(...)

I assume that in both cases, we have to have u->state not NULL and u->state->response_sec not NULL or 0.

Searching a little more I found that for ngx_http_upstream_connect we have this:

1203     u->state = ngx_array_push(r->upstream_states);
1204     if (u->state == NULL) {
1205         ngx_http_upstream_finalize_request(r, u,
1206                                            NGX_HTTP_INTERNAL_SERVER_ERROR);
1207         return;
1208     }
1209 
1210     ngx_memzero(u->state, sizeof(ngx_http_upstream_state_t));
1211 
1212     tp = ngx_timeofday();
1213     u->state->response_sec = tp->sec;
1214     u->state->response_msec = tp->msec;

But in ngx_http_upstream_init_request we have:

559     } else {
560 
561         u->state = ngx_array_push(r->upstream_states);
562         if (u->state == NULL) {
563             ngx_http_upstream_finalize_request(r, u,
564                                                NGX_HTTP_INTERNAL_SERVER_ERROR);
565             return;
566         }
567 
568         ngx_memzero(u->state, sizeof(ngx_http_upstream_state_t));
569     }

The u->state->response_sec and u->state->response_mset are initialized with ngx_timeofday() in the first case, but are only zeroed in the second case.

If the fields response_sec/msec are only affected if response_sec is not NULL or 0, it's possible that, in this particular condition, 
the time will be never updated with the correct value in the ngx_http_upstream_finalize_request?

Dani

On Tue, 10 Feb 2015 16:08:06 +0000
Dani Bento <dani at telecom.pt> wrote:

> 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