[lug] Debugging a startup problem

[Michael J. Hammel]

WAG time:

Seems to me that the link ready messages from the kernel represent
state change that are not happening without being poked by higher layer
software.  That would suggest that the driver is not noting state
changes on its own or that, possible due to the if name change, the
events are not associated with eth3 but with eth0 at boot time so
network manager doesn't know to bring up that interface.

I blame systemd.  Because I can.

On Wed, 2018-07-11 at 09:35 -0600, Jed S. Baer wrote:
> 08:30:28 avahi-daemon[645]: Withdrawing workstation service for eth3.
> 08:30:28 kernel: [ 1758.705861] init: job_change_state: Destroyed
> inactive instance network-interface (eth3)
> 08:30:33 kernel: [ 1764.065792] r8169 0000:01:00.0 eth3: renamed from
> eth0
> 08:30:33 kernel: [ 1764.082280] systemd-udevd[3132]: renamed network
> interface eth0 to eth3
> 08:30:33 kernel: [ 1764.085411] init: event_pending_handle_jobs: New
> instance network-interface (eth3)
> 08:30:33 kernel: [ 1764.091485] init: network-interface (eth3) pre-
> start process (3137)
> 08:30:33 kernel: [ 1764.099310] init: network-interface (eth3) pre-
> start process (3137) exited normally
> 08:30:33 kernel: [ 1764.099371] init: network-interface (eth3) state
> changed from pre-start to spawned
> 08:30:33 kernel: [ 1764.099490] init: network-interface (eth3) state
> changed from spawned to post-start
> 08:30:33 kernel: [ 1764.099553] init: network-interface (eth3) state
> changed from post-start to running
> 08:38:10 NetworkManager[3290]: <info> (eth3): carrier is OFF
> 08:38:10 NetworkManager[3290]: <info> (eth3): new Ethernet device
> (driver: 'r8169' ifindex: 3)
> 08:38:10 NetworkManager[3290]: <info> (eth3): exported as
> /org/freedesktop/NetworkManager/Devices/0
> 08:38:10 NetworkManager[3290]: <info> (eth3): device state change:
> unmanaged -> unavailable (reason 'managed') [10 20 2]
> 08:38:10 NetworkManager[3290]: <info> (eth3): bringing up device.
> 08:38:10 NetworkManager[3290]: <info> (eth3): preparing device.
> 08:38:10 NetworkManager[3290]: <info> (eth3): deactivating device
> (reason 'managed') [2]
> 08:38:10 kernel: [ 2220.594902] r8169 0000:01:00.0 eth3: link down
> 08:38:10 kernel: [ 2220.594923] IPv6: ADDRCONF(NETDEV_UP): eth3: link
> is not ready
> 08:38:10 kernel: [ 2220.594942] r8169 0000:01:00.0 eth3: link down
> 08:38:12 NetworkManager[3290]: <info> (eth3): carrier now ON (device
> state 20)
> 08:38:12 NetworkManager[3290]: <info> (eth3): device state change:
> unavailable -> disconnected (reason 'carrier-changed') [20 30 40]
> 08:38:12 NetworkManager[3290]: <info> Activation (eth3) starting
> connection 'Ethernet connection 1'
> 08:38:12 NetworkManager[3290]: <info> (eth3): device state change:
> disconnected -> prepare (reason 'none') [30 40 0]
> 08:38:12 NetworkManager[3290]: <info> Activation (eth3) Stage 1 of 5
> (Device Prepare) scheduled...
> 08:38:12 NetworkManager[3290]: <info> Activation (eth3) Stage 1 of 5
> (Device Prepare) started...
> 08:38:12 NetworkManager[3290]: <info> Activation (eth3) Stage 2 of 5
> (Device Configure) scheduled...
> 08:38:12 NetworkManager[3290]: <info> Activation (eth3) Stage 1 of 5
> (Device Prepare) complete.
> 08:38:12 NetworkManager[3290]: <info> Activation (eth3) Stage 2 of 5
> (Device Configure) starting...
> 08:38:12 NetworkManager[3290]: <info> (eth3): device state change:
> prepare -> config (reason 'none') [40 50 0]
> 08:38:12 NetworkManager[3290]: <info> Activation (eth3) Stage 2 of 5
> (Device Configure) successful.
> 08:38:12 NetworkManager[3290]: <info> Activation (eth3) Stage 3 of 5
> (IP Configure Start) scheduled.
> 08:38:12 NetworkManager[3290]: <info> Activation (eth3) Stage 2 of 5
> (Device Configure) complete.
> 08:38:12 NetworkManager[3290]: <info> Activation (eth3) Stage 3 of 5
> (IP Configure Start) started...
> 08:38:12 NetworkManager[3290]: <info> (eth3): device state change:
> config -> ip-config (reason 'none') [50 70 0]
> 08:38:12 kernel: [ 2222.392503] r8169 0000:01:00.0 eth3: link up
> 08:38:12 kernel: [ 2222.392522] IPv6: ADDRCONF(NETDEV_CHANGE): eth3:
> link becomes ready
> 
> But I note that messages such as 'link is not ready' and carrier
> state don't appear during the boot process -- only when restarting
> network manager.
> 
> During this process, a 2nd PC was connected to the router, and had no
> network dropouts.
> _______________________________________________
> Web Page:  http://lug.boulder.co.us
> Mailing List: http://lists.lug.boulder.co.us/mailman/listinfo/lug
> Join us on IRC: irc.hackingsociety.org port=6667
> channel=#hackingsociety