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

    • 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

          is related to

          Bug - A problem which impairs or prevents the functions of the product. NEXUS-12793 if java.lang.Error is thrown during request processing it may not be logged at default log levels

          • Critical - Crashes, loss of data, severe memory leak.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. NEXUS-17259 NullPointerException and upload hangs using UI to upload 5G file to raw repository

          • Major - Major loss of function.
          • Closed
          relates

          Bug - A problem which impairs or prevents the functions of the product. NEXUS-13048 java.lang.RuntimeException may not be logged correctly at default log levels

          • Major - Major loss of function.
          • Closed

          Activity

            People

              Unassigned Unassigned
              plynch Peter Lynch
              Rich Seddon Rich Seddon
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                tigCommentSecurity.panel-title