Retransmissions and duplicate acks

[talex5]

Testing from my cubieboard2, I'm getting a lot of TCP retransmissions and duplicate acks. It happens frequently when using TLS, but I have seen it even just streaming plain TCP (without even HTTP), though it took many tries before I saw it.

Here are some pcap files in case someone more knowledgable wants to take a look:

• http://test.roscidus.com/static/cuekeeper-tls-fail-fast.pcap : a trace showing Mirage ignoring the first client hello, then sending a server hello on the retransmit, getting an ack for it and immediately sending two duplicate acks, followed by lots more strangeness later. The client is Firefox trying to load CueKeeper.
• http://test.roscidus.com/static/plain-tcp.pcap : a trace from mirage-skeleton/network modified to send a fixed buffer over and over again after reading the client data. There's a dup ack near the start, then things are good for a while, then at 0.9083s it suddenly sends a TCP segment with a much higher sequence number and things go badly for a while, until it eventually recovers at around 4s (I removed the rest of the trace after that). The client is a simple nc invocation.

Could someone who understands TCP and/or Mirage's implementation suggest what could be going on here?

[balrajsingh]

Trying to understand the trace - for now just looking at plain-tcp.pcap.
Would it be possible for you to create a trace from both sides for the same
connection. This one appears to be from the side saying 'hi!', so a trace
from this side as well as from the sender for the same connection.

As you say there is a dup-ack near the beginning but that's from the
"server" and it's acking the FIN that was send from the client, after it
half-closed the connection. This particular ack is redundant and shouldn't
be there, but it really is quite harmless and doesn't have any effect on
the connection. I think it's because when a FIN is received an ACK is sent
back immediately, but the delayed-ACK timer thinks the ACK wasn't sent.
The cause of the confusion is probably because the seq number that was
advanced for ACK-ing the FIN was just done adhoc in that packet - the
delayed-ACK timer is looking at the overall connection's seq number. It
should be fixed, but this one is harmless.

The real problem is later in the trace. It looks like 1 packet gets lost -
this would be a non event. Oddly instead of that lost packet a packet
about 32 packets ahead (about 46k ahead in the seq nums) arrives - by
itself again this is not serious. All the correct signalling seems to be
happening to recover from the loss/out-of-orderness and little loss of
transfer speed is seen. But during that recovery process many other
packets arrive out of order or are lost. Again the signalling works to
recover from the chaos till there is one lost packet for which TCP is
unable to signal the loss. Usually this is a lost packet that when
received would make the flow whole again (ie the last lost packet) - if the
fast retransmit of this packet is also lost then both sides have no means
left to signal it and get stuck. This now means waiting for the re-xmit
timer to kick in and send out the critical last packet yet again. But by
this stage it looks like the retransmit timeout has backed off so much
because of the chaos, that it kicks in only after about 3 seconds. When
the missing packet is finally received all becomes well again and it's off
and running again.

If you could get a trace from both ends (and from the network as well if
possible) we can try to figure out where the out-of-orderness and loss is
happening. This is not the kind of chaos that networks usually produce
(which is what TCP is tuned to address) - it has the fingerprints of a
problem in stack -> driver -> network interface.

Looking at the other trace now...

On Sun, May 24, 2015 at 12:06 PM, Thomas Leonard notifications@github.com
wrote:

Testing from my cubieboard2, I'm getting a lot of TCP retransmissions and
duplicate acks. It happens frequently when using TLS, but I have seen it
even just streaming plain TCP (without even HTTP), though it took many
tries before I saw it.

Here are some pcap files in case someone more knowledgable wants to take a
look:

http://test.roscidus.com/static/cuekeeper-tls-fail-fast.pcap : a trace
showing Mirage ignoring the first client hello, then sending a server hello
on the retransmit, getting an ack for it and immediately sending two
duplicate acks, followed by lots more strangeness later. The client is
Firefox trying to load CueKeeper.

http://test.roscidus.com/static/plain-tcp.pcap : a trace from
mirage-skeleton/network modified to send a fixed buffer over and over again
after reading the client data. There's a dup ack near the start, then
things are good for a while, then at 0.9083s it suddenly sends a TCP
segment with a much higher sequence number and things go badly for a while,
until it eventually recovers at around 4s (I removed the rest of the trace
after that). The client is a simple nc invocation.

