pushing app fail with warden container log with info value empty

[ghost]

Hi, when I pushed a app in CF, it failed with bellow log info:

/var/vcap/sys/log/warden/warden.log
{"timestamp":1433214013.4825037,"message":"info (took 0.057741)","log_level":"debug","source":"Warden::Container::Linux","data":{"handle":"18ndqsq7ilr","request":{"handle":"18ndqsq7ilr"},"response":{"state":"active","events":[],"host_ip":"10.254.1.89","container_ip":"10.254.1.90","container_path":"/var/vcap/data/warden/depot/18ndqsq7ilr","memory_stat":"#","cpu_stat":"#","disk_stat":"#","bandwidth_stat":"#","job_ids":[]}},"thread_id":70313730315000,"fiber_id":70313783729620,"process_id":19819,"file":"/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/lib/warden/container/base.rb","lineno":300,"method":"dispatch"}
.... ...
{"timestamp":1433214018.2599485,"message":"Exited with status 1 (4.713s): [["/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/src/closefds/closefds", "/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/src/closefds/closefds"], "/var/vcap/data/warden/depot/18ndqsq7ilr/bin/iomux-link", "-w", "/var/vcap/data/warden/depot/18ndqsq7ilr/jobs/2221/cursors", "/var/vcap/data/warden/depot/18ndqsq7ilr/jobs/2221"]","log_level":"warn","source":"Warden::Container::Linux","data":{"handle":"18ndqsq7ilr","stdout":"","stderr":""},"thread_id":70313730315000,"fiber_id":70313743220340,"process_id":19819,"file":"/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/lib/warden/container/spawn.rb","lineno":135,"method":"set_deferred_success"}

I am wondering why the "info" request get the respond with informatin like "memory_stat":"#","cpu_stat":"#","disk_stat":"#","bandwidth_stat":"#" ? What might be the root cause for such case?
Could anyone help on this?

PS: I met such failures for serveral times during my APP push.

[cf-gitbot]

We have created an issue in Pivotal Tracker to manage this. You can view the current status of your issue at: https://www.pivotaltracker.com/story/show/96417090.

[ghost]

Hi @dagong123,

Unfortunately we do not see the root cause of your error while looking at your logs. However, we do see that the application "Exited with status 1". You could try taking a look at some common issues and their fixes, particularly the section on "App Fails to Start".

Hope this helps,
@DanLavine && @Quintaminant, CF Runtime Team

[ghost]

Hi DanLavine, thanks for your reply.
I think my app code is good as it is a test case in my env which is pushing periodically. For most of time, the app can be pushed successfully, but for some time, it failed with some error.
The error returned in "iomux-link" step might be "Exited with status 1", "Exited with status 8", "Exited with status 255" and so on, not just "Exited with status 1".

But the common logs for the failure cases was "memory_stat":"#","cpu_stat":"#","disk_stat":"#","bandwidth_stat":"#".

I am wondering whether the warden container is started correctly with such log info?

Can it be the env issue, for example, lack of memory or other resource for the new warden container that cause "info" request get the respond with informatin "memory_stat":"#","cpu_stat":"#","disk_stat":"#","bandwidth_stat":"#" ?

Thanks.

[ghost]

Hi @dagong123,

The logs during the failure case are coming from an info request from the DEA to the Warden container. These are fairly common logs and on running applications and we noticed that before a container is destroyed, warden requests the info one last time for logging purposes (if the container is not already destroyed).

Unfortunately we cannot determine why your application is failing based on what you provide. All logs for a particular application/warden handle from the DEA and Warden are required for a deeper investigation. If you think that the problem is memory, disk or cpu bound I would try going to the DEA which failed to run the application and checking the system health through common linux commands such as free for memory usage. You could also look at your over commit factor from the bosh manifest and see if it is unreasonable for your environment.

Hope this helps,
@MarcSchunk && @DanLavine, CF Runtime Team

[ghost]

Hi DanLavine,
please ignore my question on "memory_stat":"#","cpu_stat":"#","disk_stat":"#","bandwidth_stat":"#" part.
It was a fault due to my way of greping the log.

Here is the log related with my app push failure "Exited with status 1".

