WiFi关联拒绝log分析以及代码流程 ASSOC_REJECT

2020-07-15 11:34:40 浏览数 (2)

最近遇到一个问题,连接WiFi时,密码正确,显示saved,但是一直连接不上,分析log发现问题出在关联的时候,关联被拒绝了。 下面根据log看一下流程:

Log:

代码语言:javascript复制
04-20 16:07:59.571  1958  1958 D wpa_supplicant: nl80211: Drv Event 46 (NL80211_CMD_CONNECT) received for wlan0

04-20 16:07:59.571  1958  1958 D wpa_supplicant: nl80211: Connect event (status=1 ignore_next_local_disconnect=0)

04-20 16:07:59.571  1958  1958 D wpa_supplicant: wlan0: Event ASSOC_REJECT (12) received

04-20 16:07:59.571  1958  1958 I wpa_supplicant: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:1d:7e:59:71:0c status_code=1

04-20 16:07:59.571  1958  1958 D wpa_supplicant: Notifying assoc reject to hidl control: 1

04-20 16:07:59.571  1958  1958 D wpa_supplicant: wlan0: Radio work 'connect'@0x760802e300 done in 2.668643 seconds

04-20 16:07:59.571  1958  1958 D wpa_supplicant: wlan0: radio_work_free('connect'@0x760802e300): num_active_works --> 0

04-20 16:07:59.571  1958  1958 D wpa_supplicant: Added BSSID 00:1d:7e:59:71:0c into blacklist

04-20 16:07:59.571  1958  1958 D wpa_supplicant: wlan0: Blacklist count 3 --> request scan in 1000 ms

04-20 16:07:59.571  1958  1958 D wpa_supplicant: wlan0: Setting scan request: 1.000000 sec

04-20 16:07:59.571  1958  1958 D wpa_supplicant: nl80211: Data frame filter flags=0x0

04-20 16:07:59.571  1958  1958 E wpa_supplicant: nl80211: Failed to open /proc/sys/net/ipv4/conf/wlan0/drop_unicast_in_l2_multicast: No such file or directory

04-20 16:07:59.571  1958  1958 E wpa_supplicant: nl80211: Failed to set IPv4 unicast in multicast filter

04-20 16:07:59.571  1958  1958 D wpa_supplicant: wlan0: State: ASSOCIATING -> DISCONNECTED

04-20 16:07:59.571  1958  1958 D wpa_supplicant: nl80211: Set wlan0 operstate 0->0 (DORMANT)

04-20 16:07:59.571  1958  1958 D wpa_supplicant: netlink: Operstate: ifindex=9 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)

04-20 16:07:59.572   712   712 I ConfigStore: android::hardware::configstore::V1_0::ISurfaceFlingerConfigs::hasHDRDisplay retrieved: 0

04-20 16:07:59.572  1958  1958 D wpa_supplicant: Notifying state change event to hidl control: 0

04-20 16:07:59.572  1958  1958 D wpa_supplicant: EAPOL: External notification - portEnabled=0

04-20 16:07:59.572  1958  1958 D wpa_supplicant: EAPOL: External notification - portValid=0

04-20 16:07:59.572  1958  1958 D wpa_supplicant: EAPOL: External notification - EAP success=0

04-20 16:07:59.572  1958  1958 E wpa_supplicant: eap_proxy: eap_proxy_notify_config

04-20 16:07:59.572   712   712 I ConfigStore: android::hardware::configstore::V1_0::ISurfaceFlingerConfigs::hasHDRDisplay retrieved: 0

04-20 16:07:59.572  1334  9020 D SupplicantStaIfaceHal: ISupplicantStaIfaceCallback.onAssociationRejected received

04-20 16:07:59.572  1334  2052 D SupplicantStaIfaceHal: ISupplicantStaIfaceCallback.onVendorStateChanged received

04-20 16:07:59.572  1334  2052 D SupplicantStaIfaceHal: ISupplicantStaIfaceCallback.updateStateIsFourway received

04-20 16:07:59.572  1334  1750 D WifiStateMachine:  DisconnectedState !ASSOCIATION_REJECTION_EVENT rt=340168/340168  timedOut=0 1 00:1d:7e:59:71:0c blacklist=false

