Details
Description
We have several reports, that in rare cases, docker pushes to NXRM hosted repos may fail with messages similar to:
48983fe960c3: Preparing
128dd347f60c: Preparing
e1a204bf4760: Preparing
28f6517e2463: Preparing
d9ff549177a9: Preparing
28f6517e2463: Layer already exists
128dd347f60c: Layer already exists
d9ff549177a9: Layer already exists
e1a204bf4760: Layer already exists
48983fe960c3: Pushed
blob upload unknown
##[error]blob upload unknown
##[error]/usr/bin/docker failed with return code: 1
3.16.1 nexus.log messages
2019-07-25 16:47:13,420-0700 WARN [qtp884065834-20671] username org.sonatype.nexus.blobstore.file.FileBlobStore - Attempt to access soft-deleted blob path$nexus-repository-docker/b7654fa4-5b64-4db2-adab-7f5d1159b658/0 (F:\nexus3\blobs\primary blob store\content\directpath\nexus-repository-docker\b7654fa4-5b64-4db2-adab-7f5d1159b658\0.properties), reason: Docker upload cleaned up. 2019-07-25 16:47:13,420-0700 WARN [qtp884065834-20671] username org.sonatype.nexus.blobstore.file.FileBlobStore - Attempt to access soft-deleted blob path$nexus-repository-docker/b7654fa4-5b64-4db2-adab-7f5d1159b658/1564098432951 (F:\nexus3\blobs\primary blob store\content\directpath\nexus-repository-docker\b7654fa4-5b64-4db2-adab-7f5d1159b658\1564098432951.properties), reason: Docker upload cleaned up. 2019-07-25 16:47:13,420-0700 WARN [qtp884065834-20671] username org.sonatype.nexus.blobstore.file.FileBlobStore - Attempt to access soft-deleted blob path$nexus-repository-docker/b7654fa4-5b64-4db2-adab-7f5d1159b658/1564098433295 (F:\nexus3\blobs\primary blob store\content\directpath\nexus-repository-docker\b7654fa4-5b64-4db2-adab-7f5d1159b658\1564098433295.properties), reason: Docker upload cleaned up. 2019-07-25 16:47:13,420-0700 WARN [qtp884065834-20671] username org.sonatype.nexus.repository.docker.internal.DockerHostedFacetImpl - Failed to complete upload java.lang.IllegalStateException: Missing upload with uuid: b7654fa4-5b64-4db2-adab-7f5d1159b658 at org.sonatype.nexus.repository.docker.internal.UploadManagerImpl.ensureGetUpload(UploadManagerImpl.java:126) at org.sonatype.nexus.repository.docker.internal.UploadManagerImpl.complete(UploadManagerImpl.java:85) at org.sonatype.nexus.repository.docker.internal.DockerHostedFacetImpl.completeBlobUpload(DockerHostedFacetImpl.java:585) at org.sonatype.nexus.repository.docker.internal.DockerHostedFacetImpl$$EnhancerByGuice$$43e6bc99.CGLIB$completeBlobUpload$15(<generated>) at org.sonatype.nexus.repository.docker.internal.DockerHostedFacetImpl$$EnhancerByGuice$$43e6bc99$$FastClassByGuice$$b3a8c7a0.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.transaction.TransactionalWrapper.proceedWithTransaction(TransactionalWrapper.java:56) at org.sonatype.nexus.transaction.TransactionInterceptor.invoke(TransactionInterceptor.java:54) 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.repository.docker.internal.DockerHostedFacetImpl$$EnhancerByGuice$$43e6bc99.completeBlobUpload(<generated>) at org.sonatype.nexus.repository.docker.internal.DockerHostedFacet$completeBlobUpload$8.call(Unknown Source) at org.sonatype.nexus.repository.docker.internal.V2Handlers$_closure5.doCall(V2Handlers.groovy:150) at sun.reflect.GeneratedMethodAccessor423.invoke(Unknown Source) 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.$Proxy181.handle(Unknown Source) 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.security.SecurityHandler.handle(SecurityHandler.java:52) 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.GeneratedMethodAccessor128.invoke(Unknown Source) 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.$Proxy181.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.GeneratedMethodAccessor127.invoke(Unknown Source) 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.$Proxy181.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:68) 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:1588) 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:1557) 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:126) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) at org.eclipse.jetty.server.Server.handle(Server.java:502) at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:364) at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260) 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.ChannelEndPoint$2.run(ChannelEndPoint.java:118) 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:765) at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683) at java.lang.Thread.run(Thread.java:748)
3.161 Audit Log entries
{"timestamp":"2019-07-25 16:47:13,388-0700","nodeId":"A15B4527-0B17ADD5-D28C7AC1-EF2D5D16-ADAE52AE","initiator":"username/172.20.8.6","domain":"repository.asset","type":"created","context":"v2/-/blobs/sha256:a4ff2e7a414c9476f7edcdb69a93ba0f81f975912a7e51db8173784c50b2a7b4","attributes":{"repository.name":"docker-internal","format":"docker","name":"v2/-/blobs/sha256:a4ff2e7a414c9476f7edcdb69a93ba0f81f975912a7e51db8173784c50b2a7b4"}}
{"timestamp":"2019-07-25 16:47:13,748-0700","nodeId":"A15B4527-0B17ADD5-D28C7AC1-EF2D5D16-ADAE52AE","initiator":"username/172.20.8.6","domain":"repository.asset","type":"updated","context":"v2/-/blobs/sha256:a4ff2e7a414c9476f7edcdb69a93ba0f81f975912a7e51db8173784c50b2a7b4","attributes":{"repository.name":"docker-internal","format":"docker","name":"v2/-/blobs/sha256:a4ff2e7a414c9476f7edcdb69a93ba0f81f975912a7e51db8173784c50b2a7b4"}}
Initial Analysis
This appears to occur when two zero byte chunks for two different layers are uploaded to the same image namespace at the exact same time. Predicting when this could happen is near impossible.
Workaround
The only workaround at this time is to repeat the same docker push - in the case of CI builds this is especially troublesome, but has been reported to workaround the initial failure.
Attachments
Issue Links
- relates
-
NEXUS-22141 Docker "verification failed" with anonymous pull intermittently
-
- Open
-
