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

Issue 907129 link

Starred by 2 users

Issue metadata

Status: Verified
Owner:
Closed: Nov 30
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug



Sign in to add a comment

HP Chromebooks 11 G4 are disconnecting from cellular network

Project Member Reported by vkasatkin@google.com, Nov 20

Issue description

ChromeOS version: 70.0.3538.76, 71.0.3578.49 (beta)
ChromeOS device model: HP Chromebook 11 G4 (kip)
Case#: 17460714

Description:

Device connects to the mobile data and after 10-20 sec, mobile data is disabled automatically and after a couple of seconds it automatically re-enabled and re-connects (and repeats in a loop).
Issue started after devices updated to Chrome OS v. 70, and the only work around currently to reverted back to Chrome OS v. 69.


Steps to reproduce: 
1. Log in to device
2. Try to connect to cellular network 

Current Behavior / Reproduction: 
Mobile data is disabled and re-enabled in the loop. 

Expected Behavior: 
Devices connect to the cellular network and maintain connection.

Drive link to logs: 
https://drive.google.com/open?id=1bV0dTcA1WMYakCNO6R-S18qyXB-1D3y4

Video of the behaviour:
https://drive.google.com/open?id=1wv5ONr-zaX-2LssivfgG1hi4y8IgIOn5

Modem repeatedly power-cycling:

./messages 

2018-11-08T13:31:00.936033-06:00 INFO modem-watchdog[15060]: Powered on modem
2018-11-08T13:31:00.937607-06:00 INFO modem-watchdog[15060]: Exiting watchdog
2018-11-08T13:31:05.837381-06:00 INFO kernel: [ 1740.653485] usb 1-2.1: new high-speed USB device number 50 using xhci_hcd
2018-11-08T13:31:05.918338-06:00 INFO kernel: [ 1740.734787] usb 1-2.1: New USB device found, idVendor=12d1, idProduct=15bb, bcdDevice= 0.01
2018-11-08T13:31:05.918374-06:00 INFO kernel: [ 1740.734806] usb 1-2.1: New USB device strings: Mfr=6, Product=5, SerialNumber=0
........................................
2018-11-08T13:31:05.993641-06:00 INFO kernel: [ 1740.810565] usb 1-2.1: GSM modem (1-port) converter now attached to ttyUSB0
2018-11-08T13:31:06.049125-06:00 INFO modem-watchdog[15989]: Start waiting for modem to be ready
2018-11-08T13:31:07.018630-06:00 ERR mtpd[1440]: LIBMTP_Detect_Raw_Devices failed with 5
2018-11-08T13:31:07.025704-06:00 ERR mtpd[1440]: message repeated 4 times: [ LIBMTP_Detect_Raw_Devices failed with 5]
........................................
2018-11-08T13:31:26.039539-06:00 ERR wpa_supplicant[517]: nl80211: Failed to set IPv4 unicast in multicast filter
2018-11-08T13:31:26.045450-06:00 ERR wpa_supplicant[517]: rmdir[ctrl_interface=/run/wpa_supplicant]: Permission denied
2018-11-08T13:31:39.711599-06:00 WARNING modem-watchdog[15989]: Timed out waiting for modem to be ready; power-cycling modem
2018-11-08T13:31:39.717722-06:00 INFO modem-watchdog[15989]: Powered off modem
........................................
2018-11-08T13:31:40.227094-06:00 INFO modem-watchdog[15989]: Powered on modem
2018-11-08T13:31:40.229295-06:00 INFO modem-watchdog[15989]: Exiting watchdog
2018-11-08T13:31:45.144249-06:00 INFO kernel: [ 1780.023408] usb 1-2.1: new high-speed USB device number 51 using xhci_hcd
........................................
2018-11-08T13:31:45.370788-06:00 INFO modem-watchdog[16268]: Start waiting for modem to be ready
2018-11-08T13:31:46.322981-06:00 ERR mtpd[1440]: LIBMTP_Detect_Raw_Devices failed with 5
2018-11-08T13:31:46.337446-06:00 ERR mtpd[1440]: message repeated 4 times: [ LIBMTP_Detect_Raw_Devices failed with 5]
........................................
2018-11-08T13:32:18.978134-06:00 WARNING modem-watchdog[16268]: Timed out waiting for modem to be ready; power-cycling modem
2018-11-08T13:32:18.986648-06:00 INFO modem-watchdog[16268]: Powered off modem
........................................
2018-11-08T13:32:19.494575-06:00 INFO modem-watchdog[16268]: Powered on modem
2018-11-08T13:32:19.496527-06:00 INFO modem-watchdog[16268]: Exiting watchdog
........................................
2018-11-08T13:32:24.623242-06:00 INFO modem-watchdog[16543]: Start waiting for modem to be ready
2018-11-08T13:32:25.579292-06:00 ERR mtpd[1440]: LIBMTP_Detect_Raw_Devices failed with 5
2018-11-08T13:32:25.696005-06:00 ERR mtpd[1440]: message repeated 4 times: [ LIBMTP_Detect_Raw_Devices failed with 5]




 
 
Also, From net.log, it seems like modem fails to get a network time (AT+CCLK?) and after that got power cycled:

2018-11-08T13:31:06.049921-06:00 DEBUG ModemManager[1438]: <debug> (tty/ttyUSB0): adding device at sysfs path: /sys/devices/pci0000:00/0000:00:14.0/usb1/1-2/1-2.1/1-2.1:3.2/ttyUSB0/tty/ttyUSB0
........................................
2018-11-08T13:31:16.783384-06:00 DEBUG ModemManager[1438]: <debug> MBIM-powered Huawei modem found...
2018-11-08T13:31:16.783847-06:00 DEBUG ModemManager[1438]: <debug> (ttyUSB0) type 'at' claimed by /sys/devices/pci0000:00/0000:00:14.0/usb1/1-2/1-2.1
2018-11-08T13:31:16.783902-06:00 DEBUG ModemManager[1438]: <debug> (wwan0) type 'net' claimed by /sys/devices/pci0000:00/0000:00:14.0/usb1/1-2/1-2.1
2018-11-08T13:31:16.783947-06:00 DEBUG ModemManager[1438]: <debug> (cdc-wdm0) type 'mbim' claimed by /sys/devices/pci0000:00/0000:00:14.0/usb1/1-2/1-2.1
........................................
2018-11-08T13:31:23.753498-06:00 DEBUG ModemManager[1438]: <debug> Modem /org/freedesktop/ModemManager1/Modem/44: access technology changed (unknown -> umts, hsdpa, hsupa)
2018-11-08T13:31:23.754157-06:00 DEBUG ModemManager[1438]: <debug> Will start keeping track of state for subsystem '3gpp'
2018-11-08T13:31:23.754259-06:00 DEBUG ModemManager[1438]: <debug> Network timezone polling started
2018-11-08T13:31:23.754470-06:00 DEBUG ModemManager[1438]: <debug> Periodic signal checks enabled
2018-11-08T13:31:23.754494-06:00 DEBUG ModemManager[1438]: <debug> Periodic signal check refresh requested
2018-11-08T13:31:23.771363-06:00 DEBUG ModemManager[1438]: <debug> Initial 3GPP registration checks finished
2018-11-08T13:31:23.777338-06:00 DEBUG ModemManager[1438]: <debug> Modem /org/freedesktop/ModemManager1/Modem/44: signal quality updated (19)
2018-11-08T13:31:23.777364-06:00 DEBUG ModemManager[1438]: <debug> Periodic signal and access technologies checks not supported
2018-11-08T13:31:23.777380-06:00 DEBUG ModemManager[1438]: <debug> Periodic signal checks disabled
2018-11-08T13:31:29.013679-06:00 DEBUG ModemManager[1438]: <debug> (ttyUSB0) device open count is 3 (open)
2018-11-08T13:31:29.013756-06:00 DEBUG ModemManager[1438]: <debug> (ttyUSB0): --> 'AT+CCLK?<CR>'
2018-11-08T13:31:29.169113-06:00 DEBUG ModemManager[1438]: <debug> (ttyUSB0): <-- '<CR><LF>+CME ERROR: 100<CR><LF>'
2018-11-08T13:31:29.169251-06:00 DEBUG ModemManager[1438]: <debug> Got failure code 100: Unknown error
2018-11-08T13:31:29.169316-06:00 DEBUG ModemManager[1438]: <debug> Couldn't load network timezone: Unknown error
2018-11-08T13:31:29.169411-06:00 DEBUG ModemManager[1438]: <debug> (ttyUSB0) device open count is 2 (close)
2018-11-08T13:31:39.881098-06:00 DEBUG ModemManager[1438]: <debug> [device /sys/devices/pci0000:00/0000:00:14.0/usb1/1-2/1-2.1] unexported modem from path '/org/freedesktop/ModemManager1/Modem/44'
2018-11-08T13:31:39.882238-06:00 DEBUG ModemManager[1438]: <debug> (ttyUSB0) type 'at' claimed by /sys/devices/pci0000:00/0000:00:14.0/usb1/1-2/1-2.1
2018-11-08T13:31:39.882303-06:00 DEBUG ModemManager[1438]: <debug> (wwan0) type 'net' claimed by /sys/devices/pci0000:00/0000:00:14.0/usb1/1-2/1-2.1
........................................
2018-11-08T13:31:39.893166-06:00 DEBUG ModemManager[1438]: <debug> (ttyUSB0) forced to close port
2018-11-08T13:31:39.893289-06:00 DEBUG ModemManager[1438]: <debug> Modem (Huawei) '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-2/1-2.1' completely disposed


But is some cases it gets network time and date which does not seem correct:

2018-11-08T13:30:44.310397-06:00 DEBUG ModemManager[1438]: <debug> (ttyUSB0): --> 'AT+CCLK?<CR>'
2018-11-08T13:30:44.322259-06:00 DEBUG ModemManager[1438]: <debug> (ttyUSB0): <-- '<CR><LF>+CCLK: "04/01/01,00:00:19-24"<CR><LF><CR><LF>OK<CR><LF>'
--
2018-11-08T13:30:50.013888-06:00 DEBUG ModemManager[1438]: <debug> (ttyUSB0): --> 'AT+CCLK?<CR>'
2018-11-08T13:30:50.167279-06:00 DEBUG ModemManager[1438]: <debug> (ttyUSB0): <-- '<CR><LF>+CME ERROR: 100<CR><LF>'
--
2018-11-08T13:31:23.244309-06:00 DEBUG ModemManager[1438]: <debug> (ttyUSB0): --> 'AT+CCLK?<CR>'
2018-11-08T13:31:23.255288-06:00 DEBUG ModemManager[1438]: <debug> (ttyUSB0): <-- '<CR><LF>+CCLK: "04/01/01,00:00:19-24"<CR><LF><CR><LF>OK<CR><LF>'
--
2018-11-08T13:31:29.013756-06:00 DEBUG ModemManager[1438]: <debug> (ttyUSB0): --> 'AT+CCLK?<CR>'
2018-11-08T13:31:29.169113-06:00 DEBUG ModemManager[1438]: <debug> (ttyUSB0): <-- '<CR><LF>+CME ERROR: 100<CR><LF>'
--
2018-11-08T13:32:03.305592-06:00 DEBUG ModemManager[1438]: <debug> (ttyUSB0): --> 'AT+CCLK?<CR>'
2018-11-08T13:32:03.316924-06:00 DEBUG ModemManager[1438]: <debug> (ttyUSB0): <-- '<CR><LF>+CCLK: "04/01/01,00:00:20-24"<CR><LF><CR><LF>OK<CR><LF>'
--
2018-11-08T13:32:09.012555-06:00 DEBUG ModemManager[1438]: <debug> (ttyUSB0): --> 'AT+CCLK?<CR>'
2018-11-08T13:32:09.166364-06:00 DEBUG ModemManager[1438]: <debug> (ttyUSB0): <-- '<CR><LF>+CME ERROR: 100<CR><LF>'
--
2018-11-08T13:32:33.847148-06:00 DEBUG ModemManager[1438]: <debug> (ttyUSB0): --> 'AT+CCLK?<CR>'
2018-11-08T13:32:33.859601-06:00 DEBUG ModemManager[1438]: <debug> (ttyUSB0): <-- '<CR><LF>+CCLK: "04/01/01,00:00:11-24"<CR><LF><CR><LF>OK<CR><LF>'

Cc: harpreet@chromium.org benchan@chromium.org dsunk...@chromium.org
Cc: grundler@chromium.org
Cc: akhouderchah@chromium.org
Labels: -Pri-2 M-71 Pri-1
We have another customer reporting this issue, they also have it on Acer C732 -LT-C6TP  devices.
Hi team, I would just like to mention that customer on 17489911 was affected by an issue just like this on crbug/800515 so they are advising the following: "This is the second time this issue is occurring and we’re getting sick of this, why is nobody paying attention to this kind of connection?"
Re #5: HP Chromebook 11 G4 has a different modem than Acer C732 LTE SKU. If you've logs from the customer, please file a new bug.

Owner: benchan@chromium.org
Status: Started (was: Untriaged)
Project Member

Comment 9 by bugdroid1@chromium.org, Nov 30

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/overlays/board-overlays/+/7ec9d788a2732b51e321fae1890ccba8c0e3a93b

commit 7ec9d788a2732b51e321fae1890ccba8c0e3a93b
Author: Ben Chan <benchan@chromium.org>
Date: Fri Nov 30 05:07:19 2018

kip: modem-watchdog: fix modem VID/PID check

The following upstream change in ModemManager changed how `mmcli`
reports the modem model:

  commit 8ea8d4e7747d: broadband-modem-mbim: show USB product attribute as model

This CL updates modem-watchdog not to rely on the `mmcli` output, but
instead enumerating the modem device nodes and reading VID/PID from
sysfs.

BUG= chromium:907129 
TEST=Tested the following on a Kip with a built-in Huawei ME936 modem:
- Observed /var/log/messages for modem-watchdog messages. The messages
  produced by the same watchdog process have the same process ID.
- Manually power cycle the modem and observd a new watchdog process is
  triggered. The messages produced by the new watchdog process have a
  different process ID.

Change-Id: I32e929993b65953f8d258c0a453d7981bbbf97dc
Reviewed-on: https://chromium-review.googlesource.com/c/1355964
Reviewed-by: Mike Frysinger <vapier@chromium.org>
Tested-by: Ben Chan <benchan@chromium.org>

[modify] https://crrev.com/7ec9d788a2732b51e321fae1890ccba8c0e3a93b/overlay-kip/chromeos-base/modem-watchdog/files/chromeos-kip-modem-watchdog.sh
[rename] https://crrev.com/7ec9d788a2732b51e321fae1890ccba8c0e3a93b/overlay-kip/chromeos-base/modem-watchdog/modem-watchdog-0.0.1-r3.ebuild

Status: Fixed (was: Started)
Labels: Merge-Request-71
Project Member

Comment 12 by sheriffbot@chromium.org, Nov 30

Labels: -Merge-Request-71 Hotlist-Merge-Review Merge-Review-71
This bug requires manual review: We are only 3 days from stable.
Please contact the milestone owner if you have questions.
Owners: benmason@(Android), kariahda@(iOS), kbleicher@(ChromeOS), govind@(Desktop)

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot
We're giving late merge requests added scrutiny.
1) Which CLs are intended to be included in the merge?
2) Has this been tested in ToT or similar to verify the fix, and ensure no unintended consequences?
3) What's the scope of boards this applies to?
4) Is this considered an emergency fix?
Thanks
Re #13:

1) Which CLs are intended to be included in the merge?  crosreview.com/1355964
2) Has this been tested in ToT or similar to verify the fix, and ensure no unintended consequences? Yes
3) What's the scope of boards this applies to?  only affects kip with 4G modem
4) Is this considered an emergency fix?  Yes, 4G modem is currently non functional on kip
Status: Verified (was: Fixed)
Tested on kip/R72-11316.0.0, works fine.
Labels: -Merge-Review-71 Merge-Approved-71
Thanks for the details.

Approving merge to M71 Chrome OS.

Project Member

Comment 17 by bugdroid1@chromium.org, Dec 3

Labels: merge-merged-release-R71-11151.B
The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/overlays/board-overlays/+/0c7f05ebbd5478dc8679ac6c3da3f69845a75701

commit 0c7f05ebbd5478dc8679ac6c3da3f69845a75701
Author: Ben Chan <benchan@chromium.org>
Date: Mon Dec 03 18:59:43 2018

kip: modem-watchdog: fix modem VID/PID check

The following upstream change in ModemManager changed how `mmcli`
reports the modem model:

  commit 8ea8d4e7747d: broadband-modem-mbim: show USB product attribute as model

This CL updates modem-watchdog not to rely on the `mmcli` output, but
instead enumerating the modem device nodes and reading VID/PID from
sysfs.

BUG= chromium:907129 
TEST=Tested the following on a Kip with a built-in Huawei ME936 modem:
- Observed /var/log/messages for modem-watchdog messages. The messages
  produced by the same watchdog process have the same process ID.
- Manually power cycle the modem and observd a new watchdog process is
  triggered. The messages produced by the new watchdog process have a
  different process ID.

Change-Id: I32e929993b65953f8d258c0a453d7981bbbf97dc
Reviewed-on: https://chromium-review.googlesource.com/c/1355964
Reviewed-by: Mike Frysinger <vapier@chromium.org>
Tested-by: Ben Chan <benchan@chromium.org>
(cherry picked from commit 7ec9d788a2732b51e321fae1890ccba8c0e3a93b)
Reviewed-on: https://chromium-review.googlesource.com/c/1359107
Reviewed-by: Ben Chan <benchan@chromium.org>
Commit-Queue: Ben Chan <benchan@chromium.org>

[modify] https://crrev.com/0c7f05ebbd5478dc8679ac6c3da3f69845a75701/overlay-kip/chromeos-base/modem-watchdog/files/chromeos-kip-modem-watchdog.sh
[rename] https://crrev.com/0c7f05ebbd5478dc8679ac6c3da3f69845a75701/overlay-kip/chromeos-base/modem-watchdog/modem-watchdog-0.0.1-r3.ebuild

Labels: Merge-Merged
Can I test this solution, with changing to the dev channel?

Re #19: The fix has been merged to Chrome OS M71, which should be in stable channel pretty soon.
Project Member

Comment 21 by sheriffbot@chromium.org, Dec 7

Cc: kbleicher@google.com
This issue has been approved for a merge. Please merge the fix to any appropriate branches as soon as possible!

If all merges have been completed, please remove any remaining Merge-Approved labels from this issue.

Thanks for your time! To disable nags, add the Disable-Nags label.

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot
Labels: -Merge-Approved-71

Sign in to add a comment