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

Issue 919607 link

Starred by 1 user
Status: Untriaged
Owner: ----
Cc:
briannorris@chromium.org
aashuto...@chromium.org
dsunk...@chromium.org
█ kirtika@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

[Autotest failure] network_WiFi_LowInitialBitrates fails on veyron devices with "Frame at XX:XX:... was sent with MCS index 15."

Project Member Reported by harpreet@chromium.org, Jan 7 
Stainless link: https://stainless.corp.google.com/search?view=list&first_date=2018-11-11&last_date=2019-01-07&test=%5Enetwork_WiFi_LowInitialBitrates&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



01/06 11:19:56.637 INFO |wifi_test_context_:0262| Finished connection attempt to LowInitialBitrates_b_o1fi7_ch44 with times: discovery=2.53, association=2.82, configuration=1.05.
01/06 11:19:56.676 DEBUG|          ssh_host:0310| Running (ssh) 'iw dev wlan0 info' from 'assert_connect_wifi|wifi_signal_level|signal_level|is_wifi_device|run|run_very_slowly'
01/06 11:19:57.119 DEBUG|             utils:0287| [stdout] Interface wlan0
01/06 11:19:57.120 DEBUG|             utils:0287| [stdout] 	ifindex 4
01/06 11:19:57.120 DEBUG|             utils:0287| [stdout] 	wdev 0x1
01/06 11:19:57.120 DEBUG|             utils:0287| [stdout] 	addr 80:a5:89:0f:34:db
01/06 11:19:57.120 DEBUG|             utils:0287| [stdout] 	ssid LowInitialBitrates_b_o1fi7_ch44
01/06 11:19:57.120 DEBUG|             utils:0287| [stdout] 	type managed
01/06 11:19:57.120 DEBUG|             utils:0287| [stdout] 	wiphy 0
01/06 11:19:57.162 DEBUG|          ssh_host:0310| Running (ssh) 'iw dev wlan0 link' from 'run_once|assert_connect_wifi|wifi_signal_level|signal_level|run|run_very_slowly'
01/06 11:19:57.642 DEBUG|             utils:0287| [stdout] Connected to 30:b5:c2:34:03:bf (on wlan0)
01/06 11:19:57.643 DEBUG|             utils:0287| [stdout] 	SSID: LowInitialBitrates_b_o1fi7_ch44
01/06 11:19:57.643 DEBUG|             utils:0287| [stdout] 	freq: 5220
01/06 11:19:57.643 DEBUG|             utils:0287| [stdout] 	RX: 193296 bytes (1746 packets)
01/06 11:19:57.643 DEBUG|             utils:0287| [stdout] 	TX: 437033 bytes (3745 packets)
01/06 11:19:57.644 DEBUG|             utils:0287| [stdout] 	signal: -45 dBm
01/06 11:19:57.644 DEBUG|             utils:0287| [stdout] 	tx bitrate: 270.0 MBit/s MCS 15 40MHz
01/06 11:19:57.644 DEBUG|             utils:0287| [stdout] 
01/06 11:19:57.644 DEBUG|             utils:0287| [stdout] 	bss flags:	
01/06 11:19:57.644 DEBUG|             utils:0287| [stdout] 	dtim period:	2
01/06 11:19:57.644 DEBUG|             utils:0287| [stdout] 	beacon int:	100
01/06 11:19:57.646 INFO |wifi_test_context_:0281| Connected successfully to LowInitialBitrates_b_o1fi7_ch44, signal level: -45.
01/06 11:19:57.647 INFO | site_linux_system:0738| Pinging from the client.
01/06 11:19:57.689 DEBUG|          ssh_host:0310| Running (ssh) 'ping -c 10 192.168.0.254' from 'run_once|assert_ping_from_dut|ping|ping|run|run_very_slowly'
01/06 11:19:58.129 DEBUG|             utils:0287| [stdout] PING 192.168.0.254 (192.168.0.254) 56(84) bytes of data.
01/06 11:19:58.130 DEBUG|             utils:0287| [stdout] 64 bytes from 192.168.0.254: icmp_seq=1 ttl=64 time=7.88 ms
01/06 11:19:59.133 DEBUG|             utils:0287| [stdout] 64 bytes from 192.168.0.254: icmp_seq=2 ttl=64 time=8.92 ms
01/06 11:20:00.135 DEBUG|             utils:0287| [stdout] 64 bytes from 192.168.0.254: icmp_seq=3 ttl=64 time=9.05 ms
01/06 11:20:01.141 DEBUG|             utils:0287| [stdout] 64 bytes from 192.168.0.254: icmp_seq=4 ttl=64 time=8.94 ms
01/06 11:20:02.139 DEBUG|             utils:0287| [stdout] 64 bytes from 192.168.0.254: icmp_seq=5 ttl=64 time=9.25 ms
01/06 11:20:03.142 DEBUG|             utils:0287| [stdout] 64 bytes from 192.168.0.254: icmp_seq=6 ttl=64 time=9.89 ms
01/06 11:20:04.145 DEBUG|             utils:0287| [stdout] 64 bytes from 192.168.0.254: icmp_seq=7 ttl=64 time=9.06 ms
01/06 11:20:05.143 DEBUG|             utils:0287| [stdout] 64 bytes from 192.168.0.254: icmp_seq=8 ttl=64 time=9.10 ms
01/06 11:20:06.146 DEBUG|             utils:0287| [stdout] 64 bytes from 192.168.0.254: icmp_seq=9 ttl=64 time=9.18 ms
01/06 11:20:07.150 DEBUG|             utils:0287| [stdout] 64 bytes from 192.168.0.254: icmp_seq=10 ttl=64 time=10.2 ms
01/06 11:20:07.150 DEBUG|             utils:0287| [stdout] 
01/06 11:20:07.150 DEBUG|             utils:0287| [stdout] --- 192.168.0.254 ping statistics ---
01/06 11:20:07.150 DEBUG|             utils:0287| [stdout] 10 packets transmitted, 10 received, 0% packet loss, time 9015ms
.
.
.
01/06 11:20:11.821 INFO |network_WiFi_LowIn:0028| Analyzing packet capture...
01/06 11:20:11.859 DEBUG|          ssh_host:0310| Running (ssh) 'ip addr show wlan0 2> /dev/null' from 'check_bitrates_in_capture|wifi_mac|mac_address|addresses|run|run_very_slowly'
01/06 11:20:12.296 DEBUG|             utils:0287| [stdout] 4: wlan0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default qlen 1000
01/06 11:20:12.297 DEBUG|             utils:0287| [stdout]     link/ether 80:a5:89:0f:34:db brd ff:ff:ff:ff:ff:ff
01/06 11:20:12.297 DEBUG|             utils:0287| [stdout]     inet 192.168.0.19/24 brd 192.168.0.255 scope global wlan0
01/06 11:20:12.297 DEBUG|             utils:0287| [stdout]        valid_lft forever preferred_lft forever
01/06 11:20:12.297 DEBUG|             utils:0287| [stdout]     inet6 fe80::82a5:89ff:fe0f:34db/64 scope link 
01/06 11:20:12.297 DEBUG|             utils:0287| [stdout]        valid_lft forever preferred_lft forever
01/06 11:20:12.347 DEBUG|          ssh_host:0310| Running (ssh) 'ip addr show wlan0 2> /dev/null' from 'check_bitrates_in_capture|wifi_mac|mac_address|addresses|run|run_very_slowly'
01/06 11:20:12.747 DEBUG|             utils:0287| [stdout] 4: wlan0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default qlen 1000
01/06 11:20:12.747 DEBUG|             utils:0287| [stdout]     link/ether 80:a5:89:0f:34:db brd ff:ff:ff:ff:ff:ff
01/06 11:20:12.747 DEBUG|             utils:0287| [stdout]     inet 192.168.0.19/24 brd 192.168.0.255 scope global wlan0
01/06 11:20:12.748 DEBUG|             utils:0287| [stdout]        valid_lft forever preferred_lft forever
01/06 11:20:12.748 DEBUG|             utils:0287| [stdout]     inet6 fe80::82a5:89ff:fe0f:34db/64 scope link 
01/06 11:20:12.748 DEBUG|             utils:0287| [stdout]        valid_lft forever preferred_lft forever
01/06 11:20:12.754 DEBUG|  tcpdump_analyzer:0155| Capture: pcap.1.pcap, Filter: wlan.sa==80:a5:89:0f:34:db and not wlan.da==80:a5:89:0f:34:db
01/06 11:20:12.754 DEBUG|   selector_events:0071| Using selector: EpollSelector
01/06 11:20:13.459 INFO |  tcpdump_analyzer:0158| Parsing frames
01/06 11:20:13.485 DEBUG|  tcpdump_analyzer:0155| Capture: pcap.1.pcap, Filter: wlan.sa==80:a5:89:0f:34:db and bootp
01/06 11:20:13.485 DEBUG|   selector_events:0071| Using selector: EpollSelector
01/06 11:20:14.007 INFO |  tcpdump_analyzer:0158| Parsing frames
01/06 11:20:14.011 DEBUG|              test:0381| Test failed due to Frame at 11:19:54.053749 was sent with MCS index 15.. Exception log follows the after_iteration_hooks.
.
.
.
01/06 11:20:27.444 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_LowInitialBitrates/network_WiFi_LowInitialBitrates.py", line 101, in run_once
    self.check_bitrates_in_capture(results[0])
  File "/usr/local/autotest/server/site_tests/network_WiFi_LowInitialBitrates/network_WiFi_LowInitialBitrates.py", line 62, in check_bitrates_in_capture
    (frame.time_string, frame.mcs_index))
TestFail: Frame at 11:19:54.053749 was sent with MCS index 15.

Comment 1 by harpreet@chromium.org, Jan 7

Components: OS>Systems>Network

Comment 2 by jmuppala@google.com, Jan 8

Cc: aashuto...@chromium.org briannorris@chromium.org kirtika@chromium.org dsunk...@chromium.org

Comment 3 by kirtika@google.com, Jan 8 

How recent is this regression?
There's two possible causes: 
1. Marvell firmware regressed and now doesn't listen to the rate-set changing command. 
2. Intel driver has a hack that rejects the rate-mask setting if the rate-mask implies that we have no available rate intersecting with the AP. I wonder if this was upstreamed to wpa-supplicant and we somehow picked it up. 
If its 100% repro, it should be easy to add logging around the rate-mask setting and see if it succeeded.

Comment 4 by briannorris@chromium.org, Jan 8 

Those are almost entirely Broadcom. (The few that are Marvell are failing for reasons different than $subject.)

Comment 5 by marcuskoehler@chromium.org, Jan 15

Labels: Enterprise-Triaged
►

Sign in to add a comment