Logs and videos for this issue in this link:
https://pantheon.corp.google.com/storage/browser/chromiumos-test-logs/bugfiles/cr/777935/

The list of crashes observed:
f874471e26225e88 (Local Crash ID: Chrome)

Crash report uploaded on Monday, 23 October 2017 at 18:09:34

Provide additional details.

Crash Report ID 258c8b37a7c3e9b1 (Local Crash ID: Chrome)

Crash Report ID d340f53873fac714 (Local Crash ID: ChromeOS_ARC)

Crash Report ID db7c4eaa4535e5c7 (Local Crash ID: ChromeOS_ARC)

Crash Report ID 310777c15309a204 (Local Crash ID: Chrome)

Crash Report ID ae7141e52c454091 (Local Crash ID: ChromeOS_ARC)

Crash Report ID 9db07c9b4598c218 (Local Crash ID: Chrome)

Crash Report ID 52f07025bc8862be (Local Crash ID: ChromeOS_ARC)

Crash Report ID 5b53801a09f53208 (Local Crash ID: ChromeOS_ARC)

Crash Report ID 4bccccfbc9c2bb3b (Local Crash ID: Chrome)

Crash Report ID 5a7d0877e4dd5464 (Local Crash ID: Chrome)

Crash Report ID db5c61e5dc7494dc (Local Crash ID: ChromeOS_ARC)

Crash Report ID 247b288cf2a88d28 (Local Crash ID: Chrome)

Crash Report ID d871a021e3e91504 (Local Crash ID: ChromeOS_ARC)

Crash Report ID 6e7f005810010ea9 (Local Crash ID: Chrome)

Crash Report ID e8bdf0aee5d342ad (Local Crash ID: Chrome)

Crash Report ID ec8c3be216f33d39 (Local Crash ID: ChromeOS_ARC)

Crash Report ID 971eb3b8de151064 (Local Crash ID: Chrome)

Crash Report ID 6cd951b25c46455b (Local Crash ID: Chrome)

Many of the recent crashes on that device are marked "no files to process" not sure why. The first crash I see with a meaningful signature is an instance of  bug 741031 .

One theory is that the ARC crash on startup is interfering with the ability of the system to complete the language flip.

Settings is almost certainly innocent in this process.

There's not a good clear owner here. rkc@ since this seems to be a hiccup on signin can someone on your team take a look?

Any updates?

+takaoka who touched Android/Chrome language sync recently but not sure that made into M63.

+hidehiko, hashimoto, khmel
who touched it probably around that time.
chrome/browser/chromeos/arc/intent_helper/arc_settings_service.cc

Re #5, 6. The change takaoka@ made is not in M63. Mine is s/base::MakeUnique/std::make_unique/ so should be safer. hashimoto@'s change is fixing crash issue, and looks much safer.
What change khmel@ made do you refer, uekawa-san?

I believe this is the same issue as  https://crbug.com/774889#c3  .

Assigning to IME folks. Not closing yet, as they may have more information.

#7,  I was thinking of https://chromium-review.googlesource.com/c/chromium/src/+/651430 but that's merged to M61/M62 too if this is a M63 thing then it's probably different.

Re #9: The issue is about the IME extension, so it should not be related to internationalization of UI.

Note that I can't reproduce the issue on 64.0.3264.0/10105.0.0.

I've tried on two machines that I happened to have my hands on
10068.0.0 intel
10064.0.0 arm
and couldn't reproduce the crash at #1.

I also could not reproduce the crash.
But I do see this message ("Chrome was not shut down correctly...") , and if I run Chrome under the debugger, my UI language doesn't change.

It sounds like Local State is not written to disk on Chrome exit. Probably user prefs too (as there is a message).

Stack trace on exit is like this:


Program received signal SIGTERM, Terminated.                                     
0x00007fd13aedce2b in find (this=0xfcf55fae6e0, __k=@0x7fff0185aa38: 0xfcf57270d80)
    at ../.cros_cache/chrome-sdk/tarballs/peppy+10110.0.0+target_toolchain/usr/bin/../include/c++/v1/unordered_set:563
563         iterator       find(const key_type& __k)       {return __table_.find(__k);}
(gdb) bt                                                                         
#0  0x00007fd13aedce2b in find (this=0xfcf55fae6e0, __k=@0x7fff0185aa38: 0xfcf57270d80)
    at ../.cros_cache/chrome-sdk/tarballs/peppy+10110.0.0+target_toolchain/usr/bin/../include/c++/v1/unordered_set:563
#1  viz::DelayBasedBeginFrameSource::RemoveObserver (this=0xfcf55fae6c0, obs=0xfcf57270d80) at components/viz/common/frame_sinks/begin_frame_source.cc:222
#2  0x00007fd13b979308 in viz::DisplayScheduler::StopObservingBeginFrames (this=0xfcf57270d80) at components/viz/service/display/display_scheduler.cc:276
#3  0x00007fd13b979983 in viz::DisplayScheduler::AttemptDrawAndSwap (this=0xfcf57270d80) at components/viz/service/display/display_scheduler.cc:480
#4  0x00007fd13b9791cf in viz::DisplayScheduler::OnBeginFrameDeadline (this=0xfcf57270d80) at components/viz/service/display/display_scheduler.cc:489
#5  0x00007fd13023806f in base::internal::FunctorTraits<void (media::AliveChecker::*)(), void>::Invoke<base::WeakPtr<media::AliveChecker>>(void (media::AliveChecker::*)(), base::WeakPtr<media::AliveChecker>&&) (
    method=(void (media::AliveChecker::*)(media::AliveChecker * const)) 0x7fd13b979000 <viz::DisplayScheduler::OnBeginFrameDeadline()>, 
    receiver_ptr=<unknown type in out_peppy/Debug/chrome, CU 0x0, DIE 0x12092>) at base/bind_internal.h:194
#6  0x00007fd13b97ee5a in base::internal::InvokeHelper<true, void>::MakeItSo<void (viz::DisplayScheduler::* const&)(), base::WeakPtr<viz::DisplayScheduler> const&> (
    functor=@0xfcf56827bb0: (void (viz::DisplayScheduler::*)(viz::DisplayScheduler * const)) 0x7fd13b979000 <viz::DisplayScheduler::OnBeginFrameDeadline()>, weak_ptr=...)
    at base/bind_internal.h:297                                                  
#7  0x00007fd13b97edf0 in base::internal::Invoker<base::internal::BindState<void (viz::DisplayScheduler::*)(), base::WeakPtr<viz::DisplayScheduler> >, void ()>::RunImpl<void (viz::DisplayScheduler::* const&)(), std::__1::tuple<base::WeakPtr<viz::DisplayScheduler> > const&, 0ul>(void (viz::DisplayScheduler::* const&)(), std::__1::tuple<base::WeakPtr<viz::DisplayScheduler> > const&, std::__1::integer_sequence<unsigned long, 0ul>) (
    functor=@0xfcf56827bb0: (void (viz::DisplayScheduler::*)(viz::DisplayScheduler * const)) 0x7fd13b979000 <viz::DisplayScheduler::OnBeginFrameDeadline()>, bound=...)
    at base/bind_internal.h:351                                                  
#8  0x00007fd13b97ed3c in base::internal::Invoker<base::internal::BindState<void (viz::DisplayScheduler::*)(), base::WeakPtr<viz::DisplayScheduler> >, void ()>::Run(base::internal::BindStateBase*) (base=0xfcf56827b90)
    at base/bind_internal.h:333                                                  
#9  0x00007fd130236cfd in base::RepeatingCallback<void ()>::Run() const & (this=0xfcf57270e58) at base/callback.h:94
#10 0x00007fd1302b5275 in base::internal::CancelableCallbackImpl<base::RepeatingCallback<void ()> >::ForwardRepeating<>() (this=0xfcf57270e58) at base/cancelable_callback.h:120
#11 0x00007fd13023806f in base::internal::FunctorTraits<void (media::AliveChecker::*)(), void>::Invoke<base::WeakPtr<media::AliveChecker>>(void (media::AliveChecker::*)(), base::WeakPtr<media::AliveChecker>&&) (
    method=(void (media::AliveChecker::*)(media::AliveChecker * const)) 0x7fd1302b5260 <base::internal::CancelableCallbackImpl<base::RepeatingCallback<void ()> >::ForwardRepeating<>()>,
    receiver_ptr=<unknown type in out_peppy/Debug/chrome, CU 0x0, DIE 0x12092>) at base/bind_internal.h:194
#12 0x00007fd1302b549a in base::internal::InvokeHelper<true, void>::MakeItSo<void (base::internal::CancelableCallbackImpl<base::RepeatingCallback<void ()> >::* const&)(), base::WeakPtr<base::internal::CancelableCallbackImpl<base::RepeatingCallback<void ()> > > const&>(void (base::internal::CancelableCallbackImpl<base::RepeatingCallback<void ()> >::* const&)(), base::WeakPtr<base::internal::CancelableCallbackImpl<base::RepeatingCallback<void ()> > > const&) (
    functor=@0xfcf5aad2ed0: (void (base::internal::CancelableCallbackImpl<base::RepeatingCallback<void ()> >::*)(base::internal::CancelableCallbackImpl<base::RepeatingCallback<void ()> > * const)) 0x7fd1302b5260 <base::internal::CancelableCallbackImpl<base::RepeatingCallback<void ()> >::ForwardRepeating<>()>, weak_ptr=...) at base/bind_internal.h:297
#13 0x00007fd1302b5430 in base::internal::Invoker<base::internal::BindState<void (base::internal::CancelableCallbackImpl<base::RepeatingCallback<void ()> >::*)(), base::WeakPtr<base::internal::CancelableCallbackImpl<base::RepeatingCallback<void ()> > > >, void ()>::RunImpl<void (base::internal::CancelableCallbackImpl<base::RepeatingCallback<void ()> >::* const&)(), std::__1::tuple<base::WeakPtr<base::internal::CancelableCallbackImpl<base::RepeatingCallback<void ()> > > > const&, 0ul>(void (base::internal::CancelableCallbackImpl<base::RepeatingCallback<void ()> >::* const&)(), std::__1::tuple<base::WeakPtr<base::internal::CancelableCallbackImpl<base::RepeatingCallback<void ()> > > > const&, std::__1::integer_sequence<unsigned long, 0ul>) (
    functor=@0xfcf5aad2ed0: (void (base::internal::CancelableCallbackImpl<base::RepeatingCallback<void ()> >::*)(base::internal::CancelableCallbackImpl<base::RepeatingCallback<void ()> > * const)) 0x7fd1302b5260 <base::internal::CancelableCallbackImpl<base::RepeatingCallback<void ()> >::ForwardRepeating<>()>, bound=...) at base/bind_internal.h:351
#14 0x00007fd1302b537c in base::internal::Invoker<base::internal::BindState<void (base::internal::CancelableCallbackImpl<base::RepeatingCallback<void ()> >::*)(), base::WeakPtr<base::internal::CancelableCallbackImpl<base::RepeatingCallback<void ()> > > >, void ()>::Run(base::internal::BindStateBase*) (base=<error reading variable: Cannot access memory at address 0x7fff0185b138>) at base/bind_internal.h:333
Backtrace stopped: Cannot access memory at address 0x7fff0185b148                
(gdb)  

This is ToT, I'll try M63 build tomorrow.

There is no crash in M63 either. Preferences are not stored to disk on sign out.

Here is stack trace on exit:

Program received signal SIGTERM, Terminated.
__lll_unlock_wake () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:371
371	../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S: No such file or directory.
(gdb) bt
#0  __lll_unlock_wake () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:371
#1  0x00007f8e5a7831a2 in __pthread_mutex_unlock_usercnt (mutex=0x1b2b29971120, decr=<optimized out>) at pthread_mutex_unlock.c:55
#2  0x00007f8e5bd9fd3b in base::internal::LockImpl::Unlock (this=0x1b2b29971120) at ../../base/synchronization/lock_impl.h:70
#3  0x00007f8e5bd9f676 in base::Lock::Release (this=0x1b2b29971118) at ../../base/synchronization/lock.h:50
#4  0x00007f8e5bd9ec0b in base::AutoLock::~AutoLock (this=0x7fffeb5ecfa0) at ../../base/synchronization/lock.h:124
#5  0x00007f8e62e68565 in base::internal::IncomingTaskQueue::PostPendingTask (this=0x1b2b29971000, pending_task=0x7fffeb5ed1e8) at ../../base/message_loop/incoming_task_queue.cc:319
#6  0x00007f8e62e681ca in base::internal::IncomingTaskQueue::AddToIncomingQueue(base::Location const&, base::OnceCallback<void ()>, base::TimeDelta, base::Nestable) (this=0x1b2b29971000, 
    from_here=..., task=..., delay=..., nestable=base::Nestable::kNestable) at ../../base/message_loop/incoming_task_queue.cc:87
#7  0x00007f8e62ca1854 in base::internal::MessageLoopTaskRunner::PostDelayedTask(base::Location const&, base::OnceCallback<void ()>, base::TimeDelta) (this=0x1b2b29a2b3c0, from_here=..., 
    task=..., delay=...) at ../../base/message_loop/message_loop_task_runner.cc:31
#8  0x00007f8e62d7f021 in base::TaskRunner::PostTask(base::Location const&, base::OnceCallback<void ()>) (this=0x1b2b29a2b3c0, from_here=..., task=...) at ../../base/task_runner.cc:44
#9  0x00007f8e64f1a308 in dbus::ObjectProxy::CallMethodInternal(dbus::MethodCall*, int, base::OnceCallback<void (dbus::Response*, dbus::ErrorResponse*)>) (this=0x1b2b29a02840, method_call=
    0x7fffeb5eda80, timeout_ms=-1, callback=...) at ../../dbus/object_proxy.cc:180
#10 0x00007f8e64f19dbc in dbus::ObjectProxy::CallMethod(dbus::MethodCall*, int, base::OnceCallback<void (dbus::Response*)>) (this=0x1b2b29a02840, method_call=0x7fffeb5eda80, timeout_ms=-1, 
    callback=...) at ../../dbus/object_proxy.cc:128
#11 0x00007f8e64e180f1 in chromeos::SessionManagerClientImpl::StopSession (this=0x1b2b299c8380) at ../../chromeos/dbus/session_manager_client.cc:223
#12 0x00007f8e622dd64e in browser_shutdown::NotifyAndTerminate (fast_path=true, reboot_policy=browser_shutdown::RebootPolicy::kOptionalReboot)
    at ../../chrome/browser/lifetime/termination_notification.cc:67
#13 0x00007f8e622dd522 in browser_shutdown::NotifyAndTerminate (fast_path=true) at ../../chrome/browser/lifetime/termination_notification.cc:34
#14 0x00007f8e620518b5 in chrome::AttemptUserExit () at ../../chrome/browser/lifetime/application_lifetime.cc:210
#15 0x00007f8e69901c05 in settings::BrowserLifetimeHandler::HandleSignOutAndRestart (this=0x1b2b2efc1720, args=0x7fffeb5ee5a8)
    at ../../chrome/browser/ui/webui/settings/browser_lifetime_handler.cc:56
#16 0x00007f8e5bd89145 in base::internal::FunctorTraits<void (media::AudioDebugFileWriter::AudioFileWriter::*)(media::AudioBus const*), void>::Invoke<media::AudioDebugFileWriter::AudioFileWriter*, media::AudioBus*>(void (media::AudioDebugFileWriter::AudioFileWriter::*)(media::AudioBus const*), media::AudioDebugFileWriter::AudioFileWriter*&&, media::AudioBus*&&) (method=
    (void (media::AudioDebugFileWriter::AudioFileWriter::*)(media::AudioDebugFileWriter::AudioFileWriter * const, const media::AudioBus *)) 0x7f8e69901bf0 <settings::BrowserLifetimeHandler::HandleSignOutAndRestart(base::ListValue const*)>, receiver_ptr=<unknown type in chromium.branch_3239_M63/src/out_peppy/Debug/chrome, CU 0x0, DIE 0x10b0b>, 
    args=<unknown type in chromium.branch_3239_M63/src/out_peppy/Debug/chrome, CU 0x0, DIE 0x10b17>) at ../../base/bind_internal.h:194
#17 0x00007f8e5c2ad5e6 in base::internal::InvokeHelper<false, void>::MakeItSo<void (media::DeviceMonitorLinux::* const&)(udev_device*), media::DeviceMonitorLinux*, udev_device*>(void (media::DeviceMonitorLinux::* const&)(udev_device*), media::DeviceMonitorLinux*&&, udev_device*&&) (functor=
    @0x1b2b2b3f17a0: (void (media::DeviceMonitorLinux::*)(media::DeviceMonitorLinux * const, udev_device *)) 0x7f8e69901bf0 <settings::BrowserLifetimeHandler::HandleSignOutAndRestart(base::ListValue const*)>, args=<unknown type in chromium.branch_3239_M63/src/out_peppy/Debug/chrome, CU 0x0, DIE 0xb9cf>, 
    args=<unknown type in chromium.branch_3239_M63/src/out_peppy/Debug/chrome, CU 0x0, DIE 0xb9cf>) at ../../base/bind_internal.h:277
#18 0x00007f8e69902034 in base::internal::Invoker<base::internal::BindState<void (settings::BrowserLifetimeHandler::*)(base::ListValue const*), base::internal::UnretainedWrapper<settings::BrowserLifetimeHandler> >, void (base::ListValue const*)>::RunImpl<void (settings::BrowserLifetimeHandler::* const&)(base::ListValue const*), std::tuple<base::internal::UnretainedWrapper<settings::BrowserLifetimeHandler> > const&, 0ul>(void (settings::BrowserLifetimeHandler::* const&)(base::ListValue const*), std::tuple<base::internal::UnretainedWrapper<settings::BrowserLifetimeHandler> > const&, std::integer_sequence<unsigned long, 0ul>, base::ListValue const*&&) (functor=
    @0x1b2b2b3f17a0: (void (settings::BrowserLifetimeHandler::*)(settings::BrowserLifetimeHandler * const, const base::ListValue *)) 0x7f8e69901bf0 <settings::BrowserLifetimeHandler::HandleSignOutAndRestart(base::ListValue const*)>, bound=std::tuple containing = {...}, 
    unbound_args=<unknown type in chromium.branch_3239_M63/src/out_peppy/Debug/chrome, CU 0x0, DIE 0x3c63>) at ../../base/bind_internal.h:349
#19 0x00007f8e69901f5c in base::internal::Invoker<base::internal::BindState<void (settings::BrowserLifetimeHandler::*)(base::ListValue const*), base::internal::UnretainedWrapper<settings::BrowserLifetimeHandler> >, void (base::ListValue const*)>::Run(base::internal::BindStateBase*, base::ListValue const*&&) (base=0x1b2b2b3f1780, 
    unbound_args=<unknown type in chromium.branch_3239_M63/src/out_peppy/Debug/chrome, CU 0x0, DIE 0x3be6>) at ../../base/bind_internal.h:331
#20 0x00007f8e5be1625c in base::RepeatingCallback<void (media::VirtualAudioInputStream*)>::Run(media::VirtualAudioInputStream*) const & (this=0x1b2b2bccb3e8, args=0x7fffeb5ee5a8)
    at ../../base/callback.h:92
#21 0x00007f8e5e8f9c98 in content::WebUIImpl::ProcessWebUIMessage (this=0x1b2b2f4ef540, source_url=..., message="signOutAndRestart", args=...)
    at ../../content/browser/webui/web_ui_impl.cc:252
#22 0x00007f8e5e8f8b8d in content::WebUIImpl::OnWebUISend (this=0x1b2b2f4ef540, sender=0x1b2b2cc53000, source_url=..., message="signOutAndRestart", args=...)
    at ../../content/browser/webui/web_ui_impl.cc:119
#23 0x00007f8e5e8fbeaf in IPC::DispatchToMethodImpl<content::WebUIImpl, void (content::WebUIImpl::*)(content::RenderFrameHost*, GURL const&, std::string const&, base::ListValue const&), content::RenderFrameHost, std::tuple<GURL, std::string, base::ListValue>, 0ul, 1ul, 2ul>(content::WebUIImpl*, void (content::WebUIImpl::*)(content::RenderFrameHost*, GURL const&, std::string const&, base::ListValue const&), content::RenderFrameHost*, std::tuple<GURL, std::string, base::ListValue>&&, std::integer_sequence<unsigned long, 0ul, 1ul, 2ul>) (obj=0x1b2b2f4ef540, method=
    (void (content::WebUIImpl::*)(content::WebUIImpl * const, content::RenderFrameHost *, const GURL &, const std::basic_string<char, std::char_traits<char>, std::allocator<char> > &, const base::ListValue &)) 0x7f8e5e8f89f0 <content::WebUIImpl::OnWebUISend(content::RenderFrameHost*, GURL const&, std::string const&, base::ListValue const&)>, parameter=0x1b2b2cc53000, 
    tuple=<unknown type in chromium.branch_3239_M63/src/out_peppy/Debug/chrome, CU 0x0, DIE 0x1b868>) at ../../ipc/ipc_message_templates.h:64
---Type <return> to continue, or q <return> to quit---
#24 0x00007f8e5e8fbdbb in IPC::DispatchToMethod<content::WebUIImpl, content::RenderFrameHost, GURL const&, std::string const&, base::ListValue const&, std::tuple<GURL, std::string, base::ListValue> > (obj=0x1b2b2f4ef540, method=
    (void (content::WebUIImpl::*)(content::WebUIImpl * const, content::RenderFrameHost *, const GURL &, const std::basic_string<char, std::char_traits<char>, std::allocator<char> > &, const base::ListValue &)) 0x7f8e5e8f89f0 <content::WebUIImpl::OnWebUISend(content::RenderFrameHost*, GURL const&, std::string const&, base::ListValue const&)>, parameter=0x1b2b2cc53000, 
    tuple=<unknown type in chromium.branch_3239_M63/src/out_peppy/Debug/chrome, CU 0x0, DIE 0x1b7f4>) at ../../ipc/ipc_message_templates.h:76
#25 0x00007f8e5e8fa870 in IPC::MessageT<FrameHostMsg_WebUISend_Meta, std::tuple<GURL, std::string, base::ListValue>, void>::Dispatch<content::WebUIImpl, content::WebUIImpl, content::RenderFrameHost, void (content::WebUIImpl::*)(content::RenderFrameHost*, GURL const&, std::string const&, base::ListValue const&)> (msg=0x1b2b2c9275d0, obj=0x1b2b2f4ef540, sender=0x1b2b2f4ef540, 
    parameter=0x1b2b2cc53000, func=
    (void (content::WebUIImpl::*)(content::WebUIImpl * const, content::RenderFrameHost *, const GURL &, const std::basic_string<char, std::char_traits<char>, std::allocator<char> > &, const base::ListValue &)) 0x7f8e5e8f89f0 <content::WebUIImpl::OnWebUISend(content::RenderFrameHost*, GURL const&, std::string const&, base::ListValue const&)>)
    at ../../ipc/ipc_message_templates.h:146

#26 0x00007f8e5e8f89bc in content::WebUIImpl::OnMessageReceived (this=0x1b2b2f4ef540, message=..., sender=0x1b2b2cc53000) at ../../content/browser/webui/web_ui_impl.cc:101
#27 0x00007f8e5e86795b in content::WebContentsImpl::OnMessageReceived (this=0x1b2b2df78a00, render_frame_host=0x1b2b2cc53000, message=...)
    at ../../content/browser/web_contents/web_contents_impl.cc:814

#28 0x00007f8e5ddf754a in content::RenderFrameHostImpl::OnMessageReceived (this=0x1b2b2cc53000, msg=...) at ../../content/browser/frame_host/render_frame_host_impl.cc:851
#29 0x00007f8e5e477cd0 in content::RenderProcessHostImpl::OnMessageReceived (this=<error reading variable: Cannot access memory at address 0x7fffeb5eef30>, 
    msg=<error reading variable: Cannot access memory at address 0x7fffeb5eee50>) at ../../content/browser/renderer_host/render_process_host_impl.cc:2913
