Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Already on GitHub? Sign in to your account

Play logger is in conflict with JBoss one #54

Closed
dlecan opened this Issue Jun 15, 2012 · 37 comments

Comments

Projects
None yet
6 participants
Owner

dlecan commented Jun 15, 2012

As soon as Play core engine is started, JBoss logs are disabled.

Owner

dlecan commented Jun 15, 2012

Remove <root level="INFO"> section in logger.xml ?

Owner

dlecan commented Jun 15, 2012

sejensen commented Jul 4, 2012

Hi everyone

Does this mean that we will not be able to log from within our play2 war app on jboss?

Is there any timeframe for when this will be solved. An application without a log is not suited for customers.

Building our own log to database seems silly

Kind regards
Steffen

Owner

dlecan commented Jul 4, 2012

Does this mean that we will not be able to log from within our play2 war app on jboss?

With Play2War v0.6, i didn't find any correct log configuration yet. Something is wrong between Play logback configuration and JBoss configuration.

As you can read in stackoverflow questions, this might be solved by using a jboss-deployment-structure.xml file embedded in the WAR file.
Play2War v0.7 will allow you to embed automatically such a file, but you can already test this solution by including a jboss-deployment-structure.xml file into the WAR/META-INF folder.

Something like:

<jboss-deployment-structure>
    <deployment>
        <exclusions>
            <module name="org.sl4j" />
            <module name="org.slf4j.impl" />
        </exclusions>
    </deployment>
</jboss-deployment-structure>

sejensen commented Jul 4, 2012

I tried adding the deployment xml file to meta-inf but cannot locate any log files.

In the documentation you mention it will be created in users_home/logs. but that is empty.

standalone/log on jboss do not have any new logfiles and server log do not get log statements from play.

Any ideas?

Thanks
Steffen

Owner

dlecan commented Jul 4, 2012

Did you configure a specific logger.xml for your application ?
As described here: https://github.com/dlecan/play2-war-plugin/#configure-logging

Damien

sejensen commented Jul 4, 2012

Yes I have allready added the logger.xml to conf Should I add anything to application.conf to be able to use it?

And is it also user_home/logs that jboss will use for the log file?

My logger.xml

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

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <pattern>%date - [%level] - from %logger in %thread %n%message%n%xException%n</pattern>
    </encoder>
</appender>

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

<!-- Off these ones as they are annoying, and anyway we manage configuration ourself -->
<logger name="com.avaje.ebean.config.PropertyMapLoader" level="OFF" />
<logger name="com.avaje.ebeaninternal.server.core.XmlConfigLoader" level="OFF" />
<logger name="com.avaje.ebeaninternal.server.lib.BackgroundThread" level="OFF" />

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

dlecan commented Jul 4, 2012

Ok, this is an open bug.
I will look at that in the next weeks.

Damien

@ghost ghost assigned dlecan Aug 9, 2012

The problem is caused by these lines in play.api.Logger.scala:

Option(java.util.logging.Logger.getLogger("")).map { root =>
          root.setLevel(Level.FINEST)
          root.getHandlers.foreach(root.removeHandler(_))
        }

Can be monkeypatched by including a copy in /app/play/api/Logger.scala with these lines left out.

Not sure who should do something about this, but I posted a comment on a related issue here:
https://play.lighthouseapp.com/projects/82401-play-20/tickets/677-play-logger-implementation-configures-slf4j-jul-bridging-in-a-way-that-could-impact-performance#ticket-677-2

Owner

dlecan commented Aug 30, 2012

Thanks for investigating this issue @andersbohn !
Do you know which of the two lines disable JBoss logging ?

  1. root.setLevel(Level.FINEST)
  2. root.getHandlers.foreach(root.removeHandler(_))

Play Logger is under Play2War control, so it can try to reset JUL configuration.
I suspect this piece of code to be responsible for this too : #80

it's 2. - just testet on Redhat jboss-eap-6.0

Owner

dlecan commented Aug 30, 2012

Ok, it means that Play Logger removes a JBoss log handler, and so it explains why all logs disappear.

I can catch JBoss log handler before initializing Play logger, then add it back to the root logger after Play logger initialization.
I don't know if SLF4JBridgeHandler must be kept...

Owner

dlecan commented Aug 31, 2012

@andersbohn I published Play2War 0.8-issue54-SNAPSHOT on https://repository-play-war.forge.cloudbees.com/snapshot/ which :

  • Catch all existing loggers
  • Add them back after Play logger initialization

See cd82124

Can try it and see if your log traces are back ?

