05 December 2009

(Ubuntu 9.10) 無線LAN:NetworkManager + wpa_supplicantでの認証失敗

Ubuntu 9.10で無線LANのWPA認証に失敗する場合のログ (いまのところ、根本的な解決方法不明)。これが起こるのは、無線LANアダプタが(リセット後)始めてWPA接続を受け入れる場合にのみ起こるようだ。

■ 無線LANルータ

Buffalo WHR-AM54G54
設定:ブリッジモード(ルータ機能を使わない)、WPA-TKIP暗号化、暗号キー16文字(Key 16bytes)
状態:電源OFF→電源ON、その後始めて無線LANで接続を受け入れる時

■ 接続可能な端末環境

パソコン(Computer):Dell inspiron mini 10v
無線LANアダプタ(WirelessLAN adapter):内蔵(internal)
OS:Ubuntu 9.10 kernel 2.6.31-14 usb-hdd boot

■ 接続不可能な端末環境

パソコン(Computer):TOSHIBA dynabook Satellite P1W 160C/4W
無線LANアダプタ(WirelessLAN adapter):Buffalo WLI-CB-AMG54
OS:Ubuntu 9.10 kernel 2.6.31-15

■ 接続可能な端末で、接続成功したときのログ

同じ処理をしているところに着色している。

