I posted this on apple today but have had no response. In all honesty I probably do not expect to get one. However, in case some one in here is a wiz at osx and the brcm4360 drivers I thought I would post the details of my fault analysis here....there has to be some one out there with more knowledge on these drivers that can assist. This is on a early 2015 Macbook air running 10.11.6.
For the past year I've been living with random wake failure crashes and have never had the time to actually debug. Well its xmas and holidays and after 3 crashes in the last 5 days after sleep I thought I would spend some time looking through the logs to see what is actually happening.
First, in CoreCapture in console I notice that both com.apple.drive.Airport.Brcm4360.0 and com.apple.iokit.IO80211Family both have alot of captured logs. Even more interesting is the fact that the vast majority of these have a post fix of '=AuthFail:sts:2_rsn:0'. This is intriguing as to what is attempting to be authenticated that is actually failing against in my home.
So I set about reviewing the lastest AirportBrcm4360_logs-xxx.txt file and found and interesting item in regards to what is happening.I should say at the start that my wireless AP is a R8000 and using smart connect on the 5G band. At the time of writing my Mac Air is connected to the upper band on channel 153. This I acieved by manually stopping and starting wifi a few times. I can successfully connect to both 5G bands with my MAC in that manner. Just to prove the point I can also manually connect to both BSSIDs by using https://github.com/qpSHiNqp/airport-bssid.
So, looking through the BRCM4360 logs I find that when my MAC wakes up it looks for the BSSID associated with the lower 5G band and associates and authenticates to it. As soon as this is achieved I get another message that states there is a better signal available, which is the higher of the 2 5G bands (channel 153) and then the drivers attempt to connect and associate with it. However, the driver reports that it can not authenticate to this band and waits a bit of time and then corecapture kicks in to capture all the logs. I'm assuming at this point that the Mac has indeed crashed and restarts.
I've attached the applicable parts of the logs below as:
1. The connection to the lower of the 5G bands is shown below where the 9th line from the bottom shows that the authentication succeeded.
2. The message regarding a better signal.
3. The rejected authentication attempt against the upper 5G band.
And the tell tail message at the end of the auth failure is AuthFail:sts:2_rsn:0.
Has any body else experienced this? Has anyone found a way of solving this? I've no idea why the driver can not authenticate with the higher channel when I can perform this action manually on the MAC and connect without issue. The only thing that I can think of is that the driver does not like the R8000 and the load balancing behaviour of the 5G band. However, if that was the case then I expect it would fail when I perform the connect manually.
Any one have any idea's here? To me this seems to be a driver issue. Why does it not fallback to the initial connection that was authenticated? If any one is interested I can send the entire log that has the complete back trace etc in it.
1. Connection Authenticated.
Dec 28 22:39:34.963994 +1000 000006.088955 Brcm4360<D>[405] [0x7cdb2a37c57f0e49][1][0] wl0: wlc_join_pref_band_upd: band pref is 0
Dec 28 22:39:34.964034 +1000 000006.088995 Brcm4360<D>[406] [0x7cdb2a37c57f0e49][1][0] wl0.0: insert JOIN request in state IDLE for SSID '' in assoc_req list at slot 0
Dec 28 22:39:34.964367 +1000 000006.089328 Brcm4360<D>[407] [0x7cdb2a37c57f0e49][1][0] wl0: SCAN: wlc_join_start, Setting SSID to "MySSID"...
Dec 28 22:39:34.964370 +1000 000006.089331 Brcm4360<D>[408] [0x7cdb2a37c57f0e49][1][0] wl0.0: wlc_assoc_change_state: change assoc_state from IDLE to JOIN_INIT
Dec 28 22:39:34.964385 +1000 000006.089346 Brcm4360<D>[409] [0x7cdb2a37c57f0e49][1][0] backtrace[wlc_assoc_change_state]: 0x40df5 0xa7daf 0xaf818 0xa6b8c 0xa5ed3 0x11a309 0xef732 0x2145b 0x23a4d 0x29d54 0x3c1ba 0x7cdb2a373350d52e 0x7cdb2a37335157cf 0x21881 0x7cdb2a3733517b5b 0x7cdb2a37326b0dcd 0x7cdb2a37b23ea591 0x7cdb2a37326b0e34 0x7cdb2a3733517a10 0x7cdb2a37b20917fd 0x7cdb2a37b20895dc 0x7cdb2a37b20897f8 0x7cdb2a37b230181f 0x7cdb2a37b22ba774 0x7cdb2a37b22fc1a6 0x7cdb2a37b235c9ea 0x7cdb2a37b1f2104f
Dec 28 22:39:34.964388 +1000 000006.089349 Brcm4360<D>[410] [0x7cdb2a37c57f0e49][1][0] wl0.0: JOIN request in state JOIN_INIT for SSID 'MySSID' exists in assoc_req list at slot 0
Dec 28 22:39:34.964392 +1000 000006.089353 Brcm4360<D>[411] [0x7cdb2a37c57f0e49][1][0] wl0.0: wlc_assoc_init: assoc state machine init to assoc->type 1 JOIN
Dec 28 22:39:34.964395 +1000 000006.089356 Brcm4360<D>[412] [0x7cdb2a37c57f0e49][1][0] starting assoc scan
Dec 28 22:39:34.964397 +1000 000006.089358 Brcm4360<D>[413] [0x7cdb2a37c57f0e49][1][0] wl0: SCAN: wlc_assoc_scan_start, starting a JOIN scan for SSID MySSID
Dec 28 22:39:34.964468 +1000 000006.089429 Brcm4360<D>[414] [0x7cdb2a37c57f0e49][1][0] wl0: wlc_assoc_cache_validate_timestamps: 2 hits, oldest 0 sec, using cache hits
Dec 28 22:39:34.964470 +1000 000006.089431 Brcm4360<D>[415] [0x7cdb2a37c57f0e49][1][0] wl0: JOIN: using the cached scan results for assoc (2 hits)
Dec 28 22:39:34.964472 +1000 000006.089433 Brcm4360<D>[416] [0x7cdb2a37c57f0e49][1][0] wl0.0: wlc_assoc_change_state: change assoc_state from JOIN_INIT to SCAN
Dec 28 22:39:34.964487 +1000 000006.089448 Brcm4360<D>[417] [0x7cdb2a37c57f0e49][1][0] backtrace[wlc_assoc_change_state]: 0x40df5 0xa7daf 0xb7e56 0xa6e2e 0xa5ed3 0x11a309 0xef732 0x2145b 0x23a4d 0x29d54 0x3c1ba 0x7cdb2a373350d52e 0x7cdb2a37335157cf 0x21881 0x7cdb2a3733517b5b 0x7cdb2a37326b0dcd 0x7cdb2a37b23ea591 0x7cdb2a37326b0e34 0x7cdb2a3733517a10 0x7cdb2a37b20917fd 0x7cdb2a37b20895dc 0x7cdb2a37b20897f8 0x7cdb2a37b230181f 0x7cdb2a37b22ba774 0x7cdb2a37b22fc1a6 0x7cdb2a37b235c9ea 0x7cdb2a37b1f2104f
Dec 28 22:39:34.964490 +1000 000006.089451 Brcm4360<D>[418] [0x7cdb2a37c57f0e49][1][0] wl0: SCAN: wlc_assoc_scan_complete
Dec 28 22:39:34.964492 +1000 000006.089453 Brcm4360<D>[419] [0x7cdb2a37c57f0e49][1][0] wl0:wlc_assoc_scan_complete: delay roam scan by scan_block=10
Dec 28 22:39:34.964494 +1000 000006.089455 Brcm4360<D>[420] [0x7cdb2a37c57f0e49][1][0] wl0: SCAN for JOIN: SSID scan complete, 2 results for "MySSID"
Dec 28 22:39:34.964496 +1000 000006.089457 Brcm4360<D>[421] [0x7cdb2a37c57f0e49][1][0] wl0: ROAM: Single AP Environment
Dec 28 22:39:34.964498 +1000 000006.089459 Brcm4360<D>[422] [0x7cdb2a37c57f0e49][1][0] wl0.0: wlc_roam_prof_update_default: Only for no roam support
Dec 28 22:39:34.964501 +1000 000006.089461 Brcm4360<D>[423] [0x7cdb2a37c57f0e49][1][0] wl0: RSSI is 0; 2 roaming target; Join preference fields are 0x0
Dec 28 22:39:34.964503 +1000 000006.089464 Brcm4360<D>[424] [0x7cdb2a37c57f0e49][1][0] targ: bssid=24:9f ch=11 rssi=-25
Dec 28 22:39:34.964505 +1000 000006.089466 Brcm4360<D>[425] [0x7cdb2a37c57f0e49][1][0] pref: rssi only: delta=230 score=230
Dec 28 22:39:34.964509 +1000 000006.089470 Brcm4360<D>[426] [0x7cdb2a37c57f0e49][1][0] wl0: wlc_bss_pref_score: RSSI is -25 in BSS e8:fc:af:f2:04:9f with preference score 0xe6 (qbss_load_aac 0x0 and qbss_load_chan_free 0x0)
Dec 28 22:39:34.964510 +1000 000006.089471 Brcm4360<D>[427] [0x7cdb2a37c57f0e49][1][0] targ: bssid=24:9e ch=40 rssi=-38
Dec 28 22:39:34.964512 +1000 000006.089473 Brcm4360<D>[428] [0x7cdb2a37c57f0e49][1][0] prof: boost rssi: band=1 delta=55 rssi=0
Dec 28 22:39:34.964514 +1000 000006.089475 Brcm4360<D>[429] [0x7cdb2a37c57f0e49][1][0] pref: rssi only: delta=255 score=255
Dec 28 22:39:34.964517 +1000 000006.089478 Brcm4360<D>[430] [0x7cdb2a37c57f0e49][1][0] wl0: wlc_bss_pref_score: RSSI is -38 in BSS e8:fc:af:f2:04:9e with preference score 0xff (qbss_load_aac 0x0 and qbss_load_chan_free 0x0)
Dec 28 22:39:34.964626 +1000 000006.089587 Brcm4360<D>[431] [0x7cdb2a37c57f0e49][1][0] wl0: JOIN: attempting BSSID: e8:fc:af:f2:04:9e
Dec 28 22:39:34.964629 +1000 000006.089589 Brcm4360<D>[432] [0x7cdb2a37c57f0e49][1][0] wl0.0: wlc_assoc_change_state: change assoc_state from SCAN to JOIN_START
Dec 28 22:39:34.964645 +1000 000006.089606 Brcm4360<D>[433] [0x7cdb2a37c57f0e49][1][0] backtrace[wlc_assoc_change_state]: 0x40df5 0xa7daf 0xb1de1 0xb54a9 0xb7e63 0xa6e2e 0xa5ed3 0x11a309 0xef732 0x2145b 0x23a4d 0x29d54 0x3c1ba 0x7cdb2a373350d52e 0x7cdb2a37335157cf 0x21881 0x7cdb2a3733517b5b 0x7cdb2a37326b0dcd 0x7cdb2a37b23ea591 0x7cdb2a37326b0e34 0x7cdb2a3733517a10 0x7cdb2a37b20917fd 0x7cdb2a37b20895dc 0x7cdb2a37b20897f8 0x7cdb2a37b230181f 0x7cdb2a37b22ba774 0x7cdb2a37b22fc1a6 0x7cdb2a37b235c9ea 0x7cdb2a37b1f2104f
Dec 28 22:39:34.964647 +1000 000006.089608 Brcm4360<D>[434] [0x7cdb2a37c57f0e49][1][0] wl0.0: JOIN: wlc_join_BSS: selected BSSID: e8:fc:af:f2:04:9e
Dec 28 22:39:34.964649 +1000 000006.089610 Brcm4360<D>[435] [0x7cdb2a37c57f0e49][1][0] wl0.0: wlc_join_check_ap_need_csa: ap CSA not needed
Dec 28 22:39:34.969961 +1000 000006.094921 Brcm4360<D>[436] [0x7cdb2a37c57f0e49][1][0] wl0: Call full phy cal from join_BSS
Dec 28 22:39:35.013681 +1000 000006.138641 Brcm4360<D>[437] [0x7cdb2a37c57f0e49][1][0] wl0: JOIN: BSS case, sending AUTH REQ alg=0 ...
Dec 28 22:39:35.013686 +1000 000006.138647 Brcm4360<D>[438] [0x7cdb2a37c57f0e49][1][0] wl0.0: wlc_assoc_change_state: change assoc_state from JOIN_START to SENT_AUTH_1
Dec 28 22:39:35.013703 +1000 000006.138664 Brcm4360<D>[439] [0x7cdb2a37c57f0e49][1][0] backtrace[wlc_assoc_change_state]: 0x40df5 0xa7daf 0xa9220 0xb1de9 0xb54a9 0xb7e63 0xa6e2e 0xa5ed3 0x11a309 0xef732 0x2145b 0x23a4d 0x29d54 0x3c1ba 0x7cdb2a373350d52e 0x7cdb2a37335157cf 0x21881 0x7cdb2a3733517b5b 0x7cdb2a37326b0dcd 0x7cdb2a37b23ea591 0x7cdb2a37326b0e34 0x7cdb2a3733517a10 0x7cdb2a37b20917fd 0x7cdb2a37b20895dc 0x7cdb2a37b20897f8 0x7cdb2a37b230181f 0x7cdb2a37b22ba774 0x7cdb2a37b22fc1a6 0x7cdb2a37b235c9ea 0x7cdb2a37b1f2104f
Dec 28 22:39:35.016005 +1000 000006.140966 Brcm4360<D>[440] [0x7cdb2a37c3d91e49][1][1] wl0: JOIN: authentication success
Dec 28 22:39:35.016009 +1000 000006.140970 Brcm4360<D>[441] [0x7cdb2a37c3d91e49][1][1] wl0.0: wlc_assoc_change_state: change assoc_state from SENT_AUTH_1 to SENT_ASSOC
Dec 28 22:39:35.016017 +1000 000006.140978 Brcm4360<D>[442] [0x7cdb2a37c3d91e49][1][1] backtrace[wlc_assoc_change_state]: 0x40df5 0xa7daf 0xaa32b 0xaefaa 0x10c61b 0xc585f 0x246068 0x21278 0x7cdb2a37b23e958f 0x7cdb2a37b23e73fa 0x7cdb2a37b23e74ef 0x7cdb2a37b1efd400
Dec 28 22:39:35.016021 +1000 000006.140982 Brcm4360<D>[443] [0x7cdb2a37c3d91e49][1][1] send assoc: bssid 24:9e
Dec 28 22:39:35.017965 +1000 000006.142926 Brcm4360<D>[444] [0x7cdb2a37c3bbd779][1][0] MacAuthEvent en0
Dec 28 22:39:35.017967 +1000 000006.142928 Brcm4360<D>[445] [0x7cdb2a37c3bbd779][1][0] Auth result for: e8:fc:af:f2:04:9e
Dec 28 22:39:35.017968 +1000 000006.142929 Brcm4360<D>[446] [0x7cdb2a37c3bbd779][1][0] MAC AUTH succeeded
Dec 28 22:39:35.018096 +1000 000006.143057 Brcm4360<D>[447] [0x7cdb2a37c3d91e49][1][1] rcvd assoc: status 0: bssid 24:9e
Dec 28 22:39:35.018105 +1000 000006.143066 Brcm4360<D>[448] [0x7cdb2a37c3d91e49][1][1] wl0: wlc_assocresp_client: turn MFP on
Dec 28 22:39:35.018108 +1000 000006.143069 Brcm4360<D>[449] [0x7cdb2a37c3d91e49][1][1] Assoc Type: JOIN (1) - wlc_assoc_complete
Dec 28 22:39:35.018113 +1000 000006.143074 Brcm4360<D>[450] [0x7cdb2a37c3d91e49][1][1] Assoc State Value: SENT_ASSOC (11)
Dec 28 22:39:35.018115 +1000 000006.143076 Brcm4360<D>[451] [0x7cdb2a37c3d91e49][1][1] Event Status Code: 0
Dec 28 22:39:35.018116 +1000 000006.143077 Brcm4360<D>[452] [0x7cdb2a37c3d91e49][1][1] DOT11 Status Code: 0
Dec 28 22:39:35.018117 +1000 000006.143078 Brcm4360<D>[453] [0x7cdb2a37c3d91e49][1][1] Current Chanspec : 40/80
Dec 28 22:39:35.018119 +1000 000006.143080 Brcm4360<D>[454] [0x7cdb2a37c3d91e49][1][1] Recursive Auth Completions: 0
2. Message of better Signal.
Dec 28 22:39:58.068667 +1000 000029.043288 Brcm4360<D>[652] [0x7cdb2a37c6900779][1][0] wl0: wlc_roamscan_start: Start roam scan: Doing a new scan with a scan period of 100 seconds for reason 8
Dec 28 22:39:58.068676 +1000 000029.043297 Brcm4360<D>[653] [0x7cdb2a37c6900779][1][0] wl0.0: insert ROAM request in state IDLE for SSID 'MySSID' in assoc_req list at slot 0
Dec 28 22:39:58.068894 +1000 000029.043515 Brcm4360<D>[654] [0x7cdb2a37c6900779][1][0] wl0 wlc_roam_scan: update original roam reason to 8
Dec 28 22:39:58.068898 +1000 000029.043518 Brcm4360<D>[655] [0x7cdb2a37c6900779][1][0] wl0.0: wlc_assoc_init: assoc state machine init to assoc->type 2 ROAM
Dec 28 22:39:58.068900 +1000 000029.043521 Brcm4360<D>[656] [0x7cdb2a37c6900779][1][0] ROAM: Start roamscan reason 8
Dec 28 22:39:58.068903 +1000 000029.043524 Brcm4360<D>[657] [0x7cdb2a37c6900779][1][0] wl0: Current roam reason is BETTER AP FOUND. The cache has 0 entries.
Dec 28 22:39:58.068908 +1000 000029.043529 Brcm4360<D>[658] [0x7cdb2a37c6900779][1][0] roam scan: reason=8 rssi=-39
Dec 28 22:39:58.068910 +1000 000029.043531 Brcm4360<D>[659] [0x7cdb2a37c6900779][1][0] starting full scan
Dec 28 22:39:58.068913 +1000 000029.043534 Brcm4360<D>[660] [0x7cdb2a37c6900779][1][0] wl0: SCAN: wlc_assoc_scan_start, starting a ROAM scan for SSID MySSID
Dec 28 22:39:58.068982 +1000 000029.043603 Brcm4360<D>[661] [0x7cdb2a37c6900779][1][0] scan start: all channels
Dec 28 22:39:58.069115 +1000 000029.043736 Brcm4360<D>[662] [0x7cdb2a37c6900779][1][0] wlc_scan(): AS_ROAM start...
Dec 28 22:39:58.069129 +1000 000029.043750 Brcm4360<D>[663] [0x7cdb2a37c6900779][1][0] wl0.0: wlc_assoc_change_state: change assoc_state from IDLE to SCAN
Dec 28 22:39:58.069151 +1000 000029.043772 Brcm4360<D>[664] [0x7cdb2a37c6900779][1][0] backtrace[wlc_assoc_change_state]: 0x40df5 0xa7daf 0xb80b7 0xa7a47 0xb309b 0x3663a 0x3cb2f 0x7cdb2a373350f824 0x7cdb2a37335157cf 0x21881 0x7cdb2a3733517b5b 0x7cdb2a37326b0dcd 0x7cdb2a37b23ea591 0x7cdb2a37326b0e34 0x7cdb2a3733517a10 0x7cdb2a37b20917fd 0x7cdb2a37b20895dc 0x7cdb2a37b20897f8 0x7cdb2a37b230181f 0x7cdb2a37b22ba774 0x7cdb2a37b22fc1a6 0x7cdb2a37b235c9ea 0x7cdb2a37b1f2104f
Dec 28 22:39:58.069286 +1000 000029.043906 Brcm4360<D>[665] [0x7cdb2a37c3d369b9][1][0] wlEvent(): post APPLE80211_M_ROAM_START event.
Dec 28 22:40:01.140512 +1000 000032.115038 Brcm4360<D>[666] [0x7cdb2a37c4779c09][1][0] wl0: SCAN: wlc_assoc_scan_complete
Dec 28 22:40:01.140516 +1000 000032.115042 Brcm4360<D>[667] [0x7cdb2a37c4779c09][1][0] wl0:wlc_assoc_scan_complete: delay roam scan by scan_block=17
Dec 28 22:40:01.140519 +1000 000032.115045 Brcm4360<D>[668] [0x7cdb2a37c4779c09][1][0] wl0: SCAN for ROAM: SSID scan complete, 5 results for "MySSID"
Dec 28 22:40:01.140521 +1000 000032.115047 Brcm4360<D>[669] [0x7cdb2a37c4779c09][1][0] wl0: ROAM: Multi AP Environment
Dec 28 22:40:01.140524 +1000 000032.115050 Brcm4360<D>[670] [0x7cdb2a37c4779c09][1][0] wl0.0: wlc_roam_prof_update_default: Only for no roam support
Dec 28 22:40:01.140527 +1000 000032.115053 Brcm4360<D>[671] [0x7cdb2a37c4779c09][1][0] wl0: RSSI is -39; 5 roaming target; Join preference fields are 0x0
Dec 28 22:40:01.140530 +1000 000032.115056 Brcm4360<D>[672] [0x7cdb2a37c4779c09][1][0] targ: bssid=24:9e ch=40 rssi=-39
Dec 28 22:40:01.140533 +1000 000032.115059 Brcm4360<D>[673] [0x7cdb2a37c4779c09][1][0] pref: rssi only: delta=216 score=216
Dec 28 22:40:01.140537 +1000 000032.115062 Brcm4360<D>[674] [0x7cdb2a37c4779c09][1][0] wl0: wlc_bss_pref_score: RSSI is -39 in BSS e8:fc:af:f2:04:9e with preference score 0xd8 (qbss_load_aac 0x0 and qbss_load_chan_free 0x0)
Dec 28 22:40:01.140539 +1000 000032.115065 Brcm4360<D>[675] [0x7cdb2a37c4779c09][1][0] targ: bssid=24:a0 ch=153 rssi=-20
Dec 28 22:40:01.140541 +1000 000032.115067 Brcm4360<D>[676] [0x7cdb2a37c4779c09][1][0] pref: rssi only: delta=235 score=235
Dec 28 22:40:01.140544 +1000 000032.115070 Brcm4360<D>[677] [0x7cdb2a37c4779c09][1][0] wl0: wlc_bss_pref_score: RSSI is -20 in BSS e8:fc:af:f2:04:a0 with preference score 0xeb (qbss_load_aac 0x0 and qbss_load_chan_free 0x0)
Dec 28 22:40:01.140546 +1000 000032.115072 Brcm4360<D>[678] [0x7cdb2a37c4779c09][1][0] targ: bssid=b4:d2 ch=6 rssi=-88
Dec 28 22:40:01.140548 +1000 000032.115074 Brcm4360<D>[679] [0x7cdb2a37c4779c09][1][0] pref: rssi only: delta=167 score=167
Dec 28 22:40:01.140551 +1000 000032.115077 Brcm4360<D>[680] [0x7cdb2a37c4779c09][1][0] wl0: wlc_bss_pref_score: RSSI is -88 in BSS 10:6f:3f:e7:b4:d2 with preference score 0xa7 (qbss_load_aac 0x0 and qbss_load_chan_free 0x0)
Dec 28 22:40:01.140553 +1000 000032.115079 Brcm4360<D>[681] [0x7cdb2a37c4779c09][1][0] targ: bssid=24:9f ch=11 rssi=-24
Dec 28 22:40:01.140555 +1000 000032.115081 Brcm4360<D>[682] [0x7cdb2a37c4779c09][1][0] prof: boost rssi: band=2 delta=55 rssi=0
Dec 28 22:40:01.140557 +1000 000032.115083 Brcm4360<D>[683] [0x7cdb2a37c4779c09][1][0] pref: rssi only: delta=255 score=255
Dec 28 22:40:01.140560 +1000 000032.115086 Brcm4360<D>[684] [0x7cdb2a37c4779c09][1][0] wl0: wlc_bss_pref_score: RSSI is -24 in BSS e8:fc:af:f2:04:9f with preference score 0xff (qbss_load_aac 0x0 and qbss_load_chan_free 0x0)
Dec 28 22:40:01.140562 +1000 000032.115088 Brcm4360<D>[685] [0x7cdb2a37c4779c09][1][0] targ: bssid=b4:d3 ch=52 rssi=-91
Dec 28 22:40:01.140564 +1000 000032.115090 Brcm4360<D>[686] [0x7cdb2a37c4779c09][1][0] pref: rssi only: delta=164 score=164
Dec 28 22:40:01.140567 +1000 000032.115093 Brcm4360<D>[687] [0x7cdb2a37c4779c09][1][0] wl0: wlc_bss_pref_score: RSSI is -91 in BSS 10:6f:3f:e7:b4:d3 with preference score 0xa4 (qbss_load_aac 0x0 and qbss_load_chan_free 0x0)
Dec 28 22:40:01.140580 +1000 000032.115106 Brcm4360<D>[688] [0x7cdb2a37c4779c09][1][0] wl0: ROAM: 5 roam targets after pruning
3. New wireless connection authentication failure
Dec 28 22:40:01.140686 +1000 000032.115211 Brcm4360<D>[689] [0x7cdb2a37c4779c09][1][0] wl0: JOIN: attempting BSSID: e8:fc:af:f2:04:a0
Dec 28 22:40:01.140702 +1000 000032.115228 Brcm4360<D>[690] [0x7cdb2a37c4779c09][1][0] wl0.0: wlc_assoc_change_state: change assoc_state from SCAN to JOIN_START
Dec 28 22:40:01.140711 +1000 000032.115237 Brcm4360<D>[691] [0x7cdb2a37c4779c09][1][0] backtrace[wlc_assoc_change_state]: 0x40df5 0xa7daf 0xb1de1 0xb54a9 0x250de7 0x24e234 0x4013b 0x7cdb2a37b23edf1c 0x7cdb2a37b1e435c3 0x7cdb2a37b1efd400
Dec 28 22:40:01.140715 +1000 000032.115241 Brcm4360<D>[692] [0x7cdb2a37c4779c09][1][0] wl0.0: wlc_assoc_change_state: change assoc_state from JOIN_START to WAIT_TX_DRAIN
Dec 28 22:40:01.140722 +1000 000032.115248 Brcm4360<D>[693] [0x7cdb2a37c4779c09][1][0] backtrace[wlc_assoc_change_state]: 0x40df5 0xa7daf 0xa8169 0xb1de9 0xb54a9 0x250de7 0x24e234 0x4013b 0x7cdb2a37b23edf1c 0x7cdb2a37b1e435c3 0x7cdb2a37b1efd400
Dec 28 22:40:01.140728 +1000 000032.115254 Brcm4360<D>[694] [0x7cdb2a37c4779c09][1][0] ROAM: waiting for 1 tx packets drained out before roam
Dec 28 22:40:01.142709 +1000 000032.117234 Brcm4360<D>[695] [0x7cdb2a37c3d91e49][1][1] wl0.0: JOIN: wlc_join_BSS: selected BSSID: e8:fc:af:f2:04:a0
Dec 28 22:40:01.142713 +1000 000032.117239 Brcm4360<D>[696] [0x7cdb2a37c3d91e49][1][1] wl0.0: wlc_join_check_ap_need_csa: ap CSA not needed
Dec 28 22:40:01.148038 +1000 000032.122563 Brcm4360<D>[697] [0x7cdb2a37c3d91e49][1][1] wl0: Call full phy cal from join_BSS
Dec 28 22:40:01.189263 +1000 000032.163789 Brcm4360<D>[698] [0x7cdb2a37c3d91e49][1][1] wl0: JOIN: BSS case, sending AUTH REQ alg=0 ...
Dec 28 22:40:01.189266 +1000 000032.163792 Brcm4360<D>[699] [0x7cdb2a37c3d91e49][1][1] wl0.0: wlc_assoc_change_state: change assoc_state from WAIT_TX_DRAIN to SENT_AUTH_1
Dec 28 22:40:01.189273 +1000 000032.163799 Brcm4360<D>[700] [0x7cdb2a37c3d91e49][1][1] backtrace[wlc_assoc_change_state]: 0x40df5 0xa7daf 0xa9220 0x106c27 0xd21bd 0x245eae 0x21278 0x7cdb2a37b23e958f 0x7cdb2a37b23e73fa 0x7cdb2a37b23e74ef 0x7cdb2a37b1efd400
Dec 28 22:40:01.502615 +1000 000032.477141 Brcm4360<D>[701] [0x7cdb2a37c3d36e49][1][0] wl0: JOIN: timeout waiting for authentication response, assoc_state 8
Dec 28 22:40:01.502752 +1000 000032.477278 Brcm4360<D>[702] [0x7cdb2a37c3d36e49][1][0] wl0: JOIN: attempting BSSID: e8:fc:af:f2:04:9e
Dec 28 22:40:01.502761 +1000 000032.477287 Brcm4360<D>[703] [0x7cdb2a37c3d36e49][1][0] wl0.0: wlc_assoc_change_state: change assoc_state from SENT_AUTH_1 to JOIN_START
Dec 28 22:40:01.502771 +1000 000032.477297 Brcm4360<D>[704] [0x7cdb2a37c3d36e49][1][0] backtrace[wlc_assoc_change_state]: 0x40df5 0xa7daf 0xb1de1 0xaa478 0x4013b 0x7cdb2a37b23edf1c 0x7cdb2a37b1e435c3 0x7cdb2a37b1efd400
Dec 28 22:40:01.502776 +1000 000032.477302 Brcm4360<D>[705] [0x7cdb2a37c3d36e49][1][0] wl0.0: JOIN: wlc_join_BSS: selected BSSID: e8:fc:af:f2:04:9e
Dec 28 22:40:01.502780 +1000 000032.477305 Brcm4360<D>[706] [0x7cdb2a37c3d36e49][1][0] wl0.0: wlc_join_check_ap_need_csa: ap CSA not needed
Dec 28 22:40:01.508670 +1000 000032.483196 Brcm4360<D>[707] [0x7cdb2a37c3d36e49][1][0] wl0: Call full phy cal from join_BSS
Dec 28 22:40:01.550031 +1000 000032.524557 Brcm4360<D>[708] [0x7cdb2a37c3d36e49][1][0] wl0: JOIN: BSS case, sending AUTH REQ alg=0 ...
Dec 28 22:40:01.550033 +1000 000032.524559 Brcm4360<D>[709] [0x7cdb2a37c3d36e49][1][0] wl0: wlc_txbf_init_sta: scb aleady has user index 0
Dec 28 22:40:01.550181 +1000 000032.524707 Brcm4360<D>[710] [0x7cdb2a37c3d36e49][1][0] wl0.0: wlc_assoc_change_state: change assoc_state from JOIN_START to SENT_AUTH_1
Dec 28 22:40:01.550185 +1000 000032.524711 Brcm4360<D>[711] [0x7cdb2a37c3d36e49][1][0] backtrace[wlc_assoc_change_state]: 0x40df5 0xa7daf 0xa9220 0xb1de9 0xaa478 0x4013b 0x7cdb2a37b23edf1c 0x7cdb2a37b1e435c3 0x7cdb2a37b1efd400
Dec 28 22:40:01.552221 +1000 000032.526747 Brcm4360<D>[712] [0x7cdb2a37c4779c09][1][0] MacAuthEvent en0
Dec 28 22:40:01.552222 +1000 000032.526748 Brcm4360<D>[713] [0x7cdb2a37c4779c09][1][0] Auth result for: e8:fc:af:f2:04:a0
Dec 28 22:40:01.552223 +1000 000032.526749 Brcm4360<D>[714] [0x7cdb2a37c4779c09][1][0] Auth timed out
Dec 28 22:40:01.552225 +1000 000032.526751 Brcm4360<D>[715] [0x7cdb2a37c4779c09][1][0] Log system state... : AuthFail:sts:2_rsn:0
Dec 28 22:40:01.552228 +1000 000032.526754 Brcm4360<D>[716] [0x7cdb2a37c4779c09][1][0] wl0: Sep 25 2016 22:49:49 version 7.21.95.175 (r622517)(P2P)
For the past year I've been living with random wake failure crashes and have never had the time to actually debug. Well its xmas and holidays and after 3 crashes in the last 5 days after sleep I thought I would spend some time looking through the logs to see what is actually happening.
First, in CoreCapture in console I notice that both com.apple.drive.Airport.Brcm4360.0 and com.apple.iokit.IO80211Family both have alot of captured logs. Even more interesting is the fact that the vast majority of these have a post fix of '=AuthFail:sts:2_rsn:0'. This is intriguing as to what is attempting to be authenticated that is actually failing against in my home.
So I set about reviewing the lastest AirportBrcm4360_logs-xxx.txt file and found and interesting item in regards to what is happening.I should say at the start that my wireless AP is a R8000 and using smart connect on the 5G band. At the time of writing my Mac Air is connected to the upper band on channel 153. This I acieved by manually stopping and starting wifi a few times. I can successfully connect to both 5G bands with my MAC in that manner. Just to prove the point I can also manually connect to both BSSIDs by using https://github.com/qpSHiNqp/airport-bssid.
So, looking through the BRCM4360 logs I find that when my MAC wakes up it looks for the BSSID associated with the lower 5G band and associates and authenticates to it. As soon as this is achieved I get another message that states there is a better signal available, which is the higher of the 2 5G bands (channel 153) and then the drivers attempt to connect and associate with it. However, the driver reports that it can not authenticate to this band and waits a bit of time and then corecapture kicks in to capture all the logs. I'm assuming at this point that the Mac has indeed crashed and restarts.
I've attached the applicable parts of the logs below as:
1. The connection to the lower of the 5G bands is shown below where the 9th line from the bottom shows that the authentication succeeded.
2. The message regarding a better signal.
3. The rejected authentication attempt against the upper 5G band.
And the tell tail message at the end of the auth failure is AuthFail:sts:2_rsn:0.
Has any body else experienced this? Has anyone found a way of solving this? I've no idea why the driver can not authenticate with the higher channel when I can perform this action manually on the MAC and connect without issue. The only thing that I can think of is that the driver does not like the R8000 and the load balancing behaviour of the 5G band. However, if that was the case then I expect it would fail when I perform the connect manually.
Any one have any idea's here? To me this seems to be a driver issue. Why does it not fallback to the initial connection that was authenticated? If any one is interested I can send the entire log that has the complete back trace etc in it.
1. Connection Authenticated.
Dec 28 22:39:34.963994 +1000 000006.088955 Brcm4360<D>[405] [0x7cdb2a37c57f0e49][1][0] wl0: wlc_join_pref_band_upd: band pref is 0
Dec 28 22:39:34.964034 +1000 000006.088995 Brcm4360<D>[406] [0x7cdb2a37c57f0e49][1][0] wl0.0: insert JOIN request in state IDLE for SSID '' in assoc_req list at slot 0
Dec 28 22:39:34.964367 +1000 000006.089328 Brcm4360<D>[407] [0x7cdb2a37c57f0e49][1][0] wl0: SCAN: wlc_join_start, Setting SSID to "MySSID"...
Dec 28 22:39:34.964370 +1000 000006.089331 Brcm4360<D>[408] [0x7cdb2a37c57f0e49][1][0] wl0.0: wlc_assoc_change_state: change assoc_state from IDLE to JOIN_INIT
Dec 28 22:39:34.964385 +1000 000006.089346 Brcm4360<D>[409] [0x7cdb2a37c57f0e49][1][0] backtrace[wlc_assoc_change_state]: 0x40df5 0xa7daf 0xaf818 0xa6b8c 0xa5ed3 0x11a309 0xef732 0x2145b 0x23a4d 0x29d54 0x3c1ba 0x7cdb2a373350d52e 0x7cdb2a37335157cf 0x21881 0x7cdb2a3733517b5b 0x7cdb2a37326b0dcd 0x7cdb2a37b23ea591 0x7cdb2a37326b0e34 0x7cdb2a3733517a10 0x7cdb2a37b20917fd 0x7cdb2a37b20895dc 0x7cdb2a37b20897f8 0x7cdb2a37b230181f 0x7cdb2a37b22ba774 0x7cdb2a37b22fc1a6 0x7cdb2a37b235c9ea 0x7cdb2a37b1f2104f
Dec 28 22:39:34.964388 +1000 000006.089349 Brcm4360<D>[410] [0x7cdb2a37c57f0e49][1][0] wl0.0: JOIN request in state JOIN_INIT for SSID 'MySSID' exists in assoc_req list at slot 0
Dec 28 22:39:34.964392 +1000 000006.089353 Brcm4360<D>[411] [0x7cdb2a37c57f0e49][1][0] wl0.0: wlc_assoc_init: assoc state machine init to assoc->type 1 JOIN
Dec 28 22:39:34.964395 +1000 000006.089356 Brcm4360<D>[412] [0x7cdb2a37c57f0e49][1][0] starting assoc scan
Dec 28 22:39:34.964397 +1000 000006.089358 Brcm4360<D>[413] [0x7cdb2a37c57f0e49][1][0] wl0: SCAN: wlc_assoc_scan_start, starting a JOIN scan for SSID MySSID
Dec 28 22:39:34.964468 +1000 000006.089429 Brcm4360<D>[414] [0x7cdb2a37c57f0e49][1][0] wl0: wlc_assoc_cache_validate_timestamps: 2 hits, oldest 0 sec, using cache hits
Dec 28 22:39:34.964470 +1000 000006.089431 Brcm4360<D>[415] [0x7cdb2a37c57f0e49][1][0] wl0: JOIN: using the cached scan results for assoc (2 hits)
Dec 28 22:39:34.964472 +1000 000006.089433 Brcm4360<D>[416] [0x7cdb2a37c57f0e49][1][0] wl0.0: wlc_assoc_change_state: change assoc_state from JOIN_INIT to SCAN
Dec 28 22:39:34.964487 +1000 000006.089448 Brcm4360<D>[417] [0x7cdb2a37c57f0e49][1][0] backtrace[wlc_assoc_change_state]: 0x40df5 0xa7daf 0xb7e56 0xa6e2e 0xa5ed3 0x11a309 0xef732 0x2145b 0x23a4d 0x29d54 0x3c1ba 0x7cdb2a373350d52e 0x7cdb2a37335157cf 0x21881 0x7cdb2a3733517b5b 0x7cdb2a37326b0dcd 0x7cdb2a37b23ea591 0x7cdb2a37326b0e34 0x7cdb2a3733517a10 0x7cdb2a37b20917fd 0x7cdb2a37b20895dc 0x7cdb2a37b20897f8 0x7cdb2a37b230181f 0x7cdb2a37b22ba774 0x7cdb2a37b22fc1a6 0x7cdb2a37b235c9ea 0x7cdb2a37b1f2104f
Dec 28 22:39:34.964490 +1000 000006.089451 Brcm4360<D>[418] [0x7cdb2a37c57f0e49][1][0] wl0: SCAN: wlc_assoc_scan_complete
Dec 28 22:39:34.964492 +1000 000006.089453 Brcm4360<D>[419] [0x7cdb2a37c57f0e49][1][0] wl0:wlc_assoc_scan_complete: delay roam scan by scan_block=10
Dec 28 22:39:34.964494 +1000 000006.089455 Brcm4360<D>[420] [0x7cdb2a37c57f0e49][1][0] wl0: SCAN for JOIN: SSID scan complete, 2 results for "MySSID"
Dec 28 22:39:34.964496 +1000 000006.089457 Brcm4360<D>[421] [0x7cdb2a37c57f0e49][1][0] wl0: ROAM: Single AP Environment
Dec 28 22:39:34.964498 +1000 000006.089459 Brcm4360<D>[422] [0x7cdb2a37c57f0e49][1][0] wl0.0: wlc_roam_prof_update_default: Only for no roam support
Dec 28 22:39:34.964501 +1000 000006.089461 Brcm4360<D>[423] [0x7cdb2a37c57f0e49][1][0] wl0: RSSI is 0; 2 roaming target
Dec 28 22:39:34.964503 +1000 000006.089464 Brcm4360<D>[424] [0x7cdb2a37c57f0e49][1][0] targ: bssid=24:9f ch=11 rssi=-25
Dec 28 22:39:34.964505 +1000 000006.089466 Brcm4360<D>[425] [0x7cdb2a37c57f0e49][1][0] pref: rssi only: delta=230 score=230
Dec 28 22:39:34.964509 +1000 000006.089470 Brcm4360<D>[426] [0x7cdb2a37c57f0e49][1][0] wl0: wlc_bss_pref_score: RSSI is -25 in BSS e8:fc:af:f2:04:9f with preference score 0xe6 (qbss_load_aac 0x0 and qbss_load_chan_free 0x0)
Dec 28 22:39:34.964510 +1000 000006.089471 Brcm4360<D>[427] [0x7cdb2a37c57f0e49][1][0] targ: bssid=24:9e ch=40 rssi=-38
Dec 28 22:39:34.964512 +1000 000006.089473 Brcm4360<D>[428] [0x7cdb2a37c57f0e49][1][0] prof: boost rssi: band=1 delta=55 rssi=0
Dec 28 22:39:34.964514 +1000 000006.089475 Brcm4360<D>[429] [0x7cdb2a37c57f0e49][1][0] pref: rssi only: delta=255 score=255
Dec 28 22:39:34.964517 +1000 000006.089478 Brcm4360<D>[430] [0x7cdb2a37c57f0e49][1][0] wl0: wlc_bss_pref_score: RSSI is -38 in BSS e8:fc:af:f2:04:9e with preference score 0xff (qbss_load_aac 0x0 and qbss_load_chan_free 0x0)
Dec 28 22:39:34.964626 +1000 000006.089587 Brcm4360<D>[431] [0x7cdb2a37c57f0e49][1][0] wl0: JOIN: attempting BSSID: e8:fc:af:f2:04:9e
Dec 28 22:39:34.964629 +1000 000006.089589 Brcm4360<D>[432] [0x7cdb2a37c57f0e49][1][0] wl0.0: wlc_assoc_change_state: change assoc_state from SCAN to JOIN_START
Dec 28 22:39:34.964645 +1000 000006.089606 Brcm4360<D>[433] [0x7cdb2a37c57f0e49][1][0] backtrace[wlc_assoc_change_state]: 0x40df5 0xa7daf 0xb1de1 0xb54a9 0xb7e63 0xa6e2e 0xa5ed3 0x11a309 0xef732 0x2145b 0x23a4d 0x29d54 0x3c1ba 0x7cdb2a373350d52e 0x7cdb2a37335157cf 0x21881 0x7cdb2a3733517b5b 0x7cdb2a37326b0dcd 0x7cdb2a37b23ea591 0x7cdb2a37326b0e34 0x7cdb2a3733517a10 0x7cdb2a37b20917fd 0x7cdb2a37b20895dc 0x7cdb2a37b20897f8 0x7cdb2a37b230181f 0x7cdb2a37b22ba774 0x7cdb2a37b22fc1a6 0x7cdb2a37b235c9ea 0x7cdb2a37b1f2104f
Dec 28 22:39:34.964647 +1000 000006.089608 Brcm4360<D>[434] [0x7cdb2a37c57f0e49][1][0] wl0.0: JOIN: wlc_join_BSS: selected BSSID: e8:fc:af:f2:04:9e
Dec 28 22:39:34.964649 +1000 000006.089610 Brcm4360<D>[435] [0x7cdb2a37c57f0e49][1][0] wl0.0: wlc_join_check_ap_need_csa: ap CSA not needed
Dec 28 22:39:34.969961 +1000 000006.094921 Brcm4360<D>[436] [0x7cdb2a37c57f0e49][1][0] wl0: Call full phy cal from join_BSS
Dec 28 22:39:35.013681 +1000 000006.138641 Brcm4360<D>[437] [0x7cdb2a37c57f0e49][1][0] wl0: JOIN: BSS case, sending AUTH REQ alg=0 ...
Dec 28 22:39:35.013686 +1000 000006.138647 Brcm4360<D>[438] [0x7cdb2a37c57f0e49][1][0] wl0.0: wlc_assoc_change_state: change assoc_state from JOIN_START to SENT_AUTH_1
Dec 28 22:39:35.013703 +1000 000006.138664 Brcm4360<D>[439] [0x7cdb2a37c57f0e49][1][0] backtrace[wlc_assoc_change_state]: 0x40df5 0xa7daf 0xa9220 0xb1de9 0xb54a9 0xb7e63 0xa6e2e 0xa5ed3 0x11a309 0xef732 0x2145b 0x23a4d 0x29d54 0x3c1ba 0x7cdb2a373350d52e 0x7cdb2a37335157cf 0x21881 0x7cdb2a3733517b5b 0x7cdb2a37326b0dcd 0x7cdb2a37b23ea591 0x7cdb2a37326b0e34 0x7cdb2a3733517a10 0x7cdb2a37b20917fd 0x7cdb2a37b20895dc 0x7cdb2a37b20897f8 0x7cdb2a37b230181f 0x7cdb2a37b22ba774 0x7cdb2a37b22fc1a6 0x7cdb2a37b235c9ea 0x7cdb2a37b1f2104f
Dec 28 22:39:35.016005 +1000 000006.140966 Brcm4360<D>[440] [0x7cdb2a37c3d91e49][1][1] wl0: JOIN: authentication success
Dec 28 22:39:35.016009 +1000 000006.140970 Brcm4360<D>[441] [0x7cdb2a37c3d91e49][1][1] wl0.0: wlc_assoc_change_state: change assoc_state from SENT_AUTH_1 to SENT_ASSOC
Dec 28 22:39:35.016017 +1000 000006.140978 Brcm4360<D>[442] [0x7cdb2a37c3d91e49][1][1] backtrace[wlc_assoc_change_state]: 0x40df5 0xa7daf 0xaa32b 0xaefaa 0x10c61b 0xc585f 0x246068 0x21278 0x7cdb2a37b23e958f 0x7cdb2a37b23e73fa 0x7cdb2a37b23e74ef 0x7cdb2a37b1efd400
Dec 28 22:39:35.016021 +1000 000006.140982 Brcm4360<D>[443] [0x7cdb2a37c3d91e49][1][1] send assoc: bssid 24:9e
Dec 28 22:39:35.017965 +1000 000006.142926 Brcm4360<D>[444] [0x7cdb2a37c3bbd779][1][0] MacAuthEvent en0
Dec 28 22:39:35.017967 +1000 000006.142928 Brcm4360<D>[445] [0x7cdb2a37c3bbd779][1][0] Auth result for: e8:fc:af:f2:04:9e
Dec 28 22:39:35.017968 +1000 000006.142929 Brcm4360<D>[446] [0x7cdb2a37c3bbd779][1][0] MAC AUTH succeeded
Dec 28 22:39:35.018096 +1000 000006.143057 Brcm4360<D>[447] [0x7cdb2a37c3d91e49][1][1] rcvd assoc: status 0: bssid 24:9e
Dec 28 22:39:35.018105 +1000 000006.143066 Brcm4360<D>[448] [0x7cdb2a37c3d91e49][1][1] wl0: wlc_assocresp_client: turn MFP on
Dec 28 22:39:35.018108 +1000 000006.143069 Brcm4360<D>[449] [0x7cdb2a37c3d91e49][1][1] Assoc Type: JOIN (1) - wlc_assoc_complete
Dec 28 22:39:35.018113 +1000 000006.143074 Brcm4360<D>[450] [0x7cdb2a37c3d91e49][1][1] Assoc State Value: SENT_ASSOC (11)
Dec 28 22:39:35.018115 +1000 000006.143076 Brcm4360<D>[451] [0x7cdb2a37c3d91e49][1][1] Event Status Code: 0
Dec 28 22:39:35.018116 +1000 000006.143077 Brcm4360<D>[452] [0x7cdb2a37c3d91e49][1][1] DOT11 Status Code: 0
Dec 28 22:39:35.018117 +1000 000006.143078 Brcm4360<D>[453] [0x7cdb2a37c3d91e49][1][1] Current Chanspec : 40/80
Dec 28 22:39:35.018119 +1000 000006.143080 Brcm4360<D>[454] [0x7cdb2a37c3d91e49][1][1] Recursive Auth Completions: 0
2. Message of better Signal.
Dec 28 22:39:58.068667 +1000 000029.043288 Brcm4360<D>[652] [0x7cdb2a37c6900779][1][0] wl0: wlc_roamscan_start: Start roam scan: Doing a new scan with a scan period of 100 seconds for reason 8
Dec 28 22:39:58.068676 +1000 000029.043297 Brcm4360<D>[653] [0x7cdb2a37c6900779][1][0] wl0.0: insert ROAM request in state IDLE for SSID 'MySSID' in assoc_req list at slot 0
Dec 28 22:39:58.068894 +1000 000029.043515 Brcm4360<D>[654] [0x7cdb2a37c6900779][1][0] wl0 wlc_roam_scan: update original roam reason to 8
Dec 28 22:39:58.068898 +1000 000029.043518 Brcm4360<D>[655] [0x7cdb2a37c6900779][1][0] wl0.0: wlc_assoc_init: assoc state machine init to assoc->type 2 ROAM
Dec 28 22:39:58.068900 +1000 000029.043521 Brcm4360<D>[656] [0x7cdb2a37c6900779][1][0] ROAM: Start roamscan reason 8
Dec 28 22:39:58.068903 +1000 000029.043524 Brcm4360<D>[657] [0x7cdb2a37c6900779][1][0] wl0: Current roam reason is BETTER AP FOUND. The cache has 0 entries.
Dec 28 22:39:58.068908 +1000 000029.043529 Brcm4360<D>[658] [0x7cdb2a37c6900779][1][0] roam scan: reason=8 rssi=-39
Dec 28 22:39:58.068910 +1000 000029.043531 Brcm4360<D>[659] [0x7cdb2a37c6900779][1][0] starting full scan
Dec 28 22:39:58.068913 +1000 000029.043534 Brcm4360<D>[660] [0x7cdb2a37c6900779][1][0] wl0: SCAN: wlc_assoc_scan_start, starting a ROAM scan for SSID MySSID
Dec 28 22:39:58.068982 +1000 000029.043603 Brcm4360<D>[661] [0x7cdb2a37c6900779][1][0] scan start: all channels
Dec 28 22:39:58.069115 +1000 000029.043736 Brcm4360<D>[662] [0x7cdb2a37c6900779][1][0] wlc_scan(): AS_ROAM start...
Dec 28 22:39:58.069129 +1000 000029.043750 Brcm4360<D>[663] [0x7cdb2a37c6900779][1][0] wl0.0: wlc_assoc_change_state: change assoc_state from IDLE to SCAN
Dec 28 22:39:58.069151 +1000 000029.043772 Brcm4360<D>[664] [0x7cdb2a37c6900779][1][0] backtrace[wlc_assoc_change_state]: 0x40df5 0xa7daf 0xb80b7 0xa7a47 0xb309b 0x3663a 0x3cb2f 0x7cdb2a373350f824 0x7cdb2a37335157cf 0x21881 0x7cdb2a3733517b5b 0x7cdb2a37326b0dcd 0x7cdb2a37b23ea591 0x7cdb2a37326b0e34 0x7cdb2a3733517a10 0x7cdb2a37b20917fd 0x7cdb2a37b20895dc 0x7cdb2a37b20897f8 0x7cdb2a37b230181f 0x7cdb2a37b22ba774 0x7cdb2a37b22fc1a6 0x7cdb2a37b235c9ea 0x7cdb2a37b1f2104f
Dec 28 22:39:58.069286 +1000 000029.043906 Brcm4360<D>[665] [0x7cdb2a37c3d369b9][1][0] wlEvent(): post APPLE80211_M_ROAM_START event.
Dec 28 22:40:01.140512 +1000 000032.115038 Brcm4360<D>[666] [0x7cdb2a37c4779c09][1][0] wl0: SCAN: wlc_assoc_scan_complete
Dec 28 22:40:01.140516 +1000 000032.115042 Brcm4360<D>[667] [0x7cdb2a37c4779c09][1][0] wl0:wlc_assoc_scan_complete: delay roam scan by scan_block=17
Dec 28 22:40:01.140519 +1000 000032.115045 Brcm4360<D>[668] [0x7cdb2a37c4779c09][1][0] wl0: SCAN for ROAM: SSID scan complete, 5 results for "MySSID"
Dec 28 22:40:01.140521 +1000 000032.115047 Brcm4360<D>[669] [0x7cdb2a37c4779c09][1][0] wl0: ROAM: Multi AP Environment
Dec 28 22:40:01.140524 +1000 000032.115050 Brcm4360<D>[670] [0x7cdb2a37c4779c09][1][0] wl0.0: wlc_roam_prof_update_default: Only for no roam support
Dec 28 22:40:01.140527 +1000 000032.115053 Brcm4360<D>[671] [0x7cdb2a37c4779c09][1][0] wl0: RSSI is -39; 5 roaming target; Join preference fields are 0x0
Dec 28 22:40:01.140530 +1000 000032.115056 Brcm4360<D>[672] [0x7cdb2a37c4779c09][1][0] targ: bssid=24:9e ch=40 rssi=-39
Dec 28 22:40:01.140533 +1000 000032.115059 Brcm4360<D>[673] [0x7cdb2a37c4779c09][1][0] pref: rssi only: delta=216 score=216
Dec 28 22:40:01.140537 +1000 000032.115062 Brcm4360<D>[674] [0x7cdb2a37c4779c09][1][0] wl0: wlc_bss_pref_score: RSSI is -39 in BSS e8:fc:af:f2:04:9e with preference score 0xd8 (qbss_load_aac 0x0 and qbss_load_chan_free 0x0)
Dec 28 22:40:01.140539 +1000 000032.115065 Brcm4360<D>[675] [0x7cdb2a37c4779c09][1][0] targ: bssid=24:a0 ch=153 rssi=-20
Dec 28 22:40:01.140541 +1000 000032.115067 Brcm4360<D>[676] [0x7cdb2a37c4779c09][1][0] pref: rssi only: delta=235 score=235
Dec 28 22:40:01.140544 +1000 000032.115070 Brcm4360<D>[677] [0x7cdb2a37c4779c09][1][0] wl0: wlc_bss_pref_score: RSSI is -20 in BSS e8:fc:af:f2:04:a0 with preference score 0xeb (qbss_load_aac 0x0 and qbss_load_chan_free 0x0)
Dec 28 22:40:01.140546 +1000 000032.115072 Brcm4360<D>[678] [0x7cdb2a37c4779c09][1][0] targ: bssid=b4:d2 ch=6 rssi=-88
Dec 28 22:40:01.140548 +1000 000032.115074 Brcm4360<D>[679] [0x7cdb2a37c4779c09][1][0] pref: rssi only: delta=167 score=167
Dec 28 22:40:01.140551 +1000 000032.115077 Brcm4360<D>[680] [0x7cdb2a37c4779c09][1][0] wl0: wlc_bss_pref_score: RSSI is -88 in BSS 10:6f:3f:e7:b4:d2 with preference score 0xa7 (qbss_load_aac 0x0 and qbss_load_chan_free 0x0)
Dec 28 22:40:01.140553 +1000 000032.115079 Brcm4360<D>[681] [0x7cdb2a37c4779c09][1][0] targ: bssid=24:9f ch=11 rssi=-24
Dec 28 22:40:01.140555 +1000 000032.115081 Brcm4360<D>[682] [0x7cdb2a37c4779c09][1][0] prof: boost rssi: band=2 delta=55 rssi=0
Dec 28 22:40:01.140557 +1000 000032.115083 Brcm4360<D>[683] [0x7cdb2a37c4779c09][1][0] pref: rssi only: delta=255 score=255
Dec 28 22:40:01.140560 +1000 000032.115086 Brcm4360<D>[684] [0x7cdb2a37c4779c09][1][0] wl0: wlc_bss_pref_score: RSSI is -24 in BSS e8:fc:af:f2:04:9f with preference score 0xff (qbss_load_aac 0x0 and qbss_load_chan_free 0x0)
Dec 28 22:40:01.140562 +1000 000032.115088 Brcm4360<D>[685] [0x7cdb2a37c4779c09][1][0] targ: bssid=b4:d3 ch=52 rssi=-91
Dec 28 22:40:01.140564 +1000 000032.115090 Brcm4360<D>[686] [0x7cdb2a37c4779c09][1][0] pref: rssi only: delta=164 score=164
Dec 28 22:40:01.140567 +1000 000032.115093 Brcm4360<D>[687] [0x7cdb2a37c4779c09][1][0] wl0: wlc_bss_pref_score: RSSI is -91 in BSS 10:6f:3f:e7:b4:d3 with preference score 0xa4 (qbss_load_aac 0x0 and qbss_load_chan_free 0x0)
Dec 28 22:40:01.140580 +1000 000032.115106 Brcm4360<D>[688] [0x7cdb2a37c4779c09][1][0] wl0: ROAM: 5 roam targets after pruning
3. New wireless connection authentication failure
Dec 28 22:40:01.140686 +1000 000032.115211 Brcm4360<D>[689] [0x7cdb2a37c4779c09][1][0] wl0: JOIN: attempting BSSID: e8:fc:af:f2:04:a0
Dec 28 22:40:01.140702 +1000 000032.115228 Brcm4360<D>[690] [0x7cdb2a37c4779c09][1][0] wl0.0: wlc_assoc_change_state: change assoc_state from SCAN to JOIN_START
Dec 28 22:40:01.140711 +1000 000032.115237 Brcm4360<D>[691] [0x7cdb2a37c4779c09][1][0] backtrace[wlc_assoc_change_state]: 0x40df5 0xa7daf 0xb1de1 0xb54a9 0x250de7 0x24e234 0x4013b 0x7cdb2a37b23edf1c 0x7cdb2a37b1e435c3 0x7cdb2a37b1efd400
Dec 28 22:40:01.140715 +1000 000032.115241 Brcm4360<D>[692] [0x7cdb2a37c4779c09][1][0] wl0.0: wlc_assoc_change_state: change assoc_state from JOIN_START to WAIT_TX_DRAIN
Dec 28 22:40:01.140722 +1000 000032.115248 Brcm4360<D>[693] [0x7cdb2a37c4779c09][1][0] backtrace[wlc_assoc_change_state]: 0x40df5 0xa7daf 0xa8169 0xb1de9 0xb54a9 0x250de7 0x24e234 0x4013b 0x7cdb2a37b23edf1c 0x7cdb2a37b1e435c3 0x7cdb2a37b1efd400
Dec 28 22:40:01.140728 +1000 000032.115254 Brcm4360<D>[694] [0x7cdb2a37c4779c09][1][0] ROAM: waiting for 1 tx packets drained out before roam
Dec 28 22:40:01.142709 +1000 000032.117234 Brcm4360<D>[695] [0x7cdb2a37c3d91e49][1][1] wl0.0: JOIN: wlc_join_BSS: selected BSSID: e8:fc:af:f2:04:a0
Dec 28 22:40:01.142713 +1000 000032.117239 Brcm4360<D>[696] [0x7cdb2a37c3d91e49][1][1] wl0.0: wlc_join_check_ap_need_csa: ap CSA not needed
Dec 28 22:40:01.148038 +1000 000032.122563 Brcm4360<D>[697] [0x7cdb2a37c3d91e49][1][1] wl0: Call full phy cal from join_BSS
Dec 28 22:40:01.189263 +1000 000032.163789 Brcm4360<D>[698] [0x7cdb2a37c3d91e49][1][1] wl0: JOIN: BSS case, sending AUTH REQ alg=0 ...
Dec 28 22:40:01.189266 +1000 000032.163792 Brcm4360<D>[699] [0x7cdb2a37c3d91e49][1][1] wl0.0: wlc_assoc_change_state: change assoc_state from WAIT_TX_DRAIN to SENT_AUTH_1
Dec 28 22:40:01.189273 +1000 000032.163799 Brcm4360<D>[700] [0x7cdb2a37c3d91e49][1][1] backtrace[wlc_assoc_change_state]: 0x40df5 0xa7daf 0xa9220 0x106c27 0xd21bd 0x245eae 0x21278 0x7cdb2a37b23e958f 0x7cdb2a37b23e73fa 0x7cdb2a37b23e74ef 0x7cdb2a37b1efd400
Dec 28 22:40:01.502615 +1000 000032.477141 Brcm4360<D>[701] [0x7cdb2a37c3d36e49][1][0] wl0: JOIN: timeout waiting for authentication response, assoc_state 8
Dec 28 22:40:01.502752 +1000 000032.477278 Brcm4360<D>[702] [0x7cdb2a37c3d36e49][1][0] wl0: JOIN: attempting BSSID: e8:fc:af:f2:04:9e
Dec 28 22:40:01.502761 +1000 000032.477287 Brcm4360<D>[703] [0x7cdb2a37c3d36e49][1][0] wl0.0: wlc_assoc_change_state: change assoc_state from SENT_AUTH_1 to JOIN_START
Dec 28 22:40:01.502771 +1000 000032.477297 Brcm4360<D>[704] [0x7cdb2a37c3d36e49][1][0] backtrace[wlc_assoc_change_state]: 0x40df5 0xa7daf 0xb1de1 0xaa478 0x4013b 0x7cdb2a37b23edf1c 0x7cdb2a37b1e435c3 0x7cdb2a37b1efd400
Dec 28 22:40:01.502776 +1000 000032.477302 Brcm4360<D>[705] [0x7cdb2a37c3d36e49][1][0] wl0.0: JOIN: wlc_join_BSS: selected BSSID: e8:fc:af:f2:04:9e
Dec 28 22:40:01.502780 +1000 000032.477305 Brcm4360<D>[706] [0x7cdb2a37c3d36e49][1][0] wl0.0: wlc_join_check_ap_need_csa: ap CSA not needed
Dec 28 22:40:01.508670 +1000 000032.483196 Brcm4360<D>[707] [0x7cdb2a37c3d36e49][1][0] wl0: Call full phy cal from join_BSS
Dec 28 22:40:01.550031 +1000 000032.524557 Brcm4360<D>[708] [0x7cdb2a37c3d36e49][1][0] wl0: JOIN: BSS case, sending AUTH REQ alg=0 ...
Dec 28 22:40:01.550033 +1000 000032.524559 Brcm4360<D>[709] [0x7cdb2a37c3d36e49][1][0] wl0: wlc_txbf_init_sta: scb aleady has user index 0
Dec 28 22:40:01.550181 +1000 000032.524707 Brcm4360<D>[710] [0x7cdb2a37c3d36e49][1][0] wl0.0: wlc_assoc_change_state: change assoc_state from JOIN_START to SENT_AUTH_1
Dec 28 22:40:01.550185 +1000 000032.524711 Brcm4360<D>[711] [0x7cdb2a37c3d36e49][1][0] backtrace[wlc_assoc_change_state]: 0x40df5 0xa7daf 0xa9220 0xb1de9 0xaa478 0x4013b 0x7cdb2a37b23edf1c 0x7cdb2a37b1e435c3 0x7cdb2a37b1efd400
Dec 28 22:40:01.552221 +1000 000032.526747 Brcm4360<D>[712] [0x7cdb2a37c4779c09][1][0] MacAuthEvent en0
Dec 28 22:40:01.552222 +1000 000032.526748 Brcm4360<D>[713] [0x7cdb2a37c4779c09][1][0] Auth result for: e8:fc:af:f2:04:a0
Dec 28 22:40:01.552223 +1000 000032.526749 Brcm4360<D>[714] [0x7cdb2a37c4779c09][1][0] Auth timed out
Dec 28 22:40:01.552225 +1000 000032.526751 Brcm4360<D>[715] [0x7cdb2a37c4779c09][1][0] Log system state... : AuthFail:sts:2_rsn:0
Dec 28 22:40:01.552228 +1000 000032.526754 Brcm4360<D>[716] [0x7cdb2a37c4779c09][1][0] wl0: Sep 25 2016 22:49:49 version 7.21.95.175 (r622517)(P2P)
Last edited: