git: a2764047702d - stable/13 - net80211: improve logging about state transitions lost

The branch stable/13 has been updated by bz:

URL: https://cgit.FreeBSD.org/src/commit/?id=a2764047702db519aca9e1b3cf6b475e5a723c65

commit a2764047702db519aca9e1b3cf6b475e5a723c65
Author:     Bjoern A. Zeeb <bz@FreeBSD.org>
AuthorDate: 2023-11-12 23:51:14 +0000
Commit:     Bjoern A. Zeeb <bz@FreeBSD.org>
CommitDate: 2024-02-19 08:02:00 +0000

    net80211: improve logging about state transitions lost
    
    It is possible that we call ieee80211_new_state_locked() again before
    a previous task finished to completion (not run yet or unlocked in
    between) since 5efea30f039c4 (and follow-up).
    In either case we would overwrite the new state and argument in the vap.
    
    While most drivers somehow deal with that (or not), LinuxKPI 802.11 compat
    code has KASSERTs to keep net80211, LinuxKPI and driver/firmware state in
    sync and they may trigger due to a missing transition or more likely a
    changed ni/lsta.
    
    Enhance the wlandebug +state logging for these cases so they
    are easier to debug.
    
    While here remove the unconditional logging to the message buffer;
    it has been here for a good decade but not helped to actually identify
    and sort the problem.
    
    Sponsored by:   The FreeBSD Foundation
    Reviewed by:    cc
    Differential Revision: https://reviews.freebsd.org/D42560
    
    (cherry picked from commit 72bb33a36b62fa30f69f01d3f6ae372be2c95b59)
---
 sys/net80211/ieee80211_proto.c | 32 ++++++++++++++++++++------------
 1 file changed, 20 insertions(+), 12 deletions(-)

diff --git a/sys/net80211/ieee80211_proto.c b/sys/net80211/ieee80211_proto.c
index f6d144169c48..cf467c08462c 100644
--- a/sys/net80211/ieee80211_proto.c
+++ b/sys/net80211/ieee80211_proto.c
@@ -2510,6 +2510,13 @@ ieee80211_newstate_cb(void *xvap, int npending)
 	nstate = vap->iv_nstate;
 	arg = vap->iv_nstate_arg;
 
+	IEEE80211_DPRINTF(vap, IEEE80211_MSG_STATE,
+	    "%s:%d: running state update %s -> %s (%d)\n",
+	    __func__, __LINE__,
+	    ieee80211_state_name[vap->iv_state],
+	    ieee80211_state_name[vap->iv_nstate],
+	    npending);
+
 	if (vap->iv_flags_ext & IEEE80211_FEXT_REINIT) {
 		/*
 		 * We have been requested to drop back to the INIT before
@@ -2677,29 +2684,30 @@ ieee80211_new_state_locked(struct ieee80211vap *vap,
 			 * until this is completed.
 			 */
 			IEEE80211_DPRINTF(vap, IEEE80211_MSG_STATE,
-			    "%s: %s -> %s (%s) transition discarded\n",
-			    __func__,
+			    "%s:%d: %s -> %s (%s) transition discarded\n",
+			    __func__, __LINE__,
 			    ieee80211_state_name[vap->iv_state],
 			    ieee80211_state_name[nstate],
 			    ieee80211_state_name[vap->iv_nstate]);
 			return -1;
 		} else if (vap->iv_state != vap->iv_nstate) {
-#if 0
 			/* Warn if the previous state hasn't completed. */
 			IEEE80211_DPRINTF(vap, IEEE80211_MSG_STATE,
-			    "%s: pending %s -> %s transition lost\n", __func__,
+			    "%s:%d: pending %s -> %s (now to %s) transition lost\n",
+			    __func__, __LINE__,
 			    ieee80211_state_name[vap->iv_state],
-			    ieee80211_state_name[vap->iv_nstate]);
-#else
-			/* XXX temporarily enable to identify issues */
-			if_printf(vap->iv_ifp,
-			    "%s: pending %s -> %s transition lost\n",
-			    __func__, ieee80211_state_name[vap->iv_state],
-			    ieee80211_state_name[vap->iv_nstate]);
-#endif
+			    ieee80211_state_name[vap->iv_nstate],
+			    ieee80211_state_name[nstate]);
 		}
 	}
 
+	IEEE80211_DPRINTF(vap, IEEE80211_MSG_STATE,
+	    "%s:%d: starting state update %s -> %s (%s)\n",
+	    __func__, __LINE__,
+	    ieee80211_state_name[vap->iv_state],
+	    ieee80211_state_name[vap->iv_nstate],
+	    ieee80211_state_name[nstate]);
+
 	nrunning = nscanning = 0;
 	/* XXX can track this state instead of calculating */
 	TAILQ_FOREACH(vp, &ic->ic_vaps, iv_next) {