Hello! On Sun, Feb 04, 2024 at 06:33:40PM +0900, Hiroaki Nakamura wrote:
> During my experimentation with Nginx's rate limit features, I > encountered an issue where Nginx occasionally sends "400 Bad Request" > responses for requests that appear to be correct. > With further investigation, I discovered that this issue also occurs > even when not utilizing the rate limit features. > > I have provided a reproduction of this issue on GitHub: > https://github.com/hnakamur/ats-nginx-bad-request/tree/enable_debug_log > > Additionally, I have included log files and tcpdump outputs within the > repository for further analysis. > > Your assistance in investigating this matter would be greatly appreciated. Take a look at the tcpdump, notably the previous request before 400 is returned: it is obviously incomplete, there is just 344 bytes of the request body instead of 1024 bytes promised in the headers: https://github.com/hnakamur/ats-nginx-bad-request/blob/7d573464627c834c97fb020997ad4a54777b8181/tcpdump-nginx.port45732.log#L267 12:46:39.140200 ? In IP (tos 0x0, ttl 64, id 32961, offset 0, flags [DF], proto TCP (6), length 373) 172.18.0.3.45732 > 172.18.0.2.80: Flags [P.], cksum 0x5991 (incorrect -> 0x999c), seq 4036:4357, ack 1087, win 501, options [nop,nop,TS val 948481122 ecr 2789766215], length 321: HTTP, length: 321 PUT / HTTP/1.1 Host: nginx User-Agent: hey/0.0.1 Content-Length: 1024 Content-Type: text/html X-Request-Id: 066a1a44a1e961068d479205d489ab85 Accept-Encoding: gzip Client-ip: 172.18.0.4 X-Forwarded-For: 172.18.0.4 Via: http/1.1 traffic_server[8e38d2ba-96f3-40ca-8974-a0df3c1575f3] (ApacheTrafficServer/10.0.0) E..u..@.@.`............P.J..u.$;....Y...... 8..b.HtGPUT / HTTP/1.1 Host: nginx User-Agent: hey/0.0.1 Content-Length: 1024 Content-Type: text/html X-Request-Id: 066a1a44a1e961068d479205d489ab85 Accept-Encoding: gzip Client-ip: 172.18.0.4 X-Forwarded-For: 172.18.0.4 Via: http/1.1 traffic_server[8e38d2ba-96f3-40ca-8974-a0df3c1575f3] (ApacheTrafficServer/10.0.0) 12:46:39.141364 ? In IP (tos 0x0, ttl 64, id 32962, offset 0, flags [DF], proto TCP (6), length 396) 172.18.0.3.45732 > 172.18.0.2.80: Flags [P.], cksum 0x59a8 (incorrect -> 0xce64), seq 4357:4701, ack 1087, win 501, options [nop,nop,TS val 948481123 ecr 2789766304], length 344: HTTP E.....@.@.`............P.J..u.$;....Y...... 8..c.Ht.0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef01234567 And then the request which "appears to be correct" comes: 12:46:39.183005 ? In IP (tos 0x0, ttl 64, id 32963, offset 0, flags [DF], proto TCP (6), length 52) 172.18.0.3.45732 > 172.18.0.2.80: Flags [.], cksum 0x5850 (incorrect -> 0x792f), seq 4701, ack 1449, win 501, options [nop,nop,TS val 948481165 ecr 2789766305], length 0 E..4..@.@.a............P.J.nu.%.....XP..... 8....Ht. 12:46:39.256214 ? In IP (tos 0x0, ttl 64, id 32964, offset 0, flags [DF], proto TCP (6), length 373) 172.18.0.3.45732 > 172.18.0.2.80: Flags [P.], cksum 0x5991 (incorrect -> 0x5c94), seq 4701:5022, ack 1449, win 501, options [nop,nop,TS val 948481238 ecr 2789766305], length 321: HTTP, length: 321 PUT / HTTP/1.1 Host: nginx User-Agent: hey/0.0.1 Content-Length: 1024 Content-Type: text/html X-Request-Id: 371df78553b367dd7b5dc699b920029c Accept-Encoding: gzip Client-ip: 172.18.0.4 X-Forwarded-For: 172.18.0.4 Via: http/1.1 traffic_server[8e38d2ba-96f3-40ca-8974-a0df3c1575f3] (ApacheTrafficServer/10.0.0) E..u..@.@.`............P.J.nu.%.....Y...... 8....Ht.PUT / HTTP/1.1 Host: nginx User-Agent: hey/0.0.1 Content-Length: 1024 Content-Type: text/html X-Request-Id: 371df78553b367dd7b5dc699b920029c Accept-Encoding: gzip Client-ip: 172.18.0.4 X-Forwarded-For: 172.18.0.4 Via: http/1.1 traffic_server[8e38d2ba-96f3-40ca-8974-a0df3c1575f3] (ApacheTrafficServer/10.0.0) 12:46:39.258000 ? In IP (tos 0x0, ttl 64, id 32965, offset 0, flags [DF], proto TCP (6), length 1076) 172.18.0.3.45732 > 172.18.0.2.80: Flags [P.], cksum 0x5c50 (incorrect -> 0xa5cf), seq 5022:6046, ack 1449, win 501, options [nop,nop,TS val 948481240 ecr 2789766305], length 1024: HTTP E..4..@.@.]............P.J..u.%.....\P..... 8....Ht.0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef Since first 680 bytes of this "request" is actually the request body of the previous request, the request line actually starts somewhere in "0123456789abcdef0123..." bytes, and the method is clearly incorrect, as indicated by nginx. Looks like an ATS bug to me. -- Maxim Dounin http://mdounin.ru/ _______________________________________________ nginx mailing list nginx@nginx.org https://mailman.nginx.org/mailman/listinfo/nginx
