[
https://issues.apache.org/jira/browse/LOG4J2-938?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Mauro Molinari updated LOG4J2-938:
----------------------------------
Attachment: LOG4J2-938.patch
Here is my patch. It was not so trivial, so let's explain what I've done.
{{Server}} doesn't use an only {{ExecutorService}} any more, but rather one for
each logger context on each {{MBeanServer}} it is registered. So, a static
{{Map<MBeanServer, Map<String, ExecutorService>>}} is managed by {{Server}}
({{String}} because the class is using the context name as a unique key to the
logger context).
This said, {{reregisterMBeansAfterReconfigure(MBeanServer)}} method creates the
{{ExecutorService}} and puts it in the map before passing it to the
{{LoggerContextAdmin}} instance it creates.
On the other hand, {{unregisterLoggerContext(String, MBeanServer)}}, which is
correctly called on logger context shutdown, retrieves the {{ExecutorService}}
from the map (if it exists) and shuts it down, cleaning up the map itself if
needed.
However, what I observe is that, depending on the logging configuration, my
webapp can still invoke Log4j2 after the logger context has been shut down,
causing a new one to be created. When this happens and JMX is enabled and used
(with JConsole or VisualVM, for instance), I observe two events:
- an MBean re-registration is invoked
({{org.apache.logging.log4j.core.jmx.Server.reregisterMBeansAfterReconfigure(MBeanServer)}})
- a call to
{{org.apache.logging.log4j.core.jmx.StatusLoggerAdmin.log(StatusData)}} is made
The first event would cause a new {{ExecutorService}} to be created and put in
the map, after the previous shutdown event. To prevent this, I wrapped the
{{ExecutorService}} into a "LazyExecutorService", which delegates to a real
{{ExecutorService}} which is however created lazily, i.e. *only* when a task is
actually submitted. In this way, even if a {{LazyExecutorService}} instance is
created, no actual {{ExecutorService}} is created and then no non-daemon thread
is started unless an actual notification task is submitted.
The second event, which however happens before the above one, causes a task to
be submitted to the executor service even if, meanwhile, that executor service
has been shut down by the {{Server}} class, causing a "task rejected"
exception. To prevent this, I added the method
{{org.apache.logging.log4j.core.jmx.Server.isLoggerContextRegistered(String,
MBeanServer)}} that detects whether a logger context is currently registered on
an MBean server or not; then,
{{org.apache.logging.log4j.core.jmx.StatusLoggerAdmin.log(StatusData)}} checks
if this condition is met and sends notifications only if it is the case. If it
is not, no task is submitted and hence no "task rejected" exception is thrown.
With this patch applied, I can finally stop my web application even without
disabling Log4j2 JMX support.
In theory, there's still a failing use case, if the following sequence of
events occur:
- logger context shutdown
- logger context re-registration
- {{org.apache.logging.log4j.core.jmx.StatusLoggerAdmin.log(StatusData)}}
invocation
In this case, although the use of a {{LazyExecutorService}} a new actual
{{ExecutorService}} would be created, together with its non-daemon thread.
However, this case never occurred in my tests.
To permanently solve all possible cases of re-initialization after Log4j2
shutdown (which by the way often produce error reportings in my console on
webapp stop), you should find a way (if it exists) to make sure that
{{org.apache.logging.log4j.web.Log4jServletContextListener.contextDestroyed(ServletContextEvent)}}
is invoked as the *very last* contextDestroyed event receiver. As of now, it
seems like there's no guarantee on the invocation order of all such receivers,
so another one may be invoked after the Log4j2 one and use Log4j2 itself to
produce further logging output.
Feel free to complete/correct/adjust/comment/change/etc. this patch as you
like. In particular, some synchronization might be required to {{Server}} to
ensure the map of executor services is accessed in a thread safe way. Honestly,
I didn't care of this aspect too much.
> org.apache.logging.log4j.core.jmx.Server never shuts down the ExecutorService
> it creates
> ----------------------------------------------------------------------------------------
>
> Key: LOG4J2-938
> URL: https://issues.apache.org/jira/browse/LOG4J2-938
> Project: Log4j 2
> Issue Type: Bug
> Components: JMX
> Affects Versions: 2.1
> Reporter: Mauro Molinari
> Priority: Critical
> Attachments: LOG4J2-938.patch
>
>
> The class {{org.apache.logging.log4j.core.jmx.Server}} creates an
> {{ExecutorService}} at construction time and and stores it as an instance
> variable of type {{Executor}} (named {{executor}}).
> This executor service is never shut down (I guess the {{unregisterMBeans()}}
> methods may be good candidates, with some care for
> {{unregisterMBeans(MBeanServer)}} which performs unregistration only for a
> single {{MBeanServer}}). This causes a memory leak if Log4j is used in a web
> application (under Tomcat, for instance) and the JMX services have been used
> (i.e.: the {{Server}} class has been instantiated).
> But even worse, what I'm observing is that a notification Job may be
> submitted to that executor by
> {{javax.management.NotificationBroadcasterSupport.sendNotification(Notification)}},
> invoked by
> {{org.apache.logging.log4j.core.jmx.StatusLoggerAdmin.log(StatusData)}} in
> certain circumstances exactly during Tomcat shutdown process: since the
> executor is using non-daemon threads to execute tasks, this eventually
> prevents the application server to shutdown (I have to kill it).
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
