NetworkManager: error -111 disaptching events on DHCPv4 lease renewal

[Jan Vesely]

Ubuntu 20.04.1 running on armv7 (IFC6410)

Occasional network interruption with the following message in journal:

Nov 28 12:03:16 drako NetworkManager[4094]: <trace> [1606582996.3983] device[dabf59d236aff82b] (enp1s0): activation-stage: complete activate_stage5_ip_config_result_6,v6 (id 51751)
Nov 28 12:03:16 drako NetworkManager[4094]: <debug> [1606582996.4026] device[dabf59d236aff82b] (enp1s0): ip6-config: update (commit=0, new-config=0x803e6140)
Nov 28 12:03:18 drako NetworkManager[4094]: <error> [1606582998.8611] dhcp4 (enp1s0): error -111 dispatching events
Nov 28 12:03:18 drako NetworkManager[4094]: <info> [1606582998.8614] dhcp4 (enp1s0): state changed extended -> fail
Nov 28 12:03:18 drako NetworkManager[4094]: <info> [1606582998.8622] device (enp1s0): DHCPv4: trying to acquire a new lease within 90 seconds
Nov 28 12:04:49 drako NetworkManager[4094]: <info> [1606583089.4023] device (enp1s0): DHCPv4: grace period expired

the ipv4 connection is then cut (the interface looses ipc4 address and the ipv4 routes are purged) until NetworkManager is restarted.

The networkmanager-dispatcher.service doesn't indicate any error:

Nov 28 06:04:05 drako systemd[1]: Started Network Manager Script Dispatcher Service.
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: new request (2 scripts)
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: CONNECTION_DBUS_PATH=/org/freedesktop/NetworkManager/Settings/1
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: CONNECTION_FILENAME=/etc/NetworkManager/system-connections/Wired
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: CONNECTION_UUID=fe299e22-2b52-43ff-9a60-fa385e239f41
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: CONNECTION_ID=Wired
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: DEVICE_IFACE=enp1s0
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: DEVICE_IP_IFACE=enp1s0

Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: IP4_NUM_ADDRESSES=1

Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: IP4_NUM_ROUTES=1

Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: IP6_NUM_ROUTES=3
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: DHCP4_DHCP_LEASE_TIME=28800
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: DHCP4_EXPIRY=1606590245

Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: DHCP4_REQUESTED_BROADCAST_ADDRESS=1
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: DHCP4_REQUESTED_DOMAIN_NAME=1
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: DHCP4_REQUESTED_DOMAIN_NAME_SERVERS=1
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: DHCP4_REQUESTED_DOMAIN_SEARCH=1
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: DHCP4_REQUESTED_HOST_NAME=1
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: DHCP4_REQUESTED_INTERFACE_MTU=1
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: DHCP4_REQUESTED_MS_CLASSLESS_STATIC_ROUTES=1
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: DHCP4_REQUESTED_NIS_DOMAIN=1
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: DHCP4_REQUESTED_NIS_SERVERS=1
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: DHCP4_REQUESTED_NTP_SERVERS=1
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: DHCP4_REQUESTED_RFC3442_CLASSLESS_STATIC_ROUTES=1
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: DHCP4_REQUESTED_ROOT_PATH=1
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: DHCP4_REQUESTED_ROUTERS=1
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: DHCP4_REQUESTED_STATIC_ROUTES=1
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: DHCP4_REQUESTED_SUBNET_MASK=1
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: DHCP4_REQUESTED_TIME_OFFSET=1
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: DHCP4_REQUESTED_WPAD=1

Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: NM_DISPATCHER_ACTION=dhcp4-change
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: start running ordered scripts...
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0], "/etc/NetworkManager/dispatcher.d/01-ifupdown": run script
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0], "/etc/NetworkManager/dispatcher.d/01-ifupdown": complete
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0], "/etc/NetworkManager/dispatcher.d/ntp": run script
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0], "/etc/NetworkManager/dispatcher.d/ntp": complete
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: completed (2 scripts)
Nov 28 06:04:15 drako systemd[1]: NetworkManager-dispatcher.service: Succeeded.

