Strange wpa_supplicant behaviour

JMearsXS · 2013-09-10 17:29:42

Hello to the Arch linux forums!

Recently, as an exercise in my linux knowledge, I decided to try and build a bootable linux usb from scratch.
in doing so, I pulled binaries from the arch repo packages as that's what runs on my tinkering laptop
during this experiment however, I had to stop as I encountered a somewhat strange bug when trying to get basic wifi networking up, which I thought was really peculiar - I was using arch's kernel, with full access to the modules on disk, and the wifi adapter (an "Intel Coporation PRO/Wireless 2200BG [Calexico2] Network Connection (rev 05)" using the ipw2200 module) had always performed perfectly under all linuxes I have used on the laptop (same one mentioned above, its an old toshiba equium m50).

The basic idea with my bootable usb is that it never leaves the initramfs that I made (modified from arch default) - the usb is mounted to access the binares and libs that I had copied over, but the contents of initramfs are kept (it can survive pulling the usb out, kinda ).
I tried to set up the wireless connection, like so...

[ rootfs / ] # modprobe ipw2200
[ rootfs / ] # modprobe lib80211_crypt_tkip
[ rootfs / ] # modprobe lib80211_crypt_ccmp
Those 3 commands completed w/o errors.
[ rootfs / ] # ip link set eth0 up
checking dmesg afterwards, the firmware was correctly loaded.
then came the broken part...

[ rootfs / ] # wpa_supplicant -B -i eth0 -c /etc/wpa_supplicant/wpa_supplicant.conf
At this point, wpa_supplicant only spits out its usual "Successfully initialised" message. No indication of an error.
however, when I do
[ rootfs / ] # dhcpcd -A eth0

it hangs at obtaining a lease, then times out 30secs later.
thinking something was amiss, I ran wpa_supplicant in the foreground with -dddt parameter, logging to a file.
It then gets stuck in a associate/disassociate loop. I noticed the following rather interesting lines...

1378827650.062814: Driver did not support SIOCSIWENCODEEXT
1378827650.062822: eth0: WPA: Failed to set GTK to the driver (alg=2 keylen=32 keyidx=1)

I had no idea what it was trying to tell me, but I never have this error before...

At this point, I decided to see if I could replicate this. booting from the laptop's internal HDD, I booted the standard archlinux initramfs, but with break=postmount.
this got me to the rescue shell, with /dev/sda1 mounted at /new_root.
I bindmounted /dev, /sys, /proc and /run into the same directories in the real root, then
[ rootfs / ] # chroot /new_root /bin/bash

I then proceeded to load the same modules as before. And again, this same loop.
I though this may have something to do with the fact that the system wasnt running in its normal fashion (normal being init exec on real root).

Then, I decided to try this again, but instead of break=postmount, I used init=/bin/bash.
This, as far as I can deduce from the source code of switch_root (does what it says on the tin ) was no different from the chroot I had before, apart from the contents of rootfs being rm -rf'd before chroot is done.
so, same deal as before, load ipw2200 and wpa crypto modules. Ran wpa_supplicant in foreground without any debug options, just to see if it still got stuck in a loop like before.
BUT this time, lo and behold:
eth0: CTRL-EVENT-CONNECTED - Connection to a0:21:b7:fd:e0:60 completed [id=0 id_str=]

wut?
I ran dhcpcd -A eth0, it completed like it normally would, I could ping my own ip, the router's ip, google's servers as a test...
So what on earth is going on here?
this is really frustrating, as the two different scenarios are virtually identical...
AND YET, the second one succeeeds.

So, I ask of the archlinux forums, has anyone any idea as to why the latter succeeds and the former does not...
I can safely rule out the following:
- need for udev: it wasnt running in any of the experiments.
- hardware problems: the EXACT same modules are loaded in both cases, the adapter itself usually has flawless operation

If anyone wants any more details, I ran wpa_supplicant in both scenarios with -dddt logging to separate files.
My conf file for wpa_supplicant:
network={
ssid="virginmedia5147636"
psk=*snip*
{
The wireless network is a WPA2-PSK network, router being a virgin media tivo superhub.

I really need to crack this one so I can work on my nano-tux usb again

Regards, JMearsXS

Active Build · 2013-09-10 19:55:01

JMearsXS wrote:

[ rootfs / ] # ip link set eth0 up
[ rootfs / ] # wpa_supplicant -B -i eth0 -c /etc/wpa_supplicant/wpa_supplicant.conf

How is your wireless thing related to eth0 (ethernet)?

JMearsXS · 2013-09-11 06:58:20

Ah, i should mention my wireless interface is eth0. Dunno why
It would normally be wlp6s2, i turned off the interface renaming.
(Shouldnt make a difference)
*EDIT* also to avoid confusion, my ethernet is turned off in bios as I dont need it.

Last edited by JMearsXS (2013-09-11 07:03:59)

r0b0t · 2013-09-11 07:21:18

It's eth0 I gues because :
a) you are using proprietary drivers (the eth* part)
b) it happens that the interfaces are switched (i.e ethernet with wireless and wireless with ethernet) there are workarounds available on the wiki

You shouldn't use dhcpcd to get an IP, try dhclient eth0 instead.

Last edited by r0b0t (2013-09-11 07:22:11)

JMearsXS · 2013-09-11 08:06:26

The fact that it's eth0 is not the problem, I believe.
rather, the issue relies with wpa_supplicant.
(I should point out that my wireless works exactly the same with either the normal name (wlp6s2) or the kernel default (eth0).)
This isnt a hardware problem as it performs exactly the same in normal use.
I am trying to find out why wpa_supplicant seemingly does not like working from an initramfs.
As I stated in the original post, in one scenario wpa_supplicant fails, in another it does not - I am trying to find out why, as the two are virtually identical from my standpoint.
(@r0b0t: dhcpcd works fine. eth0 is definetely my wireless card. however this is going off from my original problem.)

Last edited by JMearsXS (2013-09-11 08:09:55)

cfr · 2013-09-11 21:41:48

r0b0t wrote:

You shouldn't use dhcpcd to get an IP, try dhclient eth0 instead.

Do you have any evidence for this? As far as I know, the packages are alternatives.

JMearsXS · 2013-09-12 07:31:17

Well now, dhcpcd works fine for me.
However I dont think my problem has to with dhcp if wpa dont work in the first place
EDIT:
Been doing some testing. This problem appears to happen whenever / is still the initramfs ON ANY computer.
Tried it with two other machines, they also get stuck in an assoc/ disassoc loop.
This rules out hardware quirks, I'm gonna look into wpa_supplicant source, there may be clues in there.

Last edited by JMearsXS (2013-09-12 07:36:42)

skanky · 2013-09-12 09:35:47

JMearsXS wrote:

Well now, dhcpcd works fine for me.
However I dont think my problem has to with dhcp if wpa dont work in the first place
EDIT:
Been doing some testing. This problem appears to happen whenever / is still the initramfs ON ANY computer.
Tried it with two other machines, they also get stuck in an assoc/ disassoc loop.
This rules out hardware quirks, I'm gonna look into wpa_supplicant source, there may be clues in there.

Nothing profound, just thinking out loud:

As there are initramfs runable distros out there, I'm assuming there is a workable solution. You could look at one to see what they do?
The error suggests a driver compatibility issue - but that's obviously not the case generally, so you may want to look at the driver rather than wpa_supplicant?
However knowing what the driver reports to throw that error message would be useful, so the wpa_supplicant source is worth a look.

EDIT:

After doing a little digging, the error suggests that the two modules, ieee80211_crypt_tkip and ieee80211_crypt_ccmp may not be loaded. Might be worth double checking?

Last edited by skanky (2013-09-12 10:33:27)

JMearsXS · 2013-09-12 17:41:54

Yes, the two crypt modules are definitely loaded.
in a moment of paranoia, I modprobe'd the two modules. ran lsmod, they're there. still modprobe'd them again
(Probs. not necessary, I don't usually do this.)
In particular, I should note that the GTK cypher is the TKIP one - note the "Failed to set GTK to the driver" is what throws a spanner in the works in the first place.
If necessary, I can provide the two wpa_supplicant logs - one is the failing one, the other the successful one.
(Note they were both ^C terminated.)

being as I can't attach files (doesn't seem like I can... forgive my noobness else, first thread on forums ), I will post the logs if and when needed for purposes of investigation.

Regards, JM

