3proxy
3proxy copied to clipboard
3proxy
if server half-closed the connection part of the response is lost
TL/DR why don't we use SHUT_WR inside sockmap()? Why don't we wait at least CONNECTION_LONG ms for EOFs from both parties?
Reproducible with v 0.9.4 , c716c67 on ArchLinux x64 Sep 7 2022
My browser sends an HTTP proxy command CONNECT or a socks command CONNECT to a 3proxy instance and then uses this single connection to multiplex the HTTP/2 requests to an HTTPS site.
Recently I noticed that 3proxy disconnects before all requests are served and the browser has to connect again. Replacing 3proxy with GNU ssh -D dynamic port forwarding resolves the issue. Recompiling without -DWITHSPLICE does not solve the issue.
To help debug the problem I ensured that no more than one TCP connection reaches 3proxy:
# socat only accepts one client and exits
socat TCP-LISTEN:3137 TCP:proxyhost:3137
I added CFLAGS -g -O0 -DWITHLOG=2 in Makefile.Linux, recompiled and put a breakpoint at close(2). At the same time I started tcpdump on proxyhost:
tcpdump -i any -w /tmp/aaa.pcap "host at-home.ru or port 3137"
The last messages were: server_to_pipe_splice_finished_ ... res:_0,_errno:_0 (see below). I believe they're printed after splice(2) returned 0 (see the code below).
Wireshark shows that the first FIN packet originates from the site, but FIN isn't sent to the client. Instead multiple RST packets are sent to the client.
Wireshark:
Here's the traffic produced by ssh -D
You can see that the proxy sends a FIN packet to the client and waits for EOF before sendin FIN to the server.
I noticed that placing a breakpoint at so._shutdown(param->clisock, SHUT_RDWR) lets the full response reach the client. Apparently, the parameter SHUT_RDWR sends RST which will discard all unprocessed data on the client.
The code near shutdown:
┌─proxymain.c───────────────────────────────────────────────────────
│ if(param->remsock != INVALID_SOCKET) {
│ so._shutdown(param->remsock, SHUT_RDWR);
│ so._closesocket(param->remsock);
│ }
│ if(param->clisock != INVALID_SOCKET) {
│B+> so._shutdown(param->clisock, SHUT_RDWR);
│ so._closesocket(param->clisock);
│ }
│ myfree(param);
│ }
The code near splice:
res = splice(param->remsock, NULL, pipesrv[1], NULL, MIN(MAXSPLICE - inclientpipe, fromserver - inserverpipe), SPLICE_F_NONBLOCK|SPLICE_F_MOVE);
#ifdef WITHLOG
log("server to pipe splice finished\n");
#if WITHLOG > 1
#ifdef WITHSPLICE
sprintf(logbuf, "res: %d, errno: %d", (int)res, (int)errno);
log(logbuf);
#endif
#endif
#endif
if(res <= 0) {
FROMSERVER = TOSERVERPIPE = 0;
if(res == 0 && !errno) {
SERVERTERM = 1;
Here's the recent debug output by the time the breakpoint hit:
2022-11-26 12:31:16.437 SOCK5.3137 00000 - 10.8.1.1:51078 188.65.64.15:443 0 0 0 ready_writing_to_server_pipe
2022-11-26 12:31:16.437 SOCK5.3137 00000 - 10.8.1.1:51078 188.65.64.15:443 0 0 0 int_FROMCLIENT_=_0,_TOCLIENTBUF_=_0,_FROMCLIENTBUF_=_1,_TOSERVER_=_1,_FROMSERVER_=_0,_TOSERVERBUF_=_0,_FROMSERVERBUF_=_1,_TOCLIENT_=_1;_inclientbuf=0;_inserverbuf=0,_CLIENTTERM_=_0,_SERVERTERM_=0,_fromserver=4294748948,_fromclient=4294961238,_inserverpipe=0,_inclentpipe=0_TOCLIENTPIPE=1_FROMCLIENTPIPE==1_TOSERVERPIPE==1_FROMSERVERPIPE=1
2022-11-26 12:31:16.437 SOCK5.3137 00000 - 10.8.1.1:51078 188.65.64.15:443 0 0 0 wait_reading_from_client
2022-11-26 12:31:16.437 SOCK5.3137 00000 - 10.8.1.1:51078 188.65.64.15:443 0 0 0 wait_reading_from_server
2022-11-26 12:31:16.437 SOCK5.3137 00000 - 10.8.1.1:51078 188.65.64.15:443 0 0 0 entering_poll
2022-11-26 12:31:16.438 SOCK5.3137 00000 - 10.8.1.1:51078 188.65.64.15:443 0 0 0 leaving_poll
2022-11-26 12:31:16.438 SOCK5.3137 00000 - 10.8.1.1:51078 188.65.64.15:443 0 0 0 ready_to_read_from_server
2022-11-26 12:31:16.438 SOCK5.3137 00000 - 10.8.1.1:51078 188.65.64.15:443 0 0 0 int_FROMCLIENT_=_0,_TOCLIENTBUF_=_0,_FROMCLIENTBUF_=_1,_TOSERVER_=_1,_FROMSERVER_=_1,_TOSERVERBUF_=_0,_FROMSERVERBUF_=_1,_TOCLIENT_=_1;_inclientbuf=0;_inserverbuf=0,_CLIENTTERM_=_0,_SERVERTERM_=0,_fromserver=4294748948,_fromclient=4294961238,_inserverpipe=0,_inclentpipe=0_TOCLIENTPIPE=1_FROMCLIENTPIPE==1_TOSERVERPIPE==1_FROMSERVERPIPE=1
2022-11-26 12:31:16.438 SOCK5.3137 00000 - 10.8.1.1:51078 188.65.64.15:443 0 0 0 read_from_server_to_pipe_
2022-11-26 12:31:16.438 SOCK5.3137 00000 - 10.8.1.1:51078 188.65.64.15:443 0 0 0 server_to_pipe_splice_finished_
2022-11-26 12:31:16.438 SOCK5.3137 00000 - 10.8.1.1:51078 188.65.64.15:443 0 0 0 res:_14766,_errno:_0
2022-11-26 12:31:16.438 SOCK5.3137 00000 - 10.8.1.1:51078 188.65.64.15:443 0 0 0 done_read_from_server_to_pipe_
2022-11-26 12:31:16.439 SOCK5.3137 00000 - 10.8.1.1:51078 188.65.64.15:443 0 14766 0 int_FROMCLIENT_=_0,_TOCLIENTBUF_=_0,_FROMCLIENTBUF_=_1,_TOSERVER_=_1,_FROMSERVER_=_1,_TOSERVERBUF_=_0,_FROMSERVERBUF_=_1,_TOCLIENT_=_1;_inclientbuf=0;_inserverbuf=0,_CLIENTTERM_=_0,_SERVERTERM_=0,_fromserver=4294748948,_fromclient=4294961238,_inserverpipe=14766,_inclentpipe=0_TOCLIENTPIPE=1_FROMCLIENTPIPE==1_TOSERVERPIPE==1_FROMSERVERPIPE=1
2022-11-26 12:31:16.439 SOCK5.3137 00000 - 10.8.1.1:51078 188.65.64.15:443 0 0 0 send_to_client_from_pipe
2022-11-26 12:31:16.439 SOCK5.3137 00000 - 10.8.1.1:51078 188.65.64.15:443 0 0 0 client_from_pipe_splice_finished_
2022-11-26 12:31:16.439 SOCK5.3137 00000 - 10.8.1.1:51078 188.65.64.15:443 0 0 0 res:_14766,_errno:_0
2022-11-26 12:31:16.439 SOCK5.3137 00000 - 10.8.1.1:51078 188.65.64.15:443 0 0 0 int_FROMCLIENT_=_0,_TOCLIENTBUF_=_0,_FROMCLIENTBUF_=_1,_TOSERVER_=_1,_FROMSERVER_=_1,_TOSERVERBUF_=_0,_FROMSERVERBUF_=_1,_TOCLIENT_=_1;_inclientbuf=0;_inserverbuf=0,_CLIENTTERM_=_0,_SERVERTERM_=0,_fromserver=4294734182,_fromclient=4294961238,_inserverpipe=0,_inclentpipe=0_TOCLIENTPIPE=1_FROMCLIENTPIPE==1_TOSERVERPIPE==1_FROMSERVERPIPE=1
2022-11-26 12:31:16.439 SOCK5.3137 00000 - 10.8.1.1:51078 188.65.64.15:443 0 0 0 read_from_server_to_pipe_
2022-11-26 12:31:16.439 SOCK5.3137 00000 - 10.8.1.1:51078 188.65.64.15:443 0 0 0 server_to_pipe_splice_finished_
2022-11-26 12:31:16.439 SOCK5.3137 00000 - 10.8.1.1:51078 188.65.64.15:443 0 0 0 res:_0,_errno:_0
[Switching to Thread 0x7ffff7da46c0 (LWP 343012)]
Thread 6 "3proxy" hit Breakpoint 1, 0x00007ffff7eb9540 in close () from /usr/lib/libc.so.6
(gdb) bt
#0 0x00007ffff7eb9540 in close () from /usr/lib/libc.so.6
#1 0x00005555555816e9 in sockmap (param=0x7ffff00013f0, timeo=1800, usesplice=1) at sockmap.c:724
#2 0x000055555557d81b in sockschild (param=0x7ffff00013f0) at socks.c:282
#3 0x000055555555ddde in threadfunc (p=0x7ffff00013f0) at proxymain.c:77
#4 0x00007ffff7e4878d in ?? () from /usr/lib/libc.so.6
#5 0x00007ffff7ec98e4 in clone () from /usr/lib/libc.so.6
(gdb)
│ else if((inclientbuf || inserverbuf)) res = 94;
│ #ifdef WITHSPLICE
│ else if(inclientpipe || inserverpipe) res = 94;
│ #endif
│
│ CLEANRET:
│
│ #ifdef WITHSPLICE
│ > if(pipecli[0] >= 0) close(pipecli[0]);
│ if(pipecli[1] >= 0) close(pipecli[1]);
│ if(pipesrv[0] >= 0) close(pipesrv[0]);
│ if(pipesrv[1] >= 0) close(pipesrv[1]);
│ #endif
│
│ return res;
│ }
Here's the current 3proxy config on proxyhost:
log
flush
auth iponly
allow *
socks -p3137
shutdown/close do not close connection immediately, TCP stack sends bufferend data on close, see SO_LINGER description
SO_LINGER
Sets or gets the SO_LINGER option. The argument is a
linger structure.
struct linger {
int l_onoff; /* linger active */
int l_linger; /* how many seconds to linger for */
};
When enabled, a close(2) or shutdown(2) will not return
until all queued messages for the socket have been
successfully sent or the linger timeout has been reached.
Otherwise, the call returns immediately and the closing is
done in the background. When the socket is closed as part
of exit(2), it always lingers in the background.
3proxy sets linger time to STRING_LONG (60 seconds by default). I have no idea why do you get RST immediately and I never saw behaviour like this in my environment. It should only happen if linger time is set to 0. May be, it's a bug in shutdown/close behaviour in some LInux kernel. You can try to remove all occurances of shutdown() in the code, because shutdown is not actually required. If it fixes your case I can use it as a workaround.
Something tells me that SO_LINGER won't help when the other party keeps sending more data to 3proxy. If I have time I'll try to make a small c program to reproduce this, hopefully, on this holiday.
The program is ready: https://github.com/basinilya/test3proxy
See below: Connection closed before go away received It means that some data sent by server was lost.
Run program without arguments to see usage.
The program imitates HTTP/2 traffic.
In server mode
- accept a single client
- consume one dummy "request"
- send dummy "response"
- send "go away" and send EOF to client
- wait for EOF from client
In client mode
- connect to server
- send one dummy "request"
- keep sending more "requests"
- consume all data from server, look for "go away"
- send EOF to server
- wait for EOF from server
Optionally connect via HTTP CONNECT proxy
Results when connecting directly:
$ ./test3proxy server 127.0.0.1:9999
e6206f7daae552f111da091c9682569a ./test3proxy
S Server address: 127.0.0.1:9999
S Listening...
S Accepted
S linger: {1,5}
S Receiving 10000 bytes...
S Done
S Sending 500000 bytes...
S Done
S Sending 1 bytes...
S Done
S Shutting down...
S Waiting 5 seconds for EOF...
S Received EOF
S Closing...
$ ./test3proxy client 127.0.0.1:9999
C Server address: 127.0.0.1:9999
C Connecting...
C Connected
C linger: {1,5}
C Sending 10000 bytes...
C Done
C Sending extra requests...
C Received go away
C Shutting down...
C Waiting 5 seconds for EOF...
C Received EOF
C Closing...
Results when connecting to a local instance via local 3proxy:
$ ./test3proxy server 127.0.0.2:9999
e6206f7daae552f111da091c9682569a ./test3proxy
S Server address: 127.0.0.2:9999
S Listening...
S Accepted
S linger: {1,5}
S Receiving 10000 bytes...
S Done
S Sending 500000 bytes...
S Done
S Sending 1 bytes...
S Done
S Shutting down...
S Waiting 5 seconds for EOF...
S Received EOF
S Closing...
$ ./test3proxy client 127.0.0.2:9999 127.0.0.1:3131
C Proxy address: 127.0.0.1:3131
C Connecting...
C Connected
C linger: {1,5}
C Sending proxy request...
C > CONNECT 127.0.0.2:9999 HTTP/1.1
C > Host: 127.0.0.2:9999
C > User-Agent: curl/7.84.0
C > Proxy-Connection: Keep-Alive
C >
C Sending 112 bytes...
C Done
C Receiving proxy response
C < HTTP/1.0 200 Connection Established
C <
C Sending 10000 bytes...
C Done
C Sending extra requests...
SOCKET_ERROR != (nb = my_send_nosigpipe(s, buf, BUFSZ, 0)): Broken pipe
Results when connecting to a distant instance via 3proxy:
./test3proxy server 10.8.1.1:9999
S Server address: 10.8.1.1:9999
S Listening...
S Accepted
S linger: {1,5}
S Receiving 10000 bytes...
S Done
S Sending 500000 bytes...
S Done
S Sending 1 bytes...
S Done
S Shutting down...
S Waiting 5 seconds for EOF...
S Received EOF
S Closing...
$ ./test3proxy client 10.8.1.1 127.0.0.1:3131
C Proxy address: 127.0.0.1:3131
C Connecting...
C Connected
C linger: {1,5}
C Sending proxy request...
C > CONNECT 10.8.1.1:9999 HTTP/1.1
C > Host: 10.8.1.1:9999
C > User-Agent: curl/7.84.0
C > Proxy-Connection: Keep-Alive
C >
C Sending 110 bytes...
C Done
C Receiving proxy response
C < HTTP/1.0 200 Connection Established
C <
C Sending 10000 bytes...
C Done
C Sending extra requests...
C Connection closed before go away received