10/21 02:15:52.046 DEBUG|              test:0370| starting test(run_once()), test details follow
()
10/21 02:15:52.046 DEBUG|             utils:0219| Running 'openssl x509 -in /usr/local/autotest/cros/mock_owner_cert.pem -pubkey -noout | openssl rsa -outform DER -pubin -out /tmp/_autotmp_9BnjmMownership/pubkey.der'
10/21 02:15:52.299 DEBUG|             utils:0219| Running 'openssl sha1 -sign /tmp/_autotmp_9BnjmMownership/pkey.pem'
10/21 02:15:52.321 DEBUG|             utils:0219| Running 'openssl sha1 -sign /tmp/_autotmp_9BnjmMownership/pkey.pem'
10/21 02:18:52.569 ERROR|        cryptohome:0663| Cryptohome is not responding. Sending ABRT
10/21 02:18:52.579 DEBUG|             utils:0219| Running 'pgrep cryptohomed 2>&1'
10/21 02:18:52.601 DEBUG|             utils:0287| [stdout] 1175
10/21 02:18:52.608 DEBUG|             utils:0219| Running 'kill -ABRT 1175'
10/21 02:18:52.617 DEBUG|             utils:0219| Running 'kill -CONT 1175'
10/21 02:18:52.630 DEBUG|             utils:0219| Running 'ps -p 1175'
10/21 02:18:52.654 DEBUG|             utils:0287| [stdout]   PID TTY          TIME CMD
10/21 02:18:52.654 DEBUG|             utils:0287| [stdout]  1175 ?        00:00:20 cryptohomed
10/21 02:18:52.755 DEBUG|             utils:0219| Running 'ps -p 1175'
10/21 02:18:52.784 DEBUG|             utils:0287| [stdout]   PID TTY          TIME CMD
10/21 02:18:52.792 DEBUG|              test:0381| Test failed due to cryptohomed aborted. Check crashes!. Exception log follows the after_iteration_hooks.


messages:

2018-10-21T09:15:50.935789+00:00 WARNING tpm_managerd[4698]: Failed to initialize the trunks IPC proxy; trunksd is not ready.
2018-10-21T09:15:50.937105+00:00 ERR tpm_managerd[4698]: Error TrunksDBusProxy cannot connect to trunksd.
2018-10-21T09:15:50.937140+00:00 ERR tpm_managerd[4698]: GetCapability: SAPI_RC_NO_CONNECTION
2018-10-21T09:15:50.937162+00:00 ERR tpm_managerd[4698]: Failed to query TPM properties: SAPI_RC_NO_CONNECTION
2018-10-21T09:15:50.937184+00:00 WARNING tpm_managerd[4698]: Error initializing trunks tpm state: SAPI_RC_NO_CONNECTION
2018-10-21T09:15:50.938060+00:00 CRIT tpm_managerd[4698]: Check failed: initialized_. #012/usr/lib64/libbase-core-395517.so(_ZN4base5debug10StackTraceC1Ev+0x13) [0x7ae24b234c93]#012
2018-10-21T09:15:50.950726+00:00 INFO crash_reporter[5423]: libminijail[5423]: mount '/dev/log' -> '/dev/log' type '' flags 0x1001
2018-10-21T09:15:50.991895+00:00 WARNING crash_reporter[5423]: Could not load the device policy file.
2018-10-21T09:15:50.992608+00:00 WARNING crash_reporter[5423]: [user] Received crash notification for tpm_managerd[4698] sig 6, user 0 group 0 (developer build - not testing - always dumping)
2018-10-21T09:15:50.994989+00:00 INFO crash_reporter[5423]: State of crashed process [4698]: D (disk sleep)
2018-10-21T09:15:50.995560+00:00 INFO crash_reporter[5423]: Accessing crash dir '/var/spool/crash' via symlinked handle '/proc/self/fd/5'
2018-10-21T09:15:51.043810+00:00 INFO crash_reporter[5423]: Stored minidump to /var/spool/crash/tpm_managerd.20181021.021550.4698.dmp
2018-10-21T09:15:51.044284+00:00 INFO crash_reporter[5423]: Leaving core file at /proc/self/fd/5/tpm_managerd.20181021.021550.4698.core due to developer image
2018-10-21T09:15:51.044857+00:00 WARNING crash_reporter[5423]: [ARC] Received crash notification for tpm_managerd[4698] sig 6, user 0 group 0 (ignoring - crash origin is not ARC)
2018-10-21T09:15:51.052140+00:00 WARNING kernel: [  375.100446] init: tpm_managerd main process (4698) killed by ABRT signal
2018-10-21T09:15:51.052162+00:00 WARNING kernel: [  375.100473] init: tpm_managerd main process ended, respawning
2018-10-21T09:15:51.051498+00:00 ERR cryptohomed[1175]: AddDBusError(...): Domain=dbus, Code=org.freedesktop.DBus.Error.NoReply, Message=Message recipient disconnected from message bus without replying
2018-10-21T09:15:51.053655+00:00 ERR cryptohomed[1175]: AddDBusError(...): Domain=dbus, Code=org.freedesktop.DBus.Error.ServiceUnknown, Message=The name org.chromium.TpmManager was not provided by any .service files
2018-10-21T09:15:51.054368+00:00 WARNING kernel: [  375.103863] kauditd_printk_skb: 24 callbacks suppressed
2018-10-21T09:15:51.054377+00:00 NOTICE kernel: [  375.103866] audit: type=1400 audit(1540113351.052:558): avc:  granted  { execute } for  pid=5427 comm="init" name="dash" dev="dm-0" ino=32855 scontext=u:r:cros_init:s0 tcontext=u:object_r:sh_exec:s0 tclass=file
2018-10-21T09:15:51.061777+00:00 NOTICE kernel: [  375.111412] audit: type=1400 audit(1540113351.060:559): avc:  granted  { execute } for  pid=5429 comm="init" name="dash" dev="dm-0" ino=32855 scontext=u:r:cros_init:s0 tcontext=u:object_r:sh_exec:s0 tclass=file
2018-10-21T09:15:51.076033+00:00 INFO tpm_managerd[5430]: Starting TPM Manager...
2018-10-21T09:15:51.789543+00:00 WARNING attestationd[4717]: Failed to initialize the trunks IPC proxy; trunksd is not ready.
2018-10-21T09:15:51.789580+00:00 ERR attestationd[4717]: Failed to initialize trunks.
2018-10-21T09:15:51.790555+00:00 CRIT attestationd[4717]: Check failed: default_tpm_utility_->Initialize(). #012/usr/lib64/libbase-core-395517.so(_ZN4base5debug10StackTraceC1Ev+0x13) [0x7bc7c18acc93]#012
2018-10-21T09:15:51.800077+00:00 INFO crash_reporter[5433]: libminijail[5433]: mount '/dev/log' -> '/dev/log' type '' flags 0x1001
2018-10-21T09:15:51.837921+00:00 WARNING crash_reporter[5433]: Could not load the device policy file.
2018-10-21T09:15:51.838592+00:00 WARNING crash_reporter[5433]: [user] Received crash notification for attestationd[4717] sig 6, user 247 group 247 (developer build - not testing - always dumping)
2018-10-21T09:15:51.842536+00:00 INFO crash_reporter[5433]: State of crashed process [4717]: D (disk sleep)
2018-10-21T09:15:51.843150+00:00 INFO crash_reporter[5433]: Accessing crash dir '/var/spool/crash' via symlinked handle '/proc/self/fd/5'
2018-10-21T09:15:51.919107+00:00 INFO crash_reporter[5433]: Stored minidump to /var/spool/crash/attestationd.20181021.021551.4717.dmp
2018-10-21T09:15:51.919454+00:00 INFO crash_reporter[5433]: Leaving core file at /proc/self/fd/5/attestationd.20181021.021551.4717.core due to developer image
2018-10-21T09:15:51.919910+00:00 WARNING crash_reporter[5433]: [ARC] Received crash notification for attestationd[4717] sig 6, user 247 group 247 (ignoring - crash origin is not ARC)
2018-10-21T09:15:51.928434+00:00 ERR cryptohomed[1175]: AddDBusError(...): Domain=dbus, Code=org.freedesktop.DBus.Error.NoReply, Message=Message recipient disconnected from message bus without replying
2018-10-21T09:15:51.929299+00:00 WARNING kernel: [  375.976909] init: attestationd main process (4717) killed by ABRT signal
2018-10-21T09:15:51.929315+00:00 WARNING kernel: [  375.976948] init: attestationd main process ended, respawning
2018-10-21T09:15:51.932257+00:00 ERR arc-oemcrypto[5160]: Failed to call method: org.chromium.CryptohomeInterface.TpmIsAttestationPrepared: object_path= /org/chromium/Cryptohome: org.freedesktop.DBus.Error.Failed: Attestation daemon returned status 2
2018-10-21T09:15:51.932289+00:00 ERR arc-oemcrypto[5160]: Failure in D-Bus response from boolean call
2018-10-21T09:15:51.935067+00:00 WARNING cryptohomed[1175]: No valid keysets on disk for 4396c54d5a5c2c5f45f0284dc4232880536ad820
2018-10-21T09:15:51.936576+00:00 NOTICE kernel: [  375.985485] audit: type=1400 audit(1540113351.934:560): avc:  granted  { execute } for  pid=5437 comm="init" name="dash" dev="dm-0" ino=32855 scontext=u:r:cros_init:s0 tcontext=u:object_r:sh_exec:s0 tclass=file
2018-10-21T09:15:51.938087+00:00 WARNING session_manager[4888]: [WARNING:exported_object.cc(217)] Unknown method: message_type: MESSAGE_METHOD_CALL#012destination: :1.124#012path: /org/chromium/SessionManager#012interface: org.freedesktop.DBus.Introspectable#012member: Introspect#012sender: :1.132#012serial: 9#012#012
2018-10-21T09:15:51.945041+00:00 NOTICE kernel: [  375.994219] audit: type=1400 audit(1540113351.943:561): avc:  granted  { execute } for  pid=5438 comm="init" name="dash" dev="dm-0" ino=32855 scontext=u:r:cros_init:s0 tcontext=u:object_r:sh_exec:s0 tclass=file
2018-10-21T09:15:51.984531+00:00 INFO attestationd[5447]: Attestation Daemon Started.
2018-10-21T09:15:51.985610+00:00 WARNING attestationd[5447]: libminijail[5447]: non-debug build: ignoring request to enable seccomp logging
2018-10-21T09:15:51.988220+00:00 NOTICE kernel: [  376.037402] audit: type=1400 audit(1540113351.986:562): avc:  granted  { execute } for  pid=5448 comm="init" name="dash" dev="dm-0" ino=32855 scontext=u:r:cros_init:s0 tcontext=u:object_r:sh_exec:s0 tclass=file
2018-10-21T09:15:51.989839+00:00 INFO attestationd[5447]: Attestation service started.
2018-10-21T09:15:52.043522+00:00 NOTICE root[5453]: autotest starting iteration /usr/local/autotest/results/default/login_OwnershipRetaken/sysinfo/iteration.1 on grunt_1.6GHz_4GB
2018-10-21T09:15:52.347115+00:00 INFO session_manager[4888]: [INFO:policy_service.cc(229)] Attempting to install new policy key.
2018-10-21T09:15:52.359812+00:00 INFO session_manager[4888]: [INFO:policy_service.cc(264)] Persisted policy key to disk.
2018-10-21T09:15:52.365770+00:00 INFO session_manager[4888]: [INFO:policy_store.cc(88)] Persisted policy to disk, path: /var/lib/whitelist/policy.1
2018-10-21T09:15:52.485828+00:00 INFO cryptohomed[1175]: InstallAttributes have been finalized.

Issue 897575 has been merged into this issue.

attestationd also crashed. yunlian@ Can it be related to these two changes?
https://chromium-review.googlesource.com/c/chromiumos/platform2/+/1289004
https://chromium-review.googlesource.com/c/chromiumos/platform2/+/1289452

Thread 0 (crashed)
 0  libc-2.23.so!raise [raise.c : 54 + 0x10]
 1  libc-2.23.so!abort [abort.c : 89 + 0xa]
 2  libbase-core-395517.so!base::debug::BreakDebugger() [debugger_posix.cc : 249 + 0x5]
 3  libbase-core-395517.so!logging::LogMessage::~LogMessage() [logging.cc : 755 + 0x5]
 4  attestationd!attestation::AttestationService::InitializeTask() [attestation_service.cc : 419 + 0x37]
 5  libbase-core-395517.so!base::debug::TaskAnnotator::RunTask(char const*, base::PendingTask const&) [callback.h : 397 + 0x4]
 6  libbase-core-395517.so!base::MessageLoop::RunTask(base::PendingTask const&) [message_loop.cc : 478 + 0xf]
 7  libbase-core-395517.so!base::MessageLoop::DeferOrRunPendingTask(base::PendingTask const&) [message_loop.cc : 487 + 0xb]
 8  libbase-core-395517.so!base::MessageLoop::DoWork() [message_loop.cc : 604 + 0xb]
 9  libbase-core-395517.so!base::MessagePumpLibevent::Run(base::MessagePump::Delegate*) [message_pump_libevent.cc : 224 + 0x9]
10  libbase-core-395517.so!base::MessageLoop::RunHandler() [message_loop.cc : 442 + 0x9]
11  libbase-core-395517.so!base::RunLoop::Run() [run_loop.cc : 35 + 0x5]
12  libbase-core-395517.so!base::MessageLoop::Run() [message_loop.cc : 294 + 0x8]
13  libbase-core-395517.so!base::Thread::ThreadMain() [thread.cc : 252 + 0x6]
14  libbase-core-395517.so!base::(anonymous namespace)::ThreadFunc(void*) [platform_thread_posix.cc : 70 + 0x8]
15  libpthread-2.23.so!start_thread [pthread_create.c : 333 + 0x11]
16  libc-2.23.so!clone + 0x6d

For #4, it is unlikely that my change caused the crash. My change only allows some system calls under minijail and they are not been called at all with current glibc(otherwise, minijail would kill these processes).

Those messages from #1 are already consequences of the root cause problem. tpm_managerd and attestationd crash because they try to connect to trunksd that should provide a comm channel to the TPM to them, but trunksd is not running. Or at least is not registered on dbus. Since per messages in https://stainless.corp.google.com/browse/chromeos-autotest-results/250684593-chromeos-test/, trunksd started, but we heard nothing else from it:

2018-10-21T23:47:21.217279+00:00 INFO trunksd[1347]: TPM: /dev/tpm0 opened successfully
2018-10-21T23:47:21.217606+00:00 WARNING trunksd[1347]: libminijail[1347]: non-debug build: ignoring request to enable seccomp logging

And we then have all the connection issues:
2018-10-21T23:47:52.638802+00:00 WARNING tpm_managerd[1386]: Failed to initialize the trunks IPC proxy; trunksd is not ready.
2018-10-21T23:47:52.673908+00:00 ERR chapsd[1379]: Error TrunksDBusProxy cannot connect to trunksd.
2018-10-21T23:47:52.686898+00:00 WARNING attestationd[1448]: Failed to initialize the trunks IPC proxy; trunksd is not ready.
2018-10-21T23:47:52.795245+00:00 NOTICE cr50-metrics[3250]: Error: gsctool status 3, output "[ERROR:trunks_send.cc(862)] Failed to initialize dbus proxy.#012Problems reading from TPM, got 0 bytes#012Error: Failed to send vendor command 25"

Looking at the successful run in 1174.0.0 (https://stainless.corp.google.com/browse/chromeos-autotest-results/250039610-chromeos-test/), this is how trunksd normally starts:
2018-10-19T22:35:41.069896+00:00 INFO trunksd[1322]: TPM: /dev/tpm0 opened successfully

2018-10-19T22:35:41.070293+00:00 WARNING trunksd[1322]: libminijail[1322]: allowing syscall: socket
2018-10-19T22:35:41.070341+00:00 WARNING trunksd[1322]: libminijail[1322]: allowing syscall: connect
2018-10-19T22:35:41.070384+00:00 WARNING trunksd[1322]: libminijail[1322]: allowing syscall: sendto
2018-10-19T22:35:41.070465+00:00 WARNING trunksd[1322]: libminijail[1322]: allowing syscall: writev
2018-10-19T22:35:41.072291+00:00 WARNING trunksd[1322]: libminijail[1322]: logging seccomp filter failures

2018-10-19T22:35:41.073630+00:00 INFO trunksd[1322]: Trunks service started.

Given that difference, this is the most suspicious change: https://crrev.com/c/1249881

of those syscalls, "sendto" is the one not already in the trunksd seccomp policies.  if it uses that syscall (e.g. for syslog), then you'll want to add it to the existing files.

Ok, given that it depends on the arch, here's the list:

 - x86_64: allow_loggin_syscalls() allows {"socket", "connect", "sendto", "writev"}; while x86_64 and amd64 seccomp filters for trunks have only socket, connect, writev. 'sendto' is missing. [and that's our eve case above]

 - i386: {"socketcall", "time", "writev"}; x86 filter has them all.

 - arm: {"socket", "connect", "gettimeofday", "send", "writev"}; arm filter has them all.

 - aarch64: {"socket", "connect", "send", "writev"}; arm64 filter doesn't have 'send'.

- powerpc/ia64/hppa/sparc/mips: {"socket", "connect", "send"}; mips filter doesn't have 'send'.

So, if we indeed miss those calls provided by allow_loggin_syscalls() before, looks like we should be adding
 - x86_64: sendto
 - amd64: sendto
 - arm64: send
 - mips: send

I'm curious, though, why there are no selinux violation messages in the logs from #6 if that's indeed the problem. And trunksd keeps running: there are coredumps from cryptohomed, atetstationd, tpm_managerd, but not trunksd. Are we supposed to see them in this situation?

seccomp & selinux are unrelated systems, so i don't see why selinux would report anything about it.

if an earlier autotest ran and cleared out the trunksd crashes, then this one wouldn't see them.  do you know for sure that trunksd is running ?

 Issue 897907  has been merged into this issue.

Adding 'sendto' indeed fixes it for eve: https://crrev.com/c/1294817

Re #11:

> do you know for sure that trunksd is running ?

No traces in the logs that indicate that trunksd crashed. But in my experiments, trunksd was indeed crashing and respawning, also with nothing in the logs to indicate that. So, trunksd must have been not running indeed.

 Issue 897993  has been merged into this issue.

 Issue 897574  has been merged into this issue.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform2/+/704571ddd5af38cd78d21b53af0995527015b079

commit 704571ddd5af38cd78d21b53af0995527015b079
Author: Andrey Pronin <apronin@chromium.org>
Date: Tue Oct 23 20:01:55 2018

trunks: allow logging syscalls

trunksd was implicitly relying on minijail_log_seccomp_filter_failures()
to allow syscalls required for syslog(). With CL:1249881 in, minijail
ignores those requests and no longer calls allow_logging_syscalls() if
built without cros-debug use flag.

This CL explicitly adds missing syscalls from log_syscalls[] table to
the list of allowed in trunksd-seccomp-*.policy filters.

BUG= chromium:897541 
TEST=On eve board:
     1) USE=-cros-debug emerge-$BOARD minijail trunks
        cros deploy $dut minijail trunks
        grep trunks /var/log/messages
        verify that there are no issues with tpm_managerd and other
        daemons when connecting to trunksd
     2) test_that $dut login_OwnershipApi

Change-Id: I123f511a559009683306eb3e79b326ae0e456eef
Reviewed-on: https://chromium-review.googlesource.com/1294817
Commit-Ready: ChromeOS CL Exonerator Bot <chromiumos-cl-exonerator@appspot.gserviceaccount.com>
Tested-by: Andrey Pronin <apronin@chromium.org>
Reviewed-by: Mike Frysinger <vapier@chromium.org>

[modify] https://crrev.com/704571ddd5af38cd78d21b53af0995527015b079/trunks/trunksd-seccomp-amd64.policy
[modify] https://crrev.com/704571ddd5af38cd78d21b53af0995527015b079/trunks/trunksd-seccomp-arm64.policy
[modify] https://crrev.com/704571ddd5af38cd78d21b53af0995527015b079/trunks/trunksd-seccomp-mips.policy
[modify] https://crrev.com/704571ddd5af38cd78d21b53af0995527015b079/trunks/trunksd-seccomp-x86_64.policy

Issue 897869 has been merged into this issue.

we now have first version (11187.0.0) with this fix.
things look greener now.

though to me it seems that it's safer to revert 
https://chromium-review.googlesource.com/c/chromiumos/overlays/chromiumos-overlay/+/1249881

Since this change landed, the last two release builds of grunt, pyro, nautilus, eve are green (well, one nautilus is red for unrelated reasons). coral and nami are red for unrelated reasons: the login_ failures from 3 builds ago have stopped. bob's behavior has changed but it still had several login-related crashes with similar symptoms.
So, keeping the bug open to finish with bob, but lowering to P1.

For bob: still stuck at the same place:
2018-10-24T14:18:20.278727+00:00 INFO trunksd[1301]: TPM: /dev/tpm0 opened successfully
2018-10-24T14:18:20.279768+00:00 WARNING trunksd[1301]: libminijail[1301]: non-debug build: ignoring request to enable seccomp logging
<and nothing else from trunksd, no "Trunks service started.">

Then failing to connect to it afterwards:
2018-10-24T14:18:51.256611+00:00 ERR chapsd[1373]: Error TrunksDBusProxy cannot connect to trunksd.
... etc ...

So, aarch64 case seems to be missing more syscalls.
But all of the following calls defined in aosp/external/minijail/util.c for aarch64, which used to be auto-allowed after calling minijail_log_seccomp_filter_failures()
  const char *log_syscalls[] = {"socket", "connect", "send", "writev"};
are now explicitly allowed in trunksd-seccomp-arm64.policy

Hm, judging by older logs, bob is treated as arm, not aarch64:
2018-10-21T07:15:08.229054+00:00 WARNING trunksd[1395]: libminijail[1395]: allowing syscall: socket
2018-10-21T07:15:08.229485+00:00 WARNING trunksd[1395]: libminijail[1395]: allowing syscall: connect
2018-10-21T07:15:08.229693+00:00 WARNING trunksd[1395]: libminijail[1395]: allowing syscall: gettimeofday
2018-10-21T07:15:08.229766+00:00 WARNING trunksd[1395]: libminijail[1395]: allowing syscall: send
2018-10-21T07:15:08.229833+00:00 WARNING trunksd[1395]: libminijail[1395]: allowing syscall: writev

And trunksd-seccomp-arm.policy is still missing 'send'. Somehow, I didn't notice it in comment #10 :/
So, looks like there is an issue with arch incorrectly detected for bob. But, in any case, I need to add 'send' for arm case. 

Ok, trunksd on bob being built with ARCH=arm must be WAI: issue 878565. Didn't realize we are using 32-bit userspace on aarch64 boards.
The CL that adds 'send' for arm is https://crrev.com/c/1298273

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform2/+/de16b072216488671047983a70fada203bb934b4

commit de16b072216488671047983a70fada203bb934b4
Author: Andrey Pronin <apronin@chromium.org>
Date: Thu Oct 25 22:19:05 2018

trunks: allow logging syscalls for arm

trunksd was implicitly relying on minijail_log_seccomp_filter_failures()
to allow syscalls required for syslog(). With CL:1249881 in, minijail
ignores those requests and no longer calls allow_logging_syscalls() if
built without cros-debug use flag.

This CL explicitly adds missing syscalls from log_syscalls[] table to
the list of allowed in trunksd-seccomp-arm.policy filter.

BUG= chromium:897541 
TEST=emerge-bob trunks;
     verify that /build/bob/usr/share/policy/trunksd-seccomp.policy
     allows 'send'.

Change-Id: I6d43dc8819eb202449dc9e6d984a707a5db00aef
Reviewed-on: https://chromium-review.googlesource.com/1298273
Commit-Ready: ChromeOS CL Exonerator Bot <chromiumos-cl-exonerator@appspot.gserviceaccount.com>
Tested-by: Andrey Pronin <apronin@chromium.org>
Reviewed-by: Mike Frysinger <vapier@chromium.org>

[modify] https://crrev.com/de16b072216488671047983a70fada203bb934b4/trunks/trunksd-seccomp-arm.policy

thanks for the help