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:
   [<c1046e42>] warn_slowpath_common+0x72/0xa0
   [<c1046e92>] warn_slowpath_null+0x22/0x30
   [<f8cad913>] iwl_mvm_time_event_send_add+0x163/0x1a0 [iwlmvm]
   [<f8cadead>] iwl_mvm_protect_session+0xcd/0x1c0 [iwlmvm]
   [<f8ca2087>] iwl_mvm_mac_mgd_prepare_tx+0x67/0xa0 [iwlmvm]
   [<f882a130>] 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 <emmanuel.grumbach@intel.com>
Signed-off-by: Johannes Berg <johannes.berg@intel.com>

diff --git a/drivers/net/wireless/iwlwifi/mvm/time-event.c b/drivers/net/wireless/iwlwifi/mvm/time-event.c
index e025b589620345f5ea53057cf7532b73d23b93e5..e437e02c714963dc050a0701df1e9183bb1983ee 100644 (file)
--- 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;