04-20 16:07:59.572  1334  1750 D WifiStateMachine:  ConnectModeState !ASSOCIATION_REJECTION_EVENT rt=340168/340168  timedOut=0 1 00:1d:7e:59:71:0c blacklist=false

04-20 16:07:59.572  1334  1750 W WifiDiags: CaptureBugReport 1

04-20 16:07:59.600  1334  1334 W WifiStateMachin: type=1400 audit(0.0:649): avc: denied { syslog_read } for scontext=u:r:system_server:s0 tcontext=u:r:kernel:s0 tclass=system permissive=0

04-20 16:07:59.605  1334  1750 D wifi-jni: no kernel logs

04-20 16:07:59.606  1334  1750 D WifiStateMachine: Assocation Rejection event: bssid=00:1d:7e:59:71:0c reason code=1 timedOut=false

04-20 16:07:59.606  1066  1066 I /system/bin/tombstoned: found intercept fd 512 for pid 3087 and type kDebuggerdJavaBacktrace

04-20 16:07:59.607  1334  1750 D WifiConnectivityManager: trackBssid: disable 00:1d:7e:59:71:0c reason code 1

04-20 16:07:59.607  3087  3099 I e.process.gapp: Wrote stack traces to '[tombstoned]'

04-20 16:07:59.607  1334  1750 V WifiConfigManager: Disable counter for network FWDVT-WPA2 for reason NETWORK_SELECTION_DISABLED_ASSOCIATION_REJECTION  is 1 and threshold is 5

04-20 16:07:59.607  9091  9091 I /system/bin/dumpstate: libdebuggerd_client: done dumping process 3087

04-20 16:07:59.607  9091  9091 I /system/bin/dumpstate: libdebuggerd_client: started dumping process 3271

04-20 16:07:59.608  1066  1066 I /system/bin/tombstoned: registered intercept for pid 3271 and type kDebuggerdJavaBacktrace

04-20 16:07:59.608  3271  3279 I d.process.acor: Thread[3,tid=3279,WaitingInMainSignalCatcherLoop,Thread*=0x70b0416400,peer=0x12e40220,"Signal Catcher"]: reacting to signal 3

04-20 16:07:59.608  1334  1750 V WifiLastResortWatchdog: noteConnectionFailureAndTriggerIfNeeded: ["FWDVT-WPA2", 00:1d:7e:59:71:0c, 1]

04-20 16:07:59.608  1334  1750 V WifiLastResortWatchdog: updateFailureCountForNetwork: ["FWDVT-WPA2", 00:1d:7e:59:71:0c, 1]

04-20 16:07:59.608  3271  3279 I d.process.acor: 

04-20 16:07:59.608  1334  1750 V WifiLastResortWatchdog: checkTriggerCondition.

04-20 16:07:59.608  1334  1750 V WifiLastResortWatchdog: isRestartNeeded = false

04-20 16:07:59.608  1334  1750 D WifiStateMachine:  DisconnectedState !SUPPLICANT_STATE_CHANGE_EVENT rt=340204/340204 0 0 SSID: FWDVT-WPA2 BSSID: 00:1d:7e:59:71:0c nid: 3 state: DISCONNECTED

04-20 16:07:59.608  1334  1750 D WifiStateMachine: SUPPLICANT_STATE_CHANGE_EVENT state=DISCONNECTED -> state= DISCONNECTED

04-20 16:07:59.608  1334  1750 D WifiStateMachine: setDetailed state, old =CONNECTING and new state=DISCONNECTED hidden=false

04-20 16:07:59.609  1334  1750 D WifiStateMachine:  ConnectModeState !SUPPLICANT_STATE_CHANGE_EVENT rt=340204/340204 0 0 SSID: FWDVT-WPA2 BSSID: 00:1d:7e:59:71:0c nid: 3 state: DISCONNECTED

04-20 16:07:59.609  1334  1750 D SupplicantStateTracker: HandshakeState{ when=-2ms what=147499 target=com.android.internal.util.StateMachine$SmHandler }

04-20 16:07:59.609  1334  1750 D SupplicantStateTracker: DefaultState{ when=-3ms what=147499 target=com.android.internal.util.StateMachine$SmHandler }