Part of Dea log:
{"timestamp":1433214007.09653,"message":"snapshot_attributes","log_level":"debug","source":"Staging","data":{"app_guid":"6d333594-949a-44b9-b06e-1e376b7897f8","task_id":"18ccd5275334499cbc4a6ebd4794f64d","properties":{"services":[],"resources":{"memory":512,"disk":1024,"fds":16384},"environment":["CF_STACK=lucid64"],"meta":{"command":"node app.js"}}},"thread_id":70202735432440,"fiber_id":70202746654480,"process_id":22454,"file":"/var/vcap/packages/dea_next/lib/dea/staging/staging_task.rb","lineno":502,"method":"snapshot_attributes"}
{"timestamp":1433214012.781041,"message":"staging.app-download.starting","log_level":"info","source":"Staging","data":{"app_guid":"6d333594-949a-44b9-b06e-1e376b7897f8","task_id":"18ccd5275334499cbc4a6ebd4794f64d","uri":"https://$xxxxxcredential messagexxxx"},"thread_id":70202735432440,"fiber_id":70202770999940,"process_id":22454,"file":"/var/vcap/packages/dea_next/lib/dea/staging/staging_task.rb","lineno":299,"method":"block in promise_app_download"}
{"timestamp":1433214012.9028616,"message":"Download succeeded","log_level":"info","source":"Staging","data":{"app_guid":"6d333594-949a-44b9-b06e-1e376b7897f8","task_id":"18ccd5275334499cbc4a6ebd4794f64d"},"thread_id":70202735432440,"fiber_id":70202746654480,"process_id":22454,"file":"/var/vcap/packages/dea_next/lib/dea/utils/download.rb","lineno":60,"method":"block in download!"}
{"timestamp":1433214012.9033453,"message":"staging.app-download.completed","log_level":"debug","source":"Staging","data":{"app_guid":"6d333594-949a-44b9-b06e-1e376b7897f8","task_id":"18ccd5275334499cbc4a6ebd4794f64d","duration":null,"destination":"/var/vcap/data/dea_next/staging/d20150602-22454-449ozp/app.zip"},"thread_id":70202735432440,"fiber_id":70202746654480,"process_id":22454,"file":"/var/vcap/packages/dea_next/lib/dea/staging/staging_task.rb","lineno":312,"method":"block (2 levels) in promise_app_download"}
{"timestamp":1433214012.9036782,"message":"staging.task.preparing-log","log_level":"info","source":"Staging","data":{"app_guid":"6d333594-949a-44b9-b06e-1e376b7897f8","task_id":"18ccd5275334499cbc4a6ebd4794f64d","script":"mkdir -p /tmp/staged/logs && touch /tmp/staged/logs/staging_task.log"},"thread_id":70202735432440,"fiber_id":70202769273520,"process_id":22454,"file":"/var/vcap/packages/dea_next/lib/dea/staging/staging_task.rb","lineno":197,"method":"block in promise_prepare_staging_log"}
{"timestamp":1433214012.904224,"message":"staging.task.making-app-dir","log_level":"info","source":"Staging","data":{"app_guid":"6d333594-949a-44b9-b06e-1e376b7897f8","task_id":"18ccd5275334499cbc4a6ebd4794f64d","script":"mkdir -p /app && touch /app/support_heroku_buildpacks && chown -R vcap:vcap /app"},"thread_id":70202735432440,"fiber_id":70202769269040,"process_id":22454,"file":"/var/vcap/packages/dea_next/lib/dea/staging/staging_task.rb","lineno":211,"method":"block in promise_app_dir"}
{"timestamp":1433214013.3127966,"message":"staging.task.unpacking-app","log_level":"info","source":"Staging","data":{"app_guid":"6d333594-949a-44b9-b06e-1e376b7897f8","task_id":"18ccd5275334499cbc4a6ebd4794f64d","destination":"/tmp/unstaged"},"thread_id":70202735432440,"fiber_id":70202761015260,"process_id":22454,"file":"/var/vcap/packages/dea_next/lib/dea/staging/staging_task.rb","lineno":272,"method":"block in promise_unpack_app"}
{"timestamp":1433214013.487316,"message":"staging.task.execute-staging","log_level":"debug","source":"Staging","data":{"app_guid":"6d333594-949a-44b9-b06e-1e376b7897f8","task_id":"18ccd5275334499cbc4a6ebd4794f64d","script":"set -o pipefail; export VCAP_APPLICATION={\"limits\":{\"mem\":512,\"disk\":1024,\"fds\":16384},\"application_version\":\"b0e41932-bcba-4bef-a568-53e7da2ae1f9\",\"application_name\":\"A1-StatusTestApp1433213994852\",\"application_uris\":[\"A1-StatusTestApp1433213994852.testXXX.net\"],\"version\":\"b0e41932-bcba-4bef-a568-53e7da2ae1f9\",\"name\":\"A1-StatusTestApp1433213994852\",\"space_name\":\"uptime\",\"space_id\":\"2f389dba-73b4-47fa-82de-90f73a4caa65\",\"uris\":[\"A1-StatusTestApp1433213994852.testXXX.net\"],\"users\":null};\nexport VCAP_SERVICES={};\nexport MEMORY_LIMIT="512m";\nexport BUILDPACK_CACHE="/var/vcap/packages/buildpack_cache";\nexport STAGING_TIMEOUT="900.0";\nexport MEMORY_LIMIT="512m";\nexport CF_STACK="lucid64";\n /usr/bin/ruby /var/vcap/packages/dea_next/buildpacks/bin/run /var/vcap/data/dea_next/staging/d20150602-22454-449ozp/plugin_config | tee -a /tmp/staged/logs/staging_task.log"},"thread_id":70202735432440,"fiber_id":70202763359600,"process_id":22454,"file":"/var/vcap/packages/dea_next/lib/dea/staging/staging_task.rb","lineno":222,"method":"block in promise_stage"}
{"timestamp":1433214013.55066,"message":"nats.message.received","log_level":"debug","source":"Dea::Nats","data":{"subject":"dea.find.droplet","data":{"droplet":"6d333594-949a-44b9-b06e-1e376b7897f8","include_stats":true,"states":["RUNNING"],"version":"b0e41932-bcba-4bef-a568-53e7da2ae1f9"}},"thread_id":70202735432440,"fiber_id":70202746654480,"process_id":22454,"file":"/var/vcap/packages/dea_next/lib/dea/nats.rb","lineno":148,"method":"handle_incoming_message"}
{"timestamp":1433214013.5567946,"message":"snapshot_attributes","log_level":"debug","source":"Staging","data":{"app_guid":"6d333594-949a-44b9-b06e-1e376b7897f8","task_id":"18ccd5275334499cbc4a6ebd4794f64d","properties":{"services":[],"resources":{"memory":512,"disk":1024,"fds":16384},"environment":["CF_STACK=lucid64"],"meta":{"command":"node app.js"}}},"thread_id":70202735432440,"fiber_id":70202763359600,"process_id":22454,"file":"/var/vcap/packages/dea_next/lib/dea/staging/staging_task.rb","lineno":502,"method":"snapshot_attributes"}
{"timestamp":1433214015.7627804,"message":"nats.message.received","log_level":"debug","source":"Dea::Nats","data":{"subject":"dea.find.droplet","data":{"droplet":"6d333594-949a-44b9-b06e-1e376b7897f8","include_stats":true,"states":["RUNNING"],"version":"b0e41932-bcba-4bef-a568-53e7da2ae1f9"}},"thread_id":70202735432440,"fiber_id":70202746654480,"process_id":22454,"file":"/var/vcap/packages/dea_next/lib/dea/nats.rb","lineno":148,"method":"handle_incoming_message"}
{"timestamp":1433214018.338443,"message":"staging.task.execute-staging.failed","log_level":"error","source":"Staging","data":{"app_guid":"6d333594-949a-44b9-b06e-1e376b7897f8","task_id":"18ccd5275334499cbc4a6ebd4794f64d","error":"Script exited with status 1"},"thread_id":70202735432440,"fiber_id":70202763359600,"process_id":22454,"file":"/var/vcap/packages/dea_next/lib/dea/staging/staging_task.rb","lineno":244,"method":"rescue in block in promise_stage"}
{"timestamp":1433214018.3387997,"message":"staging.task-info.copying-out","log_level":"info","source":"Staging","data":{"app_guid":"6d333594-949a-44b9-b06e-1e376b7897f8","task_id":"18ccd5275334499cbc4a6ebd4794f64d","source":"/tmp/staged/staging_info.yml","destination":"/var/vcap/data/dea_next/staging/d20150602-22454-449ozp/staging_info.yml"},"thread_id":70202735432440,"fiber_id":70202772451180,"process_id":22454,"file":"/var/vcap/packages/dea_next/lib/dea/staging/staging_task.rb","lineno":263,"method":"block in promise_staging_info"}
{"timestamp":1433214018.3866498,"message":"staging.task-log.copying-out","log_level":"info","source":"Staging","data":{"app_guid":"6d333594-949a-44b9-b06e-1e376b7897f8","task_id":"18ccd5275334499cbc4a6ebd4794f64d","source":"/tmp/staged/logs/staging_task.log","destination":"/var/vcap/data/dea_next/staging/d20150602-22454-449ozp/staging_task.log"},"thread_id":70202735432440,"fiber_id":70202768207680,"process_id":22454,"file":"/var/vcap/packages/dea_next/lib/dea/staging/staging_task.rb","lineno":254,"method":"block in promise_task_log"}
{"timestamp":1433214018.4348314,"message":"staging.task.failed","log_level":"info","source":"Staging","data":{"app_guid":"6d333594-949a-44b9-b06e-1e376b7897f8","task_id":"18ccd5275334499cbc4a6ebd4794f64d","error":"Script exited with status 1","backtrace":["/var/vcap/packages/dea_next/lib/container/container.rb:184:in link_or_raise'","/var/vcap/packages/dea_next/lib/dea/staging/staging_task.rb:241:inblock in promise_stage'","/var/vcap/packages/dea_next/lib/dea/promise.rb:92:in call'","/var/vcap/packages/dea_next/lib/dea/promise.rb:92:inblock in run'"]},"thread_id":70202735432440,"fiber_id":70202763080360,"process_id":22454,"file":"/var/vcap/packages/dea_next/lib/dea/staging/staging_task.rb","lineno":57,"method":"block in start"}
{"timestamp":1433214043.0079873,"message":"nats.message.received","log_level":"debug","source":"Dea::Nats","data":{"subject":"dea.find.droplet","data":{"droplet":"6d333594-949a-44b9-b06e-1e376b7897f8","include_stats":true,"states":["RUNNING"],"version":"b0e41932-bcba-4bef-a568-53e7da2ae1f9"}},"thread_id":70202735432440,"fiber_id":70202746654480,"process_id":22454,"file":"/var/vcap/packages/dea_next/lib/dea/nats.rb","lineno":148,"method":"handle_incoming_message"}

And part of the warden log:
{"handle":"18ndqsq7ilr","request":{"handle":"18ndqsq7ilr","script":"mkdir -p /app && touch /app/support_heroku_buildpacks && chown -R vcap:vcap /app","privileged":true},"response":{"job_id":2219}},"thread_id":70313730315000,"fiber_id":70313771214020,"process_id":19819,"file":"/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/lib/warden/container/base.rb","lineno":300,"method":"dispatch"}
/var/vcap/sys/log/warden/warden.log.1:531744:{"timestamp":1433214013.1614943,"message":"Wrote snapshot in 0.000490","log_level":"debug","source":"Warden::Container::Linux","data":{"handle":"18ndqsq7ilr"},"thread_id":70313730315000,"fiber_id":70313743220340,"process_id":19819,"file":"/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/lib/warden/container/base.rb","lineno":334,"method":"write_snapshot"}
/var/vcap/sys/log/warden/warden.log.1:531745:{"timestamp":1433214013.2358902,"message":"info (took 0.074055)","log_level":"debug","source":"Warden::Container::Linux","data":{"handle":"18ndqsq7ilr","request":{"handle":"18ndqsq7ilr"},"response":{"state":"active","events":[],"host_ip":"10.254.1.89","container_ip":"10.254.1.90","container_path":"/var/vcap/data/warden/depot/18ndqsq7ilr","memory_stat":"#","cpu_stat":"#","disk_stat":"#","bandwidth_stat":"#","job_ids":[]}},"thread_id":70313730315000,"fiber_id":70313771214020,"process_id":19819,"file":"/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/lib/warden/container/base.rb","lineno":300,"method":"dispatch"}
/var/vcap/sys/log/warden/warden.log.1:531746:{"timestamp":1433214013.2363346,"message":"link (took 0.093507)","log_level":"debug","source":"Warden::Container::Linux","data":{"handle":"18ndqsq7ilr","request":{"handle":"18ndqsq7ilr","job_id":2219},"response":{"exit_status":0,"stdout":"","stderr":"","info":"#"}},"thread_id":70313730315000,"fiber_id":70313771214020,"process_id":19819,"file":"/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/lib/warden/container/base.rb","lineno":300,"method":"dispatch"}
/var/vcap/sys/log/warden/warden.log.1:531747:{"timestamp":1433214013.308567,"message":"info (took 0.071766)","log_level":"debug","source":"Warden::Container::Linux","data":{"handle":"18ndqsq7ilr","request":{"handle":"18ndqsq7ilr"},"response":{"state":"active","events":[],"host_ip":"10.254.1.89","container_ip":"10.254.1.90","container_path":"/var/vcap/data/warden/depot/18ndqsq7ilr","memory_stat":"#","cpu_stat":"#","disk_stat":"#","bandwidth_stat":"#","job_ids":[]}},"thread_id":70313730315000,"fiber_id":70313771214020,"process_id":19819,"file":"/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/lib/warden/container/base.rb","lineno":300,"method":"dispatch"}
/var/vcap/sys/log/warden/warden.log.1:531748:{"timestamp":1433214013.3089774,"message":"run (took 0.174088)","log_level":"debug","source":"Warden::Container::Linux","data":{"handle":"18ndqsq7ilr","request":{"handle":"18ndqsq7ilr","script":"mkdir -p /app && touch /app/support_heroku_buildpacks && chown -R vcap:vcap /app","privileged":true},"response":{"exit_status":0,"stdout":"","stderr":"","info":"#"}},"thread_id":70313730315000,"fiber_id":70313771214020,"process_id":19819,"file":"/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/lib/warden/container/base.rb","lineno":300,"method":"dispatch"}
/var/vcap/sys/log/warden/warden.log.1:531749:{"timestamp":1433214013.325362,"message":"Wrote snapshot in 0.000505","log_level":"debug","source":"Warden::Container::Linux","data":{"handle":"18ndqsq7ilr"},"thread_id":70313730315000,"fiber_id":70313783729620,"process_id":19819,"file":"/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/lib/warden/container/base.rb","lineno":334,"method":"write_snapshot"}
/var/vcap/sys/log/warden/warden.log.1:531750:{"timestamp":1433214013.3256,"message":"spawn (took 0.011462)","log_level":"debug","source":"Warden::Container::Linux","data":{"handle":"18ndqsq7ilr","request":{"handle":"18ndqsq7ilr","script":" set -o pipefail\n package_size=du -h /var/vcap/data/dea_next/staging/d20150602-22454-449ozp/app.zip | cut -f1\n echo "-----> Downloaded app package ($package_size)" | tee -a /tmp/staged/logs/staging_task.log\n unzip -q /var/vcap/data/dea_next/staging/d20150602-22454-449ozp/app.zip -d /tmp/unstaged\n"},"response":{"job_id":2220}},"thread_id":70313730315000,"fiber_id":70313783729620,"process_id":19819,"file":"/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/lib/warden/container/base.rb","lineno":300,"method":"dispatch"}
/var/vcap/sys/log/warden/warden.log.1:531751:{"timestamp":1433214013.3598435,"message":"Wrote snapshot in 0.000792","log_level":"debug","source":"Warden::Container::Linux","data":{"handle":"18ndqsq7ilr"},"thread_id":70313730315000,"fiber_id":70313743220340,"process_id":19819,"file":"/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/lib/warden/container/base.rb","lineno":334,"method":"write_snapshot"}
/var/vcap/sys/log/warden/warden.log.1:531752:{"timestamp":1433214013.4241705,"message":"info (took 0.063387)","log_level":"debug","source":"Warden::Container::Linux","data":{"handle":"18ndqsq7ilr","request":{"handle":"18ndqsq7ilr"},"response":{"state":"active","events":[],"host_ip":"10.254.1.89","container_ip":"10.254.1.90","container_path":"/var/vcap/data/warden/depot/18ndqsq7ilr","memory_stat":"#","cpu_stat":"#","disk_stat":"#","bandwidth_stat":"#","job_ids":[]}},"thread_id":70313730315000,"fiber_id":70313783729620,"process_id":19819,"file":"/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/lib/warden/container/base.rb","lineno":300,"method":"dispatch"}
/var/vcap/sys/log/warden/warden.log.1:531753:{"timestamp":1433214013.4244578,"message":"link (took 0.098613)","log_level":"debug","source":"Warden::Container::Linux","data":{"handle":"18ndqsq7ilr","request":{"handle":"18ndqsq7ilr","job_id":2220},"response":{"exit_status":0,"stdout":"-----> Downloaded app package (4.0K)\n","stderr":"","info":"#"}},"thread_id":70313730315000,"fiber_id":70313783729620,"process_id":19819,"file":"/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/lib/warden/container/base.rb","lineno":300,"method":"dispatch"}
/var/vcap/sys/log/warden/warden.log.1:531754:{"timestamp":1433214013.4825037,"message":"info (took 0.057741)","log_level":"debug","source":"Warden::Container::Linux","data":{"handle":"18ndqsq7ilr","request":{"handle":"18ndqsq7ilr"},"response":{"state":"active","events":[],"host_ip":"10.254.1.89","container_ip":"10.254.1.90","container_path":"/var/vcap/data/warden/depot/18ndqsq7ilr","memory_stat":"#","cpu_stat":"#","disk_stat":"#","bandwidth_stat":"#","job_ids":[]}},"thread_id":70313730315000,"fiber_id":70313783729620,"process_id":19819,"file":"/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/lib/warden/container/base.rb","lineno":300,"method":"dispatch"}

