Re: [lwip-users] out of memory -> some packet transmittion skipped (TCP Previous segment lost)?

[Domen Puncer]

On 18/12/09 16:02 +0100, address@hidden wrote:
> If you want someone to actually analyze the wireshark log, you might  
> want to attach a pcap file instead of pasting the text (which is not  
> really readable).
> :-)

OK, I'll keep that in mind for the next time.

Turns out bug was in the lpc emac driver code. It handled the case where
frame length is divisible by frame fragment length in a wrong way, so
the driver didn't send it (and neither did it send the resends that lwip
kept trying to send).

This was was hard to crack.

It was actually exactly was Bill was trying to tell me, except I didn't
get that driver could drop retransmittions too :-(

Thank you Bill, and others!


        Domen

>
> Simon
>
>
> Domen Puncer wrote:
>> Hello!
>>
>> I'm using rawapi, NO_SYS, all lwip functions are called from the same
>> thread.
>> My setup is: lwip device which is a "telnet server", that's dumping some
>> data to PC, when connected.
>> It appears that under memory pressure, some packets get lost (not in a
>> "tcp_write failed way lost", but "tcp sequences got increased, but
>> packets were never transmitted"). Unfortunately I can't reliably
>> reproduce this. Sometimes it happens after only some minutes, other
>> times everything works fine for hours.
>>
>> I'd be very glad to receive some hints on this one.
>>
>> Thank you in advance!
>>
>>
>> lwip device is the de:af:ba:be:00:01 / 192.168.101.98.
>>
>> log from it:
>> 09:22:43.682: mem_malloc: could not allocate 728 bytes
>> 09:22:43.706: tcp_enqueue : could not allocate memory for pbuf copy size
>> 656
>> 09:22:43.746: server_send_data, tcp_write failed with -1
>> 09:22:43.774: mem_malloc: could not allocate 728 bytes
>> 09:22:43.798: tcp_enqueue : could not allocate memory for pbuf copy size
>> 656
>> ..and it keeps going on and on.
>>
>> pcb:
>>   {local_ip = {addr = 1650829504 /* 192.168.101.98 */}, remote_ip = {addr = 
>> 3529877696 /* 192.168.101.210 */}, so_options = 0, tos = 0 '\000', ttl = 255 
>> '\377', next = 0x0, state = ESTABLISHED, prio = 64 '@', callback_arg = 
>> 0x4000e324, local_port = 1111, accept = 0x7164<cb_accept>, remote_port = 
>> 47170, flags = 4 '\004', rcv_nxt = 133141362, rcv_wnd = 2920, rcv_ann_wnd = 
>> 2920, rcv_ann_right_edge = 133144282, tmr = 801, polltmr = 0 '\000', 
>> pollinterval = 0 '\000', rtime = 14, mss = 1460, rttest = 815, rtseq = 
>> 4627617, sa = 7, sv = 3, rto = 24, nrtx = 3 '\003', lastack = 4627617, 
>> dupacks = 3 '\003', cwnd = 1460, ssthresh = 2920, snd_nxt = 4634231, snd_wnd 
>> = 65535, snd_wl1 = 133141362, snd_wl2 = 4627617, snd_lbb = 4634231, acked = 
>> 0, snd_buf = 686, snd_queuelen = 5, unsent = 0x40008c24, unacked = 
>> 0x40008be4, ooseq = 0x0, refused_data = 0x0, sent = 0, recv = 
>> 0x7348<cb_recv>, connected = 0, poll = 0, errf = 0, keep_idle = 1800000, 
>> keep_intvl = 75000, keep_cnt = 9, persist_cnt = 0, persist_backoff = 0 
>> '\000', kee
> p_cnt_sent = 0 '\000'}
>>
>>
>> packets captured with wireshark:
>>
>> No.     Time        Source                Destination           Protocol Info
>>    61314 0.443454    192.168.101.98        192.168.101.210       TCP      
>> lmsocialserver>  47170 [PSH, ACK] Seq=4619629 Ack=1 Win=2920 Len=1460
>>
>> Frame 61314 (1514 bytes on wire, 1514 bytes captured)
>>      Arrival Time: Dec 18, 2009 09:22:42.992757000
>>      [Time delta from previous captured frame: 0.219257000 seconds]
>>      [Time delta from previous displayed frame: 0.219257000 seconds]
>>      [Time since reference or first frame: 0.443454000 seconds]
>>      Frame Number: 61314
>>      Frame Length: 1514 bytes
>>      Capture Length: 1514 bytes
>>      [Frame is marked: False]
>>      [Protocols in frame: eth:ip:tcp:data]
>>      [Coloring Rule Name: TCP]
>>      [Coloring Rule String: tcp]
>> Ethernet II, Src: de:af:ba:be:00:01 (de:af:ba:be:00:01), Dst: 
>> G-ProCom_68:92:3a (00:0f:fe:68:92:3a)
>> Internet Protocol, Src: 192.168.101.98 (192.168.101.98), Dst: 
>> 192.168.101.210 (192.168.101.210)
>> Transmission Control Protocol, Src Port: lmsocialserver (1111), Dst Port: 
>> 47170 (47170), Seq: 4619629, Ack: 1, Len: 1460
>>      Source port: lmsocialserver (1111)
>>      Destination port: 47170 (47170)
>>      Sequence number: 4619629    (relative sequence number)
>>      [Next sequence number: 4621089    (relative sequence number)]
>>      Acknowledgement number: 1    (relative ack number)
>>      Header length: 20 bytes
>>      Flags: 0x18 (PSH, ACK)
>>      Window size: 2920
>>      Checksum: 0xa88e [correct]
>>      [SEQ/ACK analysis]
>> Data (1460 bytes)
>>
>> No.     Time        Source                Destination           Protocol Info
>>    61315 0.443468    192.168.101.210       192.168.101.98        TCP      
>> 47170>  lmsocialserver [ACK] Seq=1 Ack=4621089 Win=65535 Len=0
>>
>> Frame 61315 (54 bytes on wire, 54 bytes captured)
>>      Arrival Time: Dec 18, 2009 09:22:42.992771000
>>      [Time delta from previous captured frame: 0.000014000 seconds]
>>      [Time delta from previous displayed frame: 0.000014000 seconds]
>>      [Time since reference or first frame: 0.443468000 seconds]
>>      Frame Number: 61315
>>      Frame Length: 54 bytes
>>      Capture Length: 54 bytes
>>      [Frame is marked: False]
>>      [Protocols in frame: eth:ip:tcp]
>>      [Coloring Rule Name: TCP]
>>      [Coloring Rule String: tcp]
>> Ethernet II, Src: G-ProCom_68:92:3a (00:0f:fe:68:92:3a), Dst: 
>> de:af:ba:be:00:01 (de:af:ba:be:00:01)
>> Internet Protocol, Src: 192.168.101.210 (192.168.101.210), Dst: 
>> 192.168.101.98 (192.168.101.98)
>> Transmission Control Protocol, Src Port: 47170 (47170), Dst Port: 
>> lmsocialserver (1111), Seq: 1, Ack: 4621089, Len: 0
>>      Source port: 47170 (47170)
>>      Destination port: lmsocialserver (1111)
>>      Sequence number: 1    (relative sequence number)
>>      Acknowledgement number: 4621089    (relative ack number)
>>      Header length: 20 bytes
>>      Flags: 0x10 (ACK)
>>      Window size: 65535
>>      Checksum: 0x6e6c [correct]
>>      [SEQ/ACK analysis]
>>
>> No.     Time        Source                Destination           Protocol Info
>>    61316 0.893178    192.168.101.98        192.168.101.210       TCP      
>> [TCP Previous segment lost] lmsocialserver>  47170 [PSH, ACK] Seq=4623754 
>> Ack=1 Win=2920 Len=1254
>>
>> Frame 61316 (1308 bytes on wire, 1308 bytes captured)
>>      Arrival Time: Dec 18, 2009 09:22:43.442481000
>>      [Time delta from previous captured frame: 0.449710000 seconds]
>>      [Time delta from previous displayed frame: 0.449710000 seconds]
>>      [Time since reference or first frame: 0.893178000 seconds]
>>      Frame Number: 61316
>>      Frame Length: 1308 bytes
>>      Capture Length: 1308 bytes
>>      [Frame is marked: False]
>>      [Protocols in frame: eth:ip:tcp:data]
>>      [Coloring Rule Name: Bad TCP]
>>      [Coloring Rule String: tcp.analysis.flags]
>> Ethernet II, Src: de:af:ba:be:00:01 (de:af:ba:be:00:01), Dst: 
>> G-ProCom_68:92:3a (00:0f:fe:68:92:3a)
>> Internet Protocol, Src: 192.168.101.98 (192.168.101.98), Dst: 
>> 192.168.101.210 (192.168.101.210)
>> Transmission Control Protocol, Src Port: lmsocialserver (1111), Dst Port: 
>> 47170 (47170), Seq: 4623754, Ack: 1, Len: 1254
>>      Source port: lmsocialserver (1111)
>>      Destination port: 47170 (47170)
>>      Sequence number: 4623754    (relative sequence number)
>>      [Next sequence number: 4625008    (relative sequence number)]
>>      Acknowledgement number: 1    (relative ack number)
>>      Header length: 20 bytes
>>      Flags: 0x18 (PSH, ACK)
>>      Window size: 2920
>>      Checksum: 0xdc87 [correct]
>>      [SEQ/ACK analysis]
>> Data (1254 bytes)
>>
>> No.     Time        Source                Destination           Protocol Info
>>    61317 0.893210    192.168.101.210       192.168.101.98        TCP      
>> [TCP Dup ACK 61315#1] 47170>  lmsocialserver [ACK] Seq=1 Ack=4621089 
>> Win=65535 Len=0
>>
>> Frame 61317 (54 bytes on wire, 54 bytes captured)
>>      Arrival Time: Dec 18, 2009 09:22:43.442513000
>>      [Time delta from previous captured frame: 0.000032000 seconds]
>>      [Time delta from previous displayed frame: 0.000032000 seconds]
>>      [Time since reference or first frame: 0.893210000 seconds]
>>      Frame Number: 61317
>>      Frame Length: 54 bytes
>>      Capture Length: 54 bytes
>>      [Frame is marked: False]
>>      [Protocols in frame: eth:ip:tcp]
>>      [Coloring Rule Name: Bad TCP]
>>      [Coloring Rule String: tcp.analysis.flags]
>> Ethernet II, Src: G-ProCom_68:92:3a (00:0f:fe:68:92:3a), Dst: 
>> de:af:ba:be:00:01 (de:af:ba:be:00:01)
>> Internet Protocol, Src: 192.168.101.210 (192.168.101.210), Dst: 
>> 192.168.101.98 (192.168.101.98)
>> Transmission Control Protocol, Src Port: 47170 (47170), Dst Port: 
>> lmsocialserver (1111), Seq: 1, Ack: 4621089, Len: 0
>>      Source port: 47170 (47170)
>>      Destination port: lmsocialserver (1111)
>>      Sequence number: 1    (relative sequence number)
>>      Acknowledgement number: 4621089    (relative ack number)
>>      Header length: 20 bytes
>>      Flags: 0x10 (ACK)
>>      Window size: 65535
>>      Checksum: 0x6e6c [correct]
>>      [SEQ/ACK analysis]
>>
>> No.     Time        Source                Destination           Protocol Info
>>    61318 0.898309    192.168.101.98        192.168.101.210       TCP      
>> lmsocialserver>  47170 [PSH, ACK] Seq=4625008 Ack=1 Win=2920 Len=1432
>>
>> Frame 61318 (1486 bytes on wire, 1486 bytes captured)
>>      Arrival Time: Dec 18, 2009 09:22:43.447612000
>>      [Time delta from previous captured frame: 0.005099000 seconds]
>>      [Time delta from previous displayed frame: 0.005099000 seconds]
>>      [Time since reference or first frame: 0.898309000 seconds]
>>      Frame Number: 61318
>>      Frame Length: 1486 bytes
>>      Capture Length: 1486 bytes
>>      [Frame is marked: False]
>>      [Protocols in frame: eth:ip:tcp:data]
>>      [Coloring Rule Name: TCP]
>>      [Coloring Rule String: tcp]
>> Ethernet II, Src: de:af:ba:be:00:01 (de:af:ba:be:00:01), Dst: 
>> G-ProCom_68:92:3a (00:0f:fe:68:92:3a)
>> Internet Protocol, Src: 192.168.101.98 (192.168.101.98), Dst: 
>> 192.168.101.210 (192.168.101.210)
>> Transmission Control Protocol, Src Port: lmsocialserver (1111), Dst Port: 
>> 47170 (47170), Seq: 4625008, Ack: 1, Len: 1432
>>      Source port: lmsocialserver (1111)
>>      Destination port: 47170 (47170)
>>      Sequence number: 4625008    (relative sequence number)
>>      [Next sequence number: 4626440    (relative sequence number)]
>>      Acknowledgement number: 1    (relative ack number)
>>      Header length: 20 bytes
>>      Flags: 0x18 (PSH, ACK)
>>      Window size: 2920
>>      Checksum: 0x89c1 [correct]
>>      [SEQ/ACK analysis]
>> Data (1432 bytes)
>>
>> No.     Time        Source                Destination           Protocol Info
>>    61319 0.898322    192.168.101.210       192.168.101.98        TCP      
>> [TCP Dup ACK 61315#2] 47170>  lmsocialserver [ACK] Seq=1 Ack=4621089 
>> Win=65535 Len=0
>>
>> Frame 61319 (54 bytes on wire, 54 bytes captured)
>>      Arrival Time: Dec 18, 2009 09:22:43.447625000
>>      [Time delta from previous captured frame: 0.000013000 seconds]
>>      [Time delta from previous displayed frame: 0.000013000 seconds]
>>      [Time since reference or first frame: 0.898322000 seconds]
>>      Frame Number: 61319
>>      Frame Length: 54 bytes
>>      Capture Length: 54 bytes
>>      [Frame is marked: False]
>>      [Protocols in frame: eth:ip:tcp]
>>      [Coloring Rule Name: Bad TCP]
>>      [Coloring Rule String: tcp.analysis.flags]
>> Ethernet II, Src: G-ProCom_68:92:3a (00:0f:fe:68:92:3a), Dst: 
>> de:af:ba:be:00:01 (de:af:ba:be:00:01)
>> Internet Protocol, Src: 192.168.101.210 (192.168.101.210), Dst: 
>> 192.168.101.98 (192.168.101.98)
>> Transmission Control Protocol, Src Port: 47170 (47170), Dst Port: 
>> lmsocialserver (1111), Seq: 1, Ack: 4621089, Len: 0
>>      Source port: 47170 (47170)
>>      Destination port: lmsocialserver (1111)
>>      Sequence number: 1    (relative sequence number)
>>      Acknowledgement number: 4621089    (relative ack number)
>>      Header length: 20 bytes
>>      Flags: 0x10 (ACK)
>>      Window size: 65535
>>      Checksum: 0x6e6c [correct]
>>      [SEQ/ACK analysis]
>>
>> No.     Time        Source                Destination           Protocol Info
>>    61320 1.116775    192.168.101.98        192.168.101.210       TCP      
>> lmsocialserver>  47170 [PSH, ACK] Seq=4626440 Ack=1 Win=2920 Len=1263
>>
>> Frame 61320 (1317 bytes on wire, 1317 bytes captured)
>>      Arrival Time: Dec 18, 2009 09:22:43.666078000
>>      [Time delta from previous captured frame: 0.218453000 seconds]
>>      [Time delta from previous displayed frame: 0.218453000 seconds]
>>      [Time since reference or first frame: 1.116775000 seconds]
>>      Frame Number: 61320
>>      Frame Length: 1317 bytes
>>      Capture Length: 1317 bytes
>>      [Frame is marked: False]
>>      [Protocols in frame: eth:ip:tcp:data]
>>      [Coloring Rule Name: TCP]
>>      [Coloring Rule String: tcp]
>> Ethernet II, Src: de:af:ba:be:00:01 (de:af:ba:be:00:01), Dst: 
>> G-ProCom_68:92:3a (00:0f:fe:68:92:3a)
>> Internet Protocol, Src: 192.168.101.98 (192.168.101.98), Dst: 
>> 192.168.101.210 (192.168.101.210)
>> Transmission Control Protocol, Src Port: lmsocialserver (1111), Dst Port: 
>> 47170 (47170), Seq: 4626440, Ack: 1, Len: 1263
>>      Source port: lmsocialserver (1111)
>>      Destination port: 47170 (47170)
>>      Sequence number: 4626440    (relative sequence number)
>>      [Next sequence number: 4627703    (relative sequence number)]
>>      Acknowledgement number: 1    (relative ack number)
>>      Header length: 20 bytes
>>      Flags: 0x18 (PSH, ACK)
>>      Window size: 2920
>>      Checksum: 0x0d95 [correct]
>>      [SEQ/ACK analysis]
>> Data (1263 bytes)
>>
>> No.     Time        Source                Destination           Protocol Info
>>    61321 1.116795    192.168.101.210       192.168.101.98        TCP      
>> [TCP Dup ACK 61315#3] 47170>  lmsocialserver [ACK] Seq=1 Ack=4621089 
>> Win=65535 Len=0
>>
>> Frame 61321 (54 bytes on wire, 54 bytes captured)
>>      Arrival Time: Dec 18, 2009 09:22:43.666098000
>>      [Time delta from previous captured frame: 0.000020000 seconds]
>>      [Time delta from previous displayed frame: 0.000020000 seconds]
>>      [Time since reference or first frame: 1.116795000 seconds]
>>      Frame Number: 61321
>>      Frame Length: 54 bytes
>>      Capture Length: 54 bytes
>>      [Frame is marked: False]
>>      [Protocols in frame: eth:ip:tcp]
>>      [Coloring Rule Name: Bad TCP]
>>      [Coloring Rule String: tcp.analysis.flags]
>> Ethernet II, Src: G-ProCom_68:92:3a (00:0f:fe:68:92:3a), Dst: 
>> de:af:ba:be:00:01 (de:af:ba:be:00:01)
>> Internet Protocol, Src: 192.168.101.210 (192.168.101.210), Dst: 
>> 192.168.101.98 (192.168.101.98)
>> Transmission Control Protocol, Src Port: 47170 (47170), Dst Port: 
>> lmsocialserver (1111), Seq: 1, Ack: 4621089, Len: 0
>>      Source port: 47170 (47170)
>>      Destination port: lmsocialserver (1111)
>>      Sequence number: 1    (relative sequence number)
>>      Acknowledgement number: 4621089    (relative ack number)
>>      Header length: 20 bytes
>>      Flags: 0x10 (ACK)
>>      Window size: 65535
>>      Checksum: 0x6e6c [correct]
>>      [SEQ/ACK analysis]
>>
>>
>> _______________________________________________
>> lwip-users mailing list
>> address@hidden
>> http://lists.nongnu.org/mailman/listinfo/lwip-users
>>
>>    
>
>
>
>
> _______________________________________________
> lwip-users mailing list
> address@hidden
> http://lists.nongnu.org/mailman/listinfo/lwip-users