Play dist logger

[Emiliano Anichini]

Hi.

I've a problem with log statements in my app. If I start the app by dist and use -Dlogger.file only Play debug and exceptions are logged (no my custom messages). The problem is the same as this http://stackoverflow.com/questions/16906837/start-shell-script-from-play-dist-fails-to-locate-logger-xml-in-jar-file but I've not resolved it.

My application.conf contains:

...

# Root logger:

logger.root=DEBUG

# Logger used by the framework:

logger.play=DEBUG

# Logger provided to your application:

logger.application=DEBUG

db.default.logStatements=true

logger.com.jolbox=DEBUG

...

With play run all is fine, the issue is only with the dist.

My java play is 2.2.3

thank you.

[Emiliano Anichini]

The logger.xml file is here https://www.playframework.com/documentation/2.2.x/SettingsLogger#Configuring-logback

For bug tracking I've put my logger.xml file in debug mode.

Thank you for your help.

12:22 $ ./myapp-5-SNAPSHOT/bin/myapp -Dconfig.file=/home/eanichini/repo/myapp_server/myappDbConfigurations/local.conf -Dlogger.file=/home/eanichini/logger.xml

Java HotSpot(TM) 64-Bit Server VM warning: ignoring option MaxPermSize=256m; support was removed in 8.0

Play server process ID is 28232

12:22:14,081 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]

12:22:14,081 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]

12:22:14,082 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [jar:file:/home/eanichini/myapp-5-SNAPSHOT/lib/com.typesafe.play.play_2.10-2.2.3.jar!/logback.xml]

12:22:14,092 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@3c46e67a - URL [jar:file:/home/eanichini/myapp-5-SNAPSHOT/lib/com.typesafe.play.play_2.10-2.2.3.jar!/logback.xml] is not of type file

12:22:14,164 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set

12:22:14,165 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]

12:22:14,168 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]

12:22:14,183 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property

12:22:14,214 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to ERROR

12:22:14,214 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]

12:22:14,214 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.

12:22:14,215 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@c730b35 - Registering current configuration as safe fallback point

12:22:14,309 |-INFO in ch.qos.logback.core.joran.action.ConversionRuleAction - registering conversion word coloredLevel with class [play.api.Logger$ColoredLevel]

12:22:14,309 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.FileAppender]

12:22:14,309 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE]

12:22:14,311 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property

12:22:14,312 |-INFO in ch.qos.logback.core.FileAppender[FILE] - File property is set to [/home/eanichini/myapp-5-SNAPSHOT/logs/application.log]

12:22:14,313 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]

12:22:14,313 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]

12:22:14,313 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property

12:22:14,314 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [play] to INFO

12:22:14,314 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [application] to INFO

12:22:14,314 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO

12:22:14,314 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[ROOT]

12:22:14,314 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]

12:22:14,314 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.

12:22:14,314 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@6025e1b6 - Registering current configuration as safe fallback point

[debug] c.j.b.BoneCPDataSource - JDBC URL = jdbc:mysql://localhost:3306/mydb, Username = root, partitions = 1, max (per partition) = 30, min (per partition) = 5, idle max age = 10 min, idle test period = 1 min, strategy = DEFAULT

[info] play - database [default] connected at jdbc:mysql://localhost:3306/mydb

[debug] c.j.b.BoneCPDataSource - JDBC URL = jdbc:mysql://localhost:3306/class, Username = root, partitions = 1, max (per partition) = 30, min (per partition) = 5, idle max age = 10 min, idle test period = 1 min, strategy = DEFAULT

[info] play - database [classdb] connected at jdbc:mysql://localhost:3306/class

[debug] c.j.b.BoneCPDataSource - JDBC URL = jdbc:mysql://localhost:3306/myback, Username = root, partitions = 1, max (per partition) = 30, min (per partition) = 5, idle max age = 10 min, idle test period = 1 min, strategy = DEFAULT

[info] play - database [magmanager] connected at jdbc:mysql://localhost:3306/myback

[debug] c.a.e.c.PropertyMapLoader - No servletContext so not looking in WEB-INF for ebean.properties

[debug] c.a.e.c.PropertyMapLoader - ebean.properties found in classpath

[debug] o.r.Reflections - going to scan these urls:

        jar:file:/home/eanichini/myapp-5-SNAPSHOT/lib/myapp.myapp-5-SNAPSHOT.jar!/

[info] o.r.Reflections - Reflections took 41 ms to scan 1 urls, producing 7 keys and 15 values

[info] c.a.e.s.c.DefaultServerFactory - DatabasePlatform name:magmanager platform:mysql

[debug] c.a.e.a.ClassLoadContext - Context and Caller ClassLoader's same instance of sun.misc.Launcher$AppClassLoader

[debug] c.a.e.s.t.DefaultTypeManager - Registering Joda data types

[debug] c.a.e.s.d.BeanDescriptorManager - BeanPersistControllers[0] BeanFinders[0] BeanPersistListeners[0] BeanQueryAdapters[0]

[info] c.a.e.s.d.BeanDescriptorManager - Entities enhanced[3] subclassed[0]

[debug] j.m.mbeanserver - ObjectName = JMImplementation:type=MBeanServerDelegate

[debug] j.m.mbeanserver - name = JMImplementation:type=MBeanServerDelegate

[debug] j.m.mbeanserver - Send create notification of object JMImplementation:type=MBeanServerDelegate

[debug] j.m.mbeanserver - JMX.mbean.registered JMImplementation:type=MBeanServerDelegate

[debug] j.m.mbeanserver - ObjectName = Ebean:server=magmanager2,key=AutoFetch

[debug] j.m.mbeanserver - name = Ebean:server=magmanager2,key=AutoFetch

[debug] j.m.mbeanserver - Send create notification of object Ebean:key=AutoFetch,server=magmanager2

[debug] j.m.mbeanserver - JMX.mbean.registered Ebean:server=magmanager2,key=AutoFetch

[debug] c.a.ebean.Ebean - primaryName:null

[debug] o.r.Reflections - going to scan these urls:

        jar:file:/home/eanichini/myapp-5-SNAPSHOT/lib/com.typesafe.play.play_2.10-2.2.3.jar!/

        jar:file:/home/eanichini/myapp-5-SNAPSHOT/lib/myapp.myapp-5-SNAPSHOT.jar!/

[info] o.r.Reflections - Reflections took 29 ms to scan 2 urls, producing 23 keys and 70 values

[info] c.a.e.s.c.DefaultServerFactory - DatabasePlatform name:default platform:mysql

[debug] c.a.e.a.ClassLoadContext - Context and Caller ClassLoader's same instance of sun.misc.Launcher$AppClassLoader

[debug] c.a.e.s.t.DefaultTypeManager - Registering Joda data types

[debug] c.a.e.s.d.BeanDescriptorManager - BeanPersistControllers[0] BeanFinders[0] BeanPersistListeners[0] BeanQueryAdapters[0]

[info] c.a.e.s.d.BeanDescriptorManager - Entities enhanced[16] subclassed[0]

[debug] j.m.mbeanserver - ObjectName = Ebean:server=default3,key=AutoFetch

[debug] j.m.mbeanserver - name = Ebean:server=default3,key=AutoFetch

[debug] j.m.mbeanserver - Send create notification of object Ebean:key=AutoFetch,server=default3

[debug] j.m.mbeanserver - JMX.mbean.registered Ebean:server=default3,key=AutoFetch

[debug] o.r.Reflections - going to scan these urls:

        jar:file:/home/eanichini/myapp-5-SNAPSHOT/lib/myapp.myapp-5-SNAPSHOT.jar!/

[info] o.r.Reflections - Reflections took 2 ms to scan 1 urls, producing 4 keys and 4 values

[info] c.a.e.s.c.DefaultServerFactory - DatabasePlatform name:classdb platform:mysql

[debug] c.a.e.a.ClassLoadContext - Context and Caller ClassLoader's same instance of sun.misc.Launcher$AppClassLoader

[debug] c.a.e.s.t.DefaultTypeManager - Registering Joda data types

[debug] c.a.e.s.d.BeanDescriptorManager - BeanPersistControllers[0] BeanFinders[0] BeanPersistListeners[0] BeanQueryAdapters[0]

[info] c.a.e.s.d.BeanDescriptorManager - Entities enhanced[1] subclassed[0]

[debug] j.m.mbeanserver - ObjectName = Ebean:server=classdb4,key=AutoFetch

[debug] j.m.mbeanserver - name = Ebean:server=classdb4,key=AutoFetch

[debug] j.m.mbeanserver - Send create notification of object Ebean:key=AutoFetch,server=classdb4

[debug] j.m.mbeanserver - JMX.mbean.registered Ebean:server=classdb4,key=AutoFetch

[debug] c.j.b.StatementHandle - select id, hash, apply_script, revert_script, state, last_problem from play_evolutions where state like 'applying_%'

[debug] c.j.b.StatementHandle -

            select id, hash, apply_script, revert_script from play_evolutions order by id

[debug] n.s.e.c.ConfigurationFactory - Configuring ehcache from URL: jar:file:/home/eanichini/myapp-5-SNAPSHOT/lib/com.typesafe.play.play-cache_2.10-2.2.3.jar!/ehcache-default.xml

[debug] n.s.e.c.ConfigurationFactory - Configuring ehcache from InputStream

[debug] n.s.e.c.BeanHandler - Ignoring ehcache attribute xmlns:xsi

[debug] n.s.e.c.BeanHandler - Ignoring ehcache attribute xsi:noNamespaceSchemaLocation

[debug] n.s.e.CacheManager - Creating new CacheManager with config URL: jar:file:/home/eanichini/myapp-5-SNAPSHOT/lib/com.typesafe.play.play-cache_2.10-2.2.3.jar!/ehcache-default.xml

[debug] n.s.e.u.PropertyUtil - propertiesString is null.

[debug] n.s.e.c.ConfigurationHelper - No CacheManagerEventListenerFactory class specified. Skipping...

[debug] n.s.e.Cache - No BootstrapCacheLoaderFactory class specified. Skipping...

[debug] n.s.e.Cache - CacheWriter factory not configured. Skipping...

[debug] n.s.e.c.ConfigurationHelper - No CacheExceptionHandlerFactory class specified. Skipping...

[debug] n.s.e.s.MemoryStore - Initialized net.sf.ehcache.store.NotifyingMemoryStore for play

[debug] n.s.e.Cache - Initialised cache: play

[debug] n.s.e.c.ConfigurationHelper - CacheDecoratorFactory not configured for defaultCache. Skipping for 'play'.

[info] play - Application started (Prod)

12:22:15,306 |-INFO in ch.qos.logback.core.joran.action.ConversionRuleAction - registering conversion word coloredLevel with class [play.api.Logger$ColoredLevel]

12:22:15,306 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.FileAppender]

12:22:15,306 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE]

12:22:15,307 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property

12:22:15,307 |-INFO in ch.qos.logback.core.FileAppender[FILE] - File property is set to [/home/eanichini/myapp-5-SNAPSHOT/logs/application.log]

12:22:15,307 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]

12:22:15,307 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]

12:22:15,307 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property

12:22:15,308 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [play] to INFO

12:22:15,308 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [application] to INFO

12:22:15,308 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO

12:22:15,308 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[ROOT]

12:22:15,308 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]

12:22:15,308 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.

12:22:15,308 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@49bd54f7 - Registering current configuration as safe fallback point

[info] play - Listening for HTTP on /0:0:0:0:0:0:0:0:9000

[Emiliano Anichini]

SOLVED!

I turned all my Logger.debug(...) into Logger.info(...), untouching the application.conf file and now works with play dist too.