bug: The IP of upstream and tcpdump are inconsistent

[dimon-v]

Current Behavior

我使用了apisix.router.http: radixtree_uri_with_parameter，当我压测时，过一段时间发现，debug日志中upstream和tcpdump的ip不一致

I used apisix.router.http: radixtree_uri_with_parameter. During the pressure test, I found that the IP addresses of upstream and tcpdump packets in the debug log were inconsistent after a while

Expected Behavior

No response

Error Logs

------ apisix error.log [root@ali-xuanxing2-ServiceMaker-etcd-prod logs]# less error.log | grep '/tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=118' 2022/08/26 16:43:44 [warn] 2429#2429: 64180791 [lua] init.lua:377: http_access_phase(): DT match-route,host: api-phx-tp-tc.xxx.com.cn uri: /tlive/backend/liveroom/page matched:{"value":{"id":"418086805397570639","plugins":{"response-rewrite":{"headers":{"upstream":"$balancer_ip"},"headers_arr":["upstream","$balancer_ip"],"body_base64":false,"disable":false},"proxy-rewrite":{"scheme":"http"},"yxt-options":{}},"create_time":1658728755,"uri":"/","status":1,"update_time":1661417737,"upstream_id":"418086686480663631","name":"tptc-default","hosts":["api-paas-tp-tc.xxx.com.cn","api-phx-tp-tc.xxx.com.cn"],"priority":0},"key":"/apisix/routes/418086805397570639","createdIndex":7181614,"modifiedIndex":11667456,"clean_handlers":{},"orig_modifiedIndex":11667456,"has_domain":false,"update_count":0}, client: 123.57.135.222, server: _, request: "HEAD /tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=118 HTTP/1.1", host: "api-phx-tp-tc.xxx.com.cn" 2022/08/26 16:43:44 [info] 2429#2429: 64180791 [lua] init.lua:378: http_access_phase(): matched route: {"value":{"id":"418086805397570639","plugins":{"response-rewrite":{"headers":{"upstream":"$balancer_ip"},"headers_arr":["upstream","$balancer_ip"],"body_base64":false,"disable":false},"proxy-rewrite":{"scheme":"http"},"yxt-options":{}},"create_time":1658728755,"uri":"/","status":1,"update_time":1661417737,"upstream_id":"418086686480663631","name":"tptc-default","hosts":["api-paas-tp-tc.xxx.com.cn","api-phx-tp-tc.xxx.com.cn"],"priority":0},"key":"/apisix/routes/418086805397570639","createdIndex":7181614,"modifiedIndex":11667456,"clean_handlers":{},"orig_modifiedIndex":11667456,"has_domain":false,"update_count":0}, client: 123.57.135.222, server: _, request: "HEAD /tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=118 HTTP/1.1", host: "api-phx-tp-tc.xxx.com.cn" 2022/08/26 16:43:44 [info] 2429#2429: *64180791 [lua] upstream.lua:568: get_by_id(): parsed upstream: {"value":{"id":"418086686480663631","create_time":1658728684,"keepalive_pool":{"requests":1000,"size":320,"idle_timeout":60},"original_nodes":[{"port":80,"host":"10.100.2.169","upstream_host":"10.100.2.169","weight":1,"priority":0}],"scheme":"http","parent":{"value":"table: 0x7f0e5786a7e8","key":"/apisix/upstreams/418086686480663631","modifiedIndex":11667450,"createdIndex":7181613,"has_domain":false,"clean_handlers":{}},"timeout":{"connect":6,"read":6,"send":6},"hash_on":"vars","update_time":1661417085,"pass_host":"pass","type":"roundrobin","name":"tptc-http-ups","nodes":"table: 0x7f0e573a0a50","nodes_ref":"table: 0x7f0e573a0a50"},"key":"/apisix/upstreams/418086686480663631","modifiedIndex":11667450,"createdIndex":7181613,"has_domain":false,"clean_handlers":"table: 0x7f0e557494b8"}, client: 123.57.135.222, server: _, request: "HEAD /tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=118 HTTP/1.1", host: "api-phx-tp-tc.xxx.com.cn" 2022/08/26 16:43:44 [info] 2429#2429: 64180791 [lua] balancer.lua:194: pick_server(): route: {"value":{"id":"418086805397570639","plugins":{"response-rewrite":{"headers":{"upstream":"$balancer_ip"},"headers_arr":["upstream","$balancer_ip"],"body_base64":false,"disable":false},"proxy-rewrite":{"scheme":"http"},"yxt-options":{}},"create_time":1658728755,"uri":"/","status":1,"update_time":1661417737,"upstream_id":"418086686480663631","name":"tptc-default","hosts":["api-paas-tp-tc.xxx.com.cn","api-phx-tp-tc.xxx.com.cn"],"priority":0},"key":"/apisix/routes/418086805397570639","createdIndex":7181614,"modifiedIndex":11667456,"clean_handlers":{},"orig_modifiedIndex":11667456,"has_domain":false,"update_count":0}, client: 123.57.135.222, server: _, request: "HEAD /tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=118 HTTP/1.1", host: "api-phx-tp-tc.xxx.com.cn" 2022/08/26 16:43:44 [info] 2429#2429: *64180791 [lua] init.lua:535: http_access_phase(): stash ngx ctx: 141, client: 123.57.135.222, server: _, request: "HEAD /tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=118 HTTP/1.1", host: "api-phx-tp-tc.xxx.com.cn" 2022/08/26 16:43:44 [info] 2429#2429: *64180791 [lua] balancer.lua:377: run(): proxy request to 10.100.2.169:80 while connecting to upstream, client: 123.57.135.222, server: _, request: "HEAD /tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=118 HTTP/1.1", host: "api-phx-tp-tc.xxx.com.cn" 2022/08/26 16:43:44 [info] 2429#2429: *64180791 [lua] init.lua:551: fetch_ctx(): fetch ngx ctx: 141 while reading response header from upstream, client: 123.57.135.222, server: _, request: "HEAD /tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=118 HTTP/1.1", upstream: "http://10.100.2.169:80/tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=118", host: "api-phx-tp-tc.xxx.com.cn" 2022/08/26 16:43:44 [warn] 2429#2429: *64180791 [lua] plugin.lua:353: trace_plugins_info_for_debug(): Apisix-Plugins: response-rewrite while logging request, client: 123.57.135.222, server: _, request: "HEAD /tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=118 HTTP/1.1", upstream: "http://10.100.2.169:80/tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=118", host: "api-phx-tp-tc.xxx.com.cn" [root@ali-xuanxing2-ServiceMaker-etcd-prod logs]# less error.log | grep '/tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=117' 2022/08/26 16:43:39 [warn] 2431#2431: 64180492 [lua] init.lua:377: http_access_phase(): DT match-route,host: api-phx-tp-tc.xxx.com.cn uri: /tlive/backend/liveroom/page matched:{"value":{"id":"418086805397570639","plugins":{"response-rewrite":{"headers":{"upstream":"$balancer_ip"},"headers_arr":["upstream","$balancer_ip"],"body_base64":false,"disable":false},"proxy-rewrite":{"scheme":"http"},"yxt-options":{}},"create_time":1658728755,"uri":"/","status":1,"update_time":1661417737,"upstream_id":"418086686480663631","name":"tptc-default","hosts":["api-paas-tp-tc.xxx.com.cn","api-phx-tp-tc.xxx.com.cn"],"priority":0},"key":"/apisix/routes/418086805397570639","createdIndex":7181614,"modifiedIndex":11667456,"clean_handlers":{},"orig_modifiedIndex":11667456,"has_domain":false,"update_count":0}, client: 123.57.135.222, server: _, request: "HEAD /tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=117 HTTP/1.1", host: "api-phx-tp-tc.xxx.com.cn" 2022/08/26 16:43:39 [info] 2431#2431: 64180492 [lua] init.lua:378: http_access_phase(): matched route: {"value":{"id":"418086805397570639","plugins":{"response-rewrite":{"headers":{"upstream":"$balancer_ip"},"headers_arr":["upstream","$balancer_ip"],"body_base64":false,"disable":false},"proxy-rewrite":{"scheme":"http"},"yxt-options":{}},"create_time":1658728755,"uri":"/","status":1,"update_time":1661417737,"upstream_id":"418086686480663631","name":"tptc-default","hosts":["api-paas-tp-tc.xxx.com.cn","api-phx-tp-tc.xxx.com.cn"],"priority":0},"key":"/apisix/routes/418086805397570639","createdIndex":7181614,"modifiedIndex":11667456,"clean_handlers":{},"orig_modifiedIndex":11667456,"has_domain":false,"update_count":0}, client: 123.57.135.222, server: _, request: "HEAD /tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=117 HTTP/1.1", host: "api-phx-tp-tc.xxx.com.cn" 2022/08/26 16:43:39 [info] 2431#2431: *64180492 [lua] upstream.lua:568: get_by_id(): parsed upstream: {"value":{"id":"418086686480663631","create_time":1658728684,"keepalive_pool":{"requests":1000,"size":320,"idle_timeout":60},"original_nodes":[{"port":80,"host":"10.100.2.169","upstream_host":"10.100.2.169","weight":1,"priority":0}],"scheme":"http","parent":{"value":"table: 0x7f0e5786a7e8","key":"/apisix/upstreams/418086686480663631","modifiedIndex":11667450,"createdIndex":7181613,"has_domain":false,"clean_handlers":{}},"timeout":{"connect":6,"read":6,"send":6},"hash_on":"vars","update_time":1661417085,"pass_host":"pass","type":"roundrobin","name":"tptc-http-ups","nodes":"table: 0x7f0e573a0a50","nodes_ref":"table: 0x7f0e573a0a50"},"key":"/apisix/upstreams/418086686480663631","modifiedIndex":11667450,"createdIndex":7181613,"has_domain":false,"clean_handlers":"table: 0x7f0e56f1cd08"}, client: 123.57.135.222, server: _, request: "HEAD /tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=117 HTTP/1.1", host: "api-phx-tp-tc.xxx.com.cn" 2022/08/26 16:43:39 [info] 2431#2431: 64180492 [lua] balancer.lua:194: pick_server(): route: {"value":{"id":"418086805397570639","plugins":{"response-rewrite":{"headers":{"upstream":"$balancer_ip"},"headers_arr":["upstream","$balancer_ip"],"body_base64":false,"disable":false},"proxy-rewrite":{"scheme":"http"},"yxt-options":{}},"create_time":1658728755,"uri":"/","status":1,"update_time":1661417737,"upstream_id":"418086686480663631","name":"tptc-default","hosts":["api-paas-tp-tc.xxx.com.cn","api-phx-tp-tc.xxx.com.cn"],"priority":0},"key":"/apisix/routes/418086805397570639","createdIndex":7181614,"modifiedIndex":11667456,"clean_handlers":{},"orig_modifiedIndex":11667456,"has_domain":false,"update_count":0}, client: 123.57.135.222, server: _, request: "HEAD /tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=117 HTTP/1.1", host: "api-phx-tp-tc.xxx.com.cn" 2022/08/26 16:43:39 [info] 2431#2431: *64180492 [lua] init.lua:535: http_access_phase(): stash ngx ctx: 223, client: 123.57.135.222, server: _, request: "HEAD /tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=117 HTTP/1.1", host: "api-phx-tp-tc.xxx.com.cn" 2022/08/26 16:43:39 [info] 2431#2431: *64180492 [lua] balancer.lua:377: run(): proxy request to 10.100.2.169:80 while connecting to upstream, client: 123.57.135.222, server: _, request: "HEAD /tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=117 HTTP/1.1", host: "api-phx-tp-tc.xxx.com.cn" 2022/08/26 16:43:39 [info] 2431#2431: *64180492 [lua] init.lua:551: fetch_ctx(): fetch ngx ctx: 223 while reading response header from upstream, client: 123.57.135.222, server: _, request: "HEAD /tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=117 HTTP/1.1", upstream: "http://10.100.2.169:80/tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=117", host: "api-phx-tp-tc.xxx.com.cn" 2022/08/26 16:43:39 [warn] 2431#2431: *64180492 [lua] plugin.lua:353: trace_plugins_info_for_debug(): Apisix-Plugins: response-rewrite while logging request, client: 123.57.135.222, server: _, request: "HEAD /tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=117 HTTP/1.1", upstream: "http://10.100.2.169:80/tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=117", host: "api-phx-tp-tc.xxx.com.cn"

------ tcpdump

Steps to Reproduce

curl again ...

Environment

[root@ali-xuanxing2-ServiceMaker-etcd-prod apisix]# apisix version /usr/local/openresty/luajit/bin/luajit ./apisix/cli/apisix.lua version 2.14.1

[root@ali-xuanxing2-ServiceMaker-etcd-prod apisix]# uname -a Linux ali-xuanxing2-ServiceMaker-etcd-prod 3.10.0-1160.62.1.el7.x86_64 #1 SMP Tue Apr 5 16:57:59 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux

[root@ali-xuanxing2-ServiceMaker-etcd-prod apisix]# openresty -V nginx version: openresty/1.21.4.1 built by gcc 9.3.1 20200408 (Red Hat 9.3.1-2) (GCC) built with OpenSSL 1.1.1n 15 Mar 2022 TLS SNI support enabled configure arguments: --prefix=/usr/local/openresty/nginx --with-cc-opt='-O2 -DAPISIX_BASE_VER=1.21.4.1.0 -DNGX_LUA_ABORT_AT_PANIC -I/usr/local/openresty/zlib/include -I/usr/local/openresty/pcre/include -I/usr/local/openresty/openssl111/include' --add-module=../ngx_devel_kit-0.3.1 --add-module=../echo-nginx-module-0.62 --add-module=../xss-nginx-module-0.06 --add-module=../ngx_coolkit-0.2 --add-module=../set-misc-nginx-module-0.33 --add-module=../form-input-nginx-module-0.12 --add-module=../encrypted-session-nginx-module-0.09 --add-module=../srcache-nginx-module-0.32 --add-module=../ngx_lua-0.10.21 --add-module=../ngx_lua_upstream-0.07 --add-module=../headers-more-nginx-module-0.33 --add-module=../array-var-nginx-module-0.05 --add-module=../memc-nginx-module-0.19 --add-module=../redis2-nginx-module-0.15 --add-module=../redis-nginx-module-0.3.9 --add-module=../ngx_stream_lua-0.0.11 --with-ld-opt='-Wl,-rpath,/usr/local/openresty/luajit/lib -Wl,-rpath,/usr/local/openresty/wasmtime-c-api/lib -L/usr/local/openresty/zlib/lib -L/usr/local/openresty/pcre/lib -L/usr/local/openresty/openssl111/lib -Wl,-rpath,/usr/local/openresty/zlib/lib:/usr/local/openresty/pcre/lib:/usr/local/openresty/openssl111/lib' --add-module=/tmp/tmp.jxGTHHB5bC/openresty-1.21.4.1/../mod_dubbo-1.0.2 --add-module=/tmp/tmp.jxGTHHB5bC/openresty-1.21.4.1/../ngx_multi_upstream_module-1.1.0 --add-module=/tmp/tmp.jxGTHHB5bC/openresty-1.21.4.1/../apisix-nginx-module-1.9.0 --add-module=/tmp/tmp.jxGTHHB5bC/openresty-1.21.4.1/../apisix-nginx-module-1.9.0/src/stream --add-module=/tmp/tmp.jxGTHHB5bC/openresty-1.21.4.1/../apisix-nginx-module-1.9.0/src/meta --add-module=/tmp/tmp.jxGTHHB5bC/openresty-1.21.4.1/../wasm-nginx-module-0.6.1 --add-module=/tmp/tmp.jxGTHHB5bC/openresty-1.21.4.1/../lua-var-nginx-module-v0.5.2 --with-poll_module --with-pcre-jit --with-stream --with-stream_ssl_module --with-stream_ssl_preread_module --with-http_v2_module --without-mail_pop3_module --without-mail_imap_module --without-mail_smtp_module --with-http_stub_status_module --with-http_realip_module --with-http_addition_module --with-http_auth_request_module --with-http_secure_link_module --with-http_random_index_module --with-http_gzip_static_module --with-http_sub_module --with-http_dav_module --with-http_flv_module --with-http_mp4_module --with-http_gunzip_module --with-threads --with-compat --with-stream --with-http_ssl_module

etcd version: etcdctl version: 3.4.16 API version: 3.4

[tokers]

Cannot capture the keywords from your error.log. Please provide more elaborated information.

[dimon-v]

I curled twice curl -I 'https://api-phx-tp-tc.xxx.com.cn/tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=117' curl -I 'https://api-phx-tp-tc.xxx.com.cn/tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=118'

The upstream node of my route is 10.100.2.169, but it is found through packet capture that a request is connected to 10.120.0.10

[tzssangglass]

1. you can check what 10.120.0.10 is;
2. if you put host instead of ip in the nodes, then 10.120.0.10 is the result of DNS resolution.

[dimon-v]

10.120.0.10 is the route of "di-svcmaker" upstream node, the upstream node of "tp-tc" route is 10.100.2.169,

[tzssangglass]

10.120.0.10 is the route of "di-svcmaker" upstream node, the upstream node of "tp-tc" route is 10.100.2.169,

Except for tcpdump, did you also find out via curl -> APISIX -> upstream that the request was being proxied by APISIX to 10.120.0.10?

[monkeyDluffy6017]

I checked your log, the matched router and the upstream node are all correct，and there is 301 redirect in your screenshot. And connected to 10.120.0.10 is after 10.100.2.169, could you check your configuration?

[dimon-v]

@monkeyDluffy6017 tks, In the screenshot: 1、curl -I 'https://api-phx-tp-tc.xxx.com.cn/tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=117'

Upstream and tcpdump are correct,

2、curl -I 'https://api-phx-tp-tc.xxx.com.cn/tlive/backend/liveroom/page?mobile=&roomStatus=&roomName=&current=1&direction=desc&limit=10&orderby=&sourceType=0&orgType=118'

The log shows that upstream 10.100.2.169, but tcpdump requests 10.120.0.10

@tzssangglass tks，由于昨天磁盘空间不足，清空了apisix的日志。现有的日志不能跟issue截图的请求相对应，但是10.120.0.10这个nginx上有 api-phx-tp-tc.xxx.com.cn这个域名的日志，并且是301. 日志是apisix请求的。正常情况api-phx-tp-tc.xxx.com.cn是不会请求10.120.0.10

Due to insufficient disk space yesterday, the apisix log was cleared. The existing log cannot correspond to the request of the issue screenshot. However, there is a log of api-phx-tp-tc.xxx.com.cn on nginx at 10.120.0.10, and the log is 301. The log is requested by apisix. Normally, api-phx-tp-tc.xxx.com.cn does not request 10.120.0.10

[monkeyDluffy6017]

We could not find the problem from you log, and we don't know how you capture the tcpdump packets, could you provide full details of the reproduction steps, about route's config, the consumer's config, and how to send a request to test?

