Occasional "400 Bad Request" Responses from Nginx

[Maxim Dounin]

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.. at .@.`............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..... at .@.`............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.. at .@.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.. at .@.`............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.. at .@.]............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/