wifi: improve logging for roaming scenarios |
||||
Issue descriptionOS: R62/R63 We are having trouble with logs from the field that have 2.4<->5 GHz roaming or intra-BSS roaming, and the reasons for roaming aren't obvious. Bump up logging to understand these situations better.
,
Oct 7 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromiumos/third_party/hostap/+/e965d5a9d6ee4609f4604476dae6f3f3c7489eee commit e965d5a9d6ee4609f4604476dae6f3f3c7489eee Author: Kirtika Ruchandani <kirtika@chromium.org> Date: Sat Oct 07 11:54:29 2017 CHROMIUM: Bump up logging level for blacklist decisions Chrome OS relies on its connection manager, shill, to bump up the logging level in wpa_supplicant during 'interesting' times via its WiFi::SetConnectionDebugging method. The method sets wpa_supplicant debug level to 'info' (quieter) or 'debug' (verbose). It's not clear SetConnectionDebugging is being called on execution paths of interest - in particular, APs we are connected to at one instant show up as blacklisted in the scan after an unexpected disconnect, like so: (<> implies redacted/placeholder) wlan0: New scan results available (own=1 ext=0) wlan0: Radio work 'scan'@<> done in <> seconds wlan0: Selecting BSS from priority group <> // This SSID was one we were connected to before, and there was // no mention of blacklisting it in the log lines prior to this. wlan0: 0: <> ssid='<>' wpa_ie_len=0 rsn_ie_len=<> caps=<> level=<> freq=<> wps wlan0: skip - blacklisted (count=2 limit=0) wlan0: 1: <> ssid='<>' wpa_ie_len=0 rsn_ie_len=<> caps=<> level=<> freq=<> wps Ensure that we always print blacklist adding/clearing decisions - its only 3 lines anyways. BUG=chromium:771501 TEST=(TBD) Change-Id: I4ea4b01239dc95c4a1e4619f1d4ddb0c4b8eb63b Signed-off-by: Kirtika Ruchandani <kirtika@chromium.org> Reviewed-on: https://chromium-review.googlesource.com/699640 Reviewed-by: Ben Chan <benchan@chromium.org> Reviewed-by: Eric Caruso <ejcaruso@chromium.org> [modify] https://crrev.com/e965d5a9d6ee4609f4604476dae6f3f3c7489eee/wpa_supplicant/blacklist.c
,
Oct 7 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromiumos/third_party/hostap/+/402cb15bc9a824f3ffddeb1e2ba29716d6f51870 commit 402cb15bc9a824f3ffddeb1e2ba29716d6f51870 Author: Kirtika Ruchandani <kirtika@chromium.org> Date: Sat Oct 07 11:54:29 2017 CHROMIUM: Bump up logging level for roaming decisions Chrome OS relies on its connection manager, shill, to bump up the logging level in wpa_supplicant during 'interesting' times via its WiFi::SetConnectionDebugging method. The method sets wpa_supplicant debug level to 'info' (quieter) or 'debug' (when verbose). Currently, it is not guaranteed that SetConnectionDebugging will be called on all roaming paths, therefore we end up with two scenarios in the logs: one where roaming happens out of the blue, like so (timestamp removed): shill: [INFO:manager.cc(497)] Service updated; state: Connected failure Unknown shill: [INFO:wifi.cc(9)] Enabling high bitrates. // Connected here shill: [INFO:service.cc(404)] Service : state Connected -> Online shill: [INFO:manager.cc(497)] Service updated; state: Online failure Unknown shill: [INFO:wifi_service.cc(78)] Representative endpoint updated for service... shill: [INFO:manager.cc(74)] Default physical service: (connected) shill: [INFO:wifi.cc(9)] Scan on wlan0 from RequestScan // We have roamed to a new AP that we are trying to authenticate with, // and we don't know why... wpa_supplicant: wlan0: SME: Trying to authenticate with <> (SSID='' freq= MHz) wpa_supplicant: wlan0: Trying to associate with <> (SSID='' freq= MHz) The second scenario, and the preferable one, is where we get details of how roaming decisions were made. This happens when WiFi::SetConnectionDebugging(true) is on the execution path, which seems to be only when connecting to a new service: wpa_supplicant: BSS: last_scan_res_used=14/32 wpa_supplicant: wlan0: New scan results available (own=1 ext=0) wpa_supplicant: bgscan simple: scan result notification wpa_supplicant: bgscan simple: freq_idx 0 wpa_supplicant: bgscan_poll_signal_monitor: bgscan poll noisefloor: 9999 wpa_supplicant: wlan0: Radio work 'scan'<> done in <> seconds wpa_supplicant: wlan0: Selecting BSS from priority group <> wpa_supplicant: wlan0: 0: <MAC> ssid='' wpa_ie_len=<> rsn_ie_len=<> caps=<> level=<> freq=<> wps wpa_supplicant: wlan0: selected based on RSN IE wpa_supplicant: wlan0: selected BSS <> ssid='' wpa_supplicant: wlan0: Allow reassociation - selected BSS has better estimated throughput wpa_supplicant: wlan0: Considering connect request: reassociate: 0 selected: <> bssid: <> ... wpa_supplicant: wlan0: Request association with <> wpa_supplicant: wlan0: Re-association to the same ESS ... wpa_supplicant: wlan0: SME: Trying to authenticate with <> (SSID='' freq=<> MHz) Until we have confidence that all roaming scenarios do go through shill and can be intercepted with WiFi::SetConnectionDebugging(true), the safer route is to bump up the logging level of the following directly in wpa_supplicant itself: - roaming decisions. - estimated throughput and channel quality calculations. BUG=chromium:771501 TEST=(TBD) compare test runs with and without patch, for network_WiFi_RoamEndToEnd, network_WiFi_Roam, network_WiFi_RoamSuspendSSID. Change-Id: I3566c40ad561708357ba405d61f079f464a685b6 Signed-off-by: Kirtika Ruchandani <kirtika@chromium.org> Reviewed-on: https://chromium-review.googlesource.com/699915 Reviewed-by: Ben Chan <benchan@chromium.org> Reviewed-by: Eric Caruso <ejcaruso@chromium.org> [modify] https://crrev.com/402cb15bc9a824f3ffddeb1e2ba29716d6f51870/wpa_supplicant/events.c
,
Jan 3 2018
,
Mar 16 2018
The following revision refers to this bug: https://chromium.googlesource.com/chromiumos/third_party/hostap/+/d4efd4a3cea0c19a030ebfc83b3be08ccdda202b commit d4efd4a3cea0c19a030ebfc83b3be08ccdda202b Author: Kirtika Ruchandani <kirtika@chromium.org> Date: Fri Mar 16 00:58:05 2018 CHROMIUM: Bump up logging level for roaming decisions Chrome OS relies on its connection manager, shill, to bump up the logging level in wpa_supplicant during 'interesting' times via its WiFi::SetConnectionDebugging method. The method sets wpa_supplicant debug level to 'info' (quieter) or 'debug' (when verbose). Currently, it is not guaranteed that SetConnectionDebugging will be called on all roaming paths, therefore we end up with two scenarios in the logs: one where roaming happens out of the blue, like so (timestamp removed): shill: [INFO:manager.cc(497)] Service updated; state: Connected failure Unknown shill: [INFO:wifi.cc(9)] Enabling high bitrates. // Connected here shill: [INFO:service.cc(404)] Service : state Connected -> Online shill: [INFO:manager.cc(497)] Service updated; state: Online failure Unknown shill: [INFO:wifi_service.cc(78)] Representative endpoint updated for service... shill: [INFO:manager.cc(74)] Default physical service: (connected) shill: [INFO:wifi.cc(9)] Scan on wlan0 from RequestScan // We have roamed to a new AP that we are trying to authenticate with, // and we don't know why... wpa_supplicant: wlan0: SME: Trying to authenticate with <> (SSID='' freq= MHz) wpa_supplicant: wlan0: Trying to associate with <> (SSID='' freq= MHz) The second scenario, and the preferable one, is where we get details of how roaming decisions were made. This happens when WiFi::SetConnectionDebugging(true) is on the execution path, which seems to be only when connecting to a new service: wpa_supplicant: BSS: last_scan_res_used=14/32 wpa_supplicant: wlan0: New scan results available (own=1 ext=0) wpa_supplicant: bgscan simple: scan result notification wpa_supplicant: bgscan simple: freq_idx 0 wpa_supplicant: bgscan_poll_signal_monitor: bgscan poll noisefloor: 9999 wpa_supplicant: wlan0: Radio work 'scan'<> done in <> seconds wpa_supplicant: wlan0: Selecting BSS from priority group <> wpa_supplicant: wlan0: 0: <MAC> ssid='' wpa_ie_len=<> rsn_ie_len=<> caps=<> level=<> freq=<> wps wpa_supplicant: wlan0: selected based on RSN IE wpa_supplicant: wlan0: selected BSS <> ssid='' wpa_supplicant: wlan0: Allow reassociation - selected BSS has better estimated throughput wpa_supplicant: wlan0: Considering connect request: reassociate: 0 selected: <> bssid: <> ... wpa_supplicant: wlan0: Request association with <> wpa_supplicant: wlan0: Re-association to the same ESS ... wpa_supplicant: wlan0: SME: Trying to authenticate with <> (SSID='' freq=<> MHz) Until we have confidence that all roaming scenarios do go through shill and can be intercepted with WiFi::SetConnectionDebugging(true), the safer route is to bump up the logging level of the following directly in wpa_supplicant itself: - roaming decisions. - estimated throughput and channel quality calculations. BUG=chromium:771501 TEST=(TBD) compare test runs with and without patch, for network_WiFi_RoamEndToEnd, network_WiFi_Roam, network_WiFi_RoamSuspendSSID. Change-Id: I3566c40ad561708357ba405d61f079f464a685b6 Signed-off-by: Kirtika Ruchandani <kirtika@chromium.org> Reviewed-on: https://chromium-review.googlesource.com/964738 Commit-Ready: Matthew Wang <matthewmwang@chromium.org> Tested-by: Matthew Wang <matthewmwang@chromium.org> Reviewed-by: Eric Caruso <ejcaruso@chromium.org> [modify] https://crrev.com/d4efd4a3cea0c19a030ebfc83b3be08ccdda202b/wpa_supplicant/events.c
,
Mar 16 2018
The following revision refers to this bug: https://chromium.googlesource.com/chromiumos/third_party/hostap/+/ef42f5ac1970fdcb27bef6c16a8de2010ea19698 commit ef42f5ac1970fdcb27bef6c16a8de2010ea19698 Author: Kirtika Ruchandani <kirtika@chromium.org> Date: Fri Mar 16 00:58:06 2018 CHROMIUM: Bump up logging level for blacklist decisions Chrome OS relies on its connection manager, shill, to bump up the logging level in wpa_supplicant during 'interesting' times via its WiFi::SetConnectionDebugging method. The method sets wpa_supplicant debug level to 'info' (quieter) or 'debug' (verbose). It's not clear SetConnectionDebugging is being called on execution paths of interest - in particular, APs we are connected to at one instant show up as blacklisted in the scan after an unexpected disconnect, like so: (<> implies redacted/placeholder) wlan0: New scan results available (own=1 ext=0) wlan0: Radio work 'scan'@<> done in <> seconds wlan0: Selecting BSS from priority group <> // This SSID was one we were connected to before, and there was // no mention of blacklisting it in the log lines prior to this. wlan0: 0: <> ssid='<>' wpa_ie_len=0 rsn_ie_len=<> caps=<> level=<> freq=<> wps wlan0: skip - blacklisted (count=2 limit=0) wlan0: 1: <> ssid='<>' wpa_ie_len=0 rsn_ie_len=<> caps=<> level=<> freq=<> wps Ensure that we always print blacklist adding/clearing decisions - its only 3 lines anyways. BUG=chromium:771501 TEST=(TBD) Change-Id: I4ea4b01239dc95c4a1e4619f1d4ddb0c4b8eb63b Signed-off-by: Kirtika Ruchandani <kirtika@chromium.org> Reviewed-on: https://chromium-review.googlesource.com/964739 Commit-Ready: Matthew Wang <matthewmwang@chromium.org> Tested-by: Matthew Wang <matthewmwang@chromium.org> Reviewed-by: Eric Caruso <ejcaruso@chromium.org> [modify] https://crrev.com/ef42f5ac1970fdcb27bef6c16a8de2010ea19698/wpa_supplicant/blacklist.c
,
Aug 3
This bug has an owner, thus, it's been triaged. Changing status to "assigned". |
||||
►
Sign in to add a comment |
||||
Comment 1 by kirtika@chromium.org
, Oct 4 2017