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@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@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@telecom.pt

_______________________________________________
nginx-devel mailing list
nginx-devel@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx-devel