Reason why "enp1s0: Link is Down" noted in the log?

Turbocapitalist · 11-25-2023, 05:55 AM

I'd like to figure out what went on with the networking yesterday on a Linux Mint 21.2 system. It went out briefly for a short while with no warning and came back the same way. No wires were jiggled and the router logs are empty except that DHCP Request + ACK happens twice at 20:06:08 and 20:07:14 each (in other words four times) for the IP address corresponding to that system.

Below is a log excerpt from a notebook computer connected via Ethernet where interface enp1s0 lost connectivity. The kernel is Linux 5.15.0-89-generic for x86_64.

What went on, or might have gone on?

Code:

Nov 24 20:06:03 ddd wpa_supplicant[1542]: wlp3s0: WPA: Group rekeying completed with 22:xx:xx:xx:xx:xx [GTK=CCMP]
Nov 24 20:06:04 ddd kernel: r8169 0000:01:00.0 enp1s0: Link is Down
Nov 24 20:06:06 ddd ntpd[1736]: Deleting interface #9 enp1s0, 198.51.100.65#123, interface stats: received=56, sent=80, dropped=0, active_time=1191 secs
Nov 24 20:06:06 ddd ntpd[1736]: Deleting interface #10 enp1s0, fe80::xxxx:xxxx:xxxx:xxxx%2#123, interface stats: received=0, sent=0, dropped=0, active_time=1191 secs
Nov 24 20:06:08 ddd NetworkManager[1485]: <info>  [1700849168.4589] device (enp1s0): carrier: link connected
Nov 24 20:06:08 ddd kernel: r8169 0000:01:00.0 enp1s0: Link is Up - 1Gbps/Full - flow control rx/tx
Nov 24 20:06:08 ddd NetworkManager[1485]: <info>  [1700849168.4590] device (enp1s0): ip:dhcp4: restarting
Nov 24 20:06:08 ddd NetworkManager[1485]: <info>  [1700849168.4951] dhcp4 (enp1s0): canceled DHCP transaction
Nov 24 20:06:08 ddd NetworkManager[1485]: <info>  [1700849168.4952] dhcp4 (enp1s0): activation: beginning transaction (timeout in 45 seconds)
Nov 24 20:06:08 ddd NetworkManager[1485]: <info>  [1700849168.4952] dhcp4 (enp1s0): state changed no lease
Nov 24 20:06:08 ddd NetworkManager[1485]: <info>  [1700849168.4953] dhcp4 (enp1s0): activation: beginning transaction (timeout in 45 seconds)
Nov 24 20:06:08 ddd NetworkManager[1485]: <info>  [1700849168.5058] dhcp4 (enp1s0): state changed new lease, address=198.51.100.65
Nov 24 20:06:08 ddd dbus-daemon[1484]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.8' (uid=0 pid=1485 comm="/usr/sbin/NetworkManager --no-daemon " label="unconfined")
Nov 24 20:06:08 ddd systemd[1]: Starting Network Manager Script Dispatcher Service...
Nov 24 20:06:08 ddd dbus-daemon[1484]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Nov 24 20:06:08 ddd systemd[1]: Started Network Manager Script Dispatcher Service.
Nov 24 20:06:10 ddd ntpd[1736]: Listen normally on 11 enp1s0 198.51.100.65:123
Nov 24 20:06:10 ddd ntpd[1736]: Listen normally on 12 enp1s0 [fe80::xxxx:xxxx:xxxx:xxxx%2]:123
Nov 24 20:06:10 ddd ntpd[1736]: new interface(s) found: waking up resolver
Nov 24 20:06:18 ddd systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
Nov 24 20:06:54 ddd kernel: r8169 0000:01:00.0 enp1s0: Link is Down
Nov 24 20:06:56 ddd ntpd[1736]: Deleting interface #11 enp1s0, 198.51.100.65#123, interface stats: received=0, sent=0, dropped=0, active_time=46 secs
Nov 24 20:06:56 ddd ntpd[1736]: Deleting interface #12 enp1s0, fe80::xxxx:xxxx:xxxx:xxxx%2#123, interface stats: received=0, sent=0, dropped=0, active_time=46 secs
Nov 24 20:07:00 ddd NetworkManager[1485]: <info>  [1700849220.6786] device (enp1s0): state change: activated -> unavailable (reason 'carrier-changed', sys-iface-state: 'managed')
Nov 24 20:07:00 ddd NetworkManager[1485]: <info>  [1700849220.6957] dhcp4 (enp1s0): canceled DHCP transaction
Nov 24 20:07:00 ddd NetworkManager[1485]: <info>  [1700849220.6958] dhcp4 (enp1s0): activation: beginning transaction (timeout in 45 seconds)
Nov 24 20:07:00 ddd NetworkManager[1485]: <info>  [1700849220.6958] dhcp4 (enp1s0): state changed no lease
Nov 24 20:07:00 ddd avahi-daemon[1480]: Withdrawing address record for 198.51.100.65 on enp1s0.
Nov 24 20:07:00 ddd avahi-daemon[1480]: Leaving mDNS multicast group on interface enp1s0.IPv4 with address 198.51.100.65.
Nov 24 20:07:00 ddd avahi-daemon[1480]: Interface enp1s0.IPv4 no longer relevant for mDNS.
Nov 24 20:07:00 ddd avahi-daemon[1480]: Withdrawing address record for fe80::xxxx:xxxx:xxxx:xxxx on enp1s0.
Nov 24 20:07:00 ddd avahi-daemon[1480]: Leaving mDNS multicast group on interface enp1s0.IPv6 with address fe80::xxxx:xxxx:xxxx:xxxx.
Nov 24 20:07:00 ddd systemd-resolved[1382]: enp1s0: Bus client reset search domain list.
Nov 24 20:07:00 ddd systemd-resolved[1382]: enp1s0: Bus client set default route setting: no
Nov 24 20:07:00 ddd avahi-daemon[1480]: Interface enp1s0.IPv6 no longer relevant for mDNS.
Nov 24 20:07:00 ddd systemd-resolved[1382]: enp1s0: Bus client reset DNS server list.
Nov 24 20:07:00 ddd dbus-daemon[1484]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.8' (uid=0 pid=1485 comm="/usr/sbin/NetworkManager --no-daemon " label="unconfined")
Nov 24 20:07:00 ddd NetworkManager[1485]: <info>  [1700849220.7292] manager: NetworkManager state is now CONNECTED_GLOBAL
Nov 24 20:07:00 ddd systemd[1]: Starting Network Manager Script Dispatcher Service...
Nov 24 20:07:00 ddd dbus-daemon[1484]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Nov 24 20:07:00 ddd systemd[1]: Started Network Manager Script Dispatcher Service.
Nov 24 20:07:10 pulse15 systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
Nov 24 20:07:14 pulse15 NetworkManager[1485]: <info>  [1700849234.0316] device (enp1s0): carrier: link connected
Nov 24 20:07:14 pulse15 NetworkManager[1485]: <info>  [1700849234.0317] device (enp1s0): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')
Nov 24 20:07:14 pulse15 NetworkManager[1485]: <info>  [1700849234.0326] policy: auto-activating connection 'Wired connection 1' (xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx)
Nov 24 20:07:14 pulse15 NetworkManager[1485]: <info>  [1700849234.0328] device (enp1s0): Activation: starting connection 'Wired connection 1' (xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx)
Nov 24 20:07:14 pulse15 NetworkManager[1485]: <info>  [1700849234.0329] device (enp1s0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Nov 24 20:07:14 pulse15 NetworkManager[1485]: <info>  [1700849234.0333] device (enp1s0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Nov 24 20:07:14 pulse15 NetworkManager[1485]: <info>  [1700849234.0343] device (enp1s0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Nov 24 20:07:14 pulse15 NetworkManager[1485]: <info>  [1700849234.0349] dhcp4 (enp1s0): activation: beginning transaction (timeout in 45 seconds)
Nov 24 20:07:14 pulse15 kernel: r8169 0000:01:00.0 enp1s0: Link is Up - 1Gbps/Full - flow control rx/tx
Nov 24 20:07:14 pulse15 avahi-daemon[1480]: Joining mDNS multicast group on interface enp1s0.IPv6 with address fe80::xxxx:xxxx:xxxx:xxxx.
Nov 24 20:07:14 pulse15 avahi-daemon[1480]: New relevant interface enp1s0.IPv6 for mDNS.
Nov 24 20:07:14 pulse15 avahi-daemon[1480]: Registering new address record for fe80::xxxx:xxxx:xxxx:xxxx on enp1s0.*.
Nov 24 20:07:14 pulse15 NetworkManager[1485]: <info>  [1700849234.0505] dhcp4 (enp1s0): state changed new lease, address=198.51.100.65
Nov 24 20:07:14 pulse15 avahi-daemon[1480]: Joining mDNS multicast group on interface enp1s0.IPv4 with address 198.51.100.65.
Nov 24 20:07:14 pulse15 avahi-daemon[1480]: New relevant interface enp1s0.IPv4 for mDNS.
Nov 24 20:07:14 pulse15 avahi-daemon[1480]: Registering new address record for 198.51.100.65 on enp1s0.IPv4.
Nov 24 20:07:14 pulse15 NetworkManager[1485]: <info>  [1700849234.0523] device (enp1s0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Nov 24 20:07:14 pulse15 dbus-daemon[1484]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.8' (uid=0 pid=1485 comm="/usr/sbin/NetworkManager --no-daemon " label="unconfined")
Nov 24 20:07:14 pulse15 systemd[1]: Starting Network Manager Script Dispatcher Service...
Nov 24 20:07:14 pulse15 dbus-daemon[1484]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Nov 24 20:07:14 pulse15 systemd[1]: Started Network Manager Script Dispatcher Service.
Nov 24 20:07:14 pulse15 NetworkManager[1485]: <info>  [1700849234.0643] device (enp1s0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
Nov 24 20:07:14 pulse15 NetworkManager[1485]: <info>  [1700849234.0645] device (enp1s0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Nov 24 20:07:14 pulse15 NetworkManager[1485]: <info>  [1700849234.0651] device (enp1s0): Activation: successful, device activated.
Nov 24 20:07:14 pulse15 systemd-resolved[1382]: enp1s0: Bus client set search domain list to: home.arpa
Nov 24 20:07:14 pulse15 systemd-resolved[1382]: enp1s0: Bus client set default route setting: yes
Nov 24 20:07:14 pulse15 systemd-resolved[1382]: enp1s0: Bus client set DNS server list to: 203.0.113.94
Nov 24 20:07:14 pulse15 nm-dispatcher[59816]: /etc/network/if-up.d/resolved: 12: mystatedir: not found
Nov 24 20:07:14 pulse15 nm-dispatcher[59849]: /etc/network/if-up.d/resolved: 12: mystatedir: not found
Nov 24 20:07:14 pulse15 NetworkManager[1485]: <info>  [1700849234.1705] policy: set 'Wired connection 1' (enp1s0) as default for IPv4 routing and DNS

smallpond · 11-25-2023, 07:51 AM

Looks like the hostname changed from ddd to pulse15 at about the same time. What else was going on?

Turbocapitalist · 11-25-2023, 07:53 AM

Quote:

Originally Posted by smallpond

Looks like the hostname changed from ddd to pulse15 at about the same time. What else was going on?

Oh, that is a failed attempt to shorten the host name column there. The system was mostly idling at the time except for a few TCP connections with lesser amounts of data.

lvm_ · 11-26-2023, 12:54 PM

"Link is down" means that your network card stopped detecting valid signals because something's wrong on data link or physical layers - interruption, bad contact, interference, whatever. OS logs won't help you here.

Turbocapitalist · 11-26-2023, 12:56 PM

Thanks.

So would it be a failing network interface on the router? If so, what should I be using to document that?

lvm_ · 11-27-2023, 04:21 AM

Quote:

Originally Posted by Turbocapitalist

So would it be a failing network interface on the router?

Unlikely, when they fail they usually fail for good. When it is intermittent, it's usually the cables. But it's all guesswork, if you really want to know, you'll need a network tester - a hardware device.

Turbocapitalist · 11-27-2023, 04:34 AM

Thanks.

The cable has mostly aged in place. I'll keep an eye on the situation and if it happens more often then I will put in a brand new cable in its place.