04-20 16:07:59.609  1334  1750 E SupplicantStateTracker: Ignoring { when=-3ms what=147499 target=com.android.internal.util.StateMachine$SmHandler }

04-20 16:07:59.609  1334  1750 D SupplicantStateTracker: HandshakeState{ when=-1ms what=147462 obj= SSID: FWDVT-WPA2 BSSID: 00:1d:7e:59:71:0c nid: 3 state: DISCONNECTED target=com.android.internal.util.StateMachine$SmHandler }

04-20 16:07:59.609  1334  1750 D SupplicantStateTracker: DefaultState{ when=-1ms what=147462 obj= SSID: FWDVT-WPA2 BSSID: 00:1d:7e:59:71:0c nid: 3 state: DISCONNECTED target=com.android.internal.util.StateMachine$SmHandler }

WiFi连接时关联被拒绝,会被加入黑名单。

代码流程:

/external/wpa_supplicant_8/wpa_supplicant/events.c

代码语言:javascript复制
void wpa_supplicant_event(void *ctx, enum wpa_event_type event,
			  union wpa_event_data *data)
{
	struct wpa_supplicant *wpa_s = ctx;
	int resched;
#endif /* CONFIG_IBSS_RSN */
	case EVENT_ASSOC_REJECT:
		if (data->assoc_reject.bssid)
			wpa_msg(wpa_s, MSG_INFO, WPA_EVENT_ASSOC_REJECT
				"bssid=" MACSTR	" status_code=%u%s%s%s",
				MAC2STR(data->assoc_reject.bssid),
				data->assoc_reject.status_code,
				data->assoc_reject.timed_out ? " timeout" : "",
				data->assoc_reject.timeout_reason ? "=" : "",
				data->assoc_reject.timeout_reason ?
				data->assoc_reject.timeout_reason : "");
		else
			wpa_msg(wpa_s, MSG_INFO, WPA_EVENT_ASSOC_REJECT
				"status_code=%u%s%s%s",
				data->assoc_reject.status_code,
				data->assoc_reject.timed_out ? " timeout" : "",
				data->assoc_reject.timeout_reason ? "=" : "",
				data->assoc_reject.timeout_reason ?
				data->assoc_reject.timeout_reason : "");
		wpa_s->assoc_status_code = data->assoc_reject.status_code;
		wpa_s->assoc_timed_out = data->assoc_reject.timed_out;
		wpas_notify_assoc_status_code(wpa_s);
代码语言:javascript复制
int wpa_supplicant_connect(struct wpa_supplicant *wpa_s,
			   struct wpa_bss *selected,
			   struct wpa_ssid *ssid)
{
	wpa_msg(wpa_s, MSG_DEBUG,
		"Considering connect request: reassociate: %d  selected: "
		MACSTR "  bssid: " MACSTR "  pending: " MACSTR
		"  wpa_state: %s  ssid=%p  current_ssid=%p",
		wpa_s->reassociate, MAC2STR(selected->bssid),
		MAC2STR(wpa_s->bssid), MAC2STR(wpa_s->pending_bssid),
		wpa_supplicant_state_txt(wpa_s->wpa_state),
		ssid, wpa_s->current_ssid);

	if (wpa_s->reassociate ||
	    (os_memcmp(selected->bssid, wpa_s->bssid, ETH_ALEN) != 0 &&
	     ((wpa_s->wpa_state != WPA_ASSOCIATING &&
	       wpa_s->wpa_state != WPA_AUTHENTICATING) ||
	      (!is_zero_ether_addr(wpa_s->pending_bssid) &&
	       os_memcmp(selected->bssid, wpa_s->pending_bssid, ETH_ALEN) !=
	       0) ||
	      (is_zero_ether_addr(wpa_s->pending_bssid) &&
	       ssid != wpa_s->current_ssid)))) {
		if (wpa_supplicant_scard_init(wpa_s, ssid)) {
			wpa_supplicant_req_new_scan(wpa_s, 10, 0);
			return 0;
		}
		wpa_msg(wpa_s, MSG_DEBUG, "Request association with " MACSTR,
			MAC2STR(selected->bssid));
		wpa_supplicant_associate(wpa_s, selected, ssid);
	} else {
		wpa_dbg(wpa_s, MSG_DEBUG, "Already associated or trying to "
			"connect with the selected AP");
	}

	return 0;
}

void wpa_supplicant_associate(struct wpa_supplicant *wpa_s,

代码语言:javascript复制
struct wpa_bss *bss, struct wpa_ssid *ssid)
{
	struct wpa_connect_work *cwork;
	int rand_style;

	cwork->bss = bss;
	cwork->ssid = ssid;

	if (radio_add_work(wpa_s, bss ? bss->freq : 0, "connect", 1,
			   wpas_start_assoc_cb, cwork) < 0) {
		os_free(cwork);
	}
}
代码语言:javascript复制
static void wpas_start_assoc_cb(struct wpa_radio_work *work, int deinit)
	if (wpa_s->reassoc_same_ess && !is_zero_ether_addr(prev_bssid) &&
	    wpa_s->current_ssid)
		params.prev_bssid = prev_bssid;

	ret = wpa_drv_associate(wpa_s, &params);
	os_free(wpa_ie);
	if (ret < 0) {
		wpa_msg(wpa_s, MSG_INFO, "Association request to the driver "
			"failed");
		if (wpa_s->drv_flags & WPA_DRIVER_FLAGS_SANE_ERROR_CODES) {
			/*
			 * The driver is known to mean what is saying, so we
			 * can stop right here; the association will not
			 * succeed.
			 */
			wpas_connection_failed(wpa_s, wpa_s->pending_bssid);
			wpa_supplicant_set_state(wpa_s, WPA_DISCONNECTED);
			os_memset(wpa_s->pending_bssid, 0, ETH_ALEN);
			return;
		}
		/* try to continue anyway; new association will be tried again
		 * after timeout */
		assoc_failed = 1;
	}

