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

possible that requests abruptly terminating will not appear in request.log

    XMLWordPrintable

    Details

    • Notability:
      n/a

      Description

      Historically, if the inbound request headers are able to be read, then there is an implicit guarantee that such a request will result in an entry in the request.log.

      Users and support rely on this reliable logging of inbound requests to help diagnose if a request has arrived to NXRM at all, how many bytes were actually transmitted, what the response code was, etc.

      It has been noticed starting in version 3.26.0, it is now possible that some requests that encounter connection reset will not end up in the request log anymore, only in the nexus.log.

      The seems to be related to calling Response.sendError when the connection has already been terminated - this seems to bypass the request logging somehow.

      java.lang.IllegalStateException: ABORTED
      at org.eclipse.jetty.server.HttpChannelState.sendError(HttpChannelState.java:896)
      at org.eclipse.jetty.server.Response.sendError(Response.java:466)
      at org.eclipse.jetty.server.Response.sendError(Response.java:437)
      at org.sonatype.nexus.internal.web.ErrorPageFilter.doFilter(ErrorPageFilter.java:84)

      Reproduce

      In 3.26.0 or newer, start downloading a large file from a repository. Abruptly terminate the download. Note that your GET request is not written to the request.log. The nexus.log will contain something like this:

      2020-09-04 10:40:56,604-0300 WARN  [qtp855128718-196] admin org.sonatype.nexus.repository.httpbridge.internal.ViewServlet - Failure servicing: GET /repository/raw-hosted/large.txt
      org.eclipse.jetty.io.EofException: null
      	at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:279)
      	at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:422)
      	at org.eclipse.jetty.io.WriteFlusher.completeWrite(WriteFlusher.java:378)
      	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:119)
      	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
      	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:298)
      	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
      	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
      	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
      	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
      	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
      	at java.lang.Thread.run(Thread.java:748)
      Caused by: java.io.IOException: Broken pipe
      	at sun.nio.ch.FileDispatcherImpl.writev0(Native Method)
      	at sun.nio.ch.SocketDispatcher.writev(SocketDispatcher.java:51)
      	at sun.nio.ch.IOUtil.write(IOUtil.java:148)
      	at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:501)
      	at java.nio.channels.SocketChannel.write(SocketChannel.java:502)
      	at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:273)
      	... 11 common frames omitted
      2020-09-04 10:40:56,608-0300 ERROR [qtp855128718-196] *SYSTEM org.eclipse.jetty.util.log.StdErrLog - 2020-09-04 10:40:56.607:WARN:oejs.HttpChannel:qtp855128718-196: /repository/raw-hosted/large.txt
      java.lang.IllegalStateException: ABORTED
      	at org.eclipse.jetty.server.HttpChannelState.sendError(HttpChannelState.java:896)
      	at org.eclipse.jetty.server.Response.sendError(Response.java:466)
      	at org.eclipse.jetty.server.Response.sendError(Response.java:437)
      	at org.sonatype.nexus.internal.web.ErrorPageFilter.doFilter(ErrorPageFilter.java:84)
      	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:133)
      	at org.sonatype.nexus.bootstrap.osgi.DelegatingFilter.doFilter(DelegatingFilter.java:73)
      	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610)
      	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:549)
      	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
      	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:602)
      	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
      	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
      	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1610)
      	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
      	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1369)
      	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
      	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:489)
      	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1580)
      	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
      	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1284)
      	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
      	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
      	at com.codahale.metrics.jetty9.InstrumentedHandler.handle(InstrumentedHandler.java:239)
      	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
      	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
      	at org.eclipse.jetty.server.Server.handle(Server.java:501)
      	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)
      	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:556)
      	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)
      	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:272)
      	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
      	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
      	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
      	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
      	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
      	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
      	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
      	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
      	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
      	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
      	at java.lang.Thread.run(Thread.java:748)
      

      In 3.25.0, you end up with a request.log entry, showing the total number of bytes downloaded before the request was abruptly terminated:

      Example terminating a file download that is actually 2324951919 bytes in size:

      127.0.0.1 - admin [04/Sep/2020:10:47:15 -0300] "GET /repository/raw-hosted/large.txt HTTP/1.1" 200 - 336199680 223 "curl/7.68.0" [qtp1000867003-54]

      Expected

      If inbound request headers are read successfully, then the request must be logged to the request.log, even if the request is abruptly terminated.

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              mallen Mick Allen
              Reporter:
              plynch Peter Lynch
              Last Updated By:
              Michael Prescott Michael Prescott
              Team:
              NXRM - Groot
              Votes:
              1 Vote for this issue
              Watchers:
              6 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved:
                Date of First Response:

                  tigCommentSecurity.panel-title