/var/vcap/sys/log/warden/warden.log.1:531755:{"timestamp":1433214013.4829319,"message":"run (took 0.168858)","log_level":"debug","source":"Warden::Container::Linux","data":{"handle":"18ndqsq7ilr","request":{"handle":"18ndqsq7ilr","script":" set -o pipefail\n package_size=du -h /var/vcap/data/dea_next/staging/d20150602-22454-449ozp/app.zip | cut -f1\n echo "-----> Downloaded app package ($package_size)" | tee -a /tmp/staged/logs/staging_task.log\n unzip -q /var/vcap/data/dea_next/staging/d20150602-22454-449ozp/app.zip -d /tmp/unstaged\n"},"response":{"exit_status":0,"stdout":"-----> Downloaded app package (4.0K)\n","stderr":"","info":"#"}},"thread_id":70313730315000,"fiber_id":70313783729620,"process_id":19819,"file":"/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/lib/warden/container/base.rb","lineno":300,"method":"dispatch"}

/var/vcap/sys/log/warden/warden.log.1:531756:{"timestamp":1433214013.5506377,"message":"Wrote snapshot in 0.000522","log_level":"debug","source":"Warden::Container::Linux","data":{"handle":"18ndqsq7ilr"},"thread_id":70313730315000,"fiber_id":70313770441960,"process_id":19819,"file":"/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/lib/warden/container/base.rb","lineno":334,"method":"write_snapshot"}

