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

Issue 642552 link

Starred by 1 user
Status: Untriaged
Owner: ----
Cc:
snanda@chromium.org
█ kirtika@chromium.org
semenzato@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 3
Type: Bug



Sign in to add a comment

Test problem: network_WiFi_RoamDbus - FAIL - Failed to roam.

Project Member Reported by kirtika@chromium.org, Aug 30 2016 
TEST: network_WiFi_RoamDbus
SUITE: wifi_matfunc
CHROMEOS BUILD: R55-8752.0.0
STATUS: FAIL
REASON: Failed to roam.

SUMMARY: Test problem: network_WiFi_RoamDbus - FAIL - Failed to roam.

REF: https://wmatrix.googleplex.com/comments?test_ids=341192164

Comment 1 by briannorris@chromium.org, Apr 17 2017

Labels: OS-Chrome
FWIW, I'm seeing what looks like a test flake locally (I rerun the test and it passes) with net.log containing this:

2017-04-14T21:08:40.820690-07:00 DEBUG wpa_supplicant[675]: [dbus-new] ROAM 30:b5:c2:33:fc:a3
2017-04-14T21:08:40.821137-07:00 DEBUG wpa_supplicant[675]: mlan0: Considering connect request: reassociate: 1  selected: 30:b5:c2:33:fc:a3
  bssid: 30:b5:c2:34:11:76  pending: 00:00:00:00:00:00  wpa_state: COMPLETED  ssid=0xb8561720  current_ssid=0xb8561720