Could someone who understands TCP and/or Mirage's implementation suggest
what could be going on here?

—
Reply to this email directly or view it on GitHub
#140.

[balrajsingh]

looking at cuekeeper-..pcap:

The first 'client hello' seems to have gotten lost along the way - it's
present in this trace but since there is no response the assumption is that
it's lost. Again with more traces along the path we can try to figure out
where this loss occurred. Further along this pattern is repeated several
times. Odd that the client-hello pkt is dropped every time.

On Sun, May 24, 2015 at 2:39 PM, Balraj Singh balrajsingh@ieee.org wrote:

Trying to understand the trace - for now just looking at plain-tcp.pcap.
Would it be possible for you to create a trace from both sides for the same
connection. This one appears to be from the side saying 'hi!', so a trace
from this side as well as from the sender for the same connection.

As you say there is a dup-ack near the beginning but that's from the
"server" and it's acking the FIN that was send from the client, after it
half-closed the connection. This particular ack is redundant and shouldn't
be there, but it really is quite harmless and doesn't have any effect on
the connection. I think it's because when a FIN is received an ACK is sent
back immediately, but the delayed-ACK timer thinks the ACK wasn't sent.
The cause of the confusion is probably because the seq number that was
advanced for ACK-ing the FIN was just done adhoc in that packet - the
delayed-ACK timer is looking at the overall connection's seq number. It
should be fixed, but this one is harmless.

The real problem is later in the trace. It looks like 1 packet gets lost

• this would be a non event. Oddly instead of that lost packet a packet
  about 32 packets ahead (about 46k ahead in the seq nums) arrives - by
  itself again this is not serious. All the correct signalling seems to be
  happening to recover from the loss/out-of-orderness and little loss of
  transfer speed is seen. But during that recovery process many other
  packets arrive out of order or are lost. Again the signalling works to
  recover from the chaos till there is one lost packet for which TCP is
  unable to signal the loss. Usually this is a lost packet that when
  received would make the flow whole again (ie the last lost packet) - if the
  fast retransmit of this packet is also lost then both sides have no means
  left to signal it and get stuck. This now means waiting for the re-xmit
  timer to kick in and send out the critical last packet yet again. But by
  this stage it looks like the retransmit timeout has backed off so much
  because of the chaos, that it kicks in only after about 3 seconds. When
  the missing packet is finally received all becomes well again and it's off
  and running again.

If you could get a trace from both ends (and from the network as well if
possible) we can try to figure out where the out-of-orderness and loss is
happening. This is not the kind of chaos that networks usually produce
(which is what TCP is tuned to address) - it has the fingerprints of a
problem in stack -> driver -> network interface.

Looking at the other trace now...

On Sun, May 24, 2015 at 12:06 PM, Thomas Leonard <notifications@github.com

wrote:

Testing from my cubieboard2, I'm getting a lot of TCP retransmissions and
duplicate acks. It happens frequently when using TLS, but I have seen it
even just streaming plain TCP (without even HTTP), though it took many
tries before I saw it.

Here are some pcap files in case someone more knowledgable wants to take
a look:

http://test.roscidus.com/static/cuekeeper-tls-fail-fast.pcap : a
trace showing Mirage ignoring the first client hello, then sending a server
hello on the retransmit, getting an ack for it and immediately sending two
duplicate acks, followed by lots more strangeness later. The client is
Firefox trying to load CueKeeper.

http://test.roscidus.com/static/plain-tcp.pcap : a trace from
mirage-skeleton/network modified to send a fixed buffer over and over again
after reading the client data. There's a dup ack near the start, then
things are good for a while, then at 0.9083s it suddenly sends a TCP
segment with a much higher sequence number and things go badly for a while,
until it eventually recovers at around 4s (I removed the rest of the trace
after that). The client is a simple nc invocation.

Could someone who understands TCP and/or Mirage's implementation suggest
what could be going on here?

—
Reply to this email directly or view it on GitHub
#140.

[talex5]

