why nginx output status 200 in access.log when client get unexpected data length

[manmanjyb@…]

in a special envirment, the net quality between client and nginx is so bad,so it's easy to cause send_timeout,then nginx active close the tcp chain,then, client report error,it said recived less data length than expected. when this happened,i find two abnornal thing:
1) access log status 200
2) the parameter event_list is null is epoll_wait call

some thing abort reproduce（it it easy to do: such as set send_timeout 1ms,at here send_timeout is 500ms)
============nginx debug log==========================
2022/03/20 17:41:04 [debug] 5379#0: timer delta: 0
2022/03/20 17:41:04 [debug] 5379#0: worker cycle
2022/03/20 17:41:04 [debug] 5379#0: epoll timer: 500
2022/03/20 17:41:05 [debug] 5379#0: timer delta: 503
2022/03/20 17:41:05 [debug] 5379#0: *204227 event timer del: 3: 1617949126
2022/03/20 17:41:05 [debug] 5379#0: *204227 http run request: "/android/repository/maven-public/com/*/duapp/modules/du_product/4.90.0-SNAPSHOT/du_product-4.90.0-20220317.134753-11.aar?"
2022/03/20 17:41:05 [debug] 5379#0: *204227 http writer handler: "/android/repository/maven-public/com/*/duapp/modules/du_product/4.90.0-SNAPSHOT/du_product-4.90.0-20220317.134753-11.aar?"
2022/03/20 17:41:05 [info] 5379#0: *204227 client timed out (110: Connection timed out) while sending to client, client: 10.176.51.248, server: .com, request: "GET /android/repository/maven-public/com/*/duapp/modules/du_product/4.90.0-SNAPSHOT/du_product-4.90.0-20220317.134753-11.aar HTTP/1.1", upstream: "​http://127.0.0.1:8888/android/repository/maven-public/com/***/duapp/modules/du_product/4.90.0-SNAPSHOT/du_product-4.90.0-20220317.134753-11.aar", host: ".com"
2022/03/20 17:41:05 [debug] 5379#0: *204227 http finalize request: 408, "/android/repository/maven-public/com/*/duapp/modules/du_product/4.90.0-SNAPSHOT/du_product-4.90.0-20220317.134753-11.aar?" a:1, c:1

=========================strace========================
6186 19:33:10.563672 epoll_wait(74, [{EPOLLIN|EPOLLOUT, {u32=577594800, u64=140205490005424}}], 512, 899991) = 1 <0.000018>
6186 19:33:10.563718 readv(5, [{"s\252s\2528\17\216\356\226OQ\300\23Ygyb\5d\17\264\236 \226\313/\346c\351\272\212\372"..., 45153865}, {"", 1048576}], 2) = 189792 <0.000127>
6186 19:33:10.563881 writev(4, [{"P\272\33\367\220uzP;z\247\351\325Z~\3364\306\217\323\370M\5;\326\352\336*U\32\233\232"..., 7464727}], 1) = 6589380 <0.001301>
6186 19:33:10.565215 writev(4, [{"\1\2\324\340 \31<\263\346{\366:I\305@\321\263\247Rr\263\17k\247:\220\224&\366\211'|"..., 875347}], 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000016>
6186 19:33:10.565272 epoll_wait(74, [], 512, 500) = 0 <0.500306>
6186 19:33:11.065658 write(3, "2022/03/20 19:33:11 [info] 6186#"..., 540) = 540 <0.000033>
6186 19:33:11.065760 write(13, "2022-03-20T19:33:11+08:00 | 200 "..., 308) = 308 <0.000033>
6186 19:33:11.065823 munmap(0x7f841e8d5000, 52432896) = 0 <0.000688>
6186 19:33:11.066541 close(4) = 0 <0.000026>
6186 19:33:11.066593 epoll_wait(74, [{EPOLLIN, {u32=577593360, u64=140205490003984}}], 512, 59498) = 1 <0.720498>
6185 19:33:11.787134 <... epoll_wait resumed> [{EPOLLIN, {u32=577593360, u64=140205490003984}}], 512, -1) = 1 <1.233548>
6184 19:33:11.787165 <... epoll_wait resumed> [{EPOLLIN, {u32=577593360, u64=140205490003984}}], 512, -1) = 1 <1.233567>

==================access.log====================================
2022-03-20T19:33:11+08:00 | 200 | 0.512 | 10.176.51.248 | 7638200 | *.com | http | GET | /modules/du_product/4.90.0-SNAPSHOT/du_product-4.90.0-20220317.134753-11.aar | - | - | 127.0.0.1:8888 | 0.010 | 200 | - | Wget/1.21.2 | -
2022-03-20T19:33:14+08:00 | 206 | 0.007 | 10.176.51.248 | 876088 | *.com | http | GET | /modules/du_product/4.90.0-SNAPSHOT/du_product-4.90.0-20220317.134753-11.aar | - | - | 127.0.0.1:8888 | 0.007 | 206 | - | Wget/1.21.2 | -

[manmanjyb@…]

sorry, the nginx debug log timestampe is different from the strace log,

but it is also the true,i can reproduce all log

[manmanjyb@…]

append nginx debug log
before epoll_wait null ,there writev happed error because socket buffer is full

70699 2022/03/20 17:41:04 [debug] 5379#0: *204227 http write filter: l:0 f:0 s:7464727

70700 2022/03/20 17:41:04 [debug] 5379#0: *204227 http write filter limit 0
70701 2022/03/20 17:41:04 [debug] 5379#0: *204227 writev: 6589380 of 7464727
70702 2022/03/20 17:41:04 [debug] 5379#0: *204227 writev: -1 of 875347
70703 2022/03/20 17:41:04 [debug] 5379#0: *204227 writev() not ready (11: Resource temporarily unavailable)
70704 2022/03/20 17:41:04 [debug] 5379#0: *204227 http write filter 0000560A3C4601D8
70705 2022/03/20 17:41:04 [debug] 5379#0: *204227 http copy filter: -2 "/android/repository/maven-public/com/shizhuang/duapp/modu les/du_product/4.90.0-SNAPSHOT/du_product-4.90.0-20220317.134753-11.aar?"
70706 2022/03/20 17:41:04 [debug] 5379#0: *204227 pipe write downstream done
70707 2022/03/20 17:41:04 [debug] 5379#0: *204227 event timer: 5, old: 1618848617, new: 1618848626
70708 2022/03/20 17:41:04 [debug] 5379#0: *204227 event timer add: 3: 500:1617949126

[Maxim Dounin]

i find two abnornal thing:
1) access log status 200

That's expected: the status code is the one sent in the response headers, and it is 200 as long as 200 was sent to the client. If you want to check if the full response was sent to the client, consider checking the response length and/or the ​$request_completion variable.

Note well that it is generally isn't known to nginx if the response was fully received by the client or not. The only information nginx has is if the whole response was written to the socket buffer.

2) the parameter event_list is null is epoll_wait call

It's not NULL, you are probably misread the strace output. Rather, an empty list of events is returned by epoll_wait(), and that's what expected to happen when the epoll_wait() returns due to a timeout.

If you have further questions about nginx, consider using ​support options available.

[boost2020@…]

The only information nginx has is if the whole response was written to the socket buffer.

yes,on my case, the whole response was not complete writeten to buffer

70701 2022/03/20 17:41:04 [debug] 5379#0: *204227 writev: 6589380 of 7464727
70702 2022/03/20 17:41:04 [debug] 5379#0: *204227 writev: -1 of 875347
70703 2022/03/20 17:41:04 [debug] 5379#0: *204227 writev() not ready (11: Resource temporarily unavailable)

875347 byte stilled not writeen to buffer ,(tcpdump'data can also prove this )

so,it is not should writen 200 to access?

[boost2020@…]

and in error log,it output 408 code:

2022/03/20 17:41:05 [debug] 5379#0: *204227 http finalize request: 408, "/android/repository/maven-public/com/*/duapp/modules/du_product/4.90.0-SNAPSHOT/du_product-4.90.0-20220317.134753-11.aar?" a:1, c:1

so,it is should 408 in access?

[Maxim Dounin]

yes,on my case, the whole response was not complete writeten to buffer

Exactly. And due to this the $request_completion variable will be able to indicate that the response wasn't completely sent to the client.

so,it is should 408 in access?

No, it shouldn't. As already explained above, the status code is the one sent to the client in the response headers, and it is 200 as long as 200 was sent to the client.