You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomee.apache.org by BobbyBear <rc...@hotmail.com> on 2014/03/21 21:39:47 UTC
log4j2 initialized too early?
It seems like log4j2 is being initialized too early. This is a problem
because we rely on the application server context for various logging
configuration values.
What I see is this:
Mar 21, 2014 4:26:40 PM
org.apache.openejb.assembler.classic.ReloadableEntityManagerFactory
createDelegate
INFO: PersistenceUnit(name=PlayMap,
provider=org.apache.openjpa.persistence.PersistenceProviderImpl) - provider
time 232ms
2014-03-21 16:26:41,180 DEBUG Generated plugins in 0.000022000 seconds
2014-03-21 16:26:41,189 DEBUG Found Plugin Map at
jar:file:/Users/Bob/apache-tomcat-7.0.52/wtpwebapps/PlayMap/WEB-INF/lib/log4j-core-2.0-rc1.jar!/org/apache/logging/log4j/core/config/plugins/Log4j2Plugins.dat
2014-03-21 16:26:41,379 DEBUG Generated plugins in 0.198293000 seconds
2014-03-21 16:26:41,469 DEBUG Generated plugins in 0.088339000 seconds
2014-03-21 16:26:41,472 DEBUG Calling createLayout on class
org.apache.logging.log4j.core.layout.PatternLayout for element PatternLayout
with params(pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n",
Configuration(/Users/Bob/apache-tomcat-7.0.52/wtpwebapps/TRSMapp/WEB-INF/classes/log4j2.xml),
null, charset="null", alwaysWriteExceptions="null", noConsoleNoAnsi="null")
2014-03-21 16:26:41,564 DEBUG Generated plugins in 0.090932000 seconds
DEBUG statements show log4j2 initializing somewhere along the openjpa start.
Later on we see this:
Mar 21, 2014 4:26:42 PM org.apache.openejb.assembler.classic.Assembler
createApplication
INFO: Deployed
Application(path=/Users/Bob/apache-tomcat-7.0.52/wtpwebapps/PlayMap)
Mar 21, 2014 4:26:42 PM org.apache.catalina.core.ApplicationContext log
INFO: Log4jServletContextListener ensuring that Log4j starts up properly.
Without tomee, log4j2 works fine and the DEBUG statements are seen right
after the INFO statement above. So there is some difference in loading.
Note that I'm using log4j2, not log4j. Also, I'm using a fairly recent local
build which works on tomcat-7.0.52
Has anyone gotten log4j2 with the WebLookups, "${web:contextPath}" for
example, from the servletContext to work?
--
View this message in context: http://openejb.979440.n4.nabble.com/log4j2-initialized-too-early-tp4668307.html
Sent from the OpenEJB User mailing list archive at Nabble.com.
Re: log4j2 initialized too early?
Posted by Romain Manni-Bucau <rm...@gmail.com>.
Actually you can but not while log4j2 web integration is this one. They can
rely on a tomcat listener to get it working.
Le 5 avr. 2014 17:01, "BobbyBear" <rc...@hotmail.com> a écrit :
>
> i'm fine with option [3], i didn't realize you shouldn't (can't) use static
> loggers in EJBs.
>
> not looking to create work for something that shouldn't be done.
>
>
>
>
>
> --
> View this message in context:
> http://openejb.979440.n4.nabble.com/log4j2-initialized-too-early-tp4668307p4668609.html
> Sent from the OpenEJB User mailing list archive at Nabble.com.
>
Re: log4j2 initialized too early?
Posted by BobbyBear <rc...@hotmail.com>.
i'm fine with option [3], i didn't realize you shouldn't (can't) use static
loggers in EJBs.
not looking to create work for something that shouldn't be done.
--
View this message in context: http://openejb.979440.n4.nabble.com/log4j2-initialized-too-early-tp4668307p4668609.html
Sent from the OpenEJB User mailing list archive at Nabble.com.
Re: log4j2 initialized too early?
Posted by Romain Manni-Bucau <rm...@gmail.com>.
Ok go it
log4J uses a servlet container initialzer to get web info which is of
course initialized after openejb part of tomee and ejb are scanned (so
loaded) before.
You can consider this issue from several point of view:
1) this is an openejb issue which shouldn't load classes before -> if
we fix it we loose so much control of the apps that ears will be
totally broken and potentially a lot of wars too. (I dont get too much
into details here but I'm really -1 for it + wouldnt be before 1-2
months I guess since needs advanced changes)
2) this is a log4j issue -> log4j could use some tomcat internals (or
jmx) to get the info too I think
3) not a reall issue since you can not use static loggers
Romain Manni-Bucau
Twitter: @rmannibucau
Blog: http://rmannibucau.wordpress.com/
LinkedIn: http://fr.linkedin.com/in/rmannibucau
Github: https://github.com/rmannibucau
2014-04-05 1:54 GMT+02:00 BobbyBear <rc...@hotmail.com>:
> I have a small eclipse project at
>
> https://github.com/rcasazza/TestLog4j2
>
> which shows the issue.
>
> DaBean is a Stateless EJB with a property called "logger" which is
> initialized to log4j2.
>
> There are two lines which allow me to initialize it in two different ways:
>
> [1] initializing it with "static" creates a log file called
> ".${web:contextPath}.log" which is incorrect
>
> [2] initializing it without "static" create a log file called
> "TestLog4j2.log" which is correct
>
> I am using tomcat 7.0.53 but have seen the behavior with 7.0.52 as well. I
> pulled the latest trunk for tomee to see if the issue has gone away, but it
> has not.
>
> By creating a war for each scenario and deploying, starting and stopping in
> tomcat/bin... you will see the log files created there upon startup.
>
>
>
>
>
> --
> View this message in context: http://openejb.979440.n4.nabble.com/log4j2-initialized-too-early-tp4668307p4668598.html
> Sent from the OpenEJB User mailing list archive at Nabble.com.
Re: log4j2 initialized too early?
Posted by BobbyBear <rc...@hotmail.com>.
I have a small eclipse project at
https://github.com/rcasazza/TestLog4j2
which shows the issue.
DaBean is a Stateless EJB with a property called "logger" which is
initialized to log4j2.
There are two lines which allow me to initialize it in two different ways:
[1] initializing it with "static" creates a log file called
".${web:contextPath}.log" which is incorrect
[2] initializing it without "static" create a log file called
"TestLog4j2.log" which is correct
I am using tomcat 7.0.53 but have seen the behavior with 7.0.52 as well. I
pulled the latest trunk for tomee to see if the issue has gone away, but it
has not.
By creating a war for each scenario and deploying, starting and stopping in
tomcat/bin... you will see the log files created there upon startup.
--
View this message in context: http://openejb.979440.n4.nabble.com/log4j2-initialized-too-early-tp4668307p4668598.html
Sent from the OpenEJB User mailing list archive at Nabble.com.
Re: log4j2 initialized too early?
Posted by BobbyBear <rc...@hotmail.com>.
ok, pulled trunk 3/24 and built locally. issue has gone away. sorry, i
should have checked latest and greatest.
thanks
--
View this message in context: http://openejb.979440.n4.nabble.com/log4j2-initialized-too-early-tp4668307p4668332.html
Sent from the OpenEJB User mailing list archive at Nabble.com.
Re: log4j2 initialized too early?
Posted by Romain Manni-Bucau <rm...@gmail.com>.
didnt manage to reproduce your issue on trunk
classloader is correct.
static should be fine. Called twice but fine.
Romain Manni-Bucau
Twitter: @rmannibucau
Blog: http://rmannibucau.wordpress.com/
LinkedIn: http://fr.linkedin.com/in/rmannibucau
Github: https://github.com/rmannibucau
2014-03-22 1:14 GMT+01:00 BobbyBear <rc...@hotmail.com>:
>
> ok, it took me a bit but i've learned more from creating a minimal example.
>
> i now am not sure if this is actually an issue or not.
>
> the problem occurs when you create a static logger within an EJB class, in
> my case a Stateless EJB:
>
> ex:
>
> @Stateless
> public class SillyBean {
> static final Logger logger = LogManager.getLogger();
> .
> .
> .
>
> However, the problem goes away when you change this to not be static:
>
> @Stateless
> public class SillyBean {
> final Logger logger = LogManager.getLogger();
> .
> .
> .
>
> I admit, I don't know whether you *SHOULD* be able to create a static logger
> in an EJB... so I'm not sure if this is a problem or not. What do you think?
>
>
>
>
>
>
> --
> View this message in context: http://openejb.979440.n4.nabble.com/log4j2-initialized-too-early-tp4668307p4668313.html
> Sent from the OpenEJB User mailing list archive at Nabble.com.
Re: log4j2 initialized too early?
Posted by BobbyBear <rc...@hotmail.com>.
ok, it took me a bit but i've learned more from creating a minimal example.
i now am not sure if this is actually an issue or not.
the problem occurs when you create a static logger within an EJB class, in
my case a Stateless EJB:
ex:
@Stateless
public class SillyBean {
static final Logger logger = LogManager.getLogger();
.
.
.
However, the problem goes away when you change this to not be static:
@Stateless
public class SillyBean {
final Logger logger = LogManager.getLogger();
.
.
.
I admit, I don't know whether you *SHOULD* be able to create a static logger
in an EJB... so I'm not sure if this is a problem or not. What do you think?
--
View this message in context: http://openejb.979440.n4.nabble.com/log4j2-initialized-too-early-tp4668307p4668313.html
Sent from the OpenEJB User mailing list archive at Nabble.com.
Re: log4j2 initialized too early?
Posted by BobbyBear <rc...@hotmail.com>.
yes, i will create a very small example
--
View this message in context: http://openejb.979440.n4.nabble.com/log4j2-initialized-too-early-tp4668307p4668312.html
Sent from the OpenEJB User mailing list archive at Nabble.com.
Re: log4j2 initialized too early?
Posted by Romain Manni-Bucau <rm...@gmail.com>.
can you share a project show it with a readme.txt showing what you expect?
Romain Manni-Bucau
Twitter: @rmannibucau
Blog: http://rmannibucau.wordpress.com/
LinkedIn: http://fr.linkedin.com/in/rmannibucau
Github: https://github.com/rmannibucau
2014-03-21 22:54 GMT+01:00 BobbyBear <rc...@hotmail.com>:
>
> Yes, I pulled the 1.6.1 snapshot on 3/1/14 and built locally
>
>
>
>
>
>
>
> --
> View this message in context: http://openejb.979440.n4.nabble.com/log4j2-initialized-too-early-tp4668307p4668310.html
> Sent from the OpenEJB User mailing list archive at Nabble.com.
Re: log4j2 initialized too early?
Posted by BobbyBear <rc...@hotmail.com>.
Yes, I pulled the 1.6.1 snapshot on 3/1/14 and built locally
--
View this message in context: http://openejb.979440.n4.nabble.com/log4j2-initialized-too-early-tp4668307p4668310.html
Sent from the OpenEJB User mailing list archive at Nabble.com.
Re: log4j2 initialized too early?
Posted by Romain Manni-Bucau <rm...@gmail.com>.
Hi
do you use 1.6.1-SNAPSHOT?
Romain Manni-Bucau
Twitter: @rmannibucau
Blog: http://rmannibucau.wordpress.com/
LinkedIn: http://fr.linkedin.com/in/rmannibucau
Github: https://github.com/rmannibucau
2014-03-21 21:39 GMT+01:00 BobbyBear <rc...@hotmail.com>:
>
> It seems like log4j2 is being initialized too early. This is a problem
> because we rely on the application server context for various logging
> configuration values.
>
> What I see is this:
>
> Mar 21, 2014 4:26:40 PM
> org.apache.openejb.assembler.classic.ReloadableEntityManagerFactory
> createDelegate
> INFO: PersistenceUnit(name=PlayMap,
> provider=org.apache.openjpa.persistence.PersistenceProviderImpl) - provider
> time 232ms
> 2014-03-21 16:26:41,180 DEBUG Generated plugins in 0.000022000 seconds
> 2014-03-21 16:26:41,189 DEBUG Found Plugin Map at
> jar:file:/Users/Bob/apache-tomcat-7.0.52/wtpwebapps/PlayMap/WEB-INF/lib/log4j-core-2.0-rc1.jar!/org/apache/logging/log4j/core/config/plugins/Log4j2Plugins.dat
> 2014-03-21 16:26:41,379 DEBUG Generated plugins in 0.198293000 seconds
> 2014-03-21 16:26:41,469 DEBUG Generated plugins in 0.088339000 seconds
> 2014-03-21 16:26:41,472 DEBUG Calling createLayout on class
> org.apache.logging.log4j.core.layout.PatternLayout for element PatternLayout
> with params(pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n",
> Configuration(/Users/Bob/apache-tomcat-7.0.52/wtpwebapps/TRSMapp/WEB-INF/classes/log4j2.xml),
> null, charset="null", alwaysWriteExceptions="null", noConsoleNoAnsi="null")
> 2014-03-21 16:26:41,564 DEBUG Generated plugins in 0.090932000 seconds
>
> DEBUG statements show log4j2 initializing somewhere along the openjpa start.
>
> Later on we see this:
>
> Mar 21, 2014 4:26:42 PM org.apache.openejb.assembler.classic.Assembler
> createApplication
> INFO: Deployed
> Application(path=/Users/Bob/apache-tomcat-7.0.52/wtpwebapps/PlayMap)
> Mar 21, 2014 4:26:42 PM org.apache.catalina.core.ApplicationContext log
> INFO: Log4jServletContextListener ensuring that Log4j starts up properly.
>
> Without tomee, log4j2 works fine and the DEBUG statements are seen right
> after the INFO statement above. So there is some difference in loading.
>
> Note that I'm using log4j2, not log4j. Also, I'm using a fairly recent local
> build which works on tomcat-7.0.52
>
> Has anyone gotten log4j2 with the WebLookups, "${web:contextPath}" for
> example, from the servletContext to work?
>
>
>
>
>
> --
> View this message in context: http://openejb.979440.n4.nabble.com/log4j2-initialized-too-early-tp4668307.html
> Sent from the OpenEJB User mailing list archive at Nabble.com.