Possible duplicate: crbug.com/626887

Copied issue chromium:630401 to issue chromium:630404

We should be able to detect this pretty easily in feedback logs:

(a) State falls straight from connected to disconnected in a fixed time interval (sum of all dhcp backoff intervals tried). See attached screenshot obtained from running Addison's logs through log processor. 

(b) Consecutive DISCOVER lines in net.log: 

2016-07-13T20:09:01.813459+01:00 INFO dhcpcd[10129]: status changed to Discover
2016-07-13T20:09:01.813659+01:00 INFO dhcpcd[10129]: wlan0: soliciting a DHCP lease
2016-07-13T20:09:01.813804+01:00 INFO dhcpcd[10129]: wlan0: sending DISCOVER (xid 0x3bf4c68e), next in 4.9 seconds
2016-07-13T20:09:06.703117+01:00 INFO dhcpcd[10129]: wlan0: sending DISCOVER (xid 0x3bf4c68e), next in 8.3 seconds
2016-07-13T20:09:15.037030+01:00 INFO dhcpcd[10129]: wlan0: sending DISCOVER (xid 0x3bf4c68e), next in 16.4 seconds

IIUC, turning on full verbosity in shill and wpa_supplicant does not help understand why these packets are not responded to. 

Screenshot referenced in #5: https://screenshot.googleplex.com/ZVSCP3BCqdz

Similar failure reported on a Marvell device: https://feedback.corp.google.com/product/208/neutron?lView=rd&lReport=12805810139

Added syslog/netlog here.

Deleted: system_logs.txt 8.3 MB

system_logs.txt 8.3 MB View Download

https://feedback.corp.google.com/product/208/neutron?lView=rd&lReport=12992616611
"""
Elm occasionally will not connect to some WiFi access points in our house.  Both are on the same DHCP server, but it has issues connecting to <redacted> in this case.
"""

2016-10-08T22:38:27.914475-07:00 NOTICE dhcpcd[11756]: dhcpcd is running with reduced privileges
2016-10-08T22:38:27.915514-07:00 INFO dhcpcd[11756]: status changed to Init
2016-10-08T22:38:27.915940-07:00 INFO shill[2651]: [INFO:dhcp_config.cc(158)] Init DHCP Proxy: mlan0 at :1.47
2016-10-08T22:38:27.935326-07:00 DEBUG wpa_supplicant[1353]: nl80211: Drv Event 64 (NL80211_CMD_NOTIFY_CQM) received for mlan0
2016-10-08T22:38:27.935353-07:00 DEBUG wpa_supplicant[1353]: nl80211: Connection quality monitor event: RSSI high
2016-10-08T22:38:27.936524-07:00 DEBUG wpa_supplicant[1353]: nl80211: Signal: -36 dBm  txrate: 780000
2016-10-08T22:38:27.936553-07:00 DEBUG wpa_supplicant[1353]: nl80211: Noise: 9999 dBm
2016-10-08T22:38:27.936562-07:00 DEBUG wpa_supplicant[1353]: mlan0: Event SIGNAL_CHANGE (25) received
2016-10-08T22:38:27.936570-07:00 NOTICE wpa_supplicant[1353]: mlan0: CTRL-EVENT-SIGNAL-CHANGE above=1 signal=-36 noise=9999 txrate=780000
2016-10-08T22:38:27.936578-07:00 DEBUG wpa_supplicant[1353]: bgscan simple: signal level changed (above=1 current_signal=-36 current_noise=9999 current_txrate=780000))
2016-10-08T22:38:28.453066-07:00 INFO dhcpcd[11756]: status changed to Discover
2016-10-08T22:38:28.453327-07:00 INFO dhcpcd[11756]: mlan0: soliciting a DHCP lease
2016-10-08T22:38:28.453431-07:00 INFO dhcpcd[11756]: mlan0: sending DISCOVER (xid 0x41a06501), next in 3.5 seconds
2016-10-08T22:38:29.883786-07:00 DEBUG wpa_supplicant[1353]: EAPOL: startWhen --> 0
2016-10-08T22:38:29.883815-07:00 DEBUG wpa_supplicant[1353]: EAPOL: disable timer tick
2016-10-08T22:38:32.006566-07:00 INFO dhcpcd[11756]: mlan0: sending DISCOVER (xid 0x41a06501), next in 8.7 seconds
2016-10-08T22:38:34.031574-07:00 INFO shill[2651]: [INFO:service.cc(325)] Suppressed autoconnect to service 1 (connecting)
2016-10-08T22:38:34.031640-07:00 INFO shill[2651]: [INFO:service.cc(325)] Suppressed autoconnect to service 0 (no endpoints)
2016-10-08T22:38:40.676078-07:00 INFO dhcpcd[11756]: mlan0: sending DISCOVER (xid 0x41a06501), next in 16.6 seconds
2016-10-08T22:38:57.276942-07:00 INFO dhcpcd[11756]: mlan0: sending DISCOVER (xid 0x41a06501), next in 32.9 seconds
2016-10-08T22:38:57.910860-07:00 ERR shill[2651]: [ERROR:dhcp_config.cc(297)] Timed out waiting for DHCP lease on mlan0 (after 30 seconds).
2016-10-08T22:38:57.912103-07:00 INFO shill[2651]: [INFO:service.cc(343)] Disconnecting from service 1: OnIPConfigFailure

Full net.log attached.

Deleted: 12992616611_net.log 603 KB

12992616611_net.log 603 KB View Download

Related issues (Google access only):
b/31534163
https://code.google.com/p/chrome-os-partner/issues/detail?id=58888

Adding the following pointer to get dhcp ACKs from Johannes:

" There’s sample code in wpa_supplicant. 
If you look at driver_nl80211.c, it has code that does
 
int enabled = 1;
setsockopt(drv->eapol_tx_sock, SOL_SOCKET, SO_WIFI_STATUS, &enabled, sizeof(enabled))
 
Now, after sending a packet on this socket, and after this packet was transmitted (or not), the socket will become readable (*) and the code continues in wpa_driver_nl80211_handle_eapol_tx_status() which will read from the MSG_ERRQUEUE and process the CMSG that contains the wifi TX status value. The normal message that’s read (msg.msg_iov.iov_base == data) is exactly the frame that was transmitted, in its original 802.3 format.
 
You should be able to do this on any socket, but if it’s not a raw socket then I’m not sure exactly what frame format you get reported back, I suspect it’ll always be the 802.3 format."