Re: [lwip-users] lwIP 1.4.1 stable tcp connection stall

[Bill Auerbach]

address@hidden writes:

Maybe. As a starter, you should disable everything you can in tcp_output (TCP_OUTPUT_DEBUG, TCP_CWND_DEBUG). Then once the error happens, try dumping the lwip_stats plus the whole tcp_pcb that doesn't send any more. There's no function to do that, so you'll have to write that on your own. I mean every member of the tcp_pcb plus all "interesting" members of lists like unsent, unacked etc.

 

Below is debug output for TCP up until it fails (minus a lot more ahead of that that was OK).  The last 4 lines repeat forever. Our application disconnects and reconnects after 5 seconds of no response which unfortunately has kept customers at bay because the system does recover on its own.  We make commercial ink jet printers so if the customer is printing it’s bad – even worse with a 500 lb paper roll.  The only good thing is only one customer is seeing disconnects hourly or more.  I get them in less than 5 minutes which is great for testing.

 

tcp_receive: pcb->rttest 467 rtseq 44078 ackno 44410                                                 

tcp_receive: experienced rtt 1 ticks (500 msec).                                                     

tcp_receive: RTO 4 (2000 milliseconds)                                                               

tcp_output: nothing to send (0x00000000)                                                              

tcp_output: snd_wnd 63244, cwnd 23364, wnd 23364, seg == NULL, ack 44410                             

tcp_slowtmr: processing active pcb                                                                   

tcp_slowtmr: polling application                                                                     

tcp_output: nothing to send (0x00000000)                                                             

tcp_output: snd_wnd 63244, cwnd 23364, wnd 23364, seg == NULL, ack 44410                             

tcp_write(pcb=0x008449f8, data="" len=332, apiflags=0)                                      

tcp_write: queuelen: 0                                                                               

tcp_write: queueing 44410:44742                                                                      

tcp_write: 2 (after enqueued)                                                                        

tcp_output: snd_wnd 63244, cwnd 23364, wnd 23364, effwnd 332, seq 44410, ack 44410                   

tcp_output: snd_wnd 63244, cwnd 23364, wnd 23364, effwnd 332, seq 44410, ack 44410, i 0              

tcp_output_segment: rtseq 44410                                                                      

tcp_output_segment: 44410:44742                                                                      

tcp_output: nothing to send (0x00000000)                                                             

tcp_output: snd_wnd 63244, cwnd 23364, wnd 23364, seg == NULL, ack 44410                             

tcp_slowtmr: processing active pcb                                                                   

tcp_slowtmr: polling application                                                                     

tcp_output: nothing to send (0x00000000)                                                             

tcp_output: snd_wnd 63244, cwnd 23364, wnd 23364, seg == NULL, ack 44410                             

tcp_receive: window update 62912                                                                      

tcp_receive: congestion avoidance cwnd 23455                                                         

tcp_receive: queuelen 2 ... 0 (after freeing unacked)                                                 

tcp_receive: pcb->rttest 469 rtseq 44410 ackno 44742                                                 

tcp_receive: experienced rtt 1 ticks (500 msec).                                                     

tcp_receive: RTO 4 (2000 milliseconds)                                                                

tcp_output: nothing to send (0x00000000)                                                             

tcp_output: snd_wnd 62912, cwnd 23455, wnd 23455, seg == NULL, ack 44742                              

tcp_slowtmr: processing active pcb                                                                   

tcp_slowtmr: polling application                                                                     

tcp_output: nothing to send (0x00000000)                                                              

tcp_output: snd_wnd 62912, cwnd 23455, wnd 23455, seg == NULL, ack 44742                             

tcp_write(pcb=0x008449f8, data="" len=332, apiflags=0)                                       

tcp_write: queuelen: 0                                                                               

tcp_write: queueing 44742:45074                                                                      

tcp_write: 2 (after enqueued)                                                                         

tcp_output: snd_wnd 62912, cwnd 23455, wnd 23455, effwnd 332, seq 44742, ack 44742                   

tcp_output: snd_wnd 62912, cwnd 23455, wnd 23455, effwnd 332, seq 44742, ack 44742, i 0               

tcp_output_segment: rtseq 44742                                                                      

tcp_output_segment: 44742:45074                                                                      

