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

500 response due to application/x-www-form-urlencoded request exceeding jetty max form size is not logged at default log levels

    XMLWordPrintable

    Details

    • Notability:
      n/a

      Description

      1. Create a Raw repository named site.
      2. upload using Content-Type: application/x-www-form-urlencoded a large file ( larger than default jetty max form size) 
      3. Response is 500, nexus.log does not log anything at default log levels

       

      Diagnoses

      1. set org.eclipse.jetty.server.Server logger to DEBUG
      2. set org.sonatype.nexus.internal.web.ErrorPageServlet logger to DEBUG
      3. repeat the large post, now will see that the cause is IllegalStateException due to max form exceeded.

      Here is (somewhat unorthodox) wget example simulating the error - yes we know wget is not suitable for simulating PUTs:

      http_proxy=http://localhost:8888 wget --http-user=admin --http-password=admin123 http://192.168.2.97:8081/repository/site/some/file2.war --body-file=large-file.war --method=PUT
      

      Debug logging, Nexus 3 master branch even after NEXUS-12793 was closed fixed

       

      2017-04-26 14:50:32,624-0300 DEBUG [qtp926240219-235] *SYSTEM org.eclipse.jetty.server.Server - REQUEST on HttpChannelOverHttp@6f735f94{r=1,c=false,a=DISPATCHED,uri=//192.168.2.97:8081/repository/site/some/file2.war}
      PUT //192.168.2.97:8081/repository/site/some/file2.war
      Cache-Control: no-cache, must-revalidate
      Pragma: no-cache
      User-Agent: Wget/1.18 (darwin15.5.0)
      Accept: */*
      Accept-Encoding: identity
      Host: 192.168.2.97:8081
      Connection: keep-alive
      Content-Type: application/x-www-form-urlencoded
      Content-Length: 13412440
      
      2017-04-26 14:50:32,628-0300 DEBUG [qtp926240219-235] *SYSTEM org.sonatype.nexus.internal.web.ErrorPageServlet - Attaching cause
      javax.servlet.ServletException: Filtered request failed.
      at org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:384) [na:na]
      at org.sonatype.nexus.security.SecurityFilter.doFilterInternal(SecurityFilter.java:101) [na:na]
      at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125) [na:na]
      at org.sonatype.nexus.repository.httpbridge.internal.ExhaustRequestFilter.doFilter(ExhaustRequestFilter.java:71) [na:na]
      at com.sonatype.nexus.licensing.internal.LicensingRedirectFilter.doFilter(LicensingRedirectFilter.java:112) [na:na]
      at com.codahale.metrics.servlet.AbstractInstrumentedFilter.doFilter(AbstractInstrumentedFilter.java:97) [na:na]
      at org.sonatype.nexus.internal.web.ErrorPageFilter.doFilter(ErrorPageFilter.java:68) [na:na]
      at org.sonatype.nexus.internal.web.EnvironmentFilter.doFilter(EnvironmentFilter.java:102) [na:na]
      at org.sonatype.nexus.internal.web.HeaderPatternFilter.doFilter(HeaderPatternFilter.java:98) [na:na]
      at com.google.inject.servlet.DynamicFilterPipeline.dispatch(DynamicFilterPipeline.java:104) [com.google.inject:4.1.0]
      at com.google.inject.servlet.GuiceFilter.doFilter(GuiceFilter.java:135) [com.google.inject:4.1.0]
      at org.sonatype.nexus.bootstrap.osgi.DelegatingFilter.doFilter(DelegatingFilter.java:73) [org.sonatype.nexus.bootstrap:3.3.1.SNAPSHOT]
      at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1668) [org.eclipse.jetty.servlet:9.3.7.v20160115]
      at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:581) [org.eclipse.jetty.servlet:9.3.7.v20160115]
      at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [org.eclipse.jetty.server:9.3.7.v20160115]
      at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) [org.eclipse.jetty.security:9.3.7.v20160115]
      at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226) [org.eclipse.jetty.server:9.3.7.v20160115]
      at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1158) [org.eclipse.jetty.server:9.3.7.v20160115]
      at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:511) [org.eclipse.jetty.servlet:9.3.7.v20160115]
      at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [org.eclipse.jetty.server:9.3.7.v20160115]
      at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1090) [org.eclipse.jetty.server:9.3.7.v20160115]
      at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [org.eclipse.jetty.server:9.3.7.v20160115]
      at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:119) [org.eclipse.jetty.server:9.3.7.v20160115]
      at com.codahale.metrics.jetty9.InstrumentedHandler.handle(InstrumentedHandler.java:175) [com.codahale.metrics.jetty9:3.0.2]
      at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:109) [org.eclipse.jetty.server:9.3.7.v20160115]
      at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:119) [org.eclipse.jetty.server:9.3.7.v20160115]
      at org.eclipse.jetty.server.Server.handle(Server.java:517) [org.eclipse.jetty.server:9.3.7.v20160115]
      at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:308) [org.eclipse.jetty.server:9.3.7.v20160115]
      at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:242) [org.eclipse.jetty.server:9.3.7.v20160115]
      at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273) [org.eclipse.jetty.io:9.3.7.v20160115]
      at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95) [org.eclipse.jetty.io:9.3.7.v20160115]
      at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:75) [org.eclipse.jetty.io:9.3.7.v20160115]
      at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceAndRun(ExecuteProduceConsume.java:213) [org.eclipse.jetty.util:9.3.7.v20160115]
      at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:147) [org.eclipse.jetty.util:9.3.7.v20160115]
      at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:654) [org.eclipse.jetty.util:9.3.7.v20160115]
      at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:572) [org.eclipse.jetty.util:9.3.7.v20160115]
      at java.lang.Thread.run(Thread.java:745) [na:1.8.0_121]
      Caused by: java.lang.IllegalStateException: Form too large: 13412440 > 200000
      at org.eclipse.jetty.server.Request.extractFormParameters(Request.java:473) [org.eclipse.jetty.server:9.3.7.v20160115]
      at org.eclipse.jetty.server.Request.extractContentParameters(Request.java:411) [org.eclipse.jetty.server:9.3.7.v20160115]
      at org.eclipse.jetty.server.Request.extractParameters(Request.java:363) [org.eclipse.jetty.server:9.3.7.v20160115]
      at org.eclipse.jetty.server.Request.getParameter(Request.java:989) [org.eclipse.jetty.server:9.3.7.v20160115]
      at javax.servlet.ServletRequestWrapper.getParameter(ServletRequestWrapper.java:194) [javax.servlet-api:3.1.0]
      at javax.servlet.ServletRequestWrapper.getParameter(ServletRequestWrapper.java:194) [javax.servlet-api:3.1.0]
      at org.apache.shiro.web.session.mgt.DefaultWebSessionManager.getReferencedSessionId(DefaultWebSessionManager.java:136) [na:na]
      at org.apache.shiro.web.session.mgt.DefaultWebSessionManager.getSessionId(DefaultWebSessionManager.java:279) [na:na]
      at org.apache.shiro.web.session.mgt.DefaultWebSessionManager.getSessionId(DefaultWebSessionManager.java:273) [na:na]
      at org.apache.shiro.session.mgt.DefaultSessionManager.retrieveSession(DefaultSessionManager.java:216) [na:na]
      at org.apache.shiro.session.mgt.AbstractValidatingSessionManager.doGetSession(AbstractValidatingSessionManager.java:118) [na:na]
      at org.apache.shiro.session.mgt.AbstractNativeSessionManager.lookupSession(AbstractNativeSessionManager.java:148) [na:na]
      at org.apache.shiro.session.mgt.AbstractNativeSessionManager.getSession(AbstractNativeSessionManager.java:140) [na:na]
      at org.apache.shiro.mgt.SessionsSecurityManager.getSession(SessionsSecurityManager.java:156) [na:na]
      at org.apache.shiro.mgt.DefaultSecurityManager.resolveContextSession(DefaultSecurityManager.java:456) [na:na]
      at org.apache.shiro.mgt.DefaultSecurityManager.resolveSession(DefaultSecurityManager.java:442) [na:na]
      at org.apache.shiro.mgt.DefaultSecurityManager.createSubject(DefaultSecurityManager.java:338) [na:na]
      at org.apache.shiro.subject.Subject$Builder.buildSubject(Subject.java:846) [na:na]
      at org.apache.shiro.web.subject.WebSubject$Builder.buildWebSubject(WebSubject.java:148) [na:na]
      at org.apache.shiro.web.servlet.AbstractShiroFilter.createSubject(AbstractShiroFilter.java:292) [na:na]
      at org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:359) [na:na]
      ... 36 common frames omitted
      
      2017-04-26 14:50:32,629-0300 DEBUG [qtp926240219-235] *SYSTEM org.eclipse.jetty.server.Server - RESPONSE for /repository/site/some/file2.war h=true
      500 null
      Date: Wed, 26 Apr 2017 17:50:32 GMT
      Server: Nexus/3.3.1-SNAPSHOT (PRO)
      X-Frame-Options: SAMEORIGIN
      X-Content-Type-Options: nosniff
      

      Expected

      • log at WARN a message without stacktrace that a POST exceeded max form size at default levels - this should happen for any POST request made to the entire server (including Docker repos at other ports ) that encounters this same problem

      Regression

      When a form post exceeds max for size in Nexus 2, you always see a WARN with stack trace in the logs.

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              Unassigned
              Reporter:
              plynch Peter Lynch
              Last Updated By:
              Rich Seddon
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved:
                Date of First Response:

                  tigCommentSecurity.panel-title