tftpd says "Client 10.33.23.94 timed out"

Posted on

I am chasing a weird issue.

We have over a relatively stable Openstack ironic cluster over over 300 nodes. Occasionally I see some issues with a server not being able to deploy properly.

I have traced the issue down to the tftpd (tftp-server) process on the ironic conductor which says the tftp client (PXE boot) timed out (see last log at the bottom). Obviously the PXE client can access and does access successfully several files from the tftp server. The server also says that the client successfully downloaded the last file (deploy_ramdisk). Immediately after printing that message the tftpd (tftp-server) says client timed out.
Any pointers what could be happening?

I've downloaded the relevant packages for xinetd and tftp-server and cannot find the keywords "Client" or "timed out" anywhere in the source code.

[root@sc-ironic04 tftp-hpa-5.2]# rpm -q xinetd
xinetd-2.3.15-13.el7.x86_64
[root@sc-ironic04 tftp-hpa-5.2]# rpm -q tftpd
package tftpd is not installed
[root@sc-ironic04 tftp-hpa-5.2]# rpm -q tftp-server
tftp-server-5.2-22.el7.x86_64
[root@sc-ironic04 tftp-hpa-5.2]#

thanks,

Oct 22 09:50:03 sc-ironic04 in.tftpd[318148]: remap: input: bootx64.efi
Oct 22 09:50:03 sc-ironic04 in.tftpd[318148]: remap: rule 3: rewrite: /tftpboot/bootx64.efi
Oct 22 09:50:03 sc-ironic04 in.tftpd[318148]: remap: rule 3: exit
Oct 22 09:50:03 sc-ironic04 in.tftpd[318148]: RRQ from 10.33.23.94 filename bootx64.efi remapped to /tftpboot/bootx64.efi
Oct 22 09:50:04 sc-ironic04 in.tftpd[318148]: Error code 8: User aborted the transfer
Oct 22 09:50:04 sc-ironic04 in.tftpd[318150]: remap: input: bootx64.efi
Oct 22 09:50:04 sc-ironic04 in.tftpd[318150]: remap: rule 3: rewrite: /tftpboot/bootx64.efi
Oct 22 09:50:04 sc-ironic04 in.tftpd[318150]: remap: rule 3: exit
Oct 22 09:50:04 sc-ironic04 in.tftpd[318150]: RRQ from 10.33.23.94 filename bootx64.efi remapped to /tftpboot/bootx64.efi
Oct 22 09:50:04 sc-ironic04 in.tftpd[318150]: Client 10.33.23.94 finished bootx64.efi
Oct 22 09:50:04 sc-ironic04 in.tftpd[318151]: remap: input: grubx64.efi
Oct 22 09:50:04 sc-ironic04 in.tftpd[318151]: remap: rule 3: rewrite: /tftpboot/grubx64.efi
Oct 22 09:50:04 sc-ironic04 in.tftpd[318151]: remap: rule 3: exit
Oct 22 09:50:04 sc-ironic04 in.tftpd[318151]: RRQ from 10.33.23.94 filename grubx64.efi remapped to /tftpboot/grubx64.efi
Oct 22 09:50:05 sc-ironic04 in.tftpd[318151]: Client 10.33.23.94 finished grubx64.efi
Oct 22 09:50:05 sc-ironic04 in.tftpd[318152]: remap: input: /grub.cfg-01-6c-b3-11-4f-87-ac
Oct 22 09:50:05 sc-ironic04 in.tftpd[318152]: remap: rule 2: rewrite: /tftpboot//grub.cfg-01-6c-b3-11-4f-87-ac
Oct 22 09:50:05 sc-ironic04 in.tftpd[318152]: remap: rule 2: exit
Oct 22 09:50:05 sc-ironic04 in.tftpd[318152]: RRQ from 10.33.23.94 filename /grub.cfg-01-6c-b3-11-4f-87-ac remapped to /tftpboot//grub.cfg-01-6c-b3-11-4f-87-ac
Oct 22 09:50:05 sc-ironic04 in.tftpd[318152]: Client 10.33.23.94 File not found /tftpboot//grub.cfg-01-6c-b3-11-4f-87-ac
Oct 22 09:50:05 sc-ironic04 in.tftpd[318152]: sending NAK (1, File not found) to 10.33.23.94
Oct 22 09:50:05 sc-ironic04 in.tftpd[318153]: remap: input: /grub.cfg-0A21175E
Oct 22 09:50:05 sc-ironic04 in.tftpd[318153]: remap: rule 2: rewrite: /tftpboot//grub.cfg-0A21175E
Oct 22 09:50:05 sc-ironic04 in.tftpd[318153]: remap: rule 2: exit
Oct 22 09:50:05 sc-ironic04 in.tftpd[318153]: RRQ from 10.33.23.94 filename /grub.cfg-0A21175E remapped to /tftpboot//grub.cfg-0A21175E
Oct 22 09:50:05 sc-ironic04 in.tftpd[318153]: Client 10.33.23.94 File not found /tftpboot//grub.cfg-0A21175E
Oct 22 09:50:05 sc-ironic04 in.tftpd[318153]: sending NAK (1, File not found) to 10.33.23.94
Oct 22 09:50:05 sc-ironic04 in.tftpd[318154]: remap: input: /grub.cfg-0A21175
Oct 22 09:50:05 sc-ironic04 in.tftpd[318154]: remap: rule 2: rewrite: /tftpboot//grub.cfg-0A21175
Oct 22 09:50:05 sc-ironic04 in.tftpd[318154]: remap: rule 2: exit
Oct 22 09:50:05 sc-ironic04 in.tftpd[318154]: RRQ from 10.33.23.94 filename /grub.cfg-0A21175 remapped to /tftpboot//grub.cfg-0A21175
Oct 22 09:50:05 sc-ironic04 in.tftpd[318154]: Client 10.33.23.94 File not found /tftpboot//grub.cfg-0A21175
Oct 22 09:50:05 sc-ironic04 in.tftpd[318154]: sending NAK (1, File not found) to 10.33.23.94
Oct 22 09:50:05 sc-ironic04 in.tftpd[318155]: remap: input: /grub.cfg-0A2117
Oct 22 09:50:05 sc-ironic04 in.tftpd[318155]: remap: rule 2: rewrite: /tftpboot//grub.cfg-0A2117
Oct 22 09:50:05 sc-ironic04 in.tftpd[318155]: remap: rule 2: exit
Oct 22 09:50:05 sc-ironic04 in.tftpd[318155]: RRQ from 10.33.23.94 filename /grub.cfg-0A2117 remapped to /tftpboot//grub.cfg-0A2117
Oct 22 09:50:05 sc-ironic04 in.tftpd[318155]: Client 10.33.23.94 File not found /tftpboot//grub.cfg-0A2117
Oct 22 09:50:05 sc-ironic04 in.tftpd[318155]: sending NAK (1, File not found) to 10.33.23.94
Oct 22 09:50:05 sc-ironic04 in.tftpd[318156]: remap: input: /grub.cfg-0A211
Oct 22 09:50:05 sc-ironic04 in.tftpd[318156]: remap: rule 2: rewrite: /tftpboot//grub.cfg-0A211
Oct 22 09:50:05 sc-ironic04 in.tftpd[318156]: remap: rule 2: exit
Oct 22 09:50:05 sc-ironic04 in.tftpd[318156]: RRQ from 10.33.23.94 filename /grub.cfg-0A211 remapped to /tftpboot//grub.cfg-0A211
Oct 22 09:50:05 sc-ironic04 in.tftpd[318156]: Client 10.33.23.94 File not found /tftpboot//grub.cfg-0A211
Oct 22 09:50:05 sc-ironic04 in.tftpd[318156]: sending NAK (1, File not found) to 10.33.23.94
Oct 22 09:50:05 sc-ironic04 in.tftpd[318157]: remap: input: /grub.cfg-0A21
Oct 22 09:50:05 sc-ironic04 in.tftpd[318157]: remap: rule 2: rewrite: /tftpboot//grub.cfg-0A21
Oct 22 09:50:05 sc-ironic04 in.tftpd[318157]: remap: rule 2: exit
Oct 22 09:50:05 sc-ironic04 in.tftpd[318157]: RRQ from 10.33.23.94 filename /grub.cfg-0A21 remapped to /tftpboot//grub.cfg-0A21
Oct 22 09:50:05 sc-ironic04 in.tftpd[318157]: Client 10.33.23.94 File not found /tftpboot//grub.cfg-0A21
Oct 22 09:50:05 sc-ironic04 in.tftpd[318157]: sending NAK (1, File not found) to 10.33.23.94
Oct 22 09:50:05 sc-ironic04 in.tftpd[318158]: remap: input: /grub.cfg-0A2
Oct 22 09:50:05 sc-ironic04 in.tftpd[318158]: remap: rule 2: rewrite: /tftpboot//grub.cfg-0A2
Oct 22 09:50:05 sc-ironic04 in.tftpd[318158]: remap: rule 2: exit
Oct 22 09:50:05 sc-ironic04 in.tftpd[318178]: RRQ from 10.33.23.94 filename /EFI/centos/grub.cfg remapped to /tftpboot//EFI/centos/grub.cfg
Oct 22 09:50:05 sc-ironic04 in.tftpd[318178]: Client 10.33.23.94 finished /EFI/centos/grub.cfg
Oct 22 09:50:05 sc-ironic04 in.tftpd[318179]: remap: input: /EFI/centos/grub.cfg
Oct 22 09:50:05 sc-ironic04 in.tftpd[318179]: remap: rule 2: rewrite: /tftpboot//EFI/centos/grub.cfg
Oct 22 09:50:05 sc-ironic04 in.tftpd[318179]: remap: rule 2: exit
Oct 22 09:50:05 sc-ironic04 in.tftpd[318179]: RRQ from 10.33.23.94 filename /EFI/centos/grub.cfg remapped to /tftpboot//EFI/centos/grub.cfg
Oct 22 09:50:05 sc-ironic04 in.tftpd[318179]: Client 10.33.23.94 finished /EFI/centos/grub.cfg
Oct 22 09:50:07 sc-ironic04 ironic-conductor: 2019-10-22 09:50:07.298 267066 DEBUG futurist.periodics [-] Submitting periodic callback 'ironic.conductor.manager.ConductorManager._sync_local_state' _process_scheduled /usr/lib/python2.7/site-packages/futurist/periodics.py:639
Oct 22 09:50:07 sc-ironic04 ironic-conductor: 2019-10-22 09:50:07.298 267066 INFO ironic.conductor.manager [-] Executing sync_local_state
Oct 22 09:50:07 sc-ironic04 ironic-conductor: 2019-10-22 09:50:07.305 267066 DEBUG ironic.common.hash_ring [-] Rebuilding cached hash rings ring /usr/lib/python2.7/site-packages/ironic/common/hash_ring.py:51
Oct 22 09:50:07 sc-ironic04 ironic-conductor: 2019-10-22 09:50:07.466 267066 DEBUG ironic.common.hash_ring [-] Finished rebuilding hash rings, available drivers are ipmi, fake, snmp, fake_pxe, pxe_snmp, agent_ipmitool, pxe_ipmitool ring /usr/lib/python2.7/site-packages/ironic/common/hash_ring.py:56
Oct 22 09:50:10 sc-ironic04 in.tftpd[318184]: remap: input: /tftpboot/10.33.23.94.conf
Oct 22 09:50:10 sc-ironic04 in.tftpd[318184]: remap: rule 0: rewrite: /tftpboot/10.33.23.94.conf
Oct 22 09:50:10 sc-ironic04 in.tftpd[318184]: remap: rule 0: exit
Oct 22 09:50:10 sc-ironic04 in.tftpd[318184]: RRQ from 10.33.23.94 filename /tftpboot/10.33.23.94.conf
Oct 22 09:50:10 sc-ironic04 in.tftpd[318184]: Client 10.33.23.94 finished /tftpboot/10.33.23.94.conf
Oct 22 09:50:10 sc-ironic04 in.tftpd[318185]: remap: input: /tftpboot/10.33.23.94.conf
Oct 22 09:50:10 sc-ironic04 in.tftpd[318185]: remap: rule 0: rewrite: /tftpboot/10.33.23.94.conf
Oct 22 09:50:10 sc-ironic04 in.tftpd[318185]: remap: rule 0: exit
Oct 22 09:50:10 sc-ironic04 in.tftpd[318185]: RRQ from 10.33.23.94 filename /tftpboot/10.33.23.94.conf
Oct 22 09:50:10 sc-ironic04 in.tftpd[318185]: Client 10.33.23.94 finished /tftpboot/10.33.23.94.conf
Oct 22 09:50:10 sc-ironic04 in.tftpd[318186]: remap: input: /tftpboot/10.33.23.94.conf
Oct 22 09:50:10 sc-ironic04 in.tftpd[318186]: remap: rule 0: rewrite: /tftpboot/10.33.23.94.conf
Oct 22 09:50:10 sc-ironic04 in.tftpd[318186]: remap: rule 0: exit
Oct 22 09:50:10 sc-ironic04 in.tftpd[318186]: RRQ from 10.33.23.94 filename /tftpboot/10.33.23.94.conf
Oct 22 09:50:10 sc-ironic04 in.tftpd[318186]: Client 10.33.23.94 finished /tftpboot/10.33.23.94.conf
Oct 22 09:50:15 sc-ironic04 in.tftpd[318192]: remap: input: d465fa17-a2ea-43ff-a3a7-033cbb497774/deploy_kernel
Oct 22 09:50:15 sc-ironic04 in.tftpd[318192]: remap: rule 3: rewrite: /tftpboot/d465fa17-a2ea-43ff-a3a7-033cbb497774/deploy_kernel
Oct 22 09:50:15 sc-ironic04 in.tftpd[318192]: remap: rule 3: exit
Oct 22 09:50:15 sc-ironic04 in.tftpd[318192]: RRQ from 10.33.23.94 filename d465fa17-a2ea-43ff-a3a7-033cbb497774/deploy_kernel remapped to /tftpboot/d465fa17-a2ea-43ff-a3a7-033cbb497774/deploy_kernel
Oct 22 09:50:15 sc-ironic04 ironic-conductor: 2019-10-22 09:50:15.898 267066 DEBUG futurist.periodics [-] Submitting periodic callback 'ironic.conductor.manager.ConductorManager._check_rescuewait_timeouts' _process_scheduled /usr/lib/python2.7/site-packages/futurist/periodics.py:639
Oct 22 09:50:15 sc-ironic04 in.tftpd[318192]: Client 10.33.23.94 finished d465fa17-a2ea-43ff-a3a7-033cbb497774/deploy_kernel
Oct 22 09:50:15 sc-ironic04 in.tftpd[318194]: remap: input: d465fa17-a2ea-43ff-a3a7-033cbb497774/deploy_ramdisk
Oct 22 09:50:15 sc-ironic04 in.tftpd[318194]: remap: rule 3: rewrite: /tftpboot/d465fa17-a2ea-43ff-a3a7-033cbb497774/deploy_ramdisk
Oct 22 09:50:15 sc-ironic04 in.tftpd[318194]: remap: rule 3: exit
Oct 22 09:50:15 sc-ironic04 in.tftpd[318194]: RRQ from 10.33.23.94 filename d465fa17-a2ea-43ff-a3a7-033cbb497774/deploy_ramdisk remapped to /tftpboot/d465fa17-a2ea-43ff-a3a7-033cbb497774/deploy_ramdisk

Oct 22 09:50:44 sc-ironic04 in.tftpd[318194]: Client 10.33.23.94 finished d465fa17-a2ea-43ff-a3a7-033cbb497774/deploy_ramdisk
Oct 22 09:50:44 sc-ironic04 in.tftpd[318194]: Client 10.33.23.94 timed out

FS

Responses