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

Issue 710705 link

Starred by 2 users
Status: Assigned
Owner:
█ kirtika@chromium.org
Last visit > 30 days ago
Cc:
█ debayanb@chromium.org
snanda@chromium.org
sdantul...@chromium.org
█ cernekee@chromium.org
█ rjahagir@chromium.org
vsu...@chromium.org
dhadd...@chromium.org
harpreet@chromium.org
abod...@chromium.org
█ bhthompson@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug-Regression



Sign in to add a comment

Caroline sometimes seeing slow wireless network on M59

Project Member Reported by aashuto...@chromium.org, Apr 12 2017 
Chrome Version: <From about:version: Google Chrome 59.0.3065.0>
Chrome OS Version: <From about:version: Platform 9449.0.0>
Chrome OS Platform: <Caroline>
Network info: <WiFi>


This is not always reproducible. Kirtika@ Can you check the logs and see if you find any pointers causing this?
debug-logs_20170411-142941 (1).tgz
2.7 MB Download

Comment 1 by abod...@chromium.org, Apr 12 2017

Status: Untriaged (was: Unconfirmed)

Comment 2 by abod...@chromium.org, Apr 12 2017

Cc: dhadd...@chromium.org sdantul...@chromium.org
Labels: -Pri-2 M-58 Pri-1
Seen lot of wifi disconnects on caroline PVT with Chrome:58.0.3029.68/9334.42.0 beta-channel caroline
debug-logs_20170412-140302.tgz
1020 KB Download

Comment 3 by dhadd...@chromium.org, Apr 12 2017

Cc: bhthompson@chromium.org
I saw this today too on caroline M58

Comment 4 by aashuto...@chromium.org, Apr 12 2017

Cc: yoshi@chromium.org snanda@chromium.org

Comment 5 by snanda@chromium.org, Apr 13 2017

Cc: cernekee@chromium.org

Comment 6 by cernekee@chromium.org, Apr 13 2017 

debug-logs_20170411-142941 (1).tgz says:

2017-04-11T14:28:46.954057-07:00 INFO shill[13386]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 3. [SSID=GoogleGuest], bssid: 6c:f3:7f:af:8e:31, signal: -63, security: none, frequency: 5200

Do you have iperf or speedtest results to quantify the speed drop?  It would be helpful to plot those numbers vs. signal level.


debug-logs_20170412-140302.tgz shows some possible trouble at Caroline's problem frequency (5745 MHz), which triggered a reassociation due to link monitor failures:

2017-04-12T13:45:57.691133-07:00 INFO shill[9397]: [INFO:service.cc(309)] Auto-connecting to service 0
2017-04-12T13:45:57.691211-07:00 INFO shill[9397]: [INFO:service.cc(325)] Connect to service 0: AutoConnect
2017-04-12T13:45:57.691274-07:00 INFO shill[9397]: [INFO:wifi.cc(689)] Background scan: simple:30:-50:3601
2017-04-12T13:45:57.693024-07:00 NOTICE wpa_supplicant[559]: wlan0: SME: Trying to authenticate with 6c:f3:7f:af:8e:31 (SSID='GoogleGuest' freq=5745 MHz)
2017-04-12T13:45:57.693694-07:00 INFO shill[9397]: [INFO:service.cc(404)] Service 0: state Idle -> Associating
2017-04-12T13:45:57.693749-07:00 INFO shill[9397]: [INFO:manager.cc(1491)] Service 0 updated; state: Associating failure Unknown
2017-04-12T13:45:57.697400-07:00 INFO shill[9397]: [INFO:service.cc(318)] Suppressed autoconnect to service 0 (connecting)
2017-04-12T13:45:57.700997-07:00 INFO shill[9397]: [INFO:wifi.cc(1545)] WiFi wlan0 StateChanged inactive -> authenticating
2017-04-12T13:45:57.702570-07:00 NOTICE wpa_supplicant[559]: wlan0: Trying to associate with 6c:f3:7f:af:8e:31 (SSID='GoogleGuest' freq=5745 MHz)
2017-04-12T13:45:57.707980-07:00 INFO shill[9397]: [INFO:wifi.cc(1545)] WiFi wlan0 StateChanged authenticating -> associating
2017-04-12T13:45:57.711846-07:00 NOTICE wpa_supplicant[559]: wlan0: Associated with 6c:f3:7f:af:8e:31
2017-04-12T13:45:57.712539-07:00 NOTICE wpa_supplicant[559]: wlan0: CTRL-EVENT-CONNECTED - Connection to 6c:f3:7f:af:8e:31 completed [id=0 id_str=]
2017-04-12T13:45:57.714037-07:00 NOTICE wpa_supplicant[559]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US
2017-04-12T13:45:57.717754-07:00 INFO shill[9397]: [INFO:wifi.cc(1545)] WiFi wlan0 StateChanged associating -> completed
2017-04-12T13:45:57.749639-07:00 NOTICE wpa_supplicant[559]: wlan0: CTRL-EVENT-SIGNAL-CHANGE above=0 signal=-64 noise=9999 txrate=6000
2017-04-12T13:45:57.762858-07:00 INFO shill[9397]: [INFO:dhcp_config.cc(213)] Spawned /sbin/dhcpcd with pid: 9458
2017-04-12T13:45:57.762893-07:00 INFO shill[9397]: [INFO:wifi.cc(1600)] wlan0 is up; started L3 configuration.
2017-04-12T13:45:57.762903-07:00 INFO shill[9397]: [INFO:service.cc(404)] Service 0: state Associating -> Configuring

