Public bug reported:
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
** Affects: network-manager (Ubuntu)
Importance: Undecided
Status: New
** Description changed:
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
--
You received this bug notification because you are a member of Desktop
Packages, which is subscribed to network-manager in Ubuntu.
https://bugs.launchpad.net/bugs/1906120
Title:
NetworkManager: error -111 disaptching events on DHCPv4 lease renewal
Status in network-manager package in Ubuntu:
New
Bug description:
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
To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/network-manager/+bug/1906120/+subscriptions
--
Mailing list: https://launchpad.net/~desktop-packages
Post to : [email protected]
Unsubscribe : https://launchpad.net/~desktop-packages
More help : https://help.launchpad.net/ListHelp
