dhcpcd-6.7.1 spamming syslog with 'Bad file descriptor'

[Stuart MacDonald]

I have a system with a central PC and 60 Raspberry Pi 3s attached via ethernet. The Pis are configured to network syslog to the main PC.

Twice in the last week the PC has run out of disk space. It turns out that one of the Pis' syslog is getting spammed (to the tune of 60+ GB) by its dhcpcd client. Starting from the first problem line:

Mar 20 21:34:01 raspberrypi dhcpcd[701]: usb0: dhcp if_readrawpacket: Socket operation on non-socket
Mar 20 21:34:01 raspberrypi dhcpcd[701]: usb0: dhcp if_readrawpacket: Bad file descriptor
Mar 20 21:34:01 raspberrypi dhcpcd[701]: usb0: dhcp if_readrawpacket: Bad file descriptor
Mar 20 21:34:01 raspberrypi dhcpcd[701]: usb0: dhcp if_readrawpacket: Bad file descriptor
Mar 20 21:34:01 raspberrypi dhcpcd[701]: usb0: dhcp if_readrawpacket: Bad file descriptor
Mar 20 21:34:01 raspberrypi dhcpcd[701]: usb0: dhcp if_readrawpacket: Bad file descriptor
Mar 20 21:34:01 raspberrypi dhcpcd[701]: usb0: dhcp if_readrawpacket: Bad file descriptor
Mar 20 21:34:01 raspberrypi dhcpcd[701]: usb0: dhcp if_readrawpacket: Bad file descriptor
Mar 20 21:34:01 raspberrypi dhcpcd[701]: usb0: dhcp if_readrawpacket: Bad file descriptor
Mar 20 21:34:01 raspberrypi dhcpcd[701]: usb0: dhcp if_readrawpacket: Bad file descriptor
...
Mar 20 21:34:06 raspberrypi dhcpcd[701]: usb0: dhcp if_readrawpacket: Bad file descriptor
Mar 20 21:34:06 raspberrypi dhcpcd[701]: usb0: dhcp if_readrawpacket: Bad file descriptor
Mar 20 21:34:06 raspberrypi dhcpcd[701]: usb0: dhcp if_readrawpacket: Bad file descriptor
Mar 20 21:34:06 raspberrypi dhcpcd[701]: usb0: dhcp if_readrawpacket: Bad file descriptor
Mar 20 21:34:06 raspberrypi dhcpcd[701]: usb0: dhcp if_readrawpacket: Bad file descriptor

Versioning:
pi@raspberrypi:~/dhcpcd $ uname -a
Linux raspberrypi 4.1.19-v7+ #858 SMP Tue Mar 15 15:56:00 GMT 2016 armv7l GNU/Linux

pi@raspberrypi:~/dhcpcd $ cat /etc/issue
Raspbian GNU/Linux 8 \n \l

pi@raspberrypi:~/dhcpcd $ dhcpcd --version
dhcpcd 6.7.1
Copyright (c) 2006-2015 Roy Marples

pi@raspberrypi:~ $ uname -a
Linux raspberrypi 4.1.19-v7+ #858 SMP Tue Mar 15 15:56:00 GMT 2016 armv7l GNU/Linux

pi@raspberrypi:~ $ dpkg -s libc6 | grep ^Version
Version: 2.19-18+deb8u3

I expected that whatever the error condition, that it won't spam the syslog.

I looked a the source code for a while, but it looks like when the the error is printed, then the fd is closed appropriately, so I didn't see an obvious problem.

This is the default config of dhcpcd from the Jessie distro; nothing has been touched/local-configured.

I restarted the service with 'sudo service dhcpcd restart' but that didn't appear to help.

Apologies, my laptop crashed between this afternoon and now, so I don't have the old output handy anymore, but, I also checked the status (current, ok status showed as an example):

pi@raspberrypi:~ $ sudo service dhcpcd status
* dhcpcd.service - dhcpcd on all interfaces
   Loaded: loaded (/lib/systemd/system/dhcpcd.service; enabled)
  Drop-In: /etc/systemd/system/dhcpcd.service.d
           `-wait.conf
   Active: active (running) since Fri 2017-03-24 18:02:28 UTC; 13h ago
  Process: 427 ExecStart=/sbin/dhcpcd -q -w (code=exited, status=0/SUCCESS)
 Main PID: 705 (dhcpcd)
   CGroup: /system.slice/dhcpcd.service
           `-705 /sbin/dhcpcd -q -w

Mar 24 18:02:22 raspberrypi dhcpcd[427]: eth0: carrier acquired
Mar 24 18:02:22 raspberrypi dhcpcd[427]: eth0: IAID eb:c3:dd:28
Mar 24 18:02:23 raspberrypi dhcpcd[427]: eth0: rebinding lease of 10.11.0.29
Mar 24 18:02:23 raspberrypi dhcpcd[427]: eth0: soliciting an IPv6 router
Mar 24 18:02:28 raspberrypi dhcpcd[427]: eth0: leased 10.11.0.29 for 31536000 seconds
Mar 24 18:02:28 raspberrypi dhcpcd[427]: eth0: adding route to 10.11.0.0/24
Mar 24 18:02:28 raspberrypi dhcpcd[427]: eth0: adding default route via 10.11.0.250
Mar 24 18:02:28 raspberrypi dhcpcd[427]: forked to background, child pid 705
Mar 24 18:02:28 raspberrypi systemd[1]: Started dhcpcd on all interfaces.
Mar 24 18:02:43 raspberrypi dhcpcd[705]: eth0: no IPv6 Routers available

Warning: Unit file changed on disk, 'systemctl daemon-reload' recommended.

The syslog lines at the time were the errors from above, BUT, the Warning line was the same.

I tried the recommended systemctl command, no change to the problem.

Rebooting the Pi seems to have caused the problem to be resolved; it's about 9 hours later and no problems.