I tried adding a resolver for snapshot and changing version to:
addSbtPlugin("com.github.play2war" % "play2-war-plugin" % "0.8-issue54-SNAPSHOT")

But get:
[error] {file:/Users/abj/Projects/energinet/datahub/project/}default-711ba5/*:update: sbt.ResolveException: unresolved dependency: com.github.play2war#play2-war-plugin;0.8-issue54-SNAPSHOT: not found

I have tested the code parts (storing and re-adding) in my Logger.scala monkey patch, and that works ok.

One other thing - the resulting log becomes:
13:15:28,715 INFO [stdout] (play-akka.actor.actions-dispatcher-8) 2012-09-04 13:15:28,715 DEBUG application - logging in ENDK - Miracle Admin

Ie duplicated level, date etc. I haven't found any way to avoid this..

Owner

dlecan commented Sep 4, 2012

I tried adding a resolver for snapshot and changing version to:
addSbtPlugin("com.github.play2war" % "play2-war-plugin" % "0.8-issue54-SNAPSHOT")

Can you post your plugins.sbt file ?

... that works ok.
13:15:28,715 INFO [stdout] (play-akka.actor.actions-dispatcher-8) 2012-09-04 13:15:28,715 DEBUG application - logging in ENDK - Miracle Admin
Ie duplicated level, date etc. I haven't found any way to avoid this..

Play Logback logger logs to a console appender. All logs are then catch by JBoss logging which logs them as any others System.out.print* logs.

13:15:28,715 INFO [stdout] (play-ak...cher-8) 2012-09-04 13:15:28,715 DEBUG application - ... \__________________________/\________________________________________________________________/ . . . JBoss log. . . . . . . . . . . . .. . . . . . . Play log

If you replace console Play logger appender by a file appender, they will be logged as expected (I hope :)

Yes, with file appender, it works fine :)

plugins.sbt with snapshot-modification (and release-0.7.2 settings commented out) :

// Comment to get more information during initialization
logLevel := Level.Warn

// The Typesafe repository 
resolvers += "Typesafe repository" at "http://repo.typesafe.com/typesafe/releases/"

//resolvers += "Play2war plugins release" at "http://repository-play-war.forge.cloudbees.com/release/"
resolvers += "Play2war plugins release" at "http://repository-play-war.forge.cloudbees.com/snapshot/"

// Use the Play sbt plugin for Play projects
addSbtPlugin("play" % "sbt-plugin" % "2.0.2")

//addSbtPlugin("com.github.play2war" % "play2-war-plugin" % "0.7.2")
addSbtPlugin("com.github.play2war" % "play2-war-plugin" % "0.8-issue54-SNAPSHOT")
Owner

dlecan commented Sep 4, 2012

I published new snapshots. Can you try them ?

It builds - when deployed I get:

10:07:54,646 WARN  [org.jboss.as.ee] (MSC service thread 1-4) JBAS011006: Not installing optional component play.core.server.servlet30.AsyncListener due to exception: org.jboss.as.server.deployment.DeploymentUnitProcessingException: JBAS011054: Could not find default constructor for class play.core.server.servlet30.AsyncListener
    at org.jboss.as.ee.component.ComponentDescription$DefaultComponentConfigurator.configure(ComponentDescription.java:606) [jboss-as-ee-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
    at org.jboss.as.ee.component.deployers.EEModuleConfigurationProcessor.deploy(EEModuleConfigurationProcessor.java:83) [jboss-as-ee-7.1.2.Final-redhat-1.jar:7.1.2.Final-redhat-1]
    at org.jboss.as.server.deployment.DeploymentUnitPhaseService.start(DeploymentUnitPhaseService.java:116)
    at org.jboss.msc.service.ServiceControllerImpl$StartTask.startService(ServiceControllerImpl.java:1811)
    at org.jboss.msc.service.ServiceControllerImpl$StartTask.run(ServiceControllerImpl.java:1746)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [classes.jar:1.6.0_33]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [classes.jar:1.6.0_33]
    at java.lang.Thread.run(Thread.java:680) [classes.jar:1.6.0_33]

and no log output.

Owner

dlecan commented Sep 5, 2012

This is another issue, due to #82 (for 0.8). See #85.

I will publish new snapshots, but against 0.7.3 to avoid regressions due to 0.8 work.

Owner

dlecan commented Sep 5, 2012

Ok, I fixed #85, so I'm publishing 0.8 snapshots again
You can try again 0.8-issue54-SNAPSHOT ?

I tried this fix on JBoss 7.0.x, and logs are back !

dlecan added a commit that referenced this issue Sep 5, 2012

@dlecan dlecan closed this in c597fbc Sep 5, 2012

dlecan added a commit that referenced this issue Sep 13, 2012

This was referenced Sep 18, 2012

matgi commented Oct 8, 2012

Hello dlecan i've got a problem with the logger under jboss7.
When i deploy i see that row in server.log of jboss

15:24:11,543 INFO [play](MSC service thread 1-1) Application started (Prod)

means that the logger seems alive.
In my controllers hierarchy i've got a logger "filter" (action composition) who logs some stuff about the request (action name , request data etc...) but these infos didn't appear in the jboss server.log

I use a logger.xml config file and this kind of approach for obtain the logget class:

Logger logger = LoggerFactory.getLogger("FrontEndLogger");

And config file logger xml:

<contextName>AdiuWEB</contextName>


<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <layout class="ch.qos.logback.classic.PatternLayout">
        <pattern>%-4relative [%thread] %-5level %class - %msg%n</pattern>
    </layout>
</appender>

<!--
Basic file appender<appender name="FILE"
class="ch.qos.logback.core.FileAppender">
<layout class="ch.qos.logback.classic.PatternLayout">
<pattern>%-4relative [%thread] %-5level %class - %msg%n</pattern>
</layout>
<File>sample-log.txt</File>
</appender>
-->

<!--Daily rolling file appender -->
<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <File>${application.home}/logs/FronEndLog.log</File>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <FileNamePattern>logFile.%d{yyyy-MM-dd}.log</FileNamePattern>
    </rollingPolicy>

    <layout class="ch.qos.logback.classic.PatternLayout">
        <Pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</Pattern>
    </layout>
</appender>


<logger name="FrontEndLogger">
    <level value="debug" />
</logger>

<root>

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

Do you know how can i solve the problem?
thanx in advice,
Matgi.

Owner

dlecan commented Oct 8, 2012

This feature is not released, which version of play2war are you testing ?
I think you should use Play logging API : Logger logger = Logger("FrontEndLogger") (Scala)
Scala : http://www.playframework.org/documentation/api/2.0/scala/index.html#play.api.Logger$
Java : http://www.playframework.org/documentation/api/2.0/java/play/Logger.html

matgi commented Oct 9, 2012

I tried different approach using play logger but i can't see any logs in the server.log.
So could you explane me can i catch JBoss log handler before initializing Play logger as you did it.

thanx Matgi.

Owner

dlecan commented Oct 9, 2012

So could you explane me can i catch JBoss log handler before initializing Play logger as you did it.

This line is responsible for this issue:
https://github.com/playframework/Play20/blob/master/framework/src/play/src/main/scala/play/api/Logger.scala#L212

When Play server is initialized, you have to catch handlers before and registering them back after.
But you won't be able to do that in your application, as Play2war is reponsible for initializing Play server.

If you really need it, I can think about Play2War v0.7.5 only with this fix.

matgi commented Oct 11, 2012

I tried to test it... but it doesn't work if you are able to solve this it would be great.
Remember that unfortunatly i'm still not able to use the plug in because in give me UNRESOLVED DEPENDENCIES...
So i create ear package with an ANT script. using the library downloaded from
https://play-war.ci.cloudbees.com/job/Play_2_War_-_on_push_-_with_integration_tests_-_on_develop_branch/ws/sample/servlet30/target/

Can it be that also some other handlers have to be reattached and not only the JUL handlers?
I use the file handler in my play app and everything is logged fine. But as soon as I get the message that the PlayServletWrapper is initialised and INFO play Application started (Prod) all logs in the console and in the server.log file of JBOSS stop.

The logs of the play app continue to be appended in the file specified file in logger.xml.

Owner

dlecan commented Oct 19, 2012

Which version of Play2War ?

Can it be that also some other handlers have to be reattached and not only the JUL handlers?

I don't understand.
Handlers are JUL handlers (java.util.logging.Handler), they can't be anything else. Look at what Play does :
https://github.com/dlecan/Play20/blob/2.0.x/framework/src/play/src/main/scala/play/api/Logger.scala#L212

I use the file handler in my play app

Do you mean file appender ?

I think you should open a new issue, as several people have verified that this one.

Owner

dlecan commented Dec 14, 2012

@andersbohn @sejensen @matgi Cohabitation between JBoss logging and Play logger is very bad and will generate new bugs again and again.

So I would like to disable internal Play logger: all Play logging statements would be redirected to server application logging framework. Internal logger.xml would be useless and Play logging configuration might be done through app server logging configuration.

This feature would be enabled by adding a new dependency in the project.

What do you think of this ?

matgi commented Dec 14, 2012

I think is a good solution. I'm looking forward to see this logging system working...
This is the only open bug in our "play applications" installed under JBoss 7.
thank you very much, I really appreciate it!
Matgi.

Owner

dlecan commented Dec 27, 2012

Hi guys,

Here is a new dependency to include in your project to disable Play Logger:

val appDependencies = Seq(
  // ... Actual dependencies
  "com.github.play2war.ext" %% "redirect-playlogger" % "1.0.1" // add this after your others dependencies
)

How does it work ?
Play logger configuration is disabled, that is to say project's logger.xml file will be ignored.
So logs have to be configured by your app server (JBoss for eg.).

Known issue : all Play logs will be output twice.
To fix this, I have to release new versions of Play2War (0.8.2 and 0.9-RC1-1), but I will do this only if you are interested by this new feature.

It is already available for Play 2.0.x and Play 2.1.x and compatible with all Play2war versions.

Owner

dlecan commented Jan 7, 2013

New version 1.0.1 of the dependency:
"com.github.play2war.ext" %% "redirect-playlogger" % "1.0.1"

@dlecan dlecan reopened this Jan 7, 2013

@dlecan dlecan closed this Jan 7, 2013

lalloni commented Oct 22, 2013

This solution is not acceptable for many of us since it effectively leaves our app without logging in production!

I think we could leverage the fact that play uses logback and jboss uses log4j to have 2 separate logging configurations in runtime, so play apps log to logback instances with its own configuration and the rest of jboss logs to its traditional log4j backend.

For this to work we would need to have play apps not messing with JUL configuration, not depending on jboss' logging modules (any of the lot of them), having appropriate dependencies included in war (logback, slf4j-api, log4j-over-slf4j & jcl-over-slf4j), having our apps carrying appropriate logback configuration and finally play2war forwarding some context config to our logback configuration (I've done this in the past using system properties which you can use in logback.xml) such as JBOSS_HOME and/or jboss' instance logging directory so logback can output log files there... only drawback would be that we couldn't redirect JUL to SLF4J since that would mess jboss logging again.

Does this sound reasonable?

Owner

dlecan commented Oct 23, 2013

Does this sound reasonable?

Yes it does. However, I'm not sure to understand what you expect from Play2War.

lalloni commented Oct 23, 2013

First of all I was expecting feedback on my ideas (given you have much more knowledge than me on the matter).

Secondly (which I can help to implement) I think this could be accomplished with a "plugin" like redirect-playlogger which instead of voiding play logging configuration would just initialize logback without messing around with JUL or Log4J settings. Would this work?

Owner

dlecan commented Nov 4, 2013

Would this work?

Yes, it would work. And the good news for you is that you don't need to depend on a Play2war plugin API. "Redirect-playlogger" is not a plugin or an extension. It's just a collection of classes (play.api.Logger Scala class and object) which will supersede play's classes thank to ordered class loading: jars of classes are often loaded in alphabetical order.

So com.github.play2war.ext.redirect-playlogger-xx.jar jar is loaded before play-XX.jar jar in the WAR file (you should anticipate new Play 2.2 com.typesafe.play.**.jar artifacts' name).

lalloni commented Nov 4, 2013

That's exactly what we did at the time and it worked great!

So now we have an independent log file for each play app and another for
jboss' log.

We managed to setup logback so it writes app's log to jboss' logs directory.

There's still the potential problem that if any dependency would use JUL
directly then that logged events would be routed to jboss's log file. This
has not been the case so far.

I believe that JUL initialization by Play should be optional and as soon as
I can make a little spare time I will try to send a PR with this simple
change.

Thanks again for your feedback.
On Nov 4, 2013 9:10 AM, "Damien Lecan" notifications@github.com wrote:

Would this work?

Yes, it would work. And the good news for you is that you don't need to
depend on a Play2war plugin API. "Redirect-playlogger" is not a plugin or
an extension. It's just a collection of classes (play.api.Logger Scala
class and object) which will supersede play's classes thank to ordered
class loading: jars of classes are often loaded in alphabetical order.

So com.github.play2war.ext.redirect-playlogger-xx.jar jar is loaded
before play-XX.jar jar in the WAR file (you should anticipate new Play
2.2 com.typesafe.play.**.jar artifacts' name).


Reply to this email directly or view it on GitHubhttps://github.com/dlecan/play2-war-plugin/issues/54#issuecomment-27680746
.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment