-
Type:
Bug
-
Status: Done
-
Resolution: Done
-
Affects Version/s: 7.27.6
-
Fix Version/s: 7.31.10
-
Component/s: Artifactory
-
Labels:None
-
Location:External
Problem description:
On Windows-based installation, while Artifactory trying to rotate the logs, the thread stuck and blocked all the running threads that are trying to write logs.
This issue happened in the Artifactory version including the fix introduced in RTFACT-24727.
What is the expected behavior?
Log rotation operation should work without affecting Artifactory performance.
Steps to reproduce:
- Artifactory v7.19.4 with Windows installation
- Force Artifactory to write logs to the disk
- Take thread dump
"http-nio-8081-exec-2409" #304745 daemon prio=5 os_prio=0 cpu=229296.88ms elapsed=91248.21s tid=0x0000018ec0b26800 nid=0x2d10 runnable [0x000000c4ad5fd000] java.lang.Thread.State: RUNNABLE at java.io.WinNTFileSystem.getLastModifiedTime(java.base@11.0.10/Native Method) at java.io.File.lastModified(java.base@11.0.10/File.java:957) at org.jfrog.common.logging.logback.triggering.SizeAndIntervalTriggeringPolicy$$Lambda$1013/0x0000000800add040.apply(Unknown Source) at java.util.Comparator.lambda$comparing$77a9974f$1(java.base@11.0.10/Comparator.java:469) at java.util.Comparator$$Lambda$183/0x0000000800326c40.compare(java.base@11.0.10/Unknown Source) at java.util.function.BinaryOperator.lambda$maxBy$1(java.base@11.0.10/BinaryOperator.java:74) at java.util.function.BinaryOperator$$Lambda$1014/0x0000000800add440.apply(java.base@11.0.10/Unknown Source) at java.util.stream.ReduceOps$2ReducingSink.accept(java.base@11.0.10/ReduceOps.java:123) at java.util.stream.ReferencePipeline$2$1.accept(java.base@11.0.10/ReferencePipeline.java:177) at java.util.Spliterators$ArraySpliterator.forEachRemaining(java.base@11.0.10/Spliterators.java:948) at java.util.stream.AbstractPipeline.copyInto(java.base@11.0.10/AbstractPipeline.java:484) at java.util.stream.AbstractPipeline.wrapAndCopyInto(java.base@11.0.10/AbstractPipeline.java:474) at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(java.base@11.0.10/ReduceOps.java:913) at java.util.stream.AbstractPipeline.evaluate(java.base@11.0.10/AbstractPipeline.java:234) at java.util.stream.ReferencePipeline.reduce(java.base@11.0.10/ReferencePipeline.java:558) at java.util.stream.ReferencePipeline.max(java.base@11.0.10/ReferencePipeline.java:594) at org.jfrog.common.logging.logback.triggering.SizeAndIntervalTriggeringPolicy.getLatestTimestamp(SizeAndIntervalTriggeringPolicy.java:62) at org.jfrog.common.logging.logback.triggering.SizeAndIntervalTriggeringPolicy.getLatestArchiveTimestamp(SizeAndIntervalTriggeringPolicy.java:56) at org.jfrog.common.logging.logback.triggering.SizeAndIntervalTriggeringPolicy.isTriggeringEvent(SizeAndIntervalTriggeringPolicy.java:46) at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:230) - locked <0x000000030a3dd5a8> (a org.jfrog.common.logging.logback.triggering.SizeAndIntervalTriggeringPolicy) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383) at ch.qos.logback.classic.Logger.info(Logger.java:579) at org.artifactory.traffic.RequestLogger.request(RequestLogger.java:72) at org.artifactory.webapp.servlet.RequestFilter.doFilter(RequestFilter.java:93) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.artifactory.webapp.servlet.ArtifactoryCsrfFilter.doFilter(ArtifactoryCsrfFilter.java:83) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.session.web.http.SessionRepositoryFilter.doFilterInternal(SessionRepositoryFilter.java:164) at org.springframework.session.web.http.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:80) at org.artifactory.webapp.servlet.SessionFilter.doFilter(SessionFilter.java:68) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.artifactory.webapp.servlet.ArtifactoryTracingFilter.doFilter(ArtifactoryTracingFilter.java:32) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.artifactory.webapp.servlet.ArtifactoryFilter.doFilter(ArtifactoryFilter.java:123) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:544) at org.apache.catalina.valves.rewrite.RewriteValve.invoke(RewriteValve.java:305) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:353) at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:616) at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:831) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1629) at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) - locked <0x000000077968a310> (a org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.10/ThreadPoolExecutor.java:1128) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.10/ThreadPoolExecutor.java:628) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.lang.Thread.run(java.base@11.0.10/Thread.java:834)
Workaround:
In Logback.xml please replace any instance (it should appear at least 2 times) of:
<triggeringPolicy class="org.jfrog.common.logging.logback.triggering.SizeAndIntervalTriggeringPolicy">
with:
<triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">