cf-dev@lists.cloudfoundry.org | Does any one know application stage failed because of warden failure "mknod: 'mnt/dev/tty': No such file or directory\n" ?

Home Messages Hashtags Subgroups

Date Date 1 - 4 of 4

Does any one know application stage failed because of warden failure "mknod: 'mnt/dev/tty': No such file or directory\n" ?

吴昌龙 <clongbupt at gmail.com...>

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_controller/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_controller
 _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/container.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_deferred_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_deferred_s
 uccess"}

Stephen Peggs

#3172

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.

Show quoted text

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"}

attachment.html

Gwenn Etourneau

#3174

Please provide which version you are running on ...
Stemcell, cf-release and so on..

Show quoted text

On Tue, Dec 22, 2015 at 8:12 AM, Stephen Peggs <shemau(a)gmail.com> wrote:

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"}

attachment.html

吴昌龙 <clongbupt at gmail.com...>

#3175

Thanks a lot. We caught the root cause. It was due to wrong configuration of rootfs in the manifest.

1 - 4 of 4

Previous Topic Next Topic

Home Hashtags Subgroups Terms