[bug] the upstream-response-time value is wrong

[WALL-E]

I want to get upstream-response-time value by lua-script, but returned wrong value, inconsistent with the official website of the document description

lua script

header_filter_by_lua_block {
                ngx.header["upstream_addr"] = ngx.var.upstream_addr
                ngx.header["upstream_connect_time"] = ngx.var.upstream_connect_time
                ngx.header["upstream_header_time"] = ngx.var.upstream_header_time
                ngx.header["upstream_response_time"] = ngx.var.upstream_response_time
            }

response header

...
upstream-addr: 172.17.0.2:80
upstream-connect-time: 0.000
upstream-header-time: 0.000
upstream-response-time: 1478689090.993
...

openresty version

nginx version: openresty/1.11.2.1
built by gcc 4.8.5 20150623 (Red Hat 4.8.5-4) (GCC)
built with OpenSSL 1.0.1e-fips 11 Feb 2013
TLS SNI support enabled
configure arguments: --prefix=/opt/openresty/nginx --with-cc-opt=-O2 --add-module=../ngx_devel_kit-0.3.0 --add-module=../echo-nginx-module-0.60 --add-module=../xss-nginx-module-0.05 --add-module=../ngx_coolkit-0.2rc3 --add-module=../set-misc-nginx-module-0.31 --add-module=../form-input-nginx-module-0.12 --add-module=../encrypted-session-nginx-module-0.06 --add-module=../srcache-nginx-module-0.31 --add-module=../ngx_lua-0.10.6 --add-module=../ngx_lua_upstream-0.06 --add-module=../headers-more-nginx-module-0.31 --add-module=../array-var-nginx-module-0.05 --add-module=../memc-nginx-module-0.17 --add-module=../redis2-nginx-module-0.13 --add-module=../redis-nginx-module-0.3.7 --add-module=../rds-json-nginx-module-0.14 --add-module=../rds-csv-nginx-module-0.07 --with-ld-opt=-Wl,-rpath,/opt/openresty/luajit/lib --with-http_realip_module --with-http_ssl_module

[agentzh]

@WALL-E Please provide a standalone and minimal example that we can run on our side to reproduce the issue. Your example is not complete.

[WALL-E]

I run openresty on docker, the following is a complete configuration file nginx.conf

user  root root;
worker_processes  auto;
daemon off;

events {
    use epoll;
    multi_accept on;
    accept_mutex_delay 50ms;
    worker_connections 65535;
}

http {
     log_format  main  '$remote_addr - $remote_user [$time_local] "$request" '
                       '$status $body_bytes_sent "$http_referer" '
                       '"$http_user_agent" "$http_x_forwarded_for" '
                       '"$upstream_addr" "$upstream_status" '
                       '$request_time -- $upstream_connect_time $upstream_header_time $upstream_response_time';


    access_log  logs/access.log  main;
    upstream backend {
        server web-a:80;
        server web-b:80;
        server web-c:80;
        server web-d:80;
    }

    server {
        listen       80;
        server_name  localhost;

        set_real_ip_from 172.17.0.0/16;
        real_ip_header X-Forwarded-For;
        real_ip_recursive on;
        proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;

        more_set_headers 'Server: Qengined';

        location ~ /.* {
            proxy_pass http://backend;

            header_filter_by_lua_block {
                ngx.header["upstream_addr"] = ngx.var.upstream_addr
                ngx.header["upstream_connect_time"] = ngx.var.upstream_connect_time
                ngx.header["upstream_header_time"] = ngx.var.upstream_header_time
                ngx.header["upstream_response_time"] = ngx.var.upstream_response_time
            }
        }
    }
}

Additional

• Platform
  • host: CentOS Linux release 7.2.1511 (Core)
  • Docker version 1.12.2, build bb80604

if need, i can provide compose YML.

[agentzh]

@WALL-E Please make it minimal and complete. I have no idea about those web-a through web-d servers in your example, for example. Also, please no docker.

[WALL-E]

Steps To Reproduce

1. install openresty/1.11.2.1

2. run two openresty instances, a proxy and a web

3. web's config

   nginx_web.conf

   user  root root;
   worker_processes  auto;
   
   events {
   use epoll;
   }
   
   http {
   server {
       listen       8081;
       server_name  localhost;
   
       location ~ /.* {
           content_by_lua_block {
               ngx.say('access: ', ngx.var.server_addr, ' from: ', ngx.var.remote_addr)
           }
       }
   }
   }
   

4. start web instances

   /opt/openresty/nginx/sbin/nginx -c /root/openresty-debug/nginx_web.conf
   

5. proxy's config

   nginx_proxy.conf

   user  root root;
   worker_processes  auto;
   
   events {
     use epoll;
   }
   
   http {
       upstream backend {
           server 127.0.0.1:8081;
       }
   
   server {
       listen       8080;
       server_name  localhost;
   
       location ~ /.* {
           proxy_pass http://backend;
   
           header_filter_by_lua_block {
               ngx.header["upstream_addr"] = ngx.var.upstream_addr
               ngx.header["upstream_connect_time"] = ngx.var.upstream_connect_time
               ngx.header["upstream_header_time"] = ngx.var.upstream_header_time
               ngx.header["upstream_response_time"] = ngx.var.upstream_response_time
           }
       }
   }
   }
   

6. start proxy instances

   /opt/openresty/nginx/sbin/nginx -c /root/openresty-debug/nginx_proxy.conf
   

7. acces proxy

   [root@vagrant-172-28-32-101 openresty-debug]# curl -i http://127.0.0.1:8080
   HTTP/1.1 200 OK
   Server: openresty/1.11.2.1
   Date: Sat, 12 Nov 2016 03:00:45 GMT
   Content-Type: text/plain
   Content-Length: 34
   Connection: keep-alive
   upstream-addr: 127.0.0.1:8081
   upstream-connect-time: 0.000
   upstream-header-time: 0.000
   upstream-response-time: 1478919645.596
   
   access: 127.0.0.1 from: 127.0.0.1
   

wrong value

upstream-response-time: 1478919645.596

[WALL-E]

I test openresty/1.9.7.1, there are also the same issue.

[agentzh]

@WALL-E Okay, I see what's going on here.

Basically, what you are seeing is the expected value. It is the timestamp of the beginning of the upstream response when the upstream response is not fully received. Because you read the $upstream_response_time variable in the header filter handler, which means that the upstream response body has not yet generated.

To get what you want in that header filter handler, you need to do the math yourself, as in

local resp_time_so_far = ngx.now() - ngx.var.upstream_response_time

[agentzh]

@WALL-E To get the full response time, you need to read $upstream_response_time in the log phase instead, where the response is fully generated.

[WALL-E]

@agentzh thks, I got it.

Sorry, I forgot about phase