[ipxe-devel] iPXE tftp multicast help requested (connection timeouts)

[Erik Jacobson]

We tried some new things:
 - several captures that back up debugging statements as far as we can tell
 - enabling tracing on atftp server and debug level 15 for tftp on iPXE
 
The failure mode is iPXE keeps sending an ACK for block 0 (which I think is
an options ACK). atftpd keeps seeing the ACK for block 0 over and over and
keeps retrying the send of block 1. It never gets an ACK for block 1.

Disabling blocksize and tsize in the server doesn't help.

I started to transfer a file that is super small and fits in one block.

atftp server side:

Dec  9 17:13:16 icicle atftpd[23061]: Creating new socket: 172.23.0.1:50138
Dec  9 17:13:16 icicle atftpd[23061]: Serving /foo to 172.23.0.9:64997
Dec  9 17:13:16 icicle atftpd[23061]: received RRQ <filename: /foo, mode: octet, multicast: >
Dec  9 17:13:16 icicle atftpd[23061]: Searching a server thread to give up this client
Dec  9 17:13:16 icicle atftpd[23061]: mcast_addr: 239.255.0.0, mcast_port: 1758
Dec  9 17:13:16 icicle atftpd[23061]: multicast option -> 239.255.0.0,1758,1
Dec  9 17:13:16 icicle atftpd[23061]: sent OACK <multicast: 239.255.0.0,1758,1>
Dec  9 17:13:16 icicle atftpd[23061]: received ACK <block: 0>
Dec  9 17:13:16 icicle atftpd[23061]: sent DATA <block: 1, size 6>
Dec  9 17:13:17 icicle atftpd[23061]: received ACK <block: 0>
Dec  9 17:13:17 icicle atftpd[23061]: resending block 1
Dec  9 17:13:17 icicle atftpd[23061]: sent DATA <block: 1, size 6>
Dec  9 17:13:17 icicle atftpd[23061]: received ACK <block: 0>
Dec  9 17:13:17 icicle atftpd[23061]: resending block 1
Dec  9 17:13:17 icicle atftpd[23061]: sent DATA <block: 1, size 6>
Dec  9 17:13:19 icicle atftpd[23061]: received ACK <block: 0>
Dec  9 17:13:19 icicle atftpd[23061]: resending block 1
Dec  9 17:13:19 icicle atftpd[23061]: sent DATA <block: 1, size 6>
Dec  9 17:13:22 icicle atftpd[23061]: received ACK <block: 0>
Dec  9 17:13:22 icicle atftpd[23061]: resending block 1
Dec  9 17:13:22 icicle atftpd[23061]: sent DATA <block: 1, size 6>
Dec  9 17:13:22 icicle dhcpd: DHCPDISCOVER from 00:25:90:78:de:15 via bond0: network cluster-networks: no free leases
Dec  9 17:13:26 icicle dhcpd: DHCPDISCOVER from 00:25:90:78:de:15 via bond0: network cluster-networks: no free leases
Dec  9 17:13:27 icicle atftpd[23061]: timeout: retrying...
Dec  9 17:13:27 icicle atftpd[23061]: sent DATA <block: 1, size 6>



ipxe side (debugging set to 15 for tftp):

iPXE> dhcp                                                                      
Configuring (net0 00:25:90:0c:da:a6)...... ok                                   
iPXE> imgfetch tftm://172.23.0.1/foo                                            tftm://172.23.0.1/foo...TFTP 0xce2d4 requesting "/foo"                          
TFTP 0xce2d4 requesting "/foo"                                                  TFTP 0xce2d4 using remote port 55872                                            
TFTP 0xce2d4 is the master client                                               TFTP 0xce2d4 multicast IP address 239.255.0.0                                   
TFTP 0xce2d4 multicast port 1758                                                TFTP 0xce2d4 sending ACK for block 0                                            
TFTP 0xce2d4 sending ACK for block 0                                            .TFTP 0xce2d4 sending ACK for block 0                                           
.TFTP 0xce2d4 sending ACK for block 0                                           ...TFTP 0xce2d4 sending ACK for block 0                                         
.......TFTP 0xce2d4 finished with status -1276272693 (Connection timed out (http://ipxe.org/4c126035))                                                          
 Connection timed out (http://ipxe.org/4c126035)                                iPXE>    



Here is a working transfer from an atftp multicast client (as opposed to
iPXE) of the same file:

Dec  9 17:17:00 icicle atftpd[23061]: Creating new socket: 172.23.0.1:45666
Dec  9 17:17:00 icicle atftpd[23061]: Serving /foo to 172.23.0.7:54907
Dec  9 17:17:00 icicle atftpd[23061]: received RRQ <filename: /foo, mode: octet, multicast: yes>
Dec  9 17:17:00 icicle atftpd[23061]: Searching a server thread to give up this client
Dec  9 17:17:00 icicle atftpd[23061]: mcast_addr: 239.255.0.0, mcast_port: 1758
Dec  9 17:17:00 icicle atftpd[23061]: multicast option -> 239.255.0.0,1758,1
Dec  9 17:17:00 icicle atftpd[23061]: sent OACK <multicast: 239.255.0.0,1758,1>
Dec  9 17:17:00 icicle atftpd[23061]: received ACK <block: 0>
Dec  9 17:17:00 icicle atftpd[23061]: sent DATA <block: 1, size 6>
Dec  9 17:17:00 icicle atftpd[23061]: received ACK <block: 1>
Dec  9 17:17:00 icicle atftpd[23061]: End of multicast transfer
Dec  9 17:17:00 icicle atftpd[23061]: No more client, end of tranfers
Dec  9 17:17:00 icicle atftpd[23061]: Server thread exiting


I will now start looking the the source code and playing in there some.

Suggestions still welcome.

Best wishes,

Erik