id	summary	reporter	owner	description	type	status	priority	milestone	component	version	resolution	keywords	cc	uname	nginx_version
1269	$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."	defect	closed	minor		documentation	1.11.x	fixed	upstream upstream_response_time		"Linux metal 4.8.0-37-generic #39-Ubuntu SMP Thu Jan 26 02:27:07 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
"	"nginx version: nginx/1.11.0
built by gcc 6.2.0 20161005 (Ubuntu 6.2.0-5ubuntu12) 
configure arguments: --with-debug
"