Re: Ethernet device still disconnected after a 'link connected' log.

[Jean-Christian de Rivaz <jc eclis ch>]

Le 27. 07. 15 22:49, Dan Williams a écrit :
> On Mon, 2015-07-27 at 22:22 +0200, Jean-Christian de Rivaz wrote:
> > Le 27. 07. 15 19:32, Dan Williams a écrit :
> > > On Mon, 2015-07-27 at 19:24 +0200, Jean-Christian de Rivaz wrote:
> > > > Le 27. 07. 15 16:36, Dan Williams a écrit :
> > > > > On Mon, 2015-07-27 at 13:30 +0200, Jean-Christian de Rivaz wrote:
> > > > > > In this observation NetworkManager still think that eth0 is disconnected
> > > > > > while he correctly logged the message 'link connected':
> > > > > Just to make sure, the ethernet connection being used is
> > > > > autoconnect=true, right?
> > # nmcli con show "Wired connection 1" | grep autoconnect
> > connection.autoconnect:                 yes
> >
> > I hope that 'true' and 'yes' are equal in this context, so I think this
> > is not the cause of the observed problem.
>
> Correct, it's not the cause.  But something we need to rule out.  So
> now, getting a debug log from NetworkManager is the next thing.  You can
> use "nmcli g log level debug" and then attempt to reproduce the problem,
> and then lets see what the log say.

Ok, I take some time to reproduce the problem, but finally we hit it 
again with debug log level. Here is what I hope is the relevant part of 
the log:

Jul 30 09:09:30 x NetworkManager[1831]: <debug> [1438240170.534668] 
[platform/nm-linux-platform.c:1850] event_notification(): netlink event 
(type 16) for link: eth0 (2, family 0)
Jul 30 09:09:30 x NetworkManager[1831]: <debug> [1438240170.535480] 
[platform/nm-linux-platform.c:412] get_kernel_object(): 
get_kernel_object for link: eth0 (2, family 0)
Jul 30 09:09:30 x NetworkManager[1831]: <debug> 
[1438240170.537562][platform/nm-platform.c:2565] log_link(): signal: 
link changed: 2: eth0 <UP,LOWER_UP> mtu 1500 ethernet driver 'macb' udi 
'/sys/devices/platform/ahb/ahb:apb/f802c000.ethernet/net/eth0'
Jul 30 09:09:30 x NetworkManager[1831]: <info> (eth0): link connected
Jul 30 09:09:30 x NetworkManager[1831]: <debug> [1438240170.553426] 
[devices/nm-device.c:6346] nm_device_add_pending_action(): (eth0): 
add_pending_action (1): 'queued state change to disconnected'
Jul 30 09:09:30 x NetworkManager[1831]: <debug> [1438240170.553789] 
[devices/nm-device.c:6891] nm_device_queue_state(): (eth0): queued state 
change to disconnected due to carrier-changed (id 5817)
Jul 30 09:09:30 x NetworkManager[1831]: <debug> [1438240170.558548] 
[devices/nm-device.c:6839] queued_set_state(): (eth0): running queued 
state change to disconnected (id 5817)
Jul 30 09:09:30 x NetworkManager[1831]: <info> (eth0): device state 
change: unavailable -> disconnected (reason 'carrier-changed') [20 30 40]
Jul 30 09:09:30 x NetworkManager[1831]: <debug> [1438240170.576305] 
[nm-policy.c:1158] reset_autoconnect_all(): Re-enabling autoconnect for 
all connections on eth0
Jul 30 09:09:30 x NetworkManager[1831]: <debug> [1438240170.576770] 
[devices/nm-device.c:6346] nm_device_add_pending_action(): (eth0): 
add_pending_action (2): 'autoactivate'
Jul 30 09:09:30 x NetworkManager[1831]: <debug> [1438240170.577166] 
[devices/nm-device.c:6380] nm_device_remove_pending_action(): (eth0): 
remove_pending_action (1): 'queued state change to disconnected'
Jul 30 09:09:30 x NetworkManager[1831]: <debug> [1438240170.584887] 
[devices/nm-device.c:6380] nm_device_remove_pending_action(): (eth0): 
remove_pending_action (0): 'autoactivate'

Jean-Christian