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
