Detected deadlock in logging - rolling the file

[dmatej]

Blocks whole server after a while because of this "recursion". I thought it is ok when I was rewriting that, but I forgot on one special case: the handler doesn't accept new records because it is rolling the file AND the buffer is full. Then the record saying that the file is rolled effectively blocks its own thread.

It is randomly reproducible when you enable FINEST level on some logger with high traffic (ie. CDI) that is able to fill the buffer. Any new message has to wait.

Possible solution: Do not use logging from log file manager until we are able to use the file again.

"GlassFishLogHandler log pump" #67 [112445] daemon prio=10 os_prio=0 cpu=3112,83ms elapsed=199,27s tid=0x00007fb614a92760 nid=112445 waiting on condition  [0x00007fb598bf2000]
java.lang.Thread.State: WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@21.0.1/Native Method)
- parking to wait for  <0x00000000e14f2f08> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(java.base@21.0.1/LockSupport.java:371)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(java.base@21.0.1/AbstractQueuedSynchronizer.java:519)
at java.util.concurrent.ForkJoinPool.unmanagedBlock(java.base@21.0.1/ForkJoinPool.java:3780)
at java.util.concurrent.ForkJoinPool.managedBlock(java.base@21.0.1/ForkJoinPool.java:3725)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@21.0.1/AbstractQueuedSynchronizer.java:1707)
at java.util.concurrent.ArrayBlockingQueue.put(java.base@21.0.1/ArrayBlockingQueue.java:370)
at org.glassfish.main.jul.handler.LogRecordBuffer.addWithUnlimitedWaiting(LogRecordBuffer.java:160)
at org.glassfish.main.jul.handler.LogRecordBuffer.add(LogRecordBuffer.java:120)
at org.glassfish.main.jul.handler.GlassFishLogHandler.publish(GlassFishLogHandler.java:234)
at org.glassfish.main.jul.GlassFishLogger.lambda$checkAndLog$7(GlassFishLogger.java:459)
at org.glassfish.main.jul.GlassFishLogger$$Lambda/0x00007fb5a01e7c18.accept(Unknown Source)
at java.util.Spliterators$1Adapter.forEachRemaining(java.base@21.0.1/Spliterators.java:704)
at org.glassfish.main.jul.GlassFishLogger.checkAndLog(GlassFishLogger.java:459)
at org.glassfish.main.jul.GlassFishLogger.logOrQueue(GlassFishLogger.java:502)
at org.glassfish.main.jul.GlassFishLogger.log(GlassFishLogger.java:197)
at sun.util.logging.internal.LoggingProviderImpl$JULWrapper.log(java.logging@21.0.1/LoggingProviderImpl.java:274)
at org.glassfish.main.jul.rotation.LogFileManager.roll(LogFileManager.java:160)
- locked <0x00000000ffab9d30> (a org.glassfish.main.jul.rotation.LogFileManager)
at org.glassfish.main.jul.rotation.LogFileManager.rollIfFileTooBig(LogFileManager.java:132)
- locked <0x00000000ffab9d30> (a org.glassfish.main.jul.rotation.LogFileManager)
at org.glassfish.main.jul.rotation.LogFileManager.flush(LogFileManager.java:114)
- locked <0x00000000ffab9d30> (a org.glassfish.main.jul.rotation.LogFileManager)
at org.glassfish.main.jul.handler.GlassFishLogHandler.flush(GlassFishLogHandler.java:249)
at org.glassfish.main.jul.handler.GlassFishLogHandler$LoggingPump.flushOutput(GlassFishLogHandler.java:480)
at org.glassfish.main.jul.handler.LoggingPumpThread.publishBatchFromBuffer(LoggingPumpThread.java:97)
at org.glassfish.main.jul.handler.LoggingPumpThread.run(LoggingPumpThread.java:73)

Environment Details

• GlassFish Version (and build number): 7.0.15
• JDK version: 17