[dimon-v]

My other online apisix cluster, the same version of apisix, has the same problem again; Please show me how to check. Thank you very much

[tokers]

@dimon-v Could you check out the changelog of APISIX 2.15: https://github.com/apache/apisix/blob/master/CHANGELOG.md#2150?

There was a fix:

Upstream keepalive should consider TLS param: - https://github.com/apache/apisix/pull/7054 - https://github.com/apache/apisix/pull/7466

Maybe it's related to your issue.

[dimon-v]

Thank you very much, this is not accidental; If testing, how to reproduce this problem

[tokers]

If it's not accidental. Please give a minimum case so that we can reproduce it.

[hardme]

我也有同样的问题

[tzssangglass]

Thank you very much, this is not accidental; If testing, how to reproduce this problem

try to reproduce with: https://github.com/apache/apisix/issues/7053#issue-1236241279

[shreemaan-abhishek]

@hardme @dimon-v any updates?

[github-actions[bot]]

Due to lack of the reporter's response this issue has been labeled with "no response". It will be close in 3 days if no further activity occurs. If this issue is still relevant, please simply write any comment. Even if closed, you can still revive the issue at any time or discuss it on the [email protected] list. Thank you for your contributions.

[github-actions[bot]]

This issue has been closed due to lack of activity. If you think that is incorrect, or the issue requires additional review, you can revive the issue at any time.