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

Issue 838033 link

Starred by 5 users
Status: Duplicate
Merged: issue 810716
Owner:
igorcov@chromium.org
Closed: May 2018
Cc:
apronin@chromium.org
█ pelets...@chromium.org
ryutas@chromium.org
█ jayhlee@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

The devices are losing enrollment after returning from sleep mode.

Project Member Reported by ryutas@chromium.org, Apr 30 2018 
-ChromeOS version: Since Chrome OS version 64, keeps happening in version 65.0.3325.209 
-ChromeOS device model: Lenovo N22 (Touch) Chromebook Reks
-Case#: 15472453

-Description:The devices losing enrollment after returning from sleep mode.
The devices go to sleep, close the lid and in some cases it will just randomly happen, they will lose the enrollment and network connection and wont connect back to the network unless they connect to an open network.

- Steps to reproduce 
*The issue is not consistently affecting all the devices 
1) Sign in to the device.
2) The device goes idle or the lid is closed.
3) Open the lid or try to wake the device.
4) The Chromebook will not connect to the managed network, it seems like the device loses the enrollment.

- Timeframe when issue started: 
Since version 64. 

- Does it affect all devices? 
50 devices reported.

-Current Behavior / Reproduction: Randomly losing the enrollment after returning from sleep mode.
-Expected Behavior: The device should not lose the enrollment after returning from sleep mode.

- Existing Workaround: 
Temporal - Connect to an open network and re-enroll.
 
Drive link to logs: 
-Debug logs / LR05DYB1 / Issue time 11AM 19-04-2017 
https://drive.google.com/open?id=1WLWndG7q-3dZq5NDDLO5Dd1WdI-JXkCL

-Debug logs / LR05F712 / 1:10 pm EST. / 27-04-2017 
https://drive.google.com/open?id=1GCM08FW8JYvRX3FQDpk6fFyF_h_V-b3o

-Screenshot of issue.
https://drive.google.com/open?id=1ieiYD8r0LDv4-I0m8-Mn7pFYt-_5tOXl

-Debug logs from device in version 63, they closed the lid and opened it again as in the other devices.
LR05E700 / 8:50 - 52 am EST / 25-04-2018 
https://drive.google.com/open?id=1wEd9B1p1N4g8O1NBgwNJhMmwW5bY4K23

-Additional Information about LR05DYB1 
1) Version 
https://drive.google.com/open?id=1wy6yATZfioTBpkBieexybLm68zclfU7j
2) Debug logs / LR05DYB1 / Issue time 11AM 19-04-2017 
https://drive.google.com/open?id=1WLWndG7q-3dZq5NDDLO5Dd1WdI-JXkCL
3) Extensions 
https://drive.google.com/open?id=1MGC3vX3cqPWYqOCwIKikEtJOwCRtSmHp
4) Chrome//:network 
https://drive.google.com/open?id=1SD0OFma_SWby7uFGHDTazdKF-2zzJEde

-Additional Information about device LR06GYYT 
1) Policies 
https://drive.google.com/open?id=1-BLpwV5PZAHxtHqssBY6eR1Vxsxe_c25
2) Chrome://network 
https://drive.google.com/open?id=1_IVmpMaCLTCmvEFq6ZlFBlJldbIjUUTp
3) Extensions 
https://drive.google.com/open?id=1nEmySLlNUabofByNtqM2HpKrzCEr_a66
4) debug logs / LR06GYYT /The debug were collected after the issue was reproduced, no timestamp provided 
https://drive.google.com/open?id=1NQcuLwkeB71sxoDt4e8oBjuoEol2aqDQ
5) Version 
https://drive.google.com/open?id=1cOdRkSPxPPqClu_u09ZGU5pH-Ma57SGC

--log crom chrome_20180427-130541 (Debug-logs_20180427-130842) I am not sure if this is mesa's fault or something but I noticed.--
[1116:1116:0427/130541.979606:VERBOSE1:update_display_configuration_task.cc(69)] OnDisplaysUpdated: new_display_state=SINGLE new_power_state=ALL_ON flags=1 force_configure=1 display_count=1
[1116:1116:0427/130541.981934:VERBOSE1:display_configurator.cc(212)] EnterState: display=SINGLE power=ALL_ON
[1116:1116:0427/130541.982070:VERBOSE1:display_configurator.cc(1062)] OnConfigured: success=1 new_display_state=SINGLE new_power_state=ALL_ON
[1116:1116:0427/130542.080877:ERROR:device_cloud_policy_store_chromeos.cc(232)] Device policy read on enrolled device yields no DM token! Status: 1.
[1116:1116:0427/130542.097543:WARNING:statistics_provider.cc(370)] Requested statistic not found: Product_S/N
[1116:1116:0427/130542.362323:ERROR:input_method_manager_impl.cc(1031)] IMEEngine for "jkghodnilhceideoidjikpgommlajknk" is not registered
[1116:1116:0427/130542.363942:VERBOSE1:chrome_session_manager.cc(188)] Starting Chrome with login/oobe screen.
[1116:1116:0427/130542.365699:VERBOSE1:login_display_host_webui.cc(1220)] Showing OOBE screen: unknown
[1116:1116:0427/130542.371753:VERBOSE1:login_display_host_webui.cc(498)] Login WebUI >> zero_delay: 0 wait_for_wp_load_: 1 init_webui_hidden_: 0
[1116:1116:0427/130542.371865:VERBOSE1:login_display_host_webui.cc(626)] Login WebUI >> wizard postponed
[1116:1116:0427/130542.389710:VERBOSE1:display_configurator.cc(908)] SetDisplayPower: power_state=ALL_ON flags=0, configure timer=Stopped
[1116:1116:0427/130542.395048:ERROR:object_proxy.cc(626)] Failed to call method: org.chromium.flimflam.Manager.GetProperties: object_path= /: org.freedesktop.DBus.Error.ServiceUnknown: The name org.chromium.flimflam was not provided by any .service files
[1116:1116:0427/130542.398164:ERROR:device_event_log_impl.cc(156)] [13:05:42.398] Network: shill_property_handler.cc:298 ManagerPropertiesCallback Failed: 0
[1116:1116:0427/130542.398281:ERROR:object_proxy.cc(626)] Failed to call method: org.chromium.flimflam.Manager.GetProperties: object_path= /: org.freedesktop.DBus.Error.ServiceUnknown: The name org.chromium.flimflam was not provided by any .service files
[1116:1116:0427/130542.398323:ERROR:network_profile_handler.cc(83)] Manager properties returned from Shill don't contain the field Profiles
[1116:1116:0427/130542.398391:ERROR:device_event_log_impl.cc(156)] [13:05:42.398] Network: network_handler_callbacks.cc:84 SetTechnologiesProhibited Failed: org.freedesktop.DBus.Error.ServiceUnknown: The name org.chromium.flimflam was not provided by any .service files
[1116:1116:0427/130542.398466:ERROR:object_proxy.cc(626)] Failed to call method: org.chromium.flimflam.Manager.GetProperties: object_path= /: org.freedesktop.DBus.Error.ServiceUnknown: The name org.chromium.flimflam was not provided by any .service files
[1116:1116:0427/130542.398504:ERROR:network_sms_handler.cc(404)] NetworkSmsHandler: Failed to get manager properties.
[1116:1116:0427/130542.398555:ERROR:object_proxy.cc(626)] Failed to call method: org.chromium.flimflam.Manager.GetProperties: object_path= /: org.freedesktop.DBus.Error.ServiceUnknown: The name org.chromium.flimflam was not provided by any .service files
[1116:1116:0427/130542.411695:VERBOSE1:drm_display_host_manager.cc(247)] Got display event ADD for /dev/dri/card0
[1116:1116:0427/130542.416081:VERBOSE1:drm_display_host_manager.cc(247)] Got display event ADD for /dev/dri/card1
[1116:1237:0427/130542.430328:VERBOSE1:drm_device_handle.cc(83)] Succeeded authenticating /dev/dri/card1 in 0 ms with 1 attempt(s)
[1116:1116:0427/130542.439501:ERROR:device_event_log_impl.cc(156)] [13:05:42.439] Network: network_handler_callbacks.cc:84 SetHostname Failed: Manager: org.freedesktop.DBus.Error.ServiceUnknown: The name org.chromium.flimflam was not provided by any .service files
[1116:1116:0427/130542.558169:VERBOSE1:display_configurator.cc(908)] SetDisplayPower: power_state=ALL_ON flags=0, configure timer=Running
[1116:1116:0427/130542.561959:VERBOSE1:automatic_reboot_manager.cc(310)] Rescheduling reboot
[1213:1235:0427/130542.567507:VERBOSE1:drm_device_manager.cc(53)] Could not initialize DRM device for /sys/devices/platform/vgem/drm/card1
[1116:1116:0427/130543.696847:VERBOSE1:display_configurator.cc(956)] Display snapshots invalidated.
[1116:1116:0427/130543.696979:VERBOSE1:update_display_configuration_task.cc(69)] OnDisplaysUpdated: new_display_state=SINGLE new_power_state=ALL_ON flags=0 force_configure=1 display_count=1
[1116:1116:0427/130543.697070:VERBOSE1:display_configurator.cc(212)] EnterState: display=SINGLE power=ALL_ON
[1213:1235:0427/130543.697316:VERBOSE1:drm_display.cc(105)] DRM configuring: device=/sys/devices/pci0000:00/0000:00:02.0/drm/card0 crtc=26 connector=47 origin=0,0 size=1366x768
[1116:1116:0427/130543.714508:VERBOSE1:display_configurator.cc(1062)] OnConfigured: success=1 new_display_state=SINGLE new_power_state=ALL_ON
[1116:1116:0427/130544.180943:VERBOSE1:login_display_host_webui.cc(846)] Login WebUI >> wp animation done
[1116:1116:0427/130544.181257:VERBOSE1:login_display_host_webui.cc(1037)] Login WebUI >> Init postponed WebUI
[1116:1116:0427/130544.181318:VERBOSE1:login_display_host_webui.cc(629)] Login WebUI >> wizard
[1116:1116:0427/130544.184648:VERBOSE1:login_display_host_webui.cc(1125)] Login WebUI >> show login wnd on create
[1116:1116:0427/130544.223230:VERBOSE1:wizard_controller.cc(302)] Starting OOBE wizard with screen: connect
[1116:1116:0427/130544.231181:VERBOSE1:wizard_controller.cc(476)] Showing network screen.
[1116:1116:0427/130544.245900:VERBOSE1:wizard_controller.cc(1082)] SetCurrentScreenrSmooth: connect
[1116:1116:0427/130544.935590:WARNING:CONSOLE(0)] "Styling master document from stylesheets defined in HTML Imports is deprecated, and is planned to be removed in M65, around March 2018. Please refer to https://goo.gl/EGXzpw for possible migration paths.", source:  (0)
[1116:1116:0427/130546.764760:ERROR:device_event_log_impl.cc(156)] [13:05:46.764] Network: network_handler_callbacks.cc:84 RequestScan Failed: wifi: org.freedesktop.DBus.Error.ServiceUnknown: The name org.chromium.flimflam was not provided by any .service files
[1116:1116:0427/130547.282482:WARNING:statistics_provider.cc(370)] Requested statistic not found: Product_S/N
[1116:1116:0427/130547.819833:ERROR:device_event_log_impl.cc(156)] [13:05:47.819] Network: network_handler_callbacks.cc:84 RequestScan Failed: wifi: org.freedesktop.DBus.Error.ServiceUnknown: The name org.chromium.flimflam was not provided by any .service files
[1116:1116:0427/130548.098952:WARNING:CONSOLE(294)] "<webview>: The load has aborted with error -106: ERR_INTERNET_DISCONNECTED.", source: extensions::webViewEvents (294)
[1116:1116:0427/130548.300975:VERBOSE1:signin_screen_handler.cc(1381)] Login WebUI >> loginVisible, src: oobe, webui_visible_: 0
[1116:1116:0427/130548.302747:VERBOSE1:webui_login_view.cc(638)] Login WebUI >> login-prompt-visible
[1116:1116:0427/130548.302852:VERBOSE1:arc_session_runner.cc(168)] Session start requested: MINI_INSTANCE
[1116:1116:0427/130548.302886:VERBOSE1:arc_session_runner.cc(241)] Starting ARC instance
[1116:1116:0427/130552.703956:ERROR:device_event_log_impl.cc(156)] [13:05:52.703] USB: usb_service_linux.cc:212 Got duplicate add event for path: /dev/bus/usb/001/002
[1116:1116:0427/130552.726023:ERROR:device_event_log_impl.cc(156)] [13:05:52.725] USB: usb_service_linux.cc:212 Got duplicate add event for path: /dev/bus/usb/001/003
[1116:1116:0427/130554.123892:ERROR:geolocation_handler.cc(146)] Failed to get Geolocation data: 0
[1116:1116:0427/130554.435099:ERROR:server.cc(1919)] Not implemented reached in void exo::wayland::(anonymous namespace)::remote_surface_set_rectangular_shadow_background_opacity_DEPRECATED(wl_client *, wl_resource *, wl_fixed_t)

