ChromeOS version: 69, 70
ChromeOS device model: Acer Chromebook CP5-471 (lars)
Case#: 17250969
Description:
Chrome OS devices (a fleet of 10) are constantly dropping network connections.
Customer also mentioned that it happens when device wakes up from sleep.
Steps to reproduce:
1. Login to device
2. Connect to a network
3. Wait for device turn to a sleep mode
4. Wake up device and check network connection
Current Behavior / Reproduction:
Wifi network gets disconnected
Expected Behavior:
Devices maintain stable connection
Drive link to logs and additional details:
https://drive.google.com/open?id=1LovZdulXCz3uOlBM04gpLLLQM2JCmFIg
As I can see from the latest network log, device was woke up at 13:26:16:
eventlog.txt:307 | 2018-10-30 13:26:16 | ACPI Wake | S3
eventlog.txt:308 | 2018-10-30 13:26:16 | Wake Source | GPE # | 5
And network was disconnected:
2018-10-30T13:26:16.273673+05:30 DEBUG wpa_supplicant[572]: RTM_NEWLINK: ifi_index=2 ifname=wlan0 operstate=2 linkmode=1 ifi_family=0 ifi_flags=0x1003 ([UP])
2018-10-30T13:26:16.273736+05:30 DEBUG wpa_supplicant[572]: RTM_NEWLINK: ifi_index=2 ifname=wlan0 wext ifi_family=0 ifi_flags=0x1043 ([UP][RUNNING])
2018-10-30T13:26:16.273798+05:30 DEBUG wpa_supplicant[572]: nl80211: Drv Event 20 (NL80211_CMD_DEL_STATION) received for wlan0
2018-10-30T13:26:16.273812+05:30 DEBUG wpa_supplicant[572]: nl80211: Delete station
2018-10-30T13:26:16.273847+05:30 DEBUG wpa_supplicant[572]: nl80211: Drv Event 39 (NL80211_CMD_DEAUTHENTICATE) received for wlan0
2018-10-30T13:26:16.273859+05:30 DEBUG wpa_supplicant[572]: nl80211: Deauthenticate event
2018-10-30T13:26:16.273876+05:30 DEBUG wpa_supplicant[572]: wlan0: Event DEAUTH (12) received
2018-10-30T13:26:16.273904+05:30 DEBUG wpa_supplicant[572]: wlan0: Deauthentication notification
2018-10-30T13:26:16.273922+05:30 DEBUG wpa_supplicant[572]: wlan0: * reason 3 (locally generated)
....................................
2018-10-30T13:26:16.274617+05:30 DEBUG wpa_supplicant[572]: wlan0: State: COMPLETED -> DISCONNECTED
2018-10-30T13:26:16.274645+05:30 DEBUG wpa_supplicant[572]: nl80211: Set wlan0 operstate 1->0 (DORMANT)
2018-10-30T13:26:16.274658+05:30 DEBUG wpa_supplicant[572]: netlink: Operstate: ifindex=2 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
2018-10-30T13:26:16.274682+05:30 DEBUG wpa_supplicant[572]: bgscan: Deinitializing module 'simple'
2018-10-30T13:26:16.274695+05:30 DEBUG wpa_supplicant[572]: nl80211: Signal monitor threshold=0 hysteresis=0
2018-10-30T13:26:16.274733+05:30 DEBUG wpa_supplicant[572]: WMM AC: WMM AC is disabled
2018-10-30T13:26:16.274811+05:30 DEBUG wpa_supplicant[572]: EAPOL: External notification - portEnabled=0
2018-10-30T13:26:16.274821+05:30 DEBUG wpa_supplicant[572]: EAPOL: SUPP_PAE entering state DISCONNECTED
....................................
net.log:2018-10-30T13:26:16.278586+05:30 INFO shill[1123]: [INFO:wifi.cc(857)] WiFi wlan0 supplicant updated DisconnectReason to -3
net.log:2018-10-30T13:26:16.279747+05:30 DEBUG wpa_supplicant[572]: dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/1
net.log:2018-10-30T13:26:16.280736+05:30 DEBUG shill[1123]: [VERBOSE2:wifi.cc(378)] /device/wlan0 PropertiesChanged
net.log:2018-10-30T13:26:16.280821+05:30 DEBUG shill[1123]: [VERBOSE3:wifi.cc(789)] /device/wlan0 WiFi wlan0 CurrentBSS /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/2 -> /
net.log:2018-10-30T13:26:16.280845+05:30 DEBUG shill[1123]: [VERBOSE2:wifi.cc(2294)] /device/wlan0 WiFi Device wlan0: StopReconnectTimer
net.log:2018-10-30T13:26:16.280864+05:30 DEBUG shill[1123]: [VERBOSE2:wifi.cc(2945)] /device/wlan0 WiFi Device wlan0: StopRequestingStationInfo
net.log:2018-10-30T13:26:16.280891+05:30 DEBUG shill[1123]: [VERBOSE2:wifi.cc(885)] /device/wlan0 WiFi wlan0 disconnected from (or failed to connect to) service 1
net.log:2018-10-30T13:26:16.280909+05:30 DEBUG shill[1123]: [VERBOSE2:wifi.cc(951)] /device/wlan0 ServiceDisconnected service 1
net.log:2018-10-30T13:26:16.280927+05:30 ERR shill[1123]: [ERROR:wifi.cc(970)] Disconnected due to inability to connect to the service.
net.log:2018-10-30T13:26:16.281071+05:30 INFO shill[1123]: [INFO:service.cc(399)] Service 1: state Online -> Failure
net.log:2018-10-30T13:26:16.281090+05:30 DEBUG shill[1123]: [VERBOSE2:service.cc(957)] /service/1 NoteDisconnectEvent
net.log:2018-10-30T13:26:16.281108+05:30 DEBUG shill[1123]: [VERBOSE2:service.cc(972)] /service/1 Disconnect in transitional power state ignored.
net.log:2018-10-30T13:26:16.281130+05:30 INFO shill[1123]: [INFO:manager.cc(1500)] Service 1 updated; state: Failure failure out-of-range
net.log:2018-10-30T13:26:16.281149+05:30 DEBUG shill[1123]: [VERBOSE2:manager.cc(1504)] manager IsConnected(): 0
net.log:2018-10-30T13:26:16.281165+05:30 DEBUG shill[1123]: [VERBOSE2:manager.cc(1505)] manager IsConnecting(): 0
net.log:2018-10-30T13:26:16.281757+05:30 INFO shill[1123]: [INFO:service.cc(399)] Service 1: state Failure -> Idle
Signal levels for this bssid looks good:
2018-10-30T12:58:10.847020+05:30 Rep ep updated for 1. [SSID=], sig: -46,
2018-10-30T13:00:10.865162+05:30 Rep ep updated for 1. [SSID=], sig: -60,
2018-10-30T13:01:50.887933+05:30 Rep ep updated for 1. [SSID=], sig: -60,
2018-10-30T13:06:30.938635+05:30 Rep ep updated for 1. [SSID=], sig: -41,
2018-10-30T13:26:19.887545+05:30 Rep ep updated for 1. [SSID=], sig: -62,
Comment 1 by marcuskoehler@chromium.org
, Jan 15