Loading...

Details

Type: Bug
Resolution: Unresolved
Priority: Major
Fix Version/s: None
Affects Version/s: 3.22.1
Component/s: Raw, Transport
Labels:
- performance
- supportant

Notability:
3
Impact:
3

Description

Proxy repositories cache remote content. Repository Managers must serve this cached content to clients that request it, even if during the same inbound request, NXRM has to check the remote for new content and experiences a network I/O problem while doing so.

Problem

NXRM may start receiving a response from the remote. If during transmission of the content to NXRM, there is a SocketTimeoutException, then there are two problems experienced

the requesting inbound NXRM client gets a 500 response
the configured proxy repo number of retries may not be used

Example Reproduce

This manual reproduce relies on a failure occurring after receiving some data from the remote, but then timing out receiving any more data from the remote. This condition is quite common under some circumstances such as

the outbound network connection is not reliable
the remote server is not reliable
heavy outbound network I/O congestion
too low connection socket timeout settings inside NXRM for the proxy repo

There is likely a simple reproduce case that can be programatically made. The steps below are a somewhat convoluted procedure:

Configure NXRM to

use HTTP proxy server such as Charles
have a remote connection timeout of 20 seconds and 1 retry
logger org.sonatype.nexus.httpclient.outbound set to DEBUG

Configure a RAW proxy repo named raw-mirror-anaconda-archive with

remote URL to https://repo.anaconda.com/archive/
Component Max Age set to 0 ( to force NXRM to always check the remote for new components )

Send a request to download this file through NXRM proxy repo:

curl -v -u admin:admin123 http://localhost:8081/repository/raw-mirror-anaconda-archive/Anaconda3-5.3.0-Linux-x86_64.sh -o /dev/null

The sh file is now cached inside and the response should be 200

Inside Charles:

configure throttling inside Charles with these settings:
Throttle Settings 2020-08-10 17-54-48
configure breakpoints inside Charles as follows:

Repeat the request for the same file into NXRM.

When prompted by Charles breakpoints, change the response code to 200 ( from 304 ) and the Last-Modified header to be a day newer than actually reported. Click Execute after making these changes. ( this is just a convoluted way to tell NXRM to cache new content from the remote )
After repeating the download procedure several times, you should eventually trigger this in NXRM logs:

2020-08-10 16:49:03,035-0300 DEBUG [qtp147556170-302] admin org.sonatype.nexus.httpclient.outbound - https://repo.anaconda.com/archive/Anaconda3-5.3.0-Linux-x86_64.sh > GET /archive/Anaconda3-5.3.0-Linux-x86_64.sh HTTP/1.1
2020-08-10 16:49:11,055-0300 DEBUG [qtp147556170-302] admin org.sonatype.nexus.httpclient.outbound - https://repo.anaconda.com/archive/Anaconda3-5.3.0-Linux-x86_64.sh < HTTP/1.1 200 Not Modified @ 8.020 s
2020-08-10 16:49:31,062-0300 WARN  [qtp147556170-302] admin org.sonatype.nexus.repository.httpbridge.internal.ViewServlet - Failure servicing: GET /repository/raw-mirror-anaconda-archive/Anaconda3-5.3.0-Linux-x86_64.sh
org.sonatype.nexus.blobstore.api.BlobStoreException: BlobId: tmp$54c8137c-5223-41d5-90d6-8b92fa7f4d4d, java.net.SocketTimeoutException: Read timed out, Cause: Read timed out
	at org.sonatype.nexus.blobstore.file.FileBlobStore.tryCreate(FileBlobStore.java:372)
	at org.sonatype.nexus.blobstore.file.FileBlobStore.create(FileBlobStore.java:308)
	at org.sonatype.nexus.blobstore.file.FileBlobStore.doCreate(FileBlobStore.java:289)
	at org.sonatype.nexus.blobstore.BlobStoreSupport.create(BlobStoreSupport.java:127)
	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:111)
	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.raw.internal.RawContentFacetImpl.put(RawContentFacetImpl.java:101)
	at org.sonatype.nexus.repository.raw.internal.RawProxyFacet.store(RawProxyFacet.java:48)
	at org.sonatype.nexus.repository.proxy.ProxyFacetSupport.doGet(ProxyFacetSupport.java:271)
	at org.sonatype.nexus.repository.proxy.ProxyFacetSupport.lambda$1(ProxyFacetSupport.java:245)
	at org.sonatype.nexus.common.io.CooperatingFuture.performCall(CooperatingFuture.java:122)
	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:236)
	at org.sonatype.nexus.repository.proxy.ProxyHandler.handle(ProxyHandler.java:52)
	at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
	at org.sonatype.nexus.repository.storage.LastDownloadedHandler.handle(LastDownloadedHandler.java:59)
	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.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 org.sonatype.nexus.repository.cache.NegativeCacheHandler.handle(NegativeCacheHandler.java:56)
	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 com.sonatype.nexus.usertoken.plugin.internal.UserTokenHandler.handle(UserTokenHandler.java:70)
	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.internal.RoutingRuleHandler.handle(RoutingRuleHandler.java:52)
	at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
	at org.sonatype.nexus.repository.security.SecurityHandler.handle(SecurityHandler.java:51)
	at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
	at com.sonatype.analytics.internal.handler.AnalyticsMeteringHandler.handle(AnalyticsMeteringHandler.java:69)
	at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80)
	at org.sonatype.nexus.repository.view.handlers.TimingHandler.handle(TimingHandler.java:58)
	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:65)
	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:387)
	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.net.SocketTimeoutException: Read timed out
	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.read(InputRecord.java:503)
	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)
	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.IdentityInputStream.read(IdentityInputStream.java:93)
	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$1(FileBlobStore.java:289)
	at org.sonatype.nexus.blobstore.file.FileBlobStore.tryCreate(FileBlobStore.java:342)
	... 140 common frames omitted

While at the same time the client receives a 500 response:

curl -v -u admin:admin123 http://localhost:8081/repository/raw-mirror-anaconda-archive/Anaconda3-5.3.0-Linux-x86_64.sh -o /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0*   Trying ::1:8081...
* TCP_NODELAY set
* Connection failed
* connect to ::1 port 8081 failed: Connection refused
*   Trying 127.0.0.1:8081...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 8081 (#0)
* Server auth using Basic with user 'admin'
> GET /repository/raw-mirror-anaconda-archive/Anaconda3-5.3.0-Linux-x86_64.sh HTTP/1.1
> Host: localhost:8081
> Authorization: Basic YWRtaW46YWRtaW4xMjM=
> User-Agent: curl/7.68.0
> Accept: */*
> 
  0     0    0     0    0     0      0      0 --:--:--  0:00:27 --:--:--     0* Mark bundle as not supporting multiuse
< HTTP/1.1 500 javax.servlet.ServletException: org.sonatype.nexus.blobstore.api.BlobStoreException: BlobId: tmp$54c8137c-5223-41d5-90d6-8b92fa7f4d4d, java.net.SocketTimeoutException: Read timed out, Cause: Read timed out
< Date: Mon, 10 Aug 2020 19:49:03 GMT
< Server: Nexus/3.22.1-02 (PRO)
< X-Content-Type-Options: nosniff
< Content-Security-Policy: sandbox allow-forms allow-modals allow-popups allow-presentation allow-scripts allow-top-navigation
< X-XSS-Protection: 1; mode=block
< X-Frame-Options: DENY
< Pragma: no-cache
< Cache-Control: no-cache, no-store, max-age=0, must-revalidate, post-check=0, pre-check=0
< Expires: 0
< Content-Type: text/html
< Content-Length: 2075
< 
{ [2075 bytes data]
100  2075  100  2075    0     0     74      0  0:00:28  0:00:28 --:--:--   433
* Connection #0 to host localhost left intact

Expected

If there is a problem communicating with the remote and retries are exhausted, NXRM already has the content being requested, serve the cached content.

In the test case the retry wasn't used, and client received a 500 response.

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

image-2020-08-10-17-55-11-897.png
687 kB
08/10/20 08:55 PM
image-2020-08-10-17-56-49-247.png
95 kB
08/10/20 08:56 PM

Issue Links

relates

NEXUS-23399 NuGet v3 proxy repository will not serve cached content if remote is blocked

Closed

raw proxy repositories may not serve already cached components if there is an SocketTimeoutException: Read timed out while reading the remote response

Details

Description

Problem

Example Reproduce

Expected

Attachments

Attachments

Issue Links

Activity

People

Dates

tigCommentSecurity.panel-title