Play 2.1 and Neo4J WrappingNeoServer errors with Logback.xml

Question

I had an embedded neo4j server with admin console working within a Play 2.0.1 application. I recently upgraded to the release candidate for compatibilities with DeadBolt and found that the application no longer runs.

To start the server I was doing the following:

    graphDb = (GraphDatabaseAPI) new GraphDatabaseFactory()
                .newEmbeddedDatabaseBuilder(CONF_DBMETA_LOCATION)
                .setConfig(ShellSettings.remote_shell_enabled, "true")
                .newGraphDatabase();
        ServerConfigurator config;
        config = new ServerConfigurator(graphDb);
        // let the server endpoint be on a custom port

        srv = new WrappingNeoServerBootstrapper(graphDb, config);
        srv.start();

Unfortunately I then get:

> java.lang.RuntimeException:
> org.neo4j.kernel.lifecycle.LifecycleException: Component
> 'org.neo4j.kernel.logging.LogbackService@4c043845' failed to
> initialize. Please see attached cause exception.

I have tried removing slf4j and logback dependencies from my Build.scala where neo4j-server is added but to no avail. It seems that the wrong logback.xml is being loaded by neo4j. Also, if I add notTransitive() to the neo4j-server dependency the logback.xml warnings at startup go away. I imagine that the neo4j specific logback.xml is embedded within the jar(s) and is causing the issue. One potential solution I see is to write a custom configuration via code, but I'm unsure how to do this. Any thoughts? For reference, I get these errors at startup:

>     22:11:05,124 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find
> resource [logback.groovy]
>     22:11:05,125 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find
> resource [logback-test.xml]
>     22:11:05,125 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource
> [logback.xml] at
> [jar:file:/Users/steve/Code/play-2.1-RC1/repository/local/play/play_2.10/2.1-RC1/jars/play_2.10.jar!/logback.xml]
>     22:11:05,126 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml]
> occurs multiple times on the classpath.
>     22:11:05,126 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml]
> occurs at
> [jar:file:/Users/steve/Code/play-2.1-RC1/framework/../repository/cache/org.neo4j.app/neo4j-server/jars/neo4j-server-1.9-SNAPSHOT.jar!/logback.xml]
>     22:11:05,126 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml]
> occurs at
> [jar:file:/Users/steve/Code/play-2.1-RC1/repository/local/play/play_2.10/2.1-RC1/jars/play_2.10.jar!/logback.xml]
>     22:11:05,139 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@733b8bc1 - URL
> [jar:file:/Users/steve/Code/play-2.1-RC1/repository/local/play/play_2.10/2.1-RC1/jars/play_2.10.jar!/logback.xml]
> is not of type file
>     22:11:05,265 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug
> attribute not set
>     22:11:05,614 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate
> appender of type [ch.qos.logback.core.ConsoleAppender]
>     22:11:05,625 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as
> [STDOUT]
>     22:11:05,657 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming
> default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for
> [encoder] property
>     22:11:05,707 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level
> of ROOT logger to ERROR
>     22:11:05,707 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching
> appender named [STDOUT] to Logger[ROOT]
>     22:11:05,707 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of
> configuration.
>     22:11:05,709 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@4a546701 - Registering
> current configuration as safe fallback point

See below for the full exception:

> play.api.UnexpectedException: Unexpected exception[RuntimeException:
> org.neo4j.kernel.lifecycle.LifecycleException: Component
> 'org.neo4j.kernel.logging.LogbackService@4c043845' failed to
> initialize. Please see attached cause exception.]     at
> play.core.ReloadableApplication$$anonfun$get$1$$anonfun$1.apply(ApplicationProvider.scala:134)
> ~[play_2.10.jar:2.1-RC1]  at
> play.core.ReloadableApplication$$anonfun$get$1$$anonfun$1.apply(ApplicationProvider.scala:101)
> ~[play_2.10.jar:2.1-RC1]  at scala.Option.map(Option.scala:145)
> ~[scala-library.jar:na]   at
> play.core.ReloadableApplication$$anonfun$get$1.apply(ApplicationProvider.scala:101)
> ~[play_2.10.jar:2.1-RC1]  at
> play.core.ReloadableApplication$$anonfun$get$1.apply(ApplicationProvider.scala:99)
> ~[play_2.10.jar:2.1-RC1]  at
> scala.util.Either$RightProjection.flatMap(Either.scala:523)
> [scala-library.jar:na] Caused by: java.lang.RuntimeException:
> org.neo4j.kernel.lifecycle.LifecycleException: Component
> 'org.neo4j.kernel.logging.LogbackService@4c043845' failed to
> initialize. Please see attached cause exception.  at
> org.neo4j.kernel.InternalAbstractGraphDatabase.run(InternalAbstractGraphDatabase.java:258)
> ~[neo4j-kernel-1.9.M03.jar:na]    at
> org.neo4j.kernel.EmbeddedGraphDatabase.<init>(EmbeddedGraphDatabase.java:88)
> ~[neo4j-kernel-1.9.M03.jar:na]    at
> org.neo4j.graphdb.factory.GraphDatabaseFactory$1.newDatabase(GraphDatabaseFactory.java:83)
> ~[neo4j-kernel-1.9.M03.jar:1.9.M03]   at
> org.neo4j.graphdb.factory.GraphDatabaseBuilder.newGraphDatabase(GraphDatabaseBuilder.java:206)
> ~[neo4j-kernel-1.9.M03.jar:1.9.M03]   at
> EmbeddedGraphDB.initializeDatabase(EmbeddedGraphDB.java:70)
> ~[na:na]  at
> EmbeddedGraphDB.<init>(EmbeddedGraphDB.java:51)
> ~[na:na] Caused by: org.neo4j.kernel.lifecycle.LifecycleException:
> Component 'org.neo4j.kernel.logging.LogbackService@4c043845' failed to
> initialize. Please see attached cause exception.  at
> org.neo4j.kernel.lifecycle.LifeSupport$LifecycleInstance.init(LifeSupport.java:471)
> ~[neo4j-kernel-1.9.M03.jar:1.9.M03]   at
> org.neo4j.kernel.lifecycle.LifeSupport.init(LifeSupport.java:62)
> ~[neo4j-kernel-1.9.M03.jar:1.9.M03]   at
> org.neo4j.kernel.lifecycle.LifeSupport.start(LifeSupport.java:96)
> ~[neo4j-kernel-1.9.M03.jar:1.9.M03]   at
> org.neo4j.kernel.InternalAbstractGraphDatabase.run(InternalAbstractGraphDatabase.java:245)
> ~[neo4j-kernel-1.9.M03.jar:na]    at
> org.neo4j.kernel.EmbeddedGraphDatabase.<init>(EmbeddedGraphDatabase.java:88)
> ~[neo4j-kernel-1.9.M03.jar:na]    at
> org.neo4j.graphdb.factory.GraphDatabaseFactory$1.newDatabase(GraphDatabaseFactory.java:83)
> ~[neo4j-kernel-1.9.M03.jar:1.9.M03] Caused by:
> org.neo4j.kernel.lifecycle.LifecycleException: Component
> 'org.neo4j.kernel.logging.LogbackService$1@1955bd61' was successfully
> initialized, but failed to start. Please see attached cause exception.
>   at
> org.neo4j.kernel.lifecycle.LifeSupport$LifecycleInstance.start(LifeSupport.java:495)
> ~[neo4j-kernel-1.9.M03.jar:1.9.M03]   at
> org.neo4j.kernel.lifecycle.LifeSupport.start(LifeSupport.java:105)
> ~[neo4j-kernel-1.9.M03.jar:1.9.M03]   at
> org.neo4j.kernel.logging.LogbackService.init(LogbackService.java:106)
> ~[neo4j-kernel-1.9.M03.jar:1.9.M03]   at
> org.neo4j.kernel.lifecycle.LifeSupport$LifecycleInstance.init(LifeSupport.java:465)
> ~[neo4j-kernel-1.9.M03.jar:1.9.M03]   at
> org.neo4j.kernel.lifecycle.LifeSupport.init(LifeSupport.java:62)
> ~[neo4j-kernel-1.9.M03.jar:1.9.M03]   at
> org.neo4j.kernel.lifecycle.LifeSupport.start(LifeSupport.java:96)
> ~[neo4j-kernel-1.9.M03.jar:1.9.M03] Caused by:
> java.lang.NoSuchMethodError:
> org.codehaus.janino.ClassBodyEvaluator.setImplementedInterfaces([Ljava/lang/Class;)V
>   at
> ch.qos.logback.core.joran.conditional.PropertyEvalScriptBuilder.build(PropertyEvalScriptBuilder.java:48)
> ~[logback-core.jar:na]    at
> ch.qos.logback.core.joran.conditional.IfAction.begin(IfAction.java:67)
> ~[logback-core.jar:na]    at
> ch.qos.logback.core.joran.spi.Interpreter.callBeginAction(Interpreter.java:276)
> ~[logback-core.jar:na]    at
> ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:148)
> ~[logback-core.jar:na]    at
> ch.qos.logback.core.joran.spi.Interpreter.startElement(Interpreter.java:130)
> ~[logback-core.jar:na]    at
> ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:50)
> ~[logback-core.jar:na]