Comment 1 by gwendal@chromium.org, Apr 30 2018 

Looking at 
-Debug logs / LR05DYB1 / Issue time 11AM 19-04-2017 
https://drive.google.com/open?id=1WLWndG7q-3dZq5NDDLO5Dd1WdI-JXkCL

and
-Debug logs / LR05F712 / 1:10 pm EST. / 27-04-2017 
https://drive.google.com/open?id=1GCM08FW8JYvRX3FQDpk6fFyF_h_V-b3o

We are deleting and recreating the user directory:
2018-04-27T13:07:17.858366-04:00 INFO cryptohomed[1277]: Migrated (or created) user directory: /home/.shadow/4c75c275ef351664df58f957d309c03514770d44/mount
2018-04-27T13:07:17.860432-04:00 INFO cryptohomed[1277]: Creating pass-through directories /home/.shadow/4c75c275ef351664df58f957d309c03514770d44/mount/user/Cache
....
and as expected, not policy key exists:
2018-04-27T13:07:17.967669-04:00 INFO session_manager[1085]: [INFO:policy_key.cc(51)] No policy key on disk at /home/root/4c75c275ef351664df58f957d309c03514770d44/session_manager/policy/key

Comment 2 by pelets...@chromium.org, May 8 2018

Cc: pelets...@chromium.org
Labels: Enterprise-Triaged
Owner: atwilson@chromium.org
Hey Drew, it seems this is our issue. Do you know who may take a look?

Comment 3 by jraybi...@gwusd.org, May 8 2018 

Not sure which of these bug reports to post debug logs to as there are a couple out there that seem to refer to the same thing.

 Issue 760007 

 Issue 810716 

either way here are some debug logs from the past couple of days.

This issue with devices losing enrollment on N22s is happening to us we have roughly 2000 N22s an we have had enrollment lost on a couple hundred at this point.
debug-logs_20180430-154121
554 KB View Download
debug-logs_20180503-080301
675 KB View Download
debug-logs_20180508-075924.tgz
506 KB Download
debug-logs_20180508-102907
304 KB View Download
debug-logs_20180508-103313
665 KB View Download

Comment 4 by atwilson@chromium.org, May 8 2018

Cc: apronin@chromium.org
Owner: igorcov@chromium.org
Igor, can you take a look at the logs? From the screenshot we're definitely losing enrollment/unable to read device policy - any clue why (recent causes have been TPM initialization issues causing us to wipe the stateful partition - not sure if that's happening here).

Comment 5 by igorcov@chromium.org, May 9 2018 

Looking at the debug logs in #1 from 27-04-2018 (I guess 2017 is a typo there):

The message "Migrated (or created) user directory:" from cryptohome doesn't mean the policy key is deleted. The message says the new user folder is created on the device, while the policy key is per device (not dependent on user data). And the device policy files which are kept in /var/lib/whitelist/ should not be affected by the changes in user folders.

I don't see any information in the logs about the time when the device had a device policy. From the first boot in the logs, we have

2018-04-21T19:38:34.006957+00:00 WARNING session_manager[904]: [WARNING:libpolicy.cc(35)] Could not load the device policy file.

And this continues until:
2018-04-27T13:06:43.158600-04:00 INFO session_manager[1085]: [INFO:policy_store.cc(89)] Persisted policy to disk, path: /var/lib/whitelist/policy.1

So, it seems like from 21-04 till 27-04 the device was in the enrollment lost state and then it got re-enrolled.

From Chrome logs from 21-04 we have:
[931:931:0421/123838.225458:WARNING:install_attributes.cc(94)] Install attributes missing, first sign in

Then the device boots on 23-04 and we have:
[1083:1083:0423/071717.329268:ERROR:device_cloud_policy_store_chromeos.cc(232)] Device policy read on enrolled device yields no DM token! Status: 1.

gwendal@, do you know when last time that device had a successful boot with enrollment?

This problem starts to grow, according to stats the number of devices losing enrollment has been increasing in the last 3 months:
https://uma.googleplex.com/p/chrome/timeline_v2/?sid=3412a27364afba2e2c399f7b825e3b14

Comment 6 by igorcov@chromium.org, May 9 2018 

There's something suspicious in debug_vboot_noisy.log

Config:
console= loglevel=7 init=/sbin/init cros_secure oops=panic panic=-1 root=/dev/dm-0 rootwait ro dm_verity.error_behavior=3 dm_verity.max_bios=-1 dm_verity.dev_wait=1 dm="1 vroot none ro 1,0 3584000 verity payload=PARTUUID=%U/PARTNROFF=1 hashtree=PARTUUID=%U/PARTNROFF=1 hashstart=3584000 alg=sha1 root_hexdigest=7e835fe1124e3189afc2a77b6cc9c3bb7157cc05 salt=2b1de062d8c748bc906082af3af6b111608fc21b8ff96bc2dab9c471c7272b54" noinitrd vt.global_cursor_default=0 kern_guid=%U add_efi_memmap boot=local noresume noswap i915.modeset=1 tpm_tis.force=1 tpm_tis.interrupts=0 nmi_watchdog=panic,lapic  
# OK
#     TPM=0x00020001 this=0x00020001
#   Verify /dev/mmcblk0p4 with recoverykey.vbpubk: 
+ futility vbutil_kernel --verify kern_1 --signpubkey recoverykey.vbpubk
Error verifying key block.
# FAILED
# copying /dev/mmcblk0p6 to kern_2...
+ dd if=/dev/mmcblk0p6 of=kern_2
1+0 records in
1+0 records out
512 bytes copied, 0.00382812 s, 134 kB/s
# Kernel /dev/mmcblk0p6: 
+ futility vbutil_keyblock --unpack kern_2
Invalid key block file: kern_2
vbutil_keyblock: Error reading key block.
# FAILED

Unfortunately there's no timestamp there.

Comment 7 by apronin@chromium.org, May 10 2018 

On 04/27 I see:

2018-04-27T18:18:28.597616+00:00 ERR kernel: [    1.071796] tpm_tis tpm_tis: Unable to read header

leading to no /dev/tpm0 on start, which is confirmed by a later

2018-04-27T18:18:28.685428+00:00 NOTICE tpm-probe[519]: tpm is non-functional or tpm driver is missing

That leads to mount-encrypted recreating the stateful partition (its log is lost - it is rewritten on each reboot, and there were reboots since 04/27 in the first debug_logs captured).

That stateful partition is where /var is mounted from, and that's how device policy files in /var/lib/whitelist/ were likely lost. Sounds like  issue 810716 .

Comment 8 by apronin@chromium.org, May 10 2018 

Oh, and the solution is updating to M67. That's where the fix for the probably root cause is.

Comment 9 by apronin@chromium.org, May 10 2018

Mergedinto: 810716
Status: Duplicate (was: Untriaged)
►

Sign in to add a comment