Answering from phone, which is not ideal for reading logs. Make sure the
rootfs package_path in the yml is correct. If in doubt try removing it from
yml and letting it default. The default package path changed around 212, so
if it was hard coded, it could be wrong. The symptoms I saw were warden
terminating immediately, but connection to client taking 15 minutes to
timeout. Hope that helps.

On Mon, 21 Dec 2015 11:34 am Wu Changlong <clongbupt(a)gmail.com> wrote:

We are trying to deploy some applications. But in the staging phase, it
usually stuck.

cf push command snapshot is:
...
Starting app stuck-test in org TEST / space getting-started as
cloudfoundry(a)example.com...

FAILED

And used CF_TRACE cf push and also monitored cf logs TEST --recent. No
useful information there.

Checked cloud_controller found related error : (due to timeout)

{"timestamp":1450691546.9286427,"message":"Request failed: 400:
{\"code\"=>170001, \"description\"=>\"Staging error: failed to stage
application:\\n\", \"error_code\"=>\"CF-StagingError\",
\"backtrace\"=>[\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/lib/cloud_controller/dea/app_stager_task.rb:112:in
`check_staging_error!'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/lib/cloud_controller/dea/app_stager_task.rb:75:in
`handle_first_response'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/lib/cloud_controller/dea/app_stager_task.rb:49:in
`block (2 levels) in stage'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/lib/cloud_controller/multi_response_message_bus_request.rb:48:in
`call'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/lib/cloud_controller/multi_response_message_bus_request.rb:48:in
`trigger_on_response'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/lib/cloud_controlle
r/multi_
response_message_bus_request.rb:59:in `block in timeout_request'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.1.0/gems/eventmachine-1.0.3/lib/eventmachine.rb:187:in
`call'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.1.0/gems/eventmachine-1.0.3/lib/eventmachine.rb:187:in
`run_machine'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.1.0/gems/eventmachine-1.0.3/lib/eventmachine.rb:187:in
`run'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/lib/cloud_controller/runner.rb:85:in
`run!'\",
\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/bin/cloud_controller:12:in
`<main>'\"]}","log_level":"info","source":"cc.api","data":{"request_guid":"84de364e-f3e4-42ba-7f39-b521db4d31f0::e58d0500-183f-45ec-87ad-0bf1454e34b2"},"thread_id":70359150060440,"fiber_id":70359143708760,"process_id":2656,"file":"/var/vcap/packages/cloud_controller_ng/cloud_co
ntroller
_ng/lib/sinatra/vcap.rb","lineno":51,"method":"block in registered"}

Checked the specific dea which is selected to stage the application

Received stage.task_id.start command from nats. And finally it will fail
due to can not talk to warden server

{"timestamp":1450690646.9557974,"message":"staging.task.failed","log_level":"info","source":"Staging","data":{"app_guid":"0788f675-e67e-40a2-9245-49a7bdc3a56b","task_id":"cbcf35daaf2744008a55af03cf401dc5","error":"command
exited with
failure","backtrace":["/var/vcap/packages/dea_next/vendor/cache/warden-ad18bff7dc56/em-warden-client/lib/em/warden/client/connection.rb:27:in
`get'","/var/vcap/packages/dea_next/vendor/cache/warden-ad18bff7dc56/em-warden-client/lib/em/warden/client.rb:46:in
`call'","/var/vcap/packages/dea_next/lib/container/container.rb:192:in
`call'","/var/vcap/packages/dea_next/lib/container/container.rb:153:in
`block in
new_container_with_bind_mounts_and_rootfs'","/var/vcap/packages/dea_next/lib/container/container.rb:229:in
`call'","/var/vcap/packages/dea_next/lib/container/container.rb:229:in
`with_em'","/var/vcap/packages/dea_next/lib/container/container.rb:137:in
`new_container_with_bind_mounts_and_rootfs'","/var/vcap/packages/dea_next/lib/container/contai
ner.rb:1
20:in `block in
create_container'","/var/vcap/packages/dea_next/lib/container/container.rb:229:in
`call'","/var/vcap/packages/dea_next/lib/container/container.rb:229:in
`with_em'","/var/vcap/packages/dea_next/lib/container/container.rb:119:in
`create_container'","/var/vcap/packages/dea_next/lib/dea/staging/staging_task.rb:547:in
`resolve_staging_setup'","/var/vcap/packages/dea_next/lib/dea/staging/staging_task.rb:49:in
`block in start'","/var/vcap/packages/dea_next/lib/dea/promise.rb:92:in
`call'","/var/vcap/packages/dea_next/lib/dea/promise.rb:92:in `block in
run'"]},"thread_id":69922496713480,"fiber_id":69922501701180,"process_id":1744,"file":"/var/vcap/packages/dea_next/lib/dea/staging/staging_task.rb","lineno":57,"method":"block
in start"}
{"timestamp":1450690646.9562492,"message":"Saving snapshot took:
0.000s","log_level":"debug","source":"Snapshot","data":{},"thread_id":69922496713480,"fiber_id":69922501701180,"process_id":1744,"file":"/var/vcap/packages/dea_next/lib/dea/snapshot.rb","lineno":41,"method":"save"}
{"timestamp":1450690646.956403,"message":"task.destroy.invalid","log_level":"error","source":"Staging","data":{"app_guid":"0788f675-e67e-40a2-9245-49a7bdc3a56b","task_id":"cbcf35daaf2744008a55af03cf401dc5"},"thread_id":69922496713480,"fiber_id":69922497906140,"process_id":1744,"file":"/var/vcap/packages/dea_next/lib/dea/task.rb","lineno":66,"method":"block
in promise_destroy"}

Finally check warden server logs, found :


{"timestamp":1450364306.6088312,"message":"Configuration","log_level":"info","source":"Warden::Server","data":{"server":{"unix_domain_path":"/var/vcap/data/warden/warden.sock","unix_domain_permissions":511,"container_klass":"Warden::Container::Linux","container_grace_time":300,"job_output_limit":10485760,"quota":{"disk_quota_enabled":true},"allow_nested_warden":false,"container_rootfs_path":"/var/vcap/packages/rootfs_cflinuxfs2/rootfs","container_depot_path":"/var/vcap/data/warden/depot","container_rlimits":{"core":0},"pidfile":"/var/vcap/sys/run/warden/warden.pid"},"logging":{"level":"debug","file":"/var/vcap/sys/log/warden/warden.log","syslog":"vcap.warden"},"network":{"pool_network":"
10.254.0.0/22
","deny_networks":[],"allow_networks":[],"allow_host_access":false,"mtu":1500},"port":{"pool_start_port":61001,"pool_size":4000},"user":{"pool_start_uid":20000,"pool_size":256}},"thread_id":70081548145420,"fiber_id":70081561342720,"process_id":2450,"file":"/var/vcap/data/packages/
warden/5

f0154e5ba4baec289e1a05fe81ee1b9a5dc23e1.1-d22cdb95446b588e566fbef018274c5e620d31c2/warden/lib/warden/server.rb","lineno":271,"method":"run!"}
{"timestamp":1450364306.665695,"message":"Listening on
/var/vcap/data/warden/warden.sock","log_level":"info","source":"Warden::Server","data":{},"thread_id":70081548145420,"fiber_id":70081561340880,"process_id":2450,"file":"/var/vcap/data/packages/warden/5f0154e5ba4baec289e1a05fe81ee1b9a5dc23e1.1-d22cdb95446b588e566fbef018274c5e620d31c2/warden/lib/warden/server.rb","lineno":307,"method":"block
(2 levels) in run!"}
{"timestamp":1450364306.6657858,"message":"Writing pid 2450 to
/var/vcap/sys/run/warden/warden.pid","log_level":"info","source":"Warden::Server","data":{},"thread_id":70081548145420,"fiber_id":70081561340880,"process_id":2450,"file":"/var/vcap/data/packages/warden/5f0154e5ba4baec289e1a05fe81ee1b9a5dc23e1.1-d22cdb95446b588e566fbef018274c5e620d31c2/warden/lib/warden/server.rb","lineno":310,"method":"block
(2 levels) in run!"}
{"timestamp":1450671844.741455,"message":"Exited with status 1 (0.047s):
[[\"/var/vcap/data/packages/warden/5f0154e5ba4baec289e1a05fe81ee1b9a5dc23e1.1-d22cdb95446b588e566fbef018274c5e620d31c2/warden/src/closefds/closefds\",
\"/var/vcap/data/packages/warden/5f0154e5ba4baec289e1a05fe81ee1b9a5dc23e1.1-d22cdb95446b588e566fbef018274c5e620d31c2/warden/src/closefds/closefds\"],
\"/var/vcap/data/packages/warden/5f0154e5ba4baec289e1a05fe81ee1b9a5dc23e1.1-d22cdb95446b588e566fbef018274c5e620d31c2/warden/root/linux/create.sh\",
\"/var/vcap/data/warden/depot/197c3dvq1f2\"]","log_level":"warn","source":"Warden::Container::Linux","data":{"handle":"197c3dvq1f2","stdout":"","stderr":"mknod:
'mnt/dev/tty': No such file or
directory\n"},"thread_id":70081548145420,"fiber_id":70081561342720,"process_id":2450,"file":"/var/vcap/data/packages/warden/5f0154e5ba4baec289e1a05fe81ee1b9a5dc23e1.1-d22cdb95446b588e566fbef018274c5e620d31c2/warden/lib/warden/container/spawn.rb","lineno":135,"method":"set_def
erred_su
ccess"}
{"timestamp":1450671844.7447896,"message":"Exited with status 1 (0.002s):
[[\"/var/vcap/data/packages/warden/5f0154e5ba4baec289e1a05fe81ee1b9a5dc23e1.1-d22cdb95446b588e566fbef018274c5e620d31c2/warden/src/closefds/closefds\",
\"/var/vcap/data/packages/warden/5f0154e5ba4baec289e1a05fe81ee1b9a5dc23e1.1-d22cdb95446b588e566fbef018274c5e620d31c2/warden/src/closefds/closefds\"],
\"/var/vcap/data/warden/depot/197c3dvq1f2/stop.sh\", \"-w\",
\"0\"]","log_level":"warn","source":"Warden::Container::Linux","data":{"handle":"197c3dvq1f2","stdout":"wshd
is not
running...\n","stderr":""},"thread_id":70081548145420,"fiber_id":70081561342720,"process_id":2450,"file":"/var/vcap/data/packages/warden/5f0154e5ba4baec289e1a05fe81ee1b9a5dc23e1.1-d22cdb95446b588e566fbef018274c5e620d31c2/warden/lib/warden/container/spawn.rb","lineno":135,"method":"set_deferred_success"}
{"timestamp":1450671844.7679663,"message":"Container
destroyed","log_level":"debug","source":"Warden::Container::Linux","data":{"handle":"197c3dvq1f2"},"thread_id":70081548145420,"fiber_id":70081558886540,"process_id":2450,"file":"/var/vcap/data/packages/warden/5f0154e5ba4baec289e1a05fe81ee1b9a5dc23e1.1-d22cdb95446b588e566fbef018274c5e620d31c2/warden/lib/warden/container/linux.rb","lineno":125,"method":"do_destroy"}
{"timestamp":1450671844.7683303,"message":"destroy (took
0.026452)","log_level":"debug","source":"Warden::Container::Linux","data":{"handle":"197c3dvq1f2","request":{},"response":{}},"thread_id":70081548145420,"fiber_id":70081558886540,"process_id":2450,"file":"/var/vcap/data/packages/warden/5f0154e5ba4baec289e1a05fe81ee1b9a5dc23e1.1-d22cdb95446b588e566fbef018274c5e620d31c2/warden/lib/warden/container/base.rb","lineno":300,"method":"dispatch"}
{"timestamp":1450672323.4810724,"message":"Exited with status 1 (0.044s):
[[\"/var/vcap/data/packages/warden/5f0154e5ba4baec289e1a05fe81ee1b9a5dc23e1.1-d22cdb95446b588e566fbef018274c5e620d31c2/warden/src/closefds/closefds\",
\"/var/vcap/data/packages/warden/5f0154e5ba4baec289e1a05fe81ee1b9a5dc23e1.1-d22cdb95446b588e566fbef018274c5e620d31c2/warden/src/closefds/closefds\"],
\"/var/vcap/data/packages/warden/5f0154e5ba4baec289e1a05fe81ee1b9a5dc23e1.1-d22cdb95446b588e566fbef018274c5e620d31c2/warden/root/linux/create.sh\",
\"/var/vcap/data/warden/depot/197c3dvq1f3\"]","log_level":"warn","source":"Warden::Container::Linux","data":{"handle":"197c3dvq1f3","stdout":"","stderr":"mknod:
'mnt/dev/tty': No such file or
directory\n"},"thread_id":70081548145420,"fiber_id":70081561342720,"process_id":2450,"file":"/var/vcap/data/packages/warden/5f0154e5ba4baec289e1a05fe81ee1b9a5dc23e1.1-d22cdb95446b588e566fbef018274c5e620d31c2/warden/lib/warden/container/spawn.rb","lineno":135,"method":"set_de
ferred_s
uccess"}