New issue
Advanced search Search tips
Note: Color blocks (like █ or █) mean that a user may not be available. Tooltip shows the reason.

Issue 876481 link

Starred by 1 user
Status: Fixed
Owner:
yusukes@chromium.org
Closed: Aug 22
Cc:
█ lhchavez@chromium.org
yusukes@chromium.org
hidehiko@chromium.org
nya@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug



Sign in to add a comment

arc.Boot test timed out on caroline-arcnext with many exiting untracked processes

Project Member Reported by derat@chromium.org, Aug 21 
The arc.Boot Tast test timed out while waiting for Android to boot on the caroline-arcnext Android PFQ build at http://stainless/browse/chromeos-autotest-results/229525224-chromeos-test/

arc.log lists a ton of exiting processes near the end:

...
2018-08-21T02:02:03.881472+00:00 NOTICE arc-kmsg-logger[5814]: <6>init: starting service 'adbd'...
2018-08-21T02:02:03.890981+00:00 NOTICE arc-kmsg-logger[5814]: <6>init: Created socket '/dev/socket/adbd', mode 660, user 1000, group 1000
2018-08-21T02:02:03.925281+00:00 NOTICE arc-kmsg-logger[5814]: <6>init: Untracked pid 737 exited with status 0
2018-08-21T02:02:03.934908+00:00 NOTICE arc-kmsg-logger[5814]: <6>init: Untracked pid 739 exited with status 0
2018-08-21T02:02:03.960033+00:00 NOTICE arc-kmsg-logger[5814]: <3>selinux: avc:  denied  { set } for property=ctl.start$mdnsd pid=743 uid=2000 gid=2000 scontext=u:r:adbd:s0 tcontext=u:object_r:ctl_start_prop:s0 tclass=property_service permissive=0
2018-08-21T02:02:03.960044+00:00 NOTICE arc-kmsg-logger[5814]: 
2018-08-21T02:02:03.960056+00:00 NOTICE arc-kmsg-logger[5814]: <3>init: Unable to set property 'ctl.start' to 'mdnsd' from uid:2000 gid:2000 pid:743: Invalid permissions to perform 'start' on 'mdnsd'
2018-08-21T02:02:04.326755+00:00 NOTICE arc-kmsg-logger[5814]: <6>init: Untracked pid 784 exited with status 0
2018-08-21T02:02:04.343975+00:00 NOTICE arc-kmsg-logger[5814]: <6>init: Untracked pid 798 exited with status 0
2018-08-21T02:02:04.388227+00:00 NOTICE arc-kmsg-logger[5814]: <6>init: Received control message 'interface_start' for 'android.hardware.secure_element@1.0::ISecureElement/eSE1' from pid: 7 (/system/bin/hwservicemanager)
2018-08-21T02:02:04.388243+00:00 NOTICE arc-kmsg-logger[5814]: <3>init: Could not find service hosting interface android.hardware.secure_element@1.0::ISecureElement/eSE1
2018-08-21T02:02:04.393272+00:00 NOTICE arc-kmsg-logger[5814]: <6>init: Received control message 'interface_start' for 'android.hardware.secure_element@1.0::ISecureElement/SIM1' from pid: 7 (/system/bin/hwservicemanager)
2018-08-21T02:02:04.393290+00:00 NOTICE arc-kmsg-logger[5814]: <3>init: Could not find service hosting interface android.hardware.secure_element@1.0::ISecureElement/SIM1
2018-08-21T02:02:04.443904+00:00 NOTICE arc-kmsg-logger[5814]: <6>init: Untracked pid 847 received signal 13
2018-08-21T02:02:04.451942+00:00 NOTICE arc-kmsg-logger[5814]: <6>init: Untracked pid 868 exited with status 0
2018-08-21T02:02:04.505785+00:00 INFO arc-networkd[6174]: [INFO:router_finder.cc(57)] No IPv6 router found on iface eth0
2018-08-21T02:02:04.505987+00:00 NOTICE arc-kmsg-logger[5814]: <6>init: Untracked pid 872 exited with status 0
2018-08-21T02:02:04.513941+00:00 NOTICE arc-kmsg-logger[5814]: <6>init: Untracked pid 875 exited with status 0
2018-08-21T02:02:04.566805+00:00 NOTICE arc-kmsg-logger[5814]: <6>init: Untracked pid 895 exited with status 0
2018-08-21T02:02:04.573959+00:00 NOTICE arc-kmsg-logger[5814]: <6>init: Untracked pid 897 exited with status 0
2018-08-21T02:02:04.632970+00:00 NOTICE arc-kmsg-logger[5814]: <6>init: Untracked pid 945 exited with status 0
2018-08-21T02:02:04.640870+00:00 NOTICE arc-kmsg-logger[5814]: <6>init: Untracked pid 947 exited with status 0
2018-08-21T02:02:07.583814+00:00 NOTICE arc-kmsg-logger[5814]: <6>init: Untracked pid 1006 exited with status 0
2018-08-21T02:02:07.592986+00:00 NOTICE arc-kmsg-logger[5814]: <6>init: Untracked pid 1008 exited with status 0
2018-08-21T02:02:08.902692+00:00 NOTICE arc-kmsg-logger[5814]: <6>init: Untracked pid 1044 exited with status 0
2018-08-21T02:02:08.911920+00:00 NOTICE arc-kmsg-logger[5814]: <6>init: Untracked pid 1046 exited with status 0
...

There's also a 1.6 MB logcat.txt file in the logs directory, so hopefully there's enough info to figure out what went wrong.

Comment 1 by lhchavez@chromium.org, Aug 22

Owner: yusukes@chromium.org
This is caused by b/111316945:

08-21 02:01:58.618   577   577 I crash_dump32: performing dump of process 526 (target tid = 526)
--------- beginning of crash
08-21 02:01:58.623   577   577 F DEBUG   : *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***
08-21 02:01:58.623   577   577 F DEBUG   : Build fingerprint: 'google/caroline-arcnext/caroline-arcnext_cheets:9/R70-10985.0.9999/4963909:user/release-key'
08-21 02:01:58.623   577   577 F DEBUG   : Revision: '0'
08-21 02:01:58.623   577   577 F DEBUG   : ABI: 'x86'
08-21 02:01:58.623   577   577 F DEBUG   : pid: 526, tid: 526, name: ndroid.systemu  >>> zygote <<<
08-21 02:01:58.623   577   577 F DEBUG   : signal 6 (SIGABRT), code -6 (SI_TKILL), fault addr --------
08-21 02:01:58.623   577   577 F DEBUG   : Abort message: 'oat_file_manager.cc:639] Check failed: oat_files_.size() == GetBootOatFiles().size() (oat_files_.size()=15, GetBootOatFiles().size()=0) '
08-21 02:01:58.623   577   577 F DEBUG   :     eax 00000000  ebx 0000020e  ecx 0000020e  edx 00000006
08-21 02:01:58.623   577   577 F DEBUG   :     edi dbe9ef85  esi 00000000
08-21 02:01:58.623   577   577 F DEBUG   :     ebp 00000001  esp ff94eba8  eip e8954a40
08-21 02:01:58.643   577   577 F DEBUG   : 
08-21 02:01:58.643   577   577 F DEBUG   : backtrace:
08-21 02:01:58.643   577   577 F DEBUG   :     #00 pc 00000a40  [vdso:e8954000] (__kernel_vsyscall+16)
08-21 02:01:58.643   577   577 F DEBUG   :     #01 pc 0001fc68  /system/lib/libc.so (syscall+40)
08-21 02:01:58.643   577   577 F DEBUG   :     #02 pc 00032203  /system/lib/libc.so (abort+115)
08-21 02:01:58.643   577   577 F DEBUG   :     #03 pc 0051eb80  /system/lib/libart.so (art::Runtime::Abort(char const*)+1296)
08-21 02:01:58.643   577   577 F DEBUG   :     #04 pc 0061c343  /system/lib/libart.so (_ZNSt3__110__function6__funcIPFvPKcENS_9allocatorIS5_EES4_EclEOS3_+35)
08-21 02:01:58.643   577   577 F DEBUG   :     #05 pc 00007cae  /system/lib/libbase.so (android::base::LogMessage::~LogMessage()+734)
08-21 02:01:58.643   577   577 F DEBUG   :     #06 pc 004ab50a  /system/lib/libart.so (art::OatFileManager::SetOnlyUseSystemOatFiles()+1018)
08-21 02:01:58.643   577   577 F DEBUG   :     #07 pc 00465395  /system/lib/libart.so (art::ZygoteHooks_nativePostForkChild(_JNIEnv*, _jclass*, long long, int, unsigned char, unsigned char, _jstring*)+3525)
08-21 02:01:58.643   577   577 F DEBUG   :     #08 pc 00645f17  /system/lib/libart.so (art_quick_generic_jni_trampoline+71)
08-21 02:01:58.643   577   577 F DEBUG   :     #09 pc 006400d2  /system/lib/libart.so (art_quick_invoke_static_stub+418)
08-21 02:01:58.643   577   577 F DEBUG   :     #10 pc 000a307f  /system/lib/libart.so (art::ArtMethod::Invoke(art::Thread*, unsigned int*, unsigned int, art::JValue*, char const*)+239)
08-21 02:01:58.643   577   577 F DEBUG   :     #11 pc 002b9629  /system/lib/libart.so (art::interpreter::ArtInterpreterToCompiledCodeBridge(art::Thread*, art::ArtMethod*, art::ShadowFrame*, unsigned short, art::JValue*)+361)

The reason for the untracked pids is that a process (pid=576) is crashing (with the exact same assertion). It then fork(2)s in order to call crash_dump (pid=577), but it itself crashes. Its parent is dead, so it cannot waitpid(2) on it, so it is bubbled up to init.

Comment 2 by lhchavez@chromium.org, Aug 22 

http://ag/4839915 _may_ fix this.

Comment 3 by lhchavez@chromium.org, Aug 22

Status: Fixed (was: Assigned)
Fix has landed. Next build after a PFQ run should be good.
►

Sign in to add a comment