From e372282241316209b44ee6a7c40b9b465744fc0d Mon Sep 17 00:00:00 2001 From: Johannes Berg Date: Sat, 16 Feb 2013 00:11:34 +0100 Subject: [PATCH] iwlwifi: mvm: fix time event command handling race Occasionally, we would run into this warning: iwlwifi 0000:02:00.0: U iwl_mvm_protect_session extend 0x2601: only 200 ms left iwlwifi 0000:02:00.0: U iwl_mvm_remove_time_event Removing TE 0x2601 iwlwifi 0000:02:00.0: I iwl_pcie_enqueue_hcmd Sending command TIME_EVENT_CMD (#29), seq: 0x0925, 60 bytes at 37[5]:9 iwlwifi 0000:02:00.0: U iwl_pcie_send_hcmd_sync Attempting to send sync command TIME_EVENT_CMD iwlwifi 0000:02:00.0: U iwl_pcie_send_hcmd_sync Setting HCMD_ACTIVE for command TIME_EVENT_CMD iwlwifi 0000:02:00.0: I iwl_pcie_enqueue_hcmd Sending command TIME_EVENT_CMD (#29), seq: 0x0926, 60 bytes at 38[6]:9 iwlwifi 0000:02:00.0: U iwl_mvm_time_event_response TIME_EVENT_CMD response - UID = 0x2601 iwlwifi 0000:02:00.0: I iwl_pcie_hcmd_complete Clearing HCMD_ACTIVE for command TIME_EVENT_CMD iwlwifi 0000:02:00.0: U iwl_mvm_rx_time_event_notif Time event notification - UID = 0x2701 action 1 wlan0: associate with 00:0a:b8:55:a8:30 (try 2/3) ------------[ cut here ]------------ WARNING: at drivers/net/wireless/iwlwifi/mvm/time-event.c:269 iwl_mvm_time_event_send_add+0x163/0x1a0 [iwlmvm]() Modules linked in: [...] Call Trace: [] warn_slowpath_common+0x72/0xa0 [] warn_slowpath_null+0x22/0x30 [] iwl_mvm_time_event_send_add+0x163/0x1a0 [iwlmvm] [] iwl_mvm_protect_session+0xcd/0x1c0 [iwlmvm] [] iwl_mvm_mac_mgd_prepare_tx+0x67/0xa0 [iwlmvm] [] ieee80211_sta_work+0x8f0/0x1070 [mac80211] The reason is a problem with asynchronous vs. synchronous commands, what happens here is the following: * TE 0x2601 is removed, the TIME_EVENT_CMD for that is async * a new TE (will be 0x2701) is created, the TIME_EVENT_CMD for that is sync and also uses a notification wait for the response (to avoid another race condition) * the response for the TE 0x2601 removal comes from the firmware, and is handled by the notification wait handler that's really waiting for the second response, but can't tell the difference, we therefore see the message "TIME_EVENT_CMD response - UID = 0x2601" instead of "TIME_EVENT_CMD response - UID = 0x2701". Fix this issue by making the TE removal synchronous as well, this means that we wait for the response to that command first, before there's any chance of sending a new one. Also, to detect such issues more easily in the future, add a warning to the notification handler that detects them. Reviewed-by: Emmanuel Grumbach Signed-off-by: Johannes Berg --- drivers/net/wireless/iwlwifi/mvm/time-event.c | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/drivers/net/wireless/iwlwifi/mvm/time-event.c b/drivers/net/wireless/iwlwifi/mvm/time-event.c index e025b5896203..e437e02c7149 100644 --- a/drivers/net/wireless/iwlwifi/mvm/time-event.c +++ b/drivers/net/wireless/iwlwifi/mvm/time-event.c @@ -248,6 +248,11 @@ static bool iwl_mvm_time_event_response(struct iwl_notif_wait_data *notif_wait, } resp = (void *)pkt->data; + + /* we should never get a response to another TIME_EVENT_CMD here */ + if (WARN_ON_ONCE(le32_to_cpu(resp->id) != te_data->id)) + return false; + te_data->uid = le32_to_cpu(resp->unique_id); IWL_DEBUG_TE(mvm, "TIME_EVENT_CMD response - UID = 0x%x\n", te_data->uid); @@ -416,7 +421,7 @@ void iwl_mvm_remove_time_event(struct iwl_mvm *mvm, cpu_to_le32(FW_CMD_ID_AND_COLOR(mvmvif->id, mvmvif->color)); IWL_DEBUG_TE(mvm, "Removing TE 0x%x\n", le32_to_cpu(time_cmd.id)); - ret = iwl_mvm_send_cmd_pdu(mvm, TIME_EVENT_CMD, CMD_ASYNC, + ret = iwl_mvm_send_cmd_pdu(mvm, TIME_EVENT_CMD, CMD_SYNC, sizeof(time_cmd), &time_cmd); if (WARN_ON(ret)) return; -- 2.39.5