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

docker proxy outbound socket connection not reclaimed in a timely manner

    XMLWordPrintable

    Details

    • Story Points:
      0
    • Notability:
      n/a

      Description

      The full extent / impact of this apparent bug is not yet known, but what is happening is certainly not desired.

      1. Using 3.18.0, with SSL configured, create a docker proxy repo named docker-mcr with remote URL to https://mcr.microsoft.com with NXRM https proxy repo port 8085. Leave all other proxy repo settings at the default.
      2. Using docker CLI on Mac OS, try this pull command against docker-mcr repo:

      docker pull 192.168.2.73:8085/dotnet/framework/sdk:3.5-20190312-windowsservercore-1709
      3.5-20190312-windowsservercore-1709: Pulling from dotnet/framework/sdk
      5847a47b8593: Downloading 
      7f4a716683dc: Downloading 
      a0b9e6cc8428: Pulling fs layer 
      c7b3df59cf07: Waiting 
      0f7f4a02d07f: Waiting 
      95b085c19616: Waiting 
      0840293066db: Waiting 
      1ce78edeb082: Waiting 
      f695970932f2: Waiting 
      e973ab69584c: Waiting 
      c2cee858e78c: Waiting 
      1e5cf3025431: Waiting 
      3a47203603a8: Waiting 
      512c3f1501fc: Waiting 
      e9d87f0d4b54: Waiting 
      38d2531239bb: Waiting 
      69802bf088c5: Waiting 
      45ba04ff7a83: Waiting 
      871dfa0679ee: Waiting 
      image operating system "windows" cannot be used on this platform
      

      3. After the docker command is finished, take a NXRM thread dump. You will see a RUNNABLE qtp thread still in use waiting on Socket read:

      "qtp211978168-176" id=176 state=RUNNABLE
          at java.net.SocketInputStream.socketRead0(Native Method)
          at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
          at java.net.SocketInputStream.read(SocketInputStream.java:171)
          at java.net.SocketInputStream.read(SocketInputStream.java:141)
          at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
          at sun.security.ssl.InputRecord.readV3Record(InputRecord.java:593)
          at sun.security.ssl.InputRecord.read(InputRecord.java:532)
          at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:975)
          at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:933)
          at sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
            - locked sun.security.ssl.AppInputStream@596d8c20
          at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137)
          at org.apache.http.impl.io.SessionInputBufferImpl.read(SessionInputBufferImpl.java:198)
          at org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:176)
          at org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:135)
          at org.sonatype.nexus.common.hash.MultiHashingInputStream.read(MultiHashingInputStream.java:66)
          at com.google.common.io.CountingInputStream.read(CountingInputStream.java:63)
          at java.security.DigestInputStream.read(DigestInputStream.java:161)
          at java.io.FilterInputStream.read(FilterInputStream.java:133)
          at java.io.FilterInputStream.read(FilterInputStream.java:107)
          at com.google.common.io.ByteStreams.copy(ByteStreams.java:109)
          at org.sonatype.nexus.blobstore.file.internal.SimpleFileOperations.create(SimpleFileOperations.java:61)
          at org.sonatype.nexus.blobstore.file.FileBlobStore.lambda$0(FileBlobStore.java:284)
          at org.sonatype.nexus.blobstore.file.FileBlobStore$$Lambda$475/194325426.ingestTo(Unknown Source)
          at org.sonatype.nexus.blobstore.file.FileBlobStore.tryCreate(FileBlobStore.java:337)
          at org.sonatype.nexus.blobstore.file.FileBlobStore.create(FileBlobStore.java:303)
          at org.sonatype.nexus.blobstore.file.FileBlobStore.doCreate(FileBlobStore.java:284)
          at org.sonatype.nexus.blobstore.BlobStoreSupport.create(BlobStoreSupport.java:109)
          at org.sonatype.nexus.blobstore.file.FileBlobStore$$EnhancerByGuice$$ea200e81.CGLIB$create$33(<generated>)
          at org.sonatype.nexus.blobstore.file.FileBlobStore$$EnhancerByGuice$$ea200e81$$FastClassByGuice$$1944e0.invoke(<generated>)
          at com.google.inject.internal.cglib.proxy.$MethodProxy.invokeSuper(MethodProxy.java:228)
          at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:76)
          at org.sonatype.nexus.common.stateguard.MethodInvocationAction.run(MethodInvocationAction.java:39)
          at org.sonatype.nexus.common.stateguard.StateGuard$GuardImpl.run(StateGuard.java:272)
          at org.sonatype.nexus.common.stateguard.GuardedInterceptor.invoke(GuardedInterceptor.java:53)
          at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:77)
          at com.google.inject.internal.InterceptorStackCallback.intercept(InterceptorStackCallback.java:55)
          at org.sonatype.nexus.blobstore.file.FileBlobStore$$EnhancerByGuice$$ea200e81.create(<generated>)
          at org.sonatype.nexus.blobstore.BlobStoreSupport.create(BlobStoreSupport.java:94)
          at org.sonatype.nexus.blobstore.file.FileBlobStore$$EnhancerByGuice$$ea200e81.CGLIB$create$34(<generated>)
          at org.sonatype.nexus.blobstore.file.FileBlobStore$$EnhancerByGuice$$ea200e81$$FastClassByGuice$$1944e0.invoke(<generated>)
          at com.google.inject.internal.cglib.proxy.$MethodProxy.invokeSuper(MethodProxy.java:228)
          at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:76)
          at org.sonatype.nexus.common.stateguard.MethodInvocationAction.run(MethodInvocationAction.java:39)
          at org.sonatype.nexus.common.stateguard.StateGuard$GuardImpl.run(StateGuard.java:272)
          at org.sonatype.nexus.common.stateguard.GuardedInterceptor.invoke(GuardedInterceptor.java:53)
          at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:77)
          at com.google.inject.internal.InterceptorStackCallback.intercept(InterceptorStackCallback.java:55)
          at org.sonatype.nexus.blobstore.file.FileBlobStore$$EnhancerByGuice$$ea200e81.create(<generated>)
          at org.sonatype.nexus.repository.storage.StorageFacetImpl.createTempBlob(StorageFacetImpl.java:240)
          at org.sonatype.nexus.repository.storage.StorageFacetImpl.createTempBlob(StorageFacetImpl.java:256)
          at org.sonatype.nexus.repository.docker.internal.DockerProxyFacetImpl.putAsset(DockerProxyFacetImpl.java:551)
          at org.sonatype.nexus.repository.docker.internal.DockerProxyFacetImpl.putAssetValidatedOnDigest(DockerProxyFacetImpl.java:563)
          at org.sonatype.nexus.repository.docker.internal.DockerProxyFacetImpl.storeByAssetKind(DockerProxyFacetImpl.java:254)
          at org.sonatype.nexus.repository.docker.internal.DockerProxyFacetImpl.store(DockerProxyFacetImpl.java:220)
          at org.sonatype.nexus.repository.proxy.ProxyFacetSupport.doGet(ProxyFacetSupport.java:264)
          at org.sonatype.nexus.repository.docker.internal.DockerProxyFacetImpl.doGet(DockerProxyFacetImpl.java:861)
          at org.sonatype.nexus.repository.proxy.ProxyFacetSupport.lambda$1(ProxyFacetSupport.java:238)
          at org.sonatype.nexus.repository.proxy.ProxyFacetSupport$$Lambda$472/2020511942.call(Unknown Source)
          at org.sonatype.nexus.common.io.CooperatingFuture.performCall(CooperatingFuture.java:122)
          at com.sonatype.nexus.hazelcast.internal.io.DistributedCooperatingFuture.performCall(DistributedCooperatingFuture.java:50)
          at org.sonatype.nexus.common.io.CooperatingFuture.call(CooperatingFuture.java:64)
          at org.sonatype.nexus.common.io.ScopedCooperationFactorySupport$ScopedCooperation.cooperate(ScopedCooperationFactorySupport.java:99)
          at org.sonatype.nexus.repository.proxy.ProxyFacetSupport.get(ProxyFacetSupport.java:229)
          at org.sonatype.nexus.repository.proxy.ProxyHandler.handle(ProxyHandler.java:50)
          at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
          at org.sonatype.nexus.repository.view.handlers.LastDownloadedHandler.handle(LastDownloadedHandler.java:63)
          at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
          at org.sonatype.nexus.repository.storage.UnitOfWorkHandler.handle(UnitOfWorkHandler.java:39)
          at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
          at org.sonatype.nexus.repository.view.Context$proceed.call(Unknown Source)
          at org.sonatype.nexus.repository.docker.internal.V2Handlers$_closure16.doCall(V2Handlers.groovy:273)
          at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
          at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
          at java.lang.reflect.Method.invoke(Method.java:498)
          at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:98)
          at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:325)
          at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:264)
          at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1034)
          at groovy.lang.Closure.call(Closure.java:418)
          at org.codehaus.groovy.runtime.ConvertedClosure.invokeCustom(ConvertedClosure.java:54)
          at org.codehaus.groovy.runtime.ConversionHandler.invoke(ConversionHandler.java:124)
          at com.sun.proxy.$Proxy180.handle(Unknown Source)
          at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
          at org.sonatype.nexus.repository.http.PartialFetchHandler.handle(PartialFetchHandler.java:59)
          at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
          at org.sonatype.nexus.repository.view.handlers.ContentHeadersHandler.handle(ContentHeadersHandler.java:46)
          at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
          at org.sonatype.nexus.repository.view.handlers.ConditionalRequestHandler.handle(ConditionalRequestHandler.java:72)
          at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
          at org.sonatype.nexus.repository.view.Context$proceed.call(Unknown Source)
          at org.sonatype.nexus.repository.docker.internal.V2Handlers$_closure18.doCall(V2Handlers.groovy:298)
          at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
          at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
          at java.lang.reflect.Method.invoke(Method.java:498)
          at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:98)
          at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:325)
          at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:264)
          at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1034)
          at groovy.lang.Closure.call(Closure.java:418)
          at org.codehaus.groovy.runtime.ConvertedClosure.invokeCustom(ConvertedClosure.java:54)
          at org.codehaus.groovy.runtime.ConversionHandler.invoke(ConversionHandler.java:124)
          at com.sun.proxy.$Proxy180.handle(Unknown Source)
          at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
          at org.sonatype.nexus.repository.cache.NegativeCacheHandler.handle(NegativeCacheHandler.java:56)
          at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
          at org.sonatype.nexus.repository.routing.RoutingRuleHandler.handle(RoutingRuleHandler.java:49)
          at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
          at org.sonatype.nexus.repository.security.SecurityHandler.handle(SecurityHandler.java:52)
          at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
          at org.sonatype.nexus.repository.docker.internal.DockerNotFoundHandler.handle(DockerNotFoundHandler.java:42)
          at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
          at org.sonatype.nexus.repository.view.Context$proceed.call(Unknown Source)
          at org.sonatype.nexus.repository.docker.internal.V2Handlers$_closure18.doCall(V2Handlers.groovy:298)
          at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
          at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
          at java.lang.reflect.Method.invoke(Method.java:498)
          at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:98)
          at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:325)
          at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:264)
          at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1034)
          at groovy.lang.Closure.call(Closure.java:418)
          at org.codehaus.groovy.runtime.ConvertedClosure.invokeCustom(ConvertedClosure.java:54)
          at org.codehaus.groovy.runtime.ConversionHandler.invoke(ConversionHandler.java:124)
          at com.sun.proxy.$Proxy180.handle(Unknown Source)
          at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
          at org.sonatype.nexus.repository.view.Context$proceed.call(Unknown Source)
          at org.sonatype.nexus.repository.docker.internal.V2Handlers$_closure1.doCall(V2Handlers.groovy:90)
          at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
          at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
          at java.lang.reflect.Method.invoke(Method.java:498)
          at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:98)
          at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:325)
          at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:264)
          at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1034)
          at groovy.lang.Closure.call(Closure.java:418)
          at org.codehaus.groovy.runtime.ConvertedClosure.invokeCustom(ConvertedClosure.java:54)
          at org.codehaus.groovy.runtime.ConversionHandler.invoke(ConversionHandler.java:124)
          at com.sun.proxy.$Proxy180.handle(Unknown Source)
          at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
          at org.sonatype.nexus.repository.view.Context$proceed.call(Unknown Source)
          at org.sonatype.nexus.repository.docker.internal.V2Handlers$_closure17.doCall(V2Handlers.groovy:289)
          at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
          at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
          at java.lang.reflect.Method.invoke(Method.java:498)
          at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:98)
          at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:325)
          at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:264)
          at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1034)
          at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1099)
          at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1034)
          at groovy.lang.Closure.call(Closure.java:418)
          at org.codehaus.groovy.runtime.ConvertedClosure.invokeCustom(ConvertedClosure.java:54)
          at org.codehaus.groovy.runtime.ConversionHandler.invoke(ConversionHandler.java:124)
          at com.sun.proxy.$Proxy180.handle(Unknown Source)
          at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
          at org.sonatype.nexus.repository.view.Context$proceed.call(Unknown Source)
          at org.sonatype.nexus.repository.docker.internal.V2Handlers$_closure20.doCall(V2Handlers.groovy:479)
          at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
          at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
          at java.lang.reflect.Method.invoke(Method.java:498)
          at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:98)
          at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:325)
          at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:264)
          at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1034)
          at groovy.lang.Closure.call(Closure.java:418)
          at org.codehaus.groovy.runtime.ConvertedClosure.invokeCustom(ConvertedClosure.java:54)
          at org.codehaus.groovy.runtime.ConversionHandler.invoke(ConversionHandler.java:124)
          at com.sun.proxy.$Proxy180.handle(Unknown Source)
          at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
          at org.sonatype.nexus.repository.view.handlers.TimingHandler.handle(TimingHandler.java:46)
          at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
          at org.sonatype.nexus.repository.view.Context.start(Context.java:114)
          at org.sonatype.nexus.repository.view.Router.dispatch(Router.java:64)
          at org.sonatype.nexus.repository.view.ConfigurableViewFacet.dispatch(ConfigurableViewFacet.java:52)
          at org.sonatype.nexus.repository.view.ConfigurableViewFacet.dispatch(ConfigurableViewFacet.java:43)
          at org.sonatype.nexus.repository.httpbridge.internal.ViewServlet.dispatchAndSend(ViewServlet.java:212)
          at org.sonatype.nexus.repository.httpbridge.internal.ViewServlet.doService(ViewServlet.java:174)
          at org.sonatype.nexus.repository.httpbridge.internal.ViewServlet.service(ViewServlet.java:126)
          at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
          at com.google.inject.servlet.ServletDefinition.doServiceImpl(ServletDefinition.java:286)
          at com.google.inject.servlet.ServletDefinition.doService(ServletDefinition.java:276)
          at com.google.inject.servlet.ServletDefinition.service(ServletDefinition.java:181)
          at com.google.inject.servlet.DynamicServletPipeline.service(DynamicServletPipeline.java:71)
          at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:85)
          at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:112)
          at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
          at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:61)
          at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108)
          at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137)
          at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125)
          at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:66)
          at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108)
          at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137)
          at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125)
          at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:66)
          at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108)
          at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137)
          at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125)
          at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:66)
          at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108)
          at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137)
          at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125)
          at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:66)
          at org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:449)
          at org.sonatype.nexus.security.SecurityFilter.executeChain(SecurityFilter.java:85)
          at org.apache.shiro.web.servlet.AbstractShiroFilter$1.call(AbstractShiroFilter.java:365)
          at org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:90)
          at org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:83)
          at org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:383)
          at org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:362)
          at org.sonatype.nexus.security.SecurityFilter.doFilterInternal(SecurityFilter.java:101)
          at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125)
          at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
          at org.sonatype.nexus.repository.httpbridge.internal.ExhaustRequestFilter.doFilter(ExhaustRequestFilter.java:80)
          at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
          at com.sonatype.nexus.licensing.internal.LicensingRedirectFilter.doFilter(LicensingRedirectFilter.java:108)
          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:135)
          at org.sonatype.nexus.bootstrap.osgi.DelegatingFilter.doFilter(DelegatingFilter.java:73)
          at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1602)
          at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:540)
          at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146)
          at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
          at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
          at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257)
          at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1700)
          at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255)
          at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1345)
          at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203)
          at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:480)
          at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1667)
          at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201)
          at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1247)
          at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)
          at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
          at com.codahale.metrics.jetty9.InstrumentedHandler.handle(InstrumentedHandler.java:239)
          at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:152)
          at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
          at org.eclipse.jetty.server.Server.handle(Server.java:505)
          at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:370)
          at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:267)
          at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305)
          at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
          at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:427)
          at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:321)
          at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:159)
          at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
          at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
          at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333)
          at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310)
          at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
          at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
          at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)
          at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:698)
          at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:804)
          at java.lang.Thread.run(Thread.java:748)
      
          Locked synchronizers: count = 2
            - java.util.concurrent.locks.ReentrantLock$NonfairSync@d852fff
            - java.util.concurrent.locks.ReentrantLock$NonfairSync@11bb50ab
      

      4. Now stop the NXRM process. Stopping the NXRM process will hang, trying to clean up the stuck threads. Eventually you see:

      2019-07-30 15:43:06,772-0300 WARN  [SIGINT handler] *SYSTEM com.orientechnologies.orient.core.OSignalHandler - Received signal: SIGINT
      
      2019-07-30 15:44:06,825-0300 ERROR [Thread-7] *SYSTEM org.sonatype.nexus.repository.internal.blobstore.BlobStoreManagerImpl - Failed transition: STARTED -> STOPPED
      java.lang.RuntimeException: Failed to obtain lock after 60 seconds
      
      2019-07-30 15:44:06,863-0300 DEBUG [qtp211978168-193] admin org.sonatype.nexus.common.io.CooperatingFuture - Completing /v2/dotnet/framework/sdk/blobs/sha256:c7b3df59cf07f82a5bc1b98fa40fb151cc6002c2f15fc8290c2839153a22f342?{} (1 threads cooperating) with exception
      org.sonatype.nexus.blobstore.api.BlobStoreException: BlobId: tmp$24b8b5c6-cf57-4355-a1dc-eea2e9b383de, java.net.SocketException: Socket closed, Cause: Socket closed
      	at org.sonatype.nexus.blobstore.file.FileBlobStore.tryCreate(FileBlobStore.java:367)
      	at org.sonatype.nexus.blobstore.file.FileBlobStore.create(FileBlobStore.java:303)
      	at org.sonatype.nexus.blobstore.file.FileBlobStore.doCreate(FileBlobStore.java:284)
      	at org.sonatype.nexus.blobstore.BlobStoreSupport.create(BlobStoreSupport.java:109)
      	at org.sonatype.nexus.common.stateguard.MethodInvocationAction.run(MethodInvocationAction.java:39)
      	at org.sonatype.nexus.common.stateguard.StateGuard$GuardImpl.run(StateGuard.java:272)
      	at org.sonatype.nexus.common.stateguard.GuardedInterceptor.invoke(GuardedInterceptor.java:53)
      	at org.sonatype.nexus.blobstore.BlobStoreSupport.create(BlobStoreSupport.java:94)
      	at org.sonatype.nexus.common.stateguard.MethodInvocationAction.run(MethodInvocationAction.java:39)
      	at org.sonatype.nexus.common.stateguard.StateGuard$GuardImpl.run(StateGuard.java:272)
      	at org.sonatype.nexus.common.stateguard.GuardedInterceptor.invoke(GuardedInterceptor.java:53)
      	at org.sonatype.nexus.repository.storage.StorageFacetImpl.createTempBlob(StorageFacetImpl.java:240)
      	at org.sonatype.nexus.repository.storage.StorageFacetImpl.createTempBlob(StorageFacetImpl.java:256)
      	at org.sonatype.nexus.repository.docker.internal.DockerProxyFacetImpl.putAsset(DockerProxyFacetImpl.java:551)
      	at org.sonatype.nexus.repository.docker.internal.DockerProxyFacetImpl.putAssetValidatedOnDigest(DockerProxyFacetImpl.java:563)
      	at org.sonatype.nexus.repository.docker.internal.DockerProxyFacetImpl.storeByAssetKind(DockerProxyFacetImpl.java:254)
      	at org.sonatype.nexus.repository.docker.internal.DockerProxyFacetImpl.store(DockerProxyFacetImpl.java:220)
      	at org.sonatype.nexus.repository.proxy.ProxyFacetSupport.doGet(ProxyFacetSupport.java:264)
      	at org.sonatype.nexus.repository.docker.internal.DockerProxyFacetImpl.doGet(DockerProxyFacetImpl.java:861)
      	
      
      2019-07-30 15:44:06,869-0300 TRACE [qtp211978168-193] admin org.sonatype.nexus.common.collect.AttributesMap - Set: org.sonatype.nexus.repository.view.handlers.TimingHandler#elapsed=6.699 min (java.lang.String)
      2019-07-30 15:44:06,869-0300 TRACE [qtp211978168-193] admin org.sonatype.nexus.repository.view.handlers.TimingHandler - Timing: 6.699 min
      
      
      

      As evidenced by the above logging statements, the stuck thread seems to remain until the server is stopped.

      Worse, the more requests that are made for the same manifest, the more "cooperating" threads stack up, stealing a thread for the limited Jetty thread pool and the outbound connection pool as well.

      Lastly, the request.log never contains the original request that hung ( the request logging stopped before the thread finished )

      192.168.2.73 - - [30/Jul/2019:15:37:23 -0300] "GET /repository/docker-mcr/v2/ HTTP/1.1" 401 - 113 66 "docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \(darwin\))" [qtp211978168-188]
      192.168.2.73 - admin [30/Jul/2019:15:37:24 -0300] "GET /repository/docker-mcr/v2/dotnet/framework/sdk/manifests/3.5-20190312-windowsservercore-1709 HTTP/1.1" 200 - 4531 1045 "docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \(darwin\))" [qtp211978168-180]
      192.168.2.73 - admin [30/Jul/2019:15:37:24 -0300] "GET /repository/docker-mcr/v2/dotnet/framework/sdk/blobs/sha256:7f4a716683dc03db3521ed040924c24ea9bd17c7f134c09bf22e33f6af33ade8 HTTP/1.1" 404 - 156 142 "docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \(darwin\))" [qtp211978168-184]
      192.168.2.73 - admin [30/Jul/2019:15:37:24 -0300] "GET /repository/docker-mcr/v2/dotnet/framework/sdk/blobs/sha256:7f4a716683dc03db3521ed040924c24ea9bd17c7f134c09bf22e33f6af33ade8 HTTP/1.1" 404 - 156 12 "docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \(darwin\))" [qtp211978168-180]
      192.168.2.73 - admin [30/Jul/2019:15:37:24 -0300] "GET /repository/docker-mcr/v2/dotnet/framework/sdk/blobs/sha256:5847a47b8593f7c39aa5e3db09e50b76d42aa8898c0440c70cc9c69747d4c479 HTTP/1.1" 404 - 156 208 "docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \(darwin\))" [qtp211978168-188]
      192.168.2.73 - admin [30/Jul/2019:15:37:24 -0300] "GET /repository/docker-mcr/v2/dotnet/framework/sdk/blobs/sha256:5847a47b8593f7c39aa5e3db09e50b76d42aa8898c0440c70cc9c69747d4c479 HTTP/1.1" 404 - 156 10 "docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \(darwin\))" [qtp211978168-65]
      192.168.2.73 - admin [30/Jul/2019:15:37:25 -0300] "GET /repository/docker-mcr/v2/dotnet/framework/sdk/blobs/sha256:0f7f4a02d07fed94f55e9ec6c33d3131ae88f5ba5fb3d77e4e3185c1699b476f HTTP/1.1" 200 - 1059 367 "docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \(darwin\))" [qtp211978168-180]
      192.168.2.73 - admin [30/Jul/2019:15:37:25 -0300] "GET /repository/docker-mcr/v2/dotnet/framework/sdk/blobs/sha256:64988070c47c082a317ba296faf802c50b39ab9df737ea3bba3c11b4e9161ae6 HTTP/1.1" 200 - 11640 712 "docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \(darwin\))" [qtp211978168-190]
      127.0.0.1 - admin [30/Jul/2019:15:38:49 -0300] "GET /service/metrics/threads HTTP/1.1" 200 - 132428 66 "curl/7.61.1" [qtp211978168-192]
      127.0.0.1 - admin [30/Jul/2019:15:42:13 -0300] "GET /service/metrics/threads HTTP/1.1" 200 - 136272 54 "curl/7.61.1" [qtp211978168-180]
      

        Attachments

          Activity

            People

            Assignee:
            Unassigned Unassigned
            Reporter:
            plynch Peter Lynch
            Last Updated By:
            Rich Seddon Rich Seddon
            Team:
            NXRM - Mad Max
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved:
              Date of First Response:

                tigCommentSecurity.panel-title