Skip to content

Appdynamics integration breaks Play! Framework Applications #73

@trastle

Description

@trastle

Play! Framework applications fail to start after AppDynamics service is bound

Summary

After binding an AppDynamics User Provided Service to a Java Play! Framework application the application fails to start.

Steps to reproduce (use any Play app)

$ git clone https://github.com/FreightTrain/play-cf-env.git
$ cd ./play-cf-env/play-cf-env
$ play clean dist

# Modify manifest.yml to meet your needs

$ cf push

# Everything is fine
# Create an Appdynamics User Provided Service (dummy data for this if fine for now)

$ cf bs tastle-ad-debug app-dynamics-usp
$ cf push

# App stages but cannot start.

Primary error in app logs

2014-07-17T10:26:18.18+0100 [App/0]   OUT [INFO]: AgentInstallManager - Agent runtime directory set to [/home/vcap/app/.java-buildpack/app_dynamics_agent]
2014-07-17T10:26:18.19+0100 [App/0]   OUT [INFO]: AgentInstallManager - Agent node directory set to [unknown]
2014-07-17T10:26:18.19+0100 [App/0]   OUT Could not start Java Agent because unable to determine Tier Name or Node Name
2014-07-17T10:26:18.20+0100 [App/0]   OUT Agent Logging Directory [/home/vcap/app/.java-buildpack/app_dynamics_agent/logs/unknown]
2014-07-17T10:26:18.32+0100 [App/0]   ERR Error: Could not find or load main class Foundry
2014-07-17T10:26:18.37+0100 [DEA]     OUT Instance (index 0) failed to start accepting connections

Attempted Workarounds

I've tried manually specifying the AppDynamics controller-info.xml in a forked buildpack

This allows the Appdynamics agent to start however the error starting the application itself (once the agent is up) remains: ERR Error: Could not find or load main class Foundry

I am currently trying to work out why this is the case.



Logs

Full logs

01. Push the app with no service bound

Summary: Everything is fine.

tastle@TASTLE-M-W03P play-cf-env (master) $ cf push
Using manifest file /Users/tastle/Code/FreightTrain/bugs/2014-07-14-Play-apps-with-appdynamics/play-cf-env/play-cf-env/manifest.yml

Creating app tastle-ad-debug in org COL-DEV-QBRANCH / space Development as admin...
OK

Creating route tastle-ad-debug.paas.dev.col.tx.cpgpaas.net...
OK

Binding tastle-ad-debug.paas.dev.col.tx.cpgpaas.net to tastle-ad-debug...
OK

Uploading tastle-ad-debug...
Uploading app files from: /Users/tastle/Code/FreightTrain/bugs/2014-07-14-Play-apps-with-appdynamics/play-cf-env/play-cf-env/dist/play-cf-env-1.0-SNAPSHOT.zip
Uploading 527.2K, 24 files
OK

Starting app tastle-ad-debug in org COL-DEV-QBRANCH / space Development as admin...
OK
-----> Downloaded app package (31M)
-----> Java Buildpack Version: v2.1.2 | https://github.com/cloudfoundry/java-buildpack.git#074fd9a
-----> Downloading Open Jdk JRE 1.7.0_60 from http://download.run.pivotal.io/openjdk/lucid/x86_64/openjdk-1.7.0_60.tar.gz (19.1s)
       Expanding Open Jdk JRE to .java-buildpack/open_jdk_jre (1.0s)
-----> Downloading Play Framework Auto Reconfiguration 0.8.9 from http://download.run.pivotal.io/auto-reconfiguration/auto-reconfiguration-0.8.9.jar (1.1s)
-----> Downloading Spring Auto Reconfiguration 0.8.9 from http://download.run.pivotal.io/auto-reconfiguration/auto-reconfiguration-0.8.9.jar (found in cache)

-----> Uploading droplet (63M)

0 of 1 instances running, 1 starting
1 of 1 instances running

App started

Showing health and status for app tastle-ad-debug in org COL-DEV-QBRANCH / space Development as admin...
OK

requested state: started
instances: 1/1
usage: 1G x 1 instances
urls: tastle-ad-debug.paas.dev.col.tx.cpgpaas.net

     state     since                    cpu    memory         disk
#0   running   2014-07-17 10:22:25 AM   0.0%   223.9M of 1G   125M of 1G

02. Bind AppDynamics and Push :: Terminal Log

