It has a new green builder. Lower its priority.

This just failed again: http://cros-goldeneye/chromeos/healthmonitoring/buildDetails?buildbucketId=8946386930884402416

Please don't let flaky tests linger without investigating them. It just leaves more work for future gardeners.

05/16 03:31:13.503 WARNI|              test:0637| The test failed with the following exception
Traceback (most recent call last):
  File "/usr/local/autotest/common_lib/test.py", line 631, in _exec
    _call_test_function(self.execute, *p_args, **p_dargs)
  File "/usr/local/autotest/common_lib/test.py", line 837, in _call_test_function
    raise error.UnhandledTestFail(e)
UnhandledTestFail: 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.
Traceback (most recent call last):
  File "/usr/local/autotest/common_lib/test.py", line 831, in _call_test_function
    return func(*args, **dargs)
  File "/usr/local/autotest/common_lib/test.py", line 495, in execute
    dargs)
  File "/usr/local/autotest/common_lib/test.py", line 362, in _call_run_once_with_retry
    postprocess_profiled_run, args, dargs)
  File "/usr/local/autotest/common_lib/test.py", line 400, in _call_run_once
    self.run_once(*args, **dargs)
  File "/usr/local/autotest/tests/login_OwnershipApi/login_OwnershipApi.py", line 85, in run_once
    sm.StopSession('')
  File "/usr/local/lib64/python2.7/site-packages/dbus/proxies.py", line 145, in __call__
    **keywords)
  File "/usr/local/lib64/python2.7/site-packages/dbus/connection.py", line 651, in call_blocking
    message, timeout)
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.

---

It died when trying to make a StopSession D-Bus call to session_manager. Interestingly, that means that the earlier StartSession call succeeded:

 49     def run_once(self):
 50         pkey = ownership.known_privkey()
 51         pubkey = ownership.known_pubkey()
 52         sm = session_manager.connect(self._bus_loop)
 53         sm.StartSession(ownership.TESTUSER, '')
...
 84         try:
 85             sm.StopSession('')

I see this error, but I think it happens earlier and I suspect it's unrelated:

2018-05-16T10:30:47.021645+00:00 ERR session_manager[5178]: [ERROR:dbus_util.cc(13)] CreateError(...): Domain=dbus, Code=org.chromium.SessionManagerInterface.InitMachineInfoFail, Message=Missing parameters.

Here's the relevant part of the messages log:

2018-05-16T10:30:47.555771+00:00 WARNING session_manager[5178]: [WARNING:exported_object.cc(217)] Unknown method: message_type: MESSAGE_METHOD_CALL#012destination: :1.81#012path: /org/chromium/SessionManager#012interface: org.freedesktop.DBus.Introspectable#012member: Introspect#012sender: :1.86#012serial: 3#012#012
2018-05-16T10:30:47.559704+00:00 INFO session_manager[5178]: [INFO:policy_key.cc(51)] No policy key on disk at /home/root/c6356679f2dea53db93211c46df5c3cd962bf540/session_manager/policy/key
2018-05-16T10:30:47.590642+00:00 INFO session_manager[5178]: [INFO:upstart_signal_emitter.cc(35)] Emitting start-user-session Upstart signal
2018-05-16T10:30:47.594651+00:00 NOTICE kernel: [  240.812204] init: login: Ignoring environment variable CHROMEOS_USER=ownership_test@chromium.org. To include it in the environment, add an import declaration to the job.
2018-05-16T10:30:47.594722+00:00 NOTICE kernel: [  240.812445] init: machine-info: Ignoring environment variable CHROMEOS_USER=ownership_test@chromium.org. To include it in the environment, add an import declaration to the job.
2018-05-16T10:30:47.594588+00:00 INFO session_manager[5178]: [INFO:session_manager_impl.cc(572)] Starting user session
2018-05-16T10:30:47.594882+00:00 INFO session_manager[5178]: [INFO:session_manager_impl.cc(576)] emitting D-Bus signal SessionStateChanged:started
2018-05-16T10:30:48.286508+00:00 INFO session_manager[5178]: [INFO:policy_store.cc(89)] Persisted policy to disk, path: /var/lib/whitelist/policy.1
2018-05-16T10:30:48.396425+00:00 INFO session_manager[5178]: [INFO:session_manager_impl.cc(635)] Stopping all sessions
2018-05-16T10:30:48.396680+00:00 INFO session_manager[5178]: [INFO:session_manager_impl.cc(393)] emitting D-Bus signal SessionStateChanged:stopping
2018-05-16T10:30:48.397533+00:00 INFO session_manager[5178]: [INFO:browser_job.cc(165)] Terminating process: exiting cleanly
2018-05-16T10:30:48.397960+00:00 INFO session_manager[5178]: [INFO:system_utils_impl.cc(94)] Sending 15 to 5222 as 1000

The failed Introspect call is probably harmless. My first guess was that session_manager might exit synchronously when receiving the StopSession call and fail to reply to it, but that doesn't appear to be the case -- SessionManagerImpl::StopSession calls SessionManagerService::ScheduleShutdown, which calls SessionManagerService::SetExitAndScheduleShutdown, which posts a call to brillo::MessageLoop::BreakLoop.

Mattias, do you have any ideas? I assume there's a race of some sort.

Hmm, I also just noticed that org.chromium.SessionManagerInterface.xml sets StopSession's org.chromium.DBus.Method.Kind to "simple", i.e. session_manager doesn't even get a chance to report an error here.

re #3 - Acknowledged, sorry about that.

Sent https://crrev.com/c/1062931 as a speculative workaround (to just delete the failing call).

Failed again in http://cros-goldeneye/chromeos/healthmonitoring/buildDetails?buildbucketId=8946256095791998592.

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

commit 5c73680e75cf369206ac8a00ea341e58024da74f
Author: Daniel Erat <derat@chromium.org>
Date: Fri May 18 02:35:04 2018

autotest: Remove StopSession call in login_OwnershipApi.

Make the login_OwnershipApi client test stop making a
StopSession D-Bus method call to session_manager. This test
is flaky on amd64-generic-tot-asan-informational with
unhandled exceptions like the following:

  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.

I'm assuming that there's some sort of race in the test.
StopSession is already exercised by other tests and doesn't
seem relevant to the feature that login_OwnershipApi is
exercising.

BUG= chromium:838982 
TEST=none; the test fails with "Unhandled ImportError: No
     module named chrome_device_policy_pb2" when i use
     test_that to run it against a random cave DUT in the
     lab :-/

Change-Id: I5cd6228d68793876315ed01790ba4a4412a922e4
Reviewed-on: https://chromium-review.googlesource.com/1062931
Commit-Ready: Dan Erat <derat@chromium.org>
Tested-by: Dan Erat <derat@chromium.org>
Reviewed-by: Mattias Nissler <mnissler@chromium.org>

[modify] https://crrev.com/5c73680e75cf369206ac8a00ea341e58024da74f/client/site_tests/login_OwnershipApi/login_OwnershipApi.py