Spring Boot Log4j2 Thread Blocked

Question

In our Prod environment suddenly application got stuck and none of the requests were getting processed So, I took a thread dump of the PID

I see a Log4j is Blocked on Object that is locked by some other thread

Sharing the Parts of threaddump

    ```"http-nio-8080-exec-21025" #4910868 daemon prio=5 os_prio=0 tid=0x00007f2b3016a000 nid=0x2d87 runnable [0x00007f2b06d9e000]
   java.lang.Thread.State: RUNNABLE
    at java.io.FileOutputStream.writeBytes(Native Method)
    at java.io.FileOutputStream.write(FileOutputStream.java:326)
    at org.apache.logging.log4j.core.appender.OutputStreamManager.writeToDestination(OutputStreamManager.java:250)
    - eliminated <0x00000000deb28ba8> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager)
    at org.apache.logging.log4j.core.appender.FileManager.writeToDestination(FileManager.java:273)
    - eliminated <0x00000000deb28ba8> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager)
    at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.writeToDestination(RollingFileManager.java:240)
    - eliminated <0x00000000deb28ba8> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager)
    at org.apache.logging.log4j.core.appender.OutputStreamManager.flushBuffer(OutputStreamManager.java:282)
    - eliminated <0x00000000deb28ba8> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager)
    at org.apache.logging.log4j.core.appender.OutputStreamManager.flush(OutputStreamManager.java:291)
    - **locked <0x00000000deb28ba8>** (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager)```

    ```"http-nio-8080-exec-20991" #4899507 daemon prio=5 os_prio=0 tid=0x00007f2b30163000 nid=0x7e98 waiting for monitor entry [0x00007f2a62dcd000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.checkRollover(RollingFileManager.java:272)
    - **waiting to lock <0x00000000deb28ba8>** (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager)
    at org.apache.logging.log4j.core.appender.RollingFileAppender.append(RollingFileAppender.java:311)
    at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120) ```

    <Console name="Console-Appender" target="SYSTEM_OUT">
          <PatternLayout>
            <pattern>
                 [%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n
            </pattern>
        </PatternLayout>  
    </Console>
    <RollingFile name="RollingFile-Appender" fileName="@log4j2.path@/rbac.log" filePattern="@log4j2.path@/rbac.log.%d{yyyy-MM-dd}">
        <PatternLayout pattern="[%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] [${bundle:application:spring.application.name},%X{X-B3-TraceId},%X{X-B3-SpanId}] %c{1} - %msg%n"/>
        <Policies>
             <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
        </Policies>
        <DefaultRolloverStrategy max="100"/>
  </RollingFile>        
</Appenders>
  
<Loggers>
  <Logger name="org.springframework" level="info" additivity="false">
            <AppenderRef ref="Console-Appender"/>
        </Logger>
      <Logger name="com.pisp" level="info" additivity="false">
          <AppenderRef ref="RollingFile-Appender" level="info"/>        
      </Logger>
  <Root level="info">
          <AppenderRef ref="Console-Appender" />
          <AppenderRef ref="RollingFile-Appender" />
      </Root>
</Loggers>```


> Can Someone Help me fix this issue with Spring Boot Log4j2

Java -8 
Spring Boot Version - 2.3.2.RELEASE
spring-boot-starter-log4j2

If your logging thread is blocked for a long time, that sounds like a problem with the file system, i.e., logs are not able to be written. Check to make sure the disc partition is not full, that Apache has permission for all file operations (I think log rotation might require delete permission) etc. Basically anything that could go wrong with a process altering the a file in a directory. — markspace, Sep 07 '20 at 17:39
Are there _many_ threads all waiting for a single thread that is doing filesystem operations? That's a pretty common situation with log4j, because log lines are not buffered. All log operations have to be sequentialized, because we don't want lines in the file to get jumbled together. This is an indication that an application is writing more log output than it can cope with. I've seen this situation fairly commonly, when applications are handling more load than they were originally tested with. — Kevin Boone, Sep 07 '20 at 19:08
Hi @markspace Thanks for the reply I will check the file system condition. — user2787257, Sep 08 '20 at 02:58
I dont see a number of threads but this two are only fighting at that point and application was slow — user2787257, Sep 08 '20 at 03:50
An application being slow is not the same as being “stuck”. For logging to be affecting your application you either have to be logging a lot or have slow I/o. — rgoers, Sep 08 '20 at 14:06

score 0 · Answer 1 · answered Sep 07 '20 at 22:35

Since new requests are not being processed and application freezes it may suggest that you application has encountered deadlock. The simplest situation when deadlock can happen is when you have two threads (ThreadA, ThreadB) and two resources (R1 and R2) which can be used just by one thread at a time exclusively. Such resources can be i.e.

pessimistic lock at database protecting DB row from modification
monitor object guarding synchronized methods or utilized by objects of java.util.councurrency classes like CountDownLatch, Semaphore, Barrier, etc

Let's assume that both of the threads (ThreadA, ThreadB) need to obtain both resources (R1 and R2) to perform some operation. In situation when both threads try to do that concurrently, but in the different order a deadlock can happen:

Resource R1 and R2 is free
ThreadA obtained resource R1 - i.e. entered synchronized method
ThreadB obtained resource R2 - i.e. acquired obtained pessimistic lock
ThreadA tries to obtain resource R2, but it's taken by ThreadB so it wait indefinitely until is free to proceed with the operation flow
ThreadB tries to obtain resource R1, but it's taken by ThreadA so it wait indefinitely until is free to proceed with the operation flow
From now on all other thread which needs to obtain just one of these resources also starts to wait indefinitely and application is stuck

Thread dump can help you find monitor objects on which threads wait. When it comes to DB pessimistic locks each DB usually has some tooling allowing listing acquired pessimistic locks and the queries associated with it.

Since thread awaiting at RollingFileManager is involved I suggest checking if implementation of toString() methods in your classes does not call some synchronized method directly or indirectly. Also please ensure that your application has enough storage for logs and has permission to write them - maybe the root cause of this problem is more prosaic.

Spring Boot Log4j2 Thread Blocked

1 Answers1