2017-04-14T21:08:40.821542-07:00 DEBUG wpa_supplicant[675]: mlan0: Request association with 30:b5:c2:33:fc:a3
2017-04-14T21:08:40.821862-07:00 DEBUG wpa_supplicant[675]: mlan0: Re-association to the same ESS
2017-04-14T21:08:40.822181-07:00 DEBUG wpa_supplicant[675]: TDLS: TDLS is allowed in the target BSS
2017-04-14T21:08:40.822567-07:00 DEBUG wpa_supplicant[675]: TDLS: TDLS channel switch allowed in the target BSS
2017-04-14T21:08:40.822923-07:00 DEBUG wpa_supplicant[675]: mlan0: Add radio work 'connect'@0xb85dab68
2017-04-14T21:08:40.823324-07:00 DEBUG wpa_supplicant[675]: mlan0: First radio work item in the queue - schedule start immediately
2017-04-14T21:08:40.824950-07:00 DEBUG wpa_supplicant[675]: mlan0: Starting radio work 'connect'@0xb85dab68 after 0.001670 second wait
2017-04-14T21:08:40.825532-07:00 NOTICE wpa_supplicant[675]: mlan0: Trying to associate with 30:b5:c2:33:fc:a3 (SSID='RoamDbus_a_t357k_ch48
' freq=2412 MHz)
2017-04-14T21:08:40.825896-07:00 DEBUG wpa_supplicant[675]: FT: Stored MDIE and FTIE from (Re)Association Response - hexdump(len=0):
2017-04-14T21:08:40.826280-07:00 DEBUG wpa_supplicant[675]: mlan0: Cancelling scan request
2017-04-14T21:08:40.826619-07:00 DEBUG wpa_supplicant[675]: mlan0: WPA: clearing own WPA/RSN IE
2017-04-14T21:08:40.826933-07:00 DEBUG wpa_supplicant[675]: mlan0: Automatic auth_alg selection: 0x1
2017-04-14T21:08:40.827291-07:00 DEBUG wpa_supplicant[675]: mlan0: WPA: clearing AP WPA IE
2017-04-14T21:08:40.828571-07:00 DEBUG wpa_supplicant[675]: mlan0: WPA: clearing AP RSN IE
2017-04-14T21:08:40.830135-07:00 DEBUG wpa_supplicant[675]: mlan0: WPA: clearing own WPA/RSN IE
2017-04-14T21:08:40.830651-07:00 DEBUG wpa_supplicant[675]: mlan0: State: COMPLETED -> ASSOCIATING
2017-04-14T21:08:40.831177-07:00 DEBUG wpa_supplicant[675]: nl80211: Set mlan0 operstate 1->0 (DORMANT)
2017-04-14T21:08:40.832656-07:00 DEBUG wpa_supplicant[675]: netlink: Operstate: ifindex=4 linkmode=-1 (no change), operstate=5 (IF_OPER_DOR
MANT)
2017-04-14T21:08:40.835297-07:00 DEBUG shill[1388]: [VERBOSE5:rtnl_handler.cc(281)] ParseRTNL: received payload (1184)
2017-04-14T21:08:40.835509-07:00 DEBUG shill[1388]: [VERBOSE5:rtnl_handler.cc(285)] RTNL received payload length 1184: "A004000010000000000
0000000000000000001000400000003100100000000000A0003006D6C616E3000000008000D00E80300000500100005000000050011000100000008000400DC05000008001B
000000000008001E000000000008001F000400000008002000010000000500210001000000070006006D710000080023002E010000050027000000000024000E00000000000
00000000000000000000000000000000000000000000000000000000A0001001867B0109DCE00000A000200FFFFFFFFFFFF0000600007004E1100001AF6050023A007003173
262200000000040000000C000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
00000000000000000BC0017004E110000000000001AF605000000000023A00700000000003173262200000000000000000000000004000000000000000C0000000000000000
0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000BC021A007C00020078000100
0100000000000000000000000000000001000000010000000100000001000000010000000000000000000000000000000000000000000000000000000000000000000000000
00000000000000100000000000000000000000000000000000000000000000000000010270000E8030000000000003C020A00080001001000008014000500FFFF000035A708
002BA50000E8030000A80002000000000040000000DC0500000200000000000000010000000100000003000000A00F0000E803000002000000803A090080510100030000005
8020000100000000000000001000000010000000000000000000000000000000000000000000000000000000000000000000000010000000000000000000000000000001027
0000E80300000100000000000000000000000100000000000000000000000100000000000000240103002400000000000000000000000000000000000000000000000000000
0000000000000000000000000F303000000000000D40A0100000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
0000000000000000000000000000000200000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
000000000000000000000000000000000000000000000000000F203000000000000000000000000000000000000000000000000000000000000880A01000000000000000000
0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000034000600060000000000000000000000000
000000000000000000000F1030000000000000000000000000000000000000000000014000700000000000000000000000000000000000500080000000000"
2017-04-14T21:08:40.836345-07:00 DEBUG wpa_supplicant[675]: Limit connection to BSSID 30:b5:c2:33:fc:a3 freq=2412 MHz based on scan results
 (bssid_set=0)
...
2017-04-14T21:08:40.849459-07:00 DEBUG wpa_supplicant[675]: nl80211: Connect (ifindex=4)
2017-04-14T21:08:40.849574-07:00 DEBUG wpa_supplicant[675]:   * bssid=30:b5:c2:33:fc:a3
2017-04-14T21:08:40.849652-07:00 DEBUG wpa_supplicant[675]:   * bssid_hint=30:b5:c2:33:fc:a3
2017-04-14T21:08:40.849751-07:00 DEBUG wpa_supplicant[675]:   * freq=2412
2017-04-14T21:08:40.849835-07:00 DEBUG wpa_supplicant[675]:   * freq_hint=2412
2017-04-14T21:08:40.849967-07:00 DEBUG wpa_supplicant[675]:   * SSID - hexdump(len=21): 52 6f 61 6d 44 62 75 73 5f 61 5f 74 33 35 37 6b 5f 
63 68 34 38
2017-04-14T21:08:40.850076-07:00 DEBUG wpa_supplicant[675]:   * IEs - hexdump(len=7): 7f 05 00 00 00 00 01
2017-04-14T21:08:40.850202-07:00 DEBUG wpa_supplicant[675]:   * htcaps - hexdump(len=26): 63 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0
0 00 00 00 00 00 00 00 00 00
2017-04-14T21:08:40.850356-07:00 DEBUG wpa_supplicant[675]:   * htcaps_mask - hexdump(len=26): 63 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 00 00 00 00 00 00 00 00 00 00 00
2017-04-14T21:08:40.850489-07:00 DEBUG wpa_supplicant[675]:   * vhtcaps - hexdump(len=12): 00 00 00 00 00 00 00 00 00 00 00 00
2017-04-14T21:08:40.850597-07:00 DEBUG wpa_supplicant[675]:   * vhtcaps_mask - hexdump(len=12): 00 00 00 00 00 00 00 00 00 00 00 00
2017-04-14T21:08:40.850703-07:00 DEBUG wpa_supplicant[675]:   * Auth Type 0
2017-04-14T21:08:40.857140-07:00 DEBUG wpa_supplicant[675]: nl80211: MLME connect failed: ret=-114 (Operation already in progress)
2017-04-14T21:08:40.857358-07:00 DEBUG wpa_supplicant[675]: nl80211: Explicitly disconnecting before reassociation attempt
2017-04-14T21:08:40.857449-07:00 DEBUG wpa_supplicant[675]: wpa_driver_nl80211_disconnect(reason_code=2)
2017-04-14T21:08:40.871801-07:00 DEBUG wpa_supplicant[675]: nl80211: Connect (ifindex=4)
2017-04-14T21:08:40.871904-07:00 DEBUG wpa_supplicant[675]:   * bssid=30:b5:c2:33:fc:a3
2017-04-14T21:08:40.871991-07:00 DEBUG wpa_supplicant[675]:   * bssid_hint=30:b5:c2:33:fc:a3
2017-04-14T21:08:40.872062-07:00 DEBUG wpa_supplicant[675]:   * freq=2412
2017-04-14T21:08:40.872132-07:00 DEBUG wpa_supplicant[675]:   * freq_hint=2412
2017-04-14T21:08:40.872782-07:00 DEBUG wpa_supplicant[675]:   * SSID - hexdump(len=21): 52 6f 61 6d 44 62 75 73 5f 61 5f 74 33 35 37 6b 5f 
63 68 34 38
2017-04-14T21:08:40.872905-07:00 DEBUG wpa_supplicant[675]:   * IEs - hexdump(len=7): 7f 05 00 00 00 00 01
2017-04-14T21:08:40.873016-07:00 DEBUG shill[1388]: [VERBOSE5:rtnl_handler.cc(281)] ParseRTNL: received payload (1184)
2017-04-14T21:08:40.873019-07:00 DEBUG wpa_supplicant[675]:   * htcaps - hexdump(len=26): 63 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0
0 00 00 00 00 00 00 00 00 00
2017-04-14T21:08:40.873107-07:00 DEBUG wpa_supplicant[675]:   * htcaps_mask - hexdump(len=26): 63 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 00 00 00 00 00 00 00 00 00 00 00
2017-04-14T21:08:40.873170-07:00 DEBUG shill[1388]: [VERBOSE5:rtnl_handler.cc(285)] RTNL received payload length 1184: "A004000010000000000
0000000000000000001000400000003100000000000000A0003006D6C616E3000000008000D00E80300000500100002000000050011000100000008000400DC05000008001B
000000000008001E000000000008001F000400000008002000010000000500210000000000070006006D710000080023002F010000050027000000000024000E00000000000
00000000000000000000000000000000000000000000000000000000A0001001867B0109DCE00000A000200FFFFFFFFFFFF0000600007004E1100001AF6050023A007003173
262200000000040000000C000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
00000000000000000BC0017004E110000000000001AF605000000000023A00700000000003173262200000000000000000000000004000000000000000C0000000000000000
0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000BC021A007C00020078000100
0100000000000000000000000000000001000000010000000100000001000000010000000000000000000000000000000000000000000000000000000000000000000000000
00000000000000100000000000000000000000000000000000000000000000000000010270000E8030000000000003C020A00080001001000008014000500FFFF000035A708
002BA50000E8030000A80002000000000040000000DC0500000200000000000000010000000100000003000000A00F0000E803000002000000803A090080510100030000005
8020000100000000000000001000000010000000000000000000000000000000000000000000000000000000000000000000000010000000000000000000000000000001027
0000E80300000100000000000000000000000100000000000000000000000100000000000000240103002400000000000000000000000000000000000000000000000000000
0000000000000000000000000F303000000000000D40A0100000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
0000000000000000000000000000000200000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
000000000000000000000000000000000000000000000000000F203000000000000000000000000000000000000000000000000000000000000880A01000000000000000000
0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000034000600060000000000000000000000000
000000000000000000000F1030000000000000000000000000000000000000000000014000700000000000000000000000000000000000500080000000000"
2017-04-14T21:08:40.873182-07:00 DEBUG wpa_supplicant[675]:   * vhtcaps - hexdump(len=12): 00 00 00 00 00 00 00 00 00 00 00 00
2017-04-14T21:08:40.873291-07:00 DEBUG wpa_supplicant[675]:   * vhtcaps_mask - hexdump(len=12): 00 00 00 00 00 00 00 00 00 00 00 00
2017-04-14T21:08:40.873367-07:00 DEBUG wpa_supplicant[675]:   * Auth Type 0
2017-04-14T21:08:40.880196-07:00 DEBUG wpa_supplicant[675]: nl80211: MLME connect failed: ret=-114 (Operation already in progress)
2017-04-14T21:08:40.880361-07:00 NOTICE wpa_supplicant[675]: mlan0: Association request to the driver failed
2017-04-14T21:08:40.880461-07:00 DEBUG wpa_supplicant[675]: mlan0: Radio work 'connect'@0xb85dab68 done in 0.055740 seconds
2017-04-14T21:08:40.880544-07:00 DEBUG wpa_supplicant[675]: Added BSSID 30:b5:c2:33:fc:a3 into blacklist


Seems odd that wpa_supplicant cancels the reassociation attempt just because it gets -EALREADY from the kernel. What could be "in progress" and blocking us?

Comment 2 by marcuskoehler@chromium.org, Jan 15

Labels: Enterprise-Triaged
►

Sign in to add a comment