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

docker push may fail with blob upload unknown due to race condition

    XMLWordPrintable

    Details

    • Story Points:
      0
    • Notability:
      3

      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

            Activity

              People

              Assignee:
              sonofreichuk Sergii Onofreichuk
              Reporter:
              plynch Peter Lynch
              Last Updated By:
              Wes Wannemacher
              Team:
              NXRM - Trinity
              Votes:
              11 Vote for this issue
              Watchers:
              15 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved:
                Date of First Response:

                  tigCommentSecurity.panel-title

                    PagerDuty