Looks like in all these cases the dbus timeout happens already during the post-test cleanup ("...login_GuestAndActualSession.py", line 51, in cleanup), while doing session_manager.StopSession(''). The test itself succeeded.

Here's what's going on in https://luci-milo.appspot.com/buildbot/chromeos/wizpig-paladin/3844:
<Test start (~18:59 GMT)>
08/20 11:59:46.833 INFO |               job:0232| 	START	login_GuestAndActualSession	login_GuestAndActualSession	timestamp=1534791586	localtime=Aug 20 11:59:46	
2018-08-20T18:59:46.872140+00:00 NOTICE root[11187]: autotest runtest login_GuestAndActualSession

<stopping previous Chrome>
2018-08-20T18:59:47.471730+00:00 INFO session_manager[10499]: [INFO:system_utils_impl.cc(94)] Sending 15 to 10525 as 1000

<seeing some issues>
2018-08-20T19:00:06.853025+00:00 ERR chrome[10525]: message repeated 9 times: [ cras_client: server connect failed: Resource temporarily unavailable]
2018-08-20T19:00:07.729840+00:00 CRIT ui-post-stop-unkillable[11257]: 10525 Z<sl [chrome] <defunct>
2018-08-20T19:00:07.729913+00:00 CRIT ui-post-stop-unkillable[11257]: 10626 Z    [chrome] <defunct>

2018-08-20T19:00:08.923432+00:00 ERR arc-lifetime[11268]: [ERROR:arc_setup_util.cc(374)] Failed to lazy-umount /run/arc/shared_mounts/cache: No such file or directory
<..and more lazy-unmount failures>

<Starting a new Chrome>
2018-08-20T19:00:09.685822+00:00 INFO session_manager[11451]: [INFO:session_manager_service.cc(148)] SessionManagerService starting
2018-08-20T19:00:09.693515+00:00 INFO session_manager[11451]: [INFO:browser_job.cc(148)] Running browser [...]
2018-08-20T19:00:09.701189+00:00 INFO session_manager[11451]: [INFO:session_manager_service.cc(230)] Browser is 11471

<creating new temp directory for a guest user>
08/20 12:00:16.861 DEBUG|             utils:0218| Running '/usr/sbin/cryptohome --action=mount_guest_ex 2>&1'
2018-08-20T19:00:17.201982+00:00 INFO cryptohomed[1444]: Migrated (or created) user directory: /run/cryptohome/ephemeral_mount/bd1a7187f7d22a6de9e64ad9dca4350de7c65c40
<with some issues on arc side>
2018-08-20T19:00:18.724917+00:00 ERR arc-setup-precreate[11649]: [ERROR:arc_setup_util.cc(403)] Failed to free /dev/loop6: No such device or address
2018-08-20T19:00:18.748457+00:00 ERR arc-setup-precreate[11649]: [ERROR:arc_setup_util.cc(403)] Failed to free /dev/loop5: No such device or address
2018-08-20T19:00:18.797903+00:00 ERR arc-setup-precreate[11649]: [ERROR:arc_setup_util.cc(403)] Failed to free /dev/loop4: No such device or address
2018-08-20T19:00:18.819486+00:00 ERR arc-setup-precreate[11647]: [ERROR:arc_setup_util.cc(374)] Failed to lazy-umount /run/arc/shared_mounts: Invalid argument
<.. and more>

<but session eventually started>
2018-08-20T19:00:20.302016+00:00 INFO session_manager[11451]: [INFO:session_manager_impl.cc(571)] Emitting D-Bus signal SessionStateChanged:started

<closing guest session>
08/20 12:00:20.303 DEBUG|             utils:0218| Running '/usr/sbin/cryptohome --action=unmount 2>&1'

<bumping into unmount issues, so the guest vault is not unmounted yet>
2018-08-20T19:00:20.409931+00:00 ERR cryptohomed[1444]: Couldn't unmount vault immediately, was_busy = 1
2018-08-20T19:00:20.437494+00:00 ERR cryptohomed[1444]: Failed to read link /proc/2093/cwd: No such file or directory
2018-08-20T19:00:20.470306+00:00 ERR cryptohomed[1444]: Failed to read link /proc/11728/cwd: No such file or directory
2018-08-20T19:00:20.471241+00:00 ERR cryptohomed[1444]: Process 11451 had open files.  Command line: session_manager  
2018-08-20T19:00:20.471272+00:00 ERR cryptohomed[1444]:   (11451) CWD: /
2018-08-20T19:00:20.471581+00:00 ERR cryptohomed[1444]:   (11451) Open File: /home/user/bd1a7187f7d22a6de9e64ad9dca4350de7c65c40/.pki/nssdb/cert9.db
2018-08-20T19:00:20.471609+00:00 ERR cryptohomed[1444]:   (11451) Open File: /home/user/bd1a7187f7d22a6de9e64ad9dca4350de7c65c40/.pki/nssdb/key4.db

<requesting to mount the actual user>
08/20 12:00:20.890 DEBUG|             utils:0218| Running '/usr/sbin/cryptohome --action=mount_ex --user=first_user@nowhere.com --password=fiunpq --async --create --key_label=bar 2>&1'
2018-08-20T19:00:22.040787+00:00 INFO cryptohomed[1444]: Migrated (or created) user directory: /home/.shadow/c590e6e6ddfc9882927da06f9d79f20f519b31bb/mount
...
08/20 12:00:22.812 DEBUG|             utils:0286| [stdout] Mount succeeded.
2018-08-20T19:00:23.153872+00:00 INFO session_manager[11451]: [INFO:session_manager_impl.cc(571)] Emitting D-Bus signal SessionStateChanged:started

<this user became the actual owner, as expected by the test>
[0820/120023:INFO:keygen_worker.cc(46)] Generating Owner key.
[0820/120023:INFO:keygen_worker.cc(53)] Writing Owner key to /home/user/c590e6e6ddfc9882927da06f9d79f20f519b31bb/key.pub
[0820/120023:INFO:policy_key.cc(120)] wrote 294 bytes to /home/user/c590e6e6ddfc9882927da06f9d79f20f519b31bb/key.pub

<the test itself succeeded>
08/20 12:00:24.326 DEBUG|              test:0372| The test has completed successfully

<the Chrome session is closed here>
2018-08-20T19:00:24.356329+00:00 INFO session_manager[11451]: [INFO:session_manager_impl.cc(623)] Stopping all sessions
2018-08-20T19:00:24.356359+00:00 INFO session_manager[11451]: [INFO:session_manager_impl.cc(388)] Emitting D-Bus signal SessionStateChanged:stopping
2018-08-20T19:00:24.356499+00:00 INFO session_manager[11451]: [INFO:browser_job.cc(167)] Terminating browser process 11471 with signal 15: exiting cleanly
2018-08-20T19:00:24.356524+00:00 INFO session_manager[11451]: [INFO:system_utils_impl.cc(94)] Sending 15 to 11471 as 1000
2018-08-20T19:00:24.356616+00:00 INFO session_manager[11451]: [INFO:system_utils_impl.cc(94)] Sending 15 to 11829 as 1000

[11471:11471:0820/120024.431064:VERBOSE1:arc_session_runner.cc(211)] OnShutdown
[11471:11471:0820/120024.431376:INFO:arc_session_runner.cc(264)] ARC stopped: SHUTDOWN
[11471:11471:0820/120024.572693:VERBOSE1:arc_session_runner.cc(211)] OnShutdown

<after_hook collects all logs. unfortunately, after that we don't have further system logs in https://stainless.corp.google.com/browse/chromeos-autotest-results/229433644-chromeos-test/>
08/20 12:00:50.127 INFO |              test:0897| after_hook completed

<dbus timeout in test when trying to send StopSession to the session_manager>
08/20 12:00:50.128 ERROR|          parallel:0026| child process failed
08/20 12:00:50.144 DEBUG|          parallel:0030| UnhandledTestError: Unhandled DBusException: 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.

This sounds similar to  issue 838982 . My "fix" there was to delete the test's StopSession call.

There is also login_LoginSuccess failure in the same https://luci-milo.appspot.com/buildbot/chromeos/wizpig-paladin/3844. Which also fails due to timeout when closing the session_manager session.

1)
<as the test starts we restart the ui>
2018-08-20T18:59:58.178796+00:00 NOTICE root[21705]: autotest runtest login_LoginSuccess
08/20 11:59:59.251 DEBUG|              test:0370| starting test(run_once()), test details follow
()
08/20 11:59:59.456 INFO |    cros_interface:0575| (Re)starting the ui (logs the user out)
08/20 11:59:59.469 DEBUG|    cros_interface:0058| sh -c stop ui 

<the old browser is stopped>
2018-08-20T18:59:59.548915+00:00 INFO session_manager[21103]: [INFO:browser_job.cc(167)] Terminating browser process 21120 with signal 15: exiting cleanly
2018-08-20T18:59:59.548970+00:00 INFO session_manager[21103]: [INFO:system_utils_impl.cc(94)] Sending 15 to 21120 as 1000
2018-08-20T19:00:00.022331+00:00 INFO session_manager[21103]: [INFO:browser_job.cc(185)] Cleaned up browser process 21120
2018-08-20T19:00:00.022370+00:00 INFO session_manager[21103]: [INFO:session_manager_impl.cc(395)] Emitting D-Bus signal SessionStateChanged:stopped
2018-08-20T19:00:00.022523+00:00 INFO session_manager[21103]: [INFO:session_manager_service.cc(481)] SessionManagerService quitting run loop
2018-08-20T19:00:00.022635+00:00 INFO session_manager[21103]: [INFO:session_manager_service.cc(201)] SessionManagerService exiting
2018-08-20T19:00:00.038556+00:00 INFO session_manager[21103]: [INFO:android_oci_wrapper.cc(269)] Cleaning up container 21341
2018-08-20T19:00:00.054218+00:00 INFO session_manager[21103]: [INFO:session_manager_impl.cc(1764)] Android Container with pid 21341 stopped
2018-08-20T19:00:00.054250+00:00 INFO session_manager[21103]: [INFO:upstart_signal_emitter.cc(35)] Emitting stop-arc-instance Upstart signal

<note that we have "Emitting D-Bus signal SessionStateChanged:stopped">

<we start the new browser>
08/20 12:00:00.494 DEBUG|    cros_interface:0058| sh -c start ui 

2018-08-20T19:00:01.250422+00:00 INFO session_manager[21957]: [INFO:session_manager_main.cc(212)] Will wait 3s for graceful browser exit.
2018-08-20T19:00:01.257670+00:00 INFO session_manager[21957]: [INFO:session_manager_service.cc(148)] SessionManagerService starting
2018-08-20T19:00:01.263620+00:00 INFO session_manager[21957]: [INFO:browser_job.cc(148)] Running browser [...]
2018-08-20T19:00:01.272011+00:00 INFO session_manager[21957]: [INFO:session_manager_service.cc(230)] Browser is 21972


2)
<then for this block we restart Chrome again, using a different method>
48:        with chrome.Chrome(arc_mode=arc_mode):

08/20 12:00:01.527 INFO |cros_browser_backe:0068| Restarting Chrome (pid=21972) with remote port
08/20 12:00:01.528 INFO |cros_browser_backe:0076| dbus-send --system --type=method_call --dest=org.chromium.SessionManager /org/chromium/SessionManager org.chromium.SessionManagerInterface.EnableChromeTesting boolean:true array:string:"--enable-net-benchmarking,--metrics-recording-only,--no-default-browser-check,--no-first-run,--enable-gpu-benchmarking,--deny-permission-prompts,--autoplay-policy=no-user-gesture-required,--disable-component-extensions-with-background-pages,--disable-default-apps,--disable-search-geolocation-disclosure,--enable-smooth-scrolling,--enable-threaded-compositing,--remote-debugging-port=0,--start-maximized,--ash-disable-system-sounds,--oobe-skip-postlogin,--disable-logging-redirect,--vmodule=*/chromeos/net/*=2\,*/chromeos/login/*=2\,chrome_browser_main_posix=2,--allow-failed-policy-fetch-for-test,--disable-gaia-services" array:string:

<the browser restarts>
2018-08-20T19:00:01.544254+00:00 INFO session_manager[21957]: [INFO:browser_job.cc(157)] Terminating process group for browser 21972 with signal 9: Restarting browser on-demand.
2018-08-20T19:00:01.544289+00:00 INFO session_manager[21957]: [INFO:system_utils_impl.cc(94)] Sending 9 to -21972 as 1000
...
2018-08-20T19:00:01.573015+00:00 INFO session_manager[21957]: [INFO:browser_job.cc(185)] Cleaned up browser process 21972

2018-08-20T19:00:01.574605+00:00 INFO session_manager[21957]: [INFO:browser_job.cc(148)] Running browser /opt/google/chrome/chrome [...]
2018-08-20T19:00:01.580884+00:00 INFO session_manager[21957]: [INFO:session_manager_service.cc(230)] Browser is 22018


3)
<then the "with chrome.Chrome(arc_mode=arc_mode)" block ends and closes the current Chrome (restart ui)>
08/20 12:00:16.615 INFO |           browser:0208| Closing browser (pid=22018) ...
08/20 12:00:16.622 INFO |    cros_interface:0575| (Re)starting the ui (logs the user out)
08/20 12:00:16.673 DEBUG|    cros_interface:0058| sh -c restart ui 

2018-08-20T19:00:16.823463+00:00 INFO session_manager[21957]: [INFO:session_manager_impl.cc(388)] Emitting D-Bus signal SessionStateChanged:stopping
2018-08-20T19:00:16.830170+00:00 INFO session_manager[21957]: [INFO:browser_job.cc(167)] Terminating browser process 22018 with signal 15: exiting cleanly

<everything seems generally ok, but the ui process is eventually killed with SIGKILL instead of SIGTERM here, did the shutdown just took too long?> 
2018-08-20T19:00:36.845997+00:00 WARNING kernel: [ 4871.868255] init: ui main process (21957) killed by KILL signal


<eventually the old browser is stopped, and the new one is started fine>
2018-08-20T19:00:39.998416+00:00 INFO session_manager[22584]: [INFO:session_manager_main.cc(212)] Will wait 3s for graceful browser exit.
2018-08-20T19:00:40.003559+00:00 INFO session_manager[22584]: [INFO:session_manager_service.cc(148)] SessionManagerService starting
2018-08-20T19:00:40.006204+00:00 INFO session_manager[22584]: [INFO:policy_key.cc(51)] No policy key on disk at /var/lib/whitelist/owner.key
2018-08-20T19:00:40.010448+00:00 INFO session_manager[22584]: [INFO:browser_job.cc(148)] Running browser [...]
2018-08-20T19:00:40.020537+00:00 INFO session_manager[22584]: [INFO:session_manager_service.cc(230)] Browser is 22600

08/20 12:00:40.081 INFO |           browser:0221| Browser is closed.

<but there are indeed no 'stopped' events>


4)
<we continue and we get our timeout here after 1 minute>
57:        self._listener.wait_for_signals(desc='Session stopped.',
58:                                        timeout=self._SESSION_STOP_TIMEOUT)

08/20 12:01:40.023 ERROR|             utils:2767| Timed out waiting for condition: Session stopped.
2018-08-20T19:01:40.141577+00:00 NOTICE autotest[22863]: 12:01:40.125 WARNI|              test:0606| The test failed with the following exception#012Traceback (most recent call last):#012  File "/usr/local/autotest/common_lib/test.py", line 600, in _exec#012    _call_test_function(self.execute, *p_args, **p_dargs)#012  File "/usr/local/autotest/common_lib/test.py", line 800, in _call_test_function#012    return func(*args, **dargs)#012  File "/usr/local/autotest/common_lib/test.py", line 464, in execute#012    postprocess_profiled_run, args, dargs)#012  File "/usr/local/autotest/common_lib/test.py", line 371, in _call_run_once#012    self.run_once(*args, **dargs)#012  File "/usr/local/autotest/tests/login_LoginSuccess/login_LoginSuccess.py", line 58, in run_once#012    timeout=self._SESSION_STOP_TIMEOUT)#012  File "/usr/local/autotest/common_lib/cros/session_manager.py", line 55, in wait_for_signals#012    timeout=timeout)#012  File "/usr/local/autotest/common_lib/utils.py", line 2768, in poll_for_condition#012    raise TimeoutError(message=desc)#012TimeoutError: Timed out waiting for condition: Session stopped.


Note that on step 2 we did have 'stopped' events from the session_manager, but on step 4 we didn't have those. So, the wait timed out.

Sorry, didn't notice that my yet another overly-long comment was sitting unsubmitted. :)

Re comment #3: 
1) My one idea is that it's possible that the test is trying to send StopSession at the moment when we go through 'restart ui', so there's no session_manager listening on dbus at this point. Deleting StopSession in such case definitely helps.

2) Per comment #4 also sometimes there are no 'stopped' events from session_manager. Iiuc due to the fact that 'restart ui' kills session_manager before it gets to that point (probably because it is unresponsive). 
So, another idea: it's also possible that what causes SIGKILL during 'restart ui' in this case, in other tests leads to dbus timeouts when trying to talk to this unresponsive session_manager.

I don't see what causes that, but I'm not a session_manager expert. 
derat@, can you please take a closer look from this angle?

There haven't been any session_manager experts here since cmasone@ left, and I hate all of these flaky tests.

IIRC, my suspicions when I was looking at the earlier failures matched yours. I'm happy to delete the StopSession call here as well if nobody objects. :-P

FWIW, we ran into this, too, for enterprise_AuthPolicyDaemon, and our "solution" was to remove the StopSession call (the corresponding server test reboots the device, anyway).

Thanks, uploaded https://crrev.com/c/1185975 to do the same here.

Seems to be happening on other boards too.

cave-paladin:
https://luci-milo.appspot.com/buildbot/chromeos/cave-paladin/4527

link-paladin:
https://luci-milo.appspot.com/buildbot/chromeos/link-paladin/32599

+sheriffs

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/autotest/+/83cdcd95004eb5c7cf8562a497c70be80d928877

commit 83cdcd95004eb5c7cf8562a497c70be80d928877
Author: Daniel Erat <derat@chromium.org>
Date: Fri Aug 24 00:43:00 2018

autotest: Make login_GuestAndActualSession not stop session.

Remove a flaky StopSession call from
login_GuestAndActualSession; just stop the ui job instead.

BUG= chromium:876197 
TEST=nope, couldn't get test_that to run

Change-Id: I4fd78efaec248547f2937429fe2b30223be23225
Reviewed-on: https://chromium-review.googlesource.com/1185975
Commit-Ready: Dan Erat <derat@chromium.org>
Tested-by: Dan Erat <derat@chromium.org>
Reviewed-by: Dan Erat <derat@chromium.org>

[modify] https://crrev.com/83cdcd95004eb5c7cf8562a497c70be80d928877/client/site_tests/login_GuestAndActualSession/login_GuestAndActualSession.py