dhcpcd and dhcpcd-run-hooks on Raspbian

Written by pmd - - no comments

If you are using Raspbian GNU/Linux 9 (stretch), then you are most likely using dhcpcd as your DHCP and DHCPv6 client. How to know your OS version? Here :

$ cat /etc/os-release
PRETTY_NAME="Raspbian GNU/Linux 9 (stretch)"
NAME="Raspbian GNU/Linux"
VERSION_ID="9"
VERSION="9 (stretch)"
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"
  • dhcpcd gets the host information (IP address, routes, etc) from a DHCP server and configures the network interface of the machine on which it is running. Manual of DHCPCD(8).
  • dhcpcd-run-hooks is a DHCP client configuration script. It is used by dhcpcd to run any system and user defined hook scripts. Manual of DHCPCD-RUN-HOOKS(8).

dhcpcd

It seems that to restart all network interfaces this works :

$ sudo systemctl restart dhcpcd.service

To understand what happened, better read dhcpcd logs, here is what we can see:

$ journalctl -u dhcpcd
Dec 21 15:38:04 raspberrypi systemd[1]: Stopping dhcpcd on all interfaces...
Dec 21 15:38:04 raspberrypi dhcpcd[15174]: sending signal TERM to pid 14888
Dec 21 15:38:04 raspberrypi dhcpcd[15174]: waiting for pid 14888 to exit
Dec 21 15:38:04 raspberrypi dhcpcd[14888]: received SIGTERM, stopping
Dec 21 15:38:04 raspberrypi dhcpcd[14888]: eth0: removing interface
Dec 21 15:38:04 raspberrypi dhcpcd[14888]: wlan0: removing interface
Dec 21 15:38:04 raspberrypi dhcpcd[15174]: sending signal TERM to pid 14888
Dec 21 15:38:04 raspberrypi dhcpcd[15174]: waiting for pid 14888 to exit
Dec 21 15:38:05 raspberrypi systemd[1]: Stopped dhcpcd on all interfaces.
Dec 21 15:38:05 raspberrypi systemd[1]: Starting dhcpcd on all interfaces...
Dec 21 15:38:05 raspberrypi dhcpcd[15180]: dev: loaded udev
Dec 21 15:38:05 raspberrypi systemd[1]: Started dhcpcd on all interfaces.
Dec 21 15:38:05 raspberrypi dhcpcd-run-hooks[15203]: wlan0: starting wpa_supplicant
Dec 21 15:38:05 raspberrypi dhcpcd[15185]: eth0: waiting for carrier
Dec 21 15:38:05 raspberrypi dhcpcd[15185]: wlan0: waiting for carrier
Dec 21 15:38:06 raspberrypi dhcpcd[15185]: wlan0: carrier acquired
Dec 21 15:38:06 raspberrypi dhcpcd[15185]: DUID 00:01:00:01:21:b0:de:63:b8:27:eb:4d:6c:87
Dec 21 15:38:06 raspberrypi dhcpcd[15185]: wlan0: IAID eb:5d:6d:97
Dec 21 15:38:06 raspberrypi dhcpcd[15185]: wlan0: adding address fe80::2882:e851:cf0c:9242
Dec 21 15:38:06 raspberrypi dhcpcd[15185]: wlan0: soliciting an IPv6 router
Dec 21 15:38:06 raspberrypi dhcpcd[15185]: wlan0: rebinding lease of 192.168.254.200
Dec 21 15:38:06 raspberrypi dhcpcd[15185]: wlan0: leased 192.168.254.200 for 86400 seconds
Dec 21 15:38:06 raspberrypi dhcpcd[15185]: wlan0: adding route to 192.168.254.0/24
Dec 21 15:38:06 raspberrypi dhcpcd[15185]: wlan0: adding default route via 192.168.254.1
Dec 21 15:38:19 raspberrypi dhcpcd[15185]: wlan0: no IPv6 Routers available

Source

dhcpcd-run-hooks

dhcpcd runs /lib/dhcpcd/dhcpcd-run-hooks. This script runs each script found in /lib/dhcpcd/dhcpcd-hooks in a lexical order.
dhcpcd-run-hooks is used by dhcpcd to run any system and user defined hook scripts. System hook scripts are found in /lib/dhcpcd/dhcpcd-hooks.
There is a list of reasons why dhcpcd-run-hooks could be invoked, such as BOUND (= dhcpcd obtained a new lease from a DHCP server = computer has an IP assigned on the interface).
Many variables will then be set, along with any protocol supplied ones, such as :

  • $interface : the name of the interface
  • $reason : reason why dhcpcd-run-hooks was invoked
  • $if_up : true if the interface is up, otherwise false.

To know what is the current IPv4 address after an interface BOUNDed dhcpcd obtained a new lease from a DHCP server.:

ifconfig $interface | grep "inet " | awk '{print $2}'

