log4j блокирует поток

Tomcat-6 крутится на windows server 2016, на нем развернуто веб-приложение, для логирования использован Log4j 1.2.8.

По прошествию какого-то времени, один из http-* потоков может зависнуть, блокируя исполнение всего приложения. Через какое-то время, исполнение может продолжиться само по себе.

Как показал дамп снятый с потоков - зависает что-то связаное с логированием, зависший поток заходит в Category.callAppenders(), проходит через синхронные методы и застревает. Тем самым препятствуя вхождению других потоков в те-же синхронные методы логгера. Логгер работает синхронно, и следовательно пока первый поток не выйдет - все остальные работать не могут...

Интересно что данный апендер и не должен писать в файлик, он для консоли. Судя по трейсу в файлик пытается писать служба логирования встроеная в томкэт SystemLogHandler, видимо по какому-то ивенту.

Вот стактрейс зависшего потока:

Name: http-8443-13
State: RUNNABLE
Total blocked: 643  Total waited: 188
Stack trace:
java.io.FileOutputStream.writeBytes(Native Method)
java.io.FileOutputStream.write(FileOutputStream.java:345)
java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
- locked java.io.BufferedOutputStream@3ecd1bdf
java.io.PrintStream.write(PrintStream.java:482)
- locked java.io.PrintStream@be0edaf
org.apache.tomcat.util.log.SystemLogHandler.write(SystemLogHandler.java:166)
sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:295)
sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141)
- locked java.io.OutputStreamWriter@5c148240
java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)
org.apache.log4j.helpers.QuietWriter.flush(QuietWriter.java:49)
org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:306)
org.apache.log4j.WriterAppender.append(WriterAppender.java:150)
org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221)
- locked org.apache.log4j.ConsoleAppender@1c7cb305
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:57)
org.apache.log4j.Category.callAppenders(Category.java:187)
- locked org.apache.log4j.Logger@467366fa
org.apache.log4j.Category.forcedLog(Category.java:372)
org.apache.log4j.Category.info(Category.java:674)
kz.nat.museum.server.log.Logging.afterInsert(Logging.java:64)
kz.nat.museum.server.security.event.PostInsertListener.onPostInsert(PostInsertListener.java:19)
org.hibernate.action.EntityIdentityInsertAction.postInsert(EntityIdentityInsertAction.java:90)
org.hibernate.action.EntityIdentityInsertAction.execute(EntityIdentityInsertAction.java:66)
org.hibernate.engine.ActionQueue.execute(ActionQueue.java:250)
org.hibernate.event.def.AbstractSaveEventListener.performSaveOrReplicate(AbstractSaveEventListener.java:298)
org.hibernate.event.def.AbstractSaveEventListener.performSave(AbstractSaveEventListener.java:181)
org.hibernate.event.def.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:107)
org.hibernate.ejb.event.EJB3MergeEventListener.saveWithGeneratedId(EJB3MergeEventListener.java:43)
org.hibernate.event.def.DefaultMergeEventListener.entityIsTransient(DefaultMergeEventListener.java:186)
org.hibernate.event.def.DefaultMergeEventListener.onMerge(DefaultMergeEventListener.java:123)
org.hibernate.event.def.DefaultMergeEventListener.onMerge(DefaultMergeEventListener.java:53)
org.hibernate.impl.SessionImpl.fireMerge(SessionImpl.java:677)
org.hibernate.impl.SessionImpl.merge(SessionImpl.java:661)
org.hibernate.impl.SessionImpl.merge(SessionImpl.java:665)
org.hibernate.ejb.AbstractEntityManagerImpl.merge(AbstractEntityManagerImpl.java:228)
kz.nat.museum.server.base.db.DBManager.write(DBManager.java:421)
kz.nat.museum.server.base.db.DBManager.writeC(DBManager.java:451)
kz.nat.museum.server.inventory.InventoryModuleServiceImpl.writeInvActAcceptance(InventoryModuleServiceImpl.java:847)
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:606)
com.google.gwt.user.server.rpc.RPC.invokeAndEncodeResponse(RPC.java:561)
com.google.gwt.user.server.rpc.RemoteServiceServlet.processCall(RemoteServiceServlet.java:208)
com.google.gwt.user.server.rpc.RemoteServiceServlet.processPost(RemoteServiceServlet.java:248)
com.google.gwt.user.server.rpc.AbstractRemoteServiceServlet.doPost(AbstractRemoteServiceServlet.java:62)
javax.servlet.http.HttpServlet.service(HttpServlet.java:710)
kz.nat.museum.server.base.ProtectedModuleService.service(ProtectedModuleService.java:30)
- locked kz.nat.museum.server.inventory.InventoryModuleServiceImpl@14cf6c11
javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
kz.nat.museum.server.security.AuthorizationFilter.doFilter(AuthorizationFilter.java:189)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:230)
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175)
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:433)
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:104)
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:261)
org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:844)
org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:581)
org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
java.lang.Thread.run(Thread.java:724)

а вот след одного из тех что он заблокировал:

Name: http-8443-17  State: BLOCKED on org.apache.log4j.ConsoleAppender@1c7cb305 owned by: http-8443-13
        Total blocked: 500  Total waited: 163
        Stack trace:
        org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:201)
        org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:57)
        org.apache.log4j.Category.callAppenders(Category.java:187)
        - locked org.apache.log4j.spi.RootCategory@45f9f1f7
        org.apache.log4j.Category.forcedLog(Category.java:372)
        org.apache.log4j.Category.log(Category.java:864)
        sun.reflect.GeneratedMethodAccessor25.invoke(Unknown Source)
        sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        java.lang.reflect.Method.invoke(Method.java:606)
        org.apache.commons.logging.impl.Log4jProxy.log(Log4jProxy.java:288)
        org.apache.commons.logging.impl.Log4jProxy.debug(Log4jProxy.java:235)
        org.apache.commons.logging.impl.Log4JLogger.debug(Log4JLogger.java:84)
        org.hibernate.impl.SessionImpl.<init>(SessionImpl.java:220)

Может кто-то сталкивался с чем-то подобным? Или знает какой-то способ отменить операцию на которой завис поток...

Спасибо!

eddit 30.03.2019

log4j.xml:

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<!-- ===================================================================== -->
<!--                                                                       -->
<!--  Log4j Configuration                                                  -->
<!--                                                                       -->
<!-- ===================================================================== -->
<!-- $Id: log4j.xml,v 1.26.2.10 2006/04/21 17:29:20 csuconic Exp $ -->
<!--
   | For more configuration infromation and examples see the Jakarta Log4j
   | owebsite: http://jakarta.apache.org/log4j
 -->

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" debug="false">

    <!-- ================================= -->
    <!-- Preserve messages in a local file -->
    <!-- ================================= -->
    <!-- A time/date based rolling appender -->
    <appender name="FILE" class="org.apache.log4j.RollingFileAppender">
        <param name="Encoding" value="UTF-8" />
        <param name="File" value="${catalina.home}/logs/server.log"/>
        <param name="Append" value="true"/>
        <param name="MaxFileSize" value="100MB"/>
        <param name="MaxBackupIndex" value="10"/>
        <param name="Threshold" value="INFO"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d %-5p [%c] %m%n"/>
        </layout>
    </appender>

    <!-- ============================== -->
    <!-- Append messages to the console -->
    <!-- ============================== -->
    <appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
        <param name="Target" value="System.out"/>
        <param name="Threshold" value="INFO"/>
        <layout class="org.apache.log4j.PatternLayout">
            <!-- The default pattern: Date Priority [Category] Message\n -->
            <param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%c{1}] %m%n"/>
        </layout>
    </appender>
    <!-- ============================== -->
    <!-- Append museum messages to the server.mus-->
    <!-- ============================== -->
    <appender name="MUSEUM" class="org.apache.log4j.RollingFileAppender">
        <param name="Encoding" value="UTF-8" />
        <param name="File" value="${catalina.home}/logs/museum.log"/>
        <param name="Append" value="true"/>
        <param name="MaxFileSize" value="100MB"/>
        <param name="MaxBackupIndex" value="10"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d %-5p [%c] %m%n"/>
        </layout>
    </appender>
    <!-- Limit the org.apache category to INFO as its DEBUG is verbose -->
    <category name="org.apache">
        <priority value="INFO"/>
    </category>
    <category name="org.apache.catalina">
        <priority value="INFO"/>
    </category>

    <category name="Museum" additivity="false">
        <param name="Encoding" value="UTF-8" />
        <priority value="INFO"/>
        <appender-ref ref="MUSEUM"/>
        <appender-ref ref="CONSOLE"/>
    </category>
    <!-- ======================= -->
    <!-- Setup the Root category -->
    <!-- ======================= -->
    <root>
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="FILE"/>
    </root>
</log4j:configuration>

logging.properties:

handlers = 1catalina.org.apache.juli.FileHandler, 2localhost.org.apache.juli.FileHandler, 3manager.org.apache.juli.FileHandler, 4admin.org.apache.juli.FileHandler, 5host-manager.org.apache.juli.FileHandler, java.util.logging.ConsoleHandler
.handlers = 1catalina.org.apache.juli.FileHandler, java.util.logging.ConsoleHandler
############################################################
# Handler specific properties.
# Describes specific configuration info for Handlers.
############################################################
1catalina.org.apache.juli.FileHandler.level = FINE
1catalina.org.apache.juli.FileHandler.directory = ${catalina.base}/logs
1catalina.org.apache.juli.FileHandler.prefix = catalina.
2localhost.org.apache.juli.FileHandler.level = FINE
2localhost.org.apache.juli.FileHandler.directory = ${catalina.base}/logs
2localhost.org.apache.juli.FileHandler.prefix = localhost.
3manager.org.apache.juli.FileHandler.level = FINE
3manager.org.apache.juli.FileHandler.directory = ${catalina.base}/logs
3manager.org.apache.juli.FileHandler.prefix = manager.
4admin.org.apache.juli.FileHandler.level = FINE
4admin.org.apache.juli.FileHandler.directory = ${catalina.base}/logs
4admin.org.apache.juli.FileHandler.prefix = admin.
5host-manager.org.apache.juli.FileHandler.level = FINE
5host-manager.org.apache.juli.FileHandler.directory = ${catalina.base}/logs
5host-manager.org.apache.juli.FileHandler.prefix = host-manager.
java.util.logging.ConsoleHandler.level = FINE
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter

############################################################
# Facility specific properties.
# Provides extra control for each logger.
############################################################
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].level = INFO
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].handlers = 2localhost.org.apache.juli.FileHandler
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/manager].level = INFO
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/manager].handlers = 3manager.org.apache.juli.FileHandler
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/admin].level = INFO
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/admin].handlers = 4admin.org.apache.juli.FileHandler
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/host-manager].level = INFO
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/host-manager].handlers = 5host-manager.org.apache.juli.FileHandler
# For example, set the com.xyz.foo logger to only log SEVERE
# messages:
#org.apache.catalina.startup.ContextConfig.level = FINE
#org.apache.catalina.startup.HostConfig.level = FINE
#org.apache.catalina.session.ManagerBase.level = FINE
#org.apache.catalina.core.AprLifecycleListener.level=FINE

eddit 10.04.2019 : 16:17

Выключение вывода в консоль приложением поправило ситуацию, но некоторые необработанные ошибки продолжали попадать в консоль из-за logging.properties, из-за чего произошло новое зависание, уже в другом месте. попробую полностью выключить вывод в консоль полностью как написано

Отдельное спасибо @defaultlocale за нахождение этого и этого постов.