[2.0] PROD mode logging

[scott clasen]

Hey All...What is the procedure for configuring prod mode logging?

For instance if my conf/application.conf  has

###

# Root logger:

logger.root=DEBUG

# Logger used by the framework:

logger.play=DEBUG

# Logger provided to your application:

logger.application=DEBUG

###

I get log output when I  'play run'

but not when I 'play stage && target/start'

Where are the defaults for prod mode set/overridden?

Thanks

[KajMagnus]

Hi Scott  /  Play devs

I'm having the same trouble, and there's a workaround/fix.

(That is, logging works as configured, when I start Play 2 via the "run" command.

However when I start via the stage and dist builds, no log messages are printed.)

1.  The workaround / fix

Comment out the call to Logger.configure, see below:

trait Server {

  // First delete the default log file for a fresh start

  ...

  /*  PROD log level bugfix / workaround: comment out Logger.configure(...).

  This call doesn't specify the "levels" parameter so all log levels are reset.

  Also, this is not the first invokation of Logger.configure, but the 2nd!

  Something is amiss ...

  // Configure the logger for the first time

  Logger.configure(

    Map("application.home" -> applicationProvider.path.getAbsolutePath),

    mode = mode)

  */

2. Debugging

I did some debugging, and it seems Play 2 first configures all loggers correctly (as specified in application.conf).

But then Play 2 configures them again (see above), and then all loggers seems to be reset to some default levels

(e.g. ERROR and INFO) so none of my log messages are displayed.

Here is where Play configures logging the first time:

====================================

object NettyServer {

  ...

  def main(args: Array[String]) {

    ...  createServer(applicationPath).getOrElse(System.exit(-1))  ...

  }

--> calls --> 

class StaticApplication ... {

  val application = new Application(..., Mode.Prod)

   ...

}

--> calls --> 

Application {

  ...

  // Reconfigure logger

  {

    ...

    Logger.configure(

      ...

  ...

}

Here is where Play configures logging the second time:

====================================

/**

 * provides generic server behaviour for Play applications

 */

trait Server {

  // First delete the default log file for a fresh start

  ...

  // Configure the logger for the first time

  Logger.configure(

    Map("application.home" -> applicationProvider.path.getAbsolutePath),

    mode = mode)

3.  No "levels" specified

The *first* call to Logger.configure looks like so:

    Logger.configure(

      Map("application.home" -> path.getAbsolutePath),

      configuration.getConfig("logger").map { loggerConfig =>

        loggerConfig.keys.map {

          case "resource" | "file" | "url" => "" -> null

          case key @ "root" => "ROOT" -> loggerConfig.getString(key, validValues).map(setLevel).get

          case key => key -> loggerConfig.getString(key, validValues).map(setLevel).get

        }.toMap

      }.getOrElse(Map.empty),

      mode)

This sets a certain "levels" parameter to these values:  (for me)

Map(application -> TRACE, app.mailer -> TRACE, app.openid -> TRACE, play -> INFO, ROOT -> DEBUG)

The *second* time the configuration happens, "levels" is not specified (!), so the default value, Map(), is used, and log levels are reset to ERROR or INFO.

  Logger.configure(

    Map("application.home" -> applicationProvider.path.getAbsolutePath),

    mode = mode)

4.  A workaround

Perhaps the second invokation of Logger.configure() is broken?

The comment just above it,  "// Configure the logger for the first time",

is incorrect, anyhow, since it's actually the 2nd call.

Best regards, KajMagnus

[KajMagnus]

(Well perhaps the 1st and 2nd invokations of Logger.configure

simply happen in the wrong order, of course. I wonder why.

My Play 2 version:  (somewat more recent than v.2.0)

commit edc0fadf3ff02ed5c562b15f87726a1ea2cd25b2

Date:   Wed Mar 28 16:32:42 2012 -0400

/KajMagnus

)

[Gustavo Hexsel]

Oh wow, this bit me too. Thanks so much!!!

[KajMagnus]

Hi again Gustavo and others!

I had to comment out one more line, namely the code that deletes the application.log file.

Since the Logger.configure call was already commented out,

the log file was otherwise not recreated. So better not delete it in the first place.

(If there is no log file at all, when Play starts, then it seems the application.log file gets created by the very first and correct call to Logger.configure  -- but that file would be deleted later by the Server class, unless you comment out the delete() call.)

So now my Server class (i.e. git-repo/framework/src/play/src/main/scala/play/core/server/Server.scala) looks like so:

/**

  * provides generic server behaviour for Play applications

  */

 trait Server {

 

   /* [KajMagnus] No don't delete the log file. Since Logger.configure isn't

    * called (just below, after this try block), it seems the log file is never

    * recreated, resulting in no logging at all.  Anyway I'd rather not have

    * Play delete the log file, in case it contains useful info after a crash or

    * something. Better let an OS script rotate logs?

   // First delete the default log file for a fresh start

   try {

     scalax.file.Path(new java.io.File(applicationProvider.path, "logs/application.log")).delete()

   } catch {

     case _ =>

   }

 

    * [KajMagnus] This doesn't specify the "levels" parameter and all log levels

    * are reset to ERROR or INFO. Also, this is not the first invokation of

    * Logger.configure, but the 2nd. Something is amiss ...

   // Configure the logger for the first time

   Logger.configure(

     Map("application.home" -> applicationProvider.path.getAbsolutePath),

     mode = mode)

 

    */

   // Start the main Invoker

   val invoker = Invoker(applicationProvider)

   ...

(Hmm, this doesn't feel like a good long term solution ...)

HTH, KajMagnus

[Magnus Andersson]

Hi

This issue have bitten me as well: http://stackoverflow.com/questions/10768092/akka-scheduling-in-heroku-with-play-2-framework

My problem above proved to be the same problem you describe. Is this reported as a bug or is this simply expected behaviour? How do I configure Logging levels that stick in production? Forking Play to fix it as KajMagnus describe isn't an option in my mind, as I run/develop against Heroku and I don't want maintain my own Play version.

Any takes?

BR Magnus Andersson

[Magnus Andersson]

Hi Ryan

Thanks for the info. I will try that.

/Magnus

Den 24 jul 2012 20:45 skrev "Ryan Brainard" <ryan.b...@gmail.com>:

I ran into this as well and found that removing all logging configuration from application.conf and just using logger.conf instead worked as expected in production mode.

--
You received this message because you are subscribed to the Google Groups "play-framework" group.
To view this discussion on the web visit https://groups.google.com/d/msg/play-framework/-/QnIxt60zOo4J.
To post to this group, send email to play-fr...@googlegroups.com.
To unsubscribe from this group, send email to play-framewor...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/play-framework?hl=en.

[Galder Zamarreño]

+10000 Totally agree with you Travis.

I've just encountered this annoying issue in Play 2.1.0.

Has anyone submitted a bug report on this? If so, can you post the link?

Also, can anyone from the Play team confirm this is a bug?

Cheers,

On Monday, 19 November 2012 20:32:52 UTC+1, Travis Bailey wrote:

I just hit this issue and found this thread.

Wanted to clarify as some of the information didn't seem precise.

Based on thoughts expressed here, I followed the procedures on Play's wiki to set up conf/application-logger.xml:

https://github.com/playframework/Play20/wiki/SettingsLogger

My app is deployed to Heroku and seems to respond to my logging levels here as expected now.

I, like some of the others, don't want to fork play if I can avoid it... so this workaround is more appealing.

Travis

[Laurence Rouesnel]

This seems to be a documentation issue rather than anything else. Using application-logger.xml fixes the problem. Also the link that Travis posted no longer works (https://github.com/playframework/Play20/wiki/SettingsLogger) - although you can still use Google Cached Results.

I believe I read somewhere that the file should be called logger.xml and it caused hours of headache trying to work out what was wrong.

The wiki pages should just be updated.

[Željko Trogrlić]

It is stated in application.conf

[monzonj]

I reported it as a bug.

Even though we can use our own logback xml file to be able to properly log, the build-in logging feature is clearly broken

https://github.com/playframework/Play20/issues/1186

[Shark.Z]

I spent my whole afternoon yesterday looking at this, please fix the ambiguous descriptions in application.conf.

[Michael Slinn]

This bit me too!

Mike

[Todd O'Bryan]

+1.

Also, note that changing it in the default application.conf that gets created when you create a new project *isn't* enough. Some of us have been upgrading with the same application since a time when the description was completely wrong, and as we upgrade to new versions of Play, our application.conf file doesn't get updated with new instructions that fix the old, broken instructions.

In particular, based on this thread, my application.conf file, and people's problems, I *think* the following have all been the intended behavior at some point in Play's evolution:

1. You could change the logging level in the application.conf file and this would affect dev and prod mode.

2. Changing the logging level in the application.conf file affected dev mode, but you had to create your own logger.xml file for prod mode.

3. Changing the logging level in the application.conf file affected dev mode, but you had to create your own application-logger.xml file for prod mode.

And all along, the application.conf skeleton keeps making it sound as if you can just change the settings in there and it works, and it doesn't make any distinction between dev and prod mode.

Can we please identify (a) what the intended behavior of the logging system is, and (b) update the documentation to reflect that, and (c) file bugs that inform people if there is a disconnect between (a) and (b) and the current (or latest released stable) codebase.

Sorry if I'm sounding snippy, but I've been working to get something deployed that parent volunteers have to enter massive amounts of data into before 2000 students arrive at school a week from Tuesday. I'm realizing now what a fool I was to think that my project might work the same in dev and prod mode, but it's very frustrating to discover that after I've worked so hard to get everything working, I now have to work really hard to get everything working again.

And it's not just logging. I'm having trouble with asset paths, too, but I can't tell what's going on because I can't get my application to log anything below the INFO level in prod mode.

OK. After all that screaming and complaining, Play is awesome. Thank you for writing it.

Todd