(EDIT: I don't think its the ipw2200 driver. It functions fine in any other cases, it just seems to be this case when trying to run from initramfs.)

Last edited by JMearsXS (2013-09-12 17:44:49)

skanky · 2013-09-13 08:25:36

You can paste them inside code tags - that way they get scrollbars.

JMearsXS · 2013-09-13 12:39:24

ah, cool... like this?

Hello World!

Will post the logs later when I can get to my laptop.

skanky · 2013-09-13 12:53:27

JMearsXS wrote:

ah, cool... like this?
Hello World!
Will post the logs later when I can get to my laptop.

That's the one.

JMearsXS · 2013-09-13 18:34:24

OK then, Got the logs for you fine people.
First, the failing one, when run from initramfs.
(WARNING possible giant wall of text if i did this wrong :S )

1378827649.631784: wpa_supplicant v2.0
1378827649.631813: Successfully initialized wpa_supplicant
1378827649.631817: Initializing interface 'eth0' conf '/etc/wpa_supplicant/profiles/homewifi.conf' driver 'default' ctrl_interface 'N/A' bridge 'N/A'
1378827649.631824: Configuration file '/etc/wpa_supplicant/profiles/homewifi.conf' -> '/etc/wpa_supplicant/profiles/homewifi.conf'
1378827649.631828: Reading configuration file '/etc/wpa_supplicant/profiles/homewifi.conf'
1378827649.631853: Line: 1 - start of a new network block
1378827649.631864: ssid - hexdump_ascii(len=18):
     76 69 72 67 69 6e 6d 65 64 69 61 35 31 34 37 36   virginmedia51476
     33 36                                             36              
1378827649.631882: PSK - hexdump(len=32): [REMOVED]
1378827649.631896: Priority group 0
1378827649.631899:    id=0 ssid='virginmedia5147636'
1378827649.631942: WEXT: cfg80211-based driver detected
1378827649.631971: wext: interface eth0 phy: phy0
1378827649.632011: rfkill: initial event: idx=0 type=1 op=0 soft=0 hard=0
1378827649.632099: SIOCGIWRANGE: WE(compiled)=22 WE(source)=18 enc_capa=0xf
1378827649.632102:   capabilities: key_mgmt 0xf enc 0x1f flags 0x0
1378827649.632157: netlink: Operstate: linkmode=1, operstate=5
1378827649.641462: eth0: Own MAC address: 00:13:ce:29:a2:cd
1378827649.641466: wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
1378827649.641474: wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0
1378827649.641477: wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0
1378827649.641481: wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0
1378827649.641485: wpa_driver_wext_set_countermeasures
1378827649.641488: eth0: RSN: flushing PMKID list in the driver
1378827649.641496: eth0: Setting scan request: 0 sec 100000 usec
1378827649.641504: WPS: Set UUID for interface eth0
1378827649.641547: WPS: UUID based on MAC address - hexdump(len=16): 98 06 3d bb f3 96 56 59 a5 58 1a c8 0f 06 a3 de
1378827649.644548: EAPOL: SUPP_PAE entering state DISCONNECTED
1378827649.644552: EAPOL: Supplicant port status: Unauthorized
1378827649.644554: EAPOL: KEY_RX entering state NO_KEY_RECEIVE
1378827649.644556: EAPOL: SUPP_BE entering state INITIALIZE
1378827649.644558: EAP: EAP entering state DISABLED
1378827649.644559: EAPOL: Supplicant port status: Unauthorized
1378827649.644561: EAPOL: Supplicant port status: Unauthorized
1378827649.644574: eth0: Added interface eth0
1378827649.644577: eth0: State: DISCONNECTED -> DISCONNECTED
1378827649.644579: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1378827649.644582: netlink: Operstate: linkmode=-1, operstate=5
1378827649.644616: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1378827649.644622: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378827649.644634: WEXT: if_removed already cleared - ignore event
1378827649.644638: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1378827649.644640: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378827649.644648: WEXT: if_removed already cleared - ignore event
1378827649.644650: Wireless event: cmd=0x8b06 len=8
1378827649.644653: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1378827649.644655: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378827649.644663: WEXT: if_removed already cleared - ignore event
1378827649.644664: Wireless event: cmd=0x8b1a len=8
1378827649.741607: eth0: State: DISCONNECTED -> SCANNING
1378827649.741615: eth0: Starting AP scan for wildcard SSID
1378827649.741634: Scan requested (ret=0) - scan timeout 10 seconds
1378827650.011936: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1378827650.011940: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378827650.011951: WEXT: if_removed already cleared - ignore event
1378827650.011952: Wireless event: cmd=0x8b19 len=8
1378827650.011959: eth0: Event SCAN_RESULTS (3) received
1378827650.011983: Received 909 bytes of scan results (3 BSSes)
1378827650.011989: Sorted scan results
1378827650.011991: a0:21:b7:fd:e0:60 freq=2412 qual=37 noise=0 level=-58 flags=0x2
1378827650.011995: IEs - hexdump(len=79): 00 12 76 69 72 67 69 6e 6d 65 64 69 61 35 31 34 37 36 33 36 01 01 6c dd 1c 00 50 f2 01 01 00 00 50 f2 02 02 00 00 50 f2 04 00 50 f2 02 01 00 00 50 f2 02 0c 00 30 18 01 00 00 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 0c 00
1378827650.012075: 00:8e:f2:6a:d7:98 freq=2437 qual=37 noise=0 level=-78 flags=0x2
1378827650.012079: IEs - hexdump(len=79): 00 12 76 69 72 67 69 6e 6d 65 64 69 61 34 37 39 34 34 39 31 01 01 6c dd 1c 00 50 f2 01 01 00 00 50 f2 02 02 00 00 50 f2 04 00 50 f2 02 01 00 00 50 f2 02 0c 00 30 18 01 00 00 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 0c 00
1378827650.012105: 64:70:02:33:c7:6c freq=2412 qual=25 noise=0 level=-84 flags=0x2
1378827650.012109: IEs - hexdump(len=73): 00 0e 54 50 2d 4c 49 4e 4b 5f 33 33 43 37 36 43 01 01 6c dd 1a 00 50 f2 01 01 00 00 50 f2 02 02 00 00 50 f2 02 00 50 f2 04 01 00 00 50 f2 02 30 18 01 00 00 0f ac 02 02 00 00 0f ac 02 00 0f ac 04 01 00 00 0f ac 02 00 00
1378827650.012136: eth0: BSS: Start scan result update 1
1378827650.012142: eth0: BSS: Add new id 0 BSSID a0:21:b7:fd:e0:60 SSID 'virginmedia5147636'
1378827650.012150: eth0: BSS: Add new id 1 BSSID 00:8e:f2:6a:d7:98 SSID 'virginmedia4794491'
1378827650.012155: eth0: BSS: Add new id 2 BSSID 64:70:02:33:c7:6c SSID 'TP-LINK_33C76C'
1378827650.012157: BSS: last_scan_res_used=3/32 last_scan_full=0
1378827650.012160: eth0: New scan results available
1378827650.012171: eth0: Selecting BSS from priority group 0
1378827650.012177: eth0: 0: a0:21:b7:fd:e0:60 ssid='virginmedia5147636' wpa_ie_len=28 rsn_ie_len=24 caps=0x11 level=-58
1378827650.012186: eth0:    selected based on RSN IE
1378827650.012190: eth0:    selected BSS a0:21:b7:fd:e0:60 ssid='virginmedia5147636'
1378827650.012197: eth0: Request association: reassociate: 0  selected: a0:21:b7:fd:e0:60  bssid: 00:00:00:00:00:00  pending: 00:00:00:00:00:00  wpa_state: SCANNING
1378827650.012204: eth0: Trying to associate with a0:21:b7:fd:e0:60 (SSID='virginmedia5147636' freq=2412 MHz)
1378827650.012207: eth0: Cancelling scan request
1378827650.012210: eth0: WPA: clearing own WPA/RSN IE
1378827650.012213: eth0: Automatic auth_alg selection: 0x1
1378827650.012215: RSN: PMKSA cache search - network_ctx=(nil) try_opportunistic=0
1378827650.012218: RSN: Search for BSSID a0:21:b7:fd:e0:60
1378827650.012222: RSN: No PMKSA cache entry found
1378827650.012226: eth0: RSN: using IEEE 802.11i/D9.0
1378827650.012229: eth0: WPA: Selected cipher suites: group 8 pairwise 24 key_mgmt 2 proto 2
1378827650.012231: WPA: set AP WPA IE - hexdump(len=30): dd 1c 00 50 f2 01 01 00 00 50 f2 02 02 00 00 50 f2 04 00 50 f2 02 01 00 00 50 f2 02 0c 00
1378827650.012243: WPA: set AP RSN IE - hexdump(len=26): 30 18 01 00 00 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 0c 00
1378827650.012255: eth0: WPA: using GTK TKIP
1378827650.012257: eth0: WPA: using PTK CCMP
1378827650.012260: eth0: WPA: using KEY_MGMT WPA-PSK
1378827650.012263: WPA: Set own WPA IE default - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1378827650.012274: eth0: No keys have been configured - skip key clearing
1378827650.012277: eth0: State: SCANNING -> ASSOCIATING
1378827650.012279: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1378827650.012281: netlink: Operstate: linkmode=-1, operstate=5
1378827650.012287: Limit connection to BSSID a0:21:b7:fd:e0:60 freq=2412 MHz based on scan results (bssid_set=0)
1378827650.012293: eth0: set_disable_max_amsdu: -1
1378827650.012296: eth0: set_ampdu_factor: -1
1378827650.012298: eth0: set_ampdu_density: -1
1378827650.012300: eth0: set_disable_ht40: 0
1378827650.012302: eth0: set_disable_sgi: 0
1378827650.012304: wpa_driver_wext_associate
1378827650.012320: wpa_driver_wext_set_drop_unencrypted
1378827650.012338: wpa_driver_wext_set_psk
1378827650.012775: eth0: Setting authentication timeout: 10 sec 0 usec
1378827650.012778: EAPOL: External notification - EAP success=0
1378827650.012780: EAPOL: Supplicant port status: Unauthorized
1378827650.012782: EAPOL: External notification - EAP fail=0
1378827650.012783: EAPOL: Supplicant port status: Unauthorized
1378827650.012804: EAPOL: External notification - portControl=Auto
1378827650.012805: EAPOL: Supplicant port status: Unauthorized
1378827650.012809: RSN: Ignored PMKID candidate without preauth flag
1378827650.012813: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1378827650.012816: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378827650.012828: WEXT: if_removed already cleared - ignore event
1378827650.012829: Wireless event: cmd=0x8b1a len=8
1378827650.012833: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1378827650.012835: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378827650.012843: WEXT: if_removed already cleared - ignore event
1378827650.012844: Wireless event: cmd=0x8b06 len=8
1378827650.012847: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1378827650.012849: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378827650.012857: WEXT: if_removed already cleared - ignore event
1378827650.012859: Wireless event: cmd=0x8b04 len=12
1378827650.012861: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1378827650.012864: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378827650.012871: WEXT: if_removed already cleared - ignore event
1378827650.012873: Wireless event: cmd=0x8b1a len=26
1378827650.023655: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1378827650.023658: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378827650.023669: WEXT: if_removed already cleared - ignore event
1378827650.023672: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1378827650.023674: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378827650.023682: WEXT: if_removed already cleared - ignore event
1378827650.023684: Wireless event: cmd=0x8b15 len=20
1378827650.023686: Wireless event: new AP: a0:21:b7:fd:e0:60
1378827650.023690: eth0: Event ASSOC (0) received
1378827650.023696: eth0: State: ASSOCIATING -> ASSOCIATED
1378827650.023697: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1378827650.023700: netlink: Operstate: linkmode=-1, operstate=5
1378827650.023707: eth0: Associated to a new BSS: BSSID=a0:21:b7:fd:e0:60
1378827650.023710: eth0: No keys have been configured - skip key clearing
1378827650.023716: eth0: Associated with a0:21:b7:fd:e0:60
1378827650.023720: eth0: WPA: Association event - clear replay counter
1378827650.023722: eth0: WPA: Clear old PTK
1378827650.023724: EAPOL: External notification - portEnabled=0
1378827650.023726: EAPOL: Supplicant port status: Unauthorized
1378827650.023728: EAPOL: External notification - portValid=0
1378827650.023729: EAPOL: Supplicant port status: Unauthorized
1378827650.023730: EAPOL: External notification - EAP success=0
1378827650.023732: EAPOL: Supplicant port status: Unauthorized
1378827650.023733: EAPOL: External notification - portEnabled=1
1378827650.023735: EAPOL: SUPP_PAE entering state CONNECTING
1378827650.023736: EAPOL: SUPP_BE entering state IDLE
1378827650.023739: eth0: Setting authentication timeout: 10 sec 0 usec
1378827650.023742: eth0: Cancelling scan request
1378827650.036990: eth0: RX EAPOL from a0:21:b7:fd:e0:60
1378827650.036992: RX EAPOL - hexdump(len=121): 02 03 00 75 02 00 8a 00 10 00 00 00 00 00 00 00 00 42 b4 bf cb 12 88 7b df 9a 41 c1 f4 22 2e db de 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 70 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 16 dd 14 00 0f ac 04 d1 f9 9e a0 fe 56 44 d1 0d 29 78 15 9f 70 a2 bc
1378827650.037034: eth0: Setting authentication timeout: 10 sec 0 usec
1378827650.037038: eth0: IEEE 802.1X RX: version=2 type=3 length=117
1378827650.037041: eth0:   EAPOL-Key type=2
1378827650.037047: eth0:   key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)
1378827650.037050: eth0:   key_length=16 key_data_length=22
1378827650.037051:   replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 00
1378827650.037056:   key_nonce - hexdump(len=32): 42 b4 bf cb 12 88 7b df 9a 41 c1 f4 22 2e db de 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 70
1378827650.037066:   key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
1378827650.037092:   key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00
1378827650.037097:   key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
1378827650.037101:   key_mic - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
1378827650.037108: WPA: RX EAPOL-Key - hexdump(len=121): 02 03 00 75 02 00 8a 00 10 00 00 00 00 00 00 00 00 42 b4 bf cb 12 88 7b df 9a 41 c1 f4 22 2e db de 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 70 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 16 dd 14 00 0f ac 04 d1 f9 9e a0 fe 56 44 d1 0d 29 78 15 9f 70 a2 bc
1378827650.037157: eth0: State: ASSOCIATED -> 4WAY_HANDSHAKE
1378827650.037161: eth0: WPA: RX message 1 of 4-Way Handshake from a0:21:b7:fd:e0:60 (ver=2)
1378827650.037163: RSN: msg 1/4 key data - hexdump(len=22): dd 14 00 0f ac 04 d1 f9 9e a0 fe 56 44 d1 0d 29 78 15 9f 70 a2 bc
1378827650.037172: WPA: PMKID in EAPOL-Key - hexdump(len=22): dd 14 00 0f ac 04 d1 f9 9e a0 fe 56 44 d1 0d 29 78 15 9f 70 a2 bc
1378827650.037181: RSN: PMKID from Authenticator - hexdump(len=16): d1 f9 9e a0 fe 56 44 d1 0d 29 78 15 9f 70 a2 bc
1378827650.037189: eth0: RSN: no matching PMKID found
1378827650.037945: WPA: Renewed SNonce - hexdump(len=32): b0 6f a0 8d d8 2a 3a ab df 69 53 78 1e e5 21 b4 47 c6 e2 9a b1 b3 1a 23 25 f4 bd 59 64 c0 1e ea
1378827650.037986: WPA: PTK derivation - A1=00:13:ce:29:a2:cd A2=a0:21:b7:fd:e0:60
1378827650.037991: WPA: Nonce1 - hexdump(len=32): b0 6f a0 8d d8 2a 3a ab df 69 53 78 1e e5 21 b4 47 c6 e2 9a b1 b3 1a 23 25 f4 bd 59 64 c0 1e ea
1378827650.038002: WPA: Nonce2 - hexdump(len=32): 42 b4 bf cb 12 88 7b df 9a 41 c1 f4 22 2e db de 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 70
1378827650.038012: WPA: PMK - hexdump(len=32): [REMOVED]
1378827650.038014: WPA: PTK - hexdump(len=48): [REMOVED]
1378827650.038017: WPA: WPA IE for msg 2/4 - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1378827650.038028: WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 00
1378827650.038034: eth0: WPA: Sending EAPOL-Key 2/4
1378827650.038041: WPA: KCK - hexdump(len=16): [REMOVED]
1378827650.038043: WPA: Derived Key MIC - hexdump(len=16): f9 bb a4 1a 83 d3 f3 5f 3d 5e 60 42 6e 0c f1 9b
1378827650.038049: WPA: TX EAPOL-Key - hexdump(len=121): 01 03 00 75 02 01 0a 00 00 00 00 00 00 00 00 00 00 b0 6f a0 8d d8 2a 3a ab df 69 53 78 1e e5 21 b4 47 c6 e2 9a b1 b3 1a 23 25 f4 bd 59 64 c0 1e ea 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 f9 bb a4 1a 83 d3 f3 5f 3d 5e 60 42 6e 0c f1 9b 00 16 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1378827650.060104: eth0: RX EAPOL from a0:21:b7:fd:e0:60
1378827650.060106: RX EAPOL - hexdump(len=179): 02 03 00 af 02 13 ca 00 10 00 00 00 00 00 00 00 01 42 b4 bf cb 12 88 7b df 9a 41 c1 f4 22 2e db de 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 70 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 71 75 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 b8 d9 0c 66 fe 51 bb e2 f6 63 56 c5 12 ed 0c 37 00 50 2f f7 13 0e 44 bb 06 d3 54 af 7d f7 d9 2a b3 3d 40 ee 78 2d 4a 74 e8 ff 66 a6 29 ad 59 6e 6e 18 92 51 32 1f ae ce b8 a8 92 05 93 23 47 ab 37 59 a2 cd d4 7c a4 a5 f6 60 02 fd 42 3d d8 e2 a3 a7 76 ba 6d 82 a8 0d ed 43 5a 44 d4 c5 cc f0 dd 39
1378827650.060161: eth0: IEEE 802.1X RX: version=2 type=3 length=175
1378827650.060164: eth0:   EAPOL-Key type=2
1378827650.060168: eth0:   key_info 0x13ca (ver=2 keyidx=0 rsvd=0 Pairwise Install Ack MIC Secure Encr)
1378827650.060171: eth0:   key_length=16 key_data_length=80
1378827650.060172:   replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 01
1378827650.060177:   key_nonce - hexdump(len=32): 42 b4 bf cb 12 88 7b df 9a 41 c1 f4 22 2e db de 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 70
1378827650.060187:   key_iv - hexdump(len=16): 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 71
1378827650.060193:   key_rsc - hexdump(ioctl[SIOCSIWENCODEEXT]: Invalid argument
len=8): 75 06 00 00 00 00 00 00
1378827650.060215:   key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
1378827650.060219:   key_mic - hexdump(len=16): b8 d9 0c 66 fe 51 bb e2 f6 63 56 c5 12 ed 0c 37
1378827650.060226: WPA: RX EAPOL-Key - hexdump(len=179): 02 03 00 af 02 13 ca 00 10 00 00 00 00 00 00 00 01 42 b4 bf cb 12 88 7b df 9a 41 c1 f4 22 2e db de 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 70 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 71 75 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 b8 d9 0c 66 fe 51 bb e2 f6 63 56 c5 12 ed 0c 37 00 50 2f f7 13 0e 44 bb 06 d3 54 af 7d f7 d9 2a b3 3d 40 ee 78 2d 4a 74 e8 ff 66 a6 29 ad 59 6e 6e 18 92 51 32 1f ae ce b8 a8 92 05 93 23 47 ab 37 59 a2 cd d4 7c a4 a5 f6 60 02 fd 42 3d d8 e2 a3 a7 76 ba 6d 82 a8 0d ed 43 5a 44 d4 c5 cc f0 dd 39
1378827650.060288: RSN: encrypted key data - hexdump(len=80): 2f f7 13 0e 44 bb 06 d3 54 af 7d f7 d9 2a b3 3d 40 ee 78 2d 4a 74 e8 ff 66 a6 29 ad 59 6e 6e 18 92 51 32 1f ae ce b8 a8 92 05 93 23 47 ab 37 59 a2 cd d4 7c a4 a5 f6 60 02 fd 42 3d d8 e2 a3 a7 76 ba 6d 82 a8 0d ed 43 5a 44 d4 c5 cc f0 dd 39
1378827650.060368: WPA: decrypted EAPOL-Key key data - hexdump(len=72): [REMOVED]
1378827650.060371: eth0: State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE
1378827650.060375: eth0: WPA: RX message 3 of 4-Way Handshake from a0:21:b7:fd:e0:60 (ver=2)
1378827650.060377: WPA: IE KeyData - hexdump(len=72): 30 18 01 00 00 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 0c 00 dd 26 00 0f ac 01 01 00 15 47 e0 ec c9 4a ff ac 08 71 9f be 41 ca 95 e8 76 80 ce fe 14 4e 0f 37 e5 96 01 10 5f ba ac a9 dd 00 00 00 00 00
1378827650.060401: WPA: RSN IE in EAPOL-Key - hexdump(len=26): 30 18 01 00 00 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 0c 00
1378827650.060412: WPA: GTK in EAPOL-Key - hexdump(len=40): [REMOVED]
1378827650.060416: eth0: WPA: Sending EAPOL-Key 4/4
1378827650.060422: WPA: KCK - hexdump(len=16): [REMOVED]
1378827650.060424: WPA: Derived Key MIC - hexdump(len=16): ce d4 1b 18 c6 f8 1d 28 80 db a9 db 66 6b ab 75
1378827650.060430: WPA: TX EAPOL-Key - hexdump(len=99): 01 03 00 5f 02 03 0a 00 00 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ce d4 1b 18 c6 f8 1d 28 80 db a9 db 66 6b ab 75 00 00
1378827650.060472: eth0: WPA: Installing PTK to the driver
1378827650.060474: wpa_driver_wext_set_key: alg=3 key_idx=0 set_tx=1 seq_len=6 key_len=16
1378827650.060490: EAPOL: External notification - portValid=1
1378827650.060494: eth0: State: 4WAY_HANDSHAKE -> GROUP_HANDSHAKE
1378827650.060496: RSN: received GTK in pairwise handshake - hexdump(len=34): [REMOVED]
1378827650.060499: WPA: Group Key - hexdump(len=32): [REMOVED]
1378827650.060502: eth0: WPA: Installing GTK to the driver (keyidx=1 tx=0 len=32)
1378827650.060503: WPA: RSC - hexdump(len=6): 75 06 00 00 00 00
1378827650.060507: wpa_driver_wext_set_key: alg=2 key_idx=1 set_tx=0 seq_len=6 key_len=32
1378827650.062814: Driver did not support SIOCSIWENCODEEXT
1378827650.062822: eth0: WPA: Failed to set GTK to the driver (alg=2 keylen=32 keyidx=1)
1378827650.062824: eth0: RSN: Failed to install GTK
1378827650.062827: eth0: RSN: Failed to configure GTK
1378827650.062833: eth0: Request to deauthenticate - bssid=a0:21:b7:fd:e0:60 pending_bssid=00:00:00:00:00:00 reason=1 state=GROUP_HANDSHAKE
1378827650.062835: wpa_driver_wext_deauthenticate
1378827650.063974: eth0: Event DEAUTH (12) received
1378827650.063978: eth0: Deauthentication notification
1378827650.063980: eth0:  * reason 1 (locally generated)
1378827650.063982: Deauthentication frame IE(s) - hexdump(len=0): [NULL]
1378827650.063987: eth0: CTRL-EVENT-DISCONNECTED bssid=a0:21:b7:fd:e0:60 reason=1 locally_generated=1
1378827650.063993: eth0: Auto connect enabled: try to reconnect (wps=0 wpa_state=8)
1378827650.063996: eth0: Setting scan request: 0 sec 100000 usec
1378827650.064000: Added BSSID a0:21:b7:fd:e0:60 into blacklist
1378827650.064006: eth0: Blacklist count 1 --> request scan in 100 ms
1378827650.064035: eth0: Setting scan request: 0 sec 100000 usec
1378827650.064039: eth0: Disconnect event - remove keys
1378827650.064041: wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
1378827650.064048: wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0
1378827650.064052: wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0
1378827650.064056: wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0
1378827650.064059: wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
1378827650.064067: eth0: State: GROUP_HANDSHAKE -> DISCONNECTED
1378827650.064069: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1378827650.064071: netlink: Operstate: linkmode=-1, operstate=5
1378827650.064083: EAPOL: External notification - portEnabled=0
1378827650.064085: EAPOL: SUPP_PAE entering state DISCONNECTED
1378827650.064087: EAPOL: Supplicant port status: Unauthorized
1378827650.064088: EAPOL: SUPP_BE entering state INITIALIZE
1378827650.064090: EAPOL: Supplicant port status: Unauthorized
1378827650.064092: EAPOL: External notification - portValid=0
1378827650.064093: EAPOL: Supplicant port status: Unauthorized
1378827650.064095: EAPOL: External notification - EAP success=0
1378827650.064096: EAPOL: Supplicant port status: Unauthorized
1378827650.064098: eth0: No keys have been configured - skip key clearing
1378827650.064101: eth0: State: DISCONNECTED -> DISCONNECTED
1378827650.064103: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1378827650.064105: netlink: Operstate: linkmode=-1, operstate=5
1378827650.064109: EAPOL: External notification - portEnabled=0
1378827650.064110: EAPOL: Supplicant port status: Unauthorized
1378827650.064112: EAPOL: External notification - portValid=0
1378827650.064113: EAPOL: Supplicant port status: Unauthorized
1378827650.064117: eth0: Setting scan request: 5 sec 0 usec
1378827650.067469: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1378827650.067473: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378827650.067490: WEXT: if_removed already cleared - ignore event
1378827650.067492: Wireless event: cmd=0x8b1a len=8
1378827650.067495: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1378827650.067497: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378827650.067506: WEXT: if_removed already cleared - ignore event
1378827650.067507: Wireless event: cmd=0x8b15 len=20
1378827650.067509: Wireless event: new AP: 00:00:00:00:00:00
1378827650.067514: eth0: Event DISASSOC (1) received
1378827650.067517: eth0: Disassociation notification
1378827650.067520: eth0: Auto connect enabled: try to reconnect (wps=0 wpa_state=0)
1378827650.067522: eth0: Do not request new immediate scan
1378827650.067525: eth0: Disconnect event - remove keys
1378827650.067527: wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
1378827650.067532: wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0
1378827650.067548: wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0
1378827650.067552: wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0
1378827650.067556: wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
1378827650.067561: eth0: State: DISCONNECTED -> DISCONNECTED
1378827650.067563: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1378827650.067565: netlink: Operstate: linkmode=-1, operstate=5
1378827650.067570: EAPOL: External notification - portEnabled=0
1378827650.067572: EAPOL: Supplicant port status: Unauthorized
1378827650.067573: EAPOL: External notification - portValid=0
1378827650.067575: EAPOL: Supplicant port status: Unauthorized
1378827650.645151: EAPOL: startWhen --> 0
1378827650.645154: EAPOL: disable timer tick
1378827650.645155: EAPOL: Supplicant port status: Unauthorized
1378827651.024787: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1378827651.024791: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378827651.024802: WEXT: if_removed already cleared - ignore event
1378827654.744916: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1378827654.745899: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378827654.745911: WEXT: if_removed already cleared - ignore event
1378827654.745913: Wireless event: cmd=0x8b19 len=8
1378827654.745918: eth0: Event SCAN_RESULTS (3) received
1378827654.745943: Received 912 bytes of scan results (3 BSSes)
1378827654.745947: Sorted scan results
1378827654.745949: a0:21:b7:fd:e0:60 freq=2412 qual=70 noise=0 level=-55 flags=0x2
1378827654.745952: IEs - hexdump(len=79): 00 12 76 69 72 67 69 6e 6d 65 64 69 61 35 31 34 37 36 33 36 01 01 6c dd 1c 00 50 f2 01 01 00 00 50 f2 02 02 00 00 50 f2 04 00 50 f2 02 01 00 00 50 f2 02 0c 00 30 18 01 00 00 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 0c 00
1378827654.745980: 00:8e:f2:6a:d7:98 freq=2437 qual=37 noise=0 level=-78 flags=0x2
1378827654.745983: IEs - hexdump(len=79): 00 12 76 69 72 67 69 6e 6d 65 64 69 61 34 37 39 34 34 39 31 01 01 6c dd 1c 00 50 f2 01 01 00 00 50 f2 02 02 00 00 50 f2 04 00 50 f2 02 01 00 00 50 f2 02 0c 00 30 18 01 00 00 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 0c 00
1378827654.746010: 64:70:02:33:c7:6c freq=2412 qual=25 noise=0 level=-84 flags=0x2
1378827654.746014: IEs - hexdump(len=73): 00 0e 54 50 2d 4c 49 4e 4b 5f 33 33 43 37 36 43 01 01 6c dd 1a 00 50 f2 01 01 00 00 50 f2 02 02 00 00 50 f2 02 00 50 f2 04 01 00 00 50 f2 02 30 18 01 00 00 0f ac 02 02 00 00 0f ac 02 00 0f ac 04 01 00 00 0f ac 02 00 00
1378827654.746040: eth0: BSS: Start scan result update 2
1378827654.746051: BSS: last_scan_res_used=3/32 last_scan_full=0
1378827654.746054: eth0: New scan results available
1378827654.746061: eth0: Selecting BSS from priority group 0
1378827654.746067: eth0: 0: a0:21:b7:fd:e0:60 ssid='virginmedia5147636' wpa_ie_len=28 rsn_ie_len=24 caps=0x11 level=-55
1378827654.746070: eth0:    skip - blacklisted (count=1 limit=0)
1378827654.746075: eth0: 1: 00:8e:f2:6a:d7:98 ssid='virginmedia4794491' wpa_ie_len=28 rsn_ie_len=24 caps=0x11 level=-78
1378827654.746079: eth0:    skip - SSID mismatch
1378827654.746084: eth0: 2: 64:70:02:33:c7:6c ssid='TP-LINK_33C76C' wpa_ie_len=26 rsn_ie_len=24 caps=0x11 level=-84
1378827654.746086: eth0:    skip - SSID mismatch
1378827654.746089: eth0: No APs found - clear blacklist and try again
1378827654.746090: Removed BSSID a0:21:b7:fd:e0:60 from blacklist (clear)
1378827654.746094: eth0: Selecting BSS from priority group 0
1378827654.746099: eth0: 0: a0:21:b7:fd:e0:60 ssid='virginmedia5147636' wpa_ie_len=28 rsn_ie_len=24 caps=0x11 level=-55
1378827654.746103: eth0:    selected based on RSN IE
1378827654.746107: eth0:    selected BSS a0:21:b7:fd:e0:60 ssid='virginmedia5147636'
1378827654.746115: eth0: Request association: reassociate: 0  selected: a0:21:b7:fd:e0:60  bssid: 00:00:00:00:00:00  pending: 00:00:00:00:00:00  wpa_state: DISCONNECTED
1378827654.746119: eth0: Trying to associate with a0:21:b7:fd:e0:60 (SSID='virginmedia5147636' freq=2412 MHz)
1378827654.746122: eth0: Cancelling scan request
1378827654.746125: eth0: WPA: clearing own WPA/RSN IE
1378827654.746127: eth0: Automatic auth_alg selection: 0x1
1378827654.746129: RSN: PMKSA cache search - network_ctx=(nil) try_opportunistic=0
1378827654.746131: RSN: Search for BSSID a0:21:b7:fd:e0:60
1378827654.746134: RSN: No PMKSA cache entry found
1378827654.746136: eth0: RSN: using IEEE 802.11i/D9.0
1378827654.746139: eth0: WPA: Selected cipher suites: group 8 pairwise 24 key_mgmt 2 proto 2
1378827654.746141: WPA: set AP WPA IE - hexdump(len=30): dd 1c 00 50 f2 01 01 00 00 50 f2 02 02 00 00 50 f2 04 00 50 f2 02 01 00 00 50 f2 02 0c 00
1378827654.746153: WPA: set AP RSN IE - hexdump(len=26): 30 18 01 00 00 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 0c 00
1378827654.746164: eth0: WPA: using GTK TKIP
1378827654.746166: eth0: WPA: using PTK CCMP
1378827654.746168: eth0: WPA: using KEY_MGMT WPA-PSK
1378827654.746170: WPA: Set own WPA IE default - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1378827654.746181: eth0: No keys have been configured - skip key clearing
1378827654.746183: eth0: State: DISCONNECTED -> ASSOCIATING
1378827654.746211: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1378827654.746213: netlink: Operstate: linkmode=-1, operstate=5
1378827654.746220: Limit connection to BSSID a0:21:b7:fd:e0:60 freq=2412 MHz based on scan results (bssid_set=0)
1378827654.746225: eth0: set_disable_max_amsdu: -1
1378827654.746228: eth0: set_ampdu_factor: -1
1378827654.746230: eth0: set_ampdu_density: -1
1378827654.746232: eth0: set_disable_ht40: 0
1378827654.746234: eth0: set_disable_sgi: 0
1378827654.746236: wpa_driver_wext_associate
1378827654.746244: wpa_driver_wext_set_drop_unencrypted
1378827654.746255: wpa_driver_wext_set_psk
1378827654.746678: eth0: Setting authentication timeout: 10 sec 0 usec
1378827654.746682: EAPOL: External notification - EAP success=0
1378827654.746683: EAPOL: Supplicant port status: Unauthorized
1378827654.746685: EAPOL: External notification - EAP fail=0
1378827654.746687: EAPOL: Supplicant port status: Unauthorized
1378827654.746688: EAPOL: External notification - portControl=Auto
1378827654.746689: EAPOL: Supplicant port status: Unauthorized
1378827654.746709: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1378827654.746712: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378827654.746723: WEXT: if_removed already cleared - ignore event
1378827654.746725: Wireless event: cmd=0x8b1a len=8
1378827654.746740: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1378827654.746743: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378827654.746753: WEXT: if_removed already cleared - ignore event
1378827654.746754: Wireless event: cmd=0x8b06 len=8
1378827654.746769: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1378827654.746772: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378827654.746781: WEXT: if_removed already cleared - ignore event
1378827654.746782: Wireless event: cmd=0x8b04 len=12
1378827654.746797: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1378827654.746800: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378827654.746809: WEXT: if_removed already cleared - ignore event
1378827654.746810: Wireless event: cmd=0x8b1a len=26
1378827654.755105: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1378827654.755109: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378827654.755119: WEXT: if_removed already cleared - ignore event
1378827654.755134: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1378827654.755136: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378827654.755145: WEXT: if_removed already cleared - ignore event
1378827654.755147: Wireless event: cmd=0x8b15 len=20
1378827654.755148: Wireless event: new AP: a0:21:b7:fd:e0:60
1378827654.755153: eth0: Event ASSOC (0) received
1378827654.755158: eth0: State: ASSOCIATING -> ASSOCIATED
1378827654.755159: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1378827654.755162: netlink: Operstate: linkmode=-1, operstate=5
1378827654.755169: eth0: Associated to a new BSS: BSSID=a0:21:b7:fd:e0:60
1378827654.755172: eth0: No keys have been configured - skip key clearing
1378827654.755175: eth0: Associated with a0:21:b7:fd:e0:60
1378827654.755178: eth0: WPA: Association event - clear replay counter
1378827654.755180: eth0: WPA: Clear old PTK
1378827654.755182: EAPOL: External notification - portEnabled=0
1378827654.755183: EAPOL: Supplicant port status: Unauthorized
1378827654.755185: EAPOL: External notification - portValid=0
1378827654.755186: EAPOL: Supplicant port status: Unauthorized
1378827654.755188: EAPOL: External notification - EAP success=0
1378827654.755189: EAPOL: Supplicant port status: Unauthorized
1378827654.755190: EAPOL: External notification - portEnabled=1
1378827654.755192: EAPOL: SUPP_PAE entering state CONNECTING
1378827654.755193: EAPOL: enable timer tick
1378827654.755195: EAPOL: SUPP_BE entering state IDLE
1378827654.755198: eth0: Setting authentication timeout: 10 sec 0 usec
1378827654.755201: eth0: Cancelling scan request
1378827654.767455: eth0: RX EAPOL from a0:21:b7:fd:e0:60
1378827654.767457: RX EAPOL - hexdump(len=121): 02 03 00 75 02 00 8a 00 10 00 00 00 00 00 00 00 00 42 b4 bf cb 12 88 7b df 9a 41 c1 f4 22 2e db de 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 71 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 16 dd 14 00 0f ac 04 d1 f9 9e a0 fe 56 44 d1 0d 29 78 15 9f 70 a2 bc
1378827654.767527: eth0: Setting authentication timeout: 10 sec 0 usec
1378827654.767531: eth0: IEEE 802.1X RX: version=2 type=3 length=117
1378827654.767534: eth0:   EAPOL-Key type=2
1378827654.767538: eth0:   key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)
1378827654.767540: eth0:   key_length=16 key_data_length=22
1378827654.767542:   replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 00
1378827654.767546:   key_nonce - hexdump(len=32): 42 b4 bf cb 12 88 7b df 9a 41 c1 f4 22 2e db de 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 71
1378827654.767557:   key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
1378827654.767564:   key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00
1378827654.767568:   key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
1378827654.767572:   key_mic - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
1378827654.767580: WPA: RX EAPOL-Key - hexdump(len=121): 02 03 00 75 02 00 8a 00 10 00 00 00 00 00 00 00 00 42 b4 bf cb 12 88 7b df 9a 41 c1 f4 22 2e db de 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 71 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 16 dd 14 00 0f ac 04 d1 f9 9e a0 fe 56 44 d1 0d 29 78 15 9f 70 a2 bc
1378827654.767625: eth0: State: ASSOCIATED -> 4WAY_HANDSHAKE
1378827654.767629: eth0: WPA: RX message 1 of 4-Way Handshake from a0:21:b7:fd:e0:60 (ver=2)
1378827654.767631: RSN: msg 1/4 key data - hexdump(len=22): dd 14 00 0f ac 04 d1 f9 9e a0 fe 56 44 d1 0d 29 78 15 9f 70 a2 bc
1378827654.767640: WPA: PMKID in EAPOL-Key - hexdump(len=22): dd 14 00 0f ac 04 d1 f9 9e a0 fe 56 44 d1 0d 29 78 15 9f 70 a2 bc
1378827654.767648: RSN: PMKID from Authenticator - hexdump(len=16): d1 f9 9e a0 fe 56 44 d1 0d 29 78 15 9f 70 a2 bc
1378827654.767655: eth0: RSN: no matching PMKID found
1378827654.768416: WPA: Renewed SNonce - hexdump(len=32): a6 f3 31 0a a0 6f 32 86 95 b0 bc 3e 90 16 5e d0 d1 15 af 3b 37 99 5b 60 63 f6 48 37 86 ee fb dd
1378827654.768450: WPA: PTK derivation - A1=00:13:ce:29:a2:cd A2=a0:21:b7:fd:e0:60
1378827654.768455: WPA: Nonce1 - hexdump(len=32): a6 f3 31 0a a0 6f 32 86 95 b0 bc 3e 90 16 5e d0 d1 15 af 3b 37 99 5b 60 63 f6 48 37 86 ee fb dd
1378827654.768465: WPA: Nonce2 - hexdump(len=32): 42 b4 bf cb 12 88 7b df 9a 41 c1 f4 22 2e db de 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 71
1378827654.768476: WPA: PMK - hexdump(len=32): [REMOVED]
1378827654.768477: WPA: PTK - hexdump(len=48): [REMOVED]
1378827654.768479: WPA: WPA IE for msg 2/4 - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1378827654.768489: WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 00
1378827654.768494: eth0: WPA: Sending EAPOL-Key 2/4
1378827654.768501: WPA: KCK - hexdump(len=16): [REMOVED]
1378827654.768503: WPA: Derived Key MIC - hexdump(len=16): 6d 14 6c 86 69 93 f3 f3 3d a9 02 d5 bd 28 c2 cb
1378827654.768509: WPA: TX EAPOL-Key - hexdump(len=121): 01 03 00 75 02 01 0a 00 00 00 00 00 00 00 00 00 00 a6 f3 31 0a a0 6f 32 86 95 b0 bc 3e 90 16 5e d0 d1 15 af 3b 37 99 5b 60 63 f6 48 37 86 ee fb dd 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 6d 14 6c 86 69 93 f3 f3 3d a9 02 d5 bd 28 c2 cb 00 16 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1378827654.796851: eth0: RX EAPOL from a0:21:b7:fd:e0:60
1378827654.796853: RX EAPOL - hexdump(len=179): 02 03 00 af 02 13 ca 00 10 00 00 00 00 00 00 00 01 42 b4 bf cb 12 88 7b df 9a 41 c1 f4 22 2e db de 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 71 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 72 75 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0b 99 b2 ioctl[SIOCSIWENCODEEXT]: Invalid argument
c0 8a 84 75 16 7a 00 2b 94 29 21 e7 73 00 50 b7 46 c5 03 e0 d8 40 00 c6 26 ca 43 d0 8d 3d 64 85 b2 32 43 61 d2 37 83 37 8c e8 64 13 83 62 6e b3 60 e5 4e 6e 17 00 e9 3b e4 e3 f7 22 3e 9a 0a fd b5 52 a9 ce d6 c4 02 a5 aa c2 d7 2f b2 e2 19 68 2a 35 a8 0c 6c f6 7c 59 9d 71 b2 8d e4 b4 46
1378827654.796937: eth0: IEEE 802.1X RX: version=2 type=3 length=175
1378827654.796940: eth0:   EAPOL-Key type=2
1378827654.796944: eth0:   key_info 0x13ca (ver=2 keyidx=0 rsvd=0 Pairwise Install Ack MIC Secure Encr)
1378827654.796946: eth0:   key_length=16 key_data_length=80
1378827654.796948:   replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 01
1378827654.796952:   key_nonce - hexdump(len=32): 42 b4 bf cb 12 88 7b df 9a 41 c1 f4 22 2e db de 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 71
1378827654.796963:   key_iv - hexdump(len=16): 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 72
1378827654.796969:   key_rsc - hexdump(len=8): 75 06 00 00 00 00 00 00
1378827654.796973:   key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
1378827654.796977:   key_mic - hexdump(len=16): 0b 99 b2 c0 8a 84 75 16 7a 00 2b 94 29 21 e7 73
1378827654.796984: WPA: RX EAPOL-Key - hexdump(len=179): 02 03 00 af 02 13 ca 00 10 00 00 00 00 00 00 00 01 42 b4 bf cb 12 88 7b df 9a 41 c1 f4 22 2e db de 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 71 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 72 75 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0b 99 b2 c0 8a 84 75 16 7a 00 2b 94 29 21 e7 73 00 50 b7 46 c5 03 e0 d8 40 00 c6 26 ca 43 d0 8d 3d 64 85 b2 32 43 61 d2 37 83 37 8c e8 64 13 83 62 6e b3 60 e5 4e 6e 17 00 e9 3b e4 e3 f7 22 3e 9a 0a fd b5 52 a9 ce d6 c4 02 a5 aa c2 d7 2f b2 e2 19 68 2a 35 a8 0c 6c f6 7c 59 9d 71 b2 8d e4 b4 46
1378827654.797045: RSN: encrypted key data - hexdump(len=80): b7 46 c5 03 e0 d8 40 00 c6 26 ca 43 d0 8d 3d 64 85 b2 32 43 61 d2 37 83 37 8c e8 64 13 83 62 6e b3 60 e5 4e 6e 17 00 e9 3b e4 e3 f7 22 3e 9a 0a fd b5 52 a9 ce d6 c4 02 a5 aa c2 d7 2f b2 e2 19 68 2a 35 a8 0c 6c f6 7c 59 9d 71 b2 8d e4 b4 46
1378827654.797108: WPA: decrypted EAPOL-Key key data - hexdump(len=72): [REMOVED]
1378827654.797111: eth0: State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE
1378827654.797115: eth0: WPA: RX message 3 of 4-Way Handshake from a0:21:b7:fd:e0:60 (ver=2)
1378827654.797117: WPA: IE KeyData - hexdump(len=72): 30 18 01 00 00 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 0c 00 dd 26 00 0f ac 01 01 00 15 47 e0 ec c9 4a ff ac 08 71 9f be 41 ca 95 e8 76 80 ce fe 14 4e 0f 37 e5 96 01 10 5f ba ac a9 dd 00 00 00 00 00
1378827654.797141: WPA: RSN IE in EAPOL-Key - hexdump(len=26): 30 18 01 00 00 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 0c 00
1378827654.797151: WPA: GTK in EAPOL-Key - hexdump(len=40): [REMOVED]
1378827654.797155: eth0: WPA: Sending EAPOL-Key 4/4
1378827654.797161: WPA: KCK - hexdump(len=16): [REMOVED]
1378827654.797163: WPA: Derived Key MIC - hexdump(len=16): 9c 27 39 8f 41 e6 4c a3 44 1d f4 32 94 ab 3d 7d
1378827654.797169: WPA: TX EAPOL-Key - hexdump(len=99): 01 03 00 5f 02 03 0a 00 00 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 9c 27 39 8f 41 e6 4c a3 44 1d f4 32 94 ab 3d 7d 00 00
1378827654.797210: eth0: WPA: Installing PTK to the driver
1378827654.797213: wpa_driver_wext_set_key: alg=3 key_idx=0 set_tx=1 seq_len=6 key_len=16
1378827654.797224: EAPOL: External notification - portValid=1
1378827654.797228: eth0: State: 4WAY_HANDSHAKE -> GROUP_HANDSHAKE
1378827654.797230: RSN: received GTK in pairwise handshake - hexdump(len=34): [REMOVED]
1378827654.797232: WPA: Group Key - hexdump(len=32): [REMOVED]
1378827654.797235: eth0: WPA: Installing GTK to the driver (keyidx=1 tx=0 len=32)
1378827654.797237: WPA: RSC - hexdump(len=6): 75 06 00 00 00 00
1378827654.797240: wpa_driver_wext_set_key: alg=2 key_idx=1 set_tx=0 seq_len=6 key_len=32
1378827654.799335: Driver did not support SIOCSIWENCODEEXT
1378827654.799340: eth0: WPA: Failed to set GTK to the driver (alg=2 keylen=32 keyidx=1)
1378827654.799368: eth0: RSN: Failed to install GTK
1378827654.799371: eth0: RSN: Failed to configure GTK
1378827654.799377: eth0: Request to deauthenticate - bssid=a0:21:b7:fd:e0:60 pending_bssid=00:00:00:00:00:00 reason=1 state=GROUP_HANDSHAKE
1378827654.799379: wpa_driver_wext_deauthenticate
1378827654.799462: eth0: Event DEAUTH (12) received
1378827654.799465: eth0: Deauthentication notification
1378827654.799467: eth0:  * reason 1 (locally generated)
1378827654.799469: Deauthentication frame IE(s) - hexdump(len=0): [NULL]
1378827654.799474: eth0: CTRL-EVENT-DISCONNECTED bssid=a0:21:b7:fd:e0:60 reason=1 locally_generated=1
1378827654.799477: eth0: Auto connect enabled: try to reconnect (wps=0 wpa_state=8)
1378827654.799480: eth0: Setting scan request: 0 sec 100000 usec
1378827654.799483: Added BSSID a0:21:b7:fd:e0:60 into blacklist
1378827654.799488: eth0: Blacklist count 2 --> request scan in 500 ms
1378827654.799491: eth0: Setting scan request: 0 sec 500000 usec
1378827654.799495: eth0: Disconnect event - remove keys
1378827654.799496: wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
1378827654.799502: wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0
1378827654.799506: wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0
1378827654.799509: wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0
1378827654.799513: wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
1378827654.799519: eth0: State: GROUP_HANDSHAKE -> DISCONNECTED
1378827654.799520: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1378827654.799523: netlink: Operstate: linkmode=-1, operstate=5
1378827654.799531: EAPOL: External notification - portEnabled=0
1378827654.799533: EAPOL: SUPP_PAE entering state DISCONNECTED
1378827654.799534: EAPOL: Supplicant port status: Unauthorized
1378827654.799535: EAPOL: SUPP_BE entering state INITIALIZE
1378827654.799537: EAPOL: Supplicant port status: Unauthorized
1378827654.799538: EAPOL: External notification - portValid=0
1378827654.799540: EAPOL: Supplicant port status: Unauthorized
1378827654.799541: EAPOL: External notification - EAP success=0
1378827654.799542: EAPOL: Supplicant port status: Unauthorized
1378827654.799545: eth0: No keys have been configured - skip key clearing
1378827654.799547: eth0: State: DISCONNECTED -> DISCONNECTED
1378827654.799549: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1378827654.799551: netlink: Operstate: linkmode=-1, operstate=5
1378827654.799555: EAPOL: External notification - portEnabled=0
1378827654.799556: EAPOL: Supplicant port status: Unauthorized
1378827654.799558: EAPOL: External notification - portValid=0
1378827654.799559: EAPOL: Supplicant port status: Unauthorized
1378827654.799562: eth0: Setting scan request: 5 sec 0 usec
1378827654.801428: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1378827654.801432: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378827654.801445: WEXT: if_removed already cleared - ignore event
1378827654.801447: Wireless event: cmd=0x8b1a len=8
1378827654.801986: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1378827654.801989: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378827654.801998: WEXT: if_removed already cleared - ignore event
1378827654.802000: Wireless event: cmd=0x8b15 len=20
1378827654.802002: Wireless event: new AP: 00:00:00:00:00:00
1378827654.802007: eth0: Event DISASSOC (1) received
1378827654.802009: eth0: Disassociation notification
1378827654.802012: eth0: Auto connect enabled: try to reconnect (wps=0 wpa_state=0)
1378827654.802015: eth0: Do not request new immediate scan
1378827654.802017: eth0: Disconnect event - remove keys
1378827654.802019: wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
1378827654.802030: wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0
1378827654.802035: wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0
1378827654.802038: wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0
1378827654.802071: wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
1378827654.802077: eth0: State: DISCONNECTED -> DISCONNECTED
1378827654.802079: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1378827654.802081: netlink: Operstate: linkmode=-1, operstate=5
1378827654.802086: EAPOL: External notification - portEnabled=0
1378827654.802088: EAPOL: Supplicant port status: Unauthorized
1378827654.802090: EAPOL: External notification - portValid=0
1378827654.802091: EAPOL: Supplicant port status: Unauthorized
1378827655.756154: EAPOL: startWhen --> 0
1378827655.756157: EAPOL: disable timer tick
1378827655.756158: EAPOL: Supplicant port status: Unauthorized
1378827655.758116: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1378827655.758120: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378827655.758131: WEXT: if_removed already cleared - ignore event
1378827658.676783: eth0: Removing interface eth0
1378827658.676790: eth0: Request to deauthenticate - bssid=00:00:00:00:00:00 pending_bssid=00:00:00:00:00:00 reason=3 state=DISCONNECTED
1378827658.676793: eth0: No keys have been configured - skip key clearing
1378827658.676796: eth0: State: DISCONNECTED -> DISCONNECTED
1378827658.676798: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1378827658.676800: netlink: Operstate: linkmode=-1, operstate=5
1378827658.676806: EAPOL: External notification - portEnabled=0
1378827658.676808: EAPOL: Supplicant port status: Unauthorized
1378827658.676810: EAPOL: External notification - portValid=0
1378827658.676811: EAPOL: Supplicant port status: Unauthorized
1378827658.676813: wpa_driver_wext_set_countermeasures
1378827658.676817: eth0: No keys have been configured - skip key clearing
1378827658.701645: Removed BSSID a0:21:b7:fd:e0:60 from blacklist (clear)
1378827658.701726: eth0: BSS: Remove id 0 BSSID a0:21:b7:fd:e0:60 SSID 'virginmedia5147636' due to wpa_bss_flush
1378827658.701732: eth0: BSS: Remove id 1 BSSID 00:8e:f2:6a:d7:98 SSID 'virginmedia4794491' due to wpa_bss_flush
1378827658.701736: eth0: BSS: Remove id 2 BSSID 64:70:02:33:c7:6c SSID 'TP-LINK_33C76C' due to wpa_bss_flush
1378827658.701739: eth0: Cancelling scan request
1378827658.701742: eth0: Cancelling authentication timeout
1378827658.701760: netlink: Operstate: linkmode=0, operstate=6
1378827658.701860: eth0: CTRL-EVENT-TERMINATING

