Re: Why whenever I enable the WiFi interface NM sends a DHCPDISCOVER if still not associate with any AP?

[Stolz <stolz ya com>]

2009/2/9 Dan Williams <dcbw redhat com>:
> On Sat, 2009-02-07 at 16:24 +0000, Stolz wrote:
>> Whenever I switch from wired to wireless interface, it takes more than
>> 45 seconds to get the wireless interface enabled. Looking at the logs,
>> seems the problem is (k)Networkmanager sends a DHCPDISCOVER before
>> been associated with any AP:
>
> Can you post some logs from when you enable the wireless interface?  The
> logs you've got start too late to be able to see exactly what's
> happening.
>
> NM *should* be associating with the AP first (including all security
> setup), and only when the wifi card says it's successfully associated
> with the AP, will NetworkManager begin DHCP.
>
> Dan


Hello Dan.

Here is the full log. I activated the WiFI interface exactly at 01:04:03
The log also can be read at http://rafb.net/p/K4H7x991.html

Thanks for your help.

Feb 10 01:03:33 dhcdbd: Started up.
Feb 10 01:03:34 acpid: client connected from 30947[102:443]
Feb 10 01:03:34 acpid: 1 client rule loaded
Feb 10 01:03:35 NetworkManager: <info>  starting...
Feb 10 01:03:35 NetworkManager: <debug> [1234224215.249008]
GentooReadConfig(): Found config_eth0 in /etc/conf.d/net.
Feb 10 01:03:35 NetworkManager: <debug> [1234224215.249240]
GentooReadConfig(): Found routes_eth0 in config.
Feb 10 01:03:35 NetworkManager: <debug> [1234224215.249367]
GentooReadConfig(): Found DNS nameservers in config.
Feb 10 01:03:35 NetworkManager: <debug> [1234224215.249495]
nm_system_device_get_system_config(): Using DNS nameservers
"62.42.230.24 62.42.63.52" from config for device eth0.
Feb 10 01:03:35 NetworkManager: <info>  eth0: Device is
fully-supported using driver '(null)'.
Feb 10 01:03:35 NetworkManager: <info>  nm_device_init(): waiting for
device's worker thread to start
Feb 10 01:03:35 NetworkManager: <info>  nm_device_init(): device's
worker thread started, continuing.
Feb 10 01:03:35 NetworkManager: <info>  Now managing wired Ethernet
(802.3) device 'eth0'.
Feb 10 01:03:35 NetworkManager: <info>  Deactivating device eth0.
Feb 10 01:03:35 NetworkManager: <info>  Will activate wired connection
'eth0' because it now has a link.
Feb 10 01:03:35 iwl3945 0000:0c:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17
Feb 10 01:03:35 iwl3945 0000:0c:00.0: restoring config space at offset
0x1 (was 0x100102, writing 0x100106)
Feb 10 01:03:35 firmware: requesting iwlwifi-3945-1.ucode
Feb 10 01:03:35 NetworkManager: <debug> [1234224215.325136]
GentooReadConfig(): Enabling DHCP for device wlan0.
Feb 10 01:03:35 NetworkManager: <info>  wlan0: Driver '(null)' does
not support carrier detection.
Feb 10 01:03:35  You must switch to it manually.
Feb 10 01:03:35 NetworkManager: <info>  nm_device_init(): waiting for
device's worker thread to start
Feb 10 01:03:35 NetworkManager: <info>  nm_device_init(): device's
worker thread started, continuing.
Feb 10 01:03:35 NetworkManager: <info>  Now managing wired Ethernet
(802.3) device 'wlan0'.
Feb 10 01:03:35 NetworkManager: <info>  Deactivating device wlan0.
Feb 10 01:03:35 /etc/init.d/net.lo[30991]: WARNING: net.lo has already
been started
Feb 10 01:03:35 NetworkManager: <info>  SWITCH: no current connection,
found better connection 'eth0'.
Feb 10 01:03:36 dhcdbd: message_handler: message handler not found
under /com/redhat/dhcp/eth0 for sub-path eth0.dbus.get.reason
Feb 10 01:03:36 NetworkManager: <info>  Will activate connection 'eth0'.
Feb 10 01:03:36 NetworkManager: <info>  Device eth0 activation scheduled...
Feb 10 01:03:36 NetworkManager: <info>  Activation (eth0) started...
Feb 10 01:03:36 NetworkManager: <info>  Activation (eth0) Stage 1 of 5
(Device Prepare) scheduled...
Feb 10 01:03:36 NetworkManager: <info>  Activation (eth0) Stage 1 of 5
(Device Prepare) started...
Feb 10 01:03:36 NetworkManager: <info>  Activation (eth0) Stage 2 of 5
(Device Configure) scheduled...
Feb 10 01:03:36 NetworkManager: <info>  Activation (eth0) Stage 1 of 5
(Device Prepare) complete.
Feb 10 01:03:36 NetworkManager: <info>  Activation (eth0) Stage 2 of 5
(Device Configure) starting...
Feb 10 01:03:36 NetworkManager: <info>  Activation (eth0) Stage 2 of 5
(Device Configure) successful.
Feb 10 01:03:36 NetworkManager: <info>  Activation (eth0) Stage 3 of 5
(IP Configure Start) scheduled.
Feb 10 01:03:36 NetworkManager: <info>  Activation (eth0) Stage 2 of 5
(Device Configure) complete.
Feb 10 01:03:36 NetworkManager: <info>  Activation (eth0) Stage 3 of 5
(IP Configure Start) started...
Feb 10 01:03:36 NetworkManager: <info>  Activation (eth0) Stage 4 of 5
(IP Configure Get) scheduled...
Feb 10 01:03:36 NetworkManager: <info>  Activation (eth0) Stage 3 of 5
(IP Configure Start) complete.
Feb 10 01:03:36 NetworkManager: <info>  Activation (eth0) Stage 4 of 5
(IP Configure Get) started...
Feb 10 01:03:36 NetworkManager: <info>  Activation (eth0) Stage 5 of 5
(IP Configure Commit) scheduled...
Feb 10 01:03:36 NetworkManager: <info>  Activation (eth0) Stage 4 of 5
(IP Configure Get) complete.
Feb 10 01:03:36 NetworkManager: <info>  Activation (eth0) Stage 5 of 5
(IP Configure Commit) started...
Feb 10 01:03:37 NetworkManager: <info>  Setting hostname to 'vostro'
Feb 10 01:03:37 NetworkManager: <info>  Activation (eth0) successful,
device activated.
Feb 10 01:03:37 NetworkManager: <info>  Activation (eth0) Finish
handler scheduled.
Feb 10 01:03:37 NetworkManager: <info>  Activation (eth0) Stage 5 of 5
(IP Configure Commit) complete.
Feb 10 01:03:37 NetworkManager: <info>  Activation (eth0) Finish
handler scheduled.
Feb 10 01:03:37 NetworkManager: <info>  Activation (eth0) Stage 5 of 5
(IP Configure Commit) complete.
Feb 10 01:03:53 NetworkManager: <info>  Updating allowed wireless network lists.
Feb 10 01:03:53 NetworkManager: <WARN>  nm_dbus_get_networks_cb():
error received: org.freedesktop.NetworkManagerInfo.NoNetworks -
org.freedesktop.NetworkManagerInfo.NoNetworks.
Feb 10 01:04:03 dhcdbd: message_handler: message handler not found
under /com/redhat/dhcp/wlan0 for sub-path wlan0.dbus.get.reason
Feb 10 01:04:03 NetworkManager: <info>  User Switch:
/org/freedesktop/NetworkManager/Devices/wlan0
Feb 10 01:04:03 NetworkManager: <info>  Deactivating device wlan0.
Feb 10 01:04:03 NetworkManager: <info>  Deactivating device wlan0.
Feb 10 01:04:03 NetworkManager: <info>  Device wlan0 activation scheduled...
Feb 10 01:04:03 NetworkManager: <info>  Deactivating device eth0.
Feb 10 01:04:03 NetworkManager: <info>  Activation (wlan0) started...
Feb 10 01:04:03 NetworkManager: <info>  Activation (wlan0) Stage 1 of
5 (Device Prepare) scheduled...
Feb 10 01:04:03 NetworkManager: <info>  Activation (wlan0) Stage 1 of
5 (Device Prepare) started...
Feb 10 01:04:03 NetworkManager: <info>  Activation (wlan0) Stage 2 of
5 (Device Configure) scheduled...
Feb 10 01:04:03 NetworkManager: <info>  Activation (wlan0) Stage 1 of
5 (Device Prepare) complete.
Feb 10 01:04:03 NetworkManager: <info>  Activation (wlan0) Stage 2 of
5 (Device Configure) starting...
Feb 10 01:04:03 NetworkManager: <info>  Activation (wlan0) Stage 2 of
5 (Device Configure) successful.
Feb 10 01:04:03 NetworkManager: <info>  Activation (wlan0) Stage 3 of
5 (IP Configure Start) scheduled.
Feb 10 01:04:03 NetworkManager: <info>  Activation (wlan0) Stage 2 of
5 (Device Configure) complete.
Feb 10 01:04:03 NetworkManager: <info>  Activation (wlan0) Stage 3 of
5 (IP Configure Start) started...
Feb 10 01:04:04 NetworkManager: <info>  Activation (wlan0) Beginning
DHCP transaction.
Feb 10 01:04:04 NetworkManager: <info>  DHCP daemon state is now 12
(successfully started) for interface wlan0
Feb 10 01:04:04 NetworkManager: <info>  Activation (wlan0) Stage 3 of
5 (IP Configure Start) complete.
Feb 10 01:04:04 dhclient: wmaster0: unknown hardware address type 801
Feb 10 01:04:04 dhclient: can't create
/var/lib/dhclient/dhclient-wlan0.leases: No such file or directory
Feb 10 01:04:05 NetworkManager: <info>  DHCP daemon state is now 1
(starting) for interface wlan0
Feb 10 01:04:05 dhclient: wmaster0: unknown hardware address type 801
Feb 10 01:04:05 dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255
port 67 interval 8
Feb 10 01:04:13 dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255
port 67 interval 9
Feb 10 01:04:22 dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255
port 67 interval 10
Feb 10 01:04:32 dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255
port 67 interval 13
Feb 10 01:04:45 dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255
port 67 interval 13
Feb 10 01:04:49 NetworkManager: <info>  Device 'wlan0' DHCP
transaction took too long (>45s), stopping it.
Feb 10 01:04:49 dhclient: wmaster0: unknown hardware address type 801
Feb 10 01:04:49 dhclient: can't create
/var/lib/dhclient/dhclient-wlan0.leases: No such file or directory
Feb 10 01:04:49 dhclient: wmaster0: unknown hardware address type 801
Feb 10 01:04:50 NetworkManager: <info>  Activation (wlan0) Stage 4 of
5 (IP Configure Timeout) started...
Feb 10 01:04:50 NetworkManager: <info>  No DHCP reply received.
Automatically obtaining IP via Zeroconf.
Feb 10 01:04:50 NetworkManager: <info>  Activation (wlan0) Stage 4 of
5 (IP Configure Timeout) scheduled...
Feb 10 01:04:50 NetworkManager: <info>  DHCP daemon state is now 14
(normal exit) for interface wlan0
Feb 10 01:04:50 NetworkManager: <info>  DHCP daemon state is now 14
(normal exit) for interface wlan0
Feb 10 01:04:50 NetworkManager: <info>  autoip: Sending probe #0 for
IP address 169.254.3.193.
Feb 10 01:04:50 NetworkManager: <info>  autoip: Waiting for reply...
Feb 10 01:04:52 NetworkManager: <info>  autoip: Sending probe #1 for
IP address 169.254.3.193.
Feb 10 01:04:52 NetworkManager: <info>  autoip: Waiting for reply...
Feb 10 01:04:54 NetworkManager: <info>  autoip: Sending probe #2 for
IP address 169.254.3.193.
Feb 10 01:04:54 NetworkManager: <info>  autoip: Waiting for reply...
Feb 10 01:04:57 NetworkManager: <info>  autoip: Sending announce #0
for IP address 169.254.3.193.
Feb 10 01:04:57 NetworkManager: <info>  autoip: Waiting for reply...
Feb 10 01:05:00 NetworkManager: <info>  autoip: Sending announce #1
for IP address 169.254.3.193.
Feb 10 01:05:00 NetworkManager: <info>  autoip: Waiting for reply...
Feb 10 01:05:03 NetworkManager: <info>  autoip: Sending announce #2
for IP address 169.254.3.193.
Feb 10 01:05:03 NetworkManager: <info>  autoip: Waiting for reply...
Feb 10 01:05:06 NetworkManager: <info>  Activation (wlan0) Stage 5 of
5 (IP Configure Commit) scheduled...
Feb 10 01:05:06 NetworkManager: <info>  Activation (wlan0) Stage 4 of
5 (IP Configure Timeout) complete.
Feb 10 01:05:06 NetworkManager: <info>  Activation (wlan0) Stage 5 of
5 (IP Configure Commit) started...
Feb 10 01:05:07 NetworkManager: <WARN>  nm_system_set_hostname():
nm_system_set_hostname(): gethostbyaddr failed, h_errno = 2
Feb 10 01:05:07 NetworkManager: <info>  Activation (wlan0) successful,
device activated.
Feb 10 01:05:07 NetworkManager: <info>  Activation (wlan0) Finish
handler scheduled.
Feb 10 01:05:07 NetworkManager: <info>  Activation (wlan0) Stage 5 of
5 (IP Configure Commit) complete.