ghaerr
[inet] telnetd seems to hang in a "TCP Retransmit" situation
I am testing network connectivity on my ELKS system. I can't get telnetd to run stable.
My setup: I have added one ISA slot to my NEC V25 setup and using it with a NE2000 compatible RTL8019AS NIC. Only had to add interrupt support to my board accordingly. No changes on the ne2k network drivers. NIC is in ne1k mode as my system only has an 8 bit bus. MTU size is set to 1000. The network seems to work.
The system boots from romfs which includes ktcp but no other apps from inet, as the filesystem is nearly full. Only minix fs support is included in the kernel, because the kernel otherwise exceeds 64k.
Error description:
- Login as root
- Mount a minix filesystem on SD-card using my hardware SPI interface.
- Starting ktcp from romfs and telnetd from the mounted minix SD-card filesystem manually.
- Start endless ping against the ELKS system from my desktop PC.
- Open a remote telnet session on my desktop PC and start ELKS basic on this session. Do an endless print in basic of an incrementing integer.
- After some random time the remote telnet session stops outputing the basic counter.
- The ping reply continues.
- On the ELKS system, netstat reproducable shows
TCP Retransmits 1 - Telnetd seems to disappeare in
telnet.c, tel_out()in(void) write(fdout, buf, len);
When the remote telnet session is terminated, telnetd on ELKS reappears from (void) write(fdout, buf, len); and a new remote session can be initiated. The basic app hangs and ELKS and can't be killed.
Any advise on how to get more insight on this?
Hello @swausd,
Thanks for the bug report. We've recently updated ktcp and telnetd in ELKS from @Mellvik's TLVC, but frankly I doubt that is a problem here. Perhaps @Mellvik can comment as to whether he's seen anything like this. We could try to roll back to the previous ELKS version of all the elkscmd/ktcp/ files, but I doubt that will help, and is a bit of effort since your V25 enhancements came afterwards.
Overall, to be quite honest, I'm not completely surprised by this behavior. With TCP/IP having been developed for ELKS outside the kernel 20 years ago, it's taken quite an effort over the last five years to get the entire system working well enough such that all the kernel semaphores, ktcp<->kernel data copying, and ktcp buffer overflow and mid-operation task switching works continuously without error. There have been some very subtle fixes incorporated to get the networking system to work well to this point.
Nonetheless, we need to figure out what is happening, and try to fix it. There's lots of debug options in ktcp/config.h which will display reams of data, but those take a bit of getting used to.
I would suggest starting by introducing a significant delay in the BASIC program so that output isn't continuous - and seeing what happens. I would bet this would help a lot, but eventually a hang will be seen.
Telnetd seems to disappeare in telnet.c, tel_out() in (void) write(fdout, buf, len);
This probably means that the telnetd application entered a semaphore in the /dev/tcpdev kernel driver, which queues data in both directions for ktcp, and was never awoken. This in turn is likely because ktcp didn't answer the request, was hung itself, or the kernel itself was deadlocked or hung in the /dev/tcpdev driver.
When the remote telnet session is terminated, telnetd on ELKS reappears from (void) write(fdout, buf, len); and a new remote session can be initiated.
That probably means that telnetd's accept returned with another connection, and then communications worked between telnetd, the kernel and ktcp for that new set of sockets.
The basic app hangs and ELKS and can't be killed.
Likely means that the BASIC app write, which is actually on a socket file descriptor, entered a semaphore as described above and then was never awoken. ELKS already has an outstanding issue #1356 relating to this problem. Due to the way that applications stacks are saved within the kernel, there currently isn't any easy way to "remove the task" with other kernel code without coding in somehow a way of forcing a call to do_exit() from within each semaphore. If we can locate the semaphore the app is hanging in, it may be worth coding an explicit call when a SIGKILL is sent... we can talk about that in #1356, after getting more information on exactly what is happening in this issue.
Thanks @ghaerr for the quick reply. I will see what I can get with the ktcp debug options tomorrow.
@swausd, could you instead of running basic, run the hd command on the largest file to be found, usually the disk (/dev/hda or whatever). If the problem is related to telnetd, which is possible (I recently took out a restart timer in telnetd because I could not reproduce the error it was supposed to fix), it should show when using the hd command.
-M
Hi @Mellvik, thanks for your reply!
Sorry, but I don't know an ELKS app hd...
To make things clear: I use telnetd server on ELKS and a remote client on my PC for an ELKS session.
@swausd
hd is the hex-dump program, useful for what it was made for, equally useful for testing serial lines - and telnet. It generates a lot of outgoing traffic, mostly small packets if used with telnet.
I'm suggesting it to get basic out of the way as a possible contributor to the problem you're experiencing.
Hi @ghaerr and @Mellvik ,
I can reproduce the situation with only using hd on a remote session (no continuous ping):
# /mnt/bin/netstat
----- Received --------- ----- Sent -------------
TCP Packets 5913 TCP Packets 5916
TCP Dropped 0 TCP Retransmits 1
TCP Bad Checksum 0 TCP Retrans Memory 0
IP Packets 5944 IP Packets 5917
IP Bad Checksum 0 IP Bad Headers 0
ICMP Packets 0 ICMP Packets 0
SLIP Packets 0 SLIP Packets 0
ETH Packets 8585 ETH Packets 5937
ARP Reqs Sent 1 ARP Replies Rcvd 1
ARP Reqs Rcvd 162 ARP Replies Sent 18
ARP Cache Adds 1
No State RTT lport raddress rport
-----------------------------------------------------
1 ESTABLISHED 62ms 1026 0.0.0.0 2
2 ESTABLISHED 2812ms 23 192.168.2.140 35902
3 LISTEN 62ms 23 0.0.0.0 0
It takes a little while, but finally, it stops too. Each time with TCP Retransmits 1.Very short packets seem to provoke the situation much quicker. With a little c program
int main (int argc, char **argv)
{
for (long i = 0; i < 1000000; i++)
{
printf("%ld\n",i);
if (argc > 1)
usleep(100);
}
return 0;
}
it only takes e few hundred packets. Next I try to catch what is happening on the wire.
PS: hd did run to the end and did not hang!
Hello @swausd and @Mellvik,
Thanks for the suggestions and testing. IMO, the problem here isn't anything to do with any application program, and likely cannot be fixed by and alarm() or other hack to telnetd. I also believe that what you find on the wire is correct, and possibly see an un-ACKed packet towards the end, or not. Telnetd itself is essentially just a fancy copying program, which after accepting a connection just copies data back and forth from a network socket file descriptor to a local file descriptor.
Lets to back to @swausd's original description - the telnetd hang is occurring in write - and the application (BASIC in this case) is also hung and can't be killed. From the additional testing results, my thoughts remain as posted in my first response. I still haven't heard whether BASIC, or the new small test program, can be slowed down, and the tests repeated. We already know that fast muliple back-to-back writes hang the system. I'm interested to know whether slower writes also cause the problem. I would guess it will, but will take longer.
My current theory for the issue seen is described above, but with the "slow" test and some possible wire-watching, I hope to discern whether the problem lies in the kernel /dev/tcpdev driver (drivers/char/tcpdev.c) or ktcp (elkscmd/ktcp/), or both.
A short description of what happens when an application writes to a network socket follows, which might help with inserting printk debug statements to find where the system is hanging. I am betting its in the tcpdev_read or tcpdev_write function in tcpdev.c:
- Application
writes to socket. writeis redirected to code in elks/net/ipv4/af_inet.c::inet_write(). This code uses globalrwlocksemaphore to access global /dev/tcpdev outgoing buffer. The tcpdev_inetwrite() function is called to signal data has been transferred, and the process possibly gets slept on the globalbufinsemaphore.tcpdev_inetwritewakes up any task sleeping on the globaltcpdevqwait queue. This will be ktcp, which might be waiting inselect, or might have been running and time-sliced out, but not inselect.- ktcp ends up in
selectagain, and is notified in elkscmd/ktcp/tcpdev.c::tcpdev_process() that a TDC_WRITE event has occurred (which contains some, but not always all, of the data from the applicationwritesystem call). - In this case, I believe that ktcp sends the data by forming an ETH packet, but might, under certain conditions, not send the data since the remote side receive window is full. I can't remember exactly how this is handled, but its complicated, since ktcp can't just "sleep" on an application's data like the kernel can, since it has to handle all application read/write requests simultaneously (and that's not actually simultaneously, since ktcp itself is being time-sliced and all data is coming in and out through the /dev/tcpdev driver, similar to above for reads).
- After a successful ETH packet send (but not TCP ACK), ktcp signals that the "application" write is complete, and sends /dev/tcpdev a response saying the buffer has been sent.
- The tcpdev.c::tcp_clear_data_avail() function is called, which increments the global
bufinsemaphore. This results in possibly waking up the sending application, which is still in net/ipv4/af_inet.c::inet_write(), to run. - The writing process in
inet_writewakes up (e.g. is rescheduled to run at some later point), and finds itself in a loop to send more data from the same applicationwritesystem call (or not). Therwlockglobal semaphore is released and regained throughout this write loop. - On return from inet_write, the original application (either telnetd or BASIC), is rescheduled to run, and it then immediately executes another
writesystem call.
Complicated as hell!!!
You will also see that there's various hacks, including the -ERESTARTSYS handling in inet_write(). The reason for this IIRC is that ktcp can't always write to the wire when asked, and since it doesn't have write buffers, returns -ERESTARTSYS all the way back up the chain, where inet_write sets a kernel timer for 100ms delays and then reschedules the writing task.
So besides the obvious ridiculous complexity, there are reasons for testing how fast application writes are performed, as well as all sorts of other potential locking issues or hidden bugs. I can explain in more detail after we get more information on what is happening. It may be that we can increase the 100ms delay to alleviate the issue from occurring, but I would guess the ultimate issue is that ktcp lost an ACK on the wire for various reasons, started a retransmit operation, and then due to complexity, the kernel synchronization between the application and ktcp got screwed up.
Hi @ghaerr and @Mellvik ,
here are some insights I got with wireshark:
- Used my desktop PC for the telnet client. My PC is a fast Ubuntu PC with 1GB NIC to a switch on which the ELKS system is connected, as is the uplink to my internet router.
- On ELKS ktcp and telned are active - nothing else.
- I installed wireshark on my desktop PC to watch the network traffic. Sadly I couldn't setup a hub for watching the whole traffic on the ELKS NIC, as I couldn't match the different NIC transmission speeds. So I could only watch the PC side and filtered out only traffic between PC 192.168.2.140 and ELKS 192.168.2.19. I will try to find a setup to see the whole traffic on the ELKS side.
- My count app with the sleep active was used for action. No test debugs where activated.
- The test setup counted until 8962. Everything was ok until then.
- Then the PC did not receive the packet containing the count value 8963 because it was lost or never send. Can't see that on the PC side. A lost packet is a totally normal situation on a TCP/IP network.
- The ELKS system sends the next packet containing 8964 that is the fist black line in picture 1.
- The PC acknowledges this with a TCP DUP ACK. My understanding is, that this is an ACK for the correct received packet combined with an retransmission request for the lost packet. See: https://stackoverflow.com/questions/48148820/what-is-duplicate-ack-when-does-it-occur.
- The ELSK TCP/IP Stack sees the ACK and ignores the retransmit request and sends the next packet. The PC again send a TCP DUP ACK. This continues with 100 repeats.
- Finaly after 100 TCP DUP ACK ELKS retransmitts the lost packet with the count value 8953. The PC sends a normal ACK. See picture 2.
- The ELKS system stops transmission here...
- ELKS is still working. Count app hangs. If I type into the telnet client on the PC, there is traffic to ELKS for this direction, see picture 3, but the count app is blocked.
PIC-1
PIC-2
PIC-3
PS: Don't know how to include a working url :-(
@swausd, thanks for your testing. I'm in Costa Rica with almost no internet and I can't seem to get your large pictures downloaded yet, but I'm working on it. (For some reason the browser is insisting on reloading each of the pictures, further slowing my internet. I may not be able to respond directly to this page as it is slowing down my throughput greatly).
From your initial results, it would seem that perhaps the issue is entirely within ktcp, and also potentially related to the DUP ACK code. I think that may be experimental code from TLVC (not sure yet), as I remember some diffs in that area when pulling it over.
The ELSK TCP/IP Stack sees the ACK and ignores the retransmit request and sends the next packet. The PC again send a TCP DUP ACK. This continues with 100 repeats.
It seems this step 9 is where the ktcp problem is. @Mellvik are you aware of exactly where this is in ktcp? I will need to refresh my memory a bit for this deep dive.
If the problem is only within ktcp, that's probably good news, as it means both that a solution likely can be found self-contained within ktcp, and that the kernel<->ktcp synchronization is not screwed up, although all processes waiting on semaphore completion, etc described above would still remain in an un-killable state.
@swausd, thanks for your testing. I'm in Costa Rica with almost no internet and I can't seem to get your large pictures downloaded yet, but I'm working on it. (For some reason the browser is insisting on reloading each of the pictures, further slowing my internet. I may not be able to respond directly to this page as it is slowing down my throughput greatly).
From your initial results, it would seem that perhaps the issue is entirely within ktcp, and also potentially related to the DUP ACK code. I think that may be experimental code from TLVC (not sure yet), as I remember some diffs in that area when pulling it over.
The ELSK TCP/IP Stack sees the ACK and ignores the retransmit request and sends the next packet. The PC again send a TCP DUP ACK. This continues with 100 repeats.
It seems this step 9 is where the ktcp problem is. @Mellvik are you aware of exactly where this is in ktcp? I will need to refresh my memory a bit for this deep dive.
If the problem is only within ktcp, that's probably good news, as it means both that a solution likely can be found self-contained within ktcp, and that the kernel<->ktcp synchronization is not screwed up, although all processes waiting on semaphore completion, etc described above would still remain in an un-killable state.
Great testing @swausd and similarly great (whew) run-through of the steps, @ghaerr. If you keep all or most of this in your head, I'm really envious!!
I agree with @ghaerr that this may be purely a ktcp problem. I also agree that if so, it's a blessing. It's (still) relatively fresh stuff. I'm getting the pictures fine and they're very useful - although I have to add that I find tcpdump a lot easier to decipher - and it's text only and probably installed on your system.
A couple of observations:
- I've never before studied a situation in which one side is Gigabit Ethernet and the other 10Mbps Ethernet. The speed difference is just staggering, and packet loss would be expected. However, not packet loss from the slow side. It may seem the packet never made it to the wire, while
ktcpcertainly seems to think it did. This makes the NIC driver a possible suspect. Is there a race condition or other condition in the driver that kicks in when packets arrive back-to-back in continuous bursts? - Regardless of the above, and as @ghaerr points out, item 9 in your list is the big clue here. Why doesn't
ktcpretransmit the the other end keeps acking an 'old' seq number ? I have seen this before, but that's a long time ago. Assuming you're running the latest ELKSktcpversion I should be able to repeat it.
Thinking more about it, this may even be a tuning issue. The scenario with the peer requesting a retransmit (specifically repeatingly acking the previous packet or the packet before that, is a continuous problem when slow systems are talking. Like ELKS-to-ELKS or TLVC-to-TLVC. If one system is just marginally faster than the other, it gets impatient and re-acks before checking its own in-buffer. If the sender were to retransmit every time this happens, the transmission speed would grind to almost a halt. An interesting problem - that I spent a lot of time trying to solve last year. You may have found a case that breaks my solution. Or maybe I forgot to look for repeated occurrences of the retransmit request.
If so this is a problem to be fixed regardless. That said, finding out why the packet never gets on the wire, is interesting. You may have to test a new version of the driver to find out.
I may decide send you a tcpdump command line to run to capture a different picture of what's really on the net. Never a dull moment.
(The internet guys arrived at the vaca house, and with any luck I have fast internet again. Yay!)
item 9 in your list is the big clue here.
Yes - I would like your thoughts @Mellvik as to where this "DUP ACK" situation(s) is/are handled in the ktcp source, if you know, as that'll save some time.
Why doesn't ktcp retransmit the the other end keeps acking an 'old' seq number ? I
The PC acknowledges this with a TCP DUP ACK.
The ELSK TCP/IP Stack sees the ACK and ignores the retransmit request and sends the next packet. The PC again send a TCP DUP ACK. This continues with 100 repeats.
I recall having seen this problem from the first days I started fixing ktcp, so I will venture we still haven't fully solved it. I think that the problem starts with a DUP ACK sent to ELKS, whcih then as @swausd says is seen, ignored, and the packet retransmitted. Of course, there's something terribly wrong with the ktcp logic in that it does this 100 times. We'll want to fix that first, before worrying about the ultimate hang after 100 repeats. That's because the 100 repeats could be causing other problems, stack overflows, allocation issues, who knows.
This makes the NIC driver a possible suspect. Is there a race condition or other condition in the driver that kicks in when packets arrive back-to-back in continuous bursts?
@Mellvik, I would think ktcp should be able to handle this without a NIC driver change. If you think this is driver or network speed related, perhaps ktcp should delay a bit when seeing the first DUP ACK and before the first retransmit, set a timer, then only act if there's nothing else in the input queue (for instance).
Any help in determine where we might be in the ktcp code when this happens would be appreciated. @swausd, perhaps you can turn on ktcp config.h debug statements to further display where we are when the first ACK/retransmit is seen. We're going to nail this finally!! :)
@Mellvik I use the most current version of ELKS. Different speeds between client and server should not be the problem, as this should be handled by the switch - or am I missing something here?
@ghaerr there are no 100 retranmitts. There are 100 request for retranmission (ACK DUPs) where ELKS seems to ignore and just keeps on transmitting as if no packet got lost. May be there is a queue with 100 packets „in flight“ in ktcp? But after 100 ACK DUPs it retranmitts the one long lost packet and stops. Did not check if this is allways 100. This would be interesting to know.
There are 100 request for retranmission (ACK DUPs) where ELKS seems to ignore and just keeps on transmitting as if no packet got lost.
I see - so you're seeing the receipt of 100 ACK DUPS whilst ELKS is continuing to (slowly) transmit more data, obliviously.
This means that perhaps ktcp needs to check its receive buffer and delay received write data (as described above using 100ms -ERESTARTSYS returns) if an ACK has been received, rather than just slowly sending whatever it happens to receive. The actual kernel scheduling of the tasks means that ktcp would have to specially handle this, since the writing application could get scheduled more often than ktcp can handle the write data.
May be there is a queue with 100 packets „in flight“ in ktcp?
No - in our small systems world, there just isn't any data segment room to store much data. There are no outgoing queues at all in ktcp (and only optionally two buffers in the NIC, but they're disabled and of no concern here). There is a ktcp recieved-data queue on a per-connection basis, but that's also of little to no concern here.
But after 100 ACK DUPs it retranmitts the one long lost packet and stops
It would be interesting to know whether your desktop system gave up after sending 100 ACKs, or whether ktcp does something different at 100.
Inside ktcp, each received tcpdev "write" (described above in my long post) is sent separately, without queuing, and without assembling into a longer packet, to the NIC. Each thus-described "data packet" is also saved in a retransmit queue (whcih can quickly run out of space inside ktcp's limited 32k heap) and resent if necessary. So I don't quite understand "it retransmits one long lost packet" - ktcp won't assemble data. I would like to learn both whether this final packet is in fact different than all the others (as well as its SEQNO) as well as whether this problem occurs at count 100 all the time.
Thank you!
Different speeds between client and server should not be the problem, as this should be handled by the switch - or am I missing something here?
I think what @Mellvik is talking about here is that in your case, the host system can send data at blazing speeds, while the ELKS system is sending and responding much more slowly. That, combined with some of my comments in my last post, could result in the ELKS ktcp still sending slowly while having DUP ACKS piling up in its input queue, not checked frequently enough.
@Mellvik I use the most current version of ELKS. Different speeds between client and server should not be the problem, as this should be handled by the switch - or am I missing something here?
Keep in mind that a switch is just that, it doesn't really fix anything and certainly does no flow control (although intelligent switches really try to be helpful in many ways). If packets come in at a higher rate than they can be passed on, they're discarded.
@ghaerr there are no 100 retranmitts. There are 100 request for retranmission (ACK DUPs) where ELKS seems to ignore and just keeps on transmitting as if no packet got lost. May be there is a queue with 100 packets „in flight“ in ktcp? But after 100 ACK DUPs it retranmitts the one long lost packet and stops. Did not check if this is allways 100. This would be interesting to know.
This is the interesting part. Most of these are likely never seen by ELKS(ktcp), but don't turn on any debugging on the ELKS side, that will only change the situation for the worse. What would be useful (this is how I'm debugging setting like this) is to mirror the Elks Port of the switch to a different port and monitor that with tcpdump (or wireshark). That way you can see exactly what ELKS is seeing -and sending.
That way you can see exactly what ELKS is seeing -and sending.
Let me add an important point to this observation, one that has bitten me more often than I care to remember: What ELKS sees may not be what ktcp sees - in terms of sequence. That's why we get situations like I described above: ktcp may be retransmitting a packet that has already been acked by the other end, the ack still sitting in the NIC's input buffer or even in ktcp's inbuffer.
I'll take a shot at recreating the problem later today. To help narrow down the options, follow @ghaerr's suggestion to slow down output from your test program, @swausd .
To see the traffic on the ELSK NIC, I connected my desktop PC NIC directly to the ELKS NIC, as I don‘t have managed switches and no 10base hubs anymore. With this setup, I don‘t get the error described above! I think that has to do with the now missing, disturbing network traffic (lots of broadcasts from the router and home automation systems in my network).
I will see, if I can get a managed switch to mirror the ELKS NIC for a complete logging. Until then I will look into the network source code, to see which debug statements might help. And to look at a wireshark hint to malformed tcp messages (4 bytes extra at the end of some telegrams).
This is good, @swausd - and you're probably right. There is a lot of broadcast traffic on even the smallest of segments these days. I'm seeing STP, the Spanning Tree Protocol and LLDP, the Low Level Discovery Protocol in particular.
Essentially, what you're reporting is that reducing (actually eliminating) the broadcast traffic eliminates the problem. From previous reports, we know that while there is more than one problem in the picture, the trigger seems to be a missing packet from ELKS. One that ELKS (really ktcp) thinks has been sent but never made it to the wire. If this is indeed what happens, there must be a driver level problem. Now that we know exactly how the problem can be recreated, it is easy to find out whether the new driver version also fails and whether using NIC level buffers affects the situation.
The secondary problem is that ktcp does not handle the situation as it should. That needs to be investigated. I'm going to create an open issue on TLVC for that.
BTW - I've found the Ubiquiti USW Flex Mini - a 5 port switch at about $30 - to be very helpful to track down what's really on the wire. It has the monitor capability: Any port can be set up to monitor any one of the other ports. Then I connect the monitor-port to the (Linux) machine via an USB-Ethernet dongle and connect tcpdump to that new interface, which needs to have ARP turned off.
Thank you, @Mellvik, for the input. I will try a TP-Link switch, because all other components are from them.
My direct telnet connection with the counting app is running for hours now…
Hi @ghaerr , @Mellvik ,
I looked a little bit deeper into the ktcp code base and tried to understand the flow of incoming data. As I understand the situation, the TCP DUP ACK is issued by the receiver if out of sequence tcp packets are received. The receiver then acknowledges the reception of the last in sequence packet with an ACK and the acknowledge-number of the last in sequence packet. The receiver then has the chance to retransmit the missing packet without waiting for the retransmit timeout. ktcp doesn't seem to be prepared for this - or I didn't find it in the source code....
I put a print statement into tcp.c tcp_established() at line 316 to verify this:
if (datasize == 0 && ((h->flags & TF_ALL) == TF_ACK))
{
printf("tcp: ACK seq %lx\n", ntohl(h->acknum)); <-- added this
return; /* ACK with no data received - so don't answer*/
}
The output corresponds to wireshark. By the way, there are always 100 TCP DUP ACKs or about 10 seconds before ELKS retransmits the missing packet and stops.
I can't reproduce this error if my ELKS system is directly connected to my PC.
This is enough for today.
Hello @swausd,
Just a few questions to ensure I'm fully following this potential DUP ACK problem:
The receiver then has the chance to retransmit the missing packet without waiting for the retransmit timeout.
Don't you mean "The sender then has the chance to retransmit ..." here? The failing case is when ELKS is transmitting to the host here, right?
What is your testing showing, does the "tcp: ACK seq" message appear directly before when ktcp gets screwed up?
If so, then we might be able to set a flag here so when the following code in the ktcp.c main loop is executed, it also resets the retransmit timer(s) on any outstanding packets when tcp_retrans_retransmit() is called:
/* check for retransmit packets required*/
if (tcp_timeruse > 0)
tcp_retrans_retransmit();
What do you think @Mellvik? It appears ktcp currently does not handle the TCP duplicate acknowledgement Fast Retransmit case.
We might also need this same flag to somehow signal any further application write calls to be returned using -ERESTARTSYS while the retransmit queue is not empty for this socket. That would force the retransmit queue to empty before allowing more packets to be sent down the wire. (We might always want to do delay sending when the retransmit queue is non-empty, now that I think about it).
Hi @ghaerr ,
Don't you mean "The sender then has the chance to retransmit ..." here?
Yes, that's right. The sender of the missing packet (who is the receiver of the DUP ACK) has the chance...
What is your testing showing, does the "tcp: ACK seq" message appear directly before when ktcp gets screwed up?
My second picture above shows this situation - it always looks like this. First there are 100 DUP ACKd with ELKS continuing to send new packets, after the 100. DUP ACK my ELKS system sends a retransmit of the missing packet, then my PC sends ACK seq=77. After this there is no traffic for this telnet session from ELKS to PC and the counter app seems to hangs. The telnet channel PC to ELKS is still working, that is, packets are send from the PC to ELKS and ACKed by ELKS for each key press. But Ctrl-C shows no reaction.
PS: Between the last DUP ACK and the retransmit are aprox. 5 seconds.
@swausd Thanks for your debugging! It would seem you have accurately identified the problem, as well as the fact that ktcp ignores ACKs received without data (which I'm now learning are used as part of the missing TCP fast retransmit algorithm).
I would also venture to guess that your host system tries 100 times with its fast retransmit ACK sending, then gives up. I don't understand why ktcp's (eventual) retransmit(s) of in it's retransmit queue don't solve the problem automatically, however. In other words, adding fast transmit and/or delaying further writes should help, but something still seems amiss with ktcp retransmit?
I haven't had time to study your TCP logs, is ktcp sending a retransmit with the correct sequence number? If so, is that ignored (or possibly not seen) by the host?
after the 100. DUP ACK my ELKS system sends a retransmit of the missing packet, then my PC sends ACK seq=77.
I am assuming that the (first) ELKS packet sent from the retransmit queue is seqno 77 and the host ACKS that with 77 correctly.
The next question is whether there are more retransmit packets in the ktcp queue, in which case why are they not being sent? If not, then it seems the tcpdev or af_net kernel may be prohibited from a semaphore from sending more write data to ktcp, to continue sending the application data.
Could it be that ktcp held the application from further writes during the wait for a proper ACK, but after the retransmit was sent (and ACKed) the application is not being released from its sleeping state? This would explain the behavior seen. IIRC, the 'application sleep" for writing is effected only by returning -ERESTARTSYS, for which kernel code then sets a 100ms timer and calls schedule(). The application should be awoken every 100ms and the write retried, unless the sleep is in another area of the kernel in this instance. (That is, not being slept on write, but sleeping for another reason).
Hi @ghaerr ,
What I don't understand is, why exactly 100 ACK DUPs?
One packet is missing, so the PC ACKs the following packets with ACK DUP, which ELKS takes as normal ACKs (it does not ignore them!). But after 100 packets send and ACKed with ACK DUPs, ELKS stops and doesn't send any packets for 5 seconds. Then ELKS retransmits the missing packet, which the PC ACKs normaly. And then transmission stops completely. Why pausing 5 second and then stop?
is ktcp sending a retransmit with the correct sequence number? If so, is that ignored (or possibly not seen) by the host?
For me the retransmit looks OK and the PC reacts as expected: When the one packet is missing, the telnet session on the PC side pauses until the missing packet is retransmitted and received. Then suddenly the content of the missing packet and the content from the 100 packets acked with ACK DUP are shown in correct sequence. So for me it looks like the ELKS system has stopped to transmit any further.
I am not allowed to add a wireshark capture file as attachment here. If you have an idea how to pass it along to you ... it is about 200 KB in size.
Sorry for me pausing the last hour. Had to have coffee and cake with my wife ;-)
Hi @ghaerr,
The next question is whether there are more retransmit packets in the ktcp queue,
The wireshark capture doesn't show any other missing packets.
Hi @ghaerr
during the wait for a proper ACK
As I understand ACK DUP: It is a proper ACK and I think ELSK sees it as such. ELKS ignores the DUP bonus information encoded in the repeating acknum.