$upstream_response_time is improperly evaluated in header filter handlers

[Robert Paprocki]

$upstream_response time is incorrectly defined as the direct assignment of ngx_current_msec when used in a header phase handler. Consider the following config:

http {
    include       mime.types;
    default_type  application/octet-stream;

    log_format  main  '$remote_addr - $remote_user [$time_local] "$request" '
                      '$status $body_bytes_sent "$http_referer" '
                      '"$http_user_agent" "$http_x_forwarded_for" '
                      '$upstream_response_time';

    access_log  logs/access.log  main;

    upstream foo {
        server 127.0.0.1:9000;
    }

    server {
        listen 9000;
        server_name localhost;
        root html;

        access_log off;
        error_log off;
    }

    server {
        listen       80;
        server_name  localhost;

        location / {
            proxy_pass http://foo;

            add_header Upstream-Response-Time $upstream_response_time;
        }
}

The log format generated in such a context correctly shows $upstream_response_time:

127.0.0.1 - - [10/May/2017:19:09:48 -0700] "GET / HTTP/1.1" 200 612 "-" "curl/7.50.1" "-" 0.000

The assigned header, however, contains the value from the initial assignment:

$ curl -vv localhost
* Rebuilt URL to: localhost/
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 80 (#0)
> GET / HTTP/1.1
> Host: localhost
> User-Agent: curl/7.50.1
> Accept: */*
> 
< HTTP/1.1 200 OK
< Server: nginx/1.12.0
< Date: Thu, 11 May 2017 02:09:48 GMT
< Content-Type: text/html
< Content-Length: 612
< Connection: keep-alive
< Last-Modified: Thu, 11 May 2017 01:38:00 GMT
< ETag: "5913c078-264"
< Accept-Ranges: bytes
< Upstream-Response-Time: 1494468588.302

In cases where ngx_http_upstream_connect is only called one time (e.g. on first a successful upstream connection), ngx_http_upstream_finalize_request it not called before header phase modules execute, thus never reaching the path where u->state->response_time is reassigned to the diff between its initial value and the current ngx_current_msec (​https://github.com/nginx/nginx/blob/master/src/http/ngx_http_upstream.c#L4249). In cases where ngx_http_upstream_connect is called again (e.g. on a failed upstream connection), we do see a proper evaluation of the variable as a result of pushing the current state onto r->upstream_states (​https://github.com/nginx/nginx/blob/master/src/http/ngx_http_upstream.c#L1468-L1481). but obviously only for the previous connection).

I do not know if this is behavior should be treated as a bug per se, or if the documentation should only be updated to reflect the fact that this variable is meaningless for successful connections in header filter phases.

[Maxim Dounin]

That's expected behaviour, $upstream_response_time only make sense when a response is already received from the upstream server. Improving docs to clarify this may make sense though.

[kashiraja@…]

I'm getting a the same symptom when cache status is MISS and data is actually (and successfully) fetched from upstream server.

In my config I proxy GUNICORN/Django. But in my case I'm not yet able to get the cache to return cached data; every single response is status=MISS. I haven't found any problem with my configuration yet (I can't rule that out so this could be a corner case).

Anyways, this is what I see:

GET /api/1/vehicles HTTP/1.1
Accept: */*
Accept-Encoding: gzip, deflate
Connection: keep-alive
Host: 10.1.1.5:443
User-Agent: HTTPie/0.9.6



HTTP/1.1 200 OK
Allow: OPTIONS, GET
Cache-Control: max-age=3600
Connection: keep-alive
Content-Encoding: gzip
Content-Type: application/json
Date: Wed, 16 Aug 2017 17:25:54 GMT
Expires: Wed, 16 Aug 2017 18:25:54 GMT
Server: nginx/1.10.3 (Ubuntu)
Transfer-Encoding: chunked
X-Cache-Status: MISS                                           <----
X-Cache-Upstream-Connect-Time: 0.000
X-Cache-Upstream-Header-Time: 0.011
X-Cache-Upstream-Response-Time: 1502904354.351                 <----
X-Frame-Options: SAMEORIGIN
X-Request-Time: 0.011
X-SG-LOCATION: /api/
X-SG-URI: /api/1/vehicles
X-Upstream-Addr: unix:/srv/API/fleet_api/backend/mysite/mysite.sock

[Maxim Dounin]

Replying to kashiraja@…:

I'm getting a the same symptom when cache status is MISS and data is actually (and successfully) fetched from upstream server.

As explained above, this is expected behaviour. The $upstream_response_time variable is not yet available when generating response headers, because the response is not yet fully received at that time. You can get a correct value only when the response is fully received from the upstream server. That is, you can write the variable to access log, but you cannot use it in add_header.