Ⅰ. Issue Description

Tengine's dynamic upstream module Logs

When using upstream dynamic's tengine module , upstream_response_time and upstream_addr nginx variables behaves extrangely.

Ⅱ. Describe what happened

Despite the fallback configuration I use, upstream_response_time and upstream_addr register two values, even if was only one request and the connection was kept alive.
Note that I have set proxy_next_upstream off; to avoid retries on failed upstream connections.

It logs differently from an upstream without dynamic_resolve config.

Ⅲ. Describe what you expected to happen

I expect a single value if there is a single request. Is The first value the DNS resolution?

Ⅳ. How to reproduce it (as minimally and precisely as possible)

repository - how to reproduce with docker

1. example nginx.conf

daemon off;

events {
  worker_connections 8000;
  use epoll;
}

http {
  lua_package_path "/usr/local/lib/lua/?.lua;$prefix/lua/?.lua;;;";
  lua_package_cpath '$prefix//lua/bin/linux/x64/clibs/?.so;;';
  root ./;

  proxy_next_upstream off;

  log_format interceptorFormat '$request_method $request_uri \t[upstream_response_time:$upstream_response_time] [upstream_addr:$upstream_addr] [status:$status] [request_time:$request_time]';

  upstream google_upstream {
    server google.com;
    keepalive 200;
  }

  upstream google_dynamic_upstream {
    dynamic_resolve fallback=shutdown fail_timeout=5s;
    server google.com max_fails=0;
  }

  server {
    listen       8080;
    access_log /var/log/nginx/access.log interceptorFormat;
    keepalive_requests 100000;

    location /test-simple {
      proxy_pass http://google_upstream$request_uri;
      proxy_set_header    Host        $host;
      proxy_http_version  1.1;
      proxy_set_header    Connection  "";
    }

    location /test-dynamic {
      proxy_pass http://google_dynamic_upstream$request_uri;
      proxy_set_header    Host        $host;
      proxy_http_version  1.1;
      proxy_set_header    Connection  "";
    }
  }
}

Run

• docker-compose up -d
• curl localhost:8080/test-simple && curl localhost:8080/test-dynamic
• docker-compose logs

You'll see:

Creating tengine-dynamic-upstream-test_tengine_server_1 ... done
Attaching to tengine-dynamic-upstream-test_tengine_server_1
tengine_server_1  | GET /test-simple 	[upstream_response_time:0.033] [upstream_addr:172.217.172.46:80] [status:404] [request_time:0.034]
tengine_server_1  | GET /test-dynamic 	[upstream_response_time:0.003, 0.034] [upstream_addr:, 172.217.172.46:80] [status:404] [request_time:0.036]

Ⅴ. Anything else we need to know?

1. Tcpdump GET /test-simple

1. Tcpdump GET /test-dynamic

1. tengine 2.2.1 logs differently (- instead of a value)

tengine_server_1 | GET /test-simple [upstream_response_time:0.005] [upstream_addr:104.18.18.22:80] [status:200] [request_time:0.008]
tengine_server_1 | GET /test-dynamic [upstream_response_time:-, 0.024] [upstream_addr:, 172.21.0.5:80] [status:200] [request_time:0.024]

Ⅵ. Environment:

• Tengine version (use sbin/nginx -V ):

Tengine version: Tengine/2.3.2
nginx version: nginx/1.17.3
built by gcc 5.4.0 20160609 (Ubuntu 5.4.0-6ubuntu1~16.04.12) 
built with OpenSSL 1.0.2g  1 Mar 2016
TLS SNI support enabled
configure arguments: --prefix=/usr/local/nginx --with-ld-opt=-Wl,-lossp-uuid,-rpath,/usr/local/lib --with-cc-opt=-I/usr/include/ossp --add-module=/usr/src/nginx-2.3.2/modules/ngx_devel_kit --add-module=/usr/src/nginx-2.3.2/modules/lua-nginx-module --add-module=modules/ngx_http_upstream_dynamic_module --with-http_stub_status_module --http-log-path=/var/log/nginx/access.log --error-log-path=/var/log/nginx/error.log

• OS (e.g. from /etc/os-release):
  ubuntu:16.04
• Kernel (e.g. uname -a ):
  Linux 35afc25821a3 4.19.76-linuxkit #1 SMP Fri Mar 6 18:33:07 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
• Others:
  running on osx, docker-compose version 1.26.0-rc3, build 46118bc5