What cause the java.util.logging.SimpleFormatter.format thread block?

Question

My project uses log4j, but this seems that it blocked by using java.util.logging. java info： java version "1.8.0_121" Java(TM) SE Runtime Environment (build 1.8.0_121-b13) Java HotSpot(TM) 64-Bit Server VM (build 25.121-b13, mixed mode)

The server is tomcat.

The Jstack log is below:

"http-nio-192.168.0.94-8443-exec-316" #378 daemon prio=5 os_prio=0 tid=0x00007f96d4f42800 nid=0x3466 waiting for monitor entry [0x00007f96c753d000]
       java.lang.Thread.State: BLOCKED (on object monitor)
            at java.util.logging.SimpleFormatter.format(SimpleFormatter.java)
            - waiting to lock <0x00000006c53cdae0> (a java.util.logging.SimpleFormatter)
            at org.apache.juli.FileHandler.publish(FileHandler.java:197)
            at java.util.logging.Logger.log(Logger.java:738)
            at java.util.logging.Logger.doLog(Logger.java:765)
            at java.util.logging.Logger.log(Logger.java:788)
            at org.restlet.engine.log.LogFilter.afterHandle(LogFilter.java:106)
            at org.restlet.routing.Filter.handle(Filter.java:208)
            at org.restlet.engine.CompositeHelper.handle(CompositeHelper.java:211)
            at org.restlet.Component.handle(Component.java:406)
            at org.restlet.Server.handle(Server.java:516)
            at org.restlet.engine.connector.ServerHelper.handle(ServerHelper.java:72)
            at org.restlet.engine.adapter.HttpServerHelper.handle(HttpServerHelper.java:152)
            at org.restlet.ext.servlet.ServerServlet.service(ServerServlet.java:1118)
            at javax.servlet.http.HttpServlet.service(HttpServlet.java:731)
            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 com.xxx.xxx.web.Filter.xxxxxxx.doFilter(SGRequestCheck.java:129)
            at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
            at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
            at com.xxx.trace.http.servlet.filter.BraveServletFilter.doFilter(BraveServletFilter.java:165)
            at com.xxx.trace.http.servlet.filter.TraceServletFilter.doFilter(TraceServletFilter.java:73)
            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:218)
            at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
            at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:169)
            at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
            at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:956)
            at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
            at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:442)
            at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1082)
            at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:623)
            at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1756)
            at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1715)
            - locked <0x00000006c8a84a70> (a org.apache.tomcat.util.net.SecureNioChannel)
            at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
            at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
            at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
            at java.lang.Thread.run(Thread.java:745)

       Locked ownable synchronizers:
            - <0x00000006c9f790b0> (a java.util.concurrent.ThreadPoolExecutor$Worker)

Is it a application using spring, tomcat and OAuth? It can be a behaviour problem looking up for a OAuth token. AP is configured other way than frameworks on spring so they are locking each other while looking for it. It´s realy strang and rare. I had this problem once but can´t remember exact solution but description should be correct in case you´re using same technology like me months ago. — LenglBoy, Jun 19 '18 at 07:57
A `synchronized` block. You can probably find it in the source code. This isn't Log4j code - it's JUL. — Boris the Spider, Jun 19 '18 at 07:58
@LenglBoy whilst what you say is true, the stacktrace indicates something very different. How did you get from JUL formatting to JWT? — Boris the Spider, Jun 19 '18 at 07:59
@LenglBoy I don't use spring and Oauth, this is a tomcat application. Just as Boris said, this is not Log4j code, it is JUL code. But I can't change it to Log4j, since it is in Restlet jar. — user2613603, Jun 19 '18 at 08:43
Well, you can "change it", even through slf4j or similar approach. you may need to tackle with provided jars, but tomcat allows such things. Please see this answer: https://stackoverflow.com/questions/869945/how-to-send-java-util-logging-to-log4j — Alexander Anikin, Jun 25 '18 at 16:07

score 0 · Answer 1 · answered Jun 25 '18 at 13:37

Blocking status doesn't always mean that something bad is happening, it just says that some thread is waiting for a different thread to release its lock in order to get the monitor lock. In your case multiple threads share the same instance of SimpleFormatter class which acquires a lock when format method is invoked.

public synchronized String format(LogRecord record)

What cause the java.util.logging.SimpleFormatter.format thread block?

1 Answers1