Attachment 870988 Details for Bug 1217502

Description and initial analysis

description.txt (text/plain), 7.05 KB, created by Marcus Hüwe on 2023-11-26 17:12:29 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Marcus Hüwe

Created: 2023-11-26 17:12:29 UTC

Size: 7.05 KB

patch

obsolete

>We are facing a very strange behavior in a java.nio.channels.ServerSocketChannel
>based single-threaded tcp server, when "lots" of client threads try to connect
>to this server at the same time: It looks as if an ACKed tcp segment went
>astray because its data does not seem to reach user space. Instead, the data
>of the subsequent tcp segment arrives in user space.
>
>
>The protocol of the application is as follows:
>
>- The client connects to the server and sends:
>  <length>\n<exactly length many bytes>
>- The server responds with sha256sum(<exactly length many bytes>)
>
>Example:
>
>marcus@linux:~> echo -e "4\nfoo" | netcat localhost 3000
>b5bb9d8014a0f9b1d61e21e796d78dccdf1352f23cd32812f4850b878ae4944cmarcus@linux:~>
>
>
>According to the protocol, it is perfectly fine, if, for instance, "4\n" and
>"foo\n" are sent via two different tcp segments. However, _sometimes_ it
>looks as if the "4\n" tcp segment went astray (from the user space POV),
>even though it was ACKed.
>
>The following analysis demonstrates this strange behavior.
>
>
># Compile the source code:
>
>marcus@linux:~/repro/src> javac -d ../bin/ *.java
>marcus@linux:~/repro/src>
>
>
># Start tcpdump
>
>linux:~ # tcpdump -i lo -B 20000 -w /home/marcus/repro/repro.pcap
>
>
># Start the server
>
>marcus@linux:~/repro> strace -ff -s 400 -o strace/server.strace java -cp bin SingleThreadedServer localhost 3000
>PID: 17938
>
>
># Start the client
>
>marcus@linux:~/repro> java -cp bin/ HashClient localhost 3000 dir/ 420
>seed: 1701007244707
>marcus@linux:~/repro>
>
>(That is 420 client threads are created and try to connect to the server. Each
>of the threads picks a random (wrt. seed) file from dir/ and sends it to the
>server (according the protocol from above).)
>
>
>If we are lucky, the server throws an exception and terminates:
>
>Exception in thread "main" java.lang.IllegalStateException: illegal byte: 120, remotePort: 57550, called: 1, buffer: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
>
>	at HashRemoteEnd.parseLength(HashRemoteEnd.java:79)
>	at HashRemoteEnd.processWorkEvent(HashRemoteEnd.java:106)
>	at SingleThreadedServer.processWork(SingleThreadedServer.java:136)
>	at SingleThreadedServer.serverLoop(SingleThreadedServer.java:85)
>	at SingleThreadedServer.startAndRunServer(SingleThreadedServer.java:51)
>	at SingleThreadedServer.main(SingleThreadedServer.java:28)
>marcus@linux:~/repro>
>
>This exception tells us that for the client with remote port 57550 the
>parseLength method is called for the first time and that it encountered
>the unexpected byte 'x' (ascii 120). The whole buffer that was passed to
>parseLength consists of exactly 82 'x' and a trailing '\n'. Of course, this
>does not conform to the length specification of our protocol.
>
>
># Stop tcpdump
>
>^C3915 packets captured
>7830 packets received by filter
>0 packets dropped by kernel
>linux:~ #
>
>
># Analyze the repro.pcap file (excerpt)
>
>marcus@linux:~/repro> tcpdump -r repro.pcap -n "tcp src or dst port 57550" -A
>reading from file repro.pcap, link-type EN10MB (Ethernet), snapshot length 262144
>15:00:44.965303 IP 127.0.0.1.57550 > 127.0.0.1.3000: Flags [S], seq 1156134231, win 33280, options [mss 65495,sackOK,TS val 3776711033 ecr 0,nop,wscale 7], length 0
>E..<W@@.@..y............D.5W.........0.........
>..	y........
>15:00:45.972623 IP 127.0.0.1.57550 > 127.0.0.1.3000: Flags [S], seq 1156134231, win 33280, options [mss 65495,sackOK,TS val 3776712041 ecr 0,nop,wscale 7], length 0
>E..<WA@.@..x............D.5W.........0.........
>...i........
>15:00:45.972933 IP 127.0.0.1.3000 > 127.0.0.1.57550: Flags [S.], seq 3671196184, ack 1156134232, win 33280, options [mss 65495,sackOK,TS val 3776711985 ecr 3776712041,nop,wscale 7], length 0
>E..<..@.@.<.................D.5X.....0.........
>...1...i....
>15:00:45.973376 IP 127.0.0.1.57550 > 127.0.0.1.3000: Flags [.], ack 1, win 260, options [nop,nop,TS val 3776712041 ecr 3776711985], length 0
>E..4WB@.@...............D.5X.........(.....
>...i..1
>15:00:45.983710 IP 127.0.0.1.57550 > 127.0.0.1.3000: Flags [P.], seq 1:4, ack 1, win 260, options [nop,nop,TS val 3776712052 ecr 3776711985], length 3
>E..7WC@.@..{............D.5X.........+.....
>...t...183
>
>15:00:46.192508 IP 127.0.0.1.57550 > 127.0.0.1.3000: Flags [P.], seq 4:87, ack 1, win 260, options [nop,nop,TS val 3776712260 ecr 3776711985], length 83
>E...WD@.@..*............D.5[.........{.....
>...D...1xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
>
>15:00:46.192795 IP 127.0.0.1.3000 > 127.0.0.1.57550: Flags [.], ack 87, win 259, options [nop,nop,TS val 3776712261 ecr 3776712260], length 0
>E..4..@.@.q.................D.5......(.....
>...E...D
>15:00:46.334530 IP 127.0.0.1.3000 > 127.0.0.1.57550: Flags [F.], seq 1, ack 87, win 260, options [nop,nop,TS val 3776712403 ecr 3776712260], length 0
>E..4..@.@.q.................D.5......(.....
>.......D
>
>
>As we can see, the length data "83\n" (seq 1:4) and the data (82 times an
>'x' + a trailing '\n') (seq 4:87) were sent and also ACKed.
>
>However, when looking at the strace, it seems that the length data never reaches
>user space:
>
>marcus@linux:~/repro/strace> grep -l PID server.strace.*
>server.strace.17939
>marcus@linux:~/repro/strace>
>
>
>Relevant excerpt from the server.strace.17939 file:
>
>accept(6, {sa_family=AF_INET6, sin6_port=htons(57550), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_scope_id=0}, [28]) = 60
>fcntl(60, F_GETFL)                      = 0x2 (flags O_RDWR)
>getsockname(60, {sa_family=AF_INET6, sin6_port=htons(3000), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_scope_id=0}, [28]) = 0
>getsockname(60, {sa_family=AF_INET6, sin6_port=htons(3000), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_scope_id=0}, [28]) = 0
>
>...
>
>accept(6, 0x7f5569dfe5a0, [28])         = -1 EAGAIN (Resource temporarily unavailable)
>read(27, "3\nxx\n", 4096)               = 5
>read(60, "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx\n", 4096) = 83
>
>
>Indeed, the read(...) on fd 60 does _NOT_ yield the length. From what I can
>see via
>
>marcus@linux:~/repro/strace> grep -l '(60' server.strace.*
>server.strace.17939
>marcus@linux:~/repro/strace>
>
>all relevant IO for fd 60 occurs in 17939 (the grep should also take syscalls
>like dup* into account).
>
>
>Question: what happened with the length data/why did the read(...) yield the
>wrong data?
>
>
># Observation
>
>As mentioned earlier this behavior is intermittent. However, it seems to
>occur more often, if files with a "short" length are involved (like the
>ones in the "dir/" directory). When passing the "/usr/bin" directory to
>the "HashClient" it takes more iterations until this behavior occurs.
>But if it occured, it was always a "short" length script file.
>
>
># Version information:
>- openSUSE Tumbleweed 20231122 (in a virtualbox vm on a windows host)
>
>marcus@linux:~> uname -a
>Linux linux 6.6.2-1-default #1 SMP PREEMPT_DYNAMIC Mon Nov 20 11:22:36 UTC 2023 (263a855) x86_64 x86_64 x86_64 GNU/Linux
>marcus@linux:~> java --version
>openjdk 11.0.21 2023-10-17
>OpenJDK Runtime Environment (build 11.0.21+0-suse-1.1-x8664)
>OpenJDK 64-Bit Server VM (build 11.0.21+0-suse-1.1-x8664, mixed mode)
>marcus@linux:~>

Actions: View

Attachments on bug 1217502: 870988 | 870989