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

Issue 877950 link

Starred by 1 user

Issue metadata

Status: Untriaged
Owner: ----
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

DUT hung during testing due to blocked binder task

Project Member Reported by derat@chromium.org, Aug 27

Issue description

chromeos4-row10-rack1-host8 looks like it died mid-testing at http://stainless/browse/chromeos-autotest-results/231016631-chromeos-test/, but we were able to reconnect to it:

2018/08/25 12:10:12 Started test ui.SessionManagerRespawn
2018/08/25 12:10:12 [12:10:12.409] Getting initial session_manager process
2018/08/25 12:10:12 [12:10:12.413] Initial session_manager process is 14844
2018/08/25 12:10:12 [12:10:12.413] Killing 14844
2018/08/25 12:10:12 [12:10:12.413] Waiting for session_manager to respawn
2018/08/25 12:12:12 [12:12:12.401] Error at respawn.go:58: Failed waiting for session_manager to respawn: context deadline exceeded (/sbin/session_manager process not found)
...
2018/08/25 12:12:12 Completed test ui.SessionManagerRespawn in 2m0.006s with 1 error(s)
2018/08/25 12:12:12 Started test video.PlayH264
2018/08/25 12:12:12 [12:12:12.402] Restarting ui job
2018/08/25 12:12:12 [12:12:12.408] External command failed: exit status 1
...
2018/08/25 12:15:23 Failed to run tests: context deadline exceeded
2018/08/25 12:15:23 Lost SSH connection to chromeos4-row10-rack1-host8:22: EOF
2018/08/25 12:15:23 Collecting system information
2018/08/25 12:15:23 Connecting to chromeos4-row10-rack1-host8:22
2018/08/25 12:15:23 Copying /tmp/tast_logs.543367337 from host to /usr/local/autotest/results/lxc_job_folder/tast/results/system_logs
2018/08/25 12:15:24 Cleaning /tmp/tast_logs.543367337 on host
2018/08/25 12:15:24 Copying /tmp/tast_crashes.640965108 from host to /usr/local/autotest/results/lxc_job_folder/tast/results/crashes
2018/08/25 12:15:24 Cleaning /tmp/tast_crashes.640965108 on host

The messages log appears to suggest there might be a binder bug in the kernel:

...
2018-08-25T12:10:12.483953-07:00 NOTICE ui-respawn[15504]: ui died on signal KILL.
2018-08-25T12:10:12.493743-07:00 INFO crash_reporter[15497]: libminijail[15497]: mount /dev/log -> /dev/log type ''
2018-08-25T12:10:12.514747-07:00 INFO crash_reporter[15497]: Processing selinux violation: always collect from developer builds
2018-08-25T12:10:12.515176-07:00 INFO crash_reporter[15497]: Accessing crash dir '/var/spool/crash' via symlinked handle '/proc/self/fd/7'
2018-08-25T12:10:12.568949-07:00 INFO crash_reporter[15510]: libminijail[15510]: mount /dev/log -> /dev/log type ''
2018-08-25T12:10:12.573338-07:00 NOTICE ui-respawn[15519]: Respawning ui.
2018-08-25T12:10:12.582604-07:00 WARNING cryptohomed[840]: RemoveKeyset: key to remove not found
2018-08-25T12:10:12.586729-07:00 INFO crash_reporter[15510]: Processing selinux violation: always collect from developer builds
2018-08-25T12:10:12.587163-07:00 INFO crash_reporter[15510]: Accessing crash dir '/var/spool/crash' via symlinked handle '/proc/self/fd/7'
2018-08-25T12:10:12.587351-07:00 WARNING crash_reporter[15510]: Failed to write audit message to /proc/self/fd/7/selinux_violation.20180825.121012.0.log: File exists
2018-08-25T12:10:12.792316-07:00 INFO chapsd[755]: Token at /home/root/df31274fe57fcc97863e0c801bf994272a829ed4/chaps has been removed from slot 1
2018-08-25T12:10:15.095182-07:00 ERR chapsd[755]: GetSlotInfo - CKR_SLOT_ID_INVALID
2018-08-25T12:10:15.100166-07:00 ERR chapsd[755]: FindObjectsInit - CKR_SESSION_HANDLE_INVALID
2018-08-25T12:10:15.101807-07:00 ERR chapsd[755]: FindObjectsInit - CKR_SESSION_HANDLE_INVALID
2018-08-25T12:10:23.599479-07:00 WARNING cryptohomed[840]: ManageCCDPwd is not supported
2018-08-25T12:10:42.143517-07:00 WARNING kernel: [  812.589605] audit_printk_skb: 18 callbacks suppressed
2018-08-25T12:10:42.143531-07:00 NOTICE kernel: [  812.589611] audit: type=1400 audit(1535224242.141:1710): avc:  granted  { execute } for  pid=15689 comm="python" name="dash" dev="dm-0" ino=57432 scontext=u:r:cros_init:s0 tcontext=u:object_r:sh_exec:s0 tclass=file
2018-08-25T12:10:42.143532-07:00 NOTICE kernel: [  812.589863] audit: type=1400 audit(1535224242.141:1711): avc:  granted  { execute } for  pid=15689 comm="check_ethernet." path="/bin/dash" dev="dm-0" ino=57432 scontext=u:r:cros_init:s0 tcontext=u:object_r:sh_exec:s0 tclass=file
2018-08-25T12:11:20.596533-07:00 ERR kernel: [  851.041760] INFO: rcu_preempt detected stalls on CPUs/tasks:
2018-08-25T12:11:20.596548-07:00 ERR kernel: [  851.041767] 	Tasks blocked on level-0 rcu_node (CPUs 0-1): P13889
2018-08-25T12:11:20.596549-07:00 ERR kernel: [  851.041773] 	(detected by 0, t=60002 jiffies, g=93150, c=93149, q=744175)
2018-08-25T12:11:20.596549-07:00 INFO kernel: [  851.041778] Binder:1765_1   R  running task        0 13889  11440 0x00000004
2018-08-25T12:11:20.596550-07:00 WARNING kernel: [  851.041784]  ffff880018598f00 ffff88017ec15900 ffff880167362ac0 ffff8801062f4740
2018-08-25T12:11:20.596551-07:00 WARNING kernel: [  851.041791]  ffff880057c1dee8 ffff88013bfeb9d0 ffffffffa51e72da ffffffffa51eb970
2018-08-25T12:11:20.596552-07:00 WARNING kernel: [  851.041797]  00000001a51eb964 ffffffffa51eb970 ffffffffa51eb964 937f28651874724d
2018-08-25T12:11:20.596553-07:00 WARNING kernel: [  851.041803] Call Trace:
2018-08-25T12:11:20.596553-07:00 WARNING kernel: [  851.041812]  [<ffffffffa51e72da>] ? __schedule+0x3d6/0x92a
2018-08-25T12:11:20.596554-07:00 WARNING kernel: [  851.041816]  [<ffffffffa51eb970>] ? __switch_to_asm+0x40/0x70
2018-08-25T12:11:20.596555-07:00 WARNING kernel: [  851.041820]  [<ffffffffa51eb970>] ? __switch_to_asm+0x40/0x70
2018-08-25T12:11:20.596556-07:00 WARNING kernel: [  851.041823]  [<ffffffffa51eb964>] ? __switch_to_asm+0x34/0x70
2018-08-25T12:11:20.596557-07:00 WARNING kernel: [  851.041826]  [<ffffffffa51e799e>] preempt_schedule_irq+0x49/0x86
2018-08-25T12:11:20.596557-07:00 WARNING kernel: [  851.041830]  [<ffffffffa51ec1ae>] retint_kernel+0x1b/0x1d
2018-08-25T12:11:20.596558-07:00 WARNING kernel: [  851.041834]  [<ffffffffa4c95780>] ? __d_lookup+0x59/0x15f
2018-08-25T12:11:20.596559-07:00 WARNING kernel: [  851.041837]  [<ffffffffa4c9577c>] ? __d_lookup+0x55/0x15f
2018-08-25T12:11:20.596560-07:00 WARNING kernel: [  851.041840]  [<ffffffffa4c9570e>] d_lookup+0x2b/0x44
2018-08-25T12:11:20.596560-07:00 WARNING kernel: [  851.041844]  [<ffffffffa4be099d>] d_hash_and_lookup+0x48/0x51
2018-08-25T12:11:20.596565-07:00 WARNING kernel: [  851.041847]  [<ffffffffa4c1f402>] proc_flush_task+0xe2/0x194
2018-08-25T12:11:20.596566-07:00 WARNING kernel: [  851.041851]  [<ffffffffa4ab7832>] release_task+0x3d/0x382
2018-08-25T12:11:20.596567-07:00 WARNING kernel: [  851.041854]  [<ffffffffa51eaf60>] ? _raw_spin_unlock_bh+0x1c/0x1e
2018-08-25T12:11:20.596568-07:00 WARNING kernel: [  851.041857]  [<ffffffffa4ab823b>] do_exit+0x56d/0x7c9
2018-08-25T12:11:20.596568-07:00 WARNING kernel: [  851.041861]  [<ffffffffa4ab8729>] do_group_exit+0x96/0xa5
2018-08-25T12:11:20.596569-07:00 WARNING kernel: [  851.041864]  [<ffffffffa4ac1917>] get_signal+0x135/0x56e
2018-08-25T12:11:20.596570-07:00 WARNING kernel: [  851.041868]  [<ffffffffa4a4bc4d>] do_signal+0x35/0x53c
2018-08-25T12:11:20.596571-07:00 WARNING kernel: [  851.041871]  [<ffffffffa4bd05e1>] ? __check_object_size+0xca/0x16f
2018-08-25T12:11:20.596571-07:00 WARNING kernel: [  851.041875]  [<ffffffffa4b617f0>] ? __might_sleep+0x41/0x7d
2018-08-25T12:11:20.596572-07:00 WARNING kernel: [  851.041879]  [<ffffffffa4ab2143>] prepare_exit_to_usermode+0x75/0x77
2018-08-25T12:11:20.596573-07:00 WARNING kernel: [  851.041883]  [<ffffffffa4ab2188>] syscall_return_slowpath+0x43/0x14c
2018-08-25T12:11:20.596573-07:00 WARNING kernel: [  851.041886]  [<ffffffffa4c92ae5>] ? SyS_ioctl+0x64/0x256
2018-08-25T12:11:20.596574-07:00 WARNING kernel: [  851.041889]  [<ffffffffa51eb734>] int_ret_from_sys_call+0x25/0x93
2018-08-25T12:11:20.596575-07:00 INFO kernel: [  851.041892] Binder:1765_1   R  running task        0 13889  11440 0x00000004
2018-08-25T12:11:20.596576-07:00 WARNING kernel: [  851.041897]  ffff880018598f00 ffff88017ec15900 ffff880167362ac0 ffff8801062f4740
2018-08-25T12:11:20.596576-07:00 WARNING kernel: [  851.041903]  ffff880057c1dee8 ffff88013bfeb9d0 ffffffffa51e72da ffffffffa51eb970
2018-08-25T12:11:20.596577-07:00 WARNING kernel: [  851.041909]  00000001a51eb964 ffffffffa51eb970 ffffffffa51eb964 937f28651874724d
2018-08-25T12:11:20.596578-07:00 WARNING kernel: [  851.041915] Call Trace:
2018-08-25T12:11:20.596579-07:00 WARNING kernel: [  851.041919]  [<ffffffffa51e72da>] ? __schedule+0x3d6/0x92a
2018-08-25T12:11:20.596579-07:00 WARNING kernel: [  851.041923]  [<ffffffffa51eb970>] ? __switch_to_asm+0x40/0x70
2018-08-25T12:11:20.596580-07:00 WARNING kernel: [  851.041925]  [<ffffffffa51eb970>] ? __switch_to_asm+0x40/0x70
2018-08-25T12:11:20.596581-07:00 WARNING kernel: [  851.041928]  [<ffffffffa51eb964>] ? __switch_to_asm+0x34/0x70
2018-08-25T12:11:20.596582-07:00 WARNING kernel: [  851.041932]  [<ffffffffa51e799e>] preempt_schedule_irq+0x49/0x86
2018-08-25T12:11:20.596582-07:00 WARNING kernel: [  851.041935]  [<ffffffffa51ec1ae>] retint_kernel+0x1b/0x1d
2018-08-25T12:11:20.596583-07:00 WARNING kernel: [  851.041938]  [<ffffffffa4c95780>] ? __d_lookup+0x59/0x15f
2018-08-25T12:11:20.596584-07:00 WARNING kernel: [  851.041941]  [<ffffffffa4c9577c>] ? __d_lookup+0x55/0x15f
2018-08-25T12:11:20.596584-07:00 WARNING kernel: [  851.041944]  [<ffffffffa4c9570e>] d_lookup+0x2b/0x44
2018-08-25T12:11:20.596585-07:00 WARNING kernel: [  851.041947]  [<ffffffffa4be099d>] d_hash_and_lookup+0x48/0x51
2018-08-25T12:11:20.596586-07:00 WARNING kernel: [  851.041950]  [<ffffffffa4c1f402>] proc_flush_task+0xe2/0x194
2018-08-25T12:11:20.596586-07:00 WARNING kernel: [  851.041953]  [<ffffffffa4ab7832>] release_task+0x3d/0x382
2018-08-25T12:11:20.596587-07:00 WARNING kernel: [  851.041956]  [<ffffffffa51eaf60>] ? _raw_spin_unlock_bh+0x1c/0x1e
2018-08-25T12:11:20.596588-07:00 WARNING kernel: [  851.041959]  [<ffffffffa4ab823b>] do_exit+0x56d/0x7c9
2018-08-25T12:11:20.596589-07:00 WARNING kernel: [  851.041962]  [<ffffffffa4ab8729>] do_group_exit+0x96/0xa5
2018-08-25T12:11:20.596589-07:00 WARNING kernel: [  851.041965]  [<ffffffffa4ac1917>] get_signal+0x135/0x56e
2018-08-25T12:11:20.596590-07:00 WARNING kernel: [  851.041969]  [<ffffffffa4a4bc4d>] do_signal+0x35/0x53c
2018-08-25T12:11:20.596591-07:00 WARNING kernel: [  851.041972]  [<ffffffffa4bd05e1>] ? __check_object_size+0xca/0x16f
2018-08-25T12:11:20.596592-07:00 WARNING kernel: [  851.041975]  [<ffffffffa4b617f0>] ? __might_sleep+0x41/0x7d
2018-08-25T12:11:20.596592-07:00 WARNING kernel: [  851.041979]  [<ffffffffa4ab2143>] prepare_exit_to_usermode+0x75/0x77
2018-08-25T12:11:20.596593-07:00 WARNING kernel: [  851.041982]  [<ffffffffa4ab2188>] syscall_return_slowpath+0x43/0x14c
2018-08-25T12:11:20.596594-07:00 WARNING kernel: [  851.041985]  [<ffffffffa4c92ae5>] ? SyS_ioctl+0x64/0x256
2018-08-25T12:11:20.596594-07:00 WARNING kernel: [  851.041988]  [<ffffffffa51eb734>] int_ret_from_sys_call+0x25/0x93
2018-08-25T12:13:13.123492-07:00 INFO kernel: [    0.000000] Initializing cgroup subsys cpuset
2018-08-25T12:13:13.123542-07:00 INFO kernel: [    0.000000] Initializing cgroup subsys cpu
2018-08-25T12:13:13.123547-07:00 INFO kernel: [    0.000000] Initializing cgroup subsys cpuacct
2018-08-25T12:13:13.123552-07:00 NOTICE kernel: [    0.000000] Linux version 4.4.149-14750-g9f2c000df175 (chrome-bot@swarm-cros-397) (Chromium OS 7.0_pre333878_p20180808-r3 clang version 7.0.0 (/var/cache/chromeos-cache/distfiles/host/egit-src/clang.git 38ad3c9160e5814ec8cad29a990cf76730c5f20e) (/var/cache/chromeos-cache/distfiles/host/egit-src/llvm.git 40c66c3d40377cf85640b3a35e6ec5c5b1cbc41f) (based on LLVM 7.0.0svn)) #1 SMP PREEMPT Sat Aug 25 04:12:06 PDT 2018
...
 

Sign in to add a comment