CODEWITHSUNDEEP
javalog4jlog4j2liferay-6
phantom
phantom

Reputation: 73

getting deadlock with log4j

We are using log4j for logging purposes. We are using log4j 2.x through 1.2 bridge. Due to size of the application, we cannot upgrade to 2.x. Problem we are facing is that at the time of rollover, log4j gets deadlocked and the whole application hangs up. Here are my configuration and thread dump.

<?xml version="1.0"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">
    <appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
        <layout class="org.apache.log4j.EnhancedPatternLayout">
            <param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%t][%c{1}:%L] %m%n" />
        </layout>
    </appender>

    <appender name="FILE" class="org.apache.log4j.rolling.RollingFileAppender">
        <rollingPolicy class="org.apache.log4j.rolling.TimeBasedRollingPolicy">
            <param name="FileNamePattern" value="@liferay.home@/logs/[email protected]@.%d{yyyy-MM-dd}.log" />
        </rollingPolicy>

        <layout class="org.apache.log4j.EnhancedPatternLayout">
            <param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%t][%c{1}:%L] %m%n" />
        </layout>
    </appender>

    <category name="com.browseengine.bobo">
        <priority value="ERROR" />
    </category>

    <root>
        <priority value="INFO" />
        <appender-ref ref="CONSOLE" />
        <appender-ref ref="FILE" />
    </root>
</log4j:configuration>

Thread dump:


Found one Java-level deadlock:
=============================
"http-nio-8080-exec-79":
  waiting to lock monitor 0x000001e77592f9f8 (object 0x00000005c2a7e928, a org.apache.log4j.rolling.RollingFileAppender),
  which is held by "http-nio-8080-exec-2"
"http-nio-8080-exec-2":
  waiting to lock monitor 0x000001e76f9b06f8 (object 0x00000005e6beba58, a java.io.OutputStreamWriter),
  which is held by "http-nio-8080-exec-20"
"http-nio-8080-exec-20":
  waiting to lock monitor 0x000001e77592f9f8 (object 0x00000005c2a7e928, a org.apache.log4j.rolling.RollingFileAppender),
  which is held by "http-nio-8080-exec-2"

Java stack information for the threads listed above:
===================================================
"http-nio-8080-exec-79":
    at org.apache.log4j.rolling.RollingFileAppender.rollover(RollingFileAppender.java:224)
    - waiting to lock <0x00000005c2a7e928> (a org.apache.log4j.rolling.RollingFileAppender)
    at org.apache.log4j.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:353)
    at org.apache.log4j.WriterAppender.append(WriterAppender.java:158)
    at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:112)
    at org.apache.log4j.bridge.AppenderAdapter$Adapter.append(AppenderAdapter.java:59)
    at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:161)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:134)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:125)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:89)
    at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:675)
    at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:633)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:616)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:523)
    at org.apache.logging.log4j.core.config.DefaultReliabilityStrategy.log(DefaultReliabilityStrategy.java:49)
    at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:153)
    at org.apache.log4j.Category.forcedLog(Category.java:316)
    at org.apache.log4j.Category.log(Category.java:557)
    at com.liferay.portal.log.Log4jLogImpl.info(Log4jLogImpl.java:83)
    at com.liferay.portal.kernel.log.LogWrapper.info(LogWrapper.java:123)
    at com.liferay.portal.kernel.log.SanitizerLogWrapper.info(SanitizerLogWrapper.java:140)
    at com.elixir.tango.helium.events.CustomLoginPostAction.run(CustomLoginPostAction.java:69)
    at com.liferay.portal.kernel.events.InvokerAction.run(InvokerAction.java:41)
    at com.liferay.portal.events.EventsProcessorImpl.processEvent(EventsProcessorImpl.java:83)
    at com.liferay.portal.events.EventsProcessorImpl.process(EventsProcessorImpl.java:69)
    at com.liferay.portal.ee.license.EventsProcessorImpl.process(Unknown Source)
    at com.liferay.portal.events.EventsProcessorUtil.process(EventsProcessorUtil.java:40)
    at com.liferay.portal.servlet.MainServlet.loginUser(MainServlet.java:1050)
    at com.liferay.portal.servlet.MainServlet.service(MainServlet.java:510)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:728)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.catalina.filters.HttpHeaderSecurityFilter.doFilter(HttpHeaderSecurityFilter.java:126)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilterChain.doFilter(InvokerFilterChain.java:116)
    at com.liferay.portal.kernel.servlet.BaseFilter.processFilter(BaseFilter.java:169)
    at com.liferay.portal.servlet.filters.uploadservletrequest.UploadServletRequestFilter.processFilter(UploadServletRequestFilter.java:93)
    at com.liferay.portal.kernel.servlet.BaseFilter.doFilter(BaseFilter.java:59)
    at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilterChain.processDoFilter(InvokerFilterChain.java:204)
    at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilterChain.doFilter(InvokerFilterChain.java:109)
    at com.liferay.portal.kernel.servlet.BaseFilter.processFilter(BaseFilter.java:169)
    at com.liferay.portal.servlet.filters.strip.StripFilter.processFilter(StripFilter.java:361)
    at com.liferay.portal.kernel.servlet.BaseFilter.doFilter(BaseFilter.java:59)
    at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilterChain.processDoFilter(InvokerFilterChain.java:204)
    at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilterChain.doFilter(InvokerFilterChain.java:109)
    at com.liferay.portal.kernel.servlet.BaseFilter.processFilter(BaseFilter.java:169)
    at com.liferay.portal.servlet.filters.secure.SecureFilter.processFilter(SecureFilter.java:312)
    at com.liferay.portal.kernel.servlet.BaseFilter.doFilter(BaseFilter.java:59)
    at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilterChain.processDoFilter(InvokerFilterChain.java:204)
    at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilterChain.doFilter(InvokerFilterChain.java:109)
    at com.liferay.portal.kernel.servlet.BaseFilter.processFilter(BaseFilter.java:169)
    at com.liferay.portal.servlet.filters.jsoncontenttype.JSONContentTypeFilter.processFilter(JSONContentTypeFilter.java:42)
    at com.liferay.portal.kernel.servlet.BaseFilter.doFilter(BaseFilter.java:59)
    at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilterChain.processDoFilter(InvokerFilterChain.java:204)
    at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilterChain.doFilter(InvokerFilterChain.java:109)
    at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilterChain.processDirectCallFilter(InvokerFilterChain.java:185)
    at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilterChain.doFilter(InvokerFilterChain.java:96)
    at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilterChain.processDirectCallFilter(InvokerFilterChain.java:185)
    at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilterChain.doFilter(InvokerFilterChain.java:96)
    at org.tuckey.web.filters.urlrewrite.UrlRewriteFilter.doFilter(UrlRewriteFilter.java:738)
    at com.liferay.portal.servlet.filters.urlrewrite.UrlRewriteFilter.processFilter(UrlRewriteFilter.java:57)
    at com.liferay.portal.kernel.servlet.BaseFilter.doFilter(BaseFilter.java:59)
    at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilterChain.processDoFilter(InvokerFilterChain.java:204)
    at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilterChain.doFilter(InvokerFilterChain.java:109)
    at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilterChain.processDirectCallFilter(InvokerFilterChain.java:165)
    at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilterChain.doFilter(InvokerFilterChain.java:96)
    at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilterChain.processDirectCallFilter(InvokerFilterChain.java:165)
    at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilterChain.doFilter(InvokerFilterChain.java:96)
    at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilterChain.processDirectCallFilter(InvokerFilterChain.java:185)
    at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilterChain.doFilter(InvokerFilterChain.java:96)
    at com.liferay.portal.kernel.servlet.filters.invoker.InvokerFilter.doFilter(InvokerFilter.java:117)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:110)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:492)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:165)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:104)
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:1025)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
    at com.elixir.tango.tangofilters.ProcessingValve.invoke(ProcessingValve.java:52)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:451)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1201)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:654)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1782)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1741)
    - locked <0x00000005eacac390> (a org.apache.tomcat.util.net.NioChannel)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:750)
"http-nio-8080-exec-2":
    at sun.nio.cs.StreamEncoder.close(StreamEncoder.java:147)
    - waiting to lock <0x00000005e6beba58> (a java.io.OutputStreamWriter)
    at java.io.OutputStreamWriter.close(OutputStreamWriter.java:233)
    at java.io.FilterWriter.close(FilterWriter.java:104)
    at org.apache.log4j.WriterAppender.closeWriter(WriterAppender.java:213)
    at org.apache.log4j.rolling.RollingFileAppender.rollover(RollingFileAppender.java:290)
    - locked <0x00000005c2a7e928> (a org.apache.log4j.rolling.RollingFileAppender)
    at org.apache.log4j.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:353)
    at org.apache.log4j.WriterAppender.append(WriterAppender.java:158)
    at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:112)
    at org.apache.log4j.bridge.AppenderAdapter$Adapter.append(AppenderAdapter.java:59)
    at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:161)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:134)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:125)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:89)
    at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:675)
    at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:633)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:616)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:523)
    at org.apache.logging.log4j.core.config.DefaultReliabilityStrategy.log(DefaultReliabilityStrategy.java:49)
    at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:153)
    at org.apache.log4j.Category.forcedLog(Category.java:316)
    at org.apache.log4j.Category.log(Category.java:557)
    at com.liferay.portal.log.Log4jLogImpl.info(Log4jLogImpl.java:83)
    at com.liferay.portal.kernel.log.LogWrapper.info(LogWrapper.java:123)
    at com.liferay.portal.kernel.log.SanitizerLogWrapper.info(SanitizerLogWrapper.java:140)
    at com.elixir.tango.identity.ticket.TangoTicketUtil.getRedisKeyFromTicket(TangoTicketUtil.java:706)
    at com.elixir.tango.identity.helper.filter.TangoServicesAuthFilter.doFilter(TangoServicesAuthFilter.java:136)
    at com.elixir.tango.identity.helper.filter.TangoServicesAuthFilter.doFilter(TangoServicesAuthFilter.java:47)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at com.elixir.tango.store.filter.EntityManagerFilter.doFilter(EntityManagerFilter.java:45)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:110)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:492)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:165)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:104)
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:1025)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
    at com.elixir.tango.tangofilters.ProcessingValve.invoke(ProcessingValve.java:52)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:451)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1201)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:654)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1782)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1741)
    - locked <0x00000005e9d8f6c0> (a org.apache.tomcat.util.net.NioChannel)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:750)
"http-nio-8080-exec-20":
    at org.apache.log4j.rolling.RollingFileAppender.incrementFileLength(RollingFileAppender.java:433)
    - waiting to lock <0x00000005c2a7e928> (a org.apache.log4j.rolling.RollingFileAppender)
    at org.apache.log4j.rolling.RollingFileAppender$CountingOutputStream.write(RollingFileAppender.java:521)
    at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
    at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
    at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:295)
    at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141)
    - locked <0x00000005e6beba58> (a java.io.OutputStreamWriter)
    at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)
    at org.apache.log4j.helpers.QuietWriter.flush(QuietWriter.java:55)
    at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:326)
    at org.apache.log4j.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:359)
    at org.apache.log4j.WriterAppender.append(WriterAppender.java:158)
    at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:112)
    at org.apache.log4j.bridge.AppenderAdapter$Adapter.append(AppenderAdapter.java:59)
    at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:161)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:134)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:125)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:89)
    at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:675)
    at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:633)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:616)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:523)
    at org.apache.logging.log4j.core.config.DefaultReliabilityStrategy.log(DefaultReliabilityStrategy.java:49)
    at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:153)
    at org.apache.log4j.Category.forcedLog(Category.java:316)
    at org.apache.log4j.Category.log(Category.java:557)
    at com.liferay.portal.log.Log4jLogImpl.info(Log4jLogImpl.java:83)
    at com.liferay.portal.kernel.log.LogWrapper.info(LogWrapper.java:123)
    at com.liferay.portal.kernel.log.SanitizerLogWrapper.info(SanitizerLogWrapper.java:140)
    at com.elixir.tango.identity.ticket.TangoTicketUtil.getRedisKeyFromTicket(TangoTicketUtil.java:706)
    at com.elixir.tango.identity.helper.filter.TangoServicesAuthFilter.doFilter(TangoServicesAuthFilter.java:136)
    at com.elixir.tango.identity.helper.filter.TangoServicesAuthFilter.doFilter(TangoServicesAuthFilter.java:47)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at com.elixir.tango.store.filter.EntityManagerFilter.doFilter(EntityManagerFilter.java:45)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:110)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:492)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:165)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:104)
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:1025)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
    at com.elixir.tango.tangofilters.ProcessingValve.invoke(ProcessingValve.java:52)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:451)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1201)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:654)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1782)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1741)
    - locked <0x00000005e9d9c9d8> (a org.apache.tomcat.util.net.NioChannel)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:750)

Found 1 deadlock.

Please note that we are using liferay 6.2, java 1.8, log4j-1.2-api-2.17.2.jar and log4j 2.17.2

Update 1:

After updating to latest version of bridge, api and core i.e., log4j-1.2-api-2.23.1.jar, log4j-api-2.23.1, log4j-core-2.23.1.jar, I'm getting below exception:

2024-07-01T11:07:34.858Z localhost-startStop-1 ERROR Unable to create RollingFileAppender, no file name provided.
2024-07-01T11:07:34.936Z localhost-startStop-1 ERROR Could not parse null. java.lang.NullPointerException
    at org.apache.log4j.bridge.AppenderWrapper.getName(AppenderWrapper.java:114)
    at org.apache.log4j.xml.XmlConfiguration.lambda$parse$6(XmlConfiguration.java:779)
    at org.apache.log4j.xml.XmlConfiguration.lambda$forEachElement$8(XmlConfiguration.java:796)
    at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184)
    at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)

With latest version, I'm using below configurations

<?xml version="1.0"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">
    <appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
        <layout class="org.apache.log4j.EnhancedPatternLayout">
            <param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%t][%c{1}:%L] %m%n" />
        </layout>
    </appender>
    
    <appender name="FILE" class="org.apache.log4j.rolling.RollingFileAppender">
        <rollingPolicy class="org.apache.log4j.rolling.TimeBasedRollingPolicy">
            <param name="FileNamePattern" value="@liferay.home@/logs/[email protected]@.%d{yyyy-MM-dd}.log" />
        </rollingPolicy>

        <layout class="org.apache.log4j.EnhancedPatternLayout">
            <param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%t][%c{1}:%L] %m%n" />
        </layout>
    </appender>

    <root>
        <priority value="INFO" />
        <appender-ref ref="CONSOLE" />
        <appender-ref ref="FILE" />
    </root>

</log4j:configuration>

Upvotes: 1

Views: 237

Answers (2)

Piotr P. Karwasz
Piotr P. Karwasz

Reputation: 16185

Log4j 1 had many known deadlock problems. This is one of the reasons it was replaced by Log4j 2.

As far as I can tell, you are only using log4j-1.2-api to automatically convert your Log4j 1 configuration file into a Log4j 2 configuration file at runtime. The conversion uses the following algorithm:

  • if there is a configuration converter in log4j-1.2-api that knows how to convert a Log4j 1 component configuration into the equivalent Log4j 2 component configuration, it is used.
  • if the component is unknown, Log4j 2 tries to use the native Log4j 1 appender through an adapter.

In your case:

  • the org.apache.log4j.ConsoleAppender is replaced by org.apache.logging.log4j.core.appender.ConsoleAppender,
  • but org.apache.log4j.rolling.RollingFileAppender (which is not part of Log4j 1, but Apache Extras for Apache Log4j) is used directly.

To solve your problem:

  • either upgrade Log4j 2 to the newest version (support for the conversion of Apache Extras was added in version 2.18.0, see LOG4J2-3483), which will replace the usage of org.apache.log4j.rolling.RollingFileAppender with the Log4j 2 component org.apache.logging.log4j.core.appender.rolling.RollingFileAppender.
  • or replace the log4j.xml configuration file with the equivalent log4j2.xml configuration file:
<?xml version="1.0" encoding="UTF-8" ?>
<Configuration xmlns="https://logging.apache.org/xml/ns"
               xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
               xsi:schemaLocation="https://logging.apache.org/xml/ns
                   https://logging.apache.org/xml/ns/log4j-config-2.xsd">
  <Appenders>
    <Console name="CONSOLE">
      <PatternLayout pattern="%d{ABSOLUTE} %-5p [%t][%c{1}:%L] %m%n"/>
    </Console>
    <RollingFile name="FILE"
                 filePattern="@liferay.home@/logs/[email protected]@.%d{yyyy-MM-dd}.log">
      <PatternLayout pattern="%d{ABSOLUTE} %-5p [%t][%c{1}:%L] %m%n"/>
      <TimeBasedTriggeringPolicy/>
    </RollingFile>
  </Appenders>
  <Loggers>
    <Root level="INFO">
      <AppenderRef ref="CONSOLE"/>
      <AppenderRef ref="FILE"/>
    </Root>
    <Logger name="com.browseengine.bobo" level="ERROR"/>
  </Loggers>
</Configuration>

The second solution is the recommended one, since it does not rely on log4j-1.2-api to convert the configuration file.

Remark: You can check our updated migration page. Given that almost nobody uses Log4j 1 directly in their code since 20 years (the time JCL and SLF4J were released), chances are you can already remove log4j-1.2-api from your dependencies.

Upvotes: 1

talex
talex

Reputation: 20541

Problem lies in method

public synchronized void incrementFileLength(int increment) {
    this.fileLength += (long)increment;
}

of RollingFileAppender.

It shouldn't be synchronized on this.

Unfortunately bug isn't fixed yet.

Fortunately it reproduces in rare circumstances.

Upvotes: 0

Related Questions