Uploaded image for project: 'Dev - Nexus Repo'
  1. Dev - Nexus Repo
  2. NEXUS-31564

logback dependency in Nexus Repo 3 may cause slowdown in CachingDateFormatter due to LOGBACK-1421

    Details

    • Type: Bug
    • Status: New
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 3.38.0
    • Fix Version/s: None
    • Component/s: Logging
    • Notability:
      3

      Description

      Description: 

      The Nexus Repo 3 is using logback-core 1.2.9 which could cause deadlock

      https://jira.qos.ch/browse/LOGBACK-1421

      Example:

      "qtp2084131226-27252" #27252 prio=5 os_prio=0 tid=0x00007f0aac0afc50 nid=0x6d68 waiting for monitor entry [0x00007f068d70e000]
         java.lang.Thread.State: BLOCKED (on object monitor)
      	at ch.qos.logback.core.util.CachingDateFormatter.format(CachingDateFormatter.java:45)
      	- waiting to lock <0x00000005c3225320> (a ch.qos.logback.core.util.CachingDateFormatter)
      	at ch.qos.logback.classic.pattern.DateConverter.convert(DateConverter.java:61)
      	at ch.qos.logback.classic.pattern.DateConverter.convert(DateConverter.java:23)
      	at ch.qos.logback.core.pattern.FormattingConverter.write(FormattingConverter.java:36)
      	at ch.qos.logback.core.pattern.PatternLayoutBase.writeLoopOnConverters(PatternLayoutBase.java:115)
      	at ch.qos.logback.classic.PatternLayout.doLayout(PatternLayout.java:141)
      	at ch.qos.logback.classic.PatternLayout.doLayout(PatternLayout.java:39)
      	at ch.qos.logback.core.encoder.LayoutWrappingEncoder.encode(LayoutWrappingEncoder.java:115)
      	at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:230)
      	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.log(Logger.java:765)
      	at org.ops4j.pax.logging.logback.internal.PaxLoggerImpl.doLog0(PaxLoggerImpl.java:1157)
      	at org.ops4j.pax.logging.logback.internal.PaxLoggerImpl.doLog(PaxLoggerImpl.java:1131)
      	at org.ops4j.pax.logging.logback.internal.PaxLoggerImpl.info(PaxLoggerImpl.java:422)
      	at org.ops4j.pax.logging.internal.TrackingLogger.info(TrackingLogger.java:242)
      	at org.ops4j.pax.logging.slf4j.Slf4jLogger.info(Slf4jLogger.java:612)
      	at org.owasp.esapi.logging.slf4j.Slf4JLogLevelHandlers$3.log(Slf4JLogLevelHandlers.java:65)
      	at org.owasp.esapi.logging.slf4j.Slf4JLogBridgeImpl.log(Slf4JLogBridgeImpl.java:59)
      	at org.owasp.esapi.logging.slf4j.Slf4JLogger.log(Slf4JLogger.java:43)
      	at org.owasp.esapi.logging.slf4j.Slf4JLogger.info(Slf4JLogger.java:91)
      	at com.example.nexus.util.LoggerUtil.info(LoggerUtil.java:61)
      	at com.example.nexus.util.NexusRequestUtils.getRepositoryType(NexusRequestUtils.java:73)
      	at com.example.nexus.finegrained.FineGrainedRequestInterceptor.intercept(FineGrainedRequestInterceptor.java:115)
      	at com.example.nexus.interceptor.NexusRequestFilter.doFilter(NexusRequestFilter.java:87)
      	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
      	at com.example.nexus.interceptor.NexusCadiFilter.doFilter(NexusCadiFilter.java:72)
      	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
      	at com.sonatype.nexus.licensing.internal.LicensingRedirectFilter.doFilter(LicensingRedirectFilter.java:116)
      	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
      	at com.codahale.metrics.servlet.AbstractInstrumentedFilter.doFilter(AbstractInstrumentedFilter.java:112)
      	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
      	at org.sonatype.nexus.internal.web.ErrorPageFilter.doFilter(ErrorPageFilter.java:79)
      	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
      	at org.sonatype.nexus.internal.web.EnvironmentFilter.doFilter(EnvironmentFilter.java:101)
      	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
      	at org.sonatype.nexus.internal.web.HeaderPatternFilter.doFilter(HeaderPatternFilter.java:98)
      	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
      	at com.google.inject.servlet.DynamicFilterPipeline.dispatch(DynamicFilterPipeline.java:104)
      	at com.google.inject.servlet.GuiceFilter.doFilter(GuiceFilter.java:133)
      	at org.sonatype.nexus.bootstrap.osgi.DelegatingFilter.doFilter(DelegatingFilter.java:73)
      	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193)
      	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601)
      	at com.example.nexus.swm.filter.SWMNexusHeaderFilter.doFilter(SWMNexusHeaderFilter.java:128)
      	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:201)
      	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601)
      	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:548)
      	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
      	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:602)
      	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
      	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
      	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624)
      	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
      	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1434)
      	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
      	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501)
      	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594)
      	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
      	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1349)
      	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
      	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
      	at com.codahale.metrics.jetty9.InstrumentedHandler.handle(InstrumentedHandler.java:239)
      	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
      	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
      	at org.eclipse.jetty.server.Server.handle(Server.java:516)
      	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:388)
      	at org.eclipse.jetty.server.HttpChannel$$Lambda$1659/1466156143.dispatch(Unknown Source)
      	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:633)
      	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:380)
      	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277)
      	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
      	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
      	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
      	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338)
      	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315)
      	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
      	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
      	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:386)
      	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
      	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
      	at java.lang.Thread.run(Thread.java:748)
      

      The situation was observed under high load and a custom plugin injected a request filter that logged messages at INFO level for every inbound request.

      Workaround

      Reduce the verbosity of the logger levels that log statements frequently.

      Normally this is not needed at default log levels as Nexus Repo does not ship will any application logger that logs multiple messages for every inbound request.

      Expected   

      Use a newer version of logback or another way to avoid this problem that may cause other issues when using Nexus Repo 3.

       

        Attachments

          Activity

            People

            Assignee:
            Unassigned Unassigned
            Reporter:
            dqiu Daolong Qiu
            Last Updated By:
            Michael Oliverio Michael Oliverio
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Dates

              Created:
              Updated:

                tigCommentSecurity.panel-title