Re: BUG: NM only connects the third time

[Eric Brunet lps ens fr]

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:...]

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
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.

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

Cheers,

	Éric