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

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

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: New
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 3.22.1
    • Fix Version/s: None
    • Component/s: Raw, Transport
    • Notability:
      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

      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

          Issue Links

            Activity

              People

              Assignee:
              Unassigned Unassigned
              Reporter:
              plynch Peter Lynch
              Last Updated By:
              Wes Wannemacher Wes Wannemacher
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

                Dates

                Created:
                Updated:
                Date of First Response:

                  tigCommentSecurity.panel-title