tastle@TASTLE-M-W03P play-cf-env (master) $ cf bs tastle-ad-debug app-dynamics-faast-stage
Binding service app-dynamics-faast-stage to app tastle-ad-debug in org COL-DEV-QBRANCH / space Development as admin...
OK
TIP: Use 'cf push' to ensure your env variable changes take effect
tastle@TASTLE-M-W03P play-cf-env (master) $ cf push
Using manifest file /Users/tastle/Code/FreightTrain/bugs/2014-07-14-Play-apps-with-appdynamics/play-cf-env/play-cf-env/manifest.yml

Updating app tastle-ad-debug in org COL-DEV-QBRANCH / space Development as admin...
OK

Using route tastle-ad-debug.paas.dev.col.tx.cpgpaas.net
Uploading tastle-ad-debug...
Uploading app files from: /Users/tastle/Code/FreightTrain/bugs/2014-07-14-Play-apps-with-appdynamics/play-cf-env/play-cf-env/dist/play-cf-env-1.0-SNAPSHOT.zip
Uploading 527.2K, 24 files
OK

Stopping app tastle-ad-debug in org COL-DEV-QBRANCH / space Development as admin...
OK

Starting app tastle-ad-debug in org COL-DEV-QBRANCH / space Development as admin...
OK
-----> Downloaded app package (31M)
-----> Downloaded app buildpack cache (31M)
-----> Java Buildpack Version: v2.1.2 | https://github.com/cloudfoundry/java-buildpack.git#074fd9a
-----> Downloading Open Jdk JRE 1.7.0_60 from http://download.run.pivotal.io/openjdk/lucid/x86_64/openjdk-1.7.0_60.tar.gz (found in cache)
       Expanding Open Jdk JRE to .java-buildpack/open_jdk_jre (1.0s)
-----> Downloading App Dynamics Agent 3.7.17 from http://download.run.pivotal.io/app-dynamics/app-dynamics-3.7.17.zip (2.3s)
       Expanding App Dynamics Agent to .java-buildpack/app_dynamics_agent (0.1s)
-----> Downloading Play Framework Auto Reconfiguration 0.8.9 from http://download.run.pivotal.io/auto-reconfiguration/auto-reconfiguration-0.8.9.jar (found in cache)
-----> Downloading Spring Auto Reconfiguration 0.8.9 from http://download.run.pivotal.io/auto-reconfiguration/auto-reconfiguration-0.8.9.jar (found in cache)

-----> Uploading droplet (72M)

0 of 1 instances running, 1 down
...
0 of 1 instances running, 1 down
0 of 1 instances running, 1 starting
0 of 1 instances running, 1 down
...
0 of 1 instances running, 1 down
0 of 1 instances running, 1 starting
0 of 1 instances running, 1 down
...
0 of 1 instances running, 1 down
0 of 1 instances running, 1 failing
FAILED
Start unsuccessful

TIP: use 'cf logs tastle-ad-debug --recent' for more information

03. Bind AppDynamics and Push :: App Logs