[...]

2017-04-12T13:45:58.078800-07:00 INFO shill[9397]: [INFO:service.cc(404)] Service 0: state Configuring -> Connected
2017-04-12T13:45:58.124367-07:00 INFO shill[9397]: [INFO:manager.cc(1491)] Service 0 updated; state: Connected failure Unknown
2017-04-12T13:45:58.130064-07:00 INFO shill[9397]: [INFO:wifi.cc(2359)] Enabling high bitrates.
2017-04-12T13:45:58.137711-07:00 INFO shill[9397]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 0. [SSID=GoogleGuest], bssid: 6c:f3:7f:af:8e:31, signal: -64, security: none, frequency: 5745
2017-04-12T13:45:58.138827-07:00 INFO shill[9397]: [INFO:manager.cc(1739)] Default physical service: 0 (connected)
2017-04-12T13:45:58.269836-07:00 INFO shill[9397]: [INFO:portal_detector.cc(130)] Portal detection completed attempt 1 with phase==Content, status==Success, failures in content==0
2017-04-12T13:45:58.269909-07:00 INFO shill[9397]: [INFO:service.cc(404)] Service 0: state Connected -> Online

[...]

2017-04-12T13:54:40.510237-07:00 NOTICE wpa_supplicant[559]: wlan0: CTRL-EVENT-SIGNAL-CHANGE above=0 signal=-63 noise=9999 txrate=270000
2017-04-12T13:55:11.115260-07:00 ERR shill[9397]: [ERROR:active_link_monitor.cc(222)] Link monitor has reached the failure threshold with 2 broadcast failures and 3 unicast failures.
2017-04-12T13:55:11.116121-07:00 INFO shill[9397]: [INFO:wifi.cc(2171)] WiFi Device wlan0: StartReconnectTimer
2017-04-12T13:55:11.116159-07:00 INFO shill[9397]: [INFO:wifi.cc(1740)] In OnLinkMonitorFailure(): Called Reattach().
2017-04-12T13:55:14.968764-07:00 INFO shill[9397]: [INFO:service.cc(296)] wifi service 61 constructed.
2017-04-12T13:55:14.968769-07:00 NOTICE wpa_supplicant[559]: wlan0: SME: Trying to authenticate with 6c:f3:7f:af:8e:31 (SSID='GoogleGuest' freq=5745 MHz)

[...]

