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

java.lang.RuntimeException may not be logged correctly at default log levels

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Duplicate
    • Affects Version/s: 3.3.0
    • Fix Version/s: None
    • Component/s: Logging

      Description

      Certain malformed HTTP requests may cause Nexus to return a 500 http status response to the caller. One example is in all versions of 3.x up to version 3.3.1, sending an empty User-Agent value in a request, will trigger a java.lang.NullPointerException and thus a 500 status.

      In general, it is intended that a server 500 error should be always logged at default log levels with a useful message.
      The same exception at DEBUG log levels should also include a stack trace. The cause should be clearly visible by the exception message regardless of level.
      If the exception is RuntimeException specifically, then a stack trace is always expected regardless of level, unless an exception to this rule was made deliberately.

      In the case mentioned, the NullPointerException is NOT visible at default log levels ( INFO and above ), only at DEBUG levels and without stack trace. This was not intentional.

      Expected

      • at default log levels, log at WARN unhandled RuntimeExceptions with stack trace ( this indicates a programming error that needs to be fixed and we should not hide this information)
      • prevent the mentioned NullPointerException in the first place ( see NEXUS-13136 )

      Details

      When a PUT is made to a RAW hosted repository, it may trigger a NullPointerException and a 500 response if the PUT is not well formed. Even at DEBUG log levels, the full stack trace is not logged.

      2017-04-26 10:52:28,603-0600 DEBUG [qtp916596984-1453] *UNKNOWN org.apache.shiro.session.mgt.DefaultSessionManager - Unable to resolve session ID from SessionKey [org.apache.shiro.web.session.mgt.WebSessionKey@448bca6d].  Returning null to indicate a session could not be found.
      2017-04-26 10:52:28,603-0600 DEBUG [qtp916596984-1453] *UNKNOWN org.sonatype.nexus.repository.httpbridge.internal.ViewServlet - Servicing: PUT /repository/Sencha_Release/catalog.json (http://nexus.healthlanguage.com:8081/repository/Sencha_Release/catalog.json)
      2017-04-26 10:52:28,604-0600 DEBUG [qtp916596984-1453] *UNKNOWN org.sonatype.nexus.repository.httpbridge.internal.ViewServlet - Parsed path: RepositoryPath{repositoryName='Sencha_Release', remainingPath='/catalog.json'}
      2017-04-26 10:52:28,604-0600 DEBUG [qtp916596984-1453] *UNKNOWN org.sonatype.nexus.repository.httpbridge.internal.ViewServlet - Looking for repository: Sencha_Release
      2017-04-26 10:52:28,604-0600 DEBUG [qtp916596984-1453] *UNKNOWN org.sonatype.nexus.repository.httpbridge.internal.ViewServlet - Repository: RepositoryImpl$$EnhancerByGuice$$c5f0822b{type=hosted, format=raw, name='Sencha_Release'}
      2017-04-26 10:52:28,604-0600 DEBUG [qtp916596984-1453] *UNKNOWN org.sonatype.nexus.repository.httpbridge.internal.ViewServlet - Dispatching to view facet: org.sonatype.nexus.repository.view.ConfigurableViewFacet$$EnhancerByGuice$$444d59e9@4c5dc22
      2017-04-26 10:52:28,604-0600 DEBUG [qtp916596984-1453] *UNKNOWN org.sonatype.nexus.repository.httpbridge.internal.HttpResponseSenderSelector - Looking for HTTP response sender: raw
      2017-04-26 10:52:28,604-0600 DEBUG [qtp916596984-1453] *UNKNOWN org.sonatype.nexus.repository.view.Router - Request: Request{action='PUT', path='/catalog.json', parameters={}, payload=HttpRequestPayloadAdapter{contentType='text/plain', size=439193}, multipart=false}
      2017-04-26 10:52:28,604-0600 DEBUG [qtp916596984-1453] *UNKNOWN org.sonatype.nexus.repository.view.matchers.logic.AndMatcher - Matching: org.sonatype.nexus.repository.view.matchers.ActionMatcher@3028ee52 AND SuffixMatcher{suffix='/', ignoreCase=false}
      2017-04-26 10:52:28,604-0600 DEBUG [qtp916596984-1453] *UNKNOWN org.sonatype.nexus.repository.view.matchers.token.TokenMatcher - Matching: /catalog.json~=TokenParser{pattern=\Q/\E(.+), variables=[var(name,.+)]}
      2017-04-26 10:52:28,604-0600 DEBUG [qtp916596984-1453] *UNKNOWN org.sonatype.nexus.repository.view.Context - Starting: Route{matcher=org.sonatype.nexus.repository.view.matchers.token.TokenMatcher@77f628ad, handlers=[org.sonatype.nexus.repository.view.handlers.TimingHandler@35271008, org.sonatype.nexus.repository.security.SecurityHandler@53495493, org.sonatype.nexus.repository.view.handlers.ExceptionHandler@65d47ee7, org.sonatype.nexus.repository.view.handlers.HandlerContributor@3b844dce, org.sonatype.nexus.repository.view.handlers.ConditionalRequestHandler@19f8b2b2, org.sonatype.nexus.repository.http.PartialFetchHandler@2f5a9a7c, org.sonatype.nexus.repository.view.handlers.ContentHeadersHandler@7c344934, org.sonatype.nexus.repository.storage.UnitOfWorkHandler@7b150e12, org.sonatype.nexus.repository.raw.internal.RawContentHandler@6e5595a1]}
      2017-04-26 10:52:28,604-0600 DEBUG [qtp916596984-1453] *UNKNOWN org.sonatype.nexus.repository.view.Context - Proceeding: org.sonatype.nexus.repository.view.handlers.TimingHandler@35271008
      2017-04-26 10:52:28,604-0600 DEBUG [qtp916596984-1453] *UNKNOWN org.sonatype.nexus.repository.view.Context - Proceeding: org.sonatype.nexus.repository.security.SecurityHandler@53495493
      2017-04-26 10:52:28,605-0600 DEBUG [qtp916596984-1453] *UNKNOWN org.apache.shiro.web.servlet.AdviceFilter - Filter execution resulted in an unexpected Exception (not IOException or ServletException as the Filter API recommends).  Wrapping in ServletException and propagating.
      2017-04-26 10:52:28,605-0600 DEBUG [qtp916596984-1453] *SYSTEM org.sonatype.nexus.internal.web.ErrorPageServlet - Attaching cause
      java.lang.NullPointerException: null
      

      We have indication that malformed request headers containing windows line endings may trigger this condition, but since the full stack is not printed we are not sure.

      Question: Why didn't the full stack trace get logged since the Throwable instance was passed as cause to log.debug(msg, cause)?

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              cpeters Collin Peters
              Reporter:
              plynch Peter Lynch
              Last Updated By:
              Peter Lynch Peter Lynch
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved:
                Date of First Response:

                  tigCommentSecurity.panel-title