	case EVENT_ASSOC_REJECT:
		if (data->assoc_reject.bssid)
			wpa_msg(wpa_s, MSG_INFO, WPA_EVENT_ASSOC_REJECT
				"bssid=" MACSTR	" status_code=%u%s%s%s",
				MAC2STR(data->assoc_reject.bssid),
				data->assoc_reject.status_code,
				data->assoc_reject.timed_out ? " timeout" : "",
				data->assoc_reject.timeout_reason ? "=" : "",
				data->assoc_reject.timeout_reason ?
				data->assoc_reject.timeout_reason : "");
		else
			wpa_msg(wpa_s, MSG_INFO, WPA_EVENT_ASSOC_REJECT
				"status_code=%u%s%s%s",
				data->assoc_reject.status_code,
				data->assoc_reject.timed_out ? " timeout" : "",
				data->assoc_reject.timeout_reason ? "=" : "",
				data->assoc_reject.timeout_reason ?
				data->assoc_reject.timeout_reason : "");
		wpa_s->assoc_status_code = data->assoc_reject.status_code;
		wpa_s->assoc_timed_out = data->assoc_reject.timed_out;
		wpas_notify_assoc_status_code(wpa_s);

/external/wpa_supplicant_8/wpa_supplicant/wpa_supplicant.c

代码语言:javascript复制
void wpas_connection_failed(struct wpa_supplicant *wpa_s, const u8 *bssid)
{
	int timeout;
	int count;
	int *freqs = NULL;

	wpas_connect_work_done(wpa_s);

	eloop_cancel_timeout(wpa_supplicant_timeout, wpa_s, NULL);
	if (wpa_s->own_disconnect_req) {
		wpa_s->own_disconnect_req = 0;
		wpa_dbg(wpa_s, MSG_DEBUG,
			"Ignore connection failure due to local request to disconnect");
		return;
	}
	if (wpa_s->disconnected) {
		wpa_dbg(wpa_s, MSG_DEBUG, "Ignore connection failure "
			"indication since interface has been put into "
			"disconnected state");
		return;
	}

	count = wpa_blacklist_add(wpa_s, bssid);
	if (count == 1 && wpa_s->current_bss) {
	
		freqs = get_bss_freqs_in_ess(wpa_s);
		if (freqs) {
			wpa_dbg(wpa_s, MSG_DEBUG, "Another BSS in this ESS "
				"has been seen; try it next");
			wpa_blacklist_add(wpa_s, bssid);
		
			os_free(wpa_s->next_scan_freqs);
			wpa_s->next_scan_freqs = freqs;
		}
	}

	count  = wpa_s->extra_blacklist_count;

	if (count > 3 && wpa_s->current_ssid) {
		wpa_printf(MSG_DEBUG, "Continuous association failures - "
			   "consider temporary network disabling");
		wpas_auth_failed(wpa_s, "CONN_FAILED");
	}

	switch (count) {
	case 1:
		timeout = 100;
		break;
	case 2:
		timeout = 500;
		break;
	case 3:
		timeout = 1000;
		break;
	case 4:
		timeout = 5000;
		break;
	default:
		timeout = 10000;
		break;
	}

	wpa_dbg(wpa_s, MSG_DEBUG, "Blacklist count %d --> request scan in %d "
		"ms", count, timeout);

	/*
	 * TODO: if more than one possible AP is available in scan results,
	 * could try the other ones before requesting a new scan.
	 */
	wpa_supplicant_req_scan(wpa_s, timeout / 1000,
				1000 * (timeout % 1000));
}

加入黑名单代码:

/external/wpa_supplicant_8/wpa_supplicant/blacklist.c

代码语言:javascript复制
int wpa_blacklist_add(struct wpa_supplicant *wpa_s, const u8 *bssid)
{
	struct wpa_blacklist *e;

	if (wpa_s == NULL || bssid == NULL)
		return -1;

	e = wpa_blacklist_get(wpa_s, bssid);
	if (e) {
		e->count  ;
		wpa_printf(MSG_DEBUG, "BSSID " MACSTR " blacklist count "
			   "incremented to %d",
			   MAC2STR(bssid), e->count);
		return e->count;
	}

	e = os_zalloc(sizeof(*e));
	if (e == NULL)
		return -1;
	os_memcpy(e->bssid, bssid, ETH_ALEN);
	e->count = 1;
	e->next = wpa_s->blacklist;
	wpa_s->blacklist = e;
	wpa_printf(MSG_DEBUG, "Added BSSID " MACSTR " into blacklist",
		   MAC2STR(bssid));

	return e->count;
}

其中有一个数字计数器,它在每次尝试重新连接时递增。

代码语言:javascript复制
04-20 16:07:59.607  1334  1750 V WifiConfigManager: Disable counter for network FWDVT-WPA2 for reason NETWORK_SELECTION_DISABLED_ASSOCIATION_REJECTION  is 1 and threshold is 5

04-20 16:08:05.524  1334  1750 V WifiConfigManager: Disable counter for network FWDVT-WPA2 for reason NETWORK_SELECTION_DISABLED_ASSOCIATION_REJECTION  is 2 and threshold is 5

04-20 16:08:17.640  1334  1750 V WifiConfigManager: Disable counter for network FWDVT-WPA2 for reason NETWORK_SELECTION_DISABLED_ASSOCIATION_REJECTION  is 3 and threshold is 5

04-20 16:08:32.557  1334  1750 V WifiConfigManager: Disable counter for network FWDVT-WPA2 for reason NETWORK_SELECTION_DISABLED_ASSOCIATION_REJECTION  is 4 and threshold is 5

04-20 16:10:12.561  1334  1750 V WifiConfigManager: Disable counter for network FWDVT-WPA2 for reason NETWORK_SELECTION_DISABLED_ASSOCIATION_REJECTION  is 1 and threshold is 5

04-20 16:10:25.218  1334  1750 V WifiConfigManager: Disable counter for network FWDVT-WPA2 for reason NETWORK_SELECTION_DISABLED_ASSOCIATION_REJECTION  is 2 and threshold is 5

04-20 16:10:38.021  1334  1750 V WifiConfigManager: Disable counter for network FWDVT-WPA2 for reason NETWORK_SELECTION_DISABLED_ASSOCIATION_REJECTION  is 3 and threshold is 5

04-20 16:11:03.240  1334  1750 V WifiConfigManager: Disable counter for network FWDVT-WPA2 for reason NETWORK_SELECTION_DISABLED_ASSOCIATION_REJECTION  is 4 and threshold is 5

0 人点赞