Auto-reconfiguration stopping Play Framework Java Applications from staging

[Troy Astle]

I have a Java application running on CF written with the Play Framework.

The application stages correctly until I bind services to it (in this case a user-provided Syslog service)

After the service has been bound the application will no longer stage owing to errors in auto reconfiguration.

(logs below)

I have found the following documentation for Play 2.1.x:

http://www.playframework.com/documentation/2.1.x/Deploying-CloudFoundry

However after adding the file recommended to disable auto-reconfiguration I am seeing the same error.

I am a little stumped on this at the moment, has anyone encountered this in the past?

Troy.

$ play clean dist
...
$ cf push

Using manifest file manifest.yml


Uploading cf-env... OK
Stopping cf-env... OK


Preparing to start cf-env... OK
-----> Downloaded app package (31M)
-----> Downloaded app buildpack cache (34M)
-----> Downloading OpenJDK 1.7.0_51 from http://download.pivotal.io.s3.amazonaws.com/openjdk/lucid/x86_64/openjdk-1.7.0_51.tar.gz (0.1s)
       Expanding JRE to .java (1.1s)
-----> Downloading Play Auto-reconfiguration 0.8.6 from http://download.pivotal.io.s3.amazonaws.com/auto-reconfiguration/auto-reconfiguration-0.8.6.jar (0.0s)
-----> Downloading Spring Auto-reconfiguration 0.8.6 from http://download.pivotal.io.s3.amazonaws.com/auto-reconfiguration/auto-reconfiguration-0.8.6.jar (0.1s)
-----> Downloaded app package (31M)
-----> Downloaded app buildpack cache (34M)
-----> Downloading OpenJDK 1.7.0_51 from http://download.pivotal.io.s3.amazonaws.com/openjdk/lucid/x86_64/openjdk-1.7.0_51.tar.gz (0.1s)
       Expanding JRE to .java (1.1s)
-----> Downloading Play Auto-reconfiguration 0.8.6 from http://download.pivotal.io.s3.amazonaws.com/auto-reconfiguration/auto-reconfiguration-0.8.6.jar (0.0s)
-----> Downloading Spring Auto-reconfiguration 0.8.6 from http://download.pivotal.io.s3.amazonaws.com/auto-reconfiguration/auto-reconfiguration-0.8.6.jar (0.1s)
-----> Uploading droplet (66M)
Checking status of app 'cf-env'...

  0 of 1 instances running (1 starting)
  0 of 1 instances running (1 starting)
  0 of 1 instances running (1 down)
  0 of 1 instances running (1 crashing)
Push unsuccessful.
TIP: The system will continue to attempt restarting all requested app instances that have crashed. Try 'cf app' to monitor app status. To troubleshoot crashes, try 'cf events' and 'cf crashlogs'.


$ cf crashlogs cf-env
Getting logs for cf-env #b94ed28c27ea40b0ae429d17fff2df70... OK


Reading logs/env.log... OK
TMPDIR=/home/vcap/tmp
VCAP_APP_PORT=61053
USER=vcap
VCAP_APPLICATION={"instance_id":"b94ed28c27ea40b0ae429d17fff2df70","instance_index":0,"host":"0.0.0.0","port":61053,"started_at":"2014-01-28 18:54:05 +0000","started_at_timestamp":1390935245,"start":"2014-01-28 18:54:05 +0000","state_timestamp":1390935245,"limits":{"mem":512,"disk":1024,"fds":16384},"application_version":"d808618b-ba04-4ba8-83cc-5cc708798b08","application_name":"cf-env","application_uris":["cf-env.ft6.cpgpaas.net"],"version":"d808618b-ba04-4ba8-83cc-5cc708798b08","name":"cf-env","uris":["cf-env.ft6.cpgpaas.net"],"users":null}
PATH=/bin:/usr/bin
PWD=/home/vcap
VCAP_SERVICES={"user-provided":[{"name":"FT-Logging","label":"user-provided","tags":[],"credentials":{},"syslog_drain_url":"syslog://10.123.179.195:514"}]}
SHLVL=1
HOME=/home/vcap/app
PORT=61053
VCAP_APP_HOST=0.0.0.0
DATABASE_URL=
MEMORY_LIMIT=512m
_=/usr/bin/env






Reading logs/staging_task.log... OK
-----> Downloaded app package (31M)
-----> Downloaded app buildpack cache (34M)
-----> Downloading OpenJDK 1.7.0_51 from http://download.pivotal.io.s3.amazonaws.com/openjdk/lucid/x86_64/openjdk-1.7.0_51.tar.gz (0.1s)
       Expanding JRE to .java (1.1s)
-----> Downloading Play Auto-reconfiguration 0.8.6 from http://download.pivotal.io.s3.amazonaws.com/auto-reconfiguration/auto-reconfiguration-0.8.6.jar (0.0s)
-----> Downloading Spring Auto-reconfiguration 0.8.6 from http://download.pivotal.io.s3.amazonaws.com/auto-reconfiguration/auto-reconfiguration-0.8.6.jar (0.1s)






Reading logs/stderr.log... OK
Jan 28, 2014 6:54:08 PM auto_reconfig.org.springframework.cloud.AbstractCloudConnector getServiceInfo
WARNING: No suitable service info creator found for service FT-Logging Did you forget to add a ServiceInfoCreator?
Jan 28, 2014 6:54:08 PM auto_reconfig.org.springframework.cloud.AbstractCloudConnector getServiceInfo
WARNING: No suitable service info creator found for service FT-Logging Did you forget to add a ServiceInfoCreator?
Jan 28, 2014 6:54:08 PM auto_reconfig.org.springframework.cloud.ServiceConnectorCreatorRegistry getServiceCreatorOrNull
INFO: Trying connector creator type auto_reconfig.org.springframework.cloud.service.relational.MysqlDataSourceCreator@7b8269b6
Exception in thread "main" java.lang.ClassCastException: auto_reconfig.org.springframework.cloud.service.BaseServiceInfo cannot be cast to auto_reconfig.org.springframework.cloud.service.common.RelationalServiceInfo
 at org.cloudfoundry.reconfiguration.play.PropertySetter.setCloudProperties(PropertySetter.java:51)
 at org.cloudfoundry.reconfiguration.play.Configurer.configure(Configurer.java:38)
 at org.cloudfoundry.reconfiguration.play.Bootstrap.main(Bootstrap.java:19)

Troy Astle

Cisco

[Daniel Mikusa]

Troy,

The instruction you’ve linked to look like they are for CFv1. They reference “vmc”, which is usually a dead give away. Take these with a grain of salt as they may not still be relevant for CFv2.

The docs for the Java Build Pack say that it supports Play apps.

https://github.com/cloudfoundry/java-buildpack/blob/master/docs/container-play_framework.md

Have you tried just pushing your app without using the instructions you referenced? If so, what happens?

Dan

> To unsubscribe from this group and stop receiving emails from it, send an email to vcap-dev+u...@cloudfoundry.org.

[Ben Hale]

The instruction you’ve linked to look like they are for CFv1.  They reference “vmc”, which is usually a dead give away.  Take these with a grain of salt as they may not still be relevant for CFv2. 

Troy,

As Daniel points out, the documentation you ran into is out of date.  However, you're certainly running into bug in our auto-reconfiguration stuff.  I've pointed out the issue to the lead of that project and we'll see if we can replicate and diagnose the issue.

-Ben Hale

Cloud Foundry Java Experience

[Ramnivas Laddad]

I think I have just fixed your problem in spring-cloud.

https://github.com/spring-projects/spring-cloud/commit/56c6eca8f967e97912224c0e747502309999773e

I am testing auto-reconfig based on it. Once we deploy the new auto-reconfig (I will post it here when we have done so), can you test it to see if that solves problem for you.

-Ramnivas

[Ramnivas Laddad]

Troy,

The change for auto-reconfiguration is now in production. spring-cloud version 0.9.5 is also published.

Can you try pushing your application again and let us know how it goes.

-Ramnivas

[Troy Astle]

Thanks guys,

@Ben, yes the error occurs without any custom changes. My steps to produce the error are as follows:

1) Build a Play Framework app.

2) Push it to CF - the app will work fine

3) Bind a syslog drain to the app

4) Restart the app and it failed to start 

** Note with the new changes from Ramnivas the app now starts and just shows errors in the log.

@Ramnivas

Thanks for the changes. My application now starts correctly when the service is bound but shows as series of errors in the log (see below).

Is it possible to avoid these errors and disable the automatic reconfiguration?

Thanks to you both.

Troy.

2014-01-29T09:49:54.55+0000 [App/0]   OUT [info] play - Listening for HTTP on /0.0.0.0:61141
2014-01-29T09:49:54.55+0000 [App/0]   ERR Jan 29, 2014 9:49:52 AM auto_reconfig.org.springframework.cloud.AbstractCloudConnector getServiceInfo
2014-01-29T09:49:54.55+0000 [App/0]   ERR WARNING: No suitable service info creator found for service FT-Logging Did you forget to add a ServiceInfoCreator?
2014-01-29T09:49:54.55+0000 [App/0]   ERR Jan 29, 2014 9:49:52 AM auto_reconfig.org.springframework.cloud.AbstractCloudConnector getServiceInfo
2014-01-29T09:49:54.55+0000 [App/0]   ERR WARNING: No suitable service info creator found for service FT-Logging Did you forget to add a ServiceInfoCreator?
2014-01-29T09:49:54.55+0000 [App/0]   ERR Jan 29, 2014 9:49:52 AM auto_reconfig.org.springframework.cloud.ServiceConnectorCreatorRegistry getServiceCreatorOrNull
2014-01-29T09:49:54.55+0000 [App/0]   ERR INFO: Trying connector creator type auto_reconfig.org.springframework.cloud.service.relational.MysqlDataSourceCreator@7b8269b6
2014-01-29T09:49:54.55+0000 [App/0]   ERR Jan 29, 2014 9:49:52 AM auto_reconfig.org.springframework.cloud.ServiceConnectorCreatorRegistry getServiceCreatorOrNull
2014-01-29T09:49:54.55+0000 [App/0]   ERR INFO: Trying connector creator type auto_reconfig.org.springframework.cloud.service.relational.PostgresqlDataSourceCreator@2eea6b13

[Ben Hale]

Thanks for the changes. My application now starts correctly when the service is bound but shows as series of errors in the log (see below).

Is it possible to avoid these errors and disable the automatic reconfiguration?

I'm pretty sure this is a logging level error rather than a real error.  @Ramnivas, what's your opinion? 

[Ramnivas Laddad]

Troy,

Glad to see your app starting correctly.

The log messages you see aren't really errors (logged at INFO or WARNING level). Basically, it is trying to say that there is no implementation of ServiceInfoCreator found that could work with your user-provided service. You should see no impact on your application due to those.

That said, I can see how these log messages may seem intimidating. I'll see if we can tame them down.

-Ramnivas

[Ben Hale]

The log messages you see aren't really errors (logged at INFO or WARNING level). Basically, it is trying to say that there is no implementation of ServiceInfoCreator found that could work with your user-provided service. You should see no impact on your application due to those.

That said, I can see how these log messages may seem intimidating. I'll see if we can tame them down.

 

Troy,

As Ramnivas points out, the messages are coming out at some reasonable level, but Loggergator marks them as ERR because they go to stderr.  They go to stderr because Java's default logging configuration specifies that.  Our plan is to adjust the logging for auto-reconfiguration such that those messages go to stdout which will result in them being labeled with the less-scary OUT tag.  You can track the progress of this change here.

Let us know if you come across any other scary message that we can take a look at.

[Troy Astle]

Thanks guys,

It sounds like an excellent plan to me. I can see the warning messages concerning new devs as they start pushing apps to CF. 

Thanks for the info n Loggregator, we have only started using it recently so I'm still getting used to it. 

Thanks again guys. 

Appreciate your help and the useful info. 

Troy. 

--
Sent from my phone.