Opened 3 years ago

Closed 3 years ago

#2117 closed defect (fixed)

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

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

Attachments (1)

1196.pcap​ (3.7 KB ) - added by halfcrazy@… 3 years ago.
tcpdump

Download all attachments as: .zip

Change History (5)

by halfcrazy@…, 3 years ago

Attachment: 1196.pcap​ added

tcpdump

comment:1 by halfcrazy@…, 3 years ago

Description: modified (diff)

comment:2 by Maxim Dounin, 3 years ago

Status: new → accepted

Thank you for the report.

Indeed, this is a bug in handling of incorrect responses with expected no (or zero length) response body, yet some body bytes returned along with the response headers. The following patch should fix the "zero size buf" alerts observed.

# HG changeset patch
# User Maxim Dounin <mdounin@mdounin.ru>
# Date 1609987866 -10800
#      Thu Jan 07 05:51:06 2021 +0300
# Node ID 9538fc7410b398d82124d89b9ed3e77b7afa74e9
# Parent  82228f955153527fba12211f52bf102c90f38dfb
Upstream: fixed zero size buf alerts on extra data (ticket #2117).

After 7675:9afa45068b8f and 7678:bffcc5af1d72 (1.19.1), during non-buffered
simple proxying responses with extra data might result in zero size buffers
being generated and "zero size buf" alerts in writer.  This bug is similar
to the one with FastCGI proxying fixed in 7689:da8d758aabeb.

In non-buffered mode, normally the filter function is not called if
u->length is already 0, since u->length is checked after each call of
the filter function.  There is a case when this can happen though: if
the response length is 0, and there are pre-read response body data left
after reading response headers.  As such, a check for u->length is needed
at the start of non-buffered filter functions, similar to the one
for p->length present in buffered filter functions.

Appropriate checks added to the existing non-buffered copy filters
in the upstream (used by scgi and uwsgi proxying) and proxy modules.

diff --git a/src/http/modules/ngx_http_proxy_module.c b/src/http/modules/ngx_http_proxy_module.c
--- a/src/http/modules/ngx_http_proxy_module.c
+++ b/src/http/modules/ngx_http_proxy_module.c
@@ -2334,6 +2334,13 @@ ngx_http_proxy_non_buffered_copy_filter(
 
     u = r->upstream;
 
+    if (u->length == 0) {
+        ngx_log_error(NGX_LOG_WARN, r->connection->log, 0,
+                      "upstream sent more data than specified in "
+                      "\"Content-Length\" header");
+        return NGX_OK;
+    }
+
     for (cl = u->out_bufs, ll = &u->out_bufs; cl; cl = cl->next) {
         ll = &cl->next;
     }
diff --git a/src/http/ngx_http_upstream.c b/src/http/ngx_http_upstream.c
--- a/src/http/ngx_http_upstream.c
+++ b/src/http/ngx_http_upstream.c
@@ -3721,6 +3721,13 @@ ngx_http_upstream_non_buffered_filter(vo
 
     u = r->upstream;
 
+    if (u->length == 0) {
+        ngx_log_error(NGX_LOG_WARN, r->connection->log, 0,
+                      "upstream sent more data than specified in "
+                      "\"Content-Length\" header");
+        return NGX_OK;
+    }
+
     for (cl = u->out_bufs, ll = &u->out_bufs; cl; cl = cl->next) {
         ll = &cl->next;
     }

comment:3 by Maxim Dounin <mdounin@…>, 3 years ago

In 7760:83c4622053b0/nginx:

Upstream: fixed zero size buf alerts on extra data (ticket #2117).

After 7675:9afa45068b8f and 7678:bffcc5af1d72 (1.19.1), during non-buffered
simple proxying, responses with extra data might result in zero size buffers
being generated and "zero size buf" alerts in writer. This bug is similar
to the one with FastCGI proxying fixed in 7689:da8d758aabeb.

In non-buffered mode, normally the filter function is not called if
u->length is already 0, since u->length is checked after each call of
the filter function. There is a case when this can happen though: if
the response length is 0, and there are pre-read response body data left
after reading response headers. As such, a check for u->length is needed
at the start of non-buffered filter functions, similar to the one
for p->length present in buffered filter functions.

Appropriate checks added to the existing non-buffered copy filters
in the upstream (used by scgi and uwsgi proxying) and proxy modules.

comment:4 by Maxim Dounin, 3 years ago

Resolution: → fixed
Status: accepted → closed

Fix committed, thanks for reporting this.

Note: See TracTickets for help on using tickets.