Ubuntu
network-manager package

  1. Bug #1906120
  2. Comment #0

Comment 0 for bug 1906120

Revision history for this message
Jan Vesely (jan.vesely) wrote :

Ubuntu 20.04.1 running on armv7 (IFC6410)

Occasional network interruption with the following message in journal:

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