Next: the one where it succeeds, AFTER exec'ing switch_root into the real root.

1378828538.454748: wpa_supplicant v2.0
1378828538.466302: Successfully initialized wpa_supplicant
1378828538.466308: Initializing interface 'eth0' conf '/etc/wpa_supplicant/profiles/homewifi.conf' driver 'default' ctrl_interface 'N/A' bridge 'N/A'
1378828538.466316: Configuration file '/etc/wpa_supplicant/profiles/homewifi.conf' -> '/etc/wpa_supplicant/profiles/homewifi.conf'
1378828538.466320: Reading configuration file '/etc/wpa_supplicant/profiles/homewifi.conf'
1378828538.481719: Line: 1 - start of a new network block
1378828538.481732: ssid - hexdump_ascii(len=18):
     76 69 72 67 69 6e 6d 65 64 69 61 35 31 34 37 36   virginmedia51476
     33 36                                             36              
1378828538.481749: PSK - hexdump(len=32): [REMOVED]
1378828538.481766: Priority group 0
1378828538.481769:    id=0 ssid='virginmedia5147636'
1378828538.481841: WEXT: cfg80211-based driver detected
1378828538.481875: wext: interface eth0 phy: phy0
1378828538.481919: rfkill: initial event: idx=0 type=1 op=0 soft=0 hard=0
1378828538.481966: SIOCGIWRANGE: WE(compiled)=22 WE(source)=18 enc_capa=0xf
1378828538.481969:   capabilities: key_mgmt 0xf enc 0x1f flags 0x0
1378828538.482026: netlink: Operstate: linkmode=1, operstate=5
1378828538.510261: eth0: Own MAC address: 00:13:ce:29:a2:cd
1378828538.510265: wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
1378828538.510273: wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0
1378828538.510277: wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0
1378828538.510281: wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0
1378828538.510284: wpa_driver_wext_set_countermeasures
1378828538.510288: eth0: RSN: flushing PMKID list in the driver
1378828538.510297: eth0: Setting scan request: 0 sec 100000 usec
1378828538.510304: WPS: Set UUID for interface eth0
1378828538.539518: WPS: UUID based on MAC address - hexdump(len=16): 98 06 3d bb f3 96 56 59 a5 58 1a c8 0f 06 a3 de
1378828538.570007: EAPOL: SUPP_PAE entering state DISCONNECTED
1378828538.570012: EAPOL: Supplicant port status: Unauthorized
1378828538.570013: EAPOL: KEY_RX entering state NO_KEY_RECEIVE
1378828538.570016: EAPOL: SUPP_BE entering state INITIALIZE
1378828538.570018: EAP: EAP entering state DISABLED
1378828538.570019: EAPOL: Supplicant port status: Unauthorized
1378828538.570021: EAPOL: Supplicant port status: Unauthorized
1378828538.570035: eth0: Added interface eth0
1378828538.570038: eth0: State: DISCONNECTED -> DISCONNECTED
1378828538.570040: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1378828538.570043: netlink: Operstate: linkmode=-1, operstate=5
1378828538.580118: RTM_NEWLINK: operstate=0 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
1378828538.580123: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378828538.580136: WEXT: if_removed already cleared - ignore event
1378828538.580138: Wireless event: cmd=0x8b06 len=8
1378828538.580141: RTM_NEWLINK: operstate=0 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
1378828538.580144: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378828538.580152: WEXT: if_removed already cleared - ignore event
1378828538.580154: Wireless event: cmd=0x8b1a len=8
1378828538.580157: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1378828538.580160: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378828538.580167: WEXT: if_removed already cleared - ignore event
1378828538.610363: eth0: State: DISCONNECTED -> SCANNING
1378828538.610372: eth0: Starting AP scan for wildcard SSID
1378828538.610391: Scan requested (ret=0) - scan timeout 10 seconds
1378828538.881094: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1378828538.881098: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378828538.881109: WEXT: if_removed already cleared - ignore event
1378828538.881111: Wireless event: cmd=0x8b19 len=8
1378828538.881117: eth0: Event SCAN_RESULTS (3) received
1378828538.881136: Received 305 bytes of scan results (1 BSSes)
1378828538.881141: Sorted scan results
1378828538.881142: a0:21:b7:fd:e0:60 freq=2412 qual=70 noise=0 level=-58 flags=0x2
1378828538.881217: IEs - hexdump(len=79): 00 12 76 69 72 67 69 6e 6d 65 64 69 61 35 31 34 37 36 33 36 01 01 6c dd 1c 00 50 f2 01 01 00 00 50 f2 02 02 00 00 50 f2 04 00 50 f2 02 01 00 00 50 f2 02 0c 00 30 18 01 00 00 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 0c 00
1378828538.881247: eth0: BSS: Start scan result update 1
1378828538.881254: eth0: BSS: Add new id 0 BSSID a0:21:b7:fd:e0:60 SSID 'virginmedia5147636'
1378828538.881259: BSS: last_scan_res_used=1/32 last_scan_full=0
1378828538.881262: eth0: New scan results available
1378828538.881272: eth0: Selecting BSS from priority group 0
1378828538.881278: eth0: 0: a0:21:b7:fd:e0:60 ssid='virginmedia5147636' wpa_ie_len=28 rsn_ie_len=24 caps=0x11 level=-58
1378828538.881287: eth0:    selected based on RSN IE
1378828538.881291: eth0:    selected BSS a0:21:b7:fd:e0:60 ssid='virginmedia5147636'
1378828538.881299: eth0: Request association: reassociate: 0  selected: a0:21:b7:fd:e0:60  bssid: 00:00:00:00:00:00  pending: 00:00:00:00:00:00  wpa_state: SCANNING
1378828538.881306: eth0: Trying to associate with a0:21:b7:fd:e0:60 (SSID='virginmedia5147636' freq=2412 MHz)
1378828538.881309: eth0: Cancelling scan request
1378828538.881311: eth0: WPA: clearing own WPA/RSN IE
1378828538.881314: eth0: Automatic auth_alg selection: 0x1
1378828538.881316: RSN: PMKSA cache search - network_ctx=(nil) try_opportunistic=0
1378828538.881320: RSN: Search for BSSID a0:21:b7:fd:e0:60
1378828538.881323: RSN: No PMKSA cache entry found
1378828538.881327: eth0: RSN: using IEEE 802.11i/D9.0
1378828538.881331: eth0: WPA: Selected cipher suites: group 8 pairwise 24 key_mgmt 2 proto 2
1378828538.881332: WPA: set AP WPA IE - hexdump(len=30): dd 1c 00 50 f2 01 01 00 00 50 f2 02 02 00 00 50 f2 04 00 50 f2 02 01 00 00 50 f2 02 0c 00
1378828538.881344: WPA: set AP RSN IE - hexdump(len=26): 30 18 01 00 00 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 0c 00
1378828538.881356: eth0: WPA: using GTK TKIP
1378828538.881358: eth0: WPA: using PTK CCMP
1378828538.881360: eth0: WPA: using KEY_MGMT WPA-PSK
1378828538.881364: WPA: Set own WPA IE default - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1378828538.881375: eth0: No keys have been configured - skip key clearing
1378828538.881377: eth0: State: SCANNING -> ASSOCIATING
1378828538.881379: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1378828538.881381: netlink: Operstate: linkmode=-1, operstate=5
1378828538.881388: Limit connection to BSSID a0:21:b7:fd:e0:60 freq=2412 MHz based on scan results (bssid_set=0)
1378828538.881394: eth0: set_disable_max_amsdu: -1
1378828538.881397: eth0: set_ampdu_factor: -1
1378828538.881399: eth0: set_ampdu_density: -1
1378828538.881401: eth0: set_disable_ht40: 0
1378828538.881403: eth0: set_disable_sgi: 0
1378828538.881405: wpa_driver_wext_associate
1378828538.881421: wpa_driver_wext_set_drop_unencrypted
1378828538.881441: wpa_driver_wext_set_psk
1378828538.881872: eth0: Setting authentication timeout: 10 sec 0 usec
1378828538.881876: EAPOL: External notification - EAP success=0
1378828538.881878: EAPOL: Supplicant port status: Unauthorized
1378828538.881880: EAPOL: External notification - EAP fail=0
1378828538.881881: EAPOL: Supplicant port status: Unauthorized
1378828538.881883: EAPOL: External notification - portControl=Auto
1378828538.881884: EAPOL: Supplicant port status: Unauthorized
1378828538.881888: RSN: Ignored PMKID candidate without preauth flag
1378828538.881892: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1378828538.881895: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378828538.881906: WEXT: if_removed already cleared - ignore event
1378828538.881908: Wireless event: cmd=0x8b1a len=8
1378828538.881911: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1378828538.881913: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378828538.881921: WEXT: if_removed already cleared - ignore event
1378828538.881923: Wireless event: cmd=0x8b06 len=8
1378828538.881925: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1378828538.881945: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378828538.881955: WEXT: if_removed already cleared - ignore event
1378828538.881956: Wireless event: cmd=0x8b04 len=12
1378828538.881960: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1378828538.881962: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378828538.881970: WEXT: if_removed already cleared - ignore event
1378828538.881971: Wireless event: cmd=0x8b1a len=26
1378828538.890285: RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1378828538.890289: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378828538.890299: WEXT: if_removed already cleared - ignore event
1378828538.890301: Wireless event: cmd=0x8b15 len=20
1378828538.890302: Wireless event: new AP: a0:21:b7:fd:e0:60
1378828538.890321: eth0: Event ASSOC (0) received
1378828538.890327: eth0: State: ASSOCIATING -> ASSOCIATED
1378828538.890328: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1378828538.890330: netlink: Operstate: linkmode=-1, operstate=5
1378828538.890338: eth0: Associated to a new BSS: BSSID=a0:21:b7:fd:e0:60
1378828538.890341: eth0: No keys have been configured - skip key clearing
1378828538.890347: eth0: Associated with a0:21:b7:fd:e0:60
1378828538.890350: eth0: WPA: Association event - clear replay counter
1378828538.890352: eth0: WPA: Clear old PTK
1378828538.890354: EAPOL: External notification - portEnabled=0
1378828538.890355: EAPOL: Supplicant port status: Unauthorized
1378828538.890357: EAPOL: External notification - portValid=0
1378828538.890358: EAPOL: Supplicant port status: Unauthorized
1378828538.890360: EAPOL: External notification - EAP success=0
1378828538.890361: EAPOL: Supplicant port status: Unauthorized
1378828538.890363: EAPOL: External notification - portEnabled=1
1378828538.890364: EAPOL: SUPP_PAE entering state CONNECTING
1378828538.890365: EAPOL: SUPP_BE entering state IDLE
1378828538.890368: eth0: Setting authentication timeout: 10 sec 0 usec
1378828538.890371: eth0: Cancelling scan request
1378828538.907595: eth0: RX EAPOL from a0:21:b7:fd:e0:60
1378828538.907597: RX EAPOL - hexdump(len=121): 02 03 00 75 02 00 8a 00 10 00 00 00 00 00 00 00 00 42 b4 bf cb 12 88 7b df 9a 41 c1 f4 22 2e db de 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 83 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 16 dd 14 00 0f ac 04 d1 f9 9e a0 fe 56 44 d1 0d 29 78 15 9f 70 a2 bc
1378828538.907638: eth0: Setting authentication timeout: 10 sec 0 usec
1378828538.907642: eth0: IEEE 802.1X RX: version=2 type=3 length=117
1378828538.907645: eth0:   EAPOL-Key type=2
1378828538.907865: eth0:   key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)
1378828538.907869: eth0:   key_length=16 key_data_length=22
1378828538.907871:   replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 00
1378828538.907875:   key_nonce - hexdump(len=32): 42 b4 bf cb 12 88 7b df 9a 41 c1 f4 22 2e db de 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 83
1378828538.907886:   key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
1378828538.907893:   key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00
1378828538.907897:   key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
1378828538.907902:   key_mic - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
1378828538.907909: WPA: RX EAPOL-Key - hexdump(len=121): 02 03 00 75 02 00 8a 00 10 00 00 00 00 00 00 00 00 42 b4 bf cb 12 88 7b df 9a 41 c1 f4 22 2e db de 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 83 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 16 dd 14 00 0f ac 04 d1 f9 9e a0 fe 56 44 d1 0d 29 78 15 9f 70 a2 bc
1378828538.907957: eth0: State: ASSOCIATED -> 4WAY_HANDSHAKE
1378828538.907962: eth0: WPA: RX message 1 of 4-Way Handshake from a0:21:b7:fd:e0:60 (ver=2)
1378828538.907964: RSN: msg 1/4 key data - hexdump(len=22): dd 14 00 0f ac 04 d1 f9 9e a0 fe 56 44 d1 0d 29 78 15 9f 70 a2 bc
1378828538.907991: WPA: PMKID in EAPOL-Key - hexdump(len=22): dd 14 00 0f ac 04 d1 f9 9e a0 fe 56 44 d1 0d 29 78 15 9f 70 a2 bc
1378828538.908001: RSN: PMKID from Authenticator - hexdump(len=16): d1 f9 9e a0 fe 56 44 d1 0d 29 78 15 9f 70 a2 bc
1378828538.908008: eth0: RSN: no matching PMKID found
1378828538.908768: WPA: Renewed SNonce - hexdump(len=32): c7 e6 f8 80 ab 4d 96 a8 a5 bf 18 23 f5 5f 69 67 56 2d e5 cb 5d 95 7f 2a 55 cb f7 6d 6b 15 32 86
1378828538.908809: WPA: PTK derivation - A1=00:13:ce:29:a2:cd A2=a0:21:b7:fd:e0:60
1378828538.908815: WPA: Nonce1 - hexdump(len=32): c7 e6 f8 80 ab 4d 96 a8 a5 bf 18 23 f5 5f 69 67 56 2d e5 cb 5d 95 7f 2a 55 cb f7 6d 6b 15 32 86
1378828538.908825: WPA: Nonce2 - hexdump(len=32): 42 b4 bf cb 12 88 7b df 9a 41 c1 f4 22 2e db de 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 83
1378828538.908836: WPA: PMK - hexdump(len=32): [REMOVED]
1378828538.908838: WPA: PTK - hexdump(len=48): [REMOVED]
1378828538.908841: WPA: WPA IE for msg 2/4 - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1378828538.908853: WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 00
1378828538.908858: eth0: WPA: Sending EAPOL-Key 2/4
1378828538.908865: WPA: KCK - hexdump(len=16): [REMOVED]
1378828538.908867: WPA: Derived Key MIC - hexdump(len=16): 4f a0 c4 f8 60 aa f2 6f 17 40 07 2e 17 b2 dc dd
1378828538.908873: WPA: TX EAPOL-Key - hexdump(len=121): 01 03 00 75 02 01 0a 00 00 00 00 00 00 00 00 00 00 c7 e6 f8 80 ab 4d 96 a8 a5 bf 18 23 f5 5f 69 67 56 2d e5 cb 5d 95 7f 2a 55 cb f7 6d 6b 15 32 86 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 4f a0 c4 f8 60 aa f2 6f 17 40 07 2e 17 b2 dc dd 00 16 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1378828538.928595: eth0: RX EAPOL from a0:21:b7:fd:e0:60
1378828538.928597: RX EAPOL - hexdump(len=179): 02 03 00 af 02 13 ca 00 10 00 00 00 00 00 00 00 01 42 b4 bf cb 12 88 7b df 9a 41 c1 f4 22 2e db de 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 83 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 84 b3 09 00 00 00 00 00 00 00 00 00 00 00 00 00 00 b3 65 52 19 da b9 c6 64 a6 35 af 4f e2 72 be b1 00 50 8f 66 ed e5 53 ab 0b 67 7c c1 aa 76 1a 4b 42 d9 f3 10 c9 d9 e1 a2 bc 74 9c 31 36 0f 30 31 d2 2c 18 fe fc d8 43 1a f5 bc c5 98 b4 06 81 ba ba 2b 3f 55 8e c6 40 a6 df da c2 f4 30 00 15 7b de 1f 05 fd 0c 3e 44 96 c6 58 6b e3 a8 4c 75 2c a9 b4
1378828538.928652: eth0: IEEE 802.1X RX: version=2 type=3 length=175
1378828538.928655: eth0:   EAPOL-Key type=2
1378828538.928659: eth0:   key_info 0x13ca (ver=2 keyidx=0 rsvd=0 Pairwise Install Ack MIC Secure Encr)
1378828538.928661: eth0:   key_length=16 key_data_length=80
1378828538.928663:   replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 01
1378828538.928667:   key_nonce - hexdump(len=32): 42 b4 bf cb 12 88 7b df 9a 41 c1 f4 22 2e db de 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 83
1378828538.928678:   key_iv - hexdump(len=16): 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 84
1378828538.928684:   key_rsc - hexdump(len=8): b3 09 00 00 00 00 00 00
1378828538.928688:   key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
1378828538.928692:   key_mic - hexdump(len=16): b3 65 52 19 da b9 c6 64 a6 35 af 4f e2 72 be b1
1378828538.928699: WPA: RX EAPOL-Key - hexdump(len=179): 02 03 00 af 02 13 ca 00 10 00 00 00 00 00 00 00 01 42 b4 bf cb 12 88 7b df 9a 41 c1 f4 22 2e db de 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 83 79 13 fe 7f 8a 28 e0 ca d2 8a e7 74 82 e7 d2 84 b3 09 00 00 00 00 00 00 00 00 00 00 00 00 00 00 b3 65 52 19 da b9 c6 64 a6 35 af 4f e2 72 be b1 00 50 8f 66 ed e5 53 ab 0b 67 7c c1 aa 76 1a 4b 42 d9 f3 10 c9 d9 e1 a2 bc 74 9c 31 36 0f 30 31 d2 2c 18 fe fc d8 43 1a f5 bc c5 98 b4 06 81 ba ba 2b 3f 55 8e c6 40 a6 df da c2 f4 30 00 15 7b de 1f 05 fd 0c 3e 44 96 c6 58 6b e3 a8 4c 75 2c a9 b4
1378828538.928760: RSN: encrypted key data - hexdump(len=80): 8f 66 ed e5 53 ab 0b 67 7c c1 aa 76 1a 4b 42 d9 f3 10 c9 d9 e1 a2 bc 74 9c 31 36 0f 30 31 d2 2c 18 fe fc d8 43 1a f5 bc c5 98 b4 06 81 ba ba 2b 3f 55 8e c6 40 a6 df da c2 f4 30 00 15 7b de 1f 05 fd 0c 3e 44 96 c6 58 6b e3 a8 4c 75 2c a9 b4
1378828538.928859: WPA: decrypted EAPOL-Key key data - hexdump(len=72): [REMOVED]
1378828538.928863: eth0: State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE
1378828538.928867: eth0: WPA: RX message 3 of 4-Way Handshake from a0:21:b7:fd:e0:60 (ver=2)
1378828538.928868: WPA: IE KeyData - hexdump(len=72): 30 18 01 00 00 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 0c 00 dd 26 00 0f ac 01 01 00 15 47 e0 ec c9 4a ff ac 08 71 9f be 41 ca 95 e8 76 80 ce fe 14 4e 0f 37 e5 96 01 10 5f ba ac a9 dd 00 00 00 00 00
1378828538.928893: WPA: RSN IE in EAPOL-Key - hexdump(len=26): 30 18 01 00 00 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 0c 00
1378828538.928903: WPA: GTK in EAPOL-Key - hexdump(len=40): [REMOVED]
1378828538.928908: eth0: WPA: Sending EAPOL-Key 4/4
1378828538.928915: WPA: KCK - hexdump(len=16): [REMOVED]
1378828538.928916: WPA: Derived Key MIC - hexdump(len=16): 04 9b c0 b9 18 d8 1f 18 80 49 d9 55 3e 2a b2 c7
1378828538.928922: WPA: TX EAPOL-Key - hexdump(len=99): 01 03 00 5f 02 03 0a 00 00 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 04 9b c0 b9 18 d8 1f 18 80 49 d9 55 3e 2a b2 c7 00 00
1378828538.928965: eth0: WPA: Installing PTK to the driver
1378828538.928967: wpa_driver_wext_set_key: alg=3 key_idx=0 set_tx=1 seq_len=6 key_len=16
1378828538.928985: EAPOL: External notification - portValid=1
1378828538.928988: eth0: State: 4WAY_HANDSHAKE -> GROUP_HANDSHAKE
1378828538.928990: RSN: received GTK in pairwise handshake - hexdump(len=34): [REMOVED]
1378828538.928993: WPA: Group Key - hexdump(len=32): [REMOVED]
1378828538.928996: eth0: WPA: Installing GTK to the driver (keyidx=1 tx=0 len=32)
1378828538.928997: WPA: RSC - hexdump(len=6): b3 09 00 00 00 00
1378828538.929001: wpa_driver_wext_set_key: alg=2 key_idx=1 set_tx=0 seq_len=6 key_len=32
1378828539.030571: eth0: WPA: Key negotiation completed with a0:21:b7:fd:e0:60 [PTK=CCMP GTK=TKIP]
1378828539.030578: eth0: Cancelling authentication timeout
1378828539.030582: eth0: State: GROUP_HANDSHAKE -> COMPLETED
1378828539.030586: eth0: CTRL-EVENT-CONNECTED - Connection to a0:21:b7:fd:e0:60 completed [id=0 id_str=]
1378828539.030588: wpa_driver_wext_set_operstate: operstate 0->1 (UP)
1378828539.030591: netlink: Operstate: linkmode=-1, operstate=6
1378828539.030628: EAPOL: External notification - portValid=1
1378828539.030632: EAPOL: External notification - EAP success=1
1378828539.030634: EAPOL: SUPP_PAE entering state AUTHENTICATING
1378828539.030635: EAPOL: SUPP_BE entering state SUCCESS
1378828539.030637: EAP: EAP entering state DISABLED
1378828539.030639: EAPOL: SUPP_PAE entering state AUTHENTICATED
1378828539.030640: EAPOL: Supplicant port status: Authorized
1378828539.030642: EAPOL: SUPP_BE entering state IDLE
1378828539.030643: EAPOL authentication completed successfully
1378828539.030659: RTM_NEWLINK: operstate=1 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
1378828539.030663: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1378828539.030681: WEXT: if_removed already cleared - ignore event
1378828539.570569: EAPOL: startWhen --> 0
1378828539.570572: EAPOL: disable timer tick
1378828591.115699: eth0: Removing interface eth0
1378828591.115709: eth0: Request to deauthenticate - bssid=a0:21:b7:fd:e0:60 pending_bssid=00:00:00:00:00:00 reason=3 state=COMPLETED
1378828591.115712: wpa_driver_wext_deauthenticate
1378828591.115801: eth0: Event DEAUTH (12) received
1378828591.115804: eth0: Deauthentication notification
1378828591.115807: eth0:  * reason 3 (locally generated)
1378828591.115809: Deauthentication frame IE(s) - hexdump(len=0): [NULL]
1378828591.115814: eth0: CTRL-EVENT-DISCONNECTED bssid=a0:21:b7:fd:e0:60 reason=3 locally_generated=1
1378828591.115821: eth0: Auto connect enabled: try to reconnect (wps=0 wpa_state=9)
1378828591.115824: eth0: Setting scan request: 0 sec 100000 usec
1378828591.115828: Added BSSID a0:21:b7:fd:e0:60 into blacklist
1378828591.115879: eth0: Blacklist count 1 --> request scan in 100 ms
1378828591.115883: eth0: Setting scan request: 0 sec 100000 usec
1378828591.115889: eth0: Disconnect event - remove keys
1378828591.115891: wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
1378828591.115900: wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0
1378828591.115904: wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0
1378828591.115908: wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0
1378828591.115911: wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
1378828591.115920: eth0: State: COMPLETED -> DISCONNECTED
1378828591.115923: wpa_driver_wext_set_operstate: operstate 1->0 (DORMANT)
1378828591.115925: netlink: Operstate: linkmode=-1, operstate=5
1378828591.115968: EAPOL: External notification - portEnabled=0
1378828591.115971: EAPOL: SUPP_PAE entering state DISCONNECTED
1378828591.115973: EAPOL: Supplicant port status: Unauthorized
1378828591.115975: EAPOL: SUPP_BE entering state INITIALIZE
1378828591.115978: EAPOL: Supplicant port status: Unauthorized
1378828591.115980: EAPOL: External notification - portValid=0
1378828591.115981: EAPOL: Supplicant port status: Unauthorized
1378828591.115982: EAPOL: External notification - EAP success=0
1378828591.115984: EAPOL: Supplicant port status: Unauthorized
1378828591.115987: eth0: No keys have been configured - skip key clearing
1378828591.115989: eth0: State: DISCONNECTED -> DISCONNECTED
1378828591.115991: wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1378828591.115993: netlink: Operstate: linkmode=-1, operstate=5
1378828591.115998: EAPOL: External notification - portEnabled=0
1378828591.115999: EAPOL: Supplicant port status: Unauthorized
1378828591.116001: EAPOL: External notification - portValid=0
1378828591.116002: EAPOL: Supplicant port status: Unauthorized
1378828591.116004: wpa_driver_wext_set_countermeasures
1378828591.116009: eth0: No keys have been configured - skip key clearing
1378828591.127299: Removed BSSID a0:21:b7:fd:e0:60 from blacklist (clear)
1378828591.127391: eth0: BSS: Remove id 0 BSSID a0:21:b7:fd:e0:60 SSID 'virginmedia5147636' due to wpa_bss_flush
1378828591.127395: eth0: Cancelling scan request
1378828591.127399: eth0: Cancelling authentication timeout
1378828591.127429: netlink: Operstate: linkmode=0, operstate=6
1378828591.127604: eth0: CTRL-EVENT-TERMINATING

