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

Issue 872254 link

Starred by 1 user
Status: Fixed
Owner:
█ samanthamiller@chromium.org
Last visit > 30 days ago
Closed: Aug 22
Cc:
█ jmuppala@chromium.org
ajha@chromium.org
derat@chromium.org
pucchakayala@chromium.org
wzang@chromium.org
jclinton@chromium.org
jdufault@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug-Regression



Sign in to add a comment

Regression: Delay is seen to get Sign out screen after clicking sign out in Minnie device

Project Member Reported by rkalavakuntla@chromium.org, Aug 8 
Chrome Version:70.0.3511.0/10949.0.0 dev-channel Minnie
OS: Chrome OS

What steps will reproduce the problem?
(1)Sign into user and sign out 
(2)Observe for Sign out screen

Actual: Delay is seen to get Sign  out screen(it took >40 sec)
Expected: No such delay should be there to get sign out screen(it will take 6-8 sec)

This is a Regression issue as same is working fine in 70.03498.0/10898.0.0 dev

Attached the screencast for reference..

Note:
-----
1.Checked the issue in two Minnie devices and able to repro the issue on both devices
2.Issue is also seen in Jerry device which is from the same board of Minnie i.e,Pinky 
3.Issue is not seen in other Chrome OS devices such as Daisy,Peppy,Celes,Cyan..
4.Issue is working fine in 69.0.3497.29/10895.17.0 dev
actualdelay.mp4
10.0 MB View Download
Expected.mp4
4.1 MB View Download

Comment 1 by jdufault@chromium.org, Aug 8 

Can you upload logs?

Comment 2 by rkalavakuntla@chromium.org, Aug 9 

C #1 > 
Please find the attached debug logs.
Thanks!
debug-logs_20180809-101020.tgz
276 KB Download

Comment 3 by jdufault@chromium.org, Aug 9

Cc: la...@chromium.org
There are a lot of mosys crashes in the log. +lannm@, who is an mosys owner.

There are some dash crashes as well - I wonder, is that the dash shell? I am surprised that dash shell would be crashing.

Comment 4 by jdufault@chromium.org, Aug 9 

rkalavakuntla: is the actual delay video edited? there's a sudden snap to rendered content with no animation that I'd expect from a chrome restart, I wonder if there is an issue where the display content is not refreshing even though chrome is ready

Comment 5 by jdufault@chromium.org, Aug 9 

I suspect the video is edited, given that the frame of reference changes (the asus logo); can you upload the unedited video?

Comment 6 by rkalavakuntla@chromium.org, Aug 10 

C #5

Uploaded the unedited video for your reference.Thanks!
Actual (1).mp4
3.4 MB View Download

Comment 7 by jdufault@chromium.org, Aug 10

Cc: derat@chromium.org
Owner: la...@chromium.org
Status: Assigned (was: Untriaged)
The logout seems to take about 5 seconds

# logout

2018-08-09T04:38:23.199155+00:00 INFO session_manager[1390]: [INFO:session_manager_impl.cc(620)] Stopping all sessions
2018-08-09T04:38:23.199346+00:00 INFO session_manager[1390]: [INFO:browser_job.cc(167)] Terminating browser process 1424 with signal 15: exiting cleanly
2018-08-09T04:38:23.199400+00:00 INFO session_manager[1390]: [INFO:system_utils_impl.cc(94)] Sending 15 to 1424 as 1000
2018-08-09T04:38:23.199514+00:00 INFO session_manager[1390]: [INFO:system_utils_impl.cc(94)] Sending 15 to 3333 as 1000
2018-08-09T04:38:23.654988+00:00 INFO kernel: [  246.523547] rockchip-vop ff940000.vop: Detached from iommu domain
2018-08-09T04:38:23.947907+00:00 INFO session_manager[1390]: [INFO:session_manager_service.cc(481)] SessionManagerService quitting run loop
2018-08-09T04:38:23.948470+00:00 INFO session_manager[1390]: [INFO:session_manager_service.cc(201)] SessionManagerService exiting
2018-08-09T04:38:24.187164+00:00 INFO chapsd[1228]: Token at /home/root/9569cdfdc633e14c7f67bda6522261531bf882f8/chaps has been removed from slot 1
2018-08-09T04:38:24.209894+00:00 INFO chapsd[1228]: Unloaded keys for slot 1
2018-08-09T04:38:24.215011+00:00 INFO kernel: [  247.084217] tpm_i2c_infineon 1-0020: command 0xba (size 18) returned code 0x0
2018-08-09T04:38:25.554974+00:00 WARNING chapsd[1228]: Unload Token event received for unknown path: /home/root/9569cdfdc633e14c7f67bda6522261531bf882f8/chaps
2018-08-09T04:38:25.595069+00:00 WARNING kernel: [  248.460993] audit_printk_skb: 42 callbacks suppressed
2018-08-09T04:38:25.595132+00:00 NOTICE kernel: [  248.461030] audit: type=1400 audit(1533789505.580:42): avc:  granted  { execute } for  pid=5536 comm="sh" name="kmod" dev="dm-0" ino=24060 scontext=u:r:cros_init:s0 tcontext=u:object_r:cros_modprobe_exec:s0 tclass=file
2018-08-09T04:38:25.595143+00:00 NOTICE kernel: [  248.461499] audit: type=1400 audit(1533789505.580:43): avc:  granted  { execute } for  pid=5536 comm="modprobe" path="/bin/kmod" dev="dm-0" ino=24060 scontext=u:r:cros_init:s0 tcontext=u:object_r:cros_modprobe_exec:s0 tclass=file
2018-08-09T04:38:25.640579+00:00 INFO crash_reporter[5542]: libminijail[5542]: mount /dev/log -> /dev/log type ''
2018-08-09T04:38:25.735005+00:00 NOTICE kernel: [  248.600772] audit: type=1400 audit(1533789505.720:44): avc:  granted  { execute } for  pid=5678 comm="accelerometer-i" name="kmod" dev="dm-0" ino=24060 scontext=u:r:chromeos:s0 tcontext=u:object_r:cros_modprobe_exec:s0 tclass=file
2018-08-09T04:38:25.735039+00:00 NOTICE kernel: [  248.601059] audit: type=1400 audit(1533789505.720:45): avc:  granted  { execute } for  pid=5678 comm="modprobe" path="/bin/kmod" dev="dm-0" ino=24060 scontext=u:r:chromeos:s0 tcontext=u:object_r:cros_modprobe_exec:s0 tclass=file
2018-08-09T04:38:25.741998+00:00 WARNING mosys[5687]: libminijail[5687]: allowing syscall: socket
2018-08-09T04:38:25.742264+00:00 WARNING mosys[5687]: libminijail[5687]: allowing syscall: connect
2018-08-09T04:38:25.742398+00:00 WARNING mosys[5687]: libminijail[5687]: allowing syscall: gettimeofday
2018-08-09T04:38:25.742509+00:00 WARNING mosys[5687]: libminijail[5687]: allowing syscall: send
2018-08-09T04:38:25.742620+00:00 WARNING mosys[5687]: libminijail[5687]: allowing syscall: writev
2018-08-09T04:38:25.755498+00:00 INFO imageloader[5533]: The latest-version file does not exist. Component PepperFlashPlayer is probably not installed.
2018-08-09T04:38:25.794978+00:00 DEBUG kernel: [  248.660313] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2018-08-09T04:38:25.835071+00:00 DEBUG kernel: [  248.700606] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2018-08-09T04:38:25.846726+00:00 WARNING mosys[5687]: libminijail[5687]: logging seccomp filter failures
2018-08-09T04:38:25.867883+00:00 INFO crash_reporter[5542]: Processing selinux violation: dropped sample
2018-08-09T04:38:25.900852+00:00 INFO crash_reporter[5690]: libminijail[5690]: mount /dev/log -> /dev/log type ''
2018-08-09T04:38:25.974441+00:00 INFO crash_reporter[5691]: libminijail[5691]: mount /dev/log -> /dev/log type ''
2018-08-09T04:38:26.404996+00:00 DEBUG kernel: [  249.270396] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2018-08-09T04:38:26.405042+00:00 DEBUG kernel: [  249.270592] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2018-08-09T04:38:26.444977+00:00 DEBUG kernel: [  249.310042] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2018-08-09T04:38:26.445008+00:00 DEBUG kernel: [  249.310047] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2018-08-09T04:38:26.480226+00:00 INFO crash_reporter[5691]: Processing selinux violation: dropped sample
2018-08-09T04:38:26.481901+00:00 WARNING crash_reporter[5690]: [user] Received crash notification for dash[5689] sig 31, user 0 (handling)
2018-08-09T04:38:26.488592+00:00 INFO crash_reporter[5690]: State of crashed process [5689]: S (sleeping)
2018-08-09T04:38:26.490105+00:00 INFO crash_reporter[5690]: Accessing crash dir '/var/spool/crash' via symlinked handle '/proc/self/fd/5'
2018-08-09T04:38:26.493820+00:00 WARNING metrics_daemon[2967]: [WARNING:persistent_integer.cc(96)] cannot open /var/lib/metrics/Platform.DailyUseTime for reading: No such file or directory
2018-08-09T04:38:26.494816+00:00 WARNING metrics_daemon[2967]: [WARNING:persistent_integer.cc(96)] cannot open /var/lib/metrics/Platform.UserCrashInterval for reading: No such file or directory
2018-08-09T04:38:26.495528+00:00 WARNING metrics_daemon[2967]: [WARNING:persistent_integer.cc(96)] cannot open /var/lib/metrics/Platform.KernelCrashInterval for reading: No such file or directory
2018-08-09T04:38:26.496484+00:00 WARNING metrics_daemon[2967]: [WARNING:persistent_integer.cc(96)] cannot open /var/lib/metrics/daily.cycle for reading: No such file or directory
2018-08-09T04:38:26.498429+00:00 WARNING metrics_daemon[2967]: [WARNING:persistent_integer.cc(96)] cannot open /var/lib/metrics/Platform.AnyCrashesDaily for reading: No such file or directory
2018-08-09T04:38:26.499357+00:00 WARNING metrics_daemon[2967]: [WARNING:persistent_integer.cc(96)] cannot open /var/lib/metrics/Platform.UserCrashesDaily for reading: No such file or directory
2018-08-09T04:38:26.500242+00:00 WARNING metrics_daemon[2967]: [WARNING:persistent_integer.cc(96)] cannot open /var/lib/metrics/Platform.KernelCrashesDaily for reading: No such file or directory
2018-08-09T04:38:26.501122+00:00 WARNING metrics_daemon[2967]: [WARNING:persistent_integer.cc(96)] cannot open /var/lib/metrics/Platform.UncleanShutdownsDaily for reading: No such file or directory
2018-08-09T04:38:26.502286+00:00 WARNING metrics_daemon[2967]: [WARNING:persistent_integer.cc(96)] cannot open /var/lib/metrics/weekly.cycle for reading: No such file or directory
2018-08-09T04:38:26.503162+00:00 WARNING metrics_daemon[2967]: [WARNING:persistent_integer.cc(96)] cannot open /var/lib/metrics/Platform.AnyCrashesWeekly for reading: No such file or directory
2018-08-09T04:38:26.504127+00:00 WARNING metrics_daemon[2967]: [WARNING:persistent_integer.cc(96)] cannot open /var/lib/metrics/Platform.UserCrashesWeekly for reading: No such file or directory
2018-08-09T04:38:26.505568+00:00 WARNING metrics_daemon[2967]: [WARNING:persistent_integer.cc(96)] cannot open /var/lib/metrics/Platform.KernelCrashesWeekly for reading: No such file or directory
2018-08-09T04:38:26.506431+00:00 WARNING metrics_daemon[2967]: [WARNING:persistent_integer.cc(96)] cannot open /var/lib/metrics/Platform.UncleanShutdownsWeekly for reading: No such file or directory
2018-08-09T04:38:26.525570+00:00 INFO crash_reporter[5690]: Stored minidump to /var/spool/crash/dash.20180809.100826.5689.dmp
2018-08-09T04:38:26.584882+00:00 INFO crash_reporter[5698]: libminijail[5698]: mount /dev/log -> /dev/log type ''
2018-08-09T04:38:26.729239+00:00 WARNING mosys[5699]: libminijail[5699]: allowing syscall: socket
2018-08-09T04:38:26.729478+00:00 WARNING mosys[5699]: libminijail[5699]: allowing syscall: connect
2018-08-09T04:38:26.729556+00:00 WARNING mosys[5699]: libminijail[5699]: allowing syscall: gettimeofday
2018-08-09T04:38:26.729616+00:00 WARNING mosys[5699]: libminijail[5699]: allowing syscall: send
2018-08-09T04:38:26.729677+00:00 WARNING mosys[5699]: libminijail[5699]: allowing syscall: writev
2018-08-09T04:38:27.174999+00:00 DEBUG kernel: [  250.040421] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2018-08-09T04:38:27.215334+00:00 WARNING mosys[5699]: libminijail[5699]: logging seccomp filter failures
2018-08-09T04:38:27.225279+00:00 DEBUG kernel: [  250.089986] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2018-08-09T04:38:27.268267+00:00 INFO crash_reporter[5705]: libminijail[5705]: mount /dev/log -> /dev/log type ''
2018-08-09T04:38:27.277154+00:00 INFO crash_reporter[5698]: Processing selinux violation: dropped sample
2018-08-09T04:38:28.124995+00:00 DEBUG kernel: [  250.990400] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2018-08-09T04:38:28.164972+00:00 DEBUG kernel: [  251.029971] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2018-08-09T04:38:28.216314+00:00 WARNING crash_reporter[5705]: [user] Received crash notification for dash[5704] sig 31, user 0 (handling)
2018-08-09T04:38:28.236630+00:00 INFO crash_reporter[5705]: State of crashed process [5704]: S (sleeping)
2018-08-09T04:38:28.237996+00:00 INFO crash_reporter[5705]: Accessing crash dir '/var/spool/crash' via symlinked handle '/proc/self/fd/5'
2018-08-09T04:38:28.254143+00:00 INFO crash_reporter[5705]: Stored minidump to /var/spool/crash/dash.20180809.100828.5704.dmp
2018-08-09T04:38:28.604208+00:00 INFO session_manager[5720]: [INFO:session_manager_main.cc(212)] Will wait 3s for graceful browser exit.

# session manager restarts and launches chrome

2018-08-09T04:38:28.612602+00:00 INFO session_manager[5720]: [INFO:session_manager_service.cc(148)] SessionManagerService starting
2018-08-09T04:38:28.958422+00:00 INFO session_manager[5720]: [INFO:browser_job.cc(148)] Running browser /opt/google/chrome/chrome ...





# mosys enters a crash loop

2018-08-09T04:38:28.958422+00:00 INFO session_manager[5720]: [INFO:browser_job.cc(148)] Running browser /opt/google/chrome/chrome --ppapi-flash-path=/opt/google/chrome/pepper/libpepflashplayer.so --ppapi-flash-version=30.0.0.142 --ui-prioritize-in-gpu-process --use-gl=egl --gpu-sandbox-failures-fatal=yes --gpu-sandbox-start-early --enable-logging --log-level=1 --use-cras --enable-wayland-server --user-data-dir=/home/chronos --system-developer-mode --login-profile=user --has-chromeos-keyboard --enable-touchview --guest-wallpaper-large=/usr/share/chromeos-assets/wallpaper/guest_large.jpg --guest-wallpaper-small=/usr/share/chromeos-assets/wallpaper/guest_small.jpg --child-wallpaper-large=/usr/share/chromeos-assets/wallpaper/child_large.jpg --child-wallpaper-small=/usr/share/chromeos-assets/wallpaper/child_small.jpg --default-wallpaper-large=/usr/share/chromeos-assets/wallpaper/oem_large.jpg --default-wallpaper-small=/usr/share/chromeos-assets/wallpaper/oem_small.jpg --default-wallpaper-is-oem --enable-consumer-kiosk --arc-availability=officially-supported --arc-transition-migration-required --enterprise-enrollment-initial-modulus=15 --enterprise-enrollment-modulus-limit=19 --login-manager --vmodule=*arc/*=1,*/assistant/*=1,*chromeos/login/*=1,auto_enrollment_controller=1,*/ui/ozone/*=1,*/ui/display/manager/chromeos/*=1,*night_light*=1,update_engine=1,component_updater_service=1,power_button_observer=2,webui_login_view=2,lock_state_controller=2,webui_screen_locker=2,screen_locker=2
2018-08-09T04:38:29.535087+00:00 DEBUG kernel: [  252.401432] SELinux: initialized (dev proc, type proc), uses genfs_contexts
2018-08-09T04:38:30.155059+00:00 DEBUG kernel: [  253.020147] SELinux: initialized (dev proc, type proc), uses genfs_contexts
2018-08-09T04:38:30.185050+00:00 DEBUG kernel: [  253.055793] SELinux: initialized (dev proc, type proc), uses genfs_contexts
2018-08-09T04:38:30.405692+00:00 WARNING mosys[5885]: libminijail[5885]: allowing syscall: socket
2018-08-09T04:38:30.405778+00:00 WARNING mosys[5885]: libminijail[5885]: allowing syscall: connect
2018-08-09T04:38:30.405801+00:00 WARNING mosys[5885]: libminijail[5885]: allowing syscall: gettimeofday
2018-08-09T04:38:30.405818+00:00 WARNING mosys[5885]: libminijail[5885]: allowing syscall: send
2018-08-09T04:38:30.405840+00:00 WARNING mosys[5885]: libminijail[5885]: allowing syscall: writev
2018-08-09T04:38:30.406162+00:00 ERR mosys[5885]: libminijail[5885]: unshare(CLONE_NEWNS) failed: Operation not permitted
2018-08-09T04:38:30.433943+00:00 INFO crash_reporter[5886]: libminijail[5886]: mount /dev/log -> /dev/log type ''
2018-08-09T04:38:30.595022+00:00 DEBUG kernel: [  253.460681] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2018-08-09T04:38:30.635124+00:00 DEBUG kernel: [  253.500805] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2018-08-09T04:38:30.684545+00:00 WARNING crash_reporter[5886]: [user] Received crash notification for mosys[5885] sig 6, user 1000 (handling)
2018-08-09T04:38:30.689690+00:00 INFO crash_reporter[5886]: State of crashed process [5885]: S (sleeping)
2018-08-09T04:38:30.695749+00:00 ERR crash_reporter[5886]: Could not get active user sessions, using default.
2018-08-09T04:38:30.696395+00:00 INFO crash_reporter[5886]: Accessing crash dir '/home/chronos/crash' via symlinked handle '/proc/self/fd/6'
2018-08-09T04:38:30.723701+00:00 INFO crash_reporter[5886]: Stored minidump to /home/chronos/crash/mosys.20180809.100830.5885.dmp
2018-08-09T04:38:30.827954+00:00 WARNING mosys[5906]: libminijail[5906]: allowing syscall: socket
2018-08-09T04:38:30.828189+00:00 WARNING mosys[5906]: libminijail[5906]: allowing syscall: connect
2018-08-09T04:38:30.828269+00:00 WARNING mosys[5906]: libminijail[5906]: allowing syscall: gettimeofday
2018-08-09T04:38:30.828332+00:00 WARNING mosys[5906]: libminijail[5906]: allowing syscall: send
2018-08-09T04:38:30.828395+00:00 WARNING mosys[5906]: libminijail[5906]: allowing syscall: writev
2018-08-09T04:38:30.828729+00:00 ERR mosys[5906]: libminijail[5906]: unshare(CLONE_NEWNS) failed: Operation not permitted
.....

2018-08-09T04:38:57.605562+00:00 WARNING crash_reporter[6249]: [user] Received crash notification for mosys[6248] sig 6, user 1000 (handling)
2018-08-09T04:38:57.618233+00:00 INFO crash_reporter[6249]: State of crashed process [6248]: S (sleeping)
2018-08-09T04:38:57.625634+00:00 ERR crash_reporter[6249]: Could not get active user sessions, using default.
2018-08-09T04:38:57.626369+00:00 INFO crash_reporter[6249]: Accessing crash dir '/home/chronos/crash' via symlinked handle '/proc/self/fd/6'
2018-08-09T04:38:57.654777+00:00 INFO crash_reporter[6249]: Stored minidump to /home/chronos/crash/mosys.20180809.100857.6248.dmp
2018-08-09T04:38:57.721287+00:00 WARNING mosys[6258]: libminijail[6258]: allowing syscall: socket
2018-08-09T04:38:57.721538+00:00 WARNING mosys[6258]: libminijail[6258]: allowing syscall: connect
2018-08-09T04:38:57.721631+00:00 WARNING mosys[6258]: libminijail[6258]: allowing syscall: gettimeofday
2018-08-09T04:38:57.721741+00:00 WARNING mosys[6258]: libminijail[6258]: allowing syscall: send
2018-08-09T04:38:57.721842+00:00 WARNING mosys[6258]: libminijail[6258]: allowing syscall: writev
2018-08-09T04:38:57.722318+00:00 ERR mosys[6258]: libminijail[6258]: unshare(CLONE_NEWNS) failed: Operation not permitted
2018-08-09T04:38:57.759817+00:00 INFO crash_reporter[6259]: libminijail[6259]: mount /dev/log -> /dev/log type ''
2018-08-09T04:38:58.345013+00:00 DEBUG kernel: [  281.210430] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2018-08-09T04:38:58.374967+00:00 DEBUG kernel: [  281.239945] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs



# android container is started, which likely means we're in session
2018-08-09T04:38:58.820788+00:00 INFO session_manager[5720]: [INFO:android_oci_wrapper.cc(121)] run_oci PID: 6288


So it seems to me shutdown is fine, starting chrome back up is taking a long time, possibly due to all of the mosys crashes.

Comment 8 Deleted

Comment 9 by geohsu@chromium.org, Aug 10 

Hi, Is this still a Dev blocker? If so, please update here with the plan to address this. Thanks.

Comment 10 by la...@chromium.org, Aug 13

Cc: -la...@chromium.org jclinton@chromium.org
Owner: samanthamiller@chromium.org
To samanthamiller@, who implemented mosys minijail.

Comment 12 by samanthamiller@google.com, Aug 13 

I would have expected the mosys crash loop to be fixed by https://chromium-review.googlesource.com/c/chromiumos/platform/mosys/+/1167561 . Is this still happening?

Comment 13 by samanthamiller@google.com, Aug 14 

Looks like Jason was correct, and I believe the mosys crash loop is fixed by the CL he mentioned.

Comment 14 by samanthamiller@google.com, Aug 15 

I don't have a way to test this. Can someone check what state this is in?

Comment 15 by geohsu@chromium.org, Aug 16

Labels: -ReleaseBlock-Dev ReleaseBlock-Beta
Moving this to ReleaseBlock-Beta. We should be able to live with this in Dev and verify it for Beta. Please change if you believe this is not correct. Thanks.

Comment 16 by samanthamiller@google.com, Aug 22

Status: Fixed (was: Assigned)
If anyone sees this again, feel free to reopen.
►

Sign in to add a comment