In device, after login-ed in mash, shut the lid then clicked on the profile picture to login, I only see a solid white blank login window (no text box to type password). The login page may relate to https://bugs.chromium.org/p/chromium/issues/detail?id=682402, which is not P1 at the moment.

Clicking on "Sign out" at the bottom right screen caused the crash. The SessionManager crashes (as shown in the dump above) may be in P1. I'm not sure who to direct this bug to.

+jonross re: white login pod -- I've seen this too.

+derat re: crash from "sign out".

I don't think session manager is crashing. It looks like Chrome is crashing. (session_manager is a different binary).  It's possible Chrome is trying to restart on logout, not sure.

Is there anything in /var/log/ui/ui.LATEST (like a stack?).  If you're not already deploying with --nostrip can you try that and see if you get a stack?

White login pod is  issue 694846 

I'll see if I can repro this. If you see anything in /var/log/ui please let me know.

Thanks James. I traced back the time stamp of /var/log/ui/ui.20170307-114539 and here's the content.

[4541:4609:0307/114540.046440:72015701:ERROR:instance.cc(71)] Unable to locate service manifest for tracing
[4541:4609:0307/114540.046630:72015798:ERROR:service_manager.cc(947)] Failed to resolve service name: tracing
[4541:4609:0307/114540.046997:72016165:ERROR:instance.cc(71)] Unable to locate service manifest for tracing
[4541:4609:0307/114540.047029:72016197:ERROR:service_manager.cc(947)] Failed to resolve service name: tracing
[4541:4609:0307/114540.127987:72097163:ERROR:instance.cc(71)] Unable to locate service manifest for tracing
[4541:4609:0307/114540.128056:72097224:ERROR:service_manager.cc(947)] Failed to resolve service name: tracing
[4541:4609:0307/114540.135358:72104533:ERROR:instance.cc(71)] Unable to locate service manifest for tracing
[4541:4609:0307/114540.135442:72104611:ERROR:service_manager.cc(947)] Failed to resolve service name: tracing
[4631:4631:0307/114540.199964:72169136:ERROR:device_event_log_impl.cc(137)] [11:45:40.199] Network: network_handler_callbacks.cc:84 not-supported: /device/wlan0: org.chromium.flimflam.Error.NotSupported: This WiFi device does not support MAC address randomization
[4636:4636:0307/114540.784174:72753536:VERBOSE1:drm_device_handle.cc(83)] Succeeded authenticating /dev/dri/card0 in 3 ms with 1 attempt(s)
device-enumerator: scan all dirs
  device-enumerator: scanning /sys/bus
  device-enumerator: scanning /sys/class
[4636:4636:0307/114540.830999:72800171:VERBOSE1:drm_display_host_manager.cc(243)] Got display event ADD for /dev/dri/card0
[4636:4636:0307/114540.834224:72803395:VERBOSE1:drm_display_host_manager.cc(243)] Got display event ADD for /dev/dri/card1
[4636:4800:0307/114540.834379:72803549:VERBOSE1:drm_device_handle.cc(83)] Succeeded authenticating /dev/dri/card1 in 0 ms with 1 attempt(s)
[4636:4804:0307/114540.840633:72809804:VERBOSE1:drm_device_manager.cc(54)] Could not initialize DRM device for /sys/devices/platform/vgem/drm/card1
[4636:4801:0307/114540.845270:72814440:ERROR:vaapi_wrapper.cc(1212)] Could not get a valid VA display
[4636:4636:0307/114540.876692:72845871:VERBOSE1:display_configurator.cc(951)] Display snapshots invalidated.
[4636:4636:0307/114540.876874:72846046:VERBOSE1:update_display_configuration_task.cc(74)] OnDisplaysUpdated: new_display_state=SINGLE new_power_state=ALL_ON flags=1 force_configure=1 display_count=1
[4636:4636:0307/114540.877011:72846183:VERBOSE1:display_configurator.cc(217)] EnterState: display=SINGLE power=ALL_ON
[4636:4804:0307/114540.877151:72846321:VERBOSE1:drm_display.cc(102)] DRM configuring: device=/sys/devices/pci0000:00/0000:00:02.0/drm/card0 crtc=19 connector=30 origin=0,0 size=2560x1700
[4636:4636:0307/114542.023450:73992629:VERBOSE1:display_configurator.cc(1061)] OnConfigured: success=1 new_display_state=SINGLE new_power_state=ALL_ON
[4636:4636:0307/114542.023713:73992883:ERROR:screen_manager_ozone_internal.cc(356)] Not implemented reached in virtual void display::ScreenManagerOzoneInternal::CloseMirroringDisplayIfNotNecessary()
[4631:4631:0307/114542.027234:73996406:ERROR:shell_delegate_mus.cc(166)] Not implemented reached in virtual std::unique_ptr<PaletteDelegate> ash::ShellDelegateMus::CreatePaletteDelegate()
[4631:4631:0307/114542.027316:73996485:ERROR:wm_shell_mus.cc(383)] Not implemented reached in virtual void ash::mus::WmShellMus::AddDisplayObserver(ash::WmDisplayObserver *)
[4631:4631:0307/114542.027345:73996513:ERROR:shell_delegate_mus.cc(122)] Not implemented reached in virtual void ash::ShellDelegateMus::PreInit()
[4631:4631:0307/114542.027390:73996558:ERROR:wm_shell_mus.cc(313)] Not implemented reached in virtual void ash::mus::WmShellMus::RecordUserMetricsAction(ash::UserMetricsAction)
[4631:4631:0307/114542.027661:73996830:ERROR:shell_delegate_mus.cc(156)] Not implemented reached in virtual ash::SessionStateDelegate *ash::ShellDelegateMus::CreateSessionStateDelegate()
device-enumerator: scan all dirs
  device-enumerator: scanning /sys/bus
  device-enumerator: scanning /sys/class
[4631:4631:0307/114542.073826:74042997:ERROR:wm_shell_mus.cc(250)] Not implemented reached in virtual bool ash::mus::WmShellMus::IsInUnifiedMode() const
[4636:4636:0307/114542.076683:74045853:ERROR:screen_manager_ozone_internal.cc(356)] Not implemented reached in virtual void display::ScreenManagerOzoneInternal::CloseMirroringDisplayIfNotNecessary()
[4631:4631:0307/114542.090613:74059784:ERROR:layer_tree_host_impl.cc(2248)] Forcing zero-copy tile initialization as worker context is missing
[4631:4631:0307/114542.098199:74067370:ERROR:wm_shell_mus.cc(272)] Not implemented reached in virtual bool ash::mus::WmShellMus::IsPinned()
[4631:4631:0307/114542.100711:74069882:ERROR:wm_shell_mus.cc(89)] Not implemented reached in virtual bool ash::mus::(anonymous namespace)::SessionStateDelegateStub::ShouldShowAvatar(ash::WmWindow *) const
[4631:4631:0307/114542.109792:74078965:ERROR:shell_delegate_mus.cc(112)] Not implemented reached in virtual bool ash::ShellDelegateMus::CanShowWindowForUser(ash::WmWindow *) const
[4625:4625:0307/114542.115831:ERROR:login_display_host_impl.cc(384)] Not implemented reached in chromeos::LoginDisplayHostImpl::LoginDisplayHostImpl(const gfx::Rect &)
[4625:4625:0307/114542.115932:ERROR:login_display_host_impl.cc(488)] Not implemented reached in chromeos::LoginDisplayHostImpl::LoginDisplayHostImpl(const gfx::Rect &)
[4625:4625:0307/114542.116073:ERROR:input_events_blocker.cc(21)] Not implemented reached in chromeos::InputEventsBlocker::InputEventsBlocker()
[4625:4625:0307/114542.134628:ERROR:core_oobe_handler.cc(72)] Not implemented reached in chromeos::CoreOobeHandler::CoreOobeHandler(chromeos::OobeUI *, chromeos::JSCallsContainer *)
[4625:4625:0307/114542.138394:ERROR:render_widget_host_view_aura.cc(1245)] Not implemented reached in virtual base::i18n::TextDirection content::RenderWidgetHostViewAura::GetTextDirection() const
[4625:4625:0307/114542.138947:ERROR:input_events_blocker.cc(30)] Not implemented reached in virtual chromeos::InputEventsBlocker::~InputEventsBlocker()
[4625:4625:0307/114542.200346:ERROR:device_event_log_impl.cc(137)] [11:45:42.200] Network: network_handler_callbacks.cc:84 not-supported: /device/wlan0: org.chromium.flimflam.Error.NotSupported: This WiFi device does not support MAC address randomization
[4635:4635:0307/114542.260642:74229883:ERROR:layer_tree_host_impl.cc(2248)] Forcing zero-copy tile initialization as worker context is missing
[1:5:0307/114542.286026:ERROR:layer_tree_host_impl.cc(2248)] Forcing zero-copy tile initialization as worker context is missing
[4625:4625:0307/114542.288218:ERROR:layer_tree_host_impl.cc(2248)] Forcing zero-copy tile initialization as worker context is missing
[4625:4625:0307/114543.081999:ERROR:core_oobe_handler.cc(374)] Not implemented reached in void chromeos::CoreOobeHandler::UpdateA11yState()
[4625:4625:0307/114543.180486:ERROR:oobe_ui.cc(630)] Not implemented reached in virtual void chromeos::OobeUI::OnCurrentScreenChanged(chromeos::OobeScreen)
[4631:4631:0307/114543.573176:75542349:ERROR:wm_shell_mus.cc(231)] Not implemented reached in virtual const display::ManagedDisplayInfo &ash::mus::WmShellMus::GetDisplayInfo(int64_t) const
[1:5:0307/114543.598275:ERROR:layer_tree_host_impl.cc(2248)] Forcing zero-copy tile initialization as worker context is missing
[1:5:0307/114543.959299:ERROR:layer_tree_host_impl.cc(2248)] Forcing zero-copy tile initialization as worker context is missing
[4625:4625:0307/115508.989054:ERROR:oobe_ui.cc(630)] Not implemented reached in virtual void chromeos::OobeUI::OnCurrentScreenChanged(chromeos::OobeScreen)
[1:5:0307/115509.503577:ERROR:layer_tree_host_impl.cc(2248)] Forcing zero-copy tile initialization as worker context is missing
[1:1:0307/115509.741610:ERROR:KeyboardEventManager.cpp(440)] Not implemented reached in static bool blink::KeyboardEventManager::currentCapsLockState()
[4625:4625:0307/115509.745071:ERROR:remote_text_input_client.cc(140)] Not implemented reached in virtual void RemoteTextInputClient::OnInputMethodChanged()
[4631:4631:0307/115535.600007:667569181:ERROR:shell_delegate_mus.cc(102)] Not implemented reached in virtual bool ash::ShellDelegateMus::IsMultiProfilesEnabled() const
[4631:4631:0307/115535.608906:667578077:ERROR:wm_shell_mus.cc(362)] Not implemented reached in virtual std::unique_ptr<KeyEventWatcher> ash::mus::WmShellMus::CreateKeyEventWatcher()
[4631:4631:0307/120019.564205:951533378:ERROR:device_event_log_impl.cc(137)] [12:00:19.564] Network: network_state_handler.cc:1021 Default network in unexpected state: Ethernet (/service/2)State: idle
[4625:4625:0307/120019.564872:ERROR:device_event_log_impl.cc(137)] [12:00:19.564] Network: network_state_handler.cc:1021 Default network in unexpected state: Ethernet (/service/2)State: idle
[4625:4625:0307/120019.666043:ERROR:gaia_screen_handler.cc(508)] Gaia webview error: ERR_INTERNET_DISCONNECTED
[4625:4625:0307/120019.688170:ERROR:oobe_ui.cc(630)] Not implemented reached in virtual void chromeos::OobeUI::OnCurrentScreenChanged(chromeos::OobeScreen)
[4625:4625:0307/120019.758474:ERROR:device_event_log_impl.cc(137)] [12:00:19.758] Network: network_handler_callbacks.cc:84 RequestScan Failed: org.freedesktop.DBus.Error.UnknownMethod: Method "RequestScan" with signature "s" on interface "org.chromium.flimflam.Manager" doesn't exist

[4631:4631:0307/120019.758857:951728030:WARNING:object_proxy.cc(581)] Failed to call method: org.chromium.flimflam.Device.GetProperties: object_path= /device/wlan0: org.freedesktop.DBus.Error.UnknownObject: Method "GetProperties" with signature "" on interface "org.chromium.flimflam.Device" doesn't exist

[4625:4625:0307/120019.758894:ERROR:network_sms_handler.cc(444)] NetworkSmsHandler: ERROR: 0 For: /device/wlan0
[4625:4625:0307/120019.758953:ERROR:network_sms_handler.cc(444)] NetworkSmsHandler: ERROR: 0 For: /device/eth0
[4631:4631:0307/120019.759009:951728177:WARNING:object_proxy.cc(581)] Failed to call method: org.chromium.flimflam.Device.GetProperties: object_path= /device/wlan0: org.freedesktop.DBus.Error.UnknownObject: Method "GetProperties" with signature "" on interface "org.chromium.flimflam.Device" doesn't exist

[4631:4631:0307/120019.759028:951728196:ERROR:network_sms_handler.cc(444)] NetworkSmsHandler: ERROR: 0 For: /device/wlan0
[4631:4631:0307/120019.759061:951728229:WARNING:object_proxy.cc(581)] Failed to call method: org.chromium.flimflam.Device.GetProperties: object_path= /device/eth0: org.freedesktop.DBus.Error.UnknownObject: Method "GetProperties" with signature "" on interface "org.chromium.flimflam.Device" doesn't exist

[4631:4631:0307/120019.759076:951728244:ERROR:network_sms_handler.cc(444)] NetworkSmsHandler: ERROR: 0 For: /device/eth0

From the logs in the initial report, it looks like Chrome failed to exit and session_manager sent SIGABRT to it. James, is this just the thing you fixed with mash not catching TERM properly?

thanhph, what chrome revision were you running?

I use chrome 59.0.3030.0 from image ChromeOS-test-R59-9343.0.0-link

thanhph, were you at the login screen when you clicked "Sign out" or inside a session?

The system tray menu incorrectly shows "Sign out" at the login screen. If you click it then ash (?) sends a signal to session_manager, which tries to exit chrome, which doesn't exit properly, then 60 seconds later session_manager kills chrome.

There seems to be a similar issue after login.

Yes, I was at the login screen. Login screen image: https://drive.google.com/file/d/0B0MnJn1TtqqtM0FXekdQb2E2REk/ before I clicked on Sign out. You can see the white blank login screen window as well.

The behavior you described seems like what happened under the hood. This same login screen though reappears within 10 secs after the crash.

OK. First I'm going to look at why we're showing the "sign out" button at the login screen. Filed  issue 699234 

-jonross, -rjkroege since white login pod is a known, unrelated issue.

xiyuan has a CL for session state that should fix the "sign out" button appearing at the login screen. I'm going to look at why "sign out" doesn't work from inside a session.

After hitting signout /var/log/messages shows:
2017-03-07T13:11:02.897173-08:00 INFO session_manager[25972]: [INFO:session_manager_impl.cc(457)] Stopping all sessions
2017-03-07T13:11:02.897537-08:00 INFO session_manager[25972]: [INFO:browser_job.cc(157)] Terminating process: 
2017-03-07T13:11:02.897585-08:00 INFO session_manager[25972]: [INFO:system_utils_impl.cc(110)] Sending 15 to 25997 as 1000

pid 25997 is the root process, so session_manager is sending SIGTERM to chrome --mash root.

/var/log/ui/ui.LATEST doesn't show anything for a while, then shows:

[26097:26097:0307/131127.899738:ERROR:object_proxy.cc(583)] Failed to call method: org.chromium.SessionManagerInterface.StopSession: object_path= /org/chromium/SessionManager: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
[26097:26097:0307/131127.899922:ERROR:session_manager_client.cc(549)] Failed to call StopSession

pid 26097 is the browser process.

Either the root process is ignoring the SIGTERM, or it is trying to shut down and some other process is hanging. I'm not sure why the browser process is complaining -- maybe something is getting stuck with multiple clients (ash and browser) trying to talk to session_manager?

So this was tricky...

Signals can be blocked with "signal masks" set via sigprocmask(). When spawning a subprocess the child inherits the signal mask from the parent. You can see the current masked/blocked status of a signal like this:

sigset_t oldset;
sigemptyset(&oldset);
sigprocmask(0 /* ignored */, nullptr, &oldset);
fprintf(stderr, "JAMES MashMain sigterm blocked %d\n", sigismember(&oldset, SIGTERM));

On linux desktop SIGTERM is not blocked at chrome --mash startup.

On chromeos device, SIGTERM *is* blocked.

This normally doesn't cause problems because ContentMainRunnerImpl::Initialize() calls a function SetupSignalHandlers() that happens to wipe the mask. However, chrome --mash doesn't use content, so we were not resetting the mask.

It's not clear to me why session_manager is spawning chrome with SIGTERM blocked. That said, I think we should just do what normal chrome does and reset the signal mask.

https://codereview.chromium.org/2731283008/

Filed  issue 699777  re: session_manager leaving the signals blocked.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/043b638699e0d9854aa53dfc0eeac1f8b7be16b4

commit 043b638699e0d9854aa53dfc0eeac1f8b7be16b4
Author: jamescook <jamescook@chromium.org>
Date: Thu Mar 09 00:11:28 2017

chromeos/mash: Reset signal handler mask on chrome --mash startup

This fixes an issue where the system tray "sign out" item does not cleanly
sign out of the session.

chrome inherits its signal handler masks from the parent process. These
masks are not guaranteed to be in any particular state, so they need to be
cleared on startup. Otherwise the SIGTERM signal is blocked, so the signal
handler doesn't run, so session_manager cannot cleanly shut down chrome.

For non-mash chrome this is done as part of content main initialization,
but mash chrome doesn't run that code.

BUG= 699143 , 699777 
TEST=System tray > Sign out takes you back to login screen promptly.
Also, "stop ui" on device, look at /var/log/messages, see signal 15 being
sent and chrome immediately exiting (and no signal 6 sent to kill it).

Review-Url: https://codereview.chromium.org/2731283008
Cr-Commit-Position: refs/heads/master@{#455603}

[modify] https://crrev.com/043b638699e0d9854aa53dfc0eeac1f8b7be16b4/chrome/app/mash/mash_runner.cc

This seems to work. However "stop ui" from inside a login session still results in session_manager sending a sigabrt to chrome due to slow shutdown. I suspect a service is hanging. Filed  issue 700094  for that.