Thanks! Here's a pair of traces, one from my laptop and one from the cubieboard's dom0 (they're connected only by my home router):

http://test.roscidus.com/static/ck-from-cb2.pcap
http://test.roscidus.com/static/ck-from-laptop.pcap

They look pretty similar to me. The requests were triggered by refreshing Firefox, and it never got the pages (just kept spinning) in this case.

(note: the version of tcpip I'm using is https://github.com/talex5/mirage-tcpip/commits/ignore-trailing-bytes which is master plus the fix for the trailing bytes bug, but I don't think that should be causing these problems)

[balrajsingh]

There's no real difference between the two - all the packets are in both
and in the same order. So the problem is further up in the mirage stack.
Do you think ocaml-pcap can be used to grab a trace from within the stack.

The trailing bytes fix should not affect this.

The trace doesn't look good. It may be that when mirage has to deal with
the client-hello data it somehow gets so busy that nothing gets sent out,
not even a TCP ack. The laptop retransmits client-hello pkts a couple of
times, but from the timing of the response when it finally appears, it look
like it is not a response to the retransmitted pkts but original hello.
There is more similar behaviour later.

A trace from inside ethif could be very helpful.

Thanks.

On Sun, May 24, 2015 at 3:15 PM, Thomas Leonard notifications@github.com
wrote:

Thanks! Here's a pair of traces, one from my laptop and one from the
cubieboard's dom0 (they're connected only by my home router):

http://test.roscidus.com/static/ck-from-cb2.pcap
http://test.roscidus.com/static/ck-from-laptop.pcap

They look pretty similar to me. The requests were triggered by refreshing
Firefox, and it never got the pages (just kept spinning) in this case.

(note: the version of tcpip I'm using is
https://github.com/talex5/mirage-tcpip/commits/ignore-trailing-bytes
which is master plus the fix for the trailing bytes bug, but I don't think
that should be causing these problems)

—
Reply to this email directly or view it on GitHub
#140 (comment)
.

[talex5]

I got a trace with mirage-profile:

http://test.roscidus.com/traces/ck-tcp/

At the far right, there are several red "should-resolve" threads. These correspond to unikernel threads for handling HTTP requests (the application flags them as should-resolve and they get highlighted because they don't).

Double-clicking on the highest one (to highlight it) and zooming in on the start, it's waiting for thread 5587 (waiting-for is indicated by the yellow arrow; this is new). Following that right, it ends with thread 5690, which is waiting for User_buffer.take_l. I guess this means it's waiting for data from the network.

Most of the other red threads look similar, but the second to bottom one is waiting on 5431, which ends up waiting for User_buffer.wait_for ("Wait until at least sz bytes are available in the window").

It's quite possible (probable even) that the tracing system is buggy and wrong, but this might be a useful lead...

[talex5]

Here's a better trace, with the corresponding pcap:

• http://test.roscidus.com/traces/ck-tcp2/
• http://test.roscidus.com/traces/ck-tcp2/ck-from-laptop.pcap

It defaults to showing the region where the TCP thread for client port 40312 added some data to its User_buffer.Tx. The interesting thread is near the bottom; you'll need to drag upwards to see it (it's white, so easy to spot).

1. It adds 1460 bytes to the buffer.
2. It then adds a further 700 bytes.
3. clear_buffer gets called to flush it, but get_pkt_to_send returns without doing anything because tx_wnd is zero.
4. It seems that nothing ever flushes the buffer after that: the User_buffer.Tx.bufbytes#40312 metric is still at its maximum at the end of the trace (I've hidden the other metrics; the HTML GUI doesn't let you toggle them yet).

Looking at the pcap trace in wireshark with the filter tcp.port eq 40312, this connection was very simple:

1. The TCP handshake completed.
2. The client sent an SSL Client Hello.
3. Shortly afterwards, it retransmitted it.
4. It got an ack, then a duplicate ack.
5. Later, there was a TCP Keep-Alice and ack.

Is tx_wnd supposed to be zero here?

[talex5]

This looks suspicious:

https://github.com/mirage/mirage-tcpip/blob/master/tcp/segment.ml#L102

(* Determine the transmit window, from the last segment *)
let window q =
  try (S.max_elt q).window
  with Not_found -> 0

