OS: Chrome OS R61/62

We are seeing an increasing number of locally generated (on the Chrome OS client side) wifi deauthentications, citing "inactivity" i.e. Chrome OS client couldn't hear the AP. 
The signature for this event looks like this: 

2017-04-05T12:00:20.369813-07:00 NOTICE wpa_supplicant[561]: wlan0: CTRL-EVENT-DISCONNECTED bssid=9c:1c:12:00:00:1e reason=4 locally_generated=1

It may or may not be preceded by higher level signs of inactivity (from shill): 
2017-04-05T12:00:12.886748-07:00 WARNING shill[1674]: [WARNING:traffic_monitor.cc(221)] Congested tx queues detected, out-of-credits?

Come up with ways to add more instrumentation just before this 
happens, so we get a better idea of what happened before the deauth
and why inactivity was cited. 
Can we log channel conditions, packet retry stats? What else would help? The suspected cause in many cases is platform noise. 

Typical sample log from feedback report ID: 56729187131
It shows we get an IP, continue scanning around, and then a few seconds 
later disconnect inactivity. 

2017-04-05T11:56:21.466827-07:00 INFO shill[1674]: [INFO:service.cc(318)] Suppressed autoconnect to service 0 (connecting)
2017-04-05T11:56:21.467420-07:00 INFO shill[1674]: [INFO:dhcp_config.cc(155)] Init DHCP Proxy: wlan0 at :1.62
2017-04-05T11:56:21.597877-07:00 INFO dhcpcd[7863]: status changed to Discover
2017-04-05T11:56:21.598178-07:00 INFO dhcpcd[7863]: wlan0: soliciting a DHCP lease
2017-04-05T11:56:21.598312-07:00 INFO dhcpcd[7863]: wlan0: sending DISCOVER (xid 0x809794b4), next in 4.7 seconds
2017-04-05T11:56:22.610883-07:00 INFO dhcpcd[7863]: wlan0: received OFFER with xid 0x809794b4
2017-04-05T11:56:22.610935-07:00 INFO dhcpcd[7863]: wlan0: offered <IPv4: 22>15 from <IPv4: 37>77
2017-04-05T11:56:22.610956-07:00 INFO dhcpcd[7863]: wlan0: requesting lease of <IPv4: 22>15
2017-04-05T11:56:22.610973-07:00 INFO dhcpcd[7863]: status changed to Request
2017-04-05T11:56:22.611269-07:00 INFO dhcpcd[7863]: wlan0: sending REQUEST (xid 0x809794b4), next in 3.1 seconds
2017-04-05T11:56:22.618477-07:00 INFO dhcpcd[7863]: wlan0: received ACK with xid 0x809794b4
2017-04-05T11:56:22.618515-07:00 INFO dhcpcd[7863]: wlan0: acknowledged <IPv4: 22>15 from <IPv4: 37>77
2017-04-05T11:56:22.623951-07:00 INFO dhcpcd[7863]: wlan0: ARP probing <IPv4: 21>54 (1 of 3), next in 1.6 seconds
2017-04-05T11:56:22.624038-07:00 INFO dhcpcd[7863]: status changed to ArpGateway
2017-04-05T11:56:22.624231-07:00 INFO dhcpcd[7863]: wlan0: received ACK with xid 0x809794b4
2017-04-05T11:56:22.624274-07:00 INFO dhcpcd[7863]: wlan0: acknowledged <IPv4: 22>15 from <IPv4: 37>77
2017-04-05T11:56:22.624458-07:00 INFO dhcpcd[7863]: wlan0: ARP probing <IPv4: 21>54 (1 of 3), next in 1.9 seconds
2017-04-05T11:56:22.624519-07:00 INFO dhcpcd[7863]: status changed to ArpGateway
2017-04-05T11:56:22.624729-07:00 INFO dhcpcd[7863]: wlan0: received ACK with xid 0x809794b4
2017-04-05T11:56:22.624764-07:00 INFO dhcpcd[7863]: wlan0: acknowledged <IPv4: 22>15 from <IPv4: 38>4
2017-04-05T11:56:22.624977-07:00 INFO dhcpcd[7863]: wlan0: ARP probing <IPv4: 21>54 (1 of 3), next in 1.9 seconds
2017-04-05T11:56:22.625037-07:00 INFO dhcpcd[7863]: status changed to ArpGateway
2017-04-05T11:56:22.642821-07:00 INFO dhcpcd[7863]: wlan0: leased <IPv4: 22>15 for 1800 seconds
2017-04-05T11:56:22.643166-07:00 INFO dhcpcd[7863]: event BOUND on interface wlan0
2017-04-05T11:56:22.643584-07:00 INFO dhcpcd[7863]: status changed to Bound
2017-04-05T11:56:22.644448-07:00 INFO shill[1674]: [INFO:dhcpv4_config.cc(127)] Event reason: BOUND
2017-04-05T11:56:22.644920-07:00 INFO shill[1674]: [INFO:connection.cc(243)] UpdateFromIPConfig: Installing with parameters: local=<IPv4: 22>15 broadcast=<IPv4: 21>55 peer=<unknown> gateway=<IPv4: 21>54
2017-04-05T11:56:22.646541-07:00 INFO shill[1674]: [INFO:service.cc(404)] Service 0: state Configuring -> Connected
2017-04-05T11:56:22.797096-07:00 INFO shill[1674]: [INFO:manager.cc(1491)] Service 0 updated; state: Connected failure Unknown
2017-04-05T11:56:22.803579-07:00 INFO shill[1674]: [INFO:wifi.cc(2359)] Enabling high bitrates.
2017-04-05T11:56:22.816988-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 0. [SSID=1], bssid: 9c:1c:12:00:00:1e, signal: -71, security: none, frequency: 2412
2017-04-05T11:56:22.818888-07:00 INFO shill[1674]: [INFO:manager.cc(1739)] Default physical service: 0 (connected)
2017-04-05T11:56:27.823003-07:00 ERR shill[1674]: [ERROR:http_request.cc(188)] Could not resolve hostname www.gstatic.com: The network connection was timed out
2017-04-05T11:56:27.823225-07:00 INFO shill[1674]: [INFO:portal_detector.cc(130)] Portal detection completed attempt 1 with phase==DNS, status==Timeout, failures in content==0
2017-04-05T11:56:27.838860-07:00 INFO shill[1674]: [INFO:portal_detector.cc(130)] Portal detection completed attempt 2 with phase==Content, status==Success, failures in content==0
2017-04-05T11:56:27.839042-07:00 INFO shill[1674]: [INFO:service.cc(404)] Service 0: state Connected -> Online
2017-04-05T11:56:27.839089-07:00 INFO shill[1674]: [INFO:manager.cc(1491)] Service 0 updated; state: Online failure Unknown
2017-04-05T11:56:39.812548-07:00 INFO shill[1674]: [INFO:device_info.cc(567)] Delaying creation of device for slave_android at index 4
2017-04-05T11:56:39.813045-07:00 INFO shill[1674]: [INFO:device.cc(240)] Device created: veth_android index 5
2017-04-05T11:56:40.085148-07:00 INFO arc-networkd[7976]: [INFO:manager.cc(86)] Binding to interface wlan0
2017-04-05T11:56:42.806048-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 0. [SSID=1], bssid: 9c:1c:12:00:00:1e, signal: -61, security: none, frequency: 2412
2017-04-05T11:56:45.245241-07:00 INFO arc-networkd[7976]: [INFO:manager.cc(112)] Found IPv6 network <IPv6: 49>/64 route <IPv6: 27>
2017-04-05T11:56:46.246299-07:00 INFO arc-networkd[7976]: [INFO:manager.cc(157)] Setting IPv6 address <IPv6: 24>/128 route <IPv6: 32>
2017-04-05T11:57:02.807079-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 0. [SSID=1], bssid: 9c:1c:12:00:00:1e, signal: -64, security: none, frequency: 2412
2017-04-05T11:57:22.808780-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 0. [SSID=1], bssid: 9c:1c:12:00:00:1e, signal: -69, security: none, frequency: 2412
2017-04-05T11:57:42.810643-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 0. [SSID=1], bssid: 9c:1c:12:00:00:1e, signal: -59, security: none, frequency: 2412
2017-04-05T11:58:02.812190-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 0. [SSID=1], bssid: 9c:1c:12:00:00:1e, signal: -68, security: none, frequency: 2412
2017-04-05T11:58:22.813716-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 0. [SSID=1], bssid: 9c:1c:12:00:00:1e, signal: -67, security: none, frequency: 2412
2017-04-05T11:58:42.815807-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 0. [SSID=1], bssid: 9c:1c:12:00:00:1e, signal: -69, security: none, frequency: 2412
2017-04-05T11:59:22.819082-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 0. [SSID=1], bssid: 9c:1c:12:00:00:1e, signal: -67, security: none, frequency: 2412
2017-04-05T11:59:28.442079-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 33 destroyed.
2017-04-05T11:59:28.442915-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 36 destroyed.
2017-04-05T11:59:28.443263-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 37 destroyed.
2017-04-05T11:59:28.443528-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 38 destroyed.
2017-04-05T11:59:28.443796-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 39 destroyed.
2017-04-05T11:59:28.444127-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 34 destroyed.
2017-04-05T11:59:28.444768-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 35 destroyed.
2017-04-05T11:59:28.445025-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 40. [SSID=8], bssid: 9c:1c:12:00:00:32, signal: -72, security: rsn, frequency: 5200
2017-04-05T11:59:28.445335-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 41. [SSID=10], bssid: 9c:1c:12:00:00:34, signal: -72, security: rsn, frequency: 5200
2017-04-05T11:59:28.445560-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 42. [SSID=9], bssid: 9c:1c:12:00:00:33, signal: -72, security: rsn, frequency: 5200
2017-04-05T11:59:28.446318-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 43 destroyed.
2017-04-05T11:59:28.460176-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 44 destroyed.
2017-04-05T11:59:28.460564-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 45 destroyed.
2017-04-05T11:59:28.460758-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 46. [SSID=7], bssid: 9c:1c:12:00:00:52, signal: -74, security: 802_1x, frequency: 5180
2017-04-05T11:59:28.460958-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 40. [SSID=8], bssid: 9c:1c:12:00:00:65, signal: -74, security: rsn, frequency: 5180
2017-04-05T11:59:28.461161-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 42. [SSID=9], bssid: 9c:1c:12:00:00:66, signal: -73, security: rsn, frequency: 5180
2017-04-05T11:59:28.461380-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 41. [SSID=10], bssid: 9c:1c:12:00:00:67, signal: -73, security: rsn, frequency: 2462
2017-04-05T11:59:28.461802-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 47 destroyed.
2017-04-05T11:59:28.462179-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 48 destroyed.
2017-04-05T11:59:28.462300-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 42. [SSID=9], bssid: 9c:1c:12:00:00:68, signal: -74, security: rsn, frequency: 5785
2017-04-05T11:59:28.462443-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 40. [SSID=8], bssid: 9c:1c:12:00:00:69, signal: -75, security: rsn, frequency: 5785
2017-04-05T11:59:28.462841-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 42 destroyed.
2017-04-05T11:59:28.463084-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 46. [SSID=7], bssid: 9c:1c:12:00:00:51, signal: -75, security: 802_1x, frequency: 5785
2017-04-05T11:59:28.463298-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 46. [SSID=7], bssid: 9c:1c:12:00:00:6a, signal: -80, security: 802_1x, frequency: 5785
2017-04-05T11:59:28.463541-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 40 destroyed.
2017-04-05T11:59:28.463687-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 49. [SSID=17], bssid: 50:6a:03:00:00:6b, signal: -78, security: rsn, frequency: 2457
2017-04-05T11:59:28.463941-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 50 destroyed.
2017-04-05T11:59:28.464150-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 51 destroyed.
2017-04-05T11:59:28.464358-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 52 destroyed.
2017-04-05T11:59:28.464424-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 46. [SSID=7], bssid: 9c:1c:12:00:00:6c, signal: -86, security: 802_1x, frequency: 5745
2017-04-05T11:59:28.464690-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 53 destroyed.
2017-04-05T11:59:28.464758-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 41. [SSID=10], bssid: 9c:1c:12:00:00:6d, signal: -81, security: rsn, frequency: 5785
2017-04-05T11:59:28.465004-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 41 destroyed.
2017-04-05T11:59:28.465208-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 54 destroyed.
2017-04-05T11:59:28.465418-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 55 destroyed.
2017-04-05T11:59:28.465485-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 56. [SSID=33], bssid: f4:f2:6d:00:00:6e, signal: -87, security: rsn, frequency: 5180
2017-04-05T11:59:28.465739-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 49 destroyed.
2017-04-05T11:59:28.466206-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 56 destroyed.
2017-04-05T11:59:28.466307-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 46. [SSID=7], bssid: 6c:f3:7f:00:00:56, signal: -88, security: 802_1x, frequency: 5805
2017-04-05T11:59:28.466455-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 46. [SSID=7], bssid: 6c:f3:7f:00:00:6f, signal: -92, security: 802_1x, frequency: 5220
2017-04-05T11:59:28.466900-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 57 destroyed.
2017-04-05T11:59:28.467230-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 58 destroyed.
2017-04-05T11:59:28.467621-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 46 destroyed.
2017-04-05T11:59:28.468003-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 59 destroyed.
2017-04-05T11:59:28.468588-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 60 destroyed.
2017-04-05T11:59:28.468718-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 61. [SSID=25], bssid: 9c:1c:12:00:00:58, signal: -74, security: none, frequency: 5785
2017-04-05T11:59:28.789954-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 62 destroyed.
2017-04-05T11:59:28.790429-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 61. [SSID=25], bssid: 9c:1c:12:00:00:70, signal: -81, security: none, frequency: 5785
2017-04-05T11:59:28.800178-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 61. [SSID=25], bssid: 9c:1c:12:00:00:71, signal: -85, security: none, frequency: 5745
2017-04-05T11:59:28.800807-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 63 destroyed.
2017-04-05T11:59:28.801004-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 61. [SSID=25], bssid: 9c:1c:12:00:00:72, signal: -87, security: none, frequency: 5805
2017-04-05T11:59:28.801720-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 64 destroyed.
2017-04-05T11:59:28.801846-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 61. [SSID=25], bssid: 6c:f3:7f:00:00:73, signal: -89, security: none, frequency: 5805
2017-04-05T11:59:28.802341-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 65 destroyed.
2017-04-05T11:59:28.802465-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 61. [SSID=25], bssid: 6c:f3:7f:00:00:74, signal: -92, security: none, frequency: 5500
2017-04-05T11:59:28.803067-07:00 INFO shill[1674]: [INFO:service.cc(302)] Service 61 destroyed.
2017-04-05T11:59:42.819953-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 0. [SSID=1], bssid: 9c:1c:12:00:00:1e, signal: -76, security: none, frequency: 2412
2017-04-05T12:00:02.820836-07:00 INFO shill[1674]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 0. [SSID=1], bssid: 9c:1c:12:00:00:1e, signal: -80, security: none, frequency: 2412
2017-04-05T12:00:12.886748-07:00 WARNING shill[1674]: [WARNING:traffic_monitor.cc(221)] Congested tx queues detected, out-of-credits?
2017-04-05T12:00:20.369813-07:00 NOTICE wpa_supplicant[561]: wlan0: CTRL-EVENT-DISCONNECTED bssid=9c:1c:12:00:00:1e reason=4 locally_generated=1
2017-04-05T12:00:20.371476-07:00 INFO shill[1674]: [INFO:wifi.cc(867)] WiFi wlan0 supplicant updated DisconnectReason to -4
2017-04-05T12:00:20.376260-07:00 ERR shill[1674]: [ERROR:wifi.cc(973)] Disconnected due to inability to connect to the service.
2017-04-05T12:00:20.376449-07:00 INFO shill[1674]: [INFO:service.cc(404)] Service 0: state Online -> Failure
2017-04-05T12:00:20.376494-07:00 INFO shill[1674]: [INFO:service.cc(986)] Noting an unexpected connection drop.
2017-04-05T12:00:20.376560-07:00 INFO shill[1674]: [INFO:manager.cc(1491)] Service 0 updated; state: Failure failure out-of-range
2017-04-05T12:00:20.377949-07:00 INFO shill[1674]: [INFO:service.cc(404)] Service 0: state Failure -> Idle
2017-04-05T12:00:20.378115-07:00 INFO shill[1674]: [INFO:manager.cc(1491)] Service 0 updated; state: Idle failure Unknown
2017-04-05T12:00:20.379954-07:00 INFO shill[1674]: [INFO:dhcp_config.cc(220)] Stopping 7863 (ReleaseIP)
2017-04-05T12:00:20.380132-07:00 INFO dhcpcd[7863]: received SIGTERM, stopping
2017-04-05T12:00:20.380155-07:00 INFO dhcpcd[7863]: wlan0: removing interface
2017-04-05T12:00:20.380177-07:00 INFO dhcpcd[7863]: status changed to Release
2017-04-05T12:00:20.380487-07:00 INFO dhcpcd[7863]: dhcpcd exited
2017-04-05T12:00:20.399750-07:00 INFO shill[1674]: [INFO:wifi.cc(1545)] WiFi wlan0 StateChanged completed -> disconnected
2017-04-05T12:00:20.400424-07:00 WARNING shill[1674]: [WARNING:device.cc(606)] No default route for global IPv6 address <IPv6: 48>
2017-04-05T12:00:20.402394-07:00 INFO shill[1674]: [INFO:manager.cc(1735)] Default physical service: 0 (not connected)
2017-04-05T12:00:20.402808-07:00 INFO shill[1674]: [INFO:service.cc(309)] Auto-connecting to service 0
2017-04-05T12:00:20.402945-07:00 INFO shill[1674]: [INFO:service.cc(325)] Connect to service 0: AutoConnect
2017-04-05T12:00:20.406975-07:00 DEBUG wpa_supplicant[561]: Fast associate: Old scan results
2017-04-05T12:00:20.406995-07:00 DEBUG wpa_supplicant[561]: wlan0: Rescheduling scan request: 0.000000 sec
2017-04-05T12:00:20.407161-07:00 DEBUG wpa_supplicant[561]: wlan0: State: DISCONNECTED -> SCANNING