iwlwifi: mvm: fix time event command handling race
authorJohannes Berg <johannes.berg@intel.com>
Fri, 15 Feb 2013 23:11:34 +0000 (00:11 +0100)
committerJohannes Berg <johannes.berg@intel.com>
Mon, 18 Feb 2013 19:18:07 +0000 (20:18 +0100)
commite372282241316209b44ee6a7c40b9b465744fc0d
treeb3ec4f94d3b9708dca4faba8f049980f818afbda
parent93630dc3ef897975a542bb52bbed3969e647276e
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>
drivers/net/wireless/iwlwifi/mvm/time-event.c