blob: ced332b67ce117fe47af694e3d47baacf957fa63 [file] [log] [blame]
Willy Tarreauc89f6652019-09-06 18:50:32 +02001tcp mode 8001->8008
2
3
4Remote test:
5============
6
7willy@up1:~$ echo bar | ncat -lp8008
8willy@wtap:haproxy$ echo foo | ncat 127.1 8001
9
1017:09:53.663154 epoll_wait(3, [{EPOLLIN, {u32=5, u64=5}}], 200, 1000) = 1
1117:09:54.582146 accept4(5, {sa_family=AF_INET, sin_port=htons(33378), sin_addr=inet_addr("127.0.0.1")}, [128->16], SOCK_NONBLOCK) = 8
1217:09:54.582299 setsockopt(8, SOL_TCP, TCP_NODELAY, [1], 4) = 0
1317:09:54.582527 accept4(5, 0x7ffc4a8bf330, [128], SOCK_NONBLOCK) = -1 EAGAIN (Resource temporarily unavailable)
1417:09:54.582655 recvfrom(8, "foo\n", 15360, 0, NULL, NULL) = 4
1517:09:54.582727 recvfrom(8, "", 15356, 0, NULL, NULL) = 0
1617:09:54.582827 socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 9
1717:09:54.582878 setsockopt(9, SOL_TCP, TCP_NODELAY, [1], 4) = 0
1817:09:54.582897 connect(9, {sa_family=AF_INET, sin_port=htons(8008), sin_addr=inet_addr("10.0.3.82")}, 16) = -1 EINPROGRESS (Operation now in progress)
1917:09:54.582941 sendto(9, "foo\n", 4, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = -1 EAGAIN (Resource temporarily unavailable)
2017:09:54.582968 epoll_ctl(3, EPOLL_CTL_ADD, 9, {EPOLLOUT, {u32=9, u64=9}}) = 0
2117:09:54.582997 epoll_wait(3, [{EPOLLOUT, {u32=9, u64=9}}], 200, 1000) = 1
2217:09:54.583686 connect(9, {sa_family=AF_INET, sin_port=htons(8008), sin_addr=inet_addr("10.0.3.82")}, 16) = 0
2317:09:54.583706 sendto(9, "foo\n", 4, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = 4
2417:09:54.583733 recvfrom(9, 0x19c2300, 15360, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
2517:09:54.583755 shutdown(9, SHUT_WR) = 0
2617:09:54.583775 epoll_ctl(3, EPOLL_CTL_MOD, 9, {EPOLLIN|EPOLLRDHUP, {u32=9, u64=9}}) = 0
2717:09:54.583802 epoll_wait(3, [{EPOLLIN, {u32=9, u64=9}}], 200, 1000) = 1
2817:09:54.584672 recvfrom(9, "bar\n", 16384, 0, NULL, NULL) = 4
2917:09:54.584713 recvfrom(9, "", 16380, 0, NULL, NULL) = 0
3017:09:54.584743 sendto(8, "bar\n", 4, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_MORE, NULL, 0) = 4
3117:09:54.584819 epoll_wait(3, [], 200, 0) = 0
3217:09:54.584901 epoll_wait(3, [], 200, 1000) = 0
33
34
35Notes:
36 - we had data available to try the connect() (see first attempt), despite
37 this during the retry we sent the connect again!
38
39 - why do we wait before sending the shutw to the server if we already know
40 it's needed ? missing CF_SHUTW_NOW ? Missing request forwarding ? Missing
41 auto-close ?
42
43 - response didn't feature HUP nor RDHUP
44
45
46Local:
47
4817:15:43.010786 accept4(5, {sa_family=AF_INET, sin_port=htons(33506), sin_addr=inet_addr("127.0.0.1")}, [128->16], SOCK_NONBLOCK) = 8
4917:15:43.011013 setsockopt(8, SOL_TCP, TCP_NODELAY, [1], 4) = 0
5017:15:43.011181 accept4(5, 0x7ffcd9092cd0, [128], SOCK_NONBLOCK) = -1 EAGAIN (Resource temporarily unavailable)
5117:15:43.011231 recvfrom(8, "foo\n", 15360, 0, NULL, NULL) = 4
5217:15:43.011296 recvfrom(8, "", 15356, 0, NULL, NULL) = 0
5317:15:43.011318 socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 9
5417:15:43.011340 setsockopt(9, SOL_TCP, TCP_NODELAY, [1], 4) = 0
5517:15:43.011353 connect(9, {sa_family=AF_INET, sin_port=htons(8008), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
5617:15:43.011395 sendto(9, "foo\n", 4, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = 4
5717:15:43.011425 shutdown(9, SHUT_WR) = 0
5817:15:43.011459 recvfrom(9, "bar\n", 16384, 0, NULL, NULL) = 4
5917:15:43.011491 recvfrom(9, "", 16380, 0, NULL, NULL) = 0
6017:15:43.011525 sendto(8, "bar\n", 4, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_MORE, NULL, 0) = 4
6117:15:43.011584 epoll_wait(3, [], 200, 0) = 0
62
63Notes:
64 - the shutdown() was properly done right after the sendto(), proving that
65 CF_SHUTW_NOW and auto-close were present. Maybe difference is sync vs async
66 send.
67
68
69Local with delay before closing client:
70
7117:18:17.155349 epoll_wait(3, [{EPOLLIN, {u32=5, u64=5}}], 200, 1000) = 1
7217:18:17.727327 accept4(5, {sa_family=AF_INET, sin_port=htons(33568), sin_addr=inet_addr("127.0.0.1")}, [128->16], SOCK_NONBLOCK) = 8
7317:18:17.727553 setsockopt(8, SOL_TCP, TCP_NODELAY, [1], 4) = 0
7417:18:17.727661 accept4(5, 0x7fff4eb9a0b0, [128], SOCK_NONBLOCK) = -1 EAGAIN (Resource temporarily unavailable)
7517:18:17.727798 recvfrom(8, 0xbda300, 15360, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
7617:18:17.727830 socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 9
7717:18:17.727858 setsockopt(9, SOL_TCP, TCP_NODELAY, [1], 4) = 0
7817:18:17.727877 connect(9, {sa_family=AF_INET, sin_port=htons(8008), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
7917:18:17.727923 epoll_ctl(3, EPOLL_CTL_ADD, 8, {EPOLLIN|EPOLLRDHUP, {u32=8, u64=8}}) = 0
8017:18:17.727945 epoll_ctl(3, EPOLL_CTL_ADD, 9, {EPOLLOUT, {u32=9, u64=9}}) = 0
8117:18:17.727989 epoll_wait(3, [{EPOLLOUT, {u32=9, u64=9}}], 200, 1000) = 1
8217:18:17.728010 connect(9, {sa_family=AF_INET, sin_port=htons(8008), sin_addr=inet_addr("127.0.0.1")}, 16) = 0
8317:18:17.728027 recvfrom(9, "bar\n", 15360, 0, NULL, NULL) = 4
8417:18:17.728055 recvfrom(9, 0xbd62f4, 15356, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
8517:18:17.728073 sendto(8, "bar\n", 4, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = 4
8617:18:17.728104 epoll_ctl(3, EPOLL_CTL_MOD, 9, {EPOLLIN|EPOLLRDHUP, {u32=9, u64=9}}) = 0
8717:18:17.728127 epoll_wait(3, [], 200, 1000) = 0
8817:18:18.729411 epoll_wait(3, [], 200, 1000) = 0
8917:18:19.730654 epoll_wait(3, [{EPOLLIN|EPOLLRDHUP, {u32=8, u64=8}}], 200, 1000) = 1
9017:18:20.299268 recvfrom(8, "", 16384, 0, NULL, NULL) = 0
9117:18:20.299336 epoll_ctl(3, EPOLL_CTL_DEL, 8, 0x7ff3a969f7d0) = 0
9217:18:20.299379 epoll_wait(3, [], 200, 0) = 0
9317:18:20.299401 shutdown(9, SHUT_WR) = 0
9417:18:20.299523 epoll_wait(3, [{EPOLLIN|EPOLLHUP|EPOLLRDHUP, {u32=9, u64=9}}], 200, 1000) = 1
9517:18:20.299678 recvfrom(9, "", 16384, 0, NULL, NULL) = 0
9617:18:20.299761 epoll_wait(3, [], 200, 0) = 0
97
98Notes: server sent the response in two parts ("bar" then EOF) just due to
99netcat's implementation. The second epoll_wait() caught it.
100
101Here we clearly see that :
102 - read0 alone returns EPOLLIN|EPOLLRDHUP
103 - read0 after shutw returns EPOLLIN|EPOLLRDHUP|EPOLLHUP
104 => difference indeed is "cannot write"
105
106
107Local with a delay before closing the server:
108
10917:30:32.527157 epoll_wait(3, [{EPOLLIN, {u32=5, u64=5}}], 200, 1000) = 1
11017:30:33.216827 accept4(5, {sa_family=AF_INET, sin_port=htons(33908), sin_addr=inet_addr("127.0.0.1")}, [128->16], SOCK_NONBLOCK) = 8
11117:30:33.216957 setsockopt(8, SOL_TCP, TCP_NODELAY, [1], 4) = 0
11217:30:33.216984 accept4(5, 0x7ffc1a1fb0c0, [128], SOCK_NONBLOCK) = -1 EAGAIN (Resource temporarily unavailable)
11317:30:33.217071 recvfrom(8, "GET / HTTP/1.0\r\n\r\n\n", 15360, 0, NULL, NULL) = 19
11417:30:33.217115 recvfrom(8, "", 15341, 0, NULL, NULL) = 0
11517:30:33.217135 socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 9
11617:30:33.217176 setsockopt(9, SOL_TCP, TCP_NODELAY, [1], 4) = 0
11717:30:33.217190 connect(9, {sa_family=AF_INET, sin_port=htons(8000), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
11817:30:33.217233 sendto(9, "GET / HTTP/1.0\r\n\r\n\n", 19, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = 19
11917:30:33.217272 shutdown(9, SHUT_WR) = 0
12017:30:33.217318 recvfrom(9, 0x109b2f0, 16384, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
12117:30:33.217332 epoll_ctl(3, EPOLL_CTL_ADD, 9, {EPOLLIN|EPOLLRDHUP, {u32=9, u64=9}}) = 0
12217:30:33.217355 epoll_wait(3, [{EPOLLIN|EPOLLHUP|EPOLLRDHUP, {u32=9, u64=9}}], 200, 1000) = 1
12317:30:33.217377 recvfrom(9, "HTTP/1.0 200\r\nContent-length: 0\r\nX-req: size=19, time=0 ms\r\nX-rsp: id=dummy, code=200, cache=1, size=0, time=0 ms (0 real)\r\n\r\n", 16384, 0, NULL, NULL) = 126
12417:30:33.217395 close(9) = 0
12517:30:33.217411 sendto(8, "HTTP/1.0 200\r\nContent-length: 0\r\nX-req: size=19, time=0 ms\r\nX-rsp: id=dummy, code=200, cache=1, size=0, time=0 ms (0 real)\r\n\r\n", 126, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_MORE, NULL, 0) = 126
12617:30:33.217464 close(8) = 0
12717:30:33.217496 epoll_wait(3, [], 200, 0) = 0
128
129
130Notes:
131 - RDHUP is properly present while some data remain pending.
132 - HUP is present since RDHUP + shutw
133
134It could be concluded that HUP indicates RDHUP+shutw and in no way indicates
135the ability to avoid reading.
136
137Below HUP|ERR|OUT are reported on connection failures, thus WITHOUT read:
138
139accept4(5, {sa_family=AF_INET, sin_port=htons(39080), sin_addr=inet_addr("127.0.0.1")}, [128->16], SOCK_NONBLOCK) = 8
140setsockopt(8, SOL_TCP, TCP_NODELAY, [1], 4) = 0
141accept4(5, 0x7ffffba55730, [128], SOCK_NONBLOCK) = -1 EAGAIN (Resource temporarily unavailable)
142recvfrom(8, "foo\n", 15360, 0, NULL, NULL) = 4
143recvfrom(8, 0x7f634dcfeff4, 15356, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
144socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 9
145fcntl(9, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
146setsockopt(9, SOL_TCP, TCP_NODELAY, [1], 4) = 0
147connect(9, {sa_family=AF_INET, sin_port=htons(8008), sin_addr=inet_addr("10.0.3.82")}, 16) = -1 EINPROGRESS (Operation now in progress)
148sendto(9, "foo\n", 4, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = -1 EAGAIN (Resource temporarily unavailable)
149epoll_ctl(3, EPOLL_CTL_ADD, 8, {EPOLLIN|EPOLLRDHUP, {u32=8, u64=8}}) = 0
150epoll_ctl(3, EPOLL_CTL_ADD, 9, {EPOLLOUT, {u32=9, u64=9}}) = 0
151epoll_wait(3, [{EPOLLOUT|EPOLLERR|EPOLLHUP, {u32=9, u64=9}}], 200, 1000) = 1
152getsockopt(9, SOL_SOCKET, SO_ERROR, [111], [4]) = 0
153recvfrom(9, "", 15360, 0, NULL, NULL) = 0
154close(9) = 0
155
156
157On a failed connect attempt immediately followed by a failed recv (all flags
158set), we can see this:
159
160socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 8
161fcntl(8, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
162setsockopt(8, SOL_TCP, TCP_NODELAY, [1], 4) = 0
163connect(8, {sa_family=AF_INET, sin_port=htons(8008), sin_addr=inet_addr("10.0.3.82")}, 16) = -1 EINPROGRESS (Operation now in progress)
164recvfrom(8, 0x1084a20, 16384, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
165epoll_ctl(3, EPOLL_CTL_ADD, 8, {EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=8, u64=8}}) = 0
166epoll_wait(3, [{EPOLLIN|EPOLLOUT|EPOLLERR|EPOLLHUP|EPOLLRDHUP, {u32=8, u64=8}}], 200, 1000) = 1
167connect(8, {sa_family=AF_INET, sin_port=htons(8008), sin_addr=inet_addr("10.0.3.82")}, 16) = -1 ECONNREFUSED (Connection refused)
168close(8) = 0
169
170=> all flags are reported in case of error.
171
172It's also interesting to note that POLLOUT is still reported after a shutw,
173and no send error is ever reported after shutw:
174
175 shutdown(4, SHUT_WR) = 0
176 poll([{fd=4, events=POLLIN|POLLOUT|POLLRDHUP}], 1, 0) = 1 ([{fd=4, revents=POLLOUT}])
177
178and:
179 shutdown(4, SHUT_WR) = 0
180 sendto(5, "foo", 3, MSG_NOSIGNAL, NULL, 0) = 3
181 poll([{fd=4, events=POLLIN|POLLOUT|POLLRDHUP}], 1, 0) = 1 ([{fd=4, revents=POLLIN|POLLOUT}])
182
183and:
184 shutdown(4, SHUT_WR) = 0
185 sendto(4, "bar", 3, MSG_NOSIGNAL, NULL, 0) = -1 EPIPE (Broken pipe)
186 poll([{fd=4, events=POLLIN|POLLOUT|POLLRDHUP}], 1, 0) = 1 ([{fd=4, revents=POLLOUT}])
187
188
189POLLOUT is still reported after a SHUTWR:
190
191socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 3
192setsockopt(3, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
193bind(3, {sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("0.0.0.0")}, 16) = 0
194listen(3, 1000) = 0
195getsockname(3, {sa_family=AF_INET, sin_port=htons(34729), sin_addr=inet_addr("0.0.0.0")}, [16]) = 0
196socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 4
197connect(4, {sa_family=AF_INET, sin_port=htons(34729), sin_addr=inet_addr("0.0.0.0")}, 16) = 0
198accept(3, 0x7ffcd6a68300, [0->16]) = 5
199fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 3), ...}) = 0
200brk(NULL) = 0xc4e000
201brk(0xc6f000) = 0xc6f000
202write(1, "\n", 1
203) = 1
204shutdown(4, SHUT_WR) = 0
205poll([{fd=4, events=POLLIN|POLLOUT|POLLRDHUP}], 1, 0) = 1 ([{fd=4, revents=POLLOUT}])
206write(1, "ret=1 ev={fd:4 ev:4}\n", 21ret=1 ev={fd:4 ev:4}
207) = 21
208close(5) = 0
209close(4) = 0
210close(3) = 0
211
212Performing a write() on it reports a SIGPIPE:
213
214shutdown(4, SHUT_WR) = 0
215sendto(4, "bar", 3, MSG_NOSIGNAL, NULL, 0) = -1 EPIPE (Broken pipe)
216poll([{fd=4, events=POLLIN|POLLOUT|POLLRDHUP}], 1, 0) = 1 ([{fd=4, revents=POLLOUT}])
217
218
219On SHUT_RD we see POLLIN|POLLOUT|POLLRDHUP (there's no data pending here) :
220shutdown(4, SHUT_RD) = 0
221poll([{fd=4, events=POLLIN|POLLOUT|POLLRDHUP}], 1, 0) = 1 ([{fd=4, revents=POLLIN|POLLOUT|POLLRDHUP}])
222
223
224What is observed in the end :
225 - POLLOUT is always reported for anything SHUT_WR even if it would cause a broken pipe, including listeners if they're also SHUT_RD
226 - POLLHUP is always reported for anything SHUT_WR + having a SHUT_RD pending with or without anything to read, including listeners
227 - POLLIN is always reported for anything to read or a pending zero
228 - POLLIN is NOT reported for SHUT_RD listeners, even with pending connections, only OUT+HUP are reported
229 - POLLIN and POLLRDHUP are always reported after a SHUTR
230 - POLLERR also enables IN,OUT,HUP,RHUP
231
232
233
234
235
236
237
238Currently there's a bit of an issue with connect() being too impatient to read:
239
24016:26:06.818521 connect(9, {sa_family=AF_INET, sin_port=htons(8000), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
24116:26:06.818558 recvfrom(9, 0x1db9400, 16320, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
24216:26:06.818571 epoll_ctl(3, EPOLL_CTL_ADD, 9, {EPOLLIN|EPOLLOUT|EPOLLRDHUP, {u32=9, u64=9}}) = 0
24316:26:06.818588 epoll_wait(3, [{EPOLLOUT, {u32=9, u64=9}}], 200, 1000) = 1
24416:26:06.818603 connect(9, {sa_family=AF_INET, sin_port=htons(8000), sin_addr=inet_addr("127.0.0.1")}, 16) = 0
24516:26:06.818617 sendto(9, "GET /?s=10k HTTP/1.1\r\nhost: 127.0.0.1:4445\r\nuser-agent: curl/7.54.1\r\naccept: */*\r\n\r\n", 84, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = 84
24616:26:06.818660 epoll_ctl(3, EPOLL_CTL_MOD, 9, {EPOLLIN|EPOLLRDHUP, {u32=9, u64=9}}) = 0
24716:26:06.818696 epoll_wait(3, [{EPOLLIN, {u32=9, u64=9}}], 200, 1000) = 1
24816:26:06.818711 recvfrom(9, "HTTP/1.1 200\r\nContent-length: 10240\r\nX-req: size=84, time=0 ms\r\nX-rsp: id=dummy, code=200, cache=1, size=10240, time=0 ms (0 real)\r\n\r\n89.123456789.12345678\n.123456789.123456789.123456789.123456789.123"..., 16320, 0, NULL, NULL) = 10374
24916:26:06.818735 recvfrom(9, 0x1dd75f6, 5946, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
25016:26:06.818790 epoll_ctl(3, EPOLL_CTL_DEL, 9, 0x7ffa818fd7d0) = 0
25116:26:06.818804 epoll_wait(3, [], 200, 0) = 0
252
253
254
255
256This one shows that the error is not definitive, it disappears once it's
257been signaled, then only shut remains! Also it's a proof that an error
258may well be reported after a shutw, so the r/w error may not be merged
259with a shutw since it may appear after an deliberate shutw.
260
261$ ./contrib/debug/poll -v -c snd,shw -s pol,rcv,pol,rcv,pol,snd,lin,clo -c pol,rcv,pol,rcv,pol,rcv,pol
262#### BEGIN ####
263cmd #1 stp #1: do_snd(4): ret=3
264cmd #1 stp #2: do_shw(4): ret=0
265cmd #2 stp #0: do_acc(3): ret=5
266cmd #2 stp #1: do_pol(5): ret=1 ev=0x2005 (IN OUT RDHUP)
267cmd #2 stp #2: do_rcv(5): ret=3
268cmd #2 stp #3: do_pol(5): ret=1 ev=0x2005 (IN OUT RDHUP)
269cmd #2 stp #4: do_rcv(5): ret=0
270cmd #2 stp #5: do_pol(5): ret=1 ev=0x2005 (IN OUT RDHUP)
271cmd #2 stp #6: do_snd(5): ret=3
272cmd #2 stp #7: do_lin(5): ret=0
273cmd #2 stp #8: do_clo(5): ret=0
274cmd #3 stp #1: do_pol(4): ret=1 ev=0x201d (IN OUT ERR HUP RDHUP)
275cmd #3 stp #2: do_rcv(4): ret=3
276cmd #3 stp #3: do_pol(4): ret=1 ev=0x201d (IN OUT ERR HUP RDHUP)
277cmd #3 stp #4: do_rcv(4): ret=-1 (Connection reset by peer)
278cmd #3 stp #5: do_pol(4): ret=1 ev=0x2015 (IN OUT HUP RDHUP)
279cmd #3 stp #6: do_rcv(4): ret=0
280cmd #3 stp #7: do_pol(4): ret=1 ev=0x2015 (IN OUT HUP RDHUP)
281#### END ####