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

Issue 694639 link

Starred by 7 users
Status: Archived
Owner:
█ bccheng@chromium.org
Last visit > 30 days ago
Closed: Dec 20
Cc:
snanda@chromium.org
█ kirtika@chromium.org
█ bccheng@chromium.org
█ cernekee@chromium.org
semenzato@chromium.org
cylee@chromium.org
█ benzh@chromium.org
█ jayhlee@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug


Show other hotlists

Hotlists containing this issue:
Chrome-Bug-Cleanup


Sign in to add a comment

Chromebooks show Aw Snap then out-of-credits

Project Member Reported by edoan@chromium.org, Feb 21 2017 
Chrome Version: 55.0.2883.105 / 8872.76.0 (Asus Chromebook Flip / "Minnie")

EDU customer is experiencing random disconnects across HP Chromebook 14 and Asus Chromebook Flip. Students will be using Google Slides, then the browser goes to "Aw snap!" Meanwhile, the Chromebook indicates that it's trying to reconnect to the network.

They were using 802.1x PEAP/MSCHAPv2 username & password, but have switched to WPA2-PSK to aid in troubleshooting. Legacy wireless modes have been disabled on the APs. Most APs are Cisco 3502i. They have updated the Cisco Wireless LAN Controller and all APs to firmware version 8.0.140.

Potentially relevant lines from net.log:

2017-02-16T13:49:31.754762-06:00 INFO shill[1376]: [INFO:service.cc(307)] Service 9 destroyed.
2017-02-16T13:49:31.763686-06:00 INFO shill[1376]: [INFO:wifi.cc(332)] Scan on wlan0 from RequestScan
2017-02-16T13:49:35.667726-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 0. [SSID=cfbisd-wireless], bssid: 00:3a:7d:48:19:6d, signal: -67, security: 802_1x, frequency:  [Reason: info:ieee80211_securitytype]  5765
2017-02-16T13:49:35.722619-06:00 INFO shill[1376]: [INFO:service.cc(301)] wifi service 10 constructed.
2017-02-16T13:49:35.723401-06:00 INFO shill[1376]: [INFO:wifi_service.cc(187)] Constructed WiFi service 10 name: [SSID=cfbisd-staff]
2017-02-16T13:49:35.723458-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 10. [SSID=cfbisd-staff], bssid: 00:c1:64:83:a0:bf, signal: -59, security: 802_1x, frequency:  [Reason: info:ieee80211_securitytype]  5240
2017-02-16T13:49:35.759145-06:00 INFO shill[1376]: [INFO:wifi.cc(393)] ScanDone
2017-02-16T13:49:35.759680-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 0. [SSID=cfbisd-wireless], bssid: 00:3a:7d:48:19:6d, signal: -65, security: 802_1x, frequency:  [Reason: info:ieee80211_securitytype]  5765
2017-02-16T13:49:35.772517-06:00 INFO shill[1376]: [INFO:service.cc(301)] wifi service 11 constructed.
2017-02-16T13:49:35.772895-06:00 INFO shill[1376]: [INFO:wifi_service.cc(187)] Constructed WiFi service 11 name: [SSID=cfbisd-guest]
2017-02-16T13:49:35.773240-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 11. [SSID=cfbisd-guest], bssid: 00:c1:64:83:a0:be, signal: -59, security: rsn, frequency:  [Reason: info:ieee80211_securitytype]  5240
2017-02-16T13:49:35.778057-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 10. [SSID=cfbisd-staff], bssid: 00:c1:64:83:a0:b0, signal: -34, security: 802_1x, frequency:  [Reason: info:ieee80211_securitytype]  2462
2017-02-16T13:49:35.791388-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 11. [SSID=cfbisd-guest], bssid: 00:c1:64:83:a0:b1, signal: -35, security: rsn, frequency:  [Reason: info:ieee80211_securitytype]  2462
2017-02-16T13:49:55.695134-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 0. [SSID=cfbisd-wireless], bssid: 00:3a:7d:48:19:6d, signal: -63, security: 802_1x, frequency:  [Reason: info:ieee80211_securitytype]  5765
2017-02-16T13:50:13.932047-06:00 INFO dhcpcd[4063]: received SIGTERM, stopping
2017-02-16T13:50:13.932092-06:00 INFO dhcpcd[4063]: wlan0: removing interface
2017-02-16T13:50:13.932108-06:00 INFO dhcpcd[4063]: status changed to Release
2017-02-16T13:50:13.932121-06:00 INFO shill[1376]: [INFO:shill_daemon.cc(53)] ShillDaemon received shutdown.
2017-02-16T13:50:13.932134-06:00 INFO shill[1376]: [INFO:manager.cc(1480)] Device wlan0 updated: enabled
2017-02-16T13:50:13.932150-06:00 INFO dhcpcd[4063]: dhcpcd exited
2017-02-16T13:50:13.965731-06:00 INFO shill[1376]: [INFO:service.cc(341)] Disconnecting from service 0: Stop
2017-02-16T13:50:13.975026-06:00 NOTICE wpa_supplicant[697]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:3a:7d:48:19:6d reason=3  [Reason: Warning:Wifi AP disconnected]   [Reason: info:ieee80211_reasoncode]  locally_generated=1
2017-02-16T13:50:13.975995-06:00 INFO shill[1376]: [INFO:dhcp_config.cc(223)] Stopping 4063 (ReleaseIP)
2017-02-16T13:50:13.982324-06:00 NOTICE wpa_supplicant[697]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
2017-02-16T13:50:14.005989-06:00 NOTICE wpa_supplicant[697]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=US
2017-02-16T13:50:14.014468-06:00 INFO shill[1376]: [INFO:service.cc(409)] Service 0: state Online -> Idle
2017-02-16T13:50:14.014515-06:00 INFO shill[1376]: [INFO:manager.cc(1455)] Service 0 updated; state: Idle failure Unknown
2017-02-16T13:50:14.015641-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 0. [SSID=cfbisd-wireless], bssid: 00:c1:64:83:a0:b2, signal: -34, security: 802_1x, frequency:  [Reason: info:ieee80211_securitytype]  2462
2017-02-16T13:50:14.016094-06:00 INFO shill[1376]: [INFO:manager.cc(1455)] Service 0 updated; state: Idle failure Unknown
2017-02-16T13:50:14.016382-06:00 INFO shill[1376]: [INFO:manager.cc(1455)] Service 0 updated; state: Idle failure Unknown
2017-02-16T13:50:14.016802-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 10. [SSID=cfbisd-staff], bssid: f4:0f:1b:52:d7:d0, signal: -51, security: 802_1x, frequency:  [Reason: info:ieee80211_securitytype]  2437
2017-02-16T13:50:14.019442-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 0. [SSID=cfbisd-wireless], bssid: f4:0f:1b:52:d7:dd, signal: -68, security: 802_1x, frequency:  [Reason: info:ieee80211_securitytype]  5300
2017-02-16T13:50:14.019474-06:00 INFO shill[1376]: [INFO:manager.cc(1455)] Service 0 updated; state: Idle failure Unknown
2017-02-16T13:50:14.019488-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 11. [SSID=cfbisd-guest], bssid: f4:0f:1b:52:d7:d1, signal: -51, security: rsn, frequency:  [Reason: info:ieee80211_securitytype]  2437
2017-02-16T13:50:14.019503-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 10. [SSID=cfbisd-staff], bssid: 00:3a:7d:48:19:60, signal: -54, security: 802_1x, frequency:  [Reason: info:ieee80211_securitytype]  2412
2017-02-16T13:50:14.019568-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 11. [SSID=cfbisd-guest], bssid: 00:3a:7d:48:19:61, signal: -54, security: rsn, frequency:  [Reason: info:ieee80211_securitytype]  2412
2017-02-16T13:50:14.019941-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 10. [SSID=cfbisd-staff], bssid: f4:0f:1b:52:d7:df, signal: -67, security: 802_1x, frequency:  [Reason: info:ieee80211_securitytype]  5300
2017-02-16T13:50:14.021045-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 11. [SSID=cfbisd-guest], bssid: f4:0f:1b:52:d7:de, signal: -68, security: rsn, frequency:  [Reason: info:ieee80211_securitytype]  5300
2017-02-16T13:50:14.021493-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 10. [SSID=cfbisd-staff], bssid: f4:0f:1b:70:e7:d0, signal: -76, security: 802_1x, frequency:  [Reason: info:ieee80211_securitytype]  2412
2017-02-16T13:50:14.021934-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 0. [SSID=cfbisd-wireless], bssid: f4:0f:1b:70:e7:d2, signal: -75, security: 802_1x, frequency:  [Reason: info:ieee80211_securitytype]  2412
2017-02-16T13:50:14.022371-06:00 INFO shill[1376]: [INFO:manager.cc(1455)] Service 0 updated; state: Idle failure Unknown
2017-02-16T13:50:14.022393-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 11. [SSID=cfbisd-guest], bssid: f4:0f:1b:70:e7:d1, signal: -75, security: rsn, frequency:  [Reason: info:ieee80211_securitytype]  2412
2017-02-16T13:50:14.024193-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 11. [SSID=cfbisd-guest], bssid: f4:0f:1b:70:df:51, signal: -79, security: rsn, frequency:  [Reason: info:ieee80211_securitytype]  2462
2017-02-16T13:50:14.024564-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 0. [SSID=cfbisd-wireless], bssid: f4:0f:1b:70:de:72, signal: -80, security: 802_1x, frequency:  [Reason: info:ieee80211_securitytype]  2462
2017-02-16T13:50:14.024909-06:00 INFO shill[1376]: [INFO:manager.cc(1455)] Service 0 updated; state: Idle failure Unknown
2017-02-16T13:50:14.024945-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 10. [SSID=cfbisd-staff], bssid: f4:0f:1b:70:df:50, signal: -78, security: 802_1x, frequency:  [Reason: info:ieee80211_securitytype]  2462
2017-02-16T13:50:14.025302-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 10. [SSID=cfbisd-staff], bssid: f4:0f:1b:70:e7:df, signal: -84, security: 802_1x, frequency:  [Reason: info:ieee80211_securitytype]  5220
2017-02-16T13:50:14.025752-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 11. [SSID=cfbisd-guest], bssid: f4:0f:1b:70:de:71, signal: -80, security: rsn, frequency:  [Reason: info:ieee80211_securitytype]  2462
2017-02-16T13:50:14.026034-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 10. [SSID=cfbisd-staff], bssid: 00:3a:7d:3f:89:5f, signal: -85, security: 802_1x, frequency:  [Reason: info:ieee80211_securitytype]  5260
2017-02-16T13:50:14.026487-06:00 INFO shill[1376]: [INFO:manager.cc(1455)] Service 0 updated; state: Idle failure Unknown
2017-02-16T13:50:14.026531-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 0. [SSID=cfbisd-wireless], bssid: f4:0f:1b:6a:d7:92, signal: -83, security: 802_1x, frequency:  [Reason: info:ieee80211_securitytype]  2462
2017-02-16T13:50:14.026815-06:00 INFO shill[1376]: [INFO:manager.cc(1455)] Service 0 updated; state: Idle failure Unknown
2017-02-16T13:50:14.026855-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 11. [SSID=cfbisd-guest], bssid: f4:0f:1b:6a:d7:91, signal: -82, security: rsn, frequency:  [Reason: info:ieee80211_securitytype]  2462
2017-02-16T13:50:14.028293-06:00 INFO shill[1376]: [INFO:service.cc(307)] Service 10 destroyed.
2017-02-16T13:50:14.028686-06:00 INFO shill[1376]: [INFO:manager.cc(1455)] Service 0 updated; state: Idle failure Unknown
2017-02-16T13:50:14.029857-06:00 INFO shill[1376]: [INFO:service.cc(307)] Service 11 destroyed.
2017-02-16T13:50:14.034129-06:00 ERR shill[1376]: [ERROR:object_proxy.cc(582)] Failed to call method: fi.w1.wpa_supplicant1.Interface.Disconnect: object_path= /fi/w1/wpa_supplicant1/Interfaces/1: fi.w1.wpa_supplicant1.NotConnected: This interface is not connected
2017-02-16T13:50:14.034178-06:00 ERR shill[1376]: [ERROR:dbus_method_invoker.h(111)] CallMethodAndBlockWithTimeout(...): Domain=dbus, Code=fi.w1.wpa_supplicant1.NotConnected, Message=This interface is not connected
2017-02-16T13:50:14.034196-06:00 ERR shill[1376]: [ERROR:chromeos_supplicant_interface_proxy.cc(198)] Failed to disconnect: fi.w1.wpa_supplicant1.NotConnected This interface is not connected
2017-02-16T13:50:14.035074-06:00 INFO shill[1376]: [INFO:manager.cc(1455)] Service 0 updated; state: Idle failure Unknown
2017-02-16T13:50:14.125241-06:00 NOTICE wpa_supplicant[697]: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
2017-02-16T13:50:14.173953-06:00 ERR wpa_supplicant[697]: rmdir[ctrl_interface=/var/run/wpa_supplicant]: Permission denied
2017-02-16T13:50:14.184069-06:00 INFO shill[1376]: [INFO:modem_manager.cc(120)] Stop watching modem manager service: org.chromium.ModemManager
2017-02-16T13:50:14.184125-06:00 INFO shill[1376]: [INFO:modem_manager_1.cc(67)] Stop watching modem manager service: org.freedesktop.ModemManager1
2017-02-16T13:50:14.184138-06:00 INFO shill[1376]: [INFO:device.cc(246)] Device destructed: br0 index 3
2017-02-16T13:50:14.184630-06:00 INFO shill[1376]: [INFO:power_manager.cc(81)] Stop
2017-02-16T13:50:14.184675-06:00 INFO shill[1376]: [INFO:chromeos_power_manager_proxy.cc(223)] UnregisterSuspendDelayInternal(71827457, dark=false)
2017-02-16T13:50:14.185500-06:00 INFO shill[1376]: [INFO:chromeos_power_manager_proxy.cc(223)] UnregisterSuspendDelayInternal(71860225, dark=true)
2017-02-16T13:50:14.186630-06:00 INFO shill[1376]: [INFO:crypto_util_proxy.cc(223)] CleanupShim
2017-02-16T13:50:14.186914-06:00 INFO shill[1376]: [INFO:service.cc(307)] Service 0 destroyed.
2017-02-16T13:50:14.187187-06:00 INFO shill[1376]: [INFO:device.cc(246)] Device destructed: wlan0 index 2
2017-02-16T13:50:14.187403-06:00 INFO shill[1376]: [INFO:service.cc(307)] Service 1 destroyed.
2017-02-16T13:50:14.203991-06:00 INFO shill[1376]: [INFO:shill_main.cc(255)] Process exiting.
2017-02-17T08:33:35.622191-06:00 NOTICE wpa_supplicant[694]: Successfully initialized wpa_supplicant
2017-02-17T08:33:36.787974-06:00 INFO shill[1373]: [INFO:manager.cc(261)] Manager started.
2017-02-17T08:33:36.789044-06:00 INFO shill[1373]: [INFO:chromeos_power_manager_proxy.cc(352)] OnSignalConnected interface: org.chromium.PowerManager signal: SuspendImminentsuccess: 1
2017-02-17T08:33:36.789447-06:00 INFO shill[1373]: [INFO:chromeos_power_manager_proxy.cc(352)] OnSignalConnected interface: org.chromium.PowerManager signal: SuspendDonesuccess: 1
2017-02-17T08:33:36.789815-06:00 INFO shill[1373]: [INFO:chromeos_power_manager_proxy.cc(352)] OnSignalConnected interface: org.chromium.PowerManager signal: DarkSuspendImminentsuccess: 1
2017-02-17T08:33:36.811698-06:00 INFO shill[1373]: [INFO:service.cc(301)] wifi service 0 constructed.
2017-02-17T08:33:36.811743-06:00 INFO shill[1373]: [INFO:wifi_service.cc(187)] Constructed WiFi service 0 name: [SSID=cfbisd-wireless]
2017-02-17T08:33:36.812892-06:00 INFO shill[1373]: [INFO:manager.cc(510)] PushProfileInternal finished; 1 profile(s) now present.
2017-02-17T08:33:36.813524-06:00 INFO shill[1373]: [INFO:modem_manager.cc(107)] Start watching modem manager service: org.chromium.ModemManager
2017-02-17T08:33:36.814599-06:00 INFO shill[1373]: [INFO:modem_manager_1.cc(50)] Start watching modem manager service: org.freedesktop.ModemManager1
2017-02-17T08:33:36.816035-06:00 INFO shill[1373]: [INFO:service.cc(301)] etherneteap service 1 constructed.
2017-02-17T08:33:36.817570-06:00 INFO shill[1373]: [INFO:device_info.cc(1277)] Creating WiFi device for station mode interface wlan0 at interface index 2
2017-02-17T08:33:36.817823-06:00 INFO shill[1373]: [INFO:device.cc(241)] Device created: wlan0 index 2
2017-02-17T08:33:36.820946-06:00 INFO shill[1373]: [INFO:manager.cc(1223)] Device wlan0 registered.
2017-02-17T08:33:36.821766-06:00 INFO shill[1373]: [INFO:manager.cc(1480)] Device wlan0 updated: enabled
2017-02-17T08:33:36.833073-06:00 INFO shill[1373]: [INFO:wifi.cc(2266)] wlan0: enabled supplicant: absent proxy: null
2017-02-17T08:33:36.836151-06:00 INFO shill[1373]: [INFO:manager.cc(1699)] Default physical service: 0 (not connected)
2017-02-17T08:33:36.836482-06:00 INFO shill[1373]: [INFO:service.cc(323)] Suppressed autoconnect to service 0 (no endpoints)
2017-02-17T08:33:36.837930-06:00 INFO shill[1373]: [INFO:power_manager.cc(161)] OnPowerManagerAppeared
2017-02-17T08:33:36.838217-06:00 INFO shill[1373]: [INFO:chromeos_power_manager_proxy.cc(185)] RegisterSuspendDelayInternal(19500, dark=false)
2017-02-17T08:33:36.839408-06:00 INFO shill[1373]: [INFO:chromeos_power_manager_proxy.cc(185)] RegisterSuspendDelayInternal(19500, dark=true)
2017-02-17T08:33:36.846633-06:00 INFO shill[1373]: [INFO:wifi.cc(2183)] WPA supplicant appeared.
2017-02-17T08:33:36.846674-06:00 INFO shill[1373]: [INFO:wifi.cc(2266)] wlan0: enabled supplicant: present proxy: null
2017-02-17T08:33:36.861238-06:00 NOTICE wpa_supplicant[694]: nl80211: Could not re-add multicast membership for vendor events: -2 (No such file or directory)
2017-02-17T08:33:36.958367-06:00 NOTICE wpa_supplicant[694]: MPM: Debug Dialog Token initialized 2576894220 (0x9998490c)
2017-02-17T08:33:36.966963-06:00 INFO shill[1373]: [INFO:wifi.cc(332)] Scan on wlan0 from ConnectToSupplicant
2017-02-17T08:33:36.969474-06:00 INFO shill[1373]: [INFO:wifi.cc(1539)] WiFi wlan0 StateChanged shill-unknown -> disconnected
2017-02-17T08:33:37.978772-06:00 ERR shill[1373]: [ERROR:error.cc(146)] [wifi.cc(771)]: This WiFi device does not support MAC address randomization
2017-02-17T08:33:37.978809-06:00 ERR shill[1373]: [ERROR:wifi.cc(771)] SetRandomMACEnabled(...): Domain=dbus, Code=org.chromium.flimflam.Error.NotSupported, Message=This WiFi device does not support MAC address randomization
2017-02-17T08:33:38.050208-06:00 INFO shill[1373]: [INFO:service.cc(301)] ethernet service 2 constructed.
2017-02-17T08:33:38.050264-06:00 INFO shill[1373]: [INFO:service.cc(307)] Service 2 destroyed.
2017-02-17T08:33:38.068116-06:00 INFO shill[1373]: [INFO:service.cc(1487)] Service 0: AutoConnect=1->1
2017-02-17T08:33:38.084847-06:00 INFO shill[1373]: [INFO:service.cc(301)] ethernet service 3 constructed.
2017-02-17T08:33:38.084891-06:00 INFO shill[1373]: [INFO:service.cc(307)] Service 3 destroyed.
2017-02-17T08:33:39.406269-06:00 INFO shill[1373]: [INFO:device.cc(241)] Device created: br0 index 3
2017-02-17T08:33:39.406317-06:00 INFO shill[1373]: [INFO:device_info.cc(618)] IsRenamedBlacklistedDevice: interface index 3 renamed from  to br0
2017-02-17T08:33:39.406331-06:00 INFO shill[1373]: [INFO:device.cc(246)] Device destructed: br0 index 3
2017-02-17T08:33:39.406374-06:00 INFO shill[1373]: [INFO:device.cc(241)] Device created: br0 index 3
2017-02-17T08:33:39.644426-06:00 INFO shill[1373]: [INFO:service.cc(301)] wifi service 4 constructed.
2017-02-17T08:33:39.644470-06:00 INFO shill[1373]: [INFO:wifi_service.cc(187)] Constructed WiFi service 4 name: [SSID=cfbisd-staff]
2017-02-17T08:33:39.644482-06:00 INFO shill[1373]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 4. [SSID=cfbisd-staff], bssid: f4:0f:1b:70:e7:df, signal: -61, security: 802_1x, frequency:  [Reason: info:ieee80211_securitytype]  5220
2017-02-17T08:33:39.644493-06:00 INFO ModemManager[1719]: <info>  ModemManager (version 1.5.0) starting in system bus...
2017-02-17T08:33:39.683036-06:00 INFO shill[1373]: [INFO:wifi.cc(393)] ScanDone
2017-02-17T08:33:39.686866-06:00 INFO shill[1373]: [INFO:service.cc(323)] Suppressed autoconnect to service 0 (no endpoints)
2017-02-17T08:33:39.690822-06:00 INFO shill[1373]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 0. [SSID=cfbisd-wireless], bssid: f4:0f:1b:70:e7:dd, signal: -61, security: 802_1x, frequency:  [Reason: info:ieee80211_securitytype]  5220
2017-02-17T08:33:39.696302-06:00 INFO shill[1373]: [INFO:service.cc(301)] wifi service 5 constructed.
2017-02-17T08:33:39.696899-06:00 INFO shill[1373]: [INFO:wifi_service.cc(187)] Constructed WiFi service 5 name: [SSID=cfbisd-chromebooks]
2017-02-17T08:33:39.697267-06:00 INFO shill[1373]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 5. [SSID=cfbisd-chromebooks], bssid: f4:0f:1b:70:e7:dc, signal: -61, security: rsn, frequency:  [Reason: info:ieee80211_securitytype]  5220
2017-02-17T08:33:39.700141-06:00 INFO shill[1373]: [INFO:service.cc(301)] wifi service 6 constructed.
2017-02-17T08:33:39.700858-06:00 INFO shill[1373]: [INFO:wifi_service.cc(187)] Constructed WiFi service 6 name: [SSID=cfbisd-guest]
2017-02-17T08:33:39.701262-06:00 INFO shill[1373]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 6. [SSID=cfbisd-guest], bssid: f4:0f:1b:70:e7:de, signal: -62, security: rsn, frequency:  [Reason: info:ieee80211_securitytype]  5220
2017-02-17T08:33:39.703815-06:00 INFO shill[1373]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 4. [SSID=cfbisd-staff], bssid: f4:0f:1b:70:e7:d0, signal: -49, security: 802_1x, frequency:  [Reason: info:ieee80211_securitytype]  2412
2017-02-17T08:33:39.706412-06:00 INFO shill[1373]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 6. [SSID=cfbisd-guest], bssid: f4:0f:1b:70:e7:d1, signal: -49, security: rsn, frequency:  [Reason: info:ieee80211_securitytype]  2412
2017-02-17T08:33:39.757416-06:00 INFO shill[1373]: [INFO:service.cc(301)] wifi service 7 constructed.
2017-02-17T08:33:39.757994-06:00 INFO shill[1373]: [INFO:wifi_service.cc(187)] Constructed WiFi service 7 name: [SSID=ATT4BzD3db]
2017-02-17T08:33:39.758490-06:00 INFO shill[1373]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 7. [SSID=ATT4BzD3db], bssid: dc:7f:a4:ba:23:16, signal: -89, security: rsn, frequency:  [Reason: info:ieee80211_securitytype]  2442
2017-02-17T08:33:39.761455-06:00 INFO shill[1373]: [INFO:wifi.cc(1539)] WiFi wlan0 StateChanged disconnected -> inactive
2017-02-17T08:33:39.764731-06:00 INFO shill[1373]: [INFO:service.cc(314)] Auto-connecting to service 0
2017-02-17T08:33:39.765063-06:00 INFO shill[1373]: [INFO:service.cc(330)] Connect to service 0: AutoConnect
2017-02-17T08:33:39.765261-06:00 WARNING shill[1373]: [WARNING:eap_credentials.cc(130)] PopulateSupplicantProperties: No certificate authorities are configured. Server certificates will be accepted unconditionally.
2017-02-17T08:33:39.765463-06:00 INFO shill[1373]: [INFO:wifi.cc(684)] Background scan: simple:30:-50:3601
2017-02-17T08:33:39.768876-06:00 NOTICE wpa_supplicant[694]: wlan0: Trying to associate with SSID 'cfbisd-wireless'
2017-02-17T08:33:39.768916-06:00 INFO shill[1373]: [INFO:service.cc(409)] Service 0: state Idle -> Associating
2017-02-17T08:33:39.768928-06:00 INFO shill[1373]: [INFO:manager.cc(1455)] Service 0 updated; state: Associating failure Unknown
2017-02-17T08:33:39.775754-06:00 INFO shill[1373]: [INFO:service.cc(323)] Suppressed autoconnect to service 0 (connecting)
2017-02-17T08:33:39.778043-06:00 INFO shill[1373]: [INFO:wifi.cc(1539)] WiFi wlan0 StateChanged inactive -> associating
2017-02-17T08:33:39.779339-06:00 INFO shill[1373]: [INFO:chromeos_dbus_objectmanager_proxy.cc(107)] OnServiceOwnerChanged old:  new: :1.29
2017-02-17T08:33:39.779423-06:00 INFO shill[1373]: [INFO:chromeos_dbus_objectmanager_proxy.cc(93)] OnServiceAvailable: 1
2017-02-17T08:33:39.779495-06:00 INFO shill[1373]: [INFO:chromeos_dbus_objectmanager_proxy.cc(93)] OnServiceAvailable: 1
2017-02-17T08:33:39.779583-06:00 INFO shill[1373]: [INFO:modem_manager.cc(59)] Modem manager org.freedesktop.ModemManager1 appeared.
2017-02-17T08:33:39.779702-06:00 INFO shill[1373]: [INFO:modem_manager.cc(59)] Modem manager org.freedesktop.ModemManager1 appeared.
2017-02-17T08:33:41.890279-06:00 NOTICE wpa_supplicant[694]: wlan0: Associated with f4:0f:1b:70:e7:dd
2017-02-17T08:33:41.900657-06:00 NOTICE wpa_supplicant[694]: wlan0: CTRL-EVENT-EAP-STARTED EAP authentication started
2017-02-17T08:33:41.900705-06:00 ERR shill[1373]: [ERROR:wifi.cc(1349)] WiFi wlan0 EAPEventTask with no current service.
2017-02-17T08:33:41.902669-06:00 INFO shill[1373]: [INFO:wifi.cc(1539)] WiFi wlan0 StateChanged associating -> associated
2017-02-17T08:33:41.908286-06:00 NOTICE wpa_supplicant[694]: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=25
2017-02-17T08:33:41.908358-06:00 NOTICE wpa_supplicant[694]: wlan0: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 25 (PEAP) selected
2017-02-17T08:33:41.909139-06:00 INFO shill[1373]: [INFO:supplicant_eap_state_handler.cc(35)] EAP: accepted method PEAP
2017-02-17T08:33:41.916246-06:00 NOTICE wpa_supplicant[694]: wlan0: CTRL-EVENT-EAP-PEER-CERT depth=0 subject='/CN=ACSSRV1' hash=1e8408d11d9875d6c0d2185000a1cfadab5f5ef914589564ad7c0724e3ec0d9f
2017-02-17T08:33:41.917305-06:00 INFO shill[1373]: [INFO:service.cc(854)] Received certification for /CN=ACSSRV1 at depth 0
2017-02-17T08:33:41.917346-06:00 INFO shill[1373]: [INFO:supplicant_eap_state_handler.cc(60)] EAP: Completed remote certificate verification.
2017-02-17T08:33:41.923346-06:00 NOTICE wpa_supplicant[694]: wlan0: CTRL-EVENT-EAP-PEER-CERT depth=0 subject='/CN=ACSSRV1' hash=1e8408d11d9875d6c0d2185000a1cfadab5f5ef914589564ad7c0724e3ec0d9f
2017-02-17T08:33:41.923390-06:00 INFO shill[1373]: [INFO:supplicant_eap_state_handler.cc(60)] EAP: Completed remote certificate verification.
2017-02-17T08:33:41.924881-06:00 NOTICE wpa_supplicant[694]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US
2017-02-17T08:33:41.949243-06:00 NOTICE wpa_supplicant[694]: EAP-MSCHAPV2: Authentication succeeded
2017-02-17T08:33:41.957096-06:00 NOTICE wpa_supplicant[694]: wlan0: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
2017-02-17T08:33:41.958440-06:00 INFO shill[1373]: [INFO:supplicant_eap_state_handler.cc(38)] EAP: Completed authentication successfully.
2017-02-17T08:33:41.964830-06:00 NOTICE wpa_supplicant[694]: wlan0: WPA: Key negotiation completed with f4:0f:1b:70:e7:dd [PTK=CCMP GTK=CCMP]
2017-02-17T08:33:41.964877-06:00 NOTICE wpa_supplicant[694]: wlan0: CTRL-EVENT-CONNECTED - Connection to f4:0f:1b:70:e7:dd completed  [Reason: info:Wifi BSSIDs to which chromebook successfully connected]  [id=0 id_str=]
2017-02-17T08:33:41.966391-06:00 INFO shill[1373]: [INFO:wifi.cc(1539)] WiFi wlan0 StateChanged associated -> completed
2017-02-17T08:33:41.998001-06:00 INFO shill[1373]: [INFO:dhcp_config.cc(216)] Spawned /sbin/dhcpcd with pid: 3962
2017-02-17T08:33:41.998310-06:00 INFO shill[1373]: [INFO:wifi.cc(1594)] wlan0 is up; started L3 configuration.
2017-02-17T08:33:41.998339-06:00 INFO shill[1373]: [INFO:service.cc(409)] Service 0: state Associating -> Configuring
2017-02-17T08:33:41.998352-06:00 INFO shill[1373]: [INFO:manager.cc(1455)] Service 0 updated; state: Configuring failure Unknown
2017-02-17T08:33:41.999965-06:00 INFO shill[1373]: [INFO:service.cc(323)] Suppressed autoconnect to service 0 (connecting)
2017-02-17T08:33:42.016149-06:00 NOTICE dhcpcd[3962]: dhcpcd is running with reduced privileges
2017-02-17T08:33:42.018750-06:00 INFO dhcpcd[3962]: status changed to Init
2017-02-17T08:33:42.022808-06:00 INFO shill[1373]: [INFO:dhcp_config.cc(158)] Init DHCP Proxy: wlan0 at :1.41
2017-02-17T08:33:42.614003-06:00 INFO dhcpcd[3962]: status changed to Reboot
2017-02-17T08:33:42.672636-06:00 INFO dhcpcd[3962]: wlan0: ARP probing 10.48.240.1 (1 of 3), next in 1.5 seconds
2017-02-17T08:33:42.672674-06:00 INFO dhcpcd[3962]: wlan0: rebinding lease of 10.48.240.179
2017-02-17T08:33:42.672964-06:00 INFO dhcpcd[3962]: wlan0: sending REQUEST (xid 0x40b43a87), next in 3.3 seconds
2017-02-17T08:33:44.128730-06:00 INFO dhcpcd[3962]: wlan0: ARP probing 10.48.240.1 (2 of 3), next in 1.5 seconds
2017-02-17T08:33:45.661398-06:00 INFO dhcpcd[3962]: wlan0: ARP probing 10.48.240.1 (3 of 3), next in 2.0 seconds
2017-02-17T08:33:46.021082-06:00 INFO dhcpcd[3962]: wlan0: sending REQUEST (xid 0x40b43a87), next in 8.3 seconds
2017-02-17T08:33:46.038207-06:00 INFO dhcpcd[3962]: wlan0: received ACK with xid 0x40b43a87
2017-02-17T08:33:46.038253-06:00 INFO dhcpcd[3962]: wlan0: acknowledged 10.48.240.179 from 1.1.1.1
2017-02-17T08:33:46.039083-06:00 INFO dhcpcd[3962]: wlan0: ARP probing 10.48.240.1 (1 of 3), next in 1.8 seconds
2017-02-17T08:33:46.039113-06:00 INFO dhcpcd[3962]: status changed to ArpGateway
2017-02-17T08:33:46.102612-06:00 INFO dhcpcd[3962]: wlan0: leased 10.48.240.179 for 86400 seconds
2017-02-17T08:33:46.103797-06:00 INFO dhcpcd[3962]: event REBOOT on interface wlan0
2017-02-17T08:33:46.103840-06:00 INFO dhcpcd[3962]: status changed to Bound
2017-02-17T08:33:46.105298-06:00 INFO shill[1373]: [INFO:dhcpv4_config.cc(127)] Event reason: REBOOT
2017-02-17T08:33:46.105342-06:00 INFO shill[1373]: [INFO:connection.cc(243)] UpdateFromIPConfig: Installing with parameters: local=10.48.240.179 broadcast=10.48.241.255 peer=<unknown> gateway=10.48.240.1
2017-02-17T08:33:46.105420-06:00 INFO shill[1373]: [INFO:service.cc(409)] Service 0: state Configuring -> Connected
2017-02-17T08:33:46.120112-06:00 INFO shill[1373]: [INFO:manager.cc(1455)] Service 0 updated; state: Connected failure Unknown
2017-02-17T08:33:46.132529-06:00 INFO shill[1373]: [INFO:wifi.cc(2349)] Enabling high bitrates.
2017-02-17T08:33:46.142088-06:00 INFO shill[1373]: [INFO:service.cc(409)] Service 0: state Connected -> Online
2017-02-17T08:33:46.142148-06:00 INFO shill[1373]: [INFO:manager.cc(1455)] Service 0 updated; state: Online failure Unknown
2017-02-17T08:33:46.186765-06:00 INFO shill[1373]: [INFO:manager.cc(1703)] Default physical service: 0 (connected)
2017-02-17T08:33:47.236202-06:00 INFO shill[1373]: [INFO:service.cc(301)] ethernet service 8 constructed.
2017-02-17T08:33:47.236250-06:00 INFO shill[1373]: [INFO:service.cc(307)] Service 8 destroyed.
2017-02-17T08:33:47.251580-06:00 INFO shill[1373]: [INFO:service.cc(1487)] Service 0: AutoConnect=1->0
2017-02-17T08:33:47.286997-06:00 INFO shill[1373]: [INFO:service.cc(1487)] Service 5: AutoConnect=0->1
2017-02-17T08:33:47.367283-06:00 INFO shill[1373]: [INFO:wifi.cc(332)] Scan on wlan0 from RequestScan
2017-02-17T08:33:51.301064-06:00 INFO shill[1373]: [INFO:wifi.cc(393)] ScanDone
2017-02-17T08:33:51.302224-06:00 INFO shill[1373]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 0. [SSID=cfbisd-wireless], bssid: f4:0f:1b:70:e7:dd, signal: -60, security: 802_1x, frequency:  [Reason: info:ieee80211_securitytype]  5220
2017-02-17T08:33:51.305224-06:00 INFO shill[1373]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 6. [SSID=cfbisd-guest], bssid: f4:0f:1b:70:e7:d1, signal: -46, security: rsn, frequency:  [Reason: info:ieee80211_securitytype]  2412
2017-02-17T08:33:51.306075-06:00 INFO shill[1373]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 4. [SSID=cfbisd-staff], bssid: f4:0f:1b:70:e7:d0, signal: -47, security: 802_1x, frequency:  [Reason: info:ieee80211_securitytype]  2412
2017-02-17T08:33:51.351274-06:00 INFO shill[1373]: [INFO:service.cc(330)] Connect to service 5: ConnectToBestServicesTask
2017-02-17T08:33:51.351321-06:00 INFO shill[1373]: [INFO:wifi.cc(684)] Background scan: simple:30:-50:3601
2017-02-17T08:33:51.376120-06:00 NOTICE wpa_supplicant[694]: wlan0: CTRL-EVENT-DISCONNECTED bssid=f4:0f:1b:70:e7:dd reason=3  [Reason: Warning:Wifi AP disconnected]   [Reason: info:ieee80211_reasoncode]  locally_generated=1
2017-02-17T08:33:51.379254-06:00 INFO shill[1373]: [INFO:service.cc(409)] Service 5: state Idle -> Associating
2017-02-17T08:33:51.379301-06:00 INFO shill[1373]: [INFO:manager.cc(1455)] Service 5 updated; state: Associating failure Unknown
2017-02-17T08:33:51.379314-06:00 NOTICE wpa_supplicant[694]: wlan0: Trying to associate with SSID 'cfbisd-chromebooks'
2017-02-17T08:33:51.379325-06:00 INFO shill[1373]: [INFO:service.cc(409)] Service 0: state Online -> Idle
2017-02-17T08:33:51.379335-06:00 INFO shill[1373]: [INFO:manager.cc(1455)] Service 0 updated; state: Idle failure Unknown
2017-02-17T08:33:51.386752-06:00 INFO shill[1373]: [INFO:manager.cc(1699)] Default physical service: 5 (not connected)
2017-02-17T08:33:51.389602-06:00 NOTICE wpa_supplicant[694]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
2017-02-17T08:33:51.390796-06:00 INFO shill[1373]: [INFO:service.cc(323)] Suppressed autoconnect to service 5 (connecting)
2017-02-17T08:33:51.391417-06:00 INFO shill[1373]: [INFO:wifi.cc(862)] WiFi wlan0 supplicant updated DisconnectReason to -3
2017-02-17T08:33:51.398991-06:00 INFO shill[1373]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 0. [SSID=cfbisd-wireless], bssid: 00:c1:64:83:a0:b2, signal: -54, security: 802_1x, frequency:  [Reason: info:ieee80211_securitytype]  2462
2017-02-17T08:33:51.399843-06:00 INFO shill[1373]: [INFO:wifi.cc(1539)] WiFi wlan0 StateChanged completed -> disconnected
2017-02-17T08:33:51.404187-06:00 INFO shill[1373]: [INFO:wifi.cc(1539)] WiFi wlan0 StateChanged disconnected -> associating
2017-02-17T08:33:51.434285-06:00 NOTICE wpa_supplicant[694]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=US
2017-02-17T08:33:54.161375-06:00 NOTICE wpa_supplicant[694]: wlan0: Associated with f4:0f:1b:70:e7:dc
2017-02-17T08:33:54.174260-06:00 NOTICE wpa_supplicant[694]: wlan0: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully (based on lower layer success)
2017-02-17T08:33:54.183226-06:00 NOTICE wpa_supplicant[694]: wlan0: WPA: Key negotiation completed with f4:0f:1b:70:e7:dc [PTK=CCMP GTK=CCMP]
2017-02-17T08:33:54.183396-06:00 NOTICE wpa_supplicant[694]: wlan0: CTRL-EVENT-CONNECTED - Connection to f4:0f:1b:70:e7:dc completed  [Reason: info:Wifi BSSIDs to which chromebook successfully connected]  [id=1 id_str=]
2017-02-17T08:33:54.185929-06:00 INFO shill[1373]: [INFO:wifi.cc(1539)] WiFi wlan0 StateChanged associating -> 4way_handshake
2017-02-17T08:33:54.185978-06:00 INFO shill[1373]: [INFO:wifi.cc(1539)] WiFi wlan0 StateChanged 4way_handshake -> completed
2017-02-17T08:33:54.200855-06:00 INFO shill[1373]: [INFO:dhcp_config.cc(223)] Stopping 3962 (ReleaseIP)
2017-02-17T08:33:54.200910-06:00 INFO dhcpcd[3962]: received SIGTERM, stopping
2017-02-17T08:33:54.200930-06:00 INFO dhcpcd[3962]: wlan0: removing interface
2017-02-17T08:33:54.200946-06:00 INFO dhcpcd[3962]: status changed to Release
2017-02-17T08:33:54.202028-06:00 INFO dhcpcd[3962]: dhcpcd exited
2017-02-17T08:33:54.211927-06:00 INFO shill[1373]: [INFO:dhcp_config.cc(216)] Spawned /sbin/dhcpcd with pid: 10083
2017-02-17T08:33:54.211976-06:00 INFO shill[1373]: [INFO:wifi.cc(1594)] wlan0 is up; started L3 configuration.
2017-02-17T08:33:54.211994-06:00 INFO shill[1373]: [INFO:service.cc(409)] Service 5: state Associating -> Configuring
2017-02-17T08:33:54.212009-06:00 INFO shill[1373]: [INFO:manager.cc(1455)] Service 5 updated; state: Configuring failure Unknown
2017-02-17T08:33:54.212026-06:00 NOTICE wpa_supplicant[694]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US
2017-02-17T08:33:54.212040-06:00 INFO shill[1373]: [INFO:service.cc(323)] Suppressed autoconnect to service 5 (connecting)
2017-02-17T08:33:54.214006-06:00 NOTICE dhcpcd[10083]: dhcpcd is running with reduced privileges
2017-02-17T08:33:54.216918-06:00 INFO dhcpcd[10083]: status changed to Init
2017-02-17T08:33:54.217480-06:00 INFO shill[1373]: [INFO:dhcp_config.cc(158)] Init DHCP Proxy: wlan0 at :1.43
2017-02-17T08:33:54.933937-06:00 INFO dhcpcd[10083]: status changed to Discover
2017-02-17T08:33:54.934106-06:00 INFO dhcpcd[10083]: wlan0: soliciting a DHCP lease
2017-02-17T08:33:54.934151-06:00 INFO dhcpcd[10083]: wlan0: sending DISCOVER (xid 0x7a5c806), next in 4.5 seconds
2017-02-17T08:33:59.483207-06:00 INFO dhcpcd[10083]: wlan0: sending DISCOVER (xid 0x7a5c806), next in 8.7 seconds
2017-02-17T08:33:59.495518-06:00 INFO dhcpcd[10083]: wlan0: received OFFER with xid 0x7a5c806
2017-02-17T08:33:59.495582-06:00 INFO dhcpcd[10083]: wlan0: offered 10.48.240.179 from 1.1.1.1
2017-02-17T08:33:59.495613-06:00 INFO dhcpcd[10083]: wlan0: requesting lease of 10.48.240.179
2017-02-17T08:33:59.495637-06:00 INFO dhcpcd[10083]: status changed to Request
2017-02-17T08:33:59.495661-06:00 INFO dhcpcd[10083]: wlan0: sending REQUEST (xid 0x7a5c806), next in 3.0 seconds
2017-02-17T08:33:59.499267-06:00 INFO dhcpcd[10083]: wlan0: received ACK with xid 0x7a5c806
2017-02-17T08:33:59.499370-06:00 INFO dhcpcd[10083]: wlan0: acknowledged 10.48.240.179 from 1.1.1.1
2017-02-17T08:33:59.542982-06:00 INFO dhcpcd[10083]: wlan0: ARP probing 10.48.240.1 (1 of 3), next in 1.9 seconds
2017-02-17T08:33:59.543056-06:00 INFO dhcpcd[10083]: status changed to ArpGateway
2017-02-17T08:33:59.582735-06:00 INFO dhcpcd[10083]: wlan0: leased 10.48.240.179 for 86400 seconds
2017-02-17T08:33:59.583116-06:00 INFO dhcpcd[10083]: event BOUND on interface wlan  [Reason: info:DHCP completed] 0
debug-logs_20170217-124557.tgz
1.2 MB Download

Comment 1 by yoshi@chromium.org, Feb 21 2017

Owner: kirtika@chromium.org
@kirtika
Do you have cycles to look into this?

Comment 2 by cernekee@chromium.org, Feb 21 2017 

> Students will be using Google Slides, then the browser goes to "Aw snap!" Meanwhile, the Chromebook indicates that it's trying to reconnect to the network.

"Aw snap" is a renderer crash.  It would be surprising if that was related to networking.  Do these two events always happen at the same exact time, and is there a repro case?  It might be useful to pull the info on this crash from chrome://crashes .

In the net.log I saw a couple of voluntary disconnects, suspend/resume, etc.  Could you please confirm the exact HH:MM:SS time when the problem was seen?

Comment 3 by kirtika@google.com, Feb 22 2017 

Digging more, but unless I am misunderstanding, this does not seem like a wifi issue. 
In the two log files that I saw, debugd gets killed (why?) and terminates child processes, including shill (our connection manager). This would also explain why their connection loss coincides with the tab crash.
The "ShillDaemon received shutdown" line was added precisely to catch these cases. 

From the syslog,


// Problem begins here. 
syslog2017-02-16T13:49:29.703394-06:00 WARNING kernel: [ 2430.818821] init: debugd main process (1142) killed by TERM signal
syslog2017-02-16T13:49:29.756365-06:00 INFO chapsd[1131]: Token at /home/root/da87675cf90ccafa79978f9ed707cb39eaa8779d/chaps has been removed from slot 1
syslog2017-02-16T13:49:29.788540-06:00 INFO chapsd[1131]: Unloaded keys for slot 1
syslog2017-02-16T13:49:29.793451-06:00 INFO kernel: [ 2430.912678] tpm_i2c_infineon 1-0020: command 0xba (size 18) returned code 0x0
syslog2017-02-16T13:49:29.833391-06:00 NOTICE kernel: [ 2430.950828] audit: type=1400 audit(1487274569.820:256): avc:  denied  { getattr } for  pid=12318 comm="lsof" path="/dev/log" dev="devtmpfs" ino=5296 scontext=u:r:chromeos:s0 tcontext=u:object_r:device:s0 tclass=sock_file permissive=1
syslog2017-02-16T13:49:29.833441-06:00 NOTICE kernel: [ 2430.951712] audit: type=1400 audit(1487274569.820:257): avc:  denied  { read } for  pid=12318 comm="lsof" name="fd" dev="proc" ino=54464 scontext=u:r:chromeos:s0 tcontext=u:r:kernel:s0 tclass=dir permissive=1
syslog2017-02-16T13:49:29.833449-06:00 NOTICE kernel: [ 2430.951749] audit: type=1400 audit(1487274569.820:258): avc:  denied  { open } for  pid=12318 comm="lsof" path="/proc/2/fd" dev="proc" ino=54464 scontext=u:r:chromeos:s0 tcontext=u:r:kernel:s0 tclass=dir permissive=1
syslog2017-02-16T13:49:29.853414-06:00 NOTICE kernel: [ 2430.974148] audit: type=1400 audit(1487274569.840:259): avc:  denied  { getattr } for  pid=12318 comm="lsof" path="socket:[5591]" dev="sockfs" ino=5591 scontext=u:r:chromeos:s0 tcontext=u:r:chromeos:s0 tclass=packet_socket permissive=1
syslog2017-02-16T13:49:30.361382-06:00 WARNING chapsd[1131]: Unload Token event received for unknown path: /home/root/da87675cf90ccafa79978f9ed707cb39eaa8779d/chaps
syslog2017-02-16T13:49:30.363374-06:00 NOTICE kernel: [ 2431.486845] audit: type=1400 audit(1487274570.350:260): avc:  denied  { write } for  pid=1167 comm="cryptohomed" scontext=u:r:chromeos:s0 tcontext=u:r:kernel:s0 tclass=key permissive=1
syslog2017-02-16T13:49:30.472059-06:00 INFO session_manager[12344]: 

// This should kill child processes. 
[INFO:session_manager_main.cc(188)] Will wait 3s for graceful browser exit.
syslog2017-02-16T13:49:30.478994-06:00 INFO session_manager[12344]: [INFO:session_manager_service.cc(165)] SessionManagerService starting


Soon after, in the netlog,


2017-02-16T13:49:55.695134-06:00 INFO shill[1376]: [INFO:wifi_service.cc(787)] Representative endpoint updated for service 0. [SSID=cfbisd-wireless], bssid: 00:3a:7d:48:19:6d, signal: -63, security: 802_1x, frequency: 5765
netlog2017-02-16T13:50:13.932047-06:00 INFO dhcpcd[4063]: received SIGTERM, stopping
netlog2017-02-16T13:50:13.932092-06:00 INFO dhcpcd[4063]: wlan0: removing interface
netlog2017-02-16T13:50:13.932108-06:00 INFO dhcpcd[4063]: status changed to Release

// Shill told to shut down. 

netlog2017-02-16T13:50:13.932121-06:00 INFO shill[1376]: [INFO:shill_daemon.cc(53)] ShillDaemon received shutdown.
netlog2017-02-16T13:50:13.932134-06:00 INFO shill[1376]: [INFO:manager.cc(1480)] Device wlan0 updated: enabled


The locally generated disconnects are (I think) because shill is cleanly shutting off.

Comment 4 by kirtika@chromium.org, Feb 22 2017 

As discussed offline, please email me the CLIENT_ID (from chrome://system) of the machine the logs were shared from so that I can look up the crashes (there are none uploaded as per the logs). 
Also, worth noting that HP Chromebook 14 (is this a reference to falco?) and minnie have different architectures and different wifi chips. It is very unlikely that the root cause will be the same (unless is shill), so it would be good to have two sets of each - logs, a CLIENT_ID to debug. 
Thanks!

Comment 5 by kirtika@chromium.org, Feb 22 2017 

These are the log lines from debugd before it gets killed: 

2017-02-17T09:45:12.298675-06:00 WARNING debugd[1132]: Failed to open procfs entry of process 10843
2017-02-17T09:45:12.298714-06:00 WARNING debugd[1132]: Failed to open uid map file /proc/10843/uid_map for process 10843
2017-02-17T09:45:12.298725-06:00 WARNING debugd[1132]: Invalid pid 10843, operation not allowed

Can we have someone with knowledge of how OOM handling / OOM killing works to take a look at this? 

Also, please file feedback using alt-shift-i (if you have already done so, please share the email ID the feedback was filed from or some tags used in the feedback so we can search). The feedback reports contain details about the wifi environment and also about memory usage that are not present in the debug-log*tgz files, so will be helpful. Thanks!

Comment 6 by kirtika@chromium.org, Feb 22 2017

Cc: cylee@chromium.org bccheng@chromium.org
Owner: bccheng@chromium.org
+ Ben Cheng, CY Lee
Hi Chrome OS Performance team,
This is a field report where school devices are losing connectivity. I think its because the connection manager is being shut down due to global-shutdown (debugd gets TERM signal). The log lines I pointed out in #c5 are coming from debugd's
oom_adj_tool.cc right before it gets killed. PTAL?

Comment 7 by cylee@google.com, Feb 22 2017 

If a process is killed by OOM killer, you should be able to fine lines like

Jun  4 07:41:59 plumbr kernel: [70667120.897649] Out of memory: Kill process 29957 (java) score 366 or sacrifice child
Jun  4 07:41:59 plumbr kernel: [70667120.897701] Killed process 29957 (java) total-vm:2532680kB, anon-rss:1416508kB, file-rss:0kB

in dmesg (and the log file "message").
I couldn't find similar messages in the log file attached.

#5: The error occurs when Chrome wants to set oom_score_adj for a Chrome tab or an android app, but the process in request was not present (killed?). 

Looks somebody is killing processes, but I couldn't find corresponding OOM killer log in kernel log. Also is there anyway we know the memory status at that time ? (e.g., free memory ? swap free ? )

Comment 8 by cernekee@chromium.org, Feb 22 2017 

One thing I found when reading up on "Aw snap" is that it indicates a renderer crash (with backtrace).  If a renderer process dies through other means, such as SIGKILL via OOM, the user should see "He's dead, Jim" instead.

Comment 9 by semenzato@chromium.org, Feb 22 2017 

#8 that used to be the case, and should still be, but I haven't seen any "he's dead, Jim" in a long time now and I wonder if that code has bit-rotted.  I don't know of any autotest for it.

#5 what suggested looking into OOM kills?  Also, the debugd warnings seem due to a probably unavoidable race when debugd tries to inspect the procfs of a process that's exiting.

Comment 10 by cernekee@chromium.org, Feb 22 2017 

> I haven't seen any "he's dead, Jim" in a long time now

Hmm, good point.  I tried to verify this empirically by opening a webpage, using shift-esc to get the PID, and running `kill -KILL <PID>`.  But this gave me an "Aw snap."  `kill -TERM` produced a similar result.

`kill -BUS` or `kill -SEGV` had no effect at all (which surprised me).

This is on Chrome for Linux, 56.0.2924.87.

Comment 11 by kirtika@chromium.org, Feb 22 2017 

Re #c9: Regarding what suggested looking into OOM kills- I wasn't saying OOM kills but a particular oom related file in debugd (oom_adj_tool.cc) based on the following log lines: 

2017-02-17T09:45:12.298675-06:00 WARNING debugd[1132]: Failed to open procfs entry of process 10843
2017-02-17T09:45:12.298714-06:00 WARNING debugd[1132]: Failed to open uid map file /proc/10843/uid_map for process 10843
2017-02-17T09:45:12.298725-06:00 WARNING debugd[1132]: Invalid pid 10843, operation not allowed


Re #c7: once we have the feedback reports (filed with alt-shift-i), those have cpu/memory/swap usage.

Comment 12 by semenzato@chromium.org, Feb 22 2017 

#11 thanks I get it now.

That clue may not tell us much.  OOM score adjusting is done at every tab switch, to make the OOM killer save the foreground tab for last.  I am guessing that debugd is used as a proxy for Chrome.  It's possible that a tab crashed or was closed in the middle of adjusting the scores.  I am also guessing that the race was understood, thus we're just outputting a warning when this happens.

Comment 13 by cylee@google.com, Feb 22 2017 

Thanks to Luigi for the explanation #12. It's all correct. The debugd error message itself doesn't imply it's running out memory. We need more info to know why the renderer processes are killed.

Comment 14 by edoan@chromium.org, Feb 23 2017 

It's an Aw Snap!

Got a feedback report: https://feedback.corp.google.com/product/208/neutron?&lView=rd&lRSort=1&lRFilter=1&lReportSearch=edoan%40google.com&lROrder=2&lReport=53865907972
IMG_1494.JPG
70.5 KB View Download
IMG_1495.JPG
71.3 KB View Download

Comment 15 by bccheng@chromium.org, Feb 24 2017 

Content is pretty thin in the feedback as up time is only 50 minutes. Perhaps it has just rebooted and we will wait for more feedbacks to hopefully have more clues.

Comment 16 by edoan@chromium.org, Feb 24 2017 

I have 6 crash reports / feedback reports available here: https://docs.google.com/a/google.com/document/d/1FSJMBUAgAtSIewaGadvJkt_jgfIkHhFnnBuzuDGm9hY/edit?usp=sharing

Also see attached debug logs with filenames corresponding to the asset ID listed in the document.
lavcsu041.tgz
1.4 MB Download
lavcsu046.tgz
1.1 MB Download
lavcsu047.tgz
1.2 MB Download
lavcsu033.tgz
1.5 MB Download

Comment 17 by kirtika@chromium.org, Feb 24 2017 

1. +benchan@ as your all crashes are p2pserver : https://bugs.chromium.org/p/chromium/issues/detail?id=634277
which he is looking at. These should not affect anything other than p2pserver, so IIUC, they dont explain your symptoms.

2. Can you clarify what the more severe issue is? Is it reconnection as mentioned in the bug description ("the Chromebook indicates that it's trying to reconnect to the network.") or is it the wifi slowness (the out-of-credits messages in the logs). Each will lead to different triaging.
I ignored the "out-of-credits" earlier because it doesn't explain your seeing reconnection in the UI - a larger chrome crash bringing down shill explains that. There is no evidence in the logs that we are reconnecting due to slow/unresponsive wifi.

Comment 18 by edoan@chromium.org, Feb 27 2017

Summary: Chromebooks show Aw Snap then out-of-credits (was: Chromebooks disconnecting from Wi-Fi intermittently)
@kirtika - I think we're chasing an "Aw snap" in the UI which correlates to out-of-credits in net.log. Customer has sent me several more logs including the net-internals Wi-Fi logging.
lavcsu041-verbose-Archive.zip
2.7 MB Download
lavcsu033-verbose-Archive.zip
2.7 MB Download
lavcsu046-verbose-Archive.zip
2.0 MB Download

Comment 19 by edoan@chromium.org, Feb 27 2017 

Customer tells me that they often see "Aw snap" or Google Slides say ""Reconnecting...". Their Wi-Fi is WPA2-PSK, 5 GHz only. out-of-credits message in logs seems to happen at the same time as "Aw snap" or webpage indicating with missing elements on the webpage. 

Since there might be a link to p2pserver crashing, I suggested they turn off mDNS and enable AP client isolation to disable P2P updates.

Comment 20 by edoan@chromium.org, Mar 7 2017 

I suggested to the customer to disable multicast DNS and enable AP client isolation, so as to stop P2P update from running. That seems to have resolved the out-of-credits issue on the Chromebooks. Customer also indicates that multicast queues on their AP's are also no longer congested.

Comment 21 by benhenry@chromium.org, Aug 1

Status: Assigned (was: Untriaged)

Comment 22 by sylcat@google.com, Dec 14 

Hello!
This bug is receiving this notice because there has been no acknowledgment of its existence in quite a bit of time
- If you are currently working on this bug, please provide an update.
- If you are currently affected by this bug, please update with your current symptoms and relevant logs.

If there has been no updates provided by EOD Wednesday, 12/19/18 (5pm EST), this bug will be archived and can be re-opened at any time deemed necessary.

Thank you!

Comment 23 by sylcat@google.com, Dec 20

Status: Archived (was: Assigned)
Due to lack of action this bug has been Archived. If work is still being done on this issue or you are still experiencing this issue please feel free to re-open with the appropriate information.
►

Sign in to add a comment