I've seen restarting the ui Upstart job during testing sometimes take far longer than is reasonable. See the poppy-release run at http://stainless/browse/chromeos-autotest-results/218585395-chromeos-test/ , where it took 42 seconds and caused a test timeout:

2018/07/18 23:05:13 Started test ui.ChromeCrashLoggedIn
2018/07/18 23:05:13 [23:05:12.254] Restarting ui job
2018/07/18 23:05:55 [23:05:54.824] Waiting for org.chromium.SessionManager D-Bus service
2018/07/18 23:05:55 [23:05:54.833] Asking session_manager to enable Chrome testing
2018/07/18 23:05:55 [23:05:54.835] Waiting for Chrome to write its debugging port to /home/chronos/DevToolsActivePort
2018/07/18 23:05:56 [23:05:55.882] Removing cryptohome for testuser@gmail.com
2018/07/18 23:05:57 [23:05:56.149] Finding OOBE DevTools target
2018/07/18 23:05:57 [23:05:56.150] Connecting to Chrome at ws://127.0.0.1:33931/devtools/page/99FB2FBC2F9EBF05CA779D8F6AFF948A
2018/07/18 23:05:57 [23:05:56.162] Waiting for OOBE
2018/07/18 23:05:58 [23:05:57.705] Logging in as user "testuser@gmail.com"
2018/07/18 23:05:58 [23:05:57.790] Waiting for cryptohome /home/user/cfa5cbe1eaa1426ea7d826cbcdfd70c591f207ea
2018/07/18 23:06:08 [23:06:07.834] Waiting for OOBE to be dismissed
2018/07/18 23:06:13 [23:06:12.264] Error at chrome_crash_logged_in.go:24: Chrome login failed: OOBE not dismissed: chrome://oobe target still exists

Here's /var/log/messages:

...
2018-07-19T06:05:12.871905+00:00 INFO session_manager[6625]: [INFO:session_manager_service.cc(480)] SessionManagerService quitting run loop
2018-07-19T06:05:12.871987+00:00 INFO session_manager[6625]: [INFO:session_manager_service.cc(201)] SessionManagerService exiting
2018-07-19T06:05:12.881789+00:00 INFO session_manager[6625]: [INFO:android_oci_wrapper.cc(253)] Cleaning up container 6900
2018-07-19T06:05:12.894457+00:00 INFO session_manager[6625]: [INFO:session_manager_impl.cc(1726)] Android Container with pid 6900 stopped
2018-07-19T06:05:12.914839+00:00 INFO kernel: [  318.185535] arcbr0: port 1(veth_android) entered disabled state
2018-07-19T06:05:12.915797+00:00 INFO kernel: [  318.186635] device veth_android left promiscuous mode
2018-07-19T06:05:12.915805+00:00 INFO kernel: [  318.186640] arcbr0: port 1(veth_android) entered disabled state
2018-07-19T06:05:12.937810+00:00 WARNING kernel: [  318.208833] init: arc-sdcard main process (7366) killed by TERM signal
2018-07-19T06:05:12.981014+00:00 INFO minijail0[7367]: libminijail[7367]: child process 7373 exited with status 254
2018-07-19T06:05:15.721986+00:00 INFO minijail0[9403]: libminijail[9403]: mount / -> / type ''
2018-07-19T06:05:15.722862+00:00 INFO minijail0[9403]: libminijail[9403]: mount /proc -> /proc type ''
2018-07-19T06:05:15.722890+00:00 INFO minijail0[9403]: libminijail[9403]: mount /sys -> /sys type ''
2018-07-19T06:05:15.722900+00:00 INFO minijail0[9403]: libminijail[9403]: mount /dev -> /dev type ''
2018-07-19T06:05:15.722910+00:00 INFO minijail0[9403]: libminijail[9403]: mount /var -> /var type ''
2018-07-19T06:05:15.722921+00:00 INFO minijail0[9403]: libminijail[9403]: mount /dev/shm -> /dev/shm type ''
2018-07-19T06:05:15.722957+00:00 INFO minijail0[9403]: libminijail[9403]: mount tmpfs -> /run type 'tmpfs'
2018-07-19T06:05:15.722969+00:00 INFO minijail0[9403]: libminijail[9403]: mount /run/camera -> /run/camera type ''
2018-07-19T06:05:15.723005+00:00 INFO minijail0[9403]: libminijail[9403]: mount /var/empty/run -> /var/run type 'bind'
2018-07-19T06:05:15.723100+00:00 WARNING minijail0[9403]: libminijail[9403]: allowing syscall: socket
2018-07-19T06:05:15.723113+00:00 WARNING minijail0[9403]: libminijail[9403]: allowing syscall: connect
2018-07-19T06:05:15.723123+00:00 WARNING minijail0[9403]: libminijail[9403]: allowing syscall: sendto
2018-07-19T06:05:15.723133+00:00 WARNING minijail0[9403]: libminijail[9403]: allowing syscall: writev
2018-07-19T06:05:15.725181+00:00 INFO minijail0[9403]: libminijail[9403]: not running init loop, exiting immediately
2018-07-19T06:05:15.753440+00:00 INFO cros_camera_service[9405]: libminijail[2]: mount / -> / type ''
2018-07-19T06:05:15.753461+00:00 INFO cros_camera_service[9405]: libminijail[2]: mount /proc -> /proc type ''
2018-07-19T06:05:15.753471+00:00 INFO cros_camera_service[9405]: libminijail[2]: mount /sys -> /sys type ''
2018-07-19T06:05:15.753480+00:00 INFO cros_camera_service[9405]: libminijail[2]: mount /dev -> /dev type ''
2018-07-19T06:05:15.753488+00:00 INFO cros_camera_service[9405]: libminijail[2]: mount /var -> /var type ''
2018-07-19T06:05:15.753497+00:00 INFO cros_camera_service[9405]: libminijail[2]: mount /dev/shm -> /dev/shm type ''
2018-07-19T06:05:15.753506+00:00 INFO cros_camera_service[9405]: libminijail[2]: mount tmpfs -> /run type 'tmpfs'
2018-07-19T06:05:15.753516+00:00 INFO cros_camera_service[9405]: libminijail[2]: mount /run/camera -> /run/camera type ''
2018-07-19T06:05:15.753526+00:00 INFO cros_camera_service[9405]: libminijail[2]: mount /var/empty/run -> /var/run type 'bind'
2018-07-19T06:05:15.766598+00:00 WARNING cros_camera_service[9405]: libminijail[2]: logging seccomp filter failures
2018-07-19T06:05:15.767899+00:00 INFO cros_camera_service[9407]: main(): Started camera HAL v3 adapter
2018-07-19T06:05:37.112308+00:00 ERR chapsd[2056]: Concurrent sessions
2018-07-19T06:05:39.260387+00:00 INFO attestationd[2092]: Attestation: Encrypting endorsement credential for the default ACA.
2018-07-19T06:05:39.260582+00:00 INFO attestationd[2092]: Attestation: Encrypting endorsement credential for the test ACA.
2018-07-19T06:05:39.289846+00:00 INFO chapsd[2056]: Importing opencryptoki objects.
2018-07-19T06:05:39.289969+00:00 WARNING chapsd[2056]: Did not find any opencryptoki objects to import.
2018-07-19T06:05:39.302064+00:00 INFO chapsd[2056]: Slot 1 ready for token at /home/root/cfa5cbe1eaa1426ea7d826cbcdfd70c591f207ea/chaps
2018-07-19T06:05:39.302189+00:00 INFO chapsd[2056]: Initializing key hierarchy for token at /home/root/cfa5cbe1eaa1426ea7d826cbcdfd70c591f207ea/chaps
2018-07-19T06:05:39.312177+00:00 INFO chapsd[2056]: Finished importing 0 pending objects.
2018-07-19T06:05:39.316842+00:00 INFO chapsd[2056]: Master key is ready for token at /var/lib/chaps
2018-07-19T06:05:52.454886+00:00 ERR chapsd[2056]: Concurrent sessions
2018-07-19T06:05:52.686307+00:00 INFO attestationd[2092]: Attestation: Prepared successfully (56433ms).
2018-07-19T06:05:52.686834+00:00 INFO attestationd[2092]: Loading attestation database.
2018-07-19T06:05:52.688242+00:00 INFO cryptohomed[2115]: A Pkcs11_Init event got finished.
2018-07-19T06:05:52.688441+00:00 INFO cryptohomed[2115]: PKCS#11 initialization succeeded.
2018-07-19T06:05:53.871496+00:00 INFO chapsd[2056]: Finished importing 0 pending objects.
2018-07-19T06:05:53.873463+00:00 INFO chapsd[2056]: Master key is ready for token at /home/root/cfa5cbe1eaa1426ea7d826cbcdfd70c591f207ea/chaps
2018-07-19T06:05:53.873825+00:00 INFO chapsd[2056]: Token at /home/root/cfa5cbe1eaa1426ea7d826cbcdfd70c591f207ea/chaps has been removed from slot 1
2018-07-19T06:05:54.062564+00:00 INFO attestationd[2092]: Loading attestation database.
2018-07-19T06:05:54.727003+00:00 WARNING chapsd[2056]: Unload Token event received for unknown path: /home/root/cfa5cbe1eaa1426ea7d826cbcdfd70c591f207ea/chaps
2018-07-19T06:05:54.754117+00:00 INFO imageloader[9510]: The latest-version file does not exist. Component PepperFlashPlayer is probably not installed.
2018-07-19T06:05:54.826296+00:00 WARNING session_manager[9629]: [WARNING:chrome_setup.cc(92)] Could not find both paths: /usr/share/chromeos-assets/wallpaper/oem_large.jpg and /usr/share/chromeos-assets/wallpaper/oem_small.jpg
2018-07-19T06:05:54.826851+00:00 INFO session_manager[9629]: [INFO:session_manager_main.cc(212)] Will wait 3s for graceful browser exit.
2018-07-19T06:05:54.828654+00:00 INFO session_manager[9629]: [INFO:session_manager_service.cc(148)] SessionManagerService starting
...

This is the session_manager code that prints the final log message before the long delay:

1688 void SessionManagerImpl::OnAndroidContainerStopped(
1689     const std::string& container_instance_id,
1690     pid_t pid,
1691     ArcContainerStopReason reason) {
1692   if (reason == ArcContainerStopReason::CRASH) {
1693     LOG(ERROR) << "Android Container with pid " << pid << " crashed";
1694   } else {
1695     LOG(INFO) << "Android Container with pid " << pid << " stopped";
1696   }
1697 
1698   login_metrics_->StopTrackingArcUseTime();
1699   if (!init_controller_->TriggerImpulse(
1700           kStopArcInstanceImpulse, {},
1701           InitDaemonController::TriggerMode::SYNC)) {
1702     LOG(ERROR) << "Emitting stop-arc-instance impulse failed.";
1703   }
1704 
1705   if (!init_controller_->TriggerImpulse(
1706           kStopArcNetworkImpulse, {},
1707           InitDaemonController::TriggerMode::SYNC)) {
1708     LOG(ERROR) << "Emitting stop-arc-network impulse failed.";
1709   }
1710 
1711   adaptor_.SendArcInstanceStoppedSignal(static_cast<uint32_t>(reason),
1712                                         container_instance_id);
1713 }

I suspect that we're blocking on either stop-android-instance or stop-arc-network. There are a bunch of Upstart jobs that stop on stop-android-instance, and I'm not sure which of them is responsible. Hopefully someone who I cc-ed has some ideas, though. :-)