tcp_output: nothing to send (0x00000000)                                                             

tcp_output: snd_wnd 62912, cwnd 23455, wnd 23455, seg == NULL, ack 44742                             

tcp_slowtmr: processing active pcb                                                                    

tcp_slowtmr: polling application                                                                     

tcp_output: nothing to send (0x00000000)                                                             

tcp_output: snd_wnd 62912, cwnd 23455, wnd 23455, seg == NULL, ack 44742                             

tcp_receive: window update 64240                                                                     

tcp_receive: congestion avoidance cwnd 23545                                                         

tcp_receive: queuelen 2 ... 0 (after freeing unacked)                                                

tcp_receive: pcb->rttest 471 rtseq 44742 ackno 45074                                                 

tcp_receive: experienced rtt 1 ticks (500 msec).                                                     

tcp_receive: RTO 4 (2000 milliseconds)                                                                

tcp_output: nothing to send (0x00000000)                                                             

tcp_output: snd_wnd 64240, cwnd 23545, wnd 23545, seg == NULL, ack 45074                             

tcp_slowtmr: processing active pcb                                                                    

tcp_slowtmr: polling application                                                                     

tcp_output: nothing to send (0x00000000)                                                              

tcp_output: snd_wnd 64240, cwnd 23545, wnd 23545, seg == NULL, ack 45074                             

tcp_write(pcb=0x008449f8, data="" len=332, apiflags=0)                                      

tcp_write: queuelen: 0                                                                                

tcp_write: queueing 45074:45406                                                                      

tcp_write: 2 (after enqueued)                                                                         

tcp_output: snd_wnd 64240, cwnd 23545, wnd 23545, effwnd 332, seq 45074, ack 45074                   

tcp_output: snd_wnd 64240, cwnd 23545, wnd 23545, effwnd 332, seq 45074, ack 45074, i 0              

tcp_output_segment: rtseq 45074                                                                       

tcp_output_segment: 45074:45406                                                                      

tcp_output: nothing to send (0x00000000)                                                              

tcp_output: snd_wnd 64240, cwnd 23545, wnd 23545, seg == NULL, ack 45074                             

tcp_slowtmr: processing active pcb                                                                   

tcp_slowtmr: polling application                                                                      

tcp_output: nothing to send (0x00000000)                                                             

tcp_output: snd_wnd 64240, cwnd 23545, wnd 23545, seg == NULL, ack 45074                              

tcp_receive: window update 63908                                                                     

tcp_receive: congestion avoidance cwnd 23635                                                         

tcp_receive: queuelen 2 ... 0 (after freeing unacked)                                                

tcp_receive: pcb->rttest 473 rtseq 45074 ackno 45406                                                 

tcp_receive: experienced rtt 1 ticks (500 msec).                                                     

tcp_receive: RTO 4 (2000 milliseconds)                                                               

tcp_output: nothing to send (0x00000000)                                                              

tcp_output: snd_wnd 63908, cwnd 23635, wnd 23635, seg == NULL, ack 45406                             

tcp_slowtmr: processing active pcb                                                                    

tcp_slowtmr: polling application                                                                     

tcp_output: nothing to send (0x00000000)                                                             

tcp_output: snd_wnd 63908, cwnd 23635, wnd 23635, seg == NULL, ack 45406                             

tcp_write(pcb=0x008449f8, data="" len=332, apiflags=0)                                      

tcp_write: queuelen: 0                                                                                

tcp_write: queueing 45406:45738                                                                      

tcp_write: 2 (after enqueued)                                                                        

tcp_output: snd_wnd 63908, cwnd 23635, wnd 23635, effwnd 332, seq 45406, ack 45406                   

tcp_output: snd_wnd 63908, cwnd 23635, wnd 23635, effwnd 332, seq 45406, ack 45406, i 0              

tcp_output_segment: rtseq 45406                                                                       

tcp_output_segment: 45406:45738                                                                      

tcp_output: nothing to send (0x00000000)                                                             

tcp_output: snd_wnd 63908, cwnd 23635, wnd 23635, seg == NULL, ack 45406                             

tcp_slowtmr: processing active pcb                                                                   

tcp_slowtmr: polling application                                                                      

tcp_output: nothing to send (0x00000000)                                                             

tcp_output: snd_wnd 63908, cwnd 23635, wnd 23635, seg == NULL, ack 45406                             

tcp_receive: window update 63576                                                                      

tcp_receive: congestion avoidance cwnd 23725                                                         

tcp_receive: queuelen 2 ... 0 (after freeing unacked)                                                 

tcp_receive: pcb->rttest 475 rtseq 45406 ackno 45738                                                 

tcp_receive: experienced rtt 1 ticks (500 msec).                                                     

tcp_receive: RTO 4 (2000 milliseconds)                                                               

tcp_output: nothing to send (0x00000000)                                                             

tcp_output: snd_wnd 63576, cwnd 23725, wnd 23725, seg == NULL, ack 45738                             

tcp_slowtmr: processing active pcb                                                                   

tcp_slowtmr: polling application                                                                      

tcp_output: nothing to send (0x00000000)                                                             

tcp_output: snd_wnd 63576, cwnd 23725, wnd 23725, seg == NULL, ack 45738                              

tcp_write(pcb=0x008449f8, data="" len=332, apiflags=0)                                      

tcp_write: queuelen: 0                                                                               

tcp_write: queueing 45738:46070                                                                       

tcp_write: 2 (after enqueued)                                                                        

tcp_output: snd_wnd 63576, cwnd 23725, wnd 23725, effwnd 332, seq 45738, ack 45738                    

tcp_output: snd_wnd 63576, cwnd 23725, wnd 23725, effwnd 332, seq 45738, ack 45738, i 0              

tcp_output_segment: rtseq 45738                                                                      

tcp_output_segment: 45738:46070                                                                       

tcp_output: nothing to send (0x00000000)                                                             

tcp_output: snd_wnd 63576, cwnd 23725, wnd 23725, seg == NULL, ack 45738                              

tcp_slowtmr: processing active pcb                                                                   

tcp_slowtmr: polling application                                                                     

tcp_output: nothing to send (0x00000000)                                                              

tcp_output: snd_wnd 63576, cwnd 23725, wnd 23725, seg == NULL, ack 45738                             

tcp_receive: window update 63244                                                                      

tcp_receive: congestion avoidance cwnd 23814                                                         

tcp_receive: queuelen 2 ... 0 (after freeing unacked)                                                

tcp_receive: pcb->rttest 477 rtseq 45738 ackno 46070                                                 

tcp_receive: experienced rtt 1 ticks (500 msec).                                                     

tcp_receive: RTO 4 (2000 milliseconds)                                                                

tcp_output: nothing to send (0x00000000)                                                             

tcp_output: snd_wnd 63244, cwnd 23814, wnd 23814, seg == NULL, ack 46070                             

tcp_slowtmr: processing active pcb                                                                    

tcp_slowtmr: polling application                                                                     

tcp_output: nothing to send (0x00000000)                                                             

tcp_output: snd_wnd 63244, cwnd 23814, wnd 23814, seg == NULL, ack 46070                             

tcp_write(pcb=0x008449f8, data="" len=332, apiflags=0)                                      

tcp_write: queuelen: 0                                                                               

tcp_write: queueing 46070:46402                                                                       

tcp_write: 2 (after enqueued)                                                                        

tcp_output: snd_wnd 63244, cwnd 23814, wnd 23814, effwnd 332, seq 46070, ack 46070                   

tcp_output: snd_wnd 63244, cwnd 23814, wnd 23814, effwnd 332, seq 46070, ack 46070, i 0              

tcp_output_segment: rtseq 46070                                                                      

tcp_output_segment: 46070:46402                                                                       

tcp_output: nothing to send (0x00000000)                                                             

tcp_output: snd_wnd 63244, cwnd 23814, wnd 23814, seg == NULL, ack 46070                             

tcp_slowtmr: processing active pcb                                                                    

tcp_slowtmr: polling application                                                                     

tcp_output: nothing to send (0x00000000)                                                              

tcp_output: snd_wnd 63244, cwnd 23814, wnd 23814, seg == NULL, ack 46070                             

tcp_slowtmr: processing active pcb                                                                   

tcp_slowtmr: polling application                                                                      

tcp_output: nothing to send (0x00000000)                                                             

tcp_output: snd_wnd 63244, cwnd 23814, wnd 23814, seg == NULL, ack 46070                              

tcp_write(pcb=0x008449f8, data="" len=332, apiflags=0)                                      

tcp_write: queuelen: 2                                                                               

tcp_write: queueing 46402:46734                                                                       

tcp_write: 4 (after enqueued)                                                                        

tcp_output: snd_wnd 63244, cwnd 23814, wnd 23814, effwnd 664, seq 46402, ack 46070                    

tcp_output: snd_wnd 63244, cwnd 23814, wnd 23814, effwnd 664, seq 46402, ack 46070, i 0              

tcp_output_segment: 46402:46734                                                                      

tcp_output: nothing to send (0x00000000)                                                             

tcp_output: snd_wnd 63244, cwnd 23814, wnd 23814, seg == NULL, ack 46070                             

tcp_slowtmr: processing active pcb                                                                   

tcp_slowtmr: polling application                                                                     

tcp_output: nothing to send (0x00000000)                                                              

tcp_output: snd_wnd 63244, cwnd 23814, wnd 23814, seg == NULL, ack 46070                             

tcp_slowtmr: processing active pcb                                                                    

tcp_slowtmr: rtime 4 pcb->rto 4                                                                      

tcp_slowtmr: cwnd 1460 ssthresh 11907                                                                

tcp_output: snd_wnd 63244, cwnd 1460, wnd 1460, effwnd 332, seq 46070, ack 46070                     

tcp_output: snd_wnd 63244, cwnd 1460, wnd 1460, effwnd 332, seq 46070, ack 46070, i 0                

tcp_output_segment: rtseq 46070                                                                       

tcp_output_segment: 46070:46402                                                                      

tcp_output: snd_wnd 63244, cwnd 1460, wnd 1460, effwnd 664, seq 46402, ack 46070, i 1                

tcp_output_segment: 46402:46734                                                                       

tcp_slowtmr: polling application                                                                     

tcp_output: nothing to send (0x00000000)                                                              

tcp_output: snd_wnd 63244, cwnd 1460, wnd 1460, seg == NULL, ack 46070                               

tcp_write(pcb=0x008449f8, data="" len=332, apiflags=0)                                      

tcp_write: queuelen: 4                                                                                

tcp_write: queueing 46734:47066                                                                      

tcp_write: 6 (after enqueued)                                                                         

tcp_output: snd_wnd 63244, cwnd 1460, wnd 1460, effwnd 996, seq 46734, ack 46070                     

tcp_output: snd_wnd 63244, cwnd 1460, wnd 1460, effwnd 996, seq 46734, ack 46070, i 0                

tcp_output_segment: 46734:47066                                                                       

tcp_output: nothing to send (0x00000000)                                                             

tcp_output: snd_wnd 63244, cwnd 1460, wnd 1460, seg == NULL, ack 46070                                

tcp_slowtmr: processing active pcb                                                                   

tcp_slowtmr: polling application                                                                     

tcp_output: nothing to send (0x00000000)                                                             

tcp_output: snd_wnd 63244, cwnd 1460, wnd 1460, seg == NULL, ack 46070                               

tcp_slowtmr: processing active pcb                                                                   

tcp_slowtmr: polling application                                                                     

tcp_output: nothing to send (0x00000000)                                                              

tcp_output: snd_wnd 63244, cwnd 1460, wnd 1460, seg == NULL, ack 46070                               

Oh, and do you have TCP_OVERSIZE enabled? I recall the early versions having bugs, although I'm not sure they could result in the behaviour you're seeing...

Yes!

#define TCP_OVERSIZE                    TCP_MSS

#define TCP_MSS                         (1460)

 

I’ll set it to 0 and test again.

I can understand that! The step from 1.4.1 to 2.0.x is a large one. On the other hand, 2.0.2 really has many bugs fixed, so it'll definitively be the more stable version. But release tests are always required, of course.

 

The step is huge but *all good* - we will be moving to 2.0.2.  I’ve kept up on and off with the updates and changes.  I wanted to update but I hung on to the “it ain’t broke” philosophy, especially going from one product to 9.  It’s hard to update because all customers are in production. It’s very hard to test in-house real-world. So we have to roll out slowly to “tolerant” customers.

 

Thanks Simon,

Bill