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 "