[Dnsmasq-discuss] TFTP logging strangeness

[Simon Kelley]

On 17/09/10 14:02, Ferenc Wagner wrote:
> Hi,
>
> Sorry if I'm becoming a pest, but I was unfortunate enogh to notice
> another strangeness.  Here are the logs:
>
> Sep 17 12:56:55 n0 dnsmasq-tftp[10637]: sent /var/lib/tftpboot/pxelinux.0 to 192.168.31.43
> Sep 17 12:56:55 n0 dnsmasq-tftp[10637]: error 0 TFTP Aborted received from 192.168.31.43
> Sep 17 12:56:55 n0 dnsmasq-tftp[10637]: failed sending /var/lib/tftpboot/pxelinux.0 to 192.168.31.43
>
> and the corresponding network dump:
>
> Time             Source        sport  Destination   dport  Size  Info
> 12:56:55.638273  192.168.31.43 2070   192.168.31.33 69     69    Read Request, File: pxelinux.0\000, Transfer type: octet\000
> 12:56:55.638811  192.168.31.33 44394  192.168.31.43 2070   56    Option Acknowledgement
> 12:56:55.639331  192.168.31.43 2070   192.168.31.33 44394  59    Error Code, Code: Not defined, Message: TFTP Aborted\000
>
> One thing is that pxelinux.0 wasn't actually sent in this case, that
> message seems to be unconditionally output when the transmission fails.
> (Why the PXE stack on the NIC aborts the transfer after successfully
> negotiating the tsize option is beyond me, but that's unrelated.)
This is very common behaviour, I don't know why, either.

> But it retries at once, with blksize negotiation instead (not shown):
>
> Sep 17 12:56:55 n0 dnsmasq-tftp[10637]: sent /var/lib/tftpboot/pxelinux.0 to 192.168.31.43
> Sep 17 12:57:13 n0 dnsmasq-tftp[10637]: unsupported request from 192.168.31.43
> Sep 17 12:57:13 n0 kernel: [1036596.024038] Accepted: IN= OUT=szie-aotk SRC=192.168.31.33 DST=192.168.31.43 LEN=71 TOS=0x00 PREC=0x00 TTL=64 ID=10115 PROTO=UDP SPT=42668 DPT=2072 LEN=51 UID=0 GID=0
> Sep 17 12:57:31 n0 dnsmasq-tftp[10637]: failed sending /var/lib/tftpboot/pxelinux.0 to 192.168.31.43
>
> Again the corresponding network dump:
>
> Time             Source        sport  Destination   dport  Size  Info
> 12:56:55.641492  192.168.31.43 2071   192.168.31.33 69     74    Read Request, File: pxelinux.0\000, Transfer type: octet\000
> 12:56:55.642821  192.168.31.33 43907  192.168.31.43 2071   57    Option Acknowledgement
> 12:56:55.643532  192.168.31.43 2071   192.168.31.33 43907  46    Acknowledgement, Block: 0
> 12:56:55.645010  192.168.31.33 43907  192.168.31.43 2071   1502  Data Packet, Block: 1
> 12:56:57.157363  192.168.31.33 43907  192.168.31.43 2071   1502  Data Packet, Block: 1
> 12:57:00.181397  192.168.31.33 43907  192.168.31.43 2071   1502  Data Packet, Block: 1
> 12:57:05.021365  192.168.31.33 43907  192.168.31.43 2071   1502  Data Packet, Block: 1
> 12:57:13.607268  192.168.31.43 2072   192.168.31.33 69     74    Acknowledgement, Block: 0
> 12:57:13.608470  192.168.31.33 42668  192.168.31.43 2072   85    Error Code, Code: Illegal TFTP Operation, Message: unsupported request from 192.168.31.43\000
> 12:57:14.110313  192.168.31.33 43907  192.168.31.43 2071   1502  Data Packet, Block: 1
>
> Here we got an MTU problem: the TFTP data packet didn't get through
> because of its size, so it's retransmitted in vain a couple of times,
> then finally the client also retransmits its ACK (from a different
> port!)

That's interesting. Dnsmasq disables path-MTU discovery on TFTP sockets, 
because some boot-ROMS get confused by it (allegedly: see
http://syslinux.zytor.com/wiki/index.php/Hardware_Compatibility)
Maybe that's biting us here? The TFTP code will check the MTU of the 
local interface and reduce blocksize to fit, but that's no good if the 
bottleneck is elsewhere. --tftp-no-blocksize may be yout friend here.



> Here the Linux TFTP connection tracking gets rightfully
> confused, so the firewall logs the packet, but lets it through
> nevertheless.  Dnsmasq, receiving it, mistakes the retransmitted ACK for
> a request packet, emits a confusing error message and an error packet,
> terminating the stalled transfer, but later retransmits the doomed data
> packet again.
>
> Now, retransmitting the ACK from a different port is a bug in the PXE
> ROM, there isn't much to do about that.  But it would be more helpful
> from dnsmasq to call them ACKs and not "unsupported requests".  I think.

Check the destination port too. That acknowledgement packet is being 
sent to port 69, not the port associated with the data transfer (43907) 
As far as dnsmasq is concerned it has nothing to with the existing 
transfer, it's a new request but the request is broken because the 
packet type is wrong. In the circumstances the log message is quite 
sensible! Your client is very broken, which is not that uncommon.

Cheers,

Simon.