Understanding application deployment failures in VMware Tanzu Application Service for VMs
Article ID: 297477
Updated On:
Products
VMware Tanzu Application Service for VMs
Issue/Introduction
In some cases, when an application deployed to VMware Tanzu Application Service for VMs fails it is simply not clear why it failed. You may be unsure if the issue is related to the app, bound services, or the platform.
This article will walk through troubleshooting a failed application deployment on VMware Tanzu Application Service for VMs.
If your application is failing to deploy, you will first need to obtain the logs.
Please obtain a full set of logs from the application. To do this properly, please start capturing logs with cf logs app-name > app-name.log in one terminal. Then in a second terminal, run your cf push command to deploy the app. When the failure occurs, go back and stop cf logs in the other terminal.
Resolution
With information in hand, it is time to dissect the problem. First, take a look at the logs to see where the problem occurs.
The following is an example set of logs which have been captured using the method above. They have been augmented to indicate what is generating the different sections of the logs.
# These are messages from the platform. They indicate changes in Cloud Controller. For issues here, obtain a trace with `cf -v push` and check the Cloud Controller logs.
2020-03-04T12:12:26.45-0500 [API/5] OUT Updated app with guid ########-####-####-####-############ ({"buildpack"=>"https://github.com/cloudfoundry/java-buildpack#v4.28", "disk_quota"=>1024, "environment_json"=>"[PRIVATE DATA HIDDEN]", "health_check_http_endpoint"=>"", "health_check_type"=>"port", "instances"=>1, "memory"=>1024, "name"=>"spring-music", "space_guid"=>"########-####-####-####-############"})
2020-03-04T12:12:30.09-0500 [API/15] OUT Uploading bits for app with guid ########-####-####-####-############
2020-03-04T12:12:42.87-0500 [API/16] OUT Updated app with guid ########-####-####-####-############ ({"state"=>"STOPPED"})
2020-03-04T12:12:43.17-0500 [API/10] OUT Creating build for app with guid ########-####-####-####-############
2020-03-04T12:12:43.68-0500 [API/10] OUT Updated app with guid ########-####-####-####-############ ({"state"=>"STARTED"})
# These messages are from Diego. They indicate that a container is being created & set up to run the buildpack. For issues here, check the Diego Cell referenced by the guid in the log entry.
2020-03-04T12:12:43.96-0500 [STG/0] OUT Cell ########-####-####-####-############ creating container for instance ########-####-####-####-############
2020-03-04T12:12:44.94-0500 [STG/0] OUT Cell ########-####-####-####-############ successfully created container for instance ########-####-####-####-############
2020-03-04T12:12:45.16-0500 [STG/0] OUT Downloading app package...
2020-03-04T12:12:45.16-0500 [STG/0] OUT Downloading build artifacts cache...
2020-03-04T12:12:46.72-0500 [STG/0] OUT Downloaded build artifacts cache (44.2M)
2020-03-04T12:12:47.26-0500 [STG/0] OUT Downloaded app package (47.9M)
# This marks the start of the buildpack. Buildpack output is unique to the buildpack. This example shows the Java buildpack. Errors in this section are likely buildpack configuration issues (i.e. bad input) or in rare cases buildpack bugs
2020-03-04T12:12:49.61-0500 [STG/0] OUT -----> Java Buildpack v4.28 | https://github.com/cloudfoundry/java-buildpack#7246771
2020-03-04T12:12:49.71-0500 [STG/0] OUT -----> Downloading Jvmkill Agent 1.16.0_RELEASE from https://java-buildpack.cloudfoundry.org/jvmkill/bionic/x86_64/jvmkill-1.16.0-RELEASE.so (found in cache)
2020-03-04T12:12:49.73-0500 [STG/0] OUT -----> Downloading Open Jdk JRE 1.8.0_242 from https://java-buildpack.cloudfoundry.org/openjdk/bionic/x86_64/openjdk-jre-1.8.0_242-bionic.tar.gz (found in cache)
2020-03-04T12:12:50.88-0500 [STG/0] OUT Expanding Open Jdk JRE to .java-buildpack/open_jdk_jre (1.1s)
2020-03-04T12:12:50.88-0500 [STG/0] OUT JVM DNS caching disabled in lieu of BOSH DNS caching
2020-03-04T12:12:50.91-0500 [STG/0] OUT -----> Downloading Open JDK Like Memory Calculator 3.13.0_RELEASE from https://java-buildpack.cloudfoundry.org/memory-calculator/bionic/x86_64/memory-calculator-3.13.0-RELEASE.tar.gz (found in cache)
2020-03-04T12:12:52.18-0500 [STG/0] OUT Loaded Classes: 19613, Threads: 250
2020-03-04T12:12:52.22-0500 [STG/0] OUT -----> Downloading Client Certificate Mapper 1.11.0_RELEASE from https://java-buildpack.cloudfoundry.org/client-certificate-mapper/client-certificate-mapper-1.11.0-RELEASE.jar (found in cache)
2020-03-04T12:12:52.24-0500 [STG/0] OUT -----> Downloading Container Security Provider 1.16.0_RELEASE from https://java-buildpack.cloudfoundry.org/container-security-provider/container-security-provider-1.16.0-RELEASE.jar (found in cache)
2020-03-04T12:12:52.39-0500 [STG/0] OUT -----> Downloading Java Memory Assistant Agent 0.3.0 from https://github.com/SAP/java-memory-assistant/releases/download/0.3.0/java-memory-assistant-0.3.0.jar (found in cache)
2020-03-04T12:12:52.62-0500 [STG/0] OUT -----> Downloading Java Memory Assistant Clean Up 0.1.0 from https://github.com/SAP/java-memory-assistant-tools/releases/download/0.1.0/cleanup-linux-amd64-0.1.0.zip (found in cache)
2020-03-04T12:12:52.68-0500 [STG/0] OUT Expanding Java Memory Assistant Clean Up to .java-buildpack/java_memory_assistant (0.0s)
2020-03-04T12:12:52.70-0500 [STG/0] OUT -----> Downloading Spring Auto Reconfiguration 2.11.0_RELEASE from https://java-buildpack.cloudfoundry.org/auto-reconfiguration/auto-reconfiguration-2.11.0-RELEASE.jar (found in cache)
2020-03-04T12:12:55.64-0500 [STG/0] ERR [JavaMemoryAssistantHeapDumpFolder] INFO Heap dumps will be stored under 'development-10180e2b/spring-music-25321a8f'
2020-03-04T12:13:07.26-0500 [STG/0] OUT Exit status 0
# this marks the end of the buildpack output
# Diego is handling output from staging & saving the droplet to Cloud Controller. For issues here, refer to the Diego Cell logs from the VM with the referenced Cell guid
2020-03-04T12:13:07.26-0500 [STG/0] OUT Uploading droplet, build artifacts cache...
2020-03-04T12:13:07.26-0500 [STG/0] OUT Uploading build artifacts cache...
2020-03-04T12:13:07.26-0500 [STG/0] OUT Uploading droplet...
2020-03-04T12:13:08.07-0500 [STG/0] OUT Uploaded build artifacts cache (44.2M)
2020-03-04T12:13:08.80-0500 [API/8] OUT Creating droplet for app with guid 25321a8f-260c-4714-a810-806159d1111b
2020-03-04T12:13:14.08-0500 [STG/0] OUT Uploaded droplet (92.3M)
2020-03-04T12:13:14.11-0500 [STG/0] OUT Uploading complete
2020-03-04T12:13:14.83-0500 [STG/0] OUT Cell ########-####-####-####-############ stopping instance ########-####-####-####-############
2020-03-04T12:13:14.83-0500 [STG/0] OUT Cell ########-####-####-####-############ destroying container for instance ########-####-####-####-############
2020-03-04T12:13:16.37-0500 [STG/0] OUT Cell ########-####-####-####-############ successfully destroyed container for instance ########-####-####-####-############
# Staging totally done & container has been deleted
# Diego is stopping the previous app instance. This happens when you `cf push` an app that is already running. This maybe interleaved with the output from staging.
2020-03-04T12:13:00.01-0500 [CELL/SSHD/0] OUT Exit status 0
2020-03-04T12:13:00.50-0500 [APP/PROC/WEB/0] OUT Exit status 143
2020-03-04T12:13:00.51-0500 [CELL/0] OUT Cell ########-####-####-####-############ destroying container for instance ########-####-####-####-############
2020-03-04T12:13:00.85-0500 [PROXY/0] OUT Exit status 137
2020-03-04T12:13:01.66-0500 [CELL/0] OUT Cell ########-####-####-####-############ successfully destroyed container for instance ########-####-####-####-############
# The previous application container is stopped and deleted
# Diego is creating a new container to run the app. For issues here, refer to the Diego Cell logs from the VM with the referenced Cell guid. Note: this is likely a different guid from the Cell where staging occurred.
2020-03-04T12:13:15.53-0500 [CELL/0] OUT Cell ########-####-####-####-############ creating container for instance ########-####-####-####-############
2020-03-04T12:13:16.70-0500 [CELL/0] OUT Cell ########-####-####-####-############ successfully created container for instance ########-####-####-####-############
2020-03-04T12:13:17.35-0500 [CELL/0] OUT Downloading droplet...
2020-03-04T12:13:20.93-0500 [CELL/0] OUT Downloaded droplet (92.3M)
# Diego is starting your app & begins to execute the health check against your app
2020-03-04T12:13:20.93-0500 [CELL/0] OUT Starting health monitoring of container
# This marks the beginning of log output from the application itself. Most output here will indicate an application failure, however you may see output from components configured by the buildpack which can fail. For example, a server configured by the buildpack could fail and write its output here as well.
2020-03-04T12:13:22.56-0500 [APP/PROC/WEB/0] OUT JVM Memory Configuration: -Xmx407176K -Xss1M -XX:ReservedCodeCacheSize=240M -XX:MaxDirectMemorySize=10M -XX:MaxMetaspaceSize=129400K
2020-03-04T12:13:22.82-0500 [APP/PROC/WEB/0] ERR com.sap.jma.Agent#ERROR: JavaMemoryAssistant cannot start
2020-03-04T12:13:22.82-0500 [APP/PROC/WEB/0] ERR com.sap.jma.vms.JavaVirtualMachine$UnsupportedJavaVirtualMachineException: JVM with vendor 'Pivotal Software Inc' and spec version '1.8' is not supported
2020-03-04T12:13:22.82-0500 [APP/PROC/WEB/0] ERR at com.sap.jma.vms.JavaVirtualMachine$Supported.find(JavaVirtualMachine.java:73)
2020-03-04T12:13:22.82-0500 [APP/PROC/WEB/0] ERR at com.sap.jma.MBeanMonitor.findCurrentJvm(MBeanMonitor.java:228)
2020-03-04T12:13:22.82-0500 [APP/PROC/WEB/0] ERR at com.sap.jma.MBeanMonitor.initialize(MBeanMonitor.java:57)
2020-03-04T12:13:22.82-0500 [APP/PROC/WEB/0] ERR at com.sap.jma.Monitor.start(Monitor.java:71)
2020-03-04T12:13:22.82-0500 [APP/PROC/WEB/0] ERR at com.sap.jma.Agent.start(Agent.java:89)
2020-03-04T12:13:22.82-0500 [APP/PROC/WEB/0] ERR at com.sap.jma.Agent.initAgent(Agent.java:40)
2020-03-04T12:13:22.82-0500 [APP/PROC/WEB/0] ERR at com.sap.jma.Agent.premain(Agent.java:18)
2020-03-04T12:13:22.82-0500 [APP/PROC/WEB/0] ERR at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2020-03-04T12:13:22.82-0500 [APP/PROC/WEB/0] ERR at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
2020-03-04T12:13:22.82-0500 [APP/PROC/WEB/0] ERR at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2020-03-04T12:13:22.82-0500 [APP/PROC/WEB/0] ERR at java.lang.reflect.Method.invoke(Method.java:498)
2020-03-04T12:13:22.82-0500 [APP/PROC/WEB/0] ERR at sun.instrument.InstrumentationImpl.loadClassAndStartAgent(InstrumentationImpl.java:386)
2020-03-04T12:13:22.82-0500 [APP/PROC/WEB/0] ERR at sun.instrument.InstrumentationImpl.loadClassAndCallPremain(InstrumentationImpl.java:401)
# This marks the container becoming healthy. ie. the application has past the initial health check
2020-03-04T12:13:42.31-0500 [CELL/0] OUT Container became healthy
# You will likely see more app logs here. The app is now running so app logs will continue until the app stops or crashes.
...
Using the log output and comments above, you can narrow down the scope of the problem.
For example, above we see that there is an error in the application logs. Specifically, the JavaMemoryAssistant (an item configured by the Java buildpack) is failing. This narrows the problem down to either an issue with our application or an issue with the way the Java buildpack has configured our application. At this point, we can now focus our investigation on that particular, more specific problem.
You can use the same logic with your application log in order to narrow down the problems you are facing. Locate the section in your logs where the error occurs, and use the comments above to drill down and find the likely culprit.
If you need additional assistance troubleshooting your problem, please open a support ticket with VMware Tanzu Support and attach the logs you capture plus the following information.
- Please obtain the full command being used to push your application. Please also get the
manifest.ymlfile, if one is being used as this can impact how the app is pushed. - Please get the build pack and build pack version. If your buildpack has been upgraded, please get the buildpack version before and after the upgrade.
- Please get the names and versions of any application level frameworks (Spring, Rails, Django, etc.) being used by the app.
Related KB article: https://community.pivotal.io/s/article/How-to-troubleshoot-an-application-that-fails-only-when-run-on-Cloud-Foundry
Additional Information
https://community.pivotal.io/s/article/How-to-troubleshoot-an-application-that-fails-only-when-run-on-Cloud-Foundry
Feedback
Yes
No
Powered by