/var/vcap/sys/log/warden/warden.log.1:531757:{"timestamp":1433214013.5508575,"message":"spawn (took 0.009004)","log_level":"debug","source":"Warden::Container::Linux","data":{"handle":"18ndqsq7ilr","request":{"handle":"18ndqsq7ilr","script":"set -o pipefail; export VCAP_APPLICATION={\"limits\":{\"mem\":512,\"disk\":1024,\"fds\":16384},\"application_version\":\"b0e41932-bcba-4bef-a568-53e7da2ae1f9\",\"application_name\":\"A1-StatusTestApp1433213994852\",\"application_uris\":[\"A1-StatusTestApp1433213994852.testXXX.net\"],\"version\":\"b0e41932-bcba-4bef-a568-53e7da2ae1f9\",\"name\":\"A1-StatusTestApp1433213994852\",\"space_name\":\"uptime\",\"space_id\":\"2f389dba-73b4-47fa-82de-90f73a4caa65\",\"uris\":[\"A1-StatusTestApp1433213994852.testXXX.net\"],\"users\":null};\nexport VCAP_SERVICES={};\nexport MEMORY_LIMIT="512m";\nexport BUILDPACK_CACHE="/var/vcap/packages/buildpack_cache";\nexport STAGING_TIMEOUT="900.0";\nexport MEMORY_LIMIT="512m";\nexport CF_STACK="lucid64";\n /usr/bin/ruby /var/vcap/packages/dea_next/buildpacks/bin/run /var/vcap/data/dea_next/staging/d20150602-22454-449ozp/plugin_config | tee -a /tmp/staged/logs/staging_task.log","discard_output":true},"response":{"job_id":2221}},"thread_id":70313730315000,"fiber_id":70313770441960,"process_id":19819,"file":"/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/lib/warden/container/base.rb","lineno":300,"method":"dispatch"}

/var/vcap/sys/log/warden/warden.log.1:531800:{"timestamp":1433214018.2599485,"message":"Exited with status 1 (4.713s): [["/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/src/closefds/closefds", "/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/src/closefds/closefds"], "/var/vcap/data/warden/depot/18ndqsq7ilr/bin/iomux-link", "-w", "/var/vcap/data/warden/depot/18ndqsq7ilr/jobs/2221/cursors", "/var/vcap/data/warden/depot/18ndqsq7ilr/jobs/2221"]","log_level":"warn","source":"Warden::Container::Linux","data":{"handle":"18ndqsq7ilr","stdout":"","stderr":""},"thread_id":70313730315000,"fiber_id":70313743220340,"process_id":19819,"file":"/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/lib/warden/container/spawn.rb","lineno":135,"method":"set_deferred_success"}

/var/vcap/sys/log/warden/warden.log.1:531801:{"timestamp":1433214018.260702,"message":"Wrote snapshot in 0.000468","log_level":"debug","source":"Warden::Container::Linux","data":{"handle":"18ndqsq7ilr"},"thread_id":70313730315000,"fiber_id":70313743220340,"process_id":19819,"file":"/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/lib/warden/container/base.rb","lineno":334,"method":"write_snapshot"}

/var/vcap/sys/log/warden/warden.log.1:531802:{"timestamp":1433214018.3262737,"message":"info (took 0.064934)","log_level":"debug","source":"Warden::Container::Linux","data":{"handle":"18ndqsq7ilr","request":{"handle":"18ndqsq7ilr"},"response":{"state":"active","events":[],"host_ip":"10.254.1.89","container_ip":"10.254.1.90","container_path":"/var/vcap/data/warden/depot/18ndqsq7ilr","memory_stat":"#","cpu_stat":"#","disk_stat":"#","bandwidth_stat":"#","job_ids":[]}},"thread_id":70313730315000,"fiber_id":70313732324000,"process_id":19819,"file":"/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/lib/warden/container/base.rb","lineno":300,"method":"dispatch"}

/var/vcap/sys/log/warden/warden.log.1:531803:{"timestamp":1433214018.3266022,"message":"link (took 4.755165)","log_level":"debug","source":"Warden::Container::Linux","data":{"handle":"18ndqsq7ilr","request":{"handle":"18ndqsq7ilr","job_id":2221},"response":{"exit_status":1,"stdout":"","stderr":"","info":"#"}},"thread_id":70313730315000,"fiber_id":70313732324000,"process_id":19819,"file":"/var/vcap/data/packages/warden/e4c65ef1dc975c3a06df74c0182ce9b31a20eded.1-57517380391b74c50acd1bb0f7f6a12919d563f4/warden/lib/warden/container/base.rb","lineno":300,"method":"dispatch"}

Hope my log can give you some clue on why my app fail at buildpack step.

[jpalermo]

I don't see much in those logs other than info that the app had an exit status of 1.

Is there nothing in the logs for the app itself?

[ghost]

no, I didn't take the app log for the moment of failure. But the app is a testing case which runs every certain time of period in my env. And for over 80% (the number maybe not very exact) , the push app sucess, but others will fail. I will check the app logs next time when I meet the failure.
By the way, is there any known issues which will cause the error "exit 1" during buildpack step ?

[MarcSchunk]

Hi dagong123,

we are not aware of a known issue which would result in a exit 1. The best thing you can do is look at your applications logs.

@Quintaminant & @MarcSchunk of runtime team

[jpalermo]

Hi @dagong123,

We are going to close this issue due to inactivity. If you have any additional information please feel free to reopen the issue.

Thanks,
@jpalermo && @DanLavine, CF OSS Release Integration Team