Backtrace stopped: Cannot access memory at address 0x7fffeb5eef48
(gdb) 

Assigning to pref owners.

You can trigger writing local state and user prefs via PrefService::CommitPendingWrite.

We may need to call in some ChromeOS folks here.

Assigning to pmarko@ who worked on setting the locale during shutdown here https://chromium.googlesource.com/chromium/src/+/8c3ffb5e698796da543bcbf2192bbb5aebb90807

Any updates? M63 goes stable in < 2 weeks and this is marked as a blocker.

Sorry, I was OOO yesterday (forgot to mark myself as such :/) I'm taking a look at this today.

There are two separate aspects to "language":
- the login screen language shall be always the owner's language (except if the device is managd).
- the user session language shall adhere to wheatever has been set by the user.

The code on shutdown (mentioned in Comment #21) only tries to set the login screen language into LocalState, and does trigger LocalState pref write (CommitPendingWrite) when it changes anything.

Does anyone know what code would actually be responsible for ensuring that the profile PrefService is written out to disk on shutdown? I only see a bunch of CommitPendingWrites for LocalState, but nowhere do I see a profile CommitPendingWrite near any shutdown code.

E.g. the "Chrome did not exit cleanly" message relies on the pref set by SetExitType(EXIT_NORMAL) in ProfileImpl::~ProfileImpl[1] to be actually written to disk, but ProfileImpl::prefs_ simply goes out of scope when ProfileImpl is destroyed.

PrefService itself doesn't do anything special in its dtor, nor does PrefServiceSyncable.

Anyway, I'll try to debug locally and will report what I find.

[1] https://cs.chromium.org/chromium/src/chrome/browser/profiles/profile_impl.cc?rcl=4684cfaf8fc4a4f88a5dbec29f02f3b322d6fe57&l=757

Looks like BrowserProcessImpl::EndSession[1] is responsible for writing out profile prefs since  bug 470501 . I'll check if we get there during the shutdown from settings UI.

[1] https://cs.chromium.org/chromium/src/chrome/browser/browser_process_impl.cc?rcl=086152a09ba0e2bc4e6a245d132f77b5b745ae52&l=480

Hrm, I couldn't reproduce this on Chrome OS, edgar, 63.0.3239.63. Are we sure it's still happening? What did you do to reproduce it Alexander?

I tried changing language English->German, German->English, English->Chinese(Simplified), Chinese(Simplified)->Slovak.

I tested both enterprise-managed and consumer modes (not enrolled to a domain), but the user session was always in the language I last set, and the login screen language was also behaving as expected.

Any updates? M63 goes stable in 5 days and this is marked as a blocker.

I can still reproduce this with 63.0.3239.70. Checking.

Which device did you repro on? I assume it was not enterprise-enrolled?
Thanks.

kevin.

I suspect it is gpu process that dies and kills everything on exit.
But it is difficult to reproduce.
I spent 5 hours trying to come with a stable reproduction scenario, but I still don't have it.

Basically, the problem looks like this:

localhost ~ # tail /var/log/ui/ui.20171128-185838
[5068:5068:1128/185919.403239:ERROR:gl_image_native_pixmap.cc(240)] Failed to flush rendering
[5068:5068:1128/185919.681565:ERROR:gl_image_native_pixmap.cc(240)] Failed to flush rendering
[5068:5068:1128/185920.066887:ERROR:gl_image_native_pixmap.cc(240)] Failed to flush rendering
[5068:5068:1128/185920.129487:ERROR:gl_image_native_pixmap.cc(240)] Failed to flush rendering
[5068:5068:1128/185920.181802:ERROR:gl_image_native_pixmap.cc(240)] Failed to flush rendering
[5068:5068:1128/185920.215714:ERROR:gl_image_native_pixmap.cc(240)] Failed to flush rendering
[4955:5033:1128/185934.346368:ERROR:sandbox_ipc_linux.cc(443)] sendmsg: Broken pipe (32)

Crash dump received by crash_reporter
Parent failed to complete crash dump.
localhost ~ # 

I suspect it to be board/platform/GPU/whatever specific. Sadly I don't have caroline ;(

Another problem are these messages in dmesg:

[   50.506865] binder: 5266:5266 transaction failed 29189, size 0-0
[   62.672845] Unhandled debug exception: aarch32 BKPT (0xe0000070) at 0x0000000040222300
[   62.672874] Unhandled debug exception: aarch32 BKPT (0xe000007f) at 0x0000000040222300
[   71.638994] Unhandled debug exception: aarch32 BKPT (0xe0000070) at 0x0000000040222500
[   71.639032] Unhandled debug exception: aarch32 BKPT (0xe000007f) at 0x0000000040222500
[   72.026761] atmel_mxt_ts 3-004b: Status: 10 Config Checksum: 573e89
[   72.034394] atmel_mxt_ts 3-004b: Status: 00 Config Checksum: 573e89
[   72.147090] Unhandled debug exception: aarch32 BKPT (0xe0000070) at 0x00000000402222c0
[   72.156031] Unhandled debug exception: aarch32 BKPT (0xe000007f) at 0x000000004025a004
[   72.500545] rockchip-dp ff970000.edp: Link Training Clock Recovery success
[   72.510718] rockchip-dp ff970000.edp: Link Training success!
[   76.723651] DEBUG: tsm_vte: unhandled DA: 4 0 -1 -1...
[  102.771427] atmel_mxt_ts 3-004b: Status: 10 Config Checksum: 573e89
[  102.778703] atmel_mxt_ts 3-004b: Status: 00 Config Checksum: 573e89
[  109.526748] cryptohomed (2036): drop_caches: 3
[  109.540350] cryptohomed (2036): drop_caches: 3
[  112.586931] audit: type=1400 audit(1511924384.470:13): avc:  denied  { use } for  pid=7252 comm="init" path="/init" dev="loop1" ino=15 scontext=u:r:init:s0 tcontext=u:r:chromeos:s0 tclass=fd permissive=0
[  112.623376] audit: type=1400 audit(1511924384.507:14): avc:  denied  { module_request } for  pid=7252 comm="init" kmod="fs-configfs" scontext=u:r:init:s0 tcontext=u:r:kernel:s0 tclass=system permissive=0
[  112.687070] audit: type=1400 audit(1511924384.570:15): avc:  denied  { mounton } for  pid=7252 comm="init" path="/sys/kernel/debug" dev="tmpfs" ino=15207 scontext=u:r:init:s0 tcontext=u:object_r:debugfs:s0 tclass=dir permissive=0
[  112.760669] rockchip-dp ff970000.edp: Link Training Clock Recovery success
[  112.779516] rockchip-dp ff970000.edp: Link Training success!
[  113.469527] audit: type=1400 audit(1511924385.353:16): avc:  denied  { module_request } for  pid=7252 comm="init" kmod="fs-configfs" scontext=u:r:init:s0 tcontext=u:r:kernel:s0 tclass=system permissive=0
[  153.681575] atmel_mxt_ts 3-004b: Status: 10 Config Checksum: 573e89
[  153.689053] atmel_mxt_ts 3-004b: Status: 00 Config Checksum: 573e89
[  154.961690] cryptohomed (2036): drop_caches: 3
[  154.978108] cryptohomed (2036): drop_caches: 3
[  157.854900] audit: type=1400 audit(1511924429.738:17): avc:  denied  { use } for  pid=8309 comm="init" path="/init" dev="loop1" ino=15 scontext=u:r:init:s0 tcontext=u:r:chromeos:s0 tclass=fd permissive=0
[  157.904655] audit: type=1400 audit(1511924429.788:18): avc:  denied  { module_request } for  pid=8309 comm="init" kmod="fs-configfs" scontext=u:r:init:s0 tcontext=u:r:kernel:s0 tclass=system permissive=0
[  157.952573] audit: type=1400 audit(1511924429.836:19): avc:  denied  { mounton } for  pid=8309 comm="init" path="/sys/kernel/debug" dev="tmpfs" ino=15207 scontext=u:r:init:s0 tcontext=u:object_r:debugfs:s0 tclass=dir permissive=0
[  158.111423] rockchip-dp ff970000.edp: Link Training Clock Recovery success
[  158.122786] rockchip-dp ff970000.edp: Link Training success!
[  158.738723] audit: type=1400 audit(1511924430.622:20): avc:  denied  { module_request } for  pid=8309 comm="init" kmod="fs-configfs" scontext=u:r:init:s0 tcontext=u:r:kernel:s0 tclass=system permissive=0
[  158.770495] binder: 8386:8386 transaction failed 29189, size 0-0
[  182.213012] atmel_mxt_ts 3-004b: Status: 10 Config Checksum: 573e89
[  182.220312] atmel_mxt_ts 3-004b: Status: 00 Config Checksum: 573e89


"Unhandled debug exception" should not happen on a normal system, but I also don't see obvious source for this.
Will continue tomorrow.

I should be able to get hands on a caroline today, will try if I can reproduce it there. Thanks for your investigation so far!!

Unfortunately, I couldn't gather any additional information today, sorry.
I think it might have crashed once out of ~10 tries for me but I couldn't extract anything interesting from the logs, and there was nothing interesting in /home/cronos/crash (only some arc stuff).

Did you manage to get a crash dump with a stack trace?

Not yet.

To get stack trace I need to update session_manager on the ChromeOS side, because apparently  its timeouts are no longer command-line controlled.

Basically my next idea is to hack session_managed to disable timeouts, but I did not finish it yesterday.

This is the first stack trace I got:

[29590:29590:1129/110916.224559:FATAL:file_stream_context.cc(223)] Check failed: posted. 
#0 0x00000debf038 <unknown>
#1 0x00000debe836 <unknown>
#2 0x00000deeb872 <unknown>
...
#53 0x0000f20fa8a0 __libc_start_main

But I don't think the last one is a source of the crash.

Here is what could be the problem:

D: 0.000073 BrowserProcessImpl::StartTearDown(): Started.
D: 0.000019 BrowserProcessImpl::StartTearDown(): DCHECK(IsShuttingDown());
D: 0.000018 BrowserProcessImpl::StartTearDown(): KeepAliveRegistry::GetInstance()->SetIsShuttingDown();
D: 0.002550 BrowserProcessImpl::StartTearDown(): metrics_services_manager_.reset()
D: 0.001278 BrowserProcessImpl::StartTearDown(): intranet_redirect_detector_.reset()
D: 0.003822 BrowserProcessImpl::StartTearDown(): safe_browsing_service_ exists. => safe_browsing_service()->ShutDown();
D: 0.000058 BrowserProcessImpl::StartTearDown(): network_time_tracker_.reset()
D: 0.000025 BrowserProcessImpl::StartTearDown(): plugins_resource_service_.reset();
D: 0.000039 BrowserProcessImpl::StartTearDown(): notification_ui_manager_.reset()
D: 0.000023 BrowserProcessImpl::StartTearDown(): supervised_user_whitelist_installer_.reset()
D: 0.000017 BrowserProcessImpl::StartTearDown(): remote_debugging_server_.reset();
D: 0.000026 BrowserProcessImpl::StartTearDown(): devtools_auto_opener_.reset()
D: 0.000018 BrowserProcessImpl::StartTearDown(): UserManager::Hide();
D: 5.072931 BrowserProcessImpl::StartTearDown(): profile_manager_.reset();
D: 0.000123 BrowserProcessImpl::StartTearDown(): child_process_watcher_.reset();
D: 0.000019 BrowserProcessImpl::StartTearDown(): media_file_system_registry_.reset();
D: 0.000091 BrowserProcessImpl::StartTearDown(): storage_monitor::StorageMonitor::Destroy();
D: 0.000028 BrowserProcessImpl::StartTearDown(): message_center::MessageCenter::Shutdown();
D: 0.000052 BrowserProcessImpl::StartTearDown(): browser_policy_connector_->Shutdown()
D: 0.000025 BrowserProcessImpl::StartTearDown(): gcm_driver_->Shutdown();
D: 0.000247 BrowserProcessImpl::StartTearDown(): watchdog_thread_.reset()
D: 0.000044 BrowserProcessImpl::StartTearDown(): platform_part()->StartTearDown();
D: 0.000024 BrowserProcessImpl::StartTearDown(): webrtc_log_uploader_->StartShutdown();
D: 0.002319 BrowserProcessImpl::StartTearDown(): local_state_->CommitPendingWrite();


So profile_manager_.reset() took 5 seconds. by that time session_managed would have killed it (I have timeouts disabled).

+ components/keyed_service/OWNERS for DestroyContextServices()
+ components/sync/OWNERS for "ProfileSyncService"
+ components/history/OWNERS for "HistoryService"

DestroyBrowserContextServices() may take several seconds ( 2.88 in this case):

D: 0.000015 ProfileImpl::~ProfileImpl(): Started. MaybeSendDestroyedNotification()
D: 0.000017 ProfileImpl::~ProfileImpl(): prefs_->GetInitializationStatus()
D: 0.000016 ProfileImpl::~ProfileImpl(): StopCreateSessionServiceTimer()
D: 0.000026 ProfileImpl::~ProfileImpl(): pref_change_registrar_.RemoveAll()
D: 0.000020 ProfileImpl::~ProfileImpl(): ChromePluginServiceFilter::UnregisterResourceContext()
D: 0.000017 ProfileImpl::~ProfileImpl(): not off-the-record-profile
D: 0.000039 ProfileImpl::~ProfileImpl(): ClearAllIncognitoSessionOnlyPreferences()
D: 2.880884 ProfileImpl::~ProfileImpl(): DestroyBrowserContextServices()
D: 0.000039 ProfileImpl::~ProfileImpl(): pref_proxy_config_tracker_->DetachFromPrefService();
D: 0.000059 ProfileImpl::~ProfileImpl(): SetExitType(EXIT_NORMAL);
D: 0.001676 ProfileImpl::~ProfileImpl(): ShutdownStoragePartitions();
D: 0.028351 ProfileImpl::~ProfileImpl(): Finished.
D: 0.000015 ProfileImpl::~ProfileImpl(): Started. MaybeSendDestroyedNotification()
D: 0.000016 ProfileImpl::~ProfileImpl(): prefs_->GetInitializationStatus()
D: 0.000016 ProfileImpl::~ProfileImpl(): StopCreateSessionServiceTimer()
D: 0.000031 ProfileImpl::~ProfileImpl(): pref_change_registrar_.RemoveAll()
D: 0.000020 ProfileImpl::~ProfileImpl(): ChromePluginServiceFilter::UnregisterResourceContext()
D: 0.015079 ProfileImpl::~ProfileImpl(): ProfileDestroyer::DestroyOffTheRecordProfileNow()
D: 0.019421 ProfileImpl::~ProfileImpl(): DestroyBrowserContextServices()
D: 0.000032 ProfileImpl::~ProfileImpl(): pref_proxy_config_tracker_->DetachFromPrefService();
D: 0.000036 ProfileImpl::~ProfileImpl(): SetExitType(EXIT_NORMAL);
D: 0.000762 ProfileImpl::~ProfileImpl(): ShutdownStoragePartitions();
D: 0.008913 ProfileImpl::~ProfileImpl(): Finished.
D: 0.000030 ProfileImpl::~ProfileImpl(): Started. MaybeSendDestroyedNotification()
D: 0.000047 ProfileImpl::~ProfileImpl(): prefs_->GetInitializationStatus()
D: 0.000039 ProfileImpl::~ProfileImpl(): StopCreateSessionServiceTimer()
D: 0.000052 ProfileImpl::~ProfileImpl(): pref_change_registrar_.RemoveAll()
D: 0.000037 ProfileImpl::~ProfileImpl(): ChromePluginServiceFilter::UnregisterResourceContext()
D: 0.022340 ProfileImpl::~ProfileImpl(): ProfileDestroyer::DestroyOffTheRecordProfileNow()
D: 0.021025 ProfileImpl::~ProfileImpl(): DestroyBrowserContextServices()
D: 0.000029 ProfileImpl::~ProfileImpl(): pref_proxy_config_tracker_->DetachFromPrefService();
D: 0.000028 ProfileImpl::~ProfileImpl(): SetExitType(EXIT_NORMAL);
D: 0.000689 ProfileImpl::~ProfileImpl(): ShutdownStoragePartitions();

Profiling DestroyContextServices() reveals that it's 'ProfileSyncService' + 'HistoryService' (1.6 + 1.1 seconds in this case) :

D: 0.000031 DependencyManager::DestroyContextServices(): for (auto* dependency_node : destruction_order) factory('UsbEventRouter')->ContextShutdown(context);
D: 0.000019 DependencyManager::DestroyContextServices(): for (auto* dependency_node : destruction_order) factory('TetherService')->ContextShutdown(context);
D: 0.000036 DependencyManager::DestroyContextServices(): for (auto* dependency_node : destruction_order) factory('EasyUnlockService')->ContextShutdown(context);
D: 0.000020 DependencyManager::DestroyContextServices(): for (auto* dependency_node : destruction_order) factory('UserCloudPolicyInvalidator')->ContextShutdown(context);
D: 0.000054 DependencyManager::DestroyContextServices(): for (auto* dependency_node : destruction_order) factory('AccountFetcherServiceFactory')->ContextShutdown(context);
D: 1.626815 DependencyManager::DestroyContextServices(): for (auto* dependency_node : destruction_order) factory('ProfileSyncService')->ContextShutdown(context);
D: 0.000644 DependencyManager::DestroyContextServices(): for (auto* dependency_node : destruction_order) factory('AutocompleteClassifier')->ContextShutdown(context);
D: 0.000068 DependencyManager::DestroyContextServices(): for (auto* dependency_node : destruction_order) factory('ArcBootPhaseMonitorBridgeFactory')->ContextShutdown(context);
D: 0.000066 DependencyManager::DestroyContextServices(): for (auto* dependency_node : destruction_order) factory('MessageService')->ContextShutdown(context);
D: 0.000395 DependencyManager::DestroyContextServices(): for (auto* dependency_node : destruction_order) factory('RulesRegistryService')->ContextShutdown(context);
...
D: 0.000146 DependencyManager::DestroyContextServices(): for (auto* dependency_node : destruction_order) factory('SigninManager')->ContextShutdown(context);
D: 1.178691 DependencyManager::DestroyContextServices(): for (auto* dependency_node : destruction_order) factory('HistoryService')->ContextShutdown(context);
D: 0.000157 DependencyManager::DestroyContextServices(): for (auto* dependency_node : destruction_order) factory('GaiaCookieManagerService')->ContextShutdown(context);

I know neither 'ProfileSyncService' no 'HistoryService'.

It usually happens when I create first user on a device and change language while it is still syncing.
Basically, the easiest way to reproduce this is to add user with different UI language. On first login language will change, and there will be a notification "to switch to the previous language press here". Clicking on 'here' will trigger restart. Sometimes (1 in 10 times), it could take several seconds.

Dear OWNERS, do you have ideas how to debug this further?

Impressive findings!

Out of interest and for future debugging aid: So session_manager kills chrome when it takes too long to exit, and there's no stack trace anywhere in that case? And you prolonged session_manager's timeout and added more logging to chrome's exiting parts?

Yes, session manager kills chrome after some predefined timeout.

But I thought it was actually a chrome crash, because I could not find any session_manager message that it kills chrome. So I was looking for stack trace.

As it is ARM device, I built cros-gdb-arm for remote debugging.
I already tried to debug this earlier, and knew that session manager killed my session before I was able to look in code. So I had to modify session_manager timeouts. (And I received a few hints from apronin@ and vbendeb@.)

It turned out that timeouts (3 and 12 seconds) are now hardcoded, so I had to build my own session_manager.

Then, you need debug version of Chrome for long stack traces. And you need to disable crash on DCHECKs, otherwise it won't work.

So I run Chrome, found several DCHECKs, understood that these are not the source of the crashes.

Then I discussed my findings with achuith@, who suggested to add debug print to StartTearDown, so that I could find where chrome crashes.

And some time later in syslog I found a case when session_managed seemed to stop before chrome did. So I started to look for possible session_manager crash, but decided to check timings first (as I already knew that the hardcoded timeout is 3 seconds).

So I created a one-line perl script to parse Chrome logs and extract time spent in different stages.

After I managed to get reproduce the issue in #37 , all the rest was pretty simple ;)

It took me half of yesterday and full day today to get there.

Thanks for the write-up, this is very helpful.

+Julian and Drew as we were talking about this. We had two general thoughts with regard to this behavior:
- Drew had the idea that maybe we should commit prefs after pref changes which directly resulted from a user gesture?
- Julian mentioned that when we restart Chrome due to re-applying command-line flags, we use AttemptRestart[1], which claims to "Make sure we don't send stop request to the session manager.". This was chosen specifically to ensure a clean chrome exit. Maybe we should do the same for the settings-ui-triggered "sign out and restart" instead of AttemptUserExit[2]? 

[1] https://cs.chromium.org/chromium/src/chrome/browser/lifetime/application_lifetime.cc?l=225&gs=kythe%253A%252F%252Fchromium%253Flang%253Dc%25252B%25252B%253Fpath%253Dsrc%252Fchrome%252Fbrowser%252Flifetime%252Fapplication_lifetime.cc%2523IXLXEK88D76WwbNAdq2JfGX835J37ubzsQKwg1WbkyQ%25253D&gsn=AttemptRestart&ct=xref_usages
[2] https://cs.chromium.org/chromium/src/chrome/browser/ui/webui/settings/browser_lifetime_handler.cc?rcl=e775e5017f6ce9ca04a6633654b3a7a2a8c23008&l=56

Maybe we should first check why 'ProfileSyncService' sometimes takes so long to restart. Does it wait for network connection on shutdown?

Does 'HistoryService' wait for network connection?

This actually sounds like a recent regression, so it should be fixable without extending exit timeout.

So is the idea that going forward, if a service takes too long to shutdown, we *want* to exit Chrome without flushing user pref changes to disk?

Because that feels fragile. Not saying we shouldn't fix regressions in shutdown times, but also that regressions in shutdown times shouldn't result in data loss.

We should flush user pref to disk.
The question is whether we are waiting for disk or for network in 

   factory('ProfileSyncService')->ContextShutdown(context);
?

HistoryService should not wait for a network connection.

Reminds me of those bugs:
https://bugs.chromium.org/p/chromium/issues/detail?id=712330
https://bugs.chromium.org/p/chromium/issues/detail?id=455749

HistoryService does not wait on network connection, but wait for all pending tasks to complete, including writing to disk.

Any updates?

Just discussed with alemate@. In order to unblock 63 we're going to temporarily add an immediate commit after a user initiated change. This will likely trigger a small jank but the tradeoff seems worth it.

Meanwhile, we should consider the question atwilson@ raised in #44: should we consider killing or extending the timeout on shutdown?

We also need to understand why shutdown time has regressed enough that this is firing.

I'm not sure alemate@ is the right person to own the last two. Does anyone have a suggestion of a better owner?

Looks like the fix for this will have to land in 2nd stable. Cutting stable build this am, will skip caroline.

Is this issue seen on caroline and kevin only, or on all boards?

I implemented flushing user profile data before exiting.
CL is on review. https://chromium-review.googlesource.com/c/chromium/src/+/812482

Unable to reproduce this bug on caroline and quawks with repro steps mentioned in c#0 on today's beta build  M63 	10032.68.0, 63.0.3239.85 .

Unable to reproduce this issue on caroline and eve on M64 beta build (10176.22.0, 64.0.3282.41).

Removing RBS based on #53 and #54.

Un-cc-ing me from all bugs on my final day.

Sounds like this bug has been resolved given #52-54. Please reopen if seen again.