* [PATCH 1/2] netdev: Add logging for CQM messages @ 2022-08-01 10:06 Michael Johnson 2022-08-01 10:06 ` [PATCH 2/2] station: Log scan results during a roam Michael Johnson 2022-08-01 15:17 ` [PATCH 1/2] netdev: Add logging for CQM messages Denis Kenzior 0 siblings, 2 replies; 7+ messages in thread From: Michael Johnson @ 2022-08-01 10:06 UTC (permalink / raw) To: iwd; +Cc: Michael Johnson Add extra logging around CQM events to help track wifi status. The signal strength logging matches wpa_supplicant's which looks like this: CTRL-EVENT-SIGNAL-CHANGE above=1 signal=-60 noise=-96 txrate=6000 --- src/netdev.c | 22 ++++++++++++++++++++-- 1 file changed, 20 insertions(+), 2 deletions(-) diff --git a/src/netdev.c b/src/netdev.c index 5a6a7b70..f9acd639 100644 --- a/src/netdev.c +++ b/src/netdev.c @@ -1092,12 +1092,26 @@ static void netdev_cqm_event(struct l_genl_msg *msg, struct netdev *netdev) rssi_event = (uint32_t *) data; break; + case NL80211_ATTR_CQM_PKT_LOSS_EVENT: + if (len != 4) + continue; + + l_warn("Packets lost event: %d", + *(uint32_t *) data); + break; + + case NL80211_ATTR_CQM_BEACON_LOSS_EVENT: + l_warn("Beacon lost event"); + break; + case NL80211_ATTR_CQM_RSSI_LEVEL: if (len != 4) continue; rssi_val = (int32_t *) data; break; + default: + l_debug("Unknown CQM event: %d", type); } } @@ -1106,10 +1120,14 @@ static void netdev_cqm_event(struct l_genl_msg *msg, struct netdev *netdev) } if (rssi_event) { - if (rssi_val) + if (rssi_val) { + l_info("Signal change event (above=%d signal=%d)", + *rssi_event, *rssi_val); netdev_cqm_event_rssi_value(netdev, *rssi_val); - else + } else { + l_info("Signal change event (above=%d)", *rssi_event); netdev_cqm_event_rssi_threshold(netdev, *rssi_event); + } } } -- 2.25.1 ^ permalink raw reply related [flat|nested] 7+ messages in thread
* [PATCH 2/2] station: Log scan results during a roam 2022-08-01 10:06 [PATCH 1/2] netdev: Add logging for CQM messages Michael Johnson @ 2022-08-01 10:06 ` Michael Johnson 2022-08-01 15:17 ` [PATCH 1/2] netdev: Add logging for CQM messages Denis Kenzior 1 sibling, 0 replies; 7+ messages in thread From: Michael Johnson @ 2022-08-01 10:06 UTC (permalink / raw) To: iwd; +Cc: Michael Johnson Provides useful information on why a roam might have failed, such as failing to find the BSS or the BSS being ranked lower, and why that might be. The output format is the same as station_add_seen_bss for consistency. --- src/station.c | 13 ++++++++++++- 1 file changed, 12 insertions(+), 1 deletion(-) diff --git a/src/station.c b/src/station.c index 02f21c76..e39e9d4b 100644 --- a/src/station.c +++ b/src/station.c @@ -2286,6 +2286,7 @@ static bool station_roam_scan_notify(int err, struct l_queue *bss_list, struct station *station = userdata; struct network *network = station->connected_network; struct handshake_state *hs = netdev_get_handshake(station->netdev); + struct scan_bss *current_bss = station->connected_bss; struct scan_bss *bss; struct scan_bss *best_bss = NULL; double best_bss_rank = 0.0; @@ -2317,9 +2318,20 @@ static bool station_roam_scan_notify(int err, struct l_queue *bss_list, * for BSSes that are within the FT Mobility Domain so as to favor * Fast Roaming, if it is supported. */ + l_debug("Current BSS '%s' with SSID: %s", + util_address_to_string(current_bss->addr), + util_ssid_to_utf8(current_bss->ssid_len, current_bss->ssid)); while ((bss = l_queue_pop_head(bss_list))) { double rank; + uint32_t kbps100 = DIV_ROUND_CLOSEST(bss->data_rate, 100000); + + l_debug("Processing BSS '%s' with SSID: %s, freq: %u, rank: %u," + " strength: %i, data_rate: %u.%u", + util_address_to_string(bss->addr), + util_ssid_to_utf8(bss->ssid_len, bss->ssid), + bss->frequency, bss->rank, bss->signal_strength, + kbps100 / 10, kbps100 % 10); /* Skip the BSS we are connected to if doing an AP roam */ if (station->ap_directed_roaming && !memcmp(bss->addr, @@ -2327,7 +2339,6 @@ static bool station_roam_scan_notify(int err, struct l_queue *bss_list, goto next; /* Skip result if it is not part of the ESS */ - if (bss->ssid_len != hs->ssid_len || memcmp(bss->ssid, hs->ssid, hs->ssid_len)) goto next; -- 2.25.1 ^ permalink raw reply related [flat|nested] 7+ messages in thread
* Re: [PATCH 1/2] netdev: Add logging for CQM messages 2022-08-01 10:06 [PATCH 1/2] netdev: Add logging for CQM messages Michael Johnson 2022-08-01 10:06 ` [PATCH 2/2] station: Log scan results during a roam Michael Johnson @ 2022-08-01 15:17 ` Denis Kenzior 2022-08-01 16:18 ` Michael Johnson 1 sibling, 1 reply; 7+ messages in thread From: Denis Kenzior @ 2022-08-01 15:17 UTC (permalink / raw) To: Michael Johnson, iwd Hi Michael, On 8/1/22 05:06, Michael Johnson wrote: > Add extra logging around CQM events to help track wifi status. > > The signal strength logging matches wpa_supplicant's which looks like > this: > > CTRL-EVENT-SIGNAL-CHANGE above=1 signal=-60 noise=-96 txrate=6000 > --- > src/netdev.c | 22 ++++++++++++++++++++-- > 1 file changed, 20 insertions(+), 2 deletions(-) > <snip> > @@ -1106,10 +1120,14 @@ static void netdev_cqm_event(struct l_genl_msg *msg, struct netdev *netdev) > } > > if (rssi_event) { > - if (rssi_val) > + if (rssi_val) { > + l_info("Signal change event (above=%d signal=%d)", I'm not sure 'above=%d' is going to work. rssi_event is only set on THRESHOLD_EVENT_LOW/THRESHOLD_EVENT_HIGH. If RSSI_LEVEL is being reported, that pointer is still NULL. > + *rssi_event, *rssi_val); > netdev_cqm_event_rssi_value(netdev, *rssi_val); Hmm, I don't think wpa_s uses RSSI_LEVEL stuff in the kernel, does it? The reason I ask is that we do have UIs that setup RSSI level reporting for displaying connection link quality (in number of bars for example). Since such events are quite common, I think you're going to get quite a bit of spam in the logs. Are you only interested in cases where the roaming threshold is reached? If so, you may need to modify netdev_cqm_event_rssi_value() instead. > - else > + } else { > + l_info("Signal change event (above=%d)", *rssi_event); > netdev_cqm_event_rssi_threshold(netdev, *rssi_event); > + } > } > } > Patch 2 looks fine btw, so I applied that one. Regards, -Denis ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [PATCH 1/2] netdev: Add logging for CQM messages 2022-08-01 15:17 ` [PATCH 1/2] netdev: Add logging for CQM messages Denis Kenzior @ 2022-08-01 16:18 ` Michael Johnson 2022-08-01 17:14 ` Denis Kenzior 0 siblings, 1 reply; 7+ messages in thread From: Michael Johnson @ 2022-08-01 16:18 UTC (permalink / raw) To: Denis Kenzior; +Cc: iwd Hi Denis, On Mon, 1 Aug 2022 at 16:27, Denis Kenzior <denkenz@gmail.com> wrote: > > @@ -1106,10 +1120,14 @@ static void netdev_cqm_event(struct l_genl_msg *msg, struct netdev *netdev) > > } > > > > if (rssi_event) { > > - if (rssi_val) > > + if (rssi_val) { > > + l_info("Signal change event (above=%d signal=%d)", > > I'm not sure 'above=%d' is going to work. rssi_event is only set on > THRESHOLD_EVENT_LOW/THRESHOLD_EVENT_HIGH. If RSSI_LEVEL is being reported, that > pointer is still NULL. Should the top level `if (rssi_event) {` not cover that case? I believe it checks both pointers before the info statement. I didn't add any output in the case of an RSSI_LEVEL but no THRESHOLD_EVENT_* as I haven't seen this actually occurring so assumed iwd didn't set up non-threshold events? > > > + *rssi_event, *rssi_val); > > netdev_cqm_event_rssi_value(netdev, *rssi_val); > > Hmm, I don't think wpa_s uses RSSI_LEVEL stuff in the kernel, does it? The > reason I ask is that we do have UIs that setup RSSI level reporting for > displaying connection link quality (in number of bars for example). Since such > events are quite common, I think you're going to get quite a bit of spam in the > logs. Are you only interested in cases where the roaming threshold is reached? > If so, you may need to modify netdev_cqm_event_rssi_value() instead. Sorry, I should have included more reasoning behind the change. In my use case the client is running headless and so the logs are really the only insight into why the network might have degraded to the point of causing issues. For example, if the client stops receiving data, it is useful to know what the rough signal level is that caused it as that might imply a dead zone or interference. All debugging is done remotely as well so we can't ever debug the network while it is currently in a bad state hence the log part. The useful data isn't just the threshold but the general signal level at the time of an incident. If all is working then we would have roamed before the signal gets bad enough to cause issues (it follows that we don't really care about _good_ signal values so maybe we could reduce spam there?) As for the general spamminess, does the UI RSSI reporting cause more events than running normally? I believe I was only seeing events when the signal had changed more than the hysteresis value in netdev_build_cmd_cqm_rssi_update (5 dBm). This doesn't seem too frequent (for me at least) when the client is mostly static. When it is moving it is generally useful information. For wpa_supplicant, I'm not sure the exact mechanism it uses but it does report almost identical output at a fairly high frequency if the client is moving e.g. ``` May 08 08:56:04 p3-2019 wpa_supplicant[842]: wlp2s0: CTRL-EVENT-SIGNAL-CHANGE above=1 signal=-62 noise=-93 txrate=6000 May 08 08:56:14 p3-2019 wpa_supplicant[842]: wlp2s0: CTRL-EVENT-SIGNAL-CHANGE above=0 signal=-76 noise=-93 txrate=6000 May 08 08:56:27 p3-2019 wpa_supplicant[842]: wlp2s0: CTRL-EVENT-SIGNAL-CHANGE above=0 signal=-79 noise=-94 txrate=6000 ``` Finally, the reason I made this `info` level was in the hope that I could remove the `-d` flag from iwd which does produce a lot of spam in the logs. This isn't really feasible at the moment as there isn't enough `info` logging to track down any issues that might occur on production systems where changes are harder to make. If the `info` level becomes to verbose, maybe iwd could set the default logging level to `warn` to reduce spam? > > > - else > > + } else { > > + l_info("Signal change event (above=%d)", *rssi_event); > > netdev_cqm_event_rssi_threshold(netdev, *rssi_event); > > + } > > } > > } > > > > Patch 2 looks fine btw, so I applied that one. > > Regards, > -Denis Regards, Michael ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [PATCH 1/2] netdev: Add logging for CQM messages 2022-08-01 16:18 ` Michael Johnson @ 2022-08-01 17:14 ` Denis Kenzior 2022-08-01 18:09 ` Michael Johnson 0 siblings, 1 reply; 7+ messages in thread From: Denis Kenzior @ 2022-08-01 17:14 UTC (permalink / raw) To: Michael Johnson; +Cc: iwd Hi Michael, >> I'm not sure 'above=%d' is going to work. rssi_event is only set on >> THRESHOLD_EVENT_LOW/THRESHOLD_EVENT_HIGH. If RSSI_LEVEL is being reported, that >> pointer is still NULL. > > Should the top level `if (rssi_event) {` not cover that case? I > believe it checks both > pointers before the info statement. I didn't add any output in the case of an > RSSI_LEVEL but no THRESHOLD_EVENT_* as I haven't seen this actually occurring > so assumed iwd didn't set up non-threshold events? Ah you're right. I guess the kernel does send the threshold event attribute as well. I'm really not sure why actually? This seems useless since it depends on knowing the currently used high/low thresholds, and only the kernel knows those. >> >>> + *rssi_event, *rssi_val); >>> netdev_cqm_event_rssi_value(netdev, *rssi_val); >> >> Hmm, I don't think wpa_s uses RSSI_LEVEL stuff in the kernel, does it? The >> reason I ask is that we do have UIs that setup RSSI level reporting for >> displaying connection link quality (in number of bars for example). Since such >> events are quite common, I think you're going to get quite a bit of spam in the >> logs. Are you only interested in cases where the roaming threshold is reached? >> If so, you may need to modify netdev_cqm_event_rssi_value() instead. > > Sorry, I should have included more reasoning behind the change. > > In my use case the client is running headless and so the logs are > really the only > insight into why the network might have degraded to the point of causing issues. > For example, if the client stops receiving data, it is useful to know > what the rough > signal level is that caused it as that might imply a dead zone or > interference. All > debugging is done remotely as well so we can't ever debug the network while > it is currently in a bad state hence the log part. I wonder if we should report this over D-Bus instead? I mean you can always setup your own SignalLevelAgent, or we could even add more reporting via StationDiagnostic interface? > > The useful data isn't just the threshold but the general signal level > at the time of > an incident. If all is working then we would have roamed before the signal gets > bad enough to cause issues (it follows that we don't really care about _good_ > signal values so maybe we could reduce spam there?) > > As for the general spamminess, does the UI RSSI reporting cause more events > than running normally? I believe I was only seeing events when the signal had > changed more than the hysteresis value in netdev_build_cmd_cqm_rssi_update > (5 dBm). This doesn't seem too frequent (for me at least) when the client is > mostly static. When it is moving it is generally useful information. It would. By default we program only the low signal threshold value. So you should only see signal changes around that value. If an rssi agent is used, then multiple thresholds are programmed, so you'd see rssi events even when the signal is very good. > > For wpa_supplicant, I'm not sure the exact mechanism it uses but it does report > almost identical output at a fairly high frequency if the client is moving e.g. > ``` > May 08 08:56:04 p3-2019 wpa_supplicant[842]: wlp2s0: > CTRL-EVENT-SIGNAL-CHANGE above=1 signal=-62 noise=-93 txrate=6000 > May 08 08:56:14 p3-2019 wpa_supplicant[842]: wlp2s0: > CTRL-EVENT-SIGNAL-CHANGE above=0 signal=-76 noise=-93 txrate=6000 > May 08 08:56:27 p3-2019 wpa_supplicant[842]: wlp2s0: > CTRL-EVENT-SIGNAL-CHANGE above=0 signal=-79 noise=-94 txrate=6000 > ``` > Right, but I think it sets a single CQM threshold, not multiple like we (might) do. Also, wpa_s is very spammy since it is really (only) meant for testing wifi implementations in a lab ;) > Finally, the reason I made this `info` level was in the hope that I could > remove the `-d` flag from iwd which does produce a lot of spam in the logs. > This isn't really feasible at the moment as there isn't enough `info` logging > to track down any issues that might occur on production systems where > changes are harder to make. If the `info` level becomes to verbose, maybe > iwd could set the default logging level to `warn` to reduce spam? You can use a glob match for the -d flag. Something like: #iwd -d '*Signal change event*' So you can make the rssi messages as 'debug', and have iwd only print those you want. Multiple globs are supported too, separate them by ':' or ','. Regards, -Denis ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [PATCH 1/2] netdev: Add logging for CQM messages 2022-08-01 17:14 ` Denis Kenzior @ 2022-08-01 18:09 ` Michael Johnson 2022-08-01 18:30 ` Denis Kenzior 0 siblings, 1 reply; 7+ messages in thread From: Michael Johnson @ 2022-08-01 18:09 UTC (permalink / raw) To: Denis Kenzior; +Cc: iwd Hi Denis, On Mon, 1 Aug 2022 at 18:24, Denis Kenzior <denkenz@gmail.com> wrote: > I wonder if we should report this over D-Bus instead? I mean you can always > setup your own SignalLevelAgent, or we could even add more reporting via > StationDiagnostic interface? I actually do record the signal level separately but it's stored in an annoying binary format so access is more painful :(. This was just to make things easier and reduce the jump from wpa_supplicant to iwd for anyone on plain ubuntu etc. I can understand why you don't want the spam though. > Right, but I think it sets a single CQM threshold, not multiple like we (might) > do. Also, wpa_s is very spammy since it is really (only) meant for testing wifi > implementations in a lab ;) haha fair. Of course, it's still the default on most linux systems ;). > > changes are harder to make. If the `info` level becomes to verbose, maybe > > iwd could set the default logging level to `warn` to reduce spam? > > You can use a glob match for the -d flag. Something like: > #iwd -d '*Signal change event*' > > So you can make the rssi messages as 'debug', and have iwd only print those you > want. Multiple globs are supported too, separate them by ':' or ','. That's a smart idea although as a user i feel like you only ever know what messages are important after the fact. > > Regards, > -Denis What would you like to do with the patch? I'm happy to drop it if its too spammy or we can lower the level to debug? Or make it only print when the threshold changes. Are you happy with the packet loss and beacon loss events or are they too much as well? Regards, Michael ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [PATCH 1/2] netdev: Add logging for CQM messages 2022-08-01 18:09 ` Michael Johnson @ 2022-08-01 18:30 ` Denis Kenzior 0 siblings, 0 replies; 7+ messages in thread From: Denis Kenzior @ 2022-08-01 18:30 UTC (permalink / raw) To: Michael Johnson; +Cc: iwd Hi Michael, On 8/1/22 13:09, Michael Johnson wrote: > Hi Denis, > > On Mon, 1 Aug 2022 at 18:24, Denis Kenzior <denkenz@gmail.com> wrote: >> I wonder if we should report this over D-Bus instead? I mean you can always >> setup your own SignalLevelAgent, or we could even add more reporting via >> StationDiagnostic interface? > > I actually do record the signal level separately but it's stored in an > annoying binary format so access is more painful :(. This was just to > make things easier and reduce the jump from wpa_supplicant to iwd for > anyone on plain ubuntu etc. I can understand why you don't want the > spam though. I don't mind the spam in debug mode, that's what it is for. But not sure they really belong at info/warn levels. I think we can consider putting in roaming related messages at the info level since that type of information might be generally useful. > >> Right, but I think it sets a single CQM threshold, not multiple like we (might) >> do. Also, wpa_s is very spammy since it is really (only) meant for testing wifi >> implementations in a lab ;) > > haha fair. Of course, it's still the default on most linux systems ;). > And we're working to change that. > > What would you like to do with the patch? I'm happy to drop it if its > too spammy or we can lower the level to debug? Or make it only print > when the threshold changes. I don't mind these at debug level, if you want to start with that. > Are you happy with the packet loss and beacon loss events or are they > too much as well? As I mentioned before, kernel will generally disconnect us as soon as the beacon loss event happens (depends on the STA capability if I recall correctly). Not sure how really useful this is, but since beacon loss goes via dmesg at 'info' level, I think it would be fine for iwd to do so as well. The packet loss one I'm not sure. Certaintly not 'warn'. I think I'd start with 'debug' since this event isn't being reacted to (yet). Regards, -Denis ^ permalink raw reply [flat|nested] 7+ messages in thread
end of thread, other threads:[~2022-08-01 18:40 UTC | newest] Thread overview: 7+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2022-08-01 10:06 [PATCH 1/2] netdev: Add logging for CQM messages Michael Johnson 2022-08-01 10:06 ` [PATCH 2/2] station: Log scan results during a roam Michael Johnson 2022-08-01 15:17 ` [PATCH 1/2] netdev: Add logging for CQM messages Denis Kenzior 2022-08-01 16:18 ` Michael Johnson 2022-08-01 17:14 ` Denis Kenzior 2022-08-01 18:09 ` Michael Johnson 2022-08-01 18:30 ` Denis Kenzior
This is an external index of several public inboxes, see mirroring instructions on how to clone and mirror all data and code used by this external index.