Raspberry Pi Boot vs. Avahi vs. DHCP

Sometimes, one of our homebrew streaming media players will emerge from reset without starting up properly. The system board LEDs blink more-or-less normally, but the WiFi activity monitor seems … odd. This post documents the results of some exploratory surgery hinting at a possible solution.

I set the router’s DHCP server to assign a fixed IP address to each of our homebrew streaming media players based on its MAC address. That seemed less horrible than setting a static IP address in each player’s configuration, although I could see advantages to either approach. For streamer1, the player discussed here, the IP address is 192.168.1.101; that’s a non-routable address used only on our network behind the router.

During the Raspberry Pi’s boot, the default /etc/rc.local script finds and displays its IP address:

_IP=$(hostname -I) || true
if [ "$_IP" ]; then
  printf "My IP address is %s\n" "$_IP"
fi

The /var/log/boot log showed this after one boot:

--- snippage ---
         Starting LSB: Raise network interfaces....
---
[  OK  ] Started LSB: Raise network interfaces..
         Starting ifup for wlan0...
[  OK  ] Started ifup for wlan0.
[  OK  ] Reached target System Initialization.
[  OK  ] Listening on Avahi mDNS/DNS-SD Stack Activation Socket.
---
[  OK  ] Reached target Sockets.
---
[  OK  ] Reached target Basic System.
         Starting Avahi mDNS/DNS-SD Stack...
         Starting Regular background program processing daemon...
[  OK  ] Started Regular background program processing daemon.
         Starting dhcpcd on all interfaces...
---
[  OK  ] Started Avahi mDNS/DNS-SD Stack.
---
[  OK  ] Started dhcpcd on all interfaces.
[  OK  ] Reached target Network.
---
         Starting /etc/rc.local Compatibility...
         Starting Permit User Sessions...
[  OK  ] Reached target Network is Online.
         Starting LSB: Start NTP daemon...
My IP address is 169.254.14.12
[  OK  ] Started Permit User Sessions.
connect: Network is unreachable
[  OK  ] Started /etc/rc.local Compatibility.
         Starting Terminate Plymouth Boot Screen...
         Starting Hold until boot process finishes up...

That mysterious IP address is a Link-local address, about which Wikipedia says: “If a host on an IEEE 802 (Ethernet) network cannot obtain a network address via DHCP, an address from 169.254.1.0 to 169.254.254.255 may be assigned pseudorandomly.”

So, having the router hand out IP addresses doesn’t quite work the way I expected. The Pi awards itself a link-local IP address before getting one from the DHCP server, presumably because the vast Linux startup Pachinko machine has a race condition. Alas, the pseudorandom LL address doesn’t fit in the 192.168.0.0/16 network handled by the router: the Pi can’t connect to the network.

My code in /etc/rc.local starts the streaming player immediately after the default code displaying the IP address, thus joining the race condition: if the player starts up before the DCHP server assigns the proper IP address, it can’t connect to the music server out on the Interwebs. My code includes a retry loop with a five second delay which eventually connects, at least most of the time, but sometimes gets wedged.

The most reasonable fix seems to involve forcing a static address on each Raspberry Pi, so it can immediately connect to the network, without any negotiation, and get on with the business at hand.

Rather than configuring that in  /etc/network/interfaces as before, the New Hotness adds a stanza to  /etc/dhcpcd.conf:

interface wlan0
static ip_address=192.168.1.101/8
static routers=192.168.1.1
static domain_name_servers=192.168.1.1

En passant, I killed off IPV6 with this line in /etc/sysctl.conf:

net.ipv6.conf.all.disable_ipv6=1

The router doesn’t support IPV6 and there’s no point in using it. Bonus: less log clutter. Double Bonus: startup happens faster!

All of which may help the NTP client update the system clock sooner, perhaps preventing time jumps like this:

2017-02-14 08:42:24,183 INFO: Player setup for: BR1
2017-02-14 08:42:24,184 INFO: Volume control knob: /dev/input/volume
2017-02-14 08:42:24,225 INFO: Starting mplayer on Ambient -> http://185.32.125.42:7331/maschinengeist.org.mp3
2017-02-14 08:42:27,175 INFO: Track name: [Arcticology - Nocturnal Sounds]
2017-02-14 08:42:27,194 INFO: Track unmuted
2017-02-15 04:25:00,386 INFO: Track name: [Oöphoi - Suspended Matter]
2017-02-15 04:25:00,413 INFO: Track unmuted

The timestamps in the first five lines date back to the previous shutdown. The Pi remains plugged in and powered while it’s reset, which apparently preserves the system clock variables, albeit without a hardware clock ticking along: time stands still between shutdown and restart.

In this case, the IP address situation worked itself out before the player started, but the NTP clock reset on the sixth line happened at least three seconds after the log began.

This chunk of /var/log/syslog has more detail:

 highlight="1,5,6,7,8,15,21"]
Feb 14 08:42:24 streamer1 dhcpcd[693]: wlan0: leased 192.168.1.101 for 86400 seconds
Feb 14 08:42:24 streamer1 dhcpcd[693]: wlan0: adding route to 192.168.1.0/24
Feb 14 08:42:24 streamer1 dhcpcd[693]: wlan0: adding default route via 192.168.1.1
Feb 14 08:42:24 streamer1 avahi-daemon[387]: Registering new address record for 192.168.1.101 on wlan0.IPv4.
Feb 14 08:42:24 streamer1 dhcpcd[693]: wlan0: deleting route to 169.254.0.0/16
Feb 14 08:42:24 streamer1 avahi-daemon[387]: Withdrawing address record for 169.254.14.12 on wlan0.
Feb 14 08:42:24 streamer1 avahi-daemon[387]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 169.254.14.12.
Feb 14 08:42:24 streamer1 avahi-daemon[387]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.101.
Feb 14 08:42:25 streamer1 dhcpcd[693]: wlan0: no IPv6 Routers available
Feb 14 08:42:25 streamer1 ntpd_intres[728]: DNS 0.debian.pool.ntp.org -> 206.71.252.18
Feb 14 08:42:25 streamer1 ntpd_intres[728]: DNS 1.debian.pool.ntp.org -> 45.33.13.54
Feb 14 08:42:25 streamer1 ntpd_intres[728]: DNS 2.debian.pool.ntp.org -> 204.9.54.119
Feb 14 08:42:25 streamer1 ntpd_intres[728]: DNS 3.debian.pool.ntp.org -> 216.229.4.66
Feb 14 08:42:26 streamer1 ntpd[720]: Listen normally on 6 wlan0 192.168.1.101 UDP 123
Feb 14 08:42:26 streamer1 ntpd[720]: Deleting interface #3 wlan0, 169.254.14.12#123, interface stats: received=0, sent=0, dropped=4, active_time=3 secs
Feb 14 08:42:26 streamer1 ntpd[720]: 216.229.4.66 interface 169.254.14.12 -> (none)
Feb 14 08:42:26 streamer1 ntpd[720]: 204.9.54.119 interface 169.254.14.12 -> (none)
Feb 14 08:42:26 streamer1 ntpd[720]: 45.33.13.54 interface 169.254.14.12 -> (none)
Feb 14 08:42:26 streamer1 ntpd[720]: 206.71.252.18 interface 169.254.14.12 -> (none)
Feb 14 08:42:26 streamer1 ntpd[720]: peers refreshed
Feb 15 04:20:10 streamer1 systemd[1]: Time has been changed
[/sourcecode]

Given the timestamp resolution, NTP (or systemd) apparently resets the clock three seconds after the IP address changes. That may be as good as it gets, if only because the NTP daemon must find its servers, evaluate their status, then whack the local clock.

After forcing the static address, things look better, but it’s too soon to be sure. Many things can clobber streaming, not all of which happen on this side of our router.