Uploaded image for project: 'Artifactory Binary Repository'
  1. Artifactory Binary Repository
  2. RTFACT-26452

Artifactory (Windows-based) stop responding while trying to write logs

    XMLWordPrintable

    Details

    • 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

      Description

      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:

      1. Artifactory v7.19.4 with Windows installation
      2. Force Artifactory to write logs to the disk
      3. 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">
      

       

        Attachments

          Activity

              People

              Assignee:
              Unassigned
              Reporter:
              yardeng Yarden Gitta
              Votes:
              2 Vote for this issue
              Watchers:
              3 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved:

                  Sync Status

                  Connection: RTFACT Sync
                  RTMID-26463 -
                  SYNCHRONIZED
                  • Last Sync Date: