Loading...

XML

Word

Printable

Details

Type: Bug
Resolution: Parked
Priority: Major
Fix Version/s: None
Affects Version/s: 3.16.0, 3.17.0, 3.18.0
Component/s: Docker, Transport
Labels:

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

Reporter:: Peter Lynch

Last Updated By:: Rich Seddon

Team:: NXRM - Mad Max

Votes:: 0 Vote for this issue

Watchers:: 5 Start watching this issue

Dates

Created:: 07/30/19 06:59 PM

Updated:: 10/25/21 04:50 PM

Resolved:: 10/25/21 04:50 PM

Date of First Response:: 02/Aug/19 2:25 PM

docker proxy outbound socket connection not reclaimed in a timely manner