Re: BUG: NM only connects the third time

[Dan Williams <dcbw redhat com>]

On Fri, 2007-11-02 at 11:39 +0100, Eric Brunet lps ens fr wrote:
> On Thu, Nov 01, 2007 at 05:10:24PM -0400, Dan Williams wrote:
> > > That's a Fedora 7, with a knetworkmanager from svn20070815, while the bug
> > > has been fixed (I think) on 20070827:
> > > 	2007-08-27 07:30  Helmut Schaa <hschaa suse de>
> > > 		* src/knetworkmanager-nminfo.cpp: Avoid a race on the DBus which
> > > 		  sometimes prevents connection to wireless networks
> > 
> > You might want to file a bug against knetworkmanager in Fedora bugzilla
> > to alert the maintainer to the fix so that he/she can package it up and
> > push it out.
> > 
> Will do.
> 
> > > That was it; I have a dell, but didn't know about dcdbas or libsmbiosi
> > > (and the error message didn't help...) Thanks for the info !
> > 
> > Upstream libsmbios just figured out how to get the module to autoload,
> > so hopefully that will get pushed into a new Fedora kernel at some point
> > and obsolete any hacks people have.
> 
> That would help if libsmbios is present but the driver is not loaded. The
> problem here is that libsmbios was not installed (I had never heard of
> it, and it is not installed by default). In that case, the error message
> gives no useful hint about what is going on.
> 
> While I am here, another suspicious behavior (same dell computer, FC7
> updated, eth0=tg3 and wlan0=iwl3945): on boot, networkmanager tries to
> establish a link with eth0 while there is no cable plugged in. In short,
> there are many messages from nm-netlink-monitor.c about changes in link status:
> 
> 11:06:52 NM: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device eth0 link now 0
> 11:06:52 NM: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device wlan0 link now 0
> 11:06:52 NM: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device wlan0 link now 1
> 11:06:52 NM: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device wlan0 link now 0
> 11:06:52 NM: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device eth0 link now 1
> 11:06:53 NM: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device eth0 link now 0
> 
> and between 11:06:52 and 11:06:53, NM has the time to launch dhclient on
> eth0, and this dhclient is never killed and goes on doing some DHCPDISCOVER on
> eth0 until after the computer is connected with wlan0:
> 
> 11:06:52 NM: <info>  eth0: Device is fully-supported using driver 'tg3'.
> 11:06:52 NM: <info>  nm_device_init(): waiting for device's worker thread to start
> 11:06:52 NM: <info>  nm_device_init(): device's worker thread started, continuing.
> 11:06:52 NM: <info>  Now managing wired Ethernet (802.3) device 'eth0'.
> 11:06:52 NM: <info>  Deactivating device eth0.
> 11:06:52 NM: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device eth0 link now 0
> 11:06:52 NM: <info>  nm-device-802-3-ethernet.c - nm_device_802_3_ethernet_link_deactivated (149) device eth0 scheduled link_deactivated_helper
> 11:06:52 NM: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device wlan0 link now 0
> 11:06:52 NM: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device wlan0 link now 1
> 11:06:52 NM: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device wlan0 link now 0
> 11:06:52 NM: <info>  nm-device-802-3-ethernet.c - link_deactivated_helper (129) device eth0 will set active link to FALSE
> 11:06:52 NM: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device eth0 link now 1
> 11:06:52 NM: <info>  nm-device-802-3-ethernet.c - nm_device_802_3_ethernet_link_activated (122) device eth0 scheduled link_activate d_helper
> 11:06:52 NM: <info>  nm-device-802-3-ethernet.c - link_activated_helper (102) device eth0 will set active link to TRUE
> 11:06:52 NM: <info>  nm-device.c - nm_device_set_active_link (596) device eth0 link state set to 1
> 11:06:52 NM: <info>  SWITCH: no current connection, found better connection 'eth0'.
> 11:06:52 NM: <info>  Will activate connection 'eth0'.
> 
> 	[... messages about activation till "Stage 3 of 5 started"...]
> 
> 11:06:52 NM: <info>  Wireless now enabled by radio killswitch
> 11:06:53 NM: <info>  nm-netlink-monitor.c - nm_netlink_monitor_event_handler (724) netlink reports device eth0 link now 0
> 11:06:53 NM: <info>  nm-device-802-3-ethernet.c - nm_device_802_3_ethernet_link_deactivated (149) device eth0 scheduled link_deactivated_helper
> 
> 	[... even though NM finally realized that eth0 link is now 0, it proceeds with dhcp:...]

NM ignores link changes during device activation.  This is for a number
of reasons.  The first is driver variance, and because during the
activation, the device may bounce up and down due to dhclient starting
up, or whatever.  Drivers are quite finicky; rtl8189 are quite notorious
for link bouncing.

This may have gotten better as drivers get better over time, and may no
longer be the appropriate behavior.  At a minimum, a link timer needs to
be started that would wait 5 seconds and smooth out link state before
terminating the activation.

> 11:06:53 NM: <info>  Activation (eth0) Beginning DHCP transaction.
> 11:06:53 NM: <info>  DHCP daemon state is now 12 (successfully started) for interface eth0
> 11:06:53 NM: <info>  Activation (eth0) Stage 3 of 5 (IP Configure Start) complete.
> 11:06:53 NM: <info>  nm-device-802-3-ethernet.c - link_deactivated_helper (129) device eth0 will set active link to FALSE
> 11:06:53 NM: <info>  nm-device.c - nm_device_set_active_link (596) device eth0 link state set to 0
> 11:06:53 NM: <info>  SWITCH: terminating current connection 'eth0' because it's no longer valid.
> 11:06:53 NM: <info>  Deactivating device eth0.
> 11:06:53 NM: <info>  Activation (eth0): cancelling...
> 11:06:53 NM: <info>  Activation (eth0) cancellation handler scheduled...
> 11:06:53 NM: <info>  Activation (eth0): waiting for device to cancel activation.
> 11:06:54 dhclient: wmaster0: unknown hardware address type 801
> 11:06:54 last message repeated 2 times
> 11:06:54 NM: <info>  Activation (eth0) cancellation handled.
> 11:06:54 NM: <info>  Activation (eth0): cancelled.
> 11:06:54 NM: nm_device_is_802_3_ethernet: assertion `dev != NULL' failed
> 11:06:54 NM: nm_device_is_802_11_wireless: assertion `dev != NULL' failed
> 11:06:54 dhclient: wmaster0: unknown hardware address type 801
> 11:06:54 dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 6
> 11:07:00 dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 10
> 11:07:10 dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 13
> 11:07:23 dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 21
> 11:07:30 NM: <info>  Updating allowed wireless network lists.
> 
> 	[... from here, NM switchs to wlan0, launches a dhclient on the wifi and gets my connexion, but one can still find in the logs: ...]
> 
> 11:07:44 dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 8
> 11:07:52 dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 3
> 11:07:55 dhclient: No DHCPOFFERS received.
> 
> Two problems here: link information is rubbish: eth0 should never have been
> considered up as no cable was ever plugged in during this boot sequence, and

Link information can't really be trusted completely, no.

> dhcp should never have been started on eth0 (it was started after NM realized
> the link was down, after all), and if it was started by mistake, it should have
> been killed before timing out.

Again, this behavior is perhaps too large of a hammer for the nail, but
it used to be the right size.

Dan

> Of course, it is not a very important problem as it doesn't prevent the computer
> from connecting to the wifi, but still...
> 
> Cheers,
> 
> 	�ic