but the last dispatcher log entry is 6 hours before the error.

The error is doesn't happen all the time. The difference between sucesfull DHCP renewal is failure is:

SUCCESS:

Nov 28 03:04:05 drako NetworkManager[4094]: <debug> [1606550645.1859] dhcp4 (enp1s0): send REQUEST of X.X.X.X to Y.Y.Y.Y
... REPEATS EVERY 1 MIN ...
Nov 28 06:03:23 drako NetworkManager[4094]: <debug> [1606561403.3185] dhcp4 (enp1s0): send REQUEST of X.X.X.X to Y.Y.Y.Y
Nov 28 06:04:05 drako NetworkManager[4094]: <debug> [1606561445.2416] dhcp4 (enp1s0): send REQUEST of X.X.X.X to 255.255.255.255
Nov 28 06:04:05 drako NetworkManager[4094]: <debug> [1606561445.2467] dhcp4 (enp1s0): received ACK of X.X.X.X from 0.0.0.0
Nov 28 06:04:05 drako NetworkManager[4094]: <trace> [1606561445.2474] dhcp4 (enp1s0): client event 4
Nov 28 06:04:05 drako NetworkManager[4094]: <trace> [1606561445.2476] dhcp4 (enp1s0): lease available (extended)
Nov 28 06:04:05 drako NetworkManager[4094]: <info> [1606561445.2640] dhcp4 (enp1s0): option dhcp_lease_time => '28800'
...
SUCCESSFUL LEASE
...
Nov 28 06:04:05 drako NetworkManager[4094]: <info> [1606561445.2691] dhcp4 (enp1s0): state changed bound -> extended
Nov 28 06:04:05 drako NetworkManager[4094]: <debug> [1606561445.2891] dispatcher: (6) (enp1s0) dispatching action 'dhcp4-change'
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: new request (2 scripts)
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: CONNECTION_DBUS_PATH=/org/freedesktop/NetworkManager/Settings/1
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: CONNECTION_FILENAME=/etc/NetworkManager/system-connections/Wired
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: CONNECTION_UUID=fe299e22-2b52-43ff-9a60-fa385e239f41
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: CONNECTION_ID=Wired
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: DEVICE_IFACE=enp1s0
Nov 28 06:04:05 drako nm-dispatcher[5178]: req:1 'dhcp4-change' [enp1s0]: environment: DEVICE_IP_IFACE=enp1s0

FAILURE:
Nov 28 10:04:05 drako NetworkManager[4094]: <debug> [1606575845.1875] dhcp4 (enp1s0): send REQUEST of X.X.X.X to Y.Y.Y.Y
... REPEATS EVERY 1 MINUTE ...
Nov 28 12:02:59 drako NetworkManager[4094]: <debug> [1606582979.0265] dhcp4 (enp1s0): send REQUEST of X.X.X.X to Y.Y.Y.Y
Nov 28 12:03:18 drako NetworkManager[4094]: <error> [1606582998.8611] dhcp4 (enp1s0): error -111 dispatching events
Nov 28 12:03:18 drako NetworkManager[4094]: <info> [1606582998.8614] dhcp4 (enp1s0): state changed extended -> fail

[Sebastien Bacher (seb128)]

Thank you for your bug report, you would probably have a better chance to get a reply reporting upstream on https://gitlab.freedesktop.org/NetworkManager/NetworkManager/issues/

[Stephan Kramer (s-kramer)]

I think this issue https://gitlab.freedesktop.org/NetworkManager/NetworkManager/-/merge_requests/486 might provide a fix. See also https://bugzilla.redhat.com/show_bug.cgi?id=1829178 where they mention the fix has been backported to 1.22.12. Any chance the Focal package could be upgraded to include that patch level? FWIW we've had the same issue as described on several machines (same network) when upgrading to Focal; installing the Groovy NM package (1.26.2) rebuilt from source for Focal seems to have fixed it.