tastle@TASTLE-M-W03P ~ $ cf logs tastle-ad-debug
Connected, tailing logs for app tastle-ad-debug in org COL-DEV-QBRANCH / space Development as admin...  
2014-07-17T10:24:31.90+0100 [API]     OUT Updated app with guid 3aeb7523-ed48-400a-aa65-52ae5d23d3ec ({"name"=>"tastle-ad-debug", "instances"=>1, "memory"=>1024, "environment_json"=>"PRIVATE DATA HIDDEN"})
2014-07-17T10:24:43.32+0100 [API]     OUT Updated app with guid 3aeb7523-ed48-400a-aa65-52ae5d23d3ec ({"state"=>"STOPPED"})
2014-07-17T10:24:44.46+0100 [DEA]     OUT Stopping app instance (index 0) with guid 3aeb7523-ed48-400a-aa65-52ae5d23d3ec
2014-07-17T10:24:44.46+0100 [DEA]     OUT Stopped app instance (index 0) with guid 3aeb7523-ed48-400a-aa65-52ae5d23d3ec
2014-07-17T10:24:45.09+0100 [DEA]     OUT Got staging request for app with id 3aeb7523-ed48-400a-aa65-52ae5d23d3ec
2014-07-17T10:24:47.12+0100 [API]     OUT Updated app with guid 3aeb7523-ed48-400a-aa65-52ae5d23d3ec ({"state"=>"STARTED"})
2014-07-17T10:24:47.63+0100 [STG]     OUT -----> Downloaded app package (31M)
2014-07-17T10:24:48.04+0100 [STG]     OUT -----> Downloaded app buildpack cache (31M)
2014-07-17T10:24:53.31+0100 [STG]     OUT -----> Java Buildpack Version: v2.1.2 | https://github.com/cloudfoundry/java-buildpack.git#074fd9a
2014-07-17T10:24:53.64+0100 [STG]     OUT -----> Downloading Open Jdk JRE 1.7.0_60 from http://download.run.pivotal.io/openjdk/lucid/x86_64/openjdk-1.7.0_60.tar.gz (found in cache)
2014-07-17T10:24:54.64+0100 [STG]     OUT        Expanding Open Jdk JRE to .java-buildpack/open_jdk_jre (1.0s)
2014-07-17T10:24:56.96+0100 [STG]     OUT -----> Downloading App Dynamics Agent 3.7.17 from http://download.run.pivotal.io/app-dynamics/app-dynamics-3.7.17.zip (2.3s)
2014-07-17T10:24:57.09+0100 [STG]     OUT        Expanding App Dynamics Agent to .java-buildpack/app_dynamics_agent (0.1s)
2014-07-17T10:24:57.23+0100 [STG]     OUT -----> Downloading Play Framework Auto Reconfiguration 0.8.9 from http://download.run.pivotal.io/auto-reconfiguration/auto-reconfiguration-0.8.9.jar (found in cache)
2014-07-17T10:24:57.38+0100 [STG]     OUT -----> Downloading Spring Auto Reconfiguration 0.8.9 from http://download.run.pivotal.io/auto-reconfiguration/auto-reconfiguration-0.8.9.jar (found in cache)
2014-07-17T10:24:58.41+0100 [STG]     ERR
2014-07-17T10:25:06.03+0100 [STG]     OUT -----> Uploading droplet (72M)
2014-07-17T10:25:14.68+0100 [DEA]     OUT Starting app instance (index 0) with guid 3aeb7523-ed48-400a-aa65-52ae5d23d3ec
2014-07-17T10:25:17.71+0100 [App/0]   OUT Install Directory resolved to[/home/vcap/app/.java-buildpack/app_dynamics_agent]
2014-07-17T10:25:17.71+0100 [LGR]     ERR SinkManager: Invalid syslog drain URL: . Err: Incomplete URL {  <nil>    }. This could be caused by an URL without slashes or protocol.
2014-07-17T10:25:17.81+0100 [App/0]   OUT [INFO]: JavaAgent - Using Java Agent Version [Server Agent v3.7.17.0 GA #2014-03-14_17-33-47 rdd57f118ff59ef0cbc3f6193058a58943b15fae1 88-3.7.17]
2014-07-17T10:25:17.81+0100 [App/0]   OUT [INFO]: JavaAgent - Running IBM Java Agent [No]
2014-07-17T10:25:17.82+0100 [App/0]   OUT [INFO]: AgentInstallManager - AppDynamics Agent edition [standard]
2014-07-17T10:25:17.82+0100 [App/0]   OUT [INFO]: AgentInstallManager - Full Agent Registration Info Resolver is running
2014-07-17T10:25:17.82+0100 [App/0]   OUT [INFO]: AgentInstallManager - Full Agent Registration Info Resolver using system property [appdynamics.agent.applicationName] for application name [tastle-ad-debug]
2014-07-17T10:25:17.82+0100 [App/0]   OUT [INFO]: AgentInstallManager - Full Agent Registration Info Resolver using system property [appdynamics.agent.tierName] for tier name [Cloud]
2014-07-17T10:25:17.97+0100 [App/0]   OUT [INFO]: AgentInstallManager - Full Agent Registration Info Resolver using application name [tastle-ad-debug]
2014-07-17T10:25:17.97+0100 [App/0]   OUT [INFO]: AgentInstallManager - Full Agent Registration Info Resolver using tier name [Cloud]
2014-07-17T10:25:17.97+0100 [App/0]   OUT [INFO]: AgentInstallManager - Full Agent Registration Info Resolver using node name [unknown]
2014-07-17T10:25:17.97+0100 [App/0]   OUT [INFO]: AgentInstallManager - Full Agent Registration Info Resolver finished running
2014-07-17T10:25:17.97+0100 [App/0]   OUT [INFO]: AgentInstallManager - Agent runtime directory set to [/home/vcap/app/.java-buildpack/app_dynamics_agent]
2014-07-17T10:25:17.97+0100 [App/0]   OUT [INFO]: AgentInstallManager - Agent node directory set to [unknown]
2014-07-17T10:25:17.97+0100 [App/0]   OUT Could not start Java Agent because unable to determine Tier Name or Node Name
2014-07-17T10:25:17.99+0100 [App/0]   OUT Agent Logging Directory [/home/vcap/app/.java-buildpack/app_dynamics_agent/logs/unknown]
2014-07-17T10:25:18.11+0100 [App/0]   ERR Error: Could not find or load main class Foundry
2014-07-17T10:25:18.17+0100 [DEA]     OUT Instance (index 0) failed to start accepting connections
2014-07-17T10:25:18.18+0100 [API]     OUT App instance exited with guid 3aeb7523-ed48-400a-aa65-52ae5d23d3ec payload: {"cc_partition"=>"default", "droplet"=>"3aeb7523-ed48-400a-aa65-52ae5d23d3ec", "version"=>"f5d107a8-36de-4412-b5ac-c991d899583b", "instance"=>"2572bdf0053c425eabc5531854bb6575", "index"=>0, "reason"=>"CRASHED", "exit_status"=>1, "exit_description"=>"app instance exited", "crash_timestamp"=>1405589118}

04. Custom buildpack with static controller-info.xml :: App logs

2014-07-17T12:13:25.61+0100 [API]     OUT Updated app with guid 3aeb7523-ed48-400a-aa65-52ae5d23d3ec ({"name"=>"tastle-ad-debug", "instances"=>1, "memory"=>1024, "buildpack"=>"https://[email protected]/FreightTrain/java-buildpack-qbranch.git", "environment_json"=>"PRIVATE DATA HIDDEN"})
2014-07-17T12:13:37.10+0100 [API]     OUT Updated app with guid 3aeb7523-ed48-400a-aa65-52ae5d23d3ec ({"state"=>"STOPPED"})
2014-07-17T12:13:38.39+0100 [DEA]     OUT Got staging request for app with id 3aeb7523-ed48-400a-aa65-52ae5d23d3ec
2014-07-17T12:13:40.68+0100 [API]     OUT Updated app with guid 3aeb7523-ed48-400a-aa65-52ae5d23d3ec ({"state"=>"STARTED"})
2014-07-17T12:13:41.06+0100 [STG]     OUT -----> Downloaded app package (31M)
2014-07-17T12:13:41.83+0100 [STG]     OUT -----> Downloaded app buildpack cache (81M)
2014-07-17T12:13:41.99+0100 [STG]     ERR Cloning into '/tmp/buildpacks/java-buildpack-qbranch'...
2014-07-17T12:13:44.46+0100 [STG]     OUT -----> Java Buildpack Version: 5ce4ae9 | https://[email protected]/FreightTrain/java-buildpack-qbranch.git#5ce4ae9
2014-07-17T12:13:44.84+0100 [STG]     OUT -----> Downloading Open Jdk JRE 1.7.0_60 from http://download.run.pivotal.io/openjdk/lucid/x86_64/openjdk-1.7.0_60.tar.gz (found in cache)
2014-07-17T12:13:45.85+0100 [STG]     OUT        Expanding Open Jdk JRE to .java-buildpack/open_jdk_jre (1.0s)
2014-07-17T12:13:45.99+0100 [STG]     OUT -----> Downloading App Dynamics Agent 3.8.4 from http://download.run.pivotal.io/app-dynamics/app-dynamics-3.8.4.zip (found in cache)
2014-07-17T12:13:46.12+0100 [STG]     OUT        Expanding App Dynamics Agent to .java-buildpack/app_dynamics_agent (0.1s)
2014-07-17T12:13:46.26+0100 [STG]     OUT -----> Downloading Play Framework Auto Reconfiguration 1.4.0_RELEASE from http://download.run.pivotal.io/auto-reconfiguration/auto-reconfiguration-1.4.0_RELEASE.jar (found in cache)
2014-07-17T12:13:46.40+0100 [STG]     OUT -----> Downloading Spring Auto Reconfiguration 1.4.0_RELEASE from http://download.run.pivotal.io/auto-reconfiguration/auto-reconfiguration-1.4.0_RELEASE.jar (found in cache)
2014-07-17T12:13:55.11+0100 [STG]     OUT -----> Uploading droplet (73M)
2014-07-17T12:14:05.94+0100 [DEA]     OUT Starting app instance (index 0) with guid 3aeb7523-ed48-400a-aa65-52ae5d23d3ec
2014-07-17T12:14:08.44+0100 [App/0]   OUT Install Directory resolved to[/home/vcap/app/.java-buildpack/app_dynamics_agent]
2014-07-17T12:14:08.56+0100 [App/0]   OUT [INFO]: AgentInstallManager - AppDynamics Agent edition [standard]
2014-07-17T12:14:08.56+0100 [App/0]   OUT [INFO]: AgentInstallManager - Full Agent Registration Info Resolver is running
2014-07-17T12:14:08.56+0100 [App/0]   OUT [INFO]: AgentInstallManager - Full Agent Registration Info Resolver using system property [appdynamics.agent.applicationName] for application name [tastle-ad-debug]
2014-07-17T12:14:08.56+0100 [App/0]   OUT [INFO]: AgentInstallManager - Full Agent Registration Info Resolver using system property [appdynamics.agent.tierName] for tier name [Cloud]
2014-07-17T12:14:08.73+0100 [App/0]   OUT [INFO]: AgentInstallManager - Full Agent Registration Info Resolver using application name [tastle-ad-debug]
2014-07-17T12:14:08.73+0100 [App/0]   OUT [INFO]: AgentInstallManager - Full Agent Registration Info Resolver using tier name [Cloud]
2014-07-17T12:14:08.73+0100 [App/0]   OUT [INFO]: AgentInstallManager - Full Agent Registration Info Resolver using node name [redacted]
2014-07-17T12:14:08.73+0100 [App/0]   OUT [INFO]: AgentInstallManager - Full Agent Registration Info Resolver finished running
2014-07-17T12:14:08.73+0100 [App/0]   OUT [INFO]: AgentInstallManager - Agent runtime directory set to [/home/vcap/app/.java-buildpack/app_dynamics_agent]
2014-07-17T12:14:08.73+0100 [App/0]   OUT [INFO]: AgentInstallManager - Agent node directory set to [redacted]
2014-07-17T12:14:08.76+0100 [App/0]   OUT [WARN]: AgentInstallManager - Invalid Edition [Java Agent]. Keeping current edition [STANDARD]
2014-07-17T12:14:08.76+0100 [App/0]   OUT [INFO]: JavaAgent - Using Java Agent Version [Server Agent v3.8.4.0 GA #2014-06-30_13-26-26 r5dc2d8d219673e698b0b455657ac469bc8b59337 4-3.8.4.next]
2014-07-17T12:14:08.77+0100 [App/0]   OUT [INFO]: JavaAgent - Running IBM Java Agent [No]
2014-07-17T12:14:08.77+0100 [App/0]   OUT [INFO]: JavaAgent - Java Agent Directory [/home/vcap/app/.java-buildpack/app_dynamics_agent]
2014-07-17T12:14:08.78+0100 [App/0]   OUT Agent Logging Directory [/home/vcap/app/.java-buildpack/app_dynamics_agent/logs/redacted]
2014-07-17T12:14:08.90+0100 [App/0]   OUT Running obfuscated agent
2014-07-17T12:14:11.02+0100 [App/0]   OUT Registered app server agent with Node ID[915] Component ID[306] Application ID [106]
2014-07-17T12:14:11.88+0100 [App/0]   OUT Started AppDynamics Java Agent Successfully.
2014-07-17T12:14:11.89+0100 [App/0]   ERR Error: Could not find or load main class Foundry
2014-07-17T12:14:11.94+0100 [DEA]     OUT Instance (index 0) failed to start accepting connections
2014-07-17T12:14:11.95+0100 [API]     OUT App instance exited with guid 3aeb7523-ed48-400a-aa65-52ae5d23d3ec payload: {"cc_partition"=>"default", "droplet"=>"3aeb7523-ed48-400a-aa65-52ae5d23d3ec", "version"=>"d10386fa-fe0b-4cb6-8a9f-93de23edca3a", "instance"=>"f55165ed491349709f551ee9df0df762", "index"=>0, "reason"=>"CRASHED", "exit_status"=>1, "exit_description"=>"app instance exited", "crash_timestamp"=>1405595651}

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions