Failure servicing: PUT

cino · November 13, 2019, 2:27pm

Hi everyone,
I’ve been getting some errors when maven tries to upload some really small artifacts(<200kB)
I’ve seen some other “timeout” errors around here, and google, but it’s nothing related to my situation.
I have an haproxy in front of nexus but without any particular rules.

Here’s what’s in my log
WARN [qtp796619658-13866] admin org.sonatype.nexus.repository.httpbridge.internal.ViewServlet - Failure servicing: PUT /…/Snapshots/…/client/3.636-1573646716-SNAPSHOT/client-3.636-1573646716-20191113.120819-1.jar
org.sonatype.nexus.blobstore.api.BlobStoreException: BlobId: tmp$1dfdb808-2246-4d18-bb1f-863158a1a73a, java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 30016/30000 ms, Cause: java.util.concurrent.TimeoutException: Idle timeout expired: 30016/30000 ms
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.maven.internal.MavenFacetImpl.put(MavenFacetImpl.java:210)
at org.sonatype.nexus.repository.maven.internal.hosted.HostedHandler.doPut(HostedHandler.java:92)
at org.sonatype.nexus.repository.maven.internal.hosted.HostedHandler.handle(HostedHandler.java:64)
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.handlers.ContentHeadersHandler.handle(ContentHeadersHandler.java:46)
at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
at org.sonatype.nexus.repository.maven.internal.VersionPolicyHandler.handle(VersionPolicyHandler.java:61)
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.ConditionalRequestHandler.handle(ConditionalRequestHandler.java:72)
at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
at com.sonatype.nexus.clm.internal.FirewallContributedHandler.handle(FirewallContributedHandler.java:96)
at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
at org.sonatype.nexus.repository.view.handlers.HandlerContributor.handle(HandlerContributor.java:67)
at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
at org.sonatype.nexus.repository.view.handlers.ExceptionHandler.handle(ExceptionHandler.java:44)
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.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:114)
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.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)
Caused by: java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 30016/30000 ms
at org.eclipse.jetty.server.HttpInput$ErrorState.noContent(HttpInput.java:1085)
at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:318)
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.tryCreate(FileBlobStore.java:337)
… 130 common frames omitted
Caused by: java.util.concurrent.TimeoutException: Idle timeout expired: 30016/30000 ms
at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:166)
at org.eclipse.jetty.io.IdleTimeout$1.run(IdleTimeout.java:50)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
… 1 common frames omitted
Suppressed: java.lang.Throwable: HttpInput failure
at org.eclipse.jetty.server.HttpInput.failed(HttpInput.java:831)
at org.eclipse.jetty.server.HttpConnection$BlockingReadCallback.failed(HttpConnection.java:661)
at org.eclipse.jetty.io.FillInterest.onFail(FillInterest.java:138)
at org.eclipse.jetty.io.AbstractEndPoint.onIdleExpired(AbstractEndPoint.java:406)
… 9 common frames omitted

It happens randomly. sometimes two times in a week and sometimes once in two weeks…
I have no idea

Can someone help me?
Thanks

ballinj · February 6, 2020, 6:30pm

@cino, did you find any resolution to this? I am experiencing the same problem but much more frequently than you describe. I’m trying to find a pattern of why some artifacts can be uploaded and why some fail with this exception.

rseddon · February 6, 2020, 6:47pm

This message:

java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired

means you’re hitting the Jetty idle timeout - which suggests a network issue outside of Nexus Repo (it didn’t receive any data on the socket for 30 seconds). That is not normal.

Is there anything between the client and NXRM? (ie. proxy, firewall, or scanner). If so, check its configuration and logs.

By the way, one common cause of this is using nginx as a reverse proxy. By default it has “proxy_buffering” enabled, and that will cause it to buffer uploads, resulting in idle timeouts in Nexus. If you’re using nginx see here for our recommendations:

https://help.sonatype.com/display/NXRM3/Run+Behind+a+Reverse+Proxy#RunBehindaReverseProxy-nginx

Rich

ballinj · February 6, 2020, 11:26pm

@rseddon, that is certainly where we started looking. The entire stack trace throws this specific error in the midst of the FileBlobStore.tryCreate() method, so we first knocked on the door of our server and network guys. nginx, proxies, DLP scanners, wireshark, server resources, filesystem, blob stores, you name it.

Some files failed consistently while other files worked consistently. Anecdotally we equated this to an artifact size problem as this seemed to affect files measured in MBs.

So, I think I found it. At least, this fixes the problem for me after banging on it today. If I explicitly include the finalName stanza in my <build> block, I can now make this work every time. But, if I remove that entry, I will see specific uploads fail (while other small files work without it).

Does that make sense to you?