New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 919694 link

Starred by 1 user

Issue metadata

Status: Untriaged
Owner: ----
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

network_WiFi_RoamDbus test fails on Veyron+BRCM devices with "Failed to roam" error

Project Member Reported by jmuppala@google.com, Jan 8

Issue description

network_WiFi_RoamDbus test fails on Veyron devices with "Failed to Roam" error.

https://stainless.corp.google.com/search?view=list&first_date=2018-11-11&last_date=2019-01-07&test=network_WiFi_RoamDbus&board=%5Eveyron_&status=FAIL&status=ERROR&status=ABORT&exclude_cts=true&exclude_not_run=false&exclude_non_release=true&exclude_au=true&exclude_acts=true&exclude_retried=true&exclude_non_production=false

Logs:
https://sponge.corp.googleusercontent.com/file?invocationId=bae7336b-66af-42fa-945d-f27803e21041&targetResultIndex=0&largeText=logs%2Fnetwork_WiFi_RoamDbus%2Fdebug%2Fnetwork_WiFi_RoamDbus.DEBUG&filename=network_WiFi_RoamDbus.DEBUG&contentType=text%2Fplain%3B%20charset%3Dutf-8&format=ansi&setTZID=America%2FLos_Angeles

Sample failure:
ConnectionAttempts=4 -l root -p 22' -az --no-o --no-g  root@chromeos15-row2-rack12-host7:"/tmp/autoserv-Jqoeg7/sysinfo.pickle" "/tmp/tmp4s8T7k"'
01/05 17:23:18.312 DEBUG|              test:0391| after_iteration_hooks completed
01/05 17:23:18.312 WARNI|              test:0606| The test failed with the following exception
Traceback (most recent call last):
  File "/usr/local/autotest/client/common_lib/test.py", line 600, in _exec
    _call_test_function(self.execute, *p_args, **p_dargs)
  File "/usr/local/autotest/client/common_lib/test.py", line 800, in _call_test_function
    return func(*args, **dargs)
  File "/usr/local/autotest/client/common_lib/test.py", line 464, in execute
    postprocess_profiled_run, args, dargs)
  File "/usr/local/autotest/client/common_lib/test.py", line 371, in _call_run_once
    self.run_once(*args, **dargs)
  File "/usr/local/autotest/server/site_tests/network_WiFi_RoamDbus/network_WiFi_RoamDbus.py", line 86, in run_once
    raise error.TestFail('Failed to roam.')
TestFail: Failed to roam.

 
01/06 15:15:22.236 DEBUG|             utils:0287| [stdout] BSS 30:b5:c2:33:e2:6f(on wlan0)
01/06 15:15:22.236 DEBUG|             utils:0287| [stdout] 	TSF: 0 usec (0d, 00:00:00)
01/06 15:15:22.236 DEBUG|             utils:0287| [stdout] 	freq: 2412
01/06 15:15:22.236 DEBUG|             utils:0287| [stdout] 	beacon interval: 100 TUs
01/06 15:15:22.236 DEBUG|             utils:0287| [stdout] 	capability: ESS (0x0001)
01/06 15:15:22.237 DEBUG|             utils:0287| [stdout] 	signal: -37.00 dBm
01/06 15:15:22.237 DEBUG|             utils:0287| [stdout] 	last seen: 10 ms ago
01/06 15:15:22.237 DEBUG|             utils:0287| [stdout] 	Information elements from Probe Response frame:
01/06 15:15:22.237 DEBUG|             utils:0287| [stdout] 	SSID: RoamDbus_a_tykq9_ch48
01/06 15:15:22.237 DEBUG|             utils:0287| [stdout] 	Supported rates: 1.0* 2.0* 5.5 11.0 
01/06 15:15:22.237 DEBUG|             utils:0287| [stdout] 	DS Parameter set: channel 1
01/06 15:15:22.237 DEBUG|             utils:0287| [stdout] 	Extended capabilities:
01/06 15:15:22.237 DEBUG|             utils:0287| [stdout] 		 * Extended Channel Switching
01/06 15:15:22.237 DEBUG|             utils:0287| [stdout] 		 * SSID List
01/06 15:15:22.238 DEBUG|             utils:0287| [stdout] 		 * Operating Mode Notification
01/06 15:15:22.242 DEBUG|             utils:0287| [stdout] real 3.55
01/06 15:15:22.243 DEBUG|             utils:0287| [stdout] user 0.00
01/06 15:15:22.243 DEBUG|             utils:0287| [stdout] sys 0.00
01/06 15:15:22.260 DEBUG|          ssh_host:0310| Running (ssh) '/usr/sbin/iw dev wlan0 link' from 'execute|_call_run_once|run_once|get_current_bssid|run|run_very_slowly'
01/06 15:15:22.666 DEBUG|             utils:0287| [stdout] Connected to 30:b5:c2:34:03:bf (on wlan0)
01/06 15:15:22.666 DEBUG|             utils:0287| [stdout] 	SSID: RoamDbus_a_tykq9_ch48
01/06 15:15:22.667 DEBUG|             utils:0287| [stdout] 	freq: 5240
01/06 15:15:22.667 DEBUG|             utils:0287| [stdout] 	RX: 70405 bytes (505 packets)
01/06 15:15:22.667 DEBUG|             utils:0287| [stdout] 	TX: 123994 bytes (1033 packets)
01/06 15:15:22.667 DEBUG|             utils:0287| [stdout] 	signal: -45 dBm
01/06 15:15:22.667 DEBUG|             utils:0287| [stdout] 	tx bitrate: 54.0 MBit/s
01/06 15:15:22.667 DEBUG|             utils:0287| [stdout] 
01/06 15:15:22.667 DEBUG|             utils:0287| [stdout] 	bss flags:	
01/06 15:15:22.667 DEBUG|             utils:0287| [stdout] 	dtim period:	2
01/06 15:15:22.668 DEBUG|             utils:0287| [stdout] 	beacon int:	100
01/06 15:15:22.726 DEBUG|          ssh_host:0310| Running (ssh) '/usr/sbin/iw dev wlan0 link' from 'wait_for_roam|poll_for_condition|attempt_roam|get_current_bssid|run|run_very_slowly'
01/06 15:15:23.138 DEBUG|             utils:0287| [stdout] Not connected.
01/06 15:15:23.140 DEBUG|       wifi_client:0982| Current BSSID is None.
01/06 15:15:23.653 DEBUG|          ssh_host:0310| Running (ssh) '/usr/sbin/iw dev wlan0 link' from 'wait_for_roam|poll_for_condition|attempt_roam|get_current_bssid|run|run_very_slowly'
01/06 15:15:24.034 DEBUG|             utils:0287| [stdout] Not connected.
01/06 15:15:24.051 DEBUG|       wifi_client:0982| Current BSSID is None.
01/06 15:15:24.563 DEBUG|          ssh_host:0310| Running (ssh) '/usr/sbin/iw dev wlan0 link' from 'wait_for_roam|poll_for_condition|attempt_roam|get_current_bssid|run|run_very_slowly'
01/06 15:15:24.990 DEBUG|             utils:0287| [stdout] Not connected.
01/06 15:15:24.993 DEBUG|       wifi_client:0982| Current BSSID is None.
01/06 15:15:25.502 DEBUG|          ssh_host:0310| Running (ssh) '/usr/sbin/iw dev wlan0 link' from 'wait_for_roam|poll_for_condition|attempt_roam|get_current_bssid|run|run_very_slowly'
01/06 15:15:25.916 DEBUG|             utils:0287| [stdout] Connected to 30:b5:c2:34:03:bf (on wlan0)
01/06 15:15:25.917 DEBUG|             utils:0287| [stdout] 	SSID: RoamDbus_a_tykq9_ch48
01/06 15:15:25.917 DEBUG|             utils:0287| [stdout] 	freq: 5240
01/06 15:15:25.917 DEBUG|             utils:0287| [stdout] 	RX: 70405 bytes (505 packets)
01/06 15:15:25.917 DEBUG|             utils:0287| [stdout] 	TX: 123994 bytes (1033 packets)
01/06 15:15:25.917 DEBUG|             utils:0287| [stdout] 	signal: -45 dBm
01/06 15:15:25.917 DEBUG|             utils:0287| [stdout] 	tx bitrate: 54.0 MBit/s
01/06 15:15:25.917 DEBUG|             utils:0287| [stdout] 

The DS parameter set shows channel 1 instead of channel 48, and then fails.

Cc: matthewmwang@chromium.org
Summary: network_WiFi_RoamDbus test fails on Veyron+BRCM devices with "Failed to roam" error (was: network_WiFi_RoamDbus test fails on Veyron devices with "Failed to roam" error)
It looks like the Broadcom Wifi driver is ignoring our BSSID hints most of the time.

For example:

https://stainless.corp.google.com/browse/chromeos-autotest-results/260716891-chromeos-test/

2018-11-25T02:34:45.619160+00:00 DEBUG wpa_supplicant[686]: nl80211: Connect (ifindex=3)
2018-11-25T02:34:45.619313+00:00 DEBUG wpa_supplicant[686]:   * bssid_hint=30:b5:c2:33:e2:6f
2018-11-25T02:34:45.619408+00:00 DEBUG wpa_supplicant[686]:   * freq_hint=2412
...
2018-11-25T02:34:45.620207+00:00 DEBUG wpa_supplicant[686]:   * prev_bssid=30:b5:c2:34:03:bf

See how we're supposed to move to ...:33:e2:6f / 2412MHz. But shortly afterward:

2018-11-25T02:34:48.158864+00:00 DEBUG wpa_supplicant[686]: nl80211: Drv Event 46 (NL80211_CMD_CONNECT) received for wlan0
2018-11-25T02:34:48.158988+00:00 DEBUG wpa_supplicant[686]: nl80211: Connect event (status=0 ignore_next_local_disconnect=0)
2018-11-25T02:34:48.162201+00:00 DEBUG wpa_supplicant[686]: nl80211: Associated on 5240 MHz
2018-11-25T02:34:48.162372+00:00 DEBUG wpa_supplicant[686]: nl80211: Associated with 30:b5:c2:34:03:bf

brcmfmac put us right back on the 5240 MHz BSS.

I wonder if this is related to what Matthew noticed here,

https://chromium-review.googlesource.com/c/chromiumos/third_party/autotest/+/1376889

that WPA supplicant doesn't usually try to make roaming decisions for drivers that do their own roaming. But it's still odd that the connect() callback appears to propagate the bssid hint, yet we still end up on the wrong BSS.
Labels: Enterprise-Triaged

Sign in to add a comment