1. This site uses cookies. By continuing to use this site, you are agreeing to our use of cookies. Learn More.

Finished: CALL FOR TESTERS Intel wireless 5100/5300 iwn(4) driver for FreeBSD

Discussion in 'FreeBSD Development' started by delphij@, Oct 29, 2009.

  1. delphij@

    delphij@ New Member Developer

    Messages:
    3
    Thanks Received:
    4
    Hi guys,

    Bernhard Schmidt has a patchset that updates our iwn(4) driver to support 5100/5300 wireless adapters. It also updated some firmware included in our distribution. Please test if you own these hardware and report back about how it worked, thanks for your cooperation!

    http://techwires.net/~bschmidt/patches/freebsd/iwn/iwn_merge_20081028.diff.bz2

    To apply it, go to your /usr/src/sys and do # bzcat iwn_merge_20081028.diff.bz2 | patch -p0 and recompile/install kernel.

    (We would appreciate if you would cc rpaulo@FreeBSD.org and/or freebsd-net@FreeBSD.org but I'll try to forward whatever appeared here :)

    Thanks in advance!
     
    alie, chalbersma, oliverh and 1 other person thank for this.
  2. MellowCat

    MellowCat New Member

    Messages:
    8
    Thanks Received:
    0
    Was there any specific testing you were looking for?
     
  3. delphij@

    delphij@ New Member Developer

    Messages:
    3
    Thanks Received:
    4
    Whether it works for your hardware/break existing compatibility :)
     
  4. thuglife

    thuglife New Member

    Messages:
    160
    Thanks Received:
    40
    I have 5300 on a lenovo T500, i will test it this afternoon and report back. Thank you for this!
     
  5. MellowCat

    MellowCat New Member

    Messages:
    8
    Thanks Received:
    0
    Berndt's patch worked first time 'out of the box' for me, haven't tried all the wifi features though.

    Lenovo Thinkpad T500, Intel 5100 AGN wireless card, 8.0-RC1 and RC2 (amd64).
     
  6. bschmidt

    bschmidt New Member

    Messages:
    298
    Thanks Received:
    39
    Hi,

    I'd really appreciate any kind of feedback :)

    There is a newer version available with some additional bug fixes and yet another bunch of imports from OpenBSD.
    Checkout:
    Code:
    svn co http://svn.techwires.net/svn/projects/freebsd/

    View:
    http://svn.techwires.net/viewvc/viewvc.cgi/svnrepos/projects/freebsd/

    There is one open issue reported by Mykola Dzham regarding suspend/resume I haven't been able to track down and there's still the LOR thing which is not yet fixed completely. It just happens on boot not while loading module manually later (races?)
     
    hugme thanks for this.
  7. oliverh

    oliverh New Member

    Messages:
    557
    Thanks Received:
    37
    So actually I'm able to use e.g. WPA2? Is it possible to use 11n?
     
  8. bschmidt

    bschmidt New Member

    Messages:
    298
    Thanks Received:
    39
    Not yet. I do not have access to a 11n capable accesspoint.
     
  9. bschmidt

    bschmidt New Member

    Messages:
    298
    Thanks Received:
    39
    And yes, WPA does work.
     
  10. vermaden

    vermaden Well-Known Member

    Messages:
    2,364
    Thanks Received:
    678
    @bschmidt

    You are thinkig about WPA or WPA2?
     
  11. bschmidt

    bschmidt New Member

    Messages:
    298
    Thanks Received:
    39
  12. TzunTzai

    TzunTzai New Member

    Messages:
    51
    Thanks Received:
    2
  13. bschmidt

    bschmidt New Member

    Messages:
    298
    Thanks Received:
    39
    yes it is. Revsion 1 is iwn_merge_20081028.diff.bz2
     
  14. oliverh

    oliverh New Member

    Messages:
    557
    Thanks Received:
    37
    Ah, I see. Thanks for the clarification.
     
  15. TzunTzai

    TzunTzai New Member

    Messages:
    51
    Thanks Received:
    2
    I'm sorry. I'm new to patching. Whats the next step here?


    Code:
    0# bzcat /storage/DOWNLOADS/iwn_merge_20081028.diff.bz2 | patch -p0
    Hmm...  Looks like a unified diff to me...
    The text leading up to this was:
    --------------------------
    |Index: conf/files
    |===================================================================
    |--- conf/files	(revision 198553)
    |+++ conf/files	(working copy)
    --------------------------
    Patching file conf/files using Plan A...
    Hunk #1 failed at 1082.
    Hunk #2 failed at 1107.
    Hunk #3 failed at 1121.
    Hunk #4 failed at 1138.
    4 out of 4 hunks failed--saving rejects to conf/files.rej
    Hmm...  The next patch looks like a unified diff to me...
    The text leading up to this was:
    --------------------------
    |Index: modules/iwnfw/iwn5000/Makefile
    |===================================================================
    |--- modules/iwnfw/iwn5000/Makefile	(revision 198553)
    |+++ modules/iwnfw/iwn5000/Makefile	(working copy)
    --------------------------
    File to patch: 
    No file found--skip this patch? [n] n
    File to patch: 
    
     
  16. bschmidt

    bschmidt New Member

    Messages:
    298
    Thanks Received:
    39
    Probably easier if you use the svn checkout.

    Code:
    svn co http://svn.techwires.net/svn/projects/freebsd
    cd freebsd/sys/modules/iwnfw
    make
    make install
    cd ../iwn
    env CFLAGS=-I$PWD/../../ make
    make install
    
     
    henker and abefar thanked for this.
  17. thuglife

    thuglife New Member

    Messages:
    160
    Thanks Received:
    40
    Hey there!

    Well, the driver works for me. It is stable for general - light use but when i try to cvsup the base system the link dies, if i try to bring the interface back up i get the following:

    Code:
    Nov  8 01:04:12 optimus kernel: wlan0: link state changed to DOWN
    Nov  8 01:04:12 optimus dhclient[1636]: exiting.
    Nov  8 01:04:33 optimus kernel: ifa_add_loopback_route: insertion failed
    Nov  8 01:04:35 optimus kernel: iwn0: iwn5000_post_alive: crystal calibration failed, error 35
    Nov  8 01:04:35 optimus kernel: iwn0: iwn_init_locked: could not initialize hardware, error 35


    Code:
    Failed to initiate AP scan.
    ioctl[SIOCS80211, op 103, len 128]: Device not configured


    This is me.

    Code:
    FreeBSD optimus.cybertron.local 8.0-RC2 FreeBSD 8.0-RC2 #2: Sat Nov  7 03:55:14 EET 2009     root@optimus.cybertron.local:/usr/obj/usr/src/sys/GENERIC  amd64


    Code:
    optimus# cat /etc/rc.conf
    wlans_iwn0="wlan0"
    ifconfig_em0="DHCP"
    ifconfig_wlan0="WPA DHCP"
    hostname="optimus.cybertron.local"


    Code:
    optimus# cat /etc/make.conf
    CPUTYPE         =core2
    WITH_GECKO      =libxul


    If there is anything i can do to help you debug this issue please let me know. Thank you for your work.
     
  18. bschmidt

    bschmidt New Member

    Messages:
    298
    Thanks Received:
    39
    Can you reproduce the issue with
    Code:
    wlandebug 0xffffffff

    set?

    I'm curious about why the device goes down, you're not getting a device timeout message, so it must be somewhere in net80211.
     
  19. thuglife

    thuglife New Member

    Messages:
    160
    Thanks Received:
    40
    This is the most interesting section from the log, i used:
    Code:
    sysctl net.wlan.0.debug=0xffffffff


    Code:
    Nov  8 15:38:25 optimus kernel: wlan0: [00:05:59:0c:47:60] discard duplicate frame, seqno <1365,1365> fragno <0,0> tid 16
    Nov  8 15:38:25 optimus kernel: wlan0: [00:05:59:0c:47:60] discard duplicate frame, seqno <1389,1389> fragno <0,0> tid 16
    Nov  8 15:38:25 optimus kernel: wlan0: [00:05:59:0c:47:60] discard duplicate frame, seqno <1399,1399> fragno <0,0> tid 16
    Nov  8 15:38:25 optimus kernel: wlan0: received beacon from 00:05:59:0c:47:60 rssi 65
    Nov  8 15:38:26 optimus kernel: wlan0: received beacon from 00:05:59:0c:47:60 rssi 66
    Nov  8 15:38:26 optimus kernel: wlan0: received beacon from 00:05:59:0c:47:60 rssi 66
    Nov  8 15:38:26 optimus wpa_supplicant[387]: Failed to disable WPA in the driver.
    Nov  8 15:38:26 optimus kernel: wlan0: stop running, 1 vaps running
    Nov  8 15:38:26 optimus kernel: wlan0: ieee80211_new_state_locked: RUN -> INIT (nrunning 0 nscanning 0)
    Nov  8 15:38:26 optimus kernel: wlan0: down parent iwn0
    Nov  8 15:38:26 optimus kernel: wlan0: ieee80211_newstate_cb: RUN -> INIT arg -1
    Nov  8 15:38:26 optimus kernel: wlan0: sta_newstate: RUN -> INIT (-1)
    Nov  8 15:38:26 optimus kernel: wlan0: ieee80211_ref_node (ieee80211_send_mgmt:1876) 0xffffff8000841000<00:05:59:0c:47:60> refcnt 276
    Nov  8 15:38:26 optimus kernel: wlan0: [00:05:59:0c:47:60] send station disassociate (reason 8)
    Nov  8 15:38:26 optimus kernel: [00:05:59:0c:47:60] send disassoc on channel 11
    Nov  8 15:38:26 optimus kernel: wlan0: _ieee80211_crypto_delkey: AES-CCM keyix 0 flags 0x133 rsc 50479 tsc 37776 len 16
    Nov  8 15:38:26 optimus kernel: wlan0: [00:05:59:0c:47:60] bss node leave
    Nov  8 15:38:26 optimus kernel: wlan0: node_reclaim: remove 0xffffff8000841000<00:05:59:0c:47
    Nov  8 15:38:26 optimus kernel: :<5>w6l0a> nf0r:o ml isntka tsitoatne  tcahbalneg,e dr etfoc ntD 27O5WN
    Nov  8 15:38:26 optimus kernel: 
    Nov  8 15:38:26 optimus kernel: wlan0: ieee80211_alloc_node 0xffffff8000865000<00:21:6a:6e:3d:b6> in station table
    Nov  8 15:38:26 optimus kernel: wlan0: [00:21:6a:6e:3d:b6] ieee80211_alloc_node: inact_reload 2
    Nov  8 15:38:26 optimus kernel: wlan0: ieee80211_scan_flush
    Nov  8 15:38:26 optimus kernel: wlan0: _ieee80211_crypto_delkey: NONE keyix 65535 flags 0x3 rsc 0 tsc 0 len 0
    Nov  8 15:38:26 optimus last message repeated 2 times
    Nov  8 15:38:26 optimus kernel: wlan0: _ieee80211_crypto_delkey: TKIP keyix 3 flags 0x1f6 rsc 1393 tsc 1 len 16
    Nov  8 15:38:26 optimus dhclient[1051]: connection closed
    Nov  8 15:38:26 optimus dhclient[1051]: exiting.
    Nov  8 15:38:30 optimus kernel: wlan0: start running, 0 vaps running
    Nov  8 15:38:30 optimus kernel: wlan0: ieee80211_start_locked: up parent iwn0
    Nov  8 15:38:30 optimus kernel: wlan0: start running, 1 vaps running
    Nov  8 15:38:30 optimus kernel: wlan0: ieee80211_new_state_locked: INIT -> SCAN (nrunning 0 nscanning 0)
    Nov  8 15:38:30 optimus kernel: wlan0: ieee80211_newstate_cb: INIT -> SCAN arg 0
    Nov  8 15:38:30 optimus kernel: wlan0: sta_newstate: INIT -> SCAN (0)
    Nov  8 15:38:30 optimus kernel: wlan0: ieee80211_check_scan: active scan, append
    Nov  8 15:38:30 optimus kernel: wlan0: start_scan_locked: active scan, duration 2147483647 mindwell 0 maxdwell 0, desired mode auto, append
    Nov  8 15:38:30 optimus kernel: wlan0: scan set 1g, 6g, 11g, 7g, 13g, 52a, 56a, 60a, 64a, 36a, 40a, 44a, 48a, 2g, 3g, 4g, 5g, 8g, 9g, 10g, 12g, 149a, 153a, 157a, 161a, 165a, 100a, 104a, 108a, 112a, 116a, 120a, 124a, 128a, 132a, 136a, 140a dwell min 20ms max 200ms
    Nov  8 15:38:30 optimus kernel: wlan0: scan_task: chan  11g ->   1g [active, dwell min 20ms max 200ms]
    Nov  8 15:38:30 optimus kernel: wlan0: received probe_resp from 00:14:7f:32:c5:c3 rssi 29
    Nov  8 15:38:30 optimus kernel: wlan0: [00:14:7f:32:c5:c3] discard unhandled information element, id 47, len 1
    Nov  8 15:38:30 optimus kernel: [00:14:7f:32:c5:c3] new probe_resp on chan 1 (bss chan 1) "NIKITAS-FILIPPOS" rssi 29
    Nov  8 15:38:30 optimus kernel: [00:14:7f:32:c5:c3] caps 0x411 bintval 100 erp 0x104
    Nov  8 15:38:30 optimus kernel: wlan0: scan_task: chan   1g ->   6g [active, dwell min 20ms max 200ms]
    Nov  8 15:38:30 optimus kernel: wlan0: received beacon from 00:13:33:81:bf:ad rssi 5
    Nov  8 15:38:30 optimus kernel: [00:13:33:81:bf:ad] new beacon on chan 6 (bss chan 6) "Zeus" rssi 5
    Nov  8 15:38:30 optimus kernel: [00:13:33:81:bf:ad] caps 0x411 bintval 100 erp 0x104
    Nov  8 15:38:30 optimus kernel: wlan0: received probe_resp from 00:13:33:81:bf:ad rssi 6
    Nov  8 15:38:30 optimus kernel: [00:13:33:81:bf:ad] new probe_resp on chan 6 (bss chan 6) "Zeus" rssi 6
    Nov  8 15:38:30 optimus kernel: [00:13:33:81:bf:ad] caps 0x411 bintval 100 erp 0x104
    Nov  8 15:38:30 optimus kernel: wlan0: received probe_resp from 00:13:33:81:bf:ad rssi 7
    Nov  8 15:38:30 optimus kernel: [00:13:33:81:bf:ad] new probe_resp on chan 6 (bss chan 6) "Zeus" rssi 7
    Nov  8 15:38:30 optimus kernel: [00:13:33:81:bf:ad] caps 0x411 bintval 100 erp 0x104
    Nov  8 15:38:30 optimus kernel: wlan0: scan_task: chan   6g ->  11g [active, dwell min 20ms max 200ms]
    Nov  8 15:38:30 optimus kernel: wlan0: received probe_resp from 00:05:59:0c:47:60 rssi 67
    Nov  8 15:38:30 optimus kernel: [00:05:59:0c:47:60] new probe_resp on chan 11 (bss chan 11) "Liaskos2" rssi 67
    Nov  8 15:38:30 optimus kernel: [00:05:59:0c:47:60] caps 0x431 bintval 100 erp 0x100
    Nov  8 15:38:30 optimus kernel: wlan0: received probe_resp from 00:05:59:0c:47:60 rssi 68
    Nov  8 15:38:30 optimus kernel: [00:05:59:0c:47:60] new probe_resp on chan 11 (bss chan 11) "Liaskos2" rssi 68
    Nov  8 15:38:30 optimus kernel: [00:05:59:0c:47:60] caps 0x431 bintval 100 erp 0x100
    Nov  8 15:38:30 optimus kernel: wlan0: received probe_resp from 00:1c:df:08:72:9b rssi 14
    Nov  8 15:38:30 optimus kernel: wlan0: [00:1c:df:08:72:9b] discard unhandled information element, id 47, len 1
    Nov  8 15:38:30 optimus kernel: wlan0: [00:1c:df:08:72:9b] discard probe_resp frame, for off-channel 10
    Nov  8 15:38:30 optimus kernel: wlan0: received beacon from 00:05:59:0c:47:60 rssi 68
    Nov  8 15:38:30 optimus kernel: [00:05:59:0c:47:60] new beacon on chan 11 (bss chan 11) "Liaskos2" rssi 68
    Nov  8 15:38:30 optimus kernel: [00:05:59:0c:47:60] caps 0x431 bintval 100 erp 0x100
    Nov  8 15:38:30 optimus kernel: wlan0: scan_task: chan  11g ->   7g [active, dwell min 20ms max 200ms]
    Nov  8 15:38:30 optimus kernel: wlan0: scan_task: chan   7g ->  13g [passive, dwell min 20ms max 200ms]
    Nov  8 15:38:30 optimus kernel: wlan0: received beacon from 00:1c:a2:ac:3e:21 rssi 21
    Nov  8 15:38:30 optimus kernel: [00:1c:a2:ac:3e:21] new beacon on chan 13 (bss chan 13) "WIRELESS" rssi 21
    Nov  8 15:38:30 optimus kernel: [00:1c:a2:ac:3e:21] caps 0x471 bintval 100 erp 0x103
    Nov  8 15:38:30 optimus kernel: wlan0: ieee80211_add_scan: chan  13g min dwell met (1785560 > 1785487)
    Nov  8 15:38:30 optimus kernel: wlan0: scan_task: chan  13g ->  52a [passive, dwell min 20ms max 200ms]
    Nov  8 15:38:30 optimus kernel: wlan0: received beacon from 00:1c:a2:ac:3e:21 rssi 21
    Nov  8 15:38:30 optimus kernel: wlan0: [00:1c:a2:ac:3e:21] discard beacon frame, for off-channel 13
    Nov  8 15:38:31 optimus kernel: wlan0: received beacon from 00:1c:a2:ac:3e:21 rssi 21
    Nov  8 15:38:31 optimus kernel: wlan0: [00:1c:a2:ac:3e:21] discard beacon frame, for off-channel 13
    Nov  8 15:38:31 optimus kernel: wlan0: received beacon from 00:1c:a2:ac:3e:21 rssi 21
    Nov  8 15:38:31 optimus kernel: wlan0: [00:1c:a2:ac:3e:21] discard beacon frame, for off-channel 13
    Nov  8 15:38:31 optimus kernel: wlan0: received beacon from 00:1c:a2:ac:3e:21 rssi 20
    Nov  8 15:38:31 optimus kernel: wlan0: [00:1c:a2:ac:3e:21] discard beacon frame, for off-channel 13
    Nov  8 15:38:31 optimus kernel: iwn0: iwn_config: could not configure bluetooth coexistence, error 35
    Nov  8 15:38:31 optimus kernel: wlan0: ieee80211_cancel_scan: cancel active scan
    Nov  8 15:38:31 optimus kernel: wlan0: scan_task: done, [ticks 1786601, dwell min 20 scanend 2149268980]
    Nov  8 15:38:31 optimus kernel: wlan0: [00:05:59:0c:47:60] discard frame, not to bss
    Nov  8 15:38:31 optimus kernel: wlan0: [00:05:59:0c:47:60] discard frame, not to bss
    Nov  8 15:38:31 optimus kernel: wlan0: [00:24:b2:36:61:c8] discard frame, not to bss
    Nov  8 15:38:32 optimus kernel: wlan0: [00:1c:a2:ac:3e:21] discard frame, not to bss
     
  20. bschmidt

    bschmidt New Member

    Messages:
    298
    Thanks Received:
    39
    Hmm, seems like wpa_supplicant is telling the device to stop. Can you run wpa_supplicant with debug output?

    Code:
    wpa_supplicant -Dbsd -iwlan0 -c/etc/wpa_supplicant.conf -ddt


    I have have the feeling that something with re-keying is not working correctly.
     
  21. Zhwazi

    Zhwazi New Member

    Messages:
    30
    Thanks Received:
    0
    I have a Dell Latitude E6400 with a Wifilink 5300 which I bought separately, followed the svn instructions on 8.0-RC1 i386, works fine for me so far in an hour of use.

    Tried cvsup like ThugLife says gave him problems, didn't see any problems when I tried it.

    Thank you very much for the driver, this was the last thing in my system that wasn't working as I expected it to :)
     
  22. Zephyrus

    Zephyrus New Member

    Messages:
    15
    Thanks Received:
    0
    Hi,
    well, first of all thanks for the driver, this was the last major device who was totally not supported by FreeBSD on my HP Probook.

    With regard to the driver itself, I've tested it today for about three hours to connect to an hidden ssid-open network with browser based authentication.
    In particular I performed a full-speed download test for about thirty minutes, I tested csup and then I spent the rest of the time with a standard network usage (http,imap,ssh, etc...).

    These are the most relevant messages I found in the log files:
    Code:
    Nov  8 12:38:40 polaris kernel: iwn0: iwn_config: could not set TX power
    Nov  8 12:38:41 polaris kernel: iwn0: iwn_config: could not configure valid TX chains, error 35
    Nov  9 12:46:23 polaris kernel: iwn0: <Intel(R) PRO/Wireless 5100> mem 0x98200000-0x98201fff irq 17 at device 0.0 on pci3
    Nov  9 12:46:23 polaris kernel: iwn0: MIMO 1T2R, MoW, address 00:22:fa:e4:2e:56
    Nov  9 12:46:23 polaris kernel: iwn0: [ITHREAD]
    Nov  9 12:46:23 polaris kernel: iwn0: 11a rates: 6Mbps 9Mbps 12Mbps 18Mbps 24Mbps 36Mbps 48Mbps 54Mbps
    Nov  9 12:46:23 polaris kernel: iwn0: 11b rates: 1Mbps 2Mbps 5.5Mbps 11Mbps
    Nov  9 12:46:23 polaris kernel: iwn0: 11g rates: 1Mbps 2Mbps 5.5Mbps 11Mbps 6Mbps 9Mbps 12Mbps 18Mbps 24Mbps 36Mbps 48Mbps 54Mbps
    Nov  9 12:46:23 polaris kernel: iwn0: 11na MCS: 15Mbps 30Mbps 45Mbps 60Mbps 90Mbps 120Mbps 135Mbps 150Mbps 30Mbps 60Mbps 90Mbps 120Mbps 180Mbps 240Mbps 270Mbps 300Mbps
    Nov  9 12:46:23 polaris kernel: iwn0: 11ng MCS: 15Mbps 30Mbps 45Mbps 60Mbps 90Mbps 120Mbps 135Mbps 150Mbps 30Mbps 60Mbps 90Mbps 120Mbps 180Mbps 240Mbps 270Mbps 300Mbps
    Nov  9 12:59:12 polaris kernel: iwn0: need multicast update callback
    Nov  9 12:59:14 polaris kernel: iwn0: need multicast update callback
    Nov  9 12:59:14 polaris kernel: iwn0: need multicast update callback
    Nov  9 13:05:40 polaris kernel: iwn0: need multicast update callback
    Nov  9 13:06:22 polaris kernel: iwn0: need multicast update callback
    Nov  9 13:06:22 polaris kernel: iwn0: need multicast update callback
    Nov  9 13:06:22 polaris kernel: iwn0: need multicast update callback
    Nov  9 14:11:59 polaris kernel: iwn0: need multicast update callback
    Nov  9 14:12:07 polaris kernel: iwn0: need multicast update callback
    


    The first two lines seem to appear only on the first load of if_iwn. Apart from these messages, all seems to have worked well. If you need more information or some particular test, I will gladly help, if I can.
     
  23. bschmidt

    bschmidt New Member

    Messages:
    298
    Thanks Received:
    39
    What do you mean by "first load"? Does that mean you have to load if_iwn.ko twice to get a working device?
     
  24. Zephyrus

    Zephyrus New Member

    Messages:
    15
    Thanks Received:
    0
    Wait, it seems that I cannot reproduce it anymore. And I also noticed that those lines were included by mystake, since they refer to yesterday. I will let you know if I come across that error again.
    Just to be clear, the driver works on first load, at boot.
    I also forgot to give my system information:
    Code:
    FreeBSD polaris 8.0-RC2 FreeBSD 8.0-RC2 #2: Fri Nov  6 22:55:22 CET 2009     toor@polaris:/usr/obj/usr/src/sys/POLARIS  amd64
    
     
  25. thuglife

    thuglife New Member

    Messages:
    160
    Thanks Received:
    40
    I hope you can find anything useful.

    Code:
    1257789518.518887: State: ASSOCIATING -> ASSOCIATED
    1257789518.518910: Associated to a new BSS: BSSID=00:05:59:0c:47:60
    1257789518.518917: No keys have been configured - skip key clearing
    1257789518.518926: Associated with 00:05:59:0c:47:60
    1257789518.518932: WPA: Association event - clear replay counter
    1257789518.518937: WPA: Clear old PTK
    1257789518.518942: EAPOL: External notification - portEnabled=0
    1257789518.518949: EAPOL: External notification - portValid=0
    1257789518.518954: EAPOL: External notification - EAP success=0
    1257789518.518960: EAPOL: External notification - portEnabled=1
    1257789518.518965: EAPOL: SUPP_PAE entering state CONNECTING
    1257789518.518970: EAPOL: enable timer tick
    1257789518.518979: EAPOL: SUPP_BE entering state IDLE
    1257789518.518987: Setting authentication timeout: 10 sec 0 usec
    1257789518.518998: Cancelling scan request
    1257789518.535316: RX EAPOL from 00:05:59:0c:47:60
    1257789518.535329: RX EAPOL - hexdump(len=121): 01 03 00 75 02\
       00 8a 00 10 00 00 00 00 00 00 00 36 9d 16 28 05 dd 2a c7 7c\
       a6 bc c8 67 20 68 5f c1 4d 77 81 65 30 cc bb 57 d1 ea eb 36\
       ce 6b 1a e0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00\
       00 00 00 00 00 00 00 00 00 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\
       ed 90 07 d4 a2 38 80 e7 44 a9 d6 52 28 b4 4f 85
    1257789518.535404: Setting authentication timeout: 10 sec 0 usec
    
    ...
    
    1257789518.535606: State: ASSOCIATED -> 4WAY_HANDSHAKE
    1257789518.535613: WPA: RX message 1 of 4-Way Handshake from 00:05:59:0c:47:60 (ver=2)
    1257789518.535622: RSN: msg 1/4 key data - hexdump(len=22): dd 14 00 0f ac 04 ed 90 07 d4 a2 38 80 e7 44 a9 d6 52 28 b4 4f 85
    1257789518.535644: RSN: PMKID from Authenticator - hexdump(len=16): ed 90 07 d4 a2 38 80 e7 44 a9 d6 52 28 b4 4f 85
    1257789518.535658: RSN: no matching PMKID found
    1257789518.535942: WPA: Renewed SNonce - hexdump(len=32): 10 65\
       26 99 e2 8f 6b ad dd 85 9d dc 9c 07 f6 bd af 96 86 98 9c e1\
       cf c1 1d 7c 35 99 75 58 9d 96
    1257789518.536002: WPA: PTK derivation - A1=00:21:6a:6e:3d:b6 A2=00:05:59:0c:47:60
    1257789518.536013: WPA: PMK - hexdump(len=32): [REMOVED]
    1257789518.536019: WPA: PTK - hexdump(len=64): [REMOVED]
    1257789518.536026: 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
    1257789518.536046: WPA: Sending EAPOL-Key 2/4
    1257789518.536060: WPA: TX EAPOL-Key - hexdump(len=121): 01 03\
       00 75 02 01 0a 00 00 00 00 00 00 00 00 00 36 10 65 26 99 e2\
       8f 6b ad dd 85 9d dc 9c 07 f6 bd af 96 86 98 9c e1 cf c1 1d\
       7c 35 99 75 58 9d 96 00 00 00 00 00 00 00 00 00 00 00 00 00\
       00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 22\
       ba 30 a3 fb 78 07 e3 2a e1 f4 6c 29 c7 2a 6f 00 16 30 14 01\
       00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
    1257789518.589574: RX EAPOL from 00:05:59:0c:47:60
    1257789518.589586: RX EAPOL - hexdump(len=179): 01 03 00 af 02\
       13 ca 00 10 00 00 00 00 00 00 00 37 9d 16 28 05 dd 2a c7 7c\
       a6 bc c8 67 20 68 5f c1 4d 77 81 65 30 cc bb 57 d1 ea eb 36\
       ce 6b 1a e0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00\
       00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 e5 a6 af 23\
       31 3e f1 63 6f 1e 90 b6 91 14 39 1f 00 50 fd e0 e9 a4 21 d9\
       72 aa a4 94 22 25 8c 9a 43 ae ba 03 af 5b 3e b3 96 d7 19 96\
       23 cd cd 2c 07 41 f0 f2 31 33 2a 9a 3a d3 b9 49 e3 aa 94 ee\
       55 ef 0e b2 fe b1 0c b2 a2 5d 90 03 34 4c 17 b5 8a 61 e4 23\
       f7 15 b7 05 1b c8 98 28 2f 14 eb 4e ec 8c
    1257789518.589683: IEEE 802.1X RX: version=1 type=3 length=175
    1257789518.589690:   EAPOL-Key type=2
    1257789518.589695:   key_info 0x13ca (ver=2 keyidx=0 rsvd=0 Pairwise Install Ack MIC Secure Encr)
    1257789518.589705:   key_length=16 key_data_length=80
    1257789518.589711:   replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 37
    1257789518.589722:   key_nonce - hexdump(len=32): 9d 16 28 05 dd\
       2a c7 7c a6 bc c8 67 20 68 5f c1 4d 77 81 65 30 cc bb 57 d1\
       ea eb 36 ce 6b 1a e0
    1257789518.589742:   key_iv - hexdump(len=16): 00 00 00 00 00 00\
       00 00 00 00 00 00 00 00 00 00
    1257789518.589757:   key_rsc - hexdump(len=8): 00 00 00 00 00 00\
       00 00
    1257789518.589767:   key_id (reserved) - hexdump(len=8): 00 00\
       00 00 00 00 00 00
    1257789518.589777:   key_mic - hexdump(len=16): e5 a6 af 23 31\
       3e f1 63 6f 1e 90 b6 91 14 39 1f
    1257789518.589792: WPA: RX EAPOL-Key - hexdump(len=179): 01 03\
       00 af 02 13 ca 00 10 00 00 00 00 00 00 00 37 9d 16 28 05 dd\
       2a c7 7c a6 bc c8 67 20 68 5f c1 4d 77 81 65 30 cc bb 57 d1\
       ea eb 36 ce 6b 1a e0 00 00 00 00 00 00 00 00 00 00 00 00 00\
       00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 e5\
       a6 af 23 31 3e f1 63 6f 1e 90 b6 91 14 39 1f 00 50 fd e0 e9\
       a4 21 d9 72 aa a4 94 22 25 8c 9a 43 ae ba 03 af 5b 3e b3 96\
       d7 19 96 23 cd cd 2c 07 41 f0 f2 31 33 2a 9a 3a d3 b9 49 e3\
       aa 94 ee 55 ef 0e b2 fe b1 0c b2 a2 5d 90 03 34 4c 17 b5 8a\
       61 e4 23 f7 15 b7 05 1b c8 98 28 2f 14 eb 4e ec 8c
    1257789518.589901: RSN: encrypted key data - hexdump(len=80): fd\
       e0 e9 a4 21 d9 72 aa a4 94 22 25 8c 9a 43 ae ba 03 af 5b 3e\
       b3 96 d7 19 96 23 cd cd 2c 07 41 f0 f2 31 33 2a 9a 3a d3 b9\
       49 e3 aa 94 ee 55 ef 0e b2 fe b1 0c b2 a2 5d 90 03 34 4c 17\
       b5 8a 61 e4 23 f7 15 b7 05 1b c8 98 28 2f 14 eb 4e ec 8c
    1257789518.605316: WPA: decrypted EAPOL-Key key data - hexdump(len=72): [REMOVED]
    1257789518.605326: State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE
    1257789518.605333: WPA: RX message 3 of 4-Way Handshake from 00:05:59:0c:47:60 (ver=2)
    1257789518.605342: WPA: IE KeyData - hexdump(len=72): 30 18 01\
       00 00 0f ac 02 02 00 00 0f ac 02 00 0f ac 04 01 00 00 0f ac\
       02 01 00 dd 26 00 0f ac 01 02 00 67 e1 4f 0d f4 55 5e 19 6d\
       72 53 1a f3 0c e6 41 96 3e 10 04 89 df fd d1 c7 8e ce c7 ce\
       fe 94 f5 dd 00 00 00 00 00
    1257789518.605388: WPA: Sending EAPOL-Key 4/4
    1257789518.605403: WPA: TX EAPOL-Key - hexdump(len=99): 01 03 00\
       5f 02 03 0a 00 00 00 00 00 00 00 00 00 37 00 00 00 00 00 00\
       00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00\
       00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00\
       00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ba 38\
       c6 30 64 11 44 d1 f6 fe a3 f2 de 6c bd 69 00 00
    1257789518.605476: WPA: Installing PTK to the driver.
    1257789518.605522: wpa_driver_bsd_set_key: alg=CCMP addr=00:05:59:0c:47:60 key_idx=0 set_tx=1 seq_len=6 key_len=16
    1257789518.605546: EAPOL: External notification - portValid=1
    1257789518.605553: State: 4WAY_HANDSHAKE -> GROUP_HANDSHAKE
    1257789518.605560: RSN: received GTK in pairwise handshake - hexdump(len=34): [REMOVED]
    1257789518.605567: WPA: Group Key - hexdump(len=32): [REMOVED]
    1257789518.605597: WPA: Installing GTK to the driver (keyidx=2 tx=0 len=32).
    1257789518.605605: WPA: RSC - hexdump(len=6): 00 00 00 00 00 00
    1257789518.605618: wpa_driver_bsd_set_key: alg=TKIP addr=ff:ff:ff:ff:ff:ff key_idx=2 set_tx=0 seq_len=6 key_len=32
    1257789518.605643: WPA: Key negotiation completed with 00:05:59:0c:47:60 [PTK=CCMP GTK=TKIP]
    1257789518.605650: Cancelling authentication timeout
    1257789518.605657: State: GROUP_HANDSHAKE -> COMPLETED
    1257789518.605669: CTRL-EVENT-CONNECTED - Connection to 00:05:59:0c:47:60 completed (auth) [id=0 id_str=]
    1257789518.605675: EAPOL: External notification - portValid=1
    1257789518.605681: EAPOL: External notification - EAP success=1
    1257789518.605686: EAPOL: SUPP_PAE entering state AUTHENTICATING
    1257789518.605691: EAPOL: SUPP_BE entering state SUCCESS
    1257789518.605696: EAP: EAP entering state DISABLED
    1257789518.605702: EAPOL: SUPP_PAE entering state AUTHENTICATED
    1257789518.605707: EAPOL: SUPP_BE entering state IDLE
    1257789518.605713: EAPOL authentication completed successfully
    1257789519.607926: RSN: processing PMKSA candidate list
    1257789519.607941: RSN: not in suitable state for new pre-authentication
    1257789521.537606: EAPOL: startWhen --> 0
    1257789521.537619: EAPOL: disable timer tick
    1257791506.301473: RTM_IFINFO: Interface 'wlan0' DOWN
    1257791506.301491: Configured interface was removed.
    1257791506.301500: State: COMPLETED -> DISCONNECTED
    1257791506.301508: EAPOL: External notification - portEnabled=0
    1257791506.301514: EAPOL: SUPP_PAE entering state DISCONNECTED
    1257791506.301519: EAPOL: SUPP_BE entering state INITIALIZE
    1257791506.301527: EAPOL: External notification - portValid=0
    1257791506.301533: EAPOL: External notification - EAP success=0
    1257791506.301640: Removing interface wlan0
    1257791506.301650: State: DISCONNECTED -> DISCONNECTED
    1257791506.301657: wpa_driver_bsd_del_key: keyidx=0
    1257791506.301672: wpa_driver_bsd_del_key: keyidx=1
    1257791506.301681: wpa_driver_bsd_del_key: keyidx=2
    1257791506.301691: wpa_driver_bsd_del_key: keyidx=3
    1257791506.301703: EAPOL: External notification - portEnabled=0
    1257791506.301710: EAPOL: External notification - portValid=0
    1257791506.301717: wpa_driver_bsd_set_wpa: enabled=0
    1257791506.301722: wpa_driver_bsd_set_wpa_internal: wpa=0 privacy=0
    1257791506.301863: Failed to disable WPA in the driver.
    1257791506.301868: wpa_driver_bsd_set_drop_unencrypted: enabled=0
    1257791506.301879: wpa_driver_bsd_set_countermeasures: enabled=0
    1257791506.301889: No keys have been configured - skip key clearing
    1257791506.302284: Cancelling scan request
    1257791506.302293: Cancelling authentication timeout
    1257791506.315435: wpa_driver_bsd_set_wpa_internal: wpa=0 privacy=0
    ELOOP: remaining socket: sock=4 eloop_data=0x800e0b1c0 user_data=0x800e070f0 handler=0x41fb29