I think this means that if there are no segments ready to be read (q is empty) then we set the transmit window to zero, preventing us from sending any futher data. Could this happen if we get a retransmission? Anyone familiar with TCP who can confirm what's supposed to happen here?

[samoht]

Fixed by #146

[talex5]

Reopening because #146 only stopped the connection getting stuck after a retransmission, but doesn't explain why they're happening in the first place.

[talex5]

Here's a log from mirage-www, showing a client requesting the index twice, in parallel:

Initialising timer interface
Initialising console ... done.
gnttab_table mapped at 0000000020001000.
getenv(OCAMLRUNPARAM) -> null
getenv(CAMLRUNPARAM) -> null
getenv(PATH) -> null
Unsupported function lseek called in Mini-OS kernel
Unsupported function lseek called in Mini-OS kernel
Unsupported function lseek called in Mini-OS kernel
getenv(OCAMLRUNPARAM) -> null
getenv(CAMLRUNPARAM) -> null
getenv(TMPDIR) -> null
getenv(TEMP) -> null
Netif: add resume hook
getenv(DEBUG) -> null
getenv(OMD_DEBUG) -> null
getenv(OMD_FIX) -> null
Netif.connect 0
Netfront.create: id=0 domid=0
MAC: c0:ff:ee:c0:ff:ee
Attempt to open(/dev/urandom)!
Manager: connect
Manager: configuring
Manager: Interface to 10.0.0.2 nm 255.255.255.0 gw [10.0.0.1]
[...]
Tcp.PCB: process-syn: [channels=10 listens=0 connects=0]
Tcp.PCB: new-server-connection: [channels=10 listens=0 connects=0]
Tcp.State: Closed  - Passive_open -> Listen
Tcp.State: Listen  - Send_synack(452874759) -> Syn_rcvd(452874759)
Tcp.Segment: TCP transmit seq=452874759
Tcp.PCB: process-syn: [channels=10 listens=1 connects=0]
Tcp.PCB: new-server-connection: [channels=10 listens=1 connects=0]
Tcp.State: Closed  - Passive_open -> Listen
Tcp.State: Listen  - Send_synack(452886026) -> Syn_rcvd(452886026)
Tcp.Segment: TCP transmit seq=452886026
Tcp.PCB: process-ack: [channels=10 listens=2 connects=0]
Tcp.Segment: input
Tcp.State: Syn_rcvd(452874759)  - Recv_ack(452874760) -> Established
Tcp.Segment: input
Tcp.State: Established  - Recv_ack(452874760) -> Established
Tcp.PCB: process-ack: [channels=11 listens=1 connects=0]
Tcp.Segment: input
Tcp.State: Syn_rcvd(452886026)  - Recv_ack(452886027) -> Established
Tcp.Segment: input
Tcp.State: Established  - Recv_ack(452886027) -> Established
200 GET /
Tcp.Segment: TCP transmit seq=452874760
Tcp.Segment: TCP transmit seq=452874777
Tcp.Segment: TCP transmit seq=452874841
200 GET /
Tcp.Segment: TCP transmit seq=452886027
Tcp.Segment: TCP transmit seq=452886044
Tcp.Segment: TCP transmit seq=452886108
Tcp.Segment: TCP transmit seq=452876301
Tcp.Segment: TCP transmit seq=452877761
Tcp.Segment: TCP transmit seq=452878937
Tcp.Segment: TCP transmit seq=452887568
Tcp.Segment: TCP transmit seq=452889028
Tcp.Segment: TCP transmit seq=452890204
conn 11 closed
conn 12 closed
Tcp.Segment: input
Tcp.State: Established  - Recv_ack(452874777) -> Established
Tcp.Segment: input
Tcp.State: Established  - Recv_ack(452874841) -> Established
Tcp.Segment: input
Tcp.State: Established  - Recv_ack(452876301) -> Established
Tcp.Segment: input
Tcp.State: Established  - Recv_ack(452886027) -> Established
Tcp.Segment: TCP transmit seq=452880397
Tcp.Segment: TCP transmit seq=452881857
Tcp.Segment: TCP transmit seq=452891664
Tcp.Segment: input
Tcp.State: Established  - Recv_ack(452886044) -> Established
Tcp.Segment: input
Tcp.State: Established  - Recv_ack(452886108) -> Established
Tcp.Segment: input
Tcp.State: Established  - Recv_ack(452887568) -> Established
Tcp.Segment: input
Tcp.State: Established  - Recv_ack(452877761) -> Established
Tcp.Segment: input
Tcp.State: Established  - Recv_ack(452877761) -> Established
Tcp.Segment: input
Tcp.State: Established  - Recv_ack(452889028) -> Established
Tcp.Segment: input
Tcp.State: Established  - Recv_ack(452889028) -> Established
Tcp.Segment: input
Tcp.State: Established  - Recv_ack(452877761) -> Established
Tcp.Segment: input
Tcp.State: Established  - Recv_ack(452877761) -> Established
Tcp.Segment: input
Tcp.State: Established  - Recv_ack(452889028) -> Established
Tcp.Segment: TCP transmit seq=452893124
Tcp.Segment: TCP transmit seq=452894300
Tcp.Segment: TCP transmit seq=452883033
Tcp.Segment: TCP fast retransmission seq=452877761, dupack=452877761
Tcp.Segment: input
Tcp.State: Established  - Recv_ack(452889028) -> Established
Tcp.Segment: input
Tcp.State: Established  - Recv_ack(452889028) -> Established
Tcp.Segment: input
Tcp.State: Established  - Recv_ack(452877761) -> Established
Tcp.Segment: input
Tcp.State: Established  - Recv_ack(452883372) -> Established
Tcp.Segment: input
Tcp.State: Established  - Recv_ack(452883372) -> Established
Tcp.State: Established  - Recv_fin -> Close_wait
Tcp.Segment: PUSHING TIMER - new time=1.000000, new seq=452889028
Tcp.Segment: TCP retransmission on timer seq = 452889028
Tcp.Segment: PUSHING TIMER - new time = 2.000000, new seq = 452889028
Tcp.Segment: input
Tcp.State: Established  - Recv_ack(452894639) -> Established
Tcp.Segment: input
Tcp.State: Established  - Recv_ack(452894639) -> Established
Tcp.State: Established  - Recv_fin -> Close_wait
ARP: timeout 10.0.0.1

It looks like segment 452889028 gets retransmitted after being ack'd. In particular, we have:

Tcp.Segment: TCP transmit seq=452889028
Tcp.State: Established  - Recv_ack(452889028) -> Established
Tcp.State: Established  - Recv_ack(452889028) -> Established
Tcp.State: Established  - Recv_ack(452889028) -> Established
Tcp.State: Established  - Recv_ack(452889028) -> Established
Tcp.State: Established  - Recv_ack(452889028) -> Established
Tcp.Segment: PUSHING TIMER - new time=1.000000, new seq=452889028
Tcp.Segment: TCP retransmission on timer seq = 452889028
Tcp.Segment: PUSHING TIMER - new time = 2.000000, new seq = 452889028

Am I reading this right?

CTF trace is here: http://test.roscidus.com/static/transmit.ctf

Debug logging is on, and I included Mindy's no_urx_close_t branch.
I added a line to log seq when sending the first time (in Segment.Tx.output):

Log.f debug (fun fmt -> Log.pf fmt "TCP transmit seq=%a" Sequence.pp seq);

[MagnusS]

Not sure if this should be a separate issue, but there's always a duplicate ack sent after we close a connection. These examples are from the pcap's recorded from the tests:

$ tshark -nr tests/pcap/tcp_iperf_two_stacks_basic.pcap | tail -n 5
13710   1.694047   10.0.0.100 -> 10.0.0.101   TCP 54 5001 > 18442 [FIN, ACK] Seq=1 Ack=10000002 Win=262140 Len=0
13711   1.694124   10.0.0.101 -> 10.0.0.100   TCP 54 18442 > 5001 [ACK] Seq=10000002 Ack=2 Win=262140 Len=0
13712   1.694272   10.0.0.100 -> 10.0.0.101   TCP 54 [TCP Dup ACK 13710#1] 5001 > 18442 [ACK] Seq=2 Ack=10000002 Win=262140 Len=0
13713   1.694357   10.0.0.101 -> 10.0.0.100   TCP 54 [TCP Dup ACK 13711#1] 18442 > 5001 [ACK] Seq=10000002 Ack=2 Win=262140 Len=0
13714   1.694397   10.0.0.100 -> 10.0.0.101   TCP 54 5001 > 18442 [RST, ACK] Seq=2 Ack=10000002 Win=0 Len=0

$ tshark -nr tests/pcap/tcp_iperf_two_stacks_uniform_packet_loss.pcap|tail -n 5
13634  78.002340   10.0.0.100 -> 10.0.0.101   TCP 54 5001 > 19123 [FIN, ACK] Seq=1 Ack=10000002 Win=262140 Len=0
13635  78.002417   10.0.0.101 -> 10.0.0.100   TCP 54 19123 > 5001 [ACK] Seq=10000002 Ack=2 Win=262140 Len=0
13636  78.002566   10.0.0.100 -> 10.0.0.101   TCP 54 [TCP Dup ACK 13634#1] 5001 > 19123 [ACK] Seq=2 Ack=10000002 Win=262140 Len=0
13637  78.002652   10.0.0.101 -> 10.0.0.100   TCP 54 [TCP Dup ACK 13635#1] 19123 > 5001 [ACK] Seq=10000002 Ack=2 Win=262140 Len=0
13638  78.002698   10.0.0.100 -> 10.0.0.101   TCP 54 5001 > 19123 [RST, ACK] Seq=2 Ack=10000002 Win=0 Len=0

$ tshark -nr tests/pcap/tcp_connect_two_stacks_basic.pcap | tail -n 5
  8   0.102135   10.0.0.101 -> 10.0.0.100   TCP 91 [TCP segment of a reassembled PDU]
  9   0.102217   10.0.0.100 -> 10.0.0.101   TCP 54 80 > 15426 [ACK] Seq=1 Ack=38 Win=262140 Len=0
 10   0.102437   10.0.0.101 -> 10.0.0.100   TCP 54 15426 > 80 [FIN, ACK] Seq=38 Ack=1 Win=262140 Len=0
 11   0.102514   10.0.0.100 -> 10.0.0.101   TCP 54 80 > 15426 [ACK] Seq=1 Ack=39 Win=262140 Len=0
 12   0.102665   10.0.0.100 -> 10.0.0.101   TCP 54 [TCP Dup ACK 11#1] 80 > 15426 [ACK] Seq=1 Ack=39 Win=262140 Len=0

[talex5]

Here's a simple log from requesting the index page of mirage-www using curl, with debug on (including some extra debug in ack.ml):

ARP: sending gratuitous from 10.0.0.2
Manager: configuration done
Listening on http://localhost/
ARP responding to: who-has 10.0.0.2?
Tcp.PCB: process-syn: [channels=0 listens=0 connects=0]
Tcp.PCB: new-server-connection: [channels=0 listens=0 connects=0]
Tcp.State: Closed  - Passive_open -> Listen
Tcp.State: Listen  - Send_synack(452916572) -> Syn_rcvd(452916572)
Tcp.Wire: xmit checksum=d85a 10.0.0.2.80->192.168.0.11.39081 rst=false syn=true fin=false psh=false seq=452916572 ack=4282201965 options=[ MSS=1460
Window>> 2 ] datalen=0 datafrag=0 dataoff=7 olen=8
ARP: transmitting probe -> 10.0.0.1
ARP: updating 10.0.0.1 -> fe:ff:ff:ff:ff:ff
Tcp.PCB: Notify ACK: have sent 4282201965
Tcp.ACK: Immediate.transmit 4282201965
Tcp.PCB: process-ack: [channels=0 listens=1 connects=0]
Tcp.State: Syn_rcvd(452916572)  - Recv_ack(452916573) -> Established
Tcp.State: Established  - Recv_ack(452916573) -> Established
Tcp.ACK: Immediate.receive 4282202037
Tcp.ACK: Immediate.pushack 4282202037
[HTTP 1] 200 GET /
Tcp.Wire: xmit checksum=44f8 10.0.0.2.80->192.168.0.11.39081 rst=false syn=false fin=false psh=true seq=452916573 ack=4282202037 options=[] datalen=17 datafrag=1 dataoff=5 olen=0
Tcp.Wire: xmit checksum=5936 10.0.0.2.80->192.168.0.11.39081 rst=false syn=false fin=false psh=true seq=452916590 ack=4282202037 options=[] datalen=64 datafrag=1 dataoff=5 olen=0
Tcp.Wire: xmit checksum=1132 10.0.0.2.80->192.168.0.11.39081 rst=false syn=false fin=false psh=true seq=452916654 ack=4282202037 options=[] datalen=1460 datafrag=1 dataoff=5 olen=0
Tcp.ACK: Immediate.transmit 4282202037
Tcp.PCB: send_empty_ack: sending 4282202037 (mvar requested 4282202037)
Tcp.Wire: xmit checksum=fed1 10.0.0.2.80->192.168.0.11.39081 rst=false syn=false fin=false psh=false seq=452918114 ack=4282202037 options=[] datalen=0 datafrag=0 dataoff=5 olen=0
Tcp.PCB: Notify ACK: have sent 4282202037
Tcp.ACK: Immediate.transmit 4282202037
Tcp.PCB: Notify ACK: have sent 4282202037
Tcp.ACK: Immediate.transmit 4282202037
Tcp.PCB: Notify ACK: have sent 4282202037
Tcp.ACK: Immediate.transmit 4282202037

If I'm reading it right, then in this sequence we send a segment with ack=4282202037, notify the ACK system that we've sent it, and then immediately send an empty ACK packet with it again:

Tcp.Wire: xmit checksum=1132 10.0.0.2.80->192.168.0.11.39081 rst=false syn=false fin=false psh=true seq=452916654 ack=4282202037 options=[] datalen=1460 datafrag=1 dataoff=5 olen=0
Tcp.ACK: Immediate.transmit 4282202037
Tcp.PCB: send_empty_ack: sending 4282202037 (mvar requested 4282202037)
Tcp.Wire: xmit checksum=fed1 10.0.0.2.80->192.168.0.11.39081 rst=false syn=false fin=false psh=false seq=452918114 ack=4282202037 options=[] datalen=0 datafrag=0 dataoff=5 olen=0

Wireshark indeed reports a duplicate ACK here.

Can someone explain what's supposed to happen here?

[MagnusS]

@talex5 Hm, could this have been caused by packet loss + dup ack's to trigger fast retransmit and then the broken timer from #157?

[talex5]

Maybe, but I'm still suspicious about why the retransmissions are happening in the first place. The original traces were my Cubieboard sending data to my laptop, and I'd be very surprised if my laptop wasn't able to keep up with it and was dropping packets.

[MagnusS]

I created a separate issue for the dup ack's when closing a connection in #162 as it seems to be unrelated to the cubieboard-problem.

[talex5]

The retransmissions aren't causing any major problems now, but I'm still interested in understanding what causes them.

Here are some more traces. This is from a Unix process that just sends lots of TCP data in a loop (for the record, the code is in https://github.com/talex5/mirage-skeleton/tree/debug-retransmissions in the network directory):

http://test.roscidus.com/traces/2015-07-24/linux.pcap
http://test.roscidus.com/traces/2015-07-24/mirage-unix.pcap

mirage-unix.pcap is generated by this code, showing packets sent to and received from the network device (mirage-unix-net), which is a Linux tap device.

linux.pcap is the same test run, as recorded by tshark -i tap0 -w linux.pcap -b filesize:1024 -b files:3 on Linux, and taking the last file from the ring.

In mirage-unix.pcap, we record sending a segment with sequence number 631948077 early on (#938 in that trace), then we get some duplicate acks asking for it (but we don't retransmit), then we get a higher ack showing it had arrived.

In linux.pcap, the same segment appears after the acks (#579, as a TCP fast retransmission, with a "TCP Previous segment not captured" where it should have been).

So, it seems that the packets got reordered somewhere after Netif.write and before wireshark captured them at the other end of the tap device! I don't know whether this is Linux being strange, or if we're missing some locking when we do the writes. Wiggling the mouse during the run seems to trigger these effects fairly quickly.

[yomimono]

I'm closing this in favor of #314 ; feel free to reopen if you feel something here isn't reflected there.