[Dnsmasq-discuss] TFTP logging strangeness

[Ferenc Wagner]

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.)
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!)  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.
-- 
Cheers, :)
Feri.