2017-04-12T13:55:17.924190-07:00 INFO shill[9397]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 0. [SSID=GoogleGuest], bssid: 6c:f3:7f:af:8e:31, signal: -65, security: none, frequency: 5745
2017-04-12T13:55:17.924611-07:00 INFO shill[9397]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 65. [SSID=CrOS_NetgearAC_Platform-2.4GHz], bssid: e4:f4:c6:06:ba:07, signal: -42, security: none, frequency: 2427
2017-04-12T13:55:17.927066-07:00 INFO shill[9397]: [INFO:wifi.cc(1545)] WiFi wlan0 StateChanged scanning -> authenticating
2017-04-12T13:55:17.927113-07:00 INFO shill[9397]: [INFO:service.cc(404)] Service 0: state Online -> Associating
2017-04-12T13:55:17.927140-07:00 INFO shill[9397]: [INFO:manager.cc(1491)] Service 0 updated; state: Associating failure Unknown
2017-04-12T13:55:17.927667-07:00 INFO shill[9397]: [INFO:wifi.cc(1545)] WiFi wlan0 StateChanged authenticating -> associating
2017-04-12T13:55:17.927846-07:00 INFO shill[9397]: [INFO:wifi.cc(1545)] WiFi wlan0 StateChanged associating -> completed
2017-04-12T13:55:17.934774-07:00 INFO shill[9397]: [INFO:dhcp_config.cc(220)] Stopping 9458 (ReleaseIP)
2017-04-12T13:55:17.935138-07:00 INFO dhcpcd[9458]: received SIGTERM, stopping
2017-04-12T13:55:17.935159-07:00 INFO dhcpcd[9458]: wlan0: removing interface
2017-04-12T13:55:17.935177-07:00 INFO dhcpcd[9458]: status changed to Release
2017-04-12T13:55:17.935384-07:00 INFO dhcpcd[9458]: dhcpcd exited
2017-04-12T13:55:17.941838-07:00 INFO shill[9397]: [INFO:dhcp_config.cc(213)] Spawned /sbin/dhcpcd with pid: 12899
2017-04-12T13:55:17.941941-07:00 INFO shill[9397]: [INFO:wifi.cc(1600)] wlan0 is up; started L3 configuration.
2017-04-12T13:55:17.941999-07:00 INFO shill[9397]: [INFO:service.cc(404)] Service 0: state Associating -> Configuring
2017-04-12T13:55:17.942057-07:00 INFO shill[9397]: [INFO:manager.cc(1491)] Service 0 updated; state: Configuring failure Unknown
2017-04-12T13:55:17.942770-07:00 WARNING shill[9397]: [WARNING:device.cc(606)] No default route for global IPv6 address 2620:0:1000:fd1f:4e80:93ff:fefe:30df
2017-04-12T13:55:17.946746-07:00 INFO shill[9397]: [INFO:manager.cc(1735)] Default physical service: 0 (not connected)
2017-04-12T13:55:17.946836-07:00 INFO shill[9397]: [INFO:service.cc(318)] Suppressed autoconnect to service 0 (connecting)
2017-04-12T13:55:17.949957-07:00 INFO arc-networkd[4797]: [INFO:manager.cc(81)] Unbinding services
2017-04-12T13:55:17.993575-07:00 NOTICE dhcpcd[12899]: dhcpcd is running with reduced privileges
2017-04-12T13:55:17.994287-07:00 INFO dhcpcd[12899]: status changed to Init
2017-04-12T13:55:17.994497-07:00 INFO shill[9397]: [INFO:dhcp_config.cc(155)] Init DHCP Proxy: wlan0 at :1.94
2017-04-12T13:55:18.131327-07:00 INFO dhcpcd[12899]: status changed to Reboot
2017-04-12T13:55:18.137374-07:00 INFO dhcpcd[12899]: wlan0: ARP probing 100.110.255.254 (1 of 3), next in 1.7 seconds
2017-04-12T13:55:18.137407-07:00 INFO dhcpcd[12899]: wlan0: rebinding lease of 100.110.200.157
2017-04-12T13:55:18.137477-07:00 INFO dhcpcd[12899]: wlan0: sending REQUEST (xid 0xab17ff99), next in 3.4 seconds
2017-04-12T13:55:18.151169-07:00 INFO dhcpcd[12899]: event GATEWAY-ARP on interface wlan0
2017-04-12T13:55:18.151733-07:00 INFO shill[9397]: [INFO:dhcpv4_config.cc(127)] Event reason: GATEWAY-ARP
2017-04-12T13:55:18.151942-07:00 INFO shill[9397]: [INFO:connection.cc(243)] UpdateFromIPConfig: Installing with parameters: local=100.110.200.157 broadcast=100.110.255.255 peer=<unknown> gateway=100.110.255.254
2017-04-12T13:55:18.154248-07:00 INFO shill[9397]: [INFO:service.cc(404)] Service 0: state Configuring -> Connected
2017-04-12T13:55:18.200136-07:00 INFO shill[9397]: [INFO:manager.cc(1491)] Service 0 updated; state: Connected failure Unknown
2017-04-12T13:55:18.205206-07:00 INFO shill[9397]: [INFO:wifi.cc(2359)] Enabling high bitrates.
2017-04-12T13:55:18.216761-07:00 INFO shill[9397]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 0. [SSID=GoogleGuest], bssid: 6c:f3:7f:af:8e:31, signal: -62, security: none, frequency: 5745

Comment 7 by aashuto...@chromium.org, Apr 13 2017 

I checked speedtest, it returned very low numbers. I did not make a note of it. If I see this issue again, will update with perf results.

Comment 8 by dhadd...@chromium.org, Apr 18 2017

Cc: vsu...@chromium.org rjahagir@chromium.org
Something the MO should know about?

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