EDIT1 More Details

I removed the logback.xml file from play_2.10.jar and no longer get the duplicate warning from logback at startup of the play application.

I then tried locating putting the contents of both the neo4j logback.xml and play2.1 logback.xml as custom-logback.xml within the root of my play project. The same path as Play.application().path() Perhaps this is the wrong location for neo4j to pick it up?

When reviewing dependencies I have one janino required by neo4j-server. Also, I'm not seeing any conflicts in jars for logging but perhaps I'm missing something. Here's my dependency hierarchy from 'play dependencies':

https://gist.github.com/4559389

I also tried copying the default configuration listed on the Play2.1 wiki as below into custom-logback.xml with no success:

<configuration>

  <conversionRule conversionWord="coloredLevel" converterClass="play.api.Logger$ColoredLevel" />

  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
     <file>${application.home}/logs/application.log</file>
     <encoder>
       <pattern>%date - [%level] - from %logger in %thread %n%message%n%xException%n</pattern>
     </encoder>
   </appender>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%coloredLevel %logger{15} - %message%n%xException{5}</pattern>
    </encoder>
  </appender>

  <logger name="play" level="INFO" />
  <logger name="application" level="INFO" />

  <root level="ERROR">
    <appender-ref ref="STDOUT" />
    <appender-ref ref="FILE" />
  </root>

</configuration>

EDIT 2

Definitely seems to be an issue with the logback dependency. Neo4j depends on 0.9.30 and play depends on 1.0.7 it seems. I'm guessing there's an api change between those versions that when the library gets loaded by ?janino? it can't find the appropriate method. Still unsure as to how to specify in the logback.xml properly to select the proper dependency at runtime.

Graphs were generated by yed + sbt-dependency-graph.

Answer 1

With regard to the Neo4j lifecycle exception that gets thrown because Play 2.1's newer version of logback is not compatible with Neo4j's. I ran into this issue and ended up just overriding Play's logback to an older, compatible version by putting this in my Build.scala's project dependencies:

"ch.qos.logback" % "logback-core" % "1.0.3" force(), // this should override the Play version
"ch.qos.logback" % "logback-classic" % "1.0.3" force(),

For good measure I also tried excluding any log4j transitive dependencies being pulled in by setting SBT's ivyXML parameter:

ivyXML :=
  <dependencies>
    <exclude module="log4j"/>
  </dependencies>

This is obviously a fragile fix but, at least for Play 2.1-RC2, it seems to work. I still have issues actually configuring the logging for Neo4j so I'll try and update this answer later.

Update: Since I am new to Logback I had a bit of difficulty configuring it with Play/Neo4j. To prevent Logback from erroring and drowning me in status messages I needed to put a file called custom-logback.xml in my Play app's conf directory. I think the Neo4j logging config requires this. Mine contains the following:

<included>
    <logger name="eu.mypackage" level="info">
    </logger>

    <logger name="org.neo4j" level="warn">
    </logger>

    <root level="warn">
    </root>
</included>

Also in my conf directory, I seemed to need a file called logback.properties which (in my case) contains just this line:

CONSOLE_LEVEL=ERROR

(Logback experts, feel free to correct any of this.)