Opened 3 years ago

Last modified 3 years ago

#2117 closed defect

upstream sent more data than specified in "Content-Length" header while reading response header from upstream — at Version 1

Reported by: halfcrazy@… Owned by:
Priority: minor Milestone:
Component: nginx-core Version: 1.19.x
Keywords: Cc:
uname -a: 3.10.0-1127.el7.x86_64
nginx -V: nginx version: openresty/1.19.3.1 (ALB)
built by gcc 9.3.0 (Alpine 9.3.0)
built with OpenSSL 1.1.1f 31 Mar 2020
TLS SNI support enabled
configure arguments: --prefix=/usr/local/openresty/nginx --with-cc-opt='-O2 -DNGX_LUA_ABORT_AT_PANIC -I/usr/local/openresty/pcre/include -I/usr/local/openresty/openssl/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.32 --add-module=../form-input-nginx-module-0.12 --add-module=../encrypted-session-nginx-module-0.08 --add-module=../srcache-nginx-module-0.32 --add-module=../ngx_lua-0.10.19 --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.7 --add-module=../rds-json-nginx-module-0.15 --add-module=../rds-csv-nginx-module-0.09 --add-module=../ngx_stream_lua-0.0.9 --with-ld-opt='-Wl,-rpath,/usr/local/openresty/luajit/lib -L/usr/local/openresty/pcre/lib -L/usr/local/openresty/openssl/lib -Wl,-rpath,/usr/local/openresty/pcre/lib:/usr/local/openresty/openssl/lib' --with-pcre --with-compat --with-file-aio --with-http_addition_module --with-http_auth_request_module --with-http_dav_module --with-http_flv_module --with-http_geoip_module=dynamic --with-http_gunzip_module --with-http_gzip_static_module --with-http_image_filter_module=dynamic --with-http_random_index_module --with-http_realip_module --with-http_secure_link_module --with-http_slice_module --with-http_ssl_module --with-http_stub_status_module --with-http_sub_module --with-http_v2_module --with-http_xslt_module=dynamic --with-ipv6 --with-mail --with-mail_ssl_module --with-md5-asm --with-pcre-jit --with-sha1-asm --with-stream --with-stream_ssl_module --with-threads --build=ALB --add-module=/tmp/lua-var-nginx-module-0.6 --with-stream --with-stream_ssl_preread_module

Description (last modified by halfcrazy@…)

I have an invalid upstream that repsonse 204 with extra data. It works before nginx 1.19.1. After upgrading to 1.19.3 it doesn't work anymore with nginx setting proxy_buffering off.
I tried nginx 1.9.0, 1.9.1, 1.9.3, 1.9.6, openresty 1.19.3 and found this behavior changed since nginx 1.9.1

Maybe related to https://trac.nginx.org/nginx/ticket/2018 and https://trac.nginx.org/nginx/changeset/bffcc5af1d7281c8e5fc93a28bb6f9d77a99f7fe/nginx

Here is the debug log.

2020/12/29 07:40:25 [debug] 1#1: bind() 0.0.0.0:80 #6
2020/12/29 07:40:25 [notice] 1#1: using the "epoll" event method
2020/12/29 07:40:25 [debug] 1#1: counter: 00007FB48E820080, 1
2020/12/29 07:40:25 [notice] 1#1: openresty/1.19.3.1
2020/12/29 07:40:25 [notice] 1#1: built by gcc 9.3.0 (Alpine 9.3.0)
2020/12/29 07:40:25 [notice] 1#1: OS: Linux 3.10.0-1127.el7.x86_64
2020/12/29 07:40:25 [notice] 1#1: getrlimit(RLIMIT_NOFILE): 1048576:1048576
2020/12/29 07:40:25 [debug] 1#1: write: 7, 00007FFD75B129D0, 2, 0
2020/12/29 07:40:25 [debug] 1#1: setproctitle: "nginx: master process /usr/local/openresty/bin/openresty -g daemon off;"
2020/12/29 07:40:25 [notice] 1#1: start worker processes
2020/12/29 07:40:25 [debug] 1#1: channel 3:7
2020/12/29 07:40:25 [notice] 1#1: start worker process 6
2020/12/29 07:40:25 [debug] 1#1: sigsuspend
2020/12/29 07:40:25 [debug] 6#6: add cleanup: 00005636C0D19FA8
2020/12/29 07:40:25 [debug] 6#6: malloc: 00005636C0D19880:8
2020/12/29 07:40:25 [debug] 6#6: notify eventfd: 9
2020/12/29 07:40:25 [debug] 6#6: eventfd: 10
2020/12/29 07:40:25 [debug] 6#6: testing the EPOLLRDHUP flag: success
2020/12/29 07:40:25 [debug] 6#6: malloc: 00005636C0CE59E0:6144
2020/12/29 07:40:25 [debug] 6#6: malloc: 00007FB48D707020:11878400
2020/12/29 07:40:25 [debug] 6#6: malloc: 00007FB48D256020:4915200
2020/12/29 07:40:25 [debug] 6#6: malloc: 00007FB48CDA5020:4915200
2020/12/29 07:40:25 [debug] 6#6: epoll add event: fd:6 op:1 ev:00002001
2020/12/29 07:40:25 [debug] 6#6: epoll add event: fd:11 op:1 ev:80002001
2020/12/29 07:40:25 [debug] 6#6: setting SA_RESTART for signal 1
2020/12/29 07:40:25 [debug] 6#6: setting SA_RESTART for signal 10
2020/12/29 07:40:25 [debug] 6#6: setting SA_RESTART for signal 28
2020/12/29 07:40:25 [debug] 6#6: setting SA_RESTART for signal 15
2020/12/29 07:40:25 [debug] 6#6: setting SA_RESTART for signal 3
2020/12/29 07:40:25 [debug] 6#6: setting SA_RESTART for signal 12
2020/12/29 07:40:25 [debug] 6#6: setting SA_RESTART for signal 14
2020/12/29 07:40:25 [debug] 6#6: setting SA_RESTART for signal 2
2020/12/29 07:40:25 [debug] 6#6: setting SA_RESTART for signal 29
2020/12/29 07:40:25 [debug] 6#6: setting SA_RESTART for signal 17
2020/12/29 07:40:25 [debug] 6#6: setting SA_RESTART for signal 31
2020/12/29 07:40:25 [debug] 6#6: setting SA_RESTART for signal 13
2020/12/29 07:40:25 [debug] 6#6: epoll add event: fd:7 op:1 ev:00002001
2020/12/29 07:40:25 [debug] 6#6: setproctitle: "nginx: worker process"
2020/12/29 07:40:25 [debug] 6#6: worker cycle
2020/12/29 07:40:25 [debug] 6#6: epoll timer: -1
2020/12/29 07:41:38 [debug] 6#6: epoll: fd:6 ev:0001 d:00007FB48D707020
2020/12/29 07:41:38 [debug] 6#6: accept on 0.0.0.0:80, ready: 1
2020/12/29 07:41:38 [debug] 6#6: posix_memalign: 00005636C0D14940:512 @16
2020/12/29 07:41:38 [debug] 6#6: *1 accept: 100.64.0.5:62245 fd:3
2020/12/29 07:41:38 [debug] 6#6: *1 event timer add: 3: 60000:618118840
2020/12/29 07:41:38 [debug] 6#6: *1 reusable connection: 1
2020/12/29 07:41:38 [debug] 6#6: *1 epoll add event: fd:3 op:1 ev:80002001
2020/12/29 07:41:38 [debug] 6#6: accept() not ready (11: Resource temporarily unavailable)
2020/12/29 07:41:38 [debug] 6#6: timer delta: 73205
2020/12/29 07:41:38 [debug] 6#6: worker cycle
2020/12/29 07:41:38 [debug] 6#6: epoll timer: 60000
2020/12/29 07:41:38 [debug] 6#6: epoll: fd:3 ev:0001 d:00007FB48D7072D8
2020/12/29 07:41:38 [debug] 6#6: *1 http wait request handler
2020/12/29 07:41:38 [debug] 6#6: *1 malloc: 00005636C0CD81A0:1024
2020/12/29 07:41:38 [debug] 6#6: *1 recv: eof:0, avail:-1
2020/12/29 07:41:38 [debug] 6#6: *1 recv: fd:3 847 of 1024
2020/12/29 07:41:38 [debug] 6#6: *1 reusable connection: 0
2020/12/29 07:41:38 [debug] 6#6: *1 posix_memalign: 00005636C0CE7200:4096 @16
2020/12/29 07:41:38 [debug] 6#6: *1 http process request line
2020/12/29 07:41:38 [debug] 6#6: *1 http request line: "POST /service/rapture/session HTTP/1.1"
2020/12/29 07:41:38 [debug] 6#6: *1 http uri: "/service/rapture/session"
2020/12/29 07:41:38 [debug] 6#6: *1 http args: ""
2020/12/29 07:41:38 [debug] 6#6: *1 http exten: ""
2020/12/29 07:41:38 [debug] 6#6: *1 posix_memalign: 00005636C0CDC980:4096 @16
2020/12/29 07:41:38 [debug] 6#6: *1 http process request header line
2020/12/29 07:41:38 [debug] 6#6: *1 http header: "Host: testnexus.alauda.cn"
2020/12/29 07:41:38 [debug] 6#6: *1 http header: "Accept-Encoding: deflate, gzip"
2020/12/29 07:41:38 [debug] 6#6: *1 http header: "Proxy-Connection: keep-alive"
2020/12/29 07:41:38 [debug] 6#6: *1 http header: "Pragma: no-cache"
2020/12/29 07:41:38 [debug] 6#6: *1 http header: "Cache-Control: no-cache"
2020/12/29 07:41:38 [debug] 6#6: *1 http header: "Proxy-Authorization: Basic YWxhdWRhOlRucml3MnoyNjdnZWl2bjVhTHZr"
2020/12/29 07:41:38 [debug] 6#6: *1 http header: "X-Requested-With: XMLHttpRequest"
2020/12/29 07:41:38 [debug] 6#6: *1 http header: "X-Nexus-UI: true"
2020/12/29 07:41:38 [debug] 6#6: *1 http header: "User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 11_1_0) AppleWebKit/537.36 (KHTML, likeGecko) Chrome/87.0.4280.88 Safari/537.36"
2020/12/29 07:41:38 [debug] 6#6: *1 http header: "NX-ANTI-CSRF-TOKEN: 0.8256987409765759"
2020/12/29 07:41:38 [debug] 6#6: *1 http header: "Content-Type: application/x-www-form-urlencoded; charset=UTF-8"
2020/12/29 07:41:38 [debug] 6#6: *1 http header: "Accept: */*"
2020/12/29 07:41:38 [debug] 6#6: *1 http header: "Accept-Language: zh-CN,zh;q=0.9,en-US;q=0.8,en;q=0.7"
2020/12/29 07:41:38 [debug] 6#6: *1 http header: "Cookie: isin=0; _ga=GA1.2.1412079812.1520343504; Hm_lvt_6940f47dc62d2ccc6321eb04ddd20373=1607322387; Hm_lpvt_6940f47dc62d2ccc6321eb04ddd20373=1607322387; NX-ANTI-CSRF-TOKEN=0.8256987409765759"
2020/12/29 07:41:38 [debug] 6#6: *1 http header: "Content-Length: 39"
2020/12/29 07:41:38 [debug] 6#6: *1 http header done
2020/12/29 07:41:38 [debug] 6#6: *1 event timer del: 3: 618118840
2020/12/29 07:41:38 [debug] 6#6: *1 generic phase: 0
2020/12/29 07:41:38 [debug] 6#6: *1 rewrite phase: 1
2020/12/29 07:41:38 [debug] 6#6: *1 rewrite phase: 2
2020/12/29 07:41:38 [debug] 6#6: *1 test location: "/"
2020/12/29 07:41:38 [debug] 6#6: *1 using configuration "/"
2020/12/29 07:41:38 [debug] 6#6: *1 http cl:39 max:1048576
2020/12/29 07:41:38 [debug] 6#6: *1 rewrite phase: 4
2020/12/29 07:41:38 [debug] 6#6: *1 rewrite phase: 5
2020/12/29 07:41:38 [debug] 6#6: *1 post rewrite phase: 6
2020/12/29 07:41:38 [debug] 6#6: *1 generic phase: 7
2020/12/29 07:41:38 [debug] 6#6: *1 generic phase: 8
2020/12/29 07:41:38 [debug] 6#6: *1 generic phase: 9
2020/12/29 07:41:38 [debug] 6#6: *1 access phase: 10
2020/12/29 07:41:38 [debug] 6#6: *1 access phase: 11
2020/12/29 07:41:38 [debug] 6#6: *1 access phase: 12
2020/12/29 07:41:38 [debug] 6#6: *1 post access phase: 13
2020/12/29 07:41:38 [debug] 6#6: *1 generic phase: 14
2020/12/29 07:41:38 [debug] 6#6: *1 generic phase: 15
2020/12/29 07:41:38 [debug] 6#6: *1 http client request body preread 39
2020/12/29 07:41:38 [debug] 6#6: *1 http request body content length filter
2020/12/29 07:41:38 [debug] 6#6: *1 http body new buf t:1 f:0 00005636C0CD84C8, pos 00005636C0CD84C8, size: 39 file: 0, size: 0
2020/12/29 07:41:38 [debug] 6#6: *1 http init upstream, client timer: 0
2020/12/29 07:41:38 [debug] 6#6: *1 epoll add event: fd:3 op:3 ev:80002005
2020/12/29 07:41:38 [debug] 6#6: *1 http script copy: "Host"
2020/12/29 07:41:38 [debug] 6#6: *1 http script var: "testnexus.alauda.cn"
2020/12/29 07:41:38 [debug] 6#6: *1 http script copy: "Connection"
2020/12/29 07:41:38 [debug] 6#6: *1 http script copy: "close"
2020/12/29 07:41:38 [debug] 6#6: *1 http script copy: "Content-Length"
2020/12/29 07:41:38 [debug] 6#6: *1 http script var: "39"
2020/12/29 07:41:38 [debug] 6#6: *1 http script copy: ""
2020/12/29 07:41:38 [debug] 6#6: *1 http proxy header: "Accept-Encoding: deflate, gzip"
2020/12/29 07:41:38 [debug] 6#6: *1 http proxy header: "Proxy-Connection: keep-alive"
2020/12/29 07:41:38 [debug] 6#6: *1 http proxy header: "Pragma: no-cache"
2020/12/29 07:41:38 [debug] 6#6: *1 http proxy header: "Cache-Control: no-cache"
2020/12/29 07:41:38 [debug] 6#6: *1 http proxy header: "Proxy-Authorization: Basic YWxhdWRhOlRucml3MnoyNjdnZWl2bjVhTHZr"
2020/12/29 07:41:38 [debug] 6#6: *1 http proxy header: "X-Requested-With: XMLHttpRequest"
2020/12/29 07:41:38 [debug] 6#6: *1 http proxy header: "X-Nexus-UI: true"
2020/12/29 07:41:38 [debug] 6#6: *1 http proxy header: "User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 11_1_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36"
2020/12/29 07:41:38 [debug] 6#6: *1 http proxy header: "NX-ANTI-CSRF-TOKEN: 0.8256987409765759"
2020/12/29 07:41:38 [debug] 6#6: *1 http proxy header: "Content-Type: application/x-www-form-urlencoded; charset=UTF-8"
2020/12/29 07:41:38 [debug] 6#6: *1 http proxy header: "Accept: */*"
2020/12/29 07:41:38 [debug] 6#6: *1 http proxy header: "Accept-Language: zh-CN,zh;q=0.9,en-US;q=0.8,en;q=0.7"
2020/12/29 07:41:38 [debug] 6#6: *1 http proxy header: "Cookie: isin=0; _ga=GA1.2.1412079812.1520343504; Hm_lvt_6940f47dc62d2ccc6321eb04ddd20373=1607322387; Hm_lpvt_6940f47dc62d2ccc6321eb04ddd20373=1607322387; NX-ANTI-CSRF-TOKEN=0.8256987409765759"
2020/12/29 07:41:38 [debug] 6#6: *1 http proxy header:
"POST /service/rapture/session HTTP/1.1
Host: testnexus.alauda.cn
Connection: close
Content-Length: 39
Accept-Encoding: deflate, gzip
Proxy-Connection: keep-alive
Pragma: no-cache
Cache-Control: no-cache
Proxy-Authorization: Basic YWxhdWRhOlRucml3MnoyNjdnZWl2bjVhTHZr
X-Requested-With: XMLHttpRequest
X-Nexus-UI: true
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 11_1_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36
NX-ANTI-CSRF-TOKEN: 0.8256987409765759
Content-Type: application/x-www-form-urlencoded; charset=UTF-8
Accept: */*
Accept-Language: zh-CN,zh;q=0.9,en-US;q=0.8,en;q=0.7
Cookie: isin=0; _ga=GA1.2.1412079812.1520343504; Hm_lvt_6940f47dc62d2ccc6321eb04ddd20373=1607322387; Hm_lpvt_6940f47dc62d2ccc6321eb04ddd20373=1607322387; NX-ANTI-CSRF-TOKEN=0.8256987409765759
 
"
2020/12/29 07:41:38 [debug] 6#6: *1 http cleanup add: 00005636C0CDD7C0
2020/12/29 07:41:38 [debug] 6#6: *1 get rr peer, try: 1
2020/12/29 07:41:38 [debug] 6#6: *1 stream socket 12
2020/12/29 07:41:38 [debug] 6#6: *1 epoll add connection: fd:12 ev:80002005
2020/12/29 07:41:38 [debug] 6#6: *1 connect to 10.3.0.202:8080, fd:12 #2
2020/12/29 07:41:38 [debug] 6#6: *1 http upstream connect: -2
2020/12/29 07:41:38 [debug] 6#6: *1 posix_memalign: 00005636C0D14B60:128 @16
2020/12/29 07:41:38 [debug] 6#6: *1 event timer add: 12: 60000:618118840
2020/12/29 07:41:38 [debug] 6#6: *1 http finalize request: -4, "/service/rapture/session?" a:1, c:2
2020/12/29 07:41:38 [debug] 6#6: *1 http request count:2 blk:0
2020/12/29 07:41:38 [debug] 6#6: timer delta: 0
2020/12/29 07:41:38 [debug] 6#6: worker cycle
2020/12/29 07:41:38 [debug] 6#6: epoll timer: 60000
2020/12/29 07:41:38 [debug] 6#6: epoll: fd:3 ev:0004 d:00007FB48D7072D8
2020/12/29 07:41:38 [debug] 6#6: *1 http run request: "/service/rapture/session?"
2020/12/29 07:41:38 [debug] 6#6: *1 http upstream check client, write event:1, "/service/rapture/session"
2020/12/29 07:41:38 [debug] 6#6: timer delta: 2
2020/12/29 07:41:38 [debug] 6#6: worker cycle
2020/12/29 07:41:38 [debug] 6#6: epoll timer: 59998
2020/12/29 07:41:38 [debug] 6#6: epoll: fd:12 ev:0004 d:00007FB48D7073C0
2020/12/29 07:41:38 [debug] 6#6: *1 http upstream request: "/service/rapture/session?"
2020/12/29 07:41:38 [debug] 6#6: *1 http upstream send request handler
2020/12/29 07:41:38 [debug] 6#6: *1 http upstream send request
2020/12/29 07:41:38 [debug] 6#6: *1 http upstream send request body
2020/12/29 07:41:38 [debug] 6#6: *1 chain writer buf fl:0 s:827
2020/12/29 07:41:38 [debug] 6#6: *1 chain writer buf fl:1 s:39
2020/12/29 07:41:38 [debug] 6#6: *1 chain writer in: 00005636C0CDD820
2020/12/29 07:41:38 [debug] 6#6: *1 writev: 866 of 866
2020/12/29 07:41:38 [debug] 6#6: *1 chain writer out: 0000000000000000
2020/12/29 07:41:38 [debug] 6#6: *1 event timer del: 12: 618118840
2020/12/29 07:41:38 [debug] 6#6: *1 event timer add: 12: 60000:618118848
2020/12/29 07:41:38 [debug] 6#6: timer delta: 6
2020/12/29 07:41:38 [debug] 6#6: worker cycle
2020/12/29 07:41:38 [debug] 6#6: epoll timer: 60000
2020/12/29 07:41:38 [debug] 6#6: epoll: fd:12 ev:0005 d:00007FB48D7073C0
2020/12/29 07:41:38 [debug] 6#6: *1 http upstream request: "/service/rapture/session?"
2020/12/29 07:41:38 [debug] 6#6: *1 http upstream process header
2020/12/29 07:41:38 [debug] 6#6: *1 malloc: 00005636C0CDD9A0:4096
2020/12/29 07:41:38 [debug] 6#6: *1 posix_memalign: 00005636C0CDE9C0:4096 @16
2020/12/29 07:41:38 [debug] 6#6: *1 recv: eof:0, avail:-1
2020/12/29 07:41:38 [debug] 6#6: *1 recv: fd:12 260 of 4096
2020/12/29 07:41:38 [debug] 6#6: *1 http proxy status 204 "204 No Content"
2020/12/29 07:41:38 [debug] 6#6: *1 http proxy header: "Date: Tue, 29 Dec 2020 07:41:38 GMT"
2020/12/29 07:41:38 [debug] 6#6: *1 http proxy header: "Server: Nexus/3.17.0-01 (OSS)"
2020/12/29 07:41:38 [debug] 6#6: *1 http proxy header: "X-Content-Type-Options: nosniff"
2020/12/29 07:41:38 [debug] 6#6: *1 http proxy header: "Set-Cookie: NXSESSIONID=39afc9f2-4c8d-4cae-b52e-cb624569d05c; Path=/; HttpOnly"
2020/12/29 07:41:38 [debug] 6#6: *1 http proxy header: "Connection: close"
2020/12/29 07:41:38 [debug] 6#6: *1 http proxy header: "Transfer-Encoding: chunked"
2020/12/29 07:41:38 [debug] 6#6: *1 http proxy header done
2020/12/29 07:41:38 [debug] 6#6: *1 HTTP/1.1 204 No Content
Server: openresty/1.19.3.1
Date: Tue, 29 Dec 2020 07:41:38 GMT
Connection: keep-alive
X-Content-Type-Options: nosniff
Set-Cookie: NXSESSIONID=39afc9f2-4c8d-4cae-b52e-cb624569d05c; Path=/; HttpOnly
 
2020/12/29 07:41:38 [debug] 6#6: *1 write new buf t:1 f:0 00005636C0CDEC38, pos 00005636C0CDEC38, size: 229 file: 0, size: 0
2020/12/29 07:41:38 [debug] 6#6: *1 http write filter: l:0 f:0 s:229
2020/12/29 07:41:38 [debug] 6#6: *1 http proxy filter init s:204 h:0 c:1 l:-1
2020/12/29 07:41:38 [debug] 6#6: *1 tcp_nodelay
2020/12/29 07:41:38 [warn] 6#6: *1 upstream sent more data than specified in "Content-Length" header while reading response header from upstream, client: 100.64.0.5, server: , request: "POST /service/rapture/session HTTP/1.1", upstream: "http://10.3.0.202:8080/service/rapture/session", host: "testnexus.alauda.cn"
2020/12/29 07:41:38 [debug] 6#6: *1 http upstream process non buffered downstream
2020/12/29 07:41:38 [debug] 6#6: *1 http output filter "/service/rapture/session?"
2020/12/29 07:41:38 [debug] 6#6: *1 http copy filter: "/service/rapture/session?"
2020/12/29 07:41:38 [debug] 6#6: *1 http postpone filter "/service/rapture/session?" 00005636C0CDD800
2020/12/29 07:41:38 [debug] 6#6: *1 write old buf t:1 f:0 00005636C0CDEC38, pos 00005636C0CDEC38, size: 229 file: 0, size: 0
2020/12/29 07:41:38 [debug] 6#6: *1 write new buf t:0 f:0 0000000000000000, pos 00005636C0CDDA9F, size: 0 file: 0, size: 0
2020/12/29 07:41:38 [alert] 6#6: *1 zero size buf in writer t:0 r:0 f:0 0000000000000000 00005636C0CDDA9F-00005636C0CDDA9F 0000000000000000 0-0 while sending to client, client: 100.64.0.5, server: , request: "POST /service/rapture/session HTTP/1.1", upstream: "http://10.3.0.202:8080/service/rapture/session", host: "testnexus.alauda.cn"
2020/12/29 07:41:38 [debug] 6#6: *1 http copy filter: -1 "/service/rapture/session?"
2020/12/29 07:41:38 [debug] 6#6: *1 finalize http upstream request: -1
2020/12/29 07:41:38 [debug] 6#6: *1 finalize http proxy request
2020/12/29 07:41:38 [debug] 6#6: *1 free rr peer 1 0
2020/12/29 07:41:38 [debug] 6#6: *1 close http upstream connection: 12
2020/12/29 07:41:38 [debug] 6#6: *1 free: 00005636C0D14B60, unused: 48
2020/12/29 07:41:38 [debug] 6#6: *1 event timer del: 12: 618118848
2020/12/29 07:41:38 [debug] 6#6: *1 reusable connection: 0
2020/12/29 07:41:38 [debug] 6#6: *1 http finalize request: -1, "/service/rapture/session?" a:1, c:1
2020/12/29 07:41:38 [debug] 6#6: *1 http terminate request count:1
2020/12/29 07:41:38 [debug] 6#6: *1 http terminate cleanup count:1 blk:0
2020/12/29 07:41:38 [debug] 6#6: *1 http posted request: "/service/rapture/session?"
2020/12/29 07:41:38 [debug] 6#6: *1 http terminate handler count:1
2020/12/29 07:41:38 [debug] 6#6: *1 http request count:1 blk:0
2020/12/29 07:41:38 [debug] 6#6: *1 http close request
2020/12/29 07:41:38 [debug] 6#6: *1 http log handler
2020/12/29 07:41:38 [debug] 6#6: *1 free: 00005636C0CDD9A0
2020/12/29 07:41:38 [debug] 6#6: *1 free: 00005636C0CE7200, unused: 0
2020/12/29 07:41:38 [debug] 6#6: *1 free: 00005636C0CDC980, unused: 29
2020/12/29 07:41:38 [debug] 6#6: *1 free: 00005636C0CDE9C0, unused: 2763
2020/12/29 07:41:38 [debug] 6#6: *1 close http connection: 3
2020/12/29 07:41:38 [debug] 6#6: *1 reusable connection: 0
2020/12/29 07:41:38 [debug] 6#6: *1 free: 00005636C0CD81A0
2020/12/29 07:41:38 [debug] 6#6: *1 free: 00005636C0D14940, unused: 136
2020/12/29 07:41:38 [debug] 6#6: timer delta: 90
2020/12/29 07:41:38 [debug] 6#6: worker cycle
2020/12/29 07:41:38 [debug] 6#6: epoll timer: -1

Curl upstream directly

/ # curl 'http://10.3.0.202:8080/service/rapture/session' \
>   -H 'Proxy-Connection: keep-alive' \
>   -H 'Pragma: no-cache' \
>   -H 'Cache-Control: no-cache' \
>   -H 'Proxy-Authorization: Basic YWxhdWRhOlRucml3MnoyNjdnZWl2bjVhTHZr' \
>   -H 'X-Requested-With: XMLHttpRequest' \
>   -H 'X-Nexus-UI: true' \
>   -H 'User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 11_1_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36'
\
>   -H 'NX-ANTI-CSRF-TOKEN: 0.8256987409765759' \
>   -H 'Content-Type: application/x-www-form-urlencoded; charset=UTF-8' \
>   -H 'Accept: */*' \
>   -H 'Host: testnexus.alauda.cn' \
>   -H 'Accept-Language: zh-CN,zh;q=0.9,en-US;q=0.8,en;q=0.7' \
>   -H 'Cookie: isin=0; _ga=GA1.2.1412079812.1520343504; Hm_lvt_6940f47dc62d2ccc6321eb04ddd20373=1607322387; Hm_lpvt_6940f47dc62d2ccc6321eb04
ddd20373=1607322387; NX-ANTI-CSRF-TOKEN=0.8256987409765759' \
>   --data-raw 'username=YWRtaW4%3D&password=YWRtaW4%3D' \
>   --compressed \
>   --insecure -v
*   Trying 10.3.0.202:8080...
* TCP_NODELAY set
* Connected to 10.3.0.202 (10.3.0.202) port 8080 (#0)
> POST /service/rapture/session HTTP/1.1
> Host: testnexus.alauda.cn
> Accept-Encoding: deflate, gzip
> Proxy-Connection: keep-alive
> Pragma: no-cache
> Cache-Control: no-cache
> Proxy-Authorization: Basic YWxhdWRhOlRucml3MnoyNjdnZWl2bjVhTHZr
> X-Requested-With: XMLHttpRequest
> X-Nexus-UI: true
> User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 11_1_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36
> NX-ANTI-CSRF-TOKEN: 0.8256987409765759
> Content-Type: application/x-www-form-urlencoded; charset=UTF-8
> Accept: */*
> Accept-Language: zh-CN,zh;q=0.9,en-US;q=0.8,en;q=0.7
> Cookie: isin=0; _ga=GA1.2.1412079812.1520343504; Hm_lvt_6940f47dc62d2ccc6321eb04ddd20373=1607322387; Hm_lpvt_6940f47dc62d2ccc6321eb04ddd20373=1607322387; NX-ANTI-CSRF-TOKEN=0.8256987409765759
> Content-Length: 39
>
* upload completely sent off: 39 out of 39 bytes
* Mark bundle as not supporting multiuse
< HTTP/1.1 204 No Content
< Date: Tue, 29 Dec 2020 12:58:03 GMT
< Server: Nexus/3.17.0-01 (OSS)
< X-Content-Type-Options: nosniff
< Set-Cookie: NXSESSIONID=fe44cd41-18e2-4bdd-8c54-cbaed810d1cb; Path=/; HttpOnly
< Transfer-Encoding: chunked
<
* Excess found: excess = 5 url = /service/rapture/session (zero-length body)
* Connection #0 to host 10.3.0.202 left intact

https://tva1.sinaimg.cn/large/0081Kckwgy1gm5u2y35g4j31pr0u01kx.jpg

Change History (2)

by halfcrazy@…, 3 years ago

Attachment: 1196.pcap​ added

tcpdump

comment:1 by halfcrazy@…, 3 years ago

Description: modified (diff)
Note: See TracTickets for help on using tickets.