The command run in both cases...

wpa_supplicant -B -D wext -i eth0 -c /etc/wpa_supplicant/profiles/homewifi.conf

And the contents of homewifi.conf
(Only the one network I need to connect to thus far...)

network={
	ssid="virginmedia5147636"
	psk=[Redacted]
}

I hope you can figure out more from this than I did
Regards, JM

skanky · 2013-09-15 20:48:10

I'm at a loss, sorry. You could try and find the debug messages in the code and see what the different paths are.
I don't have time to do it myself sorry - but I still think it's in the response from the driver for whatever reason, and that *it* is what doesn't like the initramfs.
But there's little concrete there, and I could easily be barking up the wrong tree.

JMearsXS · 2013-09-16 07:01:48

The ironic thing is, I just compiled a new kernel... Same version as arch one.
the same thing happens still
looks like time to jump into the kernel source...
I'll have a look at the code for lib80211_crypt_tkip module, the bit which fails
I'd be really annoyed if its in there...

On a side note, if anyone is willing to have a look, please do as I'm not THAT good at programming

Regards, JM

JMearsXS · 2013-09-16 20:10:54

arrrgggh you know i said about not being experienced...?
looking in the kernel source blew my mind

anyways, its gonna take someone better than me to examine kernel source, BUT I 'm gonna try looking in wpa_supplicant's source (hopefully that's easier ) , I have a feeling about that... I dont think its the crypt modules as theres no dmesg errors in the failing situation.
I appreciate any other ideas anyone has on this most strange issue

Regards, JM

JMearsXS · 2013-09-23 17:49:08

I've been fruitlessly working at this PITA for a while now, and just this evening stumbled upon something...
Steps:
- specified break=postmount to kernel.
- once at rootfs shell; mount --bind'd usr etc var & root from the harddisk mountpoint (why is so much in /usr?? must find out )
- now with access to libs and modules; modprobe'd ipw2200 and the lib80211 crypt modules.
- set interface up with ip link set eth0 up
- wpa_supplicant -B -i eth0 -c /etc/wpa_supplicant/wpa_supplicant.conf
no errors here. same as always
- dhcpcd -A eth0
now normally, if wpa was stuck, dhcp would have failed. but, what?
dhcpcd: eth0: leased 192.168.0.12 from 192.168.0.1 for 84600 seconds
then...
dhcpcd: forked to background
what, no errors?

now SUDDENLY I can ping the outside internets... no errors either here.
may I just say, WTBF??

I give up. I really do. I can also add that I did not change any packages during the course of this problem to try and find its cause.
welp, im stumped anyways
unless anyone can find out why wpa *suddenly* changed its mind, i suggest a mod closing this thread.
(I don't want to mark as solved when it never really was )

Thanks for the I/O, people!
Regards, JM

Arch Linux

#1 2013-09-10 17:29:42

Strange wpa_supplicant behaviour

#2 2013-09-10 19:55:01

Re: Strange wpa_supplicant behaviour

#3 2013-09-11 06:58:20

Re: Strange wpa_supplicant behaviour

#4 2013-09-11 07:21:18

Re: Strange wpa_supplicant behaviour

#5 2013-09-11 08:06:26

Re: Strange wpa_supplicant behaviour

#6 2013-09-11 21:41:48

Re: Strange wpa_supplicant behaviour

#7 2013-09-12 07:31:17

Re: Strange wpa_supplicant behaviour

#8 2013-09-12 09:35:47

Re: Strange wpa_supplicant behaviour

#9 2013-09-12 17:41:54

Re: Strange wpa_supplicant behaviour

#10 2013-09-13 08:25:36

Re: Strange wpa_supplicant behaviour

#11 2013-09-13 12:39:24

Re: Strange wpa_supplicant behaviour

#12 2013-09-13 12:53:27

Re: Strange wpa_supplicant behaviour

#13 2013-09-13 18:34:24

Re: Strange wpa_supplicant behaviour

#14 2013-09-15 20:48:10

Re: Strange wpa_supplicant behaviour

#15 2013-09-16 07:01:48

Re: Strange wpa_supplicant behaviour

#16 2013-09-16 20:10:54

Re: Strange wpa_supplicant behaviour

#17 2013-09-23 17:49:08

Re: Strange wpa_supplicant behaviour

Board footer