I created /lib/dhcpcd/dhcpcd-hooks/60-test_by_pmd in order to play with this functionality. Shell script I used in order to check IP after new DHCP lease was obtained (writing output in /home/pi/test.txt in order to see what happened afterward):

if [ "$reason" = "BOUND" ] && [ "$if_up" = "true" ]; then
     echo "$(date +"%d-%m-%y %H:%M:%S ") $reason $interface IP:$if_up DOWN:$if_down" >> /home/pi/test.txt
     ifconfig $interface | grep "inet " | awk '{print $2}' >> /home/pi/test.txt
fi

Sources : both manuals.

Unstable Wifi connection to Raspberry Pi 3

Written by pmd - - no comments

Original post

I am loosing connection to my Raspberry Pi 3 in a very much random way.

I recently replaced Subsonic by Airsonic, and connection to Pi seemed to be much more stable since that exact day. But today, it happened one more time... as I was expecting! Time to troubleshoot has come.

Since I am using 2 tables to root my traffic, one of them is not updated on some interface up/down events. I made a small script called by cron every 5 minutes to understand things and rebooting Pi once a day to get the access back:

#!/usr/bin/env bash

# Script to monitor and restart wireless access point when needed

# Logging
date >> NetworkCheckLog
echo "wap_check_pmd: Checking if network connection is down..." >> NetworkCheckLog
echo "$ ip route show table main" >> NetworkCheckLog
ip route show table main >> NetworkCheckLog
echo "$ ip route show table 42" >> NetworkCheckLog
ip route show table 42 >> NetworkCheckLog

# First make sure we can resolve google, otherwise 'ping -w' would hang
if ! $(host -W5 www.google.com > /dev/null 2>&1); then
        #Make a note in syslog
        logger "wap_check_pmd: Network connection is down..."
        date >> NetworkCheckLog
        ifconfig >> NetworkCheckLog
        echo "wap_check_pmd: Network connection is down..." >> NetworkCheckLog
        exit
fi

Time when it got fucked:

Mon  6 Aug 08:55:01 CEST 2018
wap_check_pmd: Checking if network connection is down...
$ ip route show table main
0.0.0.0/1 via 10.8.7.1 dev tun0
default via 192.168.1.1 dev wlan0 src 192.168.1.200 metric 303
10.8.8.0/24 dev tun0 proto kernel scope link src 10.8.7.12
31.192.112.170 via 192.168.1.1 dev wlan0
128.0.0.0/1 via 10.8.7.1 dev tun0
192.168.1.0/24 dev wlan0 proto kernel scope link src 192.168.1.200 metric 303
$ ip route show table 42
default via 192.168.1.1 dev wlan0 src 192.168.1.200 metric 303
192.168.1.0/24 dev wlan0 proto kernel scope link src 192.168.1.200 metric 303

Mon  6 Aug 09:00:01 CEST 2018
wap_check_pmd: Checking if network connection is down...
$ ip route show table main
0.0.0.0/1 via 10.8.7.1 dev tun0
default via 192.168.1.1 dev wlan0 src 192.168.1.200 metric 303
10.8.8.0/24 dev tun0 proto kernel scope link src 10.8.7.12
128.0.0.0/1 via 10.8.7.1 dev tun0
192.168.1.0/24 dev wlan0 proto kernel scope link src 192.168.1.200 metric 303
$ ip route show table 42
Mon  6 Aug 09:00:15 CEST 2018
wap_check_pmd: Network connection is down...

I then checked /var/log/syslog:

Aug  6 08:59:26 raspberrypi dhcpcd[382]: wlan0: carrier lost
[...]
Aug  6 08:59:26 raspberrypi dhcpcd[382]: wlan0: deleting default route via 192.168.1.1
Aug  6 08:59:26 raspberrypi dhcpcd[382]: wlan0: deleting route to 192.168.1.0/24
[...]
Aug  6 08:59:51 raspberrypi dhcpcd[382]: wlan0: carrier acquired

After Googling, I found an interesting article. Which provide interesting tips.

  1. Use this command to read the current power saving mode of your Pi:
    $ sudo iw wlan0 get power_save
    Power save: on
  2. And this one to turn power_save off:
    $ sudo iw wlan0 set power_save off
  3. To make this permanent add the following line to /etc/rc.local:
    /sbin/iw dev wlan0 set power_save off

We will see if it helps :)

Update 27/10/2018

I choose to turn the power_save off as it originally was. But I came up with this script:

#!/bin/bash
#/home/pi/wap_check
# Script to monitor and restart wireless access point when needed
maxPloss=10 #Maximum percent packet loss before a restart

# Logging
# echo "$(date +"%d-%m-%y %H:%M:%S ") wap_check_pmd: Checking if network connection is down..." >> /home/pi/NetworkCheckLog

# If table 42 is empty, we lost raspberry
TABLE_42=$(ip route show table 42)
if [[ -z "${TABLE_42}" ]]; then
  # Loging
  echo  "$(date +"%d-%m-%y %H:%M:%S ") wap_check_pmd: Table 42 is empty! Trying to populate it:" >> /home/pi/NetworkCheckLog
  logger "wap_check_pmd: Table 42 is empty! Trying to populate it."
  # Filling up the table 42
  ip route show table main | grep -v tun0 | while read LINE; do sudo ip route add $LINE table 42; done
  sleep 1
  ip route show table 42 >> /home/pi/NetworkCheckLog
fi

# IP cannot be the same, debian-transmission can go only through tun0
IP_VPN=$(sudo -u debian-transmission wget -qO- ifconfig.co)
IP_PUBLIC=$(wget -qO- ifconfig.co)
if [[ "${IP_VPN}" = "${IP_PUBLIC}" ]]; then
  echo "$(date +"%d-%m-%y %H:%M:%S ") wap_check_pmd: Same IP for debian-transmission and pi: $(echo $IP_VPN) and $(echo $IP_PUBLIC)" >> /home/pi/NetworkCheckLog
  logger "wap_check_pmd: Same IP for debian-transmission and pi..."
  if [[ -n "${IP_PUBLIC}"  ]]; then
    echo "$(date +"%d-%m-%y %H:%M:%S ") wap_check_pmd: Rebooting. [1]" >> /home/pi/NetworkCheckLog
        logger "wap_check_pmd: Rebooting. [1]"
    sleep 1
    sudo /sbin/reboot
        exit
  fi
fi

# Make sure we can resolve google, otherwise 'ping -w' would hang
if ! $(host -W5 www.google.com > /dev/null 2>&1); then
    # Make a note in syslog
    logger "wap_check_pmd: Network connection is down..."
        echo "$(date +"%d-%m-%y %H:%M:%S ") wap_check_pmd: Rebooting. [2]" >> /home/pi/NetworkCheckLog
        logger "wap_check_pmd: Rebooting. [2]"
        # Restart device
        sleep 1
        sudo /sbin/reboot
    exit
fi

# Initialize to a value that would force a restart
# (just in case ping gives an error and ploss doesn't get set)
ploss=101
# now ping google for 10 seconds and count packet loss
ploss=$(ping -q -w10 www.google.com | grep -o "[0-9]*%" | tr -d %) > /dev/null 2>&1
if [ "$ploss" -gt "$maxPloss" ]; then
    logger "wap_check_pmd: Packet loss ($ploss%) exceeded $maxPloss"
    echo "$(date +"%d-%m-%y %H:%M:%S ") wap_check_pmd: Packet loss ($ploss%) exceeded $maxPloss" >> /home/pi/NetworkCheckLog
    # restart_networking
fi

I run this script every 5 minutes, line in my crontab file:

*/5 * * * * /bin/bash /home/pi/NetworkCheck.sh

Log file looks like this:

22-09-18 22:25:02  wap_check_pmd: Table 42 is empty! Trying to populate it:
22-09-18 22:26:55  wap_check_pmd: Same IP for debian-transmission and pi:  and
22-09-18 22:27:09  wap_check_pmd: Rebooting. [2]
24-09-18 23:20:16  wap_check_pmd: Rebooting. [2]
25-09-18 22:26:10  wap_check_pmd: Packet loss (30%) exceeded 10
25-09-18 23:11:07  wap_check_pmd: Packet loss (16%) exceeded 10
04-10-18 02:55:12  wap_check_pmd: Packet loss (70%) exceeded 10
04-10-18 15:50:01  wap_check_pmd: Table 42 is empty! Trying to populate it:
default via 192.168.1.1 dev wlan0 src 192.168.1.200 metric 303
192.168.1.0/24 dev wlan0 proto kernel scope link src 192.168.1.200 metric 303
04-10-18 19:20:12  wap_check_pmd: Packet loss (20%) exceeded 10
04-10-18 20:40:27  wap_check_pmd: Packet loss (30%) exceeded 10
04-10-18 20:55:21  wap_check_pmd: Packet loss (16%) exceeded 10
05-10-18 20:20:01  wap_check_pmd: Table 42 is empty! Trying to populate it:
default via 192.168.1.1 dev wlan0 src 192.168.1.200 metric 303
192.168.1.0/24 dev wlan0 proto kernel scope link src 192.168.1.200 metric 303
05-10-18 20:52:25  wap_check_pmd: Packet loss (30%) exceeded 10
06-10-18 15:15:15  wap_check_pmd: Packet loss (30%) exceeded 10
07-10-18 08:55:02  wap_check_pmd: Same IP for debian-transmission and pi:  and
16-10-18 19:21:53  wap_check_pmd: Same IP for debian-transmission and pi:  and
16-10-18 19:22:07  wap_check_pmd: Rebooting. [2]
27-10-18 11:30:20  wap_check_pmd: Packet loss (20%) exceeded 10
Rss feed of the tag