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

Issue 703906 link

Starred by 3 users
Status: Assigned
Owner:
█ kirtika@chromium.org
Last visit > 30 days ago
Cc:
snanda@chromium.org
█ cernekee@chromium.org
█ xkong@google.com
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

Shill is oblivious to static IP, starts DHCP anyways

Project Member Reported by kirtika@chromium.org, Mar 22 2017 
OS: Seeing this since R58, has possibly existed earlier

We are seeing several attempts where setting a static IP either has 
no effect or is overridden by shill's dhcp spawning and trying to get
a dynamic IP. 
Analyzing a log snippet below: 



Try to set a static IP and then connect to the AP of your choice: 


// This seems to suggest that at least the static IP
// setting of 192.168.0.100 registered somewhere... 

messages:2017-03-21T11:06:47.703777-07:00 INFO avahi-daemon[1305]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.100.
messages:2017-03-21T11:06:47.703815-07:00 INFO avahi-daemon[1305]: Registering new address record for 192.168.0.100 on wlan0.IPv4.


// The netlog has nothing relevant from 11:06:47 to 
// 11:08:21 below, where we associated with the SSID of choice 

2017-03-21T11:08:21.045261-07:00 DEBUG wpa_supplicant[560]: wlan0:    skip - SSID mismatch
2017-03-21T11:08:21.045296-07:00 DEBUG wpa_supplicant[560]: wlan0: 18: d4:a0:2a:cc:15:70 ssid='ANRITSU' wpa_ie_len=0 rsn_ie_len=0 caps=0x421 level=-68 freq=2437 
2017-03-21T11:08:21.045315-07:00 DEBUG wpa_supplicant[560]: wlan0:    allow in non-WPA/WPA2
2017-03-21T11:08:21.045344-07:00 DEBUG wpa_supplicant[560]: wlan0:    selected BSS d4:a0:2a:cc:15:70 ssid='ANRITSU'
2017-03-21T11:08:21.045394-07:00 DEBUG wpa_supplicant[560]: wlan0: Considering connect request: reassociate: 1  selected: d4:a0:2a:cc:15:70  bssid: 00:00:00:00:00:00  pending: 00:00:00:00:00:00  wpa_state: SCANNING  ssid=0x60b0d21debc0  current_ssid=0x60b0d21debc0
2017-03-21T11:08:21.045416-07:00 DEBUG wpa_supplicant[560]: wlan0: Request association with d4:a0:2a:cc:15:70



// After completing association, we start dhcpcd and do a DISCOVER here, instead
// of using the static IP?

2017-03-21T11:08:21.074394-07:00 INFO shill[1073]: [INFO:wifi.cc(1548)] WiFi wlan0 StateChanged associating -> completed
2017-03-21T11:08:21.205644-07:00 INFO shill[1073]: [INFO:dhcp_config.cc(216)] Spawned /sbin/dhcpcd with pid: 11267
2017-03-21T11:08:21.205749-07:00 INFO shill[1073]: [INFO:wifi.cc(1603)] wlan0 is up; started L3 configuration.
2017-03-21T11:08:21.205785-07:00 INFO shill[1073]: [INFO:service.cc(405)] Service 89: state Associating -> Configuring
2017-03-21T11:08:21.205835-07:00 INFO shill[1073]: [INFO:manager.cc(1489)] Service 89 updated; state: Configuring failure Unknown
2017-03-21T11:08:21.209217-07:00 INFO shill[1073]: [INFO:service.cc(319)] Suppressed autoconnect to service 0 (no endpoints)
2017-03-21T11:08:21.209478-07:00 INFO shill[1073]: [INFO:service.cc(319)] Suppressed autoconnect to service 1 (no endpoints)
2017-03-21T11:08:21.217013-07:00 NOTICE dhcpcd[11267]: dhcpcd is running with reduced privileges
2017-03-21T11:08:21.221902-07:00 INFO dhcpcd[11267]: status changed to Init
2017-03-21T11:08:21.223019-07:00 INFO shill[1073]: [INFO:dhcp_config.cc(158)] Init DHCP Proxy: wlan0 at :1.109
2017-03-21T11:08:21.896615-07:00 INFO dhcpcd[11267]: status changed to Discover
2017-03-21T11:08:21.896912-07:00 INFO dhcpcd[11267]: wlan0: soliciting a DHCP lease
2017-03-21T11:08:21.897088-07:00 INFO dhcpcd[11267]: wlan0: sending DISCOVER (xid 0xdb1e870d), next in 3.8 seconds
2017-03-21T11:08:25.707929-07:00 INFO dhcpcd[11267]: wlan0: sending DISCOVER (xid 0xdb1e870d), next in 7.2 seconds
2017-03-21T11:08:32.906516-07:00 INFO dhcpcd[11267]: wlan0: sending DISCOVER (xid 0xdb1e870d), next in 15.6 seconds
2017-03-21T11:08:48.560602-07:00 INFO dhcpcd[11267]: wlan0: sending DISCOVER (xid 0xdb1e870d), next in 31.3 seconds
2017-03-21T11:08:51.210874-07:00 ERR shill[1073]: [ERROR:dhcp_config.cc(298)] Timed out waiting for DHCP lease on wlan0 (after 30 seconds).
2


// Not surprising that we fail and disconnect soon after.

2017-03-21T11:08:51.221396-07:00 DEBUG wpa_supplicant[560]: wlan0: Event DEAUTH (12) received
2017-03-21T11:08:51.221432-07:00 DEBUG wpa_supplicant[560]: wlan0: Deauthentication notification
2017-03-21T11:08:51.221453-07:00 DEBUG wpa_supplicant[560]: wlan0:  * reason 3 (locally generated)
2017-03-21T11:08:51.221491-07:00 DEBUG wpa_supplicant[560]: Deauthentication frame IE(s) - hexdump(len=0): [NULL]
2017-03-21T11:08:51.221520-07:00 NOTICE wpa_supplicant[560]: wlan0: CTRL-EVENT-DISCONNECTED bssid=d4:a0:2a:cc:15:70 reason=3 locally_generated=1
2017-03-21T11:08:51.221538-07:00 DEBUG wpa_supplicant[560]: wlan0: Auto connect disabled: do not try to re-connect
2017-03-21T11:08:51.221561-07:00 DEBUG wpa_supplicant[560]: wlan0: Ignore connection failure indication since interface has been put into disconnected state
2017-03-21T11:08:51.221580-07:00 DEBUG wpa_supplicant[560]: TDLS: Remove peers on disassociation
2017-03-21T11:08:51.221594-07:00 DEBUG wpa_supplicant[560]: wlan0: WPA: Clear old PMK and PTK
2017-03-21T11:08:51.221852-07:00 DEBUG wpa_supplicant[560]: wlan0: State: COMPLETED -> DISCONNECTED
2017-03-21T11:08:51.221881-07:00 DEBUG wpa_supplicant[560]: nl80211: Set wlan0 operstate 1->0 (DORMANT)
2017-03-21T11:08:51.221898-07:00 DEBUG wpa_supplicant[560]: netlink: Operstate: ifindex=2 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
2017-03-21T11:08:51.222092-07:00 DEBUG wpa_supplicant[560]: WMM AC: WMM AC is disabled

Comment 1 by kirtika@chromium.org, Mar 22 2017

Description: Show this description

Comment 2 by kirtika@chromium.org, Mar 22 2017 

For some context, we are doing to get Bluetest throughput tests working 
with Eve and other Chrome OS devices. Kerry says he's had a ~30% success rate
getting the throughput test to run with a static IP so far. 
Two theories currently:
(a) shill doesn't static IP properly (unlikely since it succeeded 30% of the time). 
(b) the issue is restricted to the TTS11 AP that comes with Bluetest, so the fault lies there instead of Chrome OS.

Comment 3 by kirtika@chromium.org, Mar 22 2017 

Kerry did some more experiments, and gave me a set of logs with a good case (static IP was honored). I am doubtful that the throughput test could have run even here though, since shill's portal detection seems to kick in and disconnect us, but that's a different bug. 

Meanwhile, a heavily reduced snippet set from Kerry's experiments with explanation follows below:


Summary of what Kerry did and observed:
- Connect to GoogleGuest and disconnect, just to reset the system I guess?
- Connect to a different bluetest AP. The Bluetest equipment comes with 
two 'instruments' both of which have AP functionality and advertise SSID
'ANRITSU'. One is the 'TTS11' that we need to connect to and fail with, the 
second is the 'alternate' AP that Kerry succeeded with. 
- He got a dynamic AP, disconnected there (not sure if this disconnect was voluntary or forced by the portal detector smelling badness).
- Then he switched back to the original AP he wanted, and this time,
the static IP was honored by shill.
It didn't last long, since this configuration didn't have gateway or DNS server
set, so shill's portal detector failed (which would have probably failed
anyway if Bluetest is designed to not talk to the outside world). 

Question: 
Why was the static IP setting honored the second time around, but not when 
when he first tried, like annotated in the bug description?
(Current theory: It looks like a portal detection fails, and causes
the dynamic IPConfig to be destroyed, and dhcpcd to be killed. That makes shill
pay attention to the static IP setting). 



// XXX: Start from here, disconnected state, locally generated, probably from
// the UI?

2017-03-21T16:50:18.668319-07:00 DEBUG wpa_supplicant[560]: dbus: Register network object '/fi/w1/wpa_supplicant1/Interfaces/13/Networks/1'
2017-03-21T16:50:18.668860-07:00 DEBUG wpa_supplicant[560]: wlan0: Request to deauthenticate - bssid=40:e3:d6:f3:e6:91 pending_bssid=00:00:00:00:00:00 reason=3 state=COMPLETED
2017-03-21T16:50:18.668865-07:00 DEBUG wpa_supplicant[560]: TDLS: Tear down peers
2017-03-21T16:50:18.668871-07:00 DEBUG wpa_supplicant[560]: wpa_driver_nl80211_deauthenticate(addr=40:e3:d6:f3:e6:91 reason_code=3)
2017-03-21T16:50:18.676000-07:00 DEBUG wpa_supplicant[560]: wlan0: Event DEAUTH (12) received
2017-03-21T16:50:18.676029-07:00 DEBUG wpa_supplicant[560]: wlan0: Deauthentication notification
2017-03-21T16:50:18.676035-07:00 DEBUG wpa_supplicant[560]: wlan0:  * reason 3 (locally generated)

// XXX: This is the other ANRITSU being picked this time (ends in 05:69)
//      The first ANRITSU we connected to ended in 15:70. 
// The 'skip-disabled'message is surely misleading, as we do auth with this AP.

2017-03-21T16:50:18.677167-07:00 DEBUG wpa_supplicant[560]: wlan0: 33: a8:54:b2:13:05:69 ssid='ANRITSU' wpa_ie_len=0 rsn_ie_len=0 caps=0x1 level=-71 freq=5805 
2017-03-21T16:50:18.677172-07:00 DEBUG wpa_supplicant[560]: wlan0:    skip - disabled
2017-03-21T16:50:18.677177-07:00 DEBUG wpa_supplicant[560]: wlan0:    allow in non-WPA/WPA2
2017-03-21T16:50:18.677185-07:00 DEBUG wpa_supplicant[560]: wlan0:    selected BSS a8:54:b2:13:05:69 ssid='ANRITSU'
2017-03-21T16:50:18.677199-07:00 DEBUG wpa_supplicant[560]: wlan0: Considering connect request: reassociate: 1  selected: a8:54:b2:13:05:69  bssid: 00:00:00:00:00:00  pending: 00:00:00:00:00:00  wpa_state: DISCONNECTED  ssid=0x60b0d220d2e0  current_ssid=0x60b0d220d2e0
2017-03-21T16:50:18.677206-07:00 DEBUG wpa_supplicant[560]: wlan0: Request association with a8:54:b2:13:05:69
2017-03-21T16:50:18.677214-07:00 DEBUG wpa_supplicant[560]: wlan0: Add radio work 'sme-connect'@0x60b0d220eb80
 

// XXX: Authenticating -> Associating

2017-03-21T16:50:18.683392-07:00 NOTICE wpa_supplicant[560]: wlan0: Trying to associate with a8:54:b2:13:05:69 (SSID='ANRITSU' freq=5805 MHz)
2017-03-21T16:50:18.683412-07:00 DEBUG wpa_supplicant[560]: wlan0: State: AUTHENTICATING -> ASSOCIATING
2017-03-21T16:50:18.683420-07:00 DEBUG wpa_supplicant[560]: nl80211: Set wlan0 operstate 0->0 (DORMANT)
2017-03-21T16:50:18.683426-07:00 DEBUG wpa_supplicant[560]: netlink: Operstate: ifindex=2 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
2017-03-21T16:50:18.683790-07:00 INFO arc-networkd[8653]: [INFO:manager.cc(81)] Unbinding services


// XXX: completed association. Why are we calling dhcp_config's ReleaseIP?
//      Did we have a static IP prior-hand that is still with us?

2017-03-21T16:50:18.694092-07:00 INFO shill[1073]: [INFO:wifi.cc(1548)] WiFi wlan0 StateChanged associating -> completed
2017-03-21T16:50:18.694189-07:00 DEBUG shill[1073]: [VERBOSE2:mac80211_monitor.cc(98)] wlan0 UpdateConnectedState (new_state=1)
2017-03-21T16:50:18.822332-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_config.cc(132)] wlan0 ReleaseIP: wlan0
2017-03-21T16:50:18.822368-07:00 INFO shill[1073]: [INFO:dhcp_config.cc(223)] Stopping 24662 (ReleaseIP)
2017-03-21T16:50:18.822396-07:00 DEBUG shill[1073]: [VERBOSE2:process_manager.cc(206)] process_manager StopProcessAndBlock(24662)
2017-03-21T16:50:18.822417-07:00 DEBUG shill[1073]: [VERBOSE2:process_manager.cc(243)] process_manager KillProcessWithTimeout(pid: 24662)
2017-03-21T16:50:18.822449-07:00 DEBUG shill[1073]: [VERBOSE2:process_manager.cc(264)] process_manager KillProcess(pid: 24662)
2017-03-21T16:50:18.822483-07:00 DEBUG shill[1073]: [VERBOSE2:process_manager.cc(282)] process_manager WaitpidWithTimeout(pid: 24662)
2017-03-21T16:50:18.822524-07:00 INFO dhcpcd[24662]: received SIGTERM, stopping
2017-03-21T16:50:18.822529-07:00 INFO dhcpcd[24662]: wlan0: removing interface
2017-03-21T16:50:18.829055-07:00 INFO dhcpcd[24662]: status changed to Release
2017-03-21T16:50:18.829175-07:00 INFO dhcpcd[24662]: dhcpcd exited


// XXX: We start a new DHCP config here..

2017-03-21T16:50:18.838145-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_config.cc(91)] wlan0 DHCPConfig: wlan0
2017-03-21T16:50:18.838155-07:00 DEBUG shill[1073]: [VERBOSE2:dhcpv4_config.cc(118)] wlan0 DHCPv4Config: wlan0
2017-03-21T16:50:18.838173-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_config.cc(105)] wlan0 RequestIP: wlan0
2017-03-21T16:50:18.838181-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_config.cc(188)] wlan0 Start: wlan0

// XXX: This looks like a regular dynamic IP, not the static IP. We sent a
//      DISCOVER and got an OFFER back.

2017-03-21T16:50:30.708280-07:00 INFO dhcpcd[24743]: wlan0: sending DISCOVER (xid 0xcc7ae59e), next in 16.1 seconds
2017-03-21T16:50:31.462141-07:00 INFO dhcpcd[24743]: wlan0: received OFFER with xid 0xcc7ae59e
2017-03-21T16:50:31.462159-07:00 INFO dhcpcd[24743]: wlan0: offered 192.168.0.34 from 192.168.0.1
2017-03-21T16:50:31.462164-07:00 INFO dhcpcd[24743]: wlan0: requesting lease of 192.168.0.34
2017-03-21T16:50:31.462169-07:00 INFO dhcpcd[24743]: status changed to Request
2017-03-21T16:50:31.462276-07:00 INFO dhcpcd[24743]: wlan0: sending REQUEST (xid 0xcc7ae59e), next in 3.1 seconds
2017-03-21T16:50:31.462478-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_provider.cc(130)] (dhcp_provider) GetConfig pid: 24743
2017-03-21T16:50:31.462493-07:00 DEBUG shill[1073]: [VERBOSE2:dhcpv4_config.cc(170)] wlan0 ProcessStatusChangeSignal: Request
2017-03-21T16:50:32.465172-07:00 INFO dhcpcd[24743]: wlan0: received ACK with xid 0xcc7ae59e
2017-03-21T16:50:32.465230-07:00 INFO dhcpcd[24743]: wlan0: acknowledged 192.168.0.34 from 192.168.0.1
2017-03-21T16:50:32.470272-07:00 INFO dhcpcd[24743]: wlan0: ARP probing 192.168.0.1 (1 of 3), next in 1.5 seconds
2017-03-21T16:50:32.470351-07:00 INFO dhcpcd[24743]: status changed to ArpGateway
2017-03-21T16:50:32.471304-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_provider.cc(130)] (dhcp_provider) GetConfig pid: 24743
2017-03-21T16:50:32.471352-07:00 DEBUG shill[1073]: [VERBOSE2:dhcpv4_config.cc(170)] wlan0 ProcessStatusChangeSignal: ArpGateway
2017-03-21T16:50:32.480123-07:00 INFO dhcpcd[24743]: wlan0: leased 192.168.0.34 for 600 seconds
2017-03-21T16:50:32.480627-07:00 INFO dhcpcd[24743]: event BOUND on interface wlan0
2017-03-21T16:50:32.481268-07:00 INFO dhcpcd[24743]: status changed to Bound

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

Continuation of events in #c3:

// XXX: Portal detection failure somehow causes ReleaseIP? 

[INFO:connection_diagnostics.cc(279)]   #0: Event: Portal detection          Phase: End (DNS)        Result: Failure   
2017-03-21T16:50:38.784171-07:00 INFO shill[1073]: [INFO:connection_diagnostics.cc(282)] Connection diagnostics completed. Connection issue: DNS servers responding to DNS queries, but sending invalid responses. DNS servers might be misconfigured.
2017-03-21T16:50:38.784198-07:00 DEBUG shill[1073]: [VERBOSE3:connection_diagnostics.cc(231)] (connection_diagnostics) Stop
2017-03-21T16:50:38.784971-07:00 DEBUG shill[1073]: [VERBOSE2:manager.cc(961)] manager GetDefaultService
2017-03-21T16:50:40.901922-07:00 DEBUG shill[1073]: [VERBOSE2:mac80211_monitor.cc(119)] wlan0 WakeQueuesIfNeeded on wlan0 (phy0)
2017-03-21T16:50:40.901952-07:00 DEBUG shill[1073]: [VERBOSE2:mac80211_monitor.cc(103)] wlan0 StartTimer
2017-03-21T16:50:46.238886-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_properties.cc(95)] (dhcp_properties) Save
2017-03-21T16:50:46.370949-07:00 DEBUG shill[1073]: message repeated 2 times: [ [VERBOSE2:dhcp_properties.cc(95)] (dhcp_properties) Save]
2017-03-21T16:50:46.376396-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_config.cc(117)] wlan0 RenewIP: wlan0
2017-03-21T16:50:46.376867-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_config.cc(132)] wlan0 ReleaseIP: wlan0


// XXX: Releasing dynamic IPConfig here. 

2017-03-21T16:50:46.377144-07:00 INFO dhcpcd[24743]: wlan0: releasing lease of 192.168.0.34
2017-03-21T16:50:46.377182-07:00 INFO dhcpcd[24743]: wlan0: sending RELEASE with xid 0x7e1ded63
2017-03-21T16:50:46.383296-07:00 INFO dhcpcd[24743]: status changed to Release
2017-03-21T16:50:46.384255-07:00 INFO shill[1073]: [INFO:dhcp_config.cc(223)] Stopping 24743 (ReleaseIP)
2017-03-21T16:50:46.384316-07:00 DEBUG shill[1073]: [VERBOSE2:process_manager.cc(206)] process_manager StopProcessAndBlock(24743)
2017-03-21T16:50:46.384342-07:00 DEBUG shill[1073]: [VERBOSE2:process_manager.cc(243)] process_manager KillProcessWithTimeout(pid: 24743)
2017-03-21T16:50:46.384357-07:00 DEBUG shill[1073]: [VERBOSE2:process_manager.cc(264)] process_manager KillProcess(pid: 24743)
2017-03-21T16:50:46.384404-07:00 DEBUG shill[1073]: [VERBOSE2:process_manager.cc(282)] process_manager WaitpidWithTimeout(pid: 24743)
2017-03-21T16:50:46.384563-07:00 INFO dhcpcd[24743]: received SIGTERM, stopping
2017-03-21T16:50:46.384582-07:00 INFO dhcpcd[24743]: wlan0: removing interface
2017-03-21T16:50:46.392071-07:00 INFO dhcpcd[24743]: status changed to Release



// XXX: W00t! Static IP of 192.168.0.100 comes into effect

2017-03-21T16:50:46.397002-07:00 INFO shill[1073]: [INFO:connection.cc(239)] UpdateFromIPConfig: Flushing old addresses and routes.
2017-03-21T16:50:46.398341-07:00 INFO shill[1073]: [INFO:connection.cc(244)] UpdateFromIPConfig: Installing with parameters: local=192.168.0.100 broadcast=192.168.0.255 peer=<unknown> gateway=<unknown>
2017-03-21T16:50:46.399068-07:00 INFO shill[1073]: [INFO:service.cc(405)] Service 236: state Portal -> Connected

// XXX: This could be why our static IP assignment fails: our 'IPConfig' is
// incomplete, we don't have gateway and DNS server.
// Portal detection fails..

2017-03-21T16:50:46.428268-07:00 ERR shill[1073]: [ERROR:error.cc(146)] [dns_client.cc(110)]: No valid DNS server addresses
2017-03-21T16:50:46.428275-07:00 ERR shill[1073]: [ERROR:http_request.cc(125)] Failed to start DNS client: No valid DNS server addresses
2017-03-21T16:50:46.428339-07:00 INFO shill[1073]: [INFO:portal_detector.cc(130)] Portal detection completed attempt 1 with phase==DNS, status==Failure, failures in content==0
2017-03-21T16:50:46.428363-07:00 ERR shill[1073]: [ERROR:arp_packet.cc(136)] Local or remote IP address is not valid.
2017-03-21T16:50:46.428371-07:00 ERR shill[1073]: [ERROR:active_link_monitor.cc(332)] Failed to send ARP request.  Stopping.
2017-03-21T16:50:46.428381-07:00 INFO shill[1073]: [INFO:wifi.cc(1715)] In OnLinkMonitorFailure(): Skipping reassociate since gateway was never found.

// XXX: We have lost connection by this time, but I dont see supplicant/shill
// changing state yet...

2017-03-21T16:50:51.567800-07:00 DEBUG shill[1073]: [VERBOSE1:wifi_provider.cc(303)] (wifi_provider) Assigned endpoint 00:15:ff:27:5f:ad to service 239.
2017-03-21T16:50:51.567865-07:00 DEBUG shill[1073]: [VERBOSE2:manager.cc(1491)] manager Service 239 updated; state: Idle failure Unknown
2017-03-21T16:50:51.567940-07:00 DEBUG shill[1073]: [VERBOSE2:manager.cc(1493)] manager IsConnected(): 0
2017-03-21T16:50:51.567999-07:00 DEBUG shill[1073]: [VERBOSE2:manager.cc(1494)] manager IsConnecting(): 0


// XXX: Finally connection_diagnostics figures out bad portal state and gets us
// to disconnect from the ANRITSU AP?  

2017-03-21T16:51:33.306205-07:00 INFO shill[1073]: [INFO:manager.cc(1514)] Device wlan0 updated: disabled
2017-03-21T16:51:33.437650-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_config.cc(132)] wlan0 ReleaseIP: wlan0
2017-03-21T16:51:33.437681-07:00 DEBUG shill[1073]: [VERBOSE2:dhcpv4_config.cc(122)] wlan0 ~DHCPv4Config: wlan0
2017-03-21T16:51:33.437706-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_config.cc(98)] wlan0 ~DHCPConfig: wlan0
2017-03-21T16:51:33.437729-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_config.cc(261)] wlan0 CleanupClientState: wlan0
2017-03-21T16:51:33.438268-07:00 DEBUG shill[1073]: [VERBOSE3:connection_diagnostics.cc(231)] (connection_diagnostics) Stop
2017-03-21T16:51:33.441525-07:00 INFO shill[1073]: [INFO:service.cc(405)] Service 236: state Portal -> Idle
2017-03-21T16:51:33.441685-07:00 INFO shill[1073]: [INFO:manager.cc(1489)] Service 236 updated; state: Idle failure Unknown
2017-03-21T16:51:33.441797-07:00 DEBUG shill[1073]: [VERBOSE2:manager.cc(1493)] manager IsConnected(): 0
2017-03-21T16:51:33.441897-07:00 DEBUG shill[1073]: [VERBOSE2:manager.cc(1494)] manager IsConnecting(): 0
2017-03-21T16:51:33.447816-07:00 DEBUG wpa_supplicant[560]: nl80211: Drv Event 20 (NL80211_CMD_DEL_STATION) received for wlan0
2017-03-21T16:51:33.447849-07:00 DEBUG wpa_supplicant[560]: nl80211: Delete station a8:54:b2:13:05:69
2017-03-21T16:51:33.451329-07:00 DEBUG wpa_supplicant[560]: nl80211: Drv Event 39 (NL80211_CMD_DEAUTHENTICATE) received for wlan0 


// XXX: A very long while and a GoogleGuest detour later, we are back to 
//   ANRITSU, and association is complete. Not sure what is the ReleaseIP for,
// but this time we start with our old static IP of 192.168.0.100. 

2017-03-21T16:54:19.044143-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_config.cc(132)] wlan0 ReleaseIP: wlan0
2017-03-21T16:54:19.044190-07:00 INFO shill[1073]: [INFO:dhcp_config.cc(223)] Stopping 25841 (ReleaseIP)
2017-03-21T16:54:19.044225-07:00 DEBUG shill[1073]: [VERBOSE2:process_manager.cc(206)] process_manager StopProcessAndBlock(25841)
2017-03-21T16:54:19.044260-07:00 DEBUG shill[1073]: [VERBOSE2:process_manager.cc(243)] process_manager KillProcessWithTimeout(pid: 25841)
2017-03-21T16:54:19.044285-07:00 DEBUG shill[1073]: [VERBOSE2:process_manager.cc(264)] process_manager KillProcess(pid: 25841)
2017-03-21T16:54:19.044336-07:00 DEBUG shill[1073]: [VERBOSE2:process_manager.cc(282)] process_manager WaitpidWithTimeout(pid: 25841)
2017-03-21T16:54:19.044516-07:00 INFO dhcpcd[25841]: received SIGTERM, stopping
2017-03-21T16:54:19.044542-07:00 INFO dhcpcd[25841]: wlan0: removing interface
2017-03-21T16:54:19.044565-07:00 INFO dhcpcd[25841]: status changed to Release
2017-03-21T16:54:19.044977-07:00 INFO dhcpcd[25841]: dhcpcd exited
2017-03-21T16:54:19.048833-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_config.cc(261)] wlan0 CleanupClientState: wlan0
2017-03-21T16:54:19.048981-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_provider.cc(144)] (dhcp_provider) UnbindPID pid: 25841
2017-03-21T16:54:19.049160-07:00 DEBUG shill[1073]: [VERBOSE2:dhcpv4_config.cc(122)] wlan0 ~DHCPv4Config: wlan0
2017-03-21T16:54:19.049197-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_config.cc(98)] wlan0 ~DHCPConfig: wlan0
2017-03-21T16:54:19.049226-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_config.cc(261)] wlan0 CleanupClientState: wlan0
2017-03-21T16:54:19.056598-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_properties.cc(114)] (anon) Combine
2017-03-21T16:54:19.056659-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_provider.cc(106)] (dhcp_provider) CreateIPv4Config device: wlan0

// XXX: We start a new DHCPConfig here..

2017-03-21T16:54:19.057806-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_config.cc(91)] wlan0 DHCPConfig: wlan0
2017-03-21T16:54:19.057855-07:00 DEBUG shill[1073]: [VERBOSE2:dhcpv4_config.cc(118)] wlan0 DHCPv4Config: wlan0
2017-03-21T16:54:19.057926-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_config.cc(105)] wlan0 RequestIP: wlan0
2017-03-21T16:54:19.057965-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_config.cc(188)] wlan0 Start: wlan0
2017-03-21T16:54:19.058132-07:00 DEBUG shill[1073]: [VERBOSE2:process_manager.cc(144)] process_manager StartProcessInMinijailWithPipes(/sbin/dhcpcd)
2017-03-21T16:54:19.060074-07:00 INFO shill[1073]: [INFO:dhcp_config.cc(216)] Spawned /sbin/dhcpcd with pid: 25946
2017-03-21T16:54:19.060170-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_provider.cc(139)] (dhcp_provider) BindPID pid: 25946
2017-03-21T16:54:19.060358-07:00 INFO shill[1073]: [INFO:wifi.cc(1603)] wlan0 is up; started L3 configuration.
2017-03-21T16:54:19.060419-07:00 INFO shill[1073]: [INFO:service.cc(405)] Service 236: state Associating -> Configuring
2017-03-21T16:54:19.060523-07:00 INFO shill[1073]: [INFO:manager.cc(1489)] Service 236 updated; state: Configuring failure Unknown
2017-03-21T16:54:19.060606-07:00 DEBUG shill[1073]: [VERBOSE2:manager.cc(1493)] manager IsConnected(): 0
2017-03-21T16:54:19.060681-07:00 DEBUG shill[1073]: [VERBOSE2:manager.cc(1494)] manager IsConnecting(): 1
2017-03-21T16:54:19.063057-07:00 DEBUG shill[1073]: [VERBOSE1:asynchronous_signal_handler.cc(49)] Dispatching task_id 2 for reading file descriptor 12, scheduled from this location.
2017-03-21T16:54:19.063344-07:00 WARNING shill[1073]: [WARNING:device.cc(606)] No default route for global IPv6 address 2620:0:1000:fd28:dea9:71ff:fecf:7de9

                                                                                                      
// XXX: This seems worth looking - these RTNL errors most likely stem from our
//      poor or incomplete IPConfig? 

2017-03-21T16:54:19.065219-07:00 DEBUG shill[1073]: [VERBOSE3:rtnl_handler.cc(314)] sequence 1188 received error 3 (No such process) 
2017-03-21T16:54:19.065250-07:00 DEBUG shill[1073]: [VERBOSE3:rtnl_handler.cc(314)] sequence 1190 received error 3 (No such process)
2017-03-21T16:54:19.065264-07:00 DEBUG shill[1073]: [VERBOSE3:rtnl_handler.cc(314)] sequence 1191 received error 3 (No such process)
2017-03-21T16:54:19.065309-07:00 DEBUG shill[1073]: [VERBOSE3:rtnl_handler.cc(314)] sequence 1193 received error 99 (Cannot assign requested address)
2017-03-21T16:54:19.065322-07:00 DEBUG shill[1073]: [VERBOSE3:rtnl_handler.cc(314)] sequence 1194 received error 99 (Cannot assign requested address)
2017-03-21T16:54:19.065597-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_config.cc(132)] wlan0 ReleaseIP: wlan0
2017-03-21T16:54:19.065617-07:00 WARNING shill[1073]: [WARNING:connection.cc(215)] Broadcast address is not set.  Using default.
2017-03-21T16:54:19.065628-07:00 WARNING shill[1073]: [WARNING:connection.cc(488)] No gateway address was provided for this connection.
2017-03-21T16:54:19.065634-07:00 WARNING shill[1073]: [WARNING:connection.cc(233)] Expect limited network connectivity.

// XXX: We are still using our old static IP. Shill is complaining because we
// don't have gateway and DNS server set.

2017-03-21T16:54:19.065648-07:00 INFO shill[1073]: [INFO:connection.cc(244)] UpdateFromIPConfig: Installing with parameters: local=192.168.0.100 broadcast=192.168.0.255 peer=<unknown> gateway=<unknown>
2017-03-21T16:54:19.067435-07:00 NOTICE dhcpcd[25946]: dhcpcd is running with reduced privileges
2017-03-21T16:54:19.067854-07:00 DEBUG wpa_supplicant[560]: RTM_NEWLINK: ifi_index=2 ifname=wlan0 operstate=6 linkmode=1 ifi_family=0 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
2017-03-21T16:54:19.067906-07:00 INFO shill[1073]: [INFO:service.cc(405)] Service 236: state Configuring -> Connected
2017-03-21T16:54:19.068090-07:00 DEBUG shill[1073]: [VERBOSE2:dhcp_properties.cc(95)] (dhcp_properties) Save
2017-03-21T16:54:19.068715-07:00 INFO dhcpcd[25946]: status changed to Init


From here on, we see the same portal detection failures again.
Curiously, shill spawns dhcp, which continues sending out DISCOVER for a dynamic IP, fails, and a long while later we disconnect.

Comment 5 by quiche@chromium.org, Mar 22 2017 

IIRC, the rationale for running DHCP even with a static IP was so that we could pick up any additional parameters for the network. E.g., additional name servers, or web proxy URL.

pstew@ might remember more detail.

Comment 6 by kirtika@chromium.org, Mar 23 2017 

Based on more experiments with Kerry (xkong@google.com) today. I might need to retitle this bug, now that it no longer looks like a shill issue. The context is Kerry and I trying to get Bluetest throughput tests running. 


1. The first issue here is that we are working with a Bluetest AP that refuses to hand out a dynamic IP, Chrome OS or other devices. IMHO, this is the main bug, if we get Bluetest to fix this (their other AP equipment hands out IPs fine), Kerry is unblocked. If IP-handing functionality is broken, there could be other things wrong too. 

2. Next - on configuring static IP. Kerry showed me that an Android device
can connect to this AP by configuring a static IP and setting the gateway address to that of the AP. 
This exact same thing does not work on Chrome OS. Why?


- I suspect a UI bug. 
- Connect to the AP, and use the dialog to enter static IP, DNS server, gateway 
manually. As soon as association completes, shill spawns DHCP ignoring
the static config. Grepping /var/log/net.log for the static IP (192.168.0.100)
gives me nothing, so I repeat the process, this time running
'dbus-monitor --system  | grep 192.168.0.100'
Again, this gives me nothing, making me conclude that the UI is not passing the static setting correctly to Shill. Worse, if I get to settings -> network name ->open configuration tab again, the static details have been forgotten and
'configure automatically' box is checked again. 
This is true irrespective of whether you enter the static settings before connecting to the AP or while associating with it. 
- So this sounds like a UI bug but I am not sure it is worth stevenjb@'s time?


3. Kerry found a workaround like so: connect to the other Bluetest AP that hands out an IP, run a test there. Then go to network configuration and change
to static IP (this works perfectly, I've tested with other normal APs as well).
Switch back to the first AP that we care about, and this time the static IP
setting is honored. (??!!)

4. A side-bug discovered here - after step 3, if you then 'forget the network' by removing it from the preferred networks list, it should ideally forget everything associated with it, including IPConfig settings. 
Instead, the static IP config is remember when you re-connect to the network, even if there is a detour connecting to other networks in between. 
Again, a bug, but not sure if its worth stevenjb@'s time. (Or it may be shill
remembering this, which I'll check).

Comment 7 Deleted

Comment 8 Deleted

Comment 9 by yoshi@chromium.org, Jan 3 2018

Cc: -yoshi@chromium.org

Comment 10 by benhenry@chromium.org, Aug 1

Status: Assigned (was: Untriaged)
►

Sign in to add a comment