/var/log/syslog
NetworkManager: <info> Wireless now enabled by radio killswitch NetworkManager: SCPlugin-Ifupdown: (153680624) ... get_connections. NetworkManager: SCPlugin-Ifupdown: (153680624) ... get_connections (managed=false): return empty list. NetworkManager: Ifupdown: get unmanaged devices count: 0 NetworkManager: <info> (eth3): driver supports SSID scans (scan_capa 0x01). NetworkManager: <info> (eth3): new 802.11 WiFi device (driver: 'wl') NetworkManager: <info> (eth3): exported as /org/freedesktop/NetworkManager/Devices/0 NetworkManager: <info> (eth3): now managed NetworkManager: <info> (eth3): device state change: 1 -> 2 (reason 2) NetworkManager: <info> (eth3): preparing device. NetworkManager: <info> (eth3): deactivating device (reason: 2). NetworkManager: supplicant_interface_acquire: assertion `mgr_state == NM_SUPPLICANT_MANAGER_STATE_IDLE' failed NetworkManager: <info> (eth1): carrier is OFF NetworkManager: <info> (eth1): new Ethernet device (driver: 'r8169') NetworkManager: <info> (eth1): exported as /org/freedesktop/NetworkManager/Devices/1 NetworkManager: <info> (eth1): now managed NetworkManager: <info> (eth1): device state change: 1 -> 2 (reason 2) NetworkManager: <info> (eth1): bringing up device. NetworkManager: <info> (eth1): preparing device. NetworkManager: <info> (eth1): deactivating device (reason: 2). NetworkManager: Added default wired connection 'Auto eth1' for /sys/devices/pci0000:00/0000:00:1c.2/0000:04:00.0/net/eth1 NetworkManager: <info> modem-manager is now available NetworkManager: <WARN> default_adapter_cb(): bluez error getting default adapter: The name org.bluez was not provided by any .service files NetworkManager: <info> Trying to start the supplicant... NetworkManager: <info> (eth3): supplicant manager state: down -> idle NetworkManager: <info> (eth3): device state change: 2 -> 3 (reason 0) wpa_supplicant[1033]: CTRL-EVENT-SCAN-RESULTS wpa_supplicant[1033]: WPS-AP-AVAILABLE NetworkManager: <info> (eth3): supplicant interface state: starting -> ready wpa_supplicant[1033]: CTRL-EVENT-SCAN-RESULTS wpa_supplicant[1033]: WPS-AP-AVAILABLE wpa_supplicant[1033]: WPS-AP-AVAILABLE wpa_supplicant[1033]: CTRL-EVENT-SCAN-RESULTS wpa_supplicant[1033]: WPS-AP-AVAILABLE NetworkManager: <info> Activation (eth3) starting connection 'Auto MY-WLAN-AP-SSID' NetworkManager: <info> (eth3): device state change: 3 -> 4 (reason 0) NetworkManager: <info> Activation (eth3) Stage 1 of 5 (Device Prepare) scheduled... NetworkManager: <info> Activation (eth3) Stage 1 of 5 (Device Prepare) started... NetworkManager: <info> Activation (eth3) Stage 2 of 5 (Device Configure) scheduled... NetworkManager: <info> Activation (eth3) Stage 1 of 5 (Device Prepare) complete. NetworkManager: <info> Activation (eth3) Stage 2 of 5 (Device Configure) starting... NetworkManager: <info> (eth3): device state change: 4 -> 5 (reason 0) NetworkManager: <info> Activation (eth3/wireless): access point 'Auto MY-WLAN-AP-SSID' has security, but secrets are required. NetworkManager: <info> (eth3): device state change: 5 -> 6 (reason 0) NetworkManager: <info> Activation (eth3) Stage 2 of 5 (Device Configure) complete. NetworkManager: <info> Activation (eth3) Stage 1 of 5 (Device Prepare) scheduled... NetworkManager: <info> Activation (eth3) Stage 1 of 5 (Device Prepare) started... NetworkManager: <info> (eth3): device state change: 6 -> 4 (reason 0) NetworkManager: <info> Activation (eth3) Stage 2 of 5 (Device Configure) scheduled... NetworkManager: <info> Activation (eth3) Stage 1 of 5 (Device Prepare) complete. NetworkManager: <info> Activation (eth3) Stage 2 of 5 (Device Configure) starting... NetworkManager: <info> (eth3): device state change: 4 -> 5 (reason 0) NetworkManager: <info> Activation (eth3/wireless): connection 'Auto MY-WLAN-AP-SSID' has security, and secrets exist. No new secrets needed. NetworkManager: <info> Config: added 'ssid' value 'MY-WLAN-AP-SSID' NetworkManager: <info> Config: added 'scan_ssid' value '1' NetworkManager: <info> Config: added 'key_mgmt' value 'WPA-PSK' NetworkManager: <info> Config: added 'psk' value '<omitted>' NetworkManager: nm_setting_802_1x_get_pkcs11_engine_path: assertion `NM_IS_SETTING_802_1X (setting)' failed NetworkManager: nm_setting_802_1x_get_pkcs11_module_path: assertion `NM_IS_SETTING_802_1X (setting)' failed NetworkManager: <info> Activation (eth3) Stage 2 of 5 (Device Configure) complete. NetworkManager: <info> Config: set interface ap_scan to 1 NetworkManager: <info> (eth3): supplicant connection state: inactive -> scanning wpa_supplicant[1033]: CTRL-EVENT-SCAN-RESULTS wpa_supplicant[1033]: Trying to associate with 00:12:34:56:78:90 (SSID='MY-WLAN-AP-SSID' freq=2462 MHz) NetworkManager: <info> (eth3): supplicant connection state: scanning -> associating wpa_supplicant[1033]: Association request to the driver failed wpa_supplicant[1033]: Associated with 00:12:34:56:78:90 NetworkManager: <info> (eth3): supplicant connection state: associating -> associated NetworkManager: <info> (eth3): supplicant connection state: associated -> 4-way handshake NetworkManager: <info> (eth3): supplicant connection state: 4-way handshake -> group handshake wpa_supplicant[1033]: WPA: Key negotiation completed with 00:12:34:56:78:90 [PTK=TKIP GTK=TKIP] wpa_supplicant[1033]: CTRL-EVENT-CONNECTED - Connection to 00:12:34:56:78:90 completed (auth) [id=0 id_str=] NetworkManager: <info> (eth3): supplicant connection state: group handshake -> completed NetworkManager: <info> Activation (eth3/wireless) Stage 2 of 5 (Device Configure) successful. Connected to wireless network 'MY-WLAN-AP-SSID'. NetworkManager: <info> Activation (eth3) Stage 3 of 5 (IP Configure Start) scheduled. NetworkManager: <info> Activation (eth3) Stage 3 of 5 (IP Configure Start) started... NetworkManager: <info> (eth3): device state change: 5 -> 7 (reason 0) NetworkManager: <info> Activation (eth3) Beginning DHCP transaction (timeout in 45 seconds) NetworkManager: <info> dhclient started with pid 1831 NetworkManager: <info> Activation (eth3) Stage 4 of 5 (IP6 Configure Get) scheduled... NetworkManager: <info> Activation (eth3) Stage 3 of 5 (IP Configure Start) complete. NetworkManager: <info> Activation (eth3) Stage 4 of 5 (IP6 Configure Get) started... NetworkManager: <info> Activation (eth3) Stage 4 of 5 (IP6 Configure Get) complete. dhclient: Internet Systems Consortium DHCP Client V3.1.2 dhclient: Copyright 2004-2008 Internet Systems Consortium. dhclient: All rights reserved. dhclient: For info, please visit http://www.isc.org/sw/dhcp/ dhclient: NetworkManager: <info> DHCP: device eth3 state changed (null) -> preinit dhclient: Listening on LPF/eth3/00:98:76:54:32:99 dhclient: Sending on LPF/eth3/00:98:76:54:32:99 dhclient: Sending on Socket/fallback dhclient: DHCPREQUEST of 192.168.1.214 on eth3 to 255.255.255.255 port 67 dhclient: DHCPACK of 192.168.1.214 from 192.168.1.1 dhclient: bound to 192.168.1.214 -- renewal in 148446 seconds. NetworkManager: <info> DHCP: device eth3 state changed preinit -> reboot NetworkManager: <info> Activation (eth3) Stage 4 of 5 (IP4 Configure Get) scheduled... NetworkManager: <info> Activation (eth3) Stage 4 of 5 (IP4 Configure Get) started... NetworkManager: <info> address 192.168.1.214 NetworkManager: <info> prefix 24 (255.255.255.0) NetworkManager: <info> gateway 192.168.1.1 NetworkManager: <info> nameserver '123.456.789.134' NetworkManager: <info> nameserver '123.456.789.135' NetworkManager: <info> Activation (eth3) Stage 5 of 5 (IP Configure Commit) scheduled... NetworkManager: <info> Activation (eth3) Stage 4 of 5 (IP4 Configure Get) complete. NetworkManager: <info> Activation (eth3) Stage 5 of 5 (IP Configure Commit) started... NetworkManager: <info> (eth3): device state change: 7 -> 8 (reason 0) NetworkManager: <info> Policy set 'Auto MY-WLAN-AP-SSID' (eth3) as default for routing and DNS. NetworkManager: <info> Activation (eth3) successful, device activated. NetworkManager: <info> Activation (eth3) Stage 5 of 5 (IP Configure Commit) complete. wpa_supplicant[1033]: CTRL-EVENT-SCAN-RESULTS

■ 接続不可能な端末で、接続失敗したときのログ

/var/log/syslog
kernel: [ 87.452064] pcmcia_socket pcmcia_socket0: pccard: CardBus card inserted into slot 0 kernel: [ 87.452140] pci 0000:0a:00.0: reg 10 32bit mmio: [0x000000-0x00ffff] kernel: [ 87.452282] yenta_cardbus 0000:09:01.0: EnE: chaning testregister 0xC9, 04 -> 04 kernel: [ 87.502804] ndiswrapper: driver netamg54 (,06/02/2006,5.0.0.107) loaded kernel: [ 87.503149] ndiswrapper 0000:0a:00.0: enabling device (0000 -> 0002) kernel: [ 87.503165] ndiswrapper 0000:0a:00.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20 kernel: [ 87.503506] ndiswrapper 0000:0a:00.0: setting latency timer to 64 kernel: [ 87.861727] ndiswrapper: using IRQ 20 kernel: [ 88.060892] wlan0: ethernet device 00:98:76:54:32:10 using serialized NDIS driver: netamg54, version: 0x50000, NDIS version: 0x501, vendor: 'NDIS Network Adapter', 168C:0013.5.conf NetworkManager: SCPlugin-Ifupdown: devices added (path: /sys/devices/pci0000:00/0000:00:14.4/0000:09:01.0/0000:0a:00.0/net/wlan0, iface: wlan0) NetworkManager: SCPlugin-Ifupdown: device added (path: /sys/devices/pci0000:00/0000:00:14.4/0000:09:01.0/0000:0a:00.0/net/wlan0, iface: wlan0): no ifupdown configuration found. NetworkManager: <info> (wlan0): driver does not support SSID scans (scan_capa 0x00). NetworkManager: <info> (wlan0): new 802.11 WiFi device (driver: 'ndiswrapper') NetworkManager: <info> (wlan0): exported as /org/freedesktop/NetworkManager/Devices/1 NetworkManager: <info> (wlan0): now managed NetworkManager: <info> (wlan0): device state change: 1 -> 2 (reason 2) NetworkManager: <info> (wlan0): bringing up device. NetworkManager: <info> (wlan0): preparing device. NetworkManager: <info> (wlan0): deactivating device (reason: 2). kernel: [ 88.084531] wlan0: encryption modes supported: WEP; TKIP with WPA, WPA2, WPA2PSK; AES/CCMP with WPA, WPA2, WPA2PSK kernel: [ 88.086012] ADDRCONF(NETDEV_UP): wlan0: link is not ready NetworkManager: <info> (wlan0): supplicant interface state: starting -> ready NetworkManager: <info> (wlan0): device state change: 2 -> 3 (reason 42) wpa_supplicant[602]: CTRL-EVENT-SCAN-RESULTS NetworkManager: <info> Activation (wlan0) starting connection 'Auto MY-WLAN-AP-SSID' NetworkManager: <info> (wlan0): device state change: 3 -> 4 (reason 0) NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started... NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting... NetworkManager: <info> (wlan0): device state change: 4 -> 5 (reason 0) NetworkManager: <info> Activation (wlan0/wireless): access point 'Auto MY-WLAN-AP-SSID' has security, but secrets are required. NetworkManager: <info> (wlan0): device state change: 5 -> 6 (reason 0) NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete. NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started... NetworkManager: <info> (wlan0): device state change: 6 -> 4 (reason 0) NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... NetworkManager: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting... NetworkManager: <info> (wlan0): device state change: 4 -> 5 (reason 0) NetworkManager: <info> Activation (wlan0/wireless): connection 'Auto MY-WLAN-AP-SSID' has security, and secrets exist. No new secrets needed. NetworkManager: <info> Config: added 'ssid' value 'MY-WLAN-AP-SSID' NetworkManager: <info> Config: added 'scan_ssid' value '1' NetworkManager: <info> Config: added 'key_mgmt' value 'WPA-PSK' NetworkManager: <info> Config: added 'psk' value '<omitted>' NetworkManager: nm_setting_802_1x_get_pkcs11_engine_path: assertion `NM_IS_SETTING_802_1X (setting)' failed NetworkManager: nm_setting_802_1x_get_pkcs11_module_path: assertion `NM_IS_SETTING_802_1X (setting)' failed NetworkManager: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete. NetworkManager: <info> Config: set interface ap_scan to 1 NetworkManager: <info> (wlan0): supplicant connection state: scanning -> disconnected NetworkManager: <info> (wlan0): supplicant connection state: disconnected -> scanning wpa_supplicant[602]: CTRL-EVENT-SCAN-RESULTS wpa_supplicant[602]: Trying to associate with 00:12:34:56:78:90 (SSID='MY-WLAN-AP-SSID' freq=2462 MHz) NetworkManager: <info> (wlan0): supplicant connection state: scanning -> associating wpa_supplicant[602]: Associated with 00:12:34:56:78:90 kernel: [ 103.196546] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready NetworkManager: <info> (wlan0): supplicant connection state: associating -> associated NetworkManager: <info> (wlan0): supplicant connection state: associated -> 4-way handshake NetworkManager: <info> (wlan0): supplicant connection state: 4-way handshake -> group handshake NetworkManager: <info> (wlan0): supplicant connection state: group handshake -> 4-way handshake NetworkManager: <info> (wlan0): supplicant connection state: 4-way handshake -> group handshake avahi-daemon[513]: Registering new address record for fe80::20d:bff:fe77:bf4e on wlan0.*. NetworkManager: <info> (wlan0): supplicant connection state: group handshake -> 4-way handshake NetworkManager: <info> (wlan0): supplicant connection state: 4-way handshake -> group handshake NetworkManager: <info> (wlan0): supplicant connection state: group handshake -> 4-way handshake NetworkManager: <info> (wlan0): supplicant connection state: 4-way handshake -> group handshake NetworkManager: <info> (wlan0): supplicant connection state: group handshake -> 4-way handshake NetworkManager: <info> (wlan0): supplicant connection state: 4-way handshake -> group handshake NetworkManager: <info> (wlan0): supplicant connection state: group handshake -> 4-way handshake NetworkManager: <info> (wlan0): supplicant connection state: 4-way handshake -> group handshake NetworkManager: <info> wlan0: link timed out. NetworkManager: <info> (wlan0): supplicant connection state: group handshake -> 4-way handshake NetworkManager: <info> (wlan0): supplicant connection state: 4-way handshake -> group handshake wpa_supplicant[602]: WPA: Key negotiation completed with 00:12:34:56:78:90 [PTK=TKIP GTK=TKIP] wpa_supplicant[602]: CTRL-EVENT-CONNECTED - Connection to 00:12:34:56:78:90 completed (auth) [id=0 id_str=] NetworkManager: <info> (wlan0): supplicant connection state: group handshake -> completed NetworkManager: <info> Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful. Connected to wireless network 'MY-WLAN-AP-SSID'. NetworkManager: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled. NetworkManager: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) started... NetworkManager: <info> (wlan0): device state change: 5 -> 7 (reason 0) NetworkManager: <info> Activation (wlan0) Beginning DHCP transaction (timeout in 45 seconds) NetworkManager: <info> dhclient started with pid 1851 NetworkManager: <info> Activation (wlan0) Stage 4 of 5 (IP6 Configure Get) scheduled... NetworkManager: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete. NetworkManager: <info> Activation (wlan0) Stage 4 of 5 (IP6 Configure Get) started... NetworkManager: <info> Activation (wlan0) Stage 4 of 5 (IP6 Configure Get) complete. dhclient: Internet Systems Consortium DHCP Client V3.1.2 dhclient: Copyright 2004-2008 Internet Systems Consortium. dhclient: All rights reserved. dhclient: For info, please visit http://www.isc.org/sw/dhcp/ dhclient: dhclient: Listening on LPF/wlan0/00:98:76:54:32:10 dhclient: Sending on LPF/wlan0/00:98:76:54:32:10 dhclient: Sending on Socket/fallback dhclient: DHCPREQUEST of 192.168.1.212 on wlan0 to 255.255.255.255 port 67 NetworkManager: <info> DHCP: device wlan0 state changed (null) -> preinit kernel: [ 113.260046] wlan0: no IPv6 routers present dhclient: DHCPREQUEST of 192.168.1.212 on wlan0 to 255.255.255.255 port 67 wpa_supplicant[602]: CTRL-EVENT-SCAN-RESULTS dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 8 wpa_supplicant[602]: Associated with 00:12:34:56:78:90 NetworkManager: <info> (wlan0): supplicant connection state: completed -> associated NetworkManager: <info> (wlan0): supplicant connection state: associated -> 4-way handshake NetworkManager: <info> (wlan0): supplicant connection state: 4-way handshake -> group handshake NetworkManager: <info> (wlan0): supplicant connection state: group handshake -> 4-way handshake NetworkManager: <info> (wlan0): supplicant connection state: 4-way handshake -> group handshake NetworkManager: <info> (wlan0): supplicant connection state: group handshake -> 4-way handshake NetworkManager: <info> (wlan0): supplicant connection state: 4-way handshake -> group handshake NetworkManager: <info> (wlan0): supplicant connection state: group handshake -> 4-way handshake NetworkManager: <info> (wlan0): supplicant connection state: 4-way handshake -> group handshake NetworkManager: <info> (wlan0): supplicant connection state: group handshake -> 4-way handshake NetworkManager: <info> (wlan0): supplicant connection state: 4-way handshake -> group handshake NetworkManager: <info> (wlan0): supplicant connection state: group handshake -> 4-way handshake NetworkManager: <info> (wlan0): supplicant connection state: 4-way handshake -> group handshake NetworkManager: <info> (wlan0): supplicant connection state: group handshake -> 4-way handshake NetworkManager: <info> (wlan0): supplicant connection state: 4-way handshake -> group handshake dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 10 wpa_supplicant[602]: WPA: Key negotiation completed with 00:12:34:56:78:90 [PTK=TKIP GTK=TKIP] wpa_supplicant[602]: CTRL-EVENT-CONNECTED - Connection to 00:12:34:56:78:90 completed (reauth) [id=0 id_str=] NetworkManager: <info> (wlan0): supplicant connection state: group handshake -> completed dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 17 NetworkManager: <info> (wlan0): DHCP transaction took too long, stopping it. NetworkManager: <info> (wlan0): canceled DHCP transaction, dhcp client pid 1851 NetworkManager: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Timeout) scheduled... NetworkManager: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Timeout) started... NetworkManager: <info> (wlan0): device state change: 7 -> 9 (reason 5) NetworkManager: <info> Activation (wlan0) failed for access point (MY-WLAN-AP-SSID) NetworkManager: <info> Marking connection 'Auto MY-WLAN-AP-SSID' invalid. NetworkManager: <info> Activation (wlan0) failed. NetworkManager: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Timeout) complete. NetworkManager: <info> (wlan0): device state change: 9 -> 3 (reason 0) NetworkManager: <info> (wlan0): deactivating device (reason: 0). wpa_supplicant[602]: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys wpa_supplicant[602]: CTRL-EVENT-SCAN-RESULTS

暫定的な対処としては、無線LANアクセスポイントに、何か他のデバイス(瞬間起動可能なWindows Mobile機など)で接続すると、その次の端末からの接続はエラーが起こらないと言うのを利用するしかない。実害はそれほど無いので、NetworkManagerなどのfixを待つしかないか…

■ 参考資料
似たような事例はたくさんあるようで…
Networkmanager-plasmoid doesn't work with wpa