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

if java.lang.Error is thrown during request processing it may not be logged at default log levels

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Critical
    • Resolution: Fixed
    • Affects Version/s: 3.2.1
    • Fix Version/s: 3.3.1
    • Component/s: Logging
    • Labels:
    • Story Points:
      1
    • Sprint:
      Formats/Core Team - Sprint 93

      Description

      A report was made recently where an NPM package deployment was failing with a 500 response.

      Analysis was performed on the Nexus 3 logs

      request.log
      172.17.25.121 - admin [22/Mar/2017:23:11:27 +0000] "PUT /repository/uwp/@itg%2fwebstack HTTP/1.1" 500 0 4624 "npm/4.4.1 node/v6.9.5 win32 x64"
      

      Nexus log were completely silent about what happened:

      nexus.log
      2017-03-22 23:10:00,025+0000 INFO [quartz-1-thread-20] *SYSTEM org.sonatype.nexus.quartz.internal.task.QuartzTaskInfo - Task 'Storage facet cleanup' [repository.storage-facet-cleanup] state change RUNNING -> WAITING (OK)
      2017-03-22 23:13:37,011+0000 INFO [qtp983685524-42] uxteam org.sonatype.nexus.internal.wonderland.DownloadServiceImpl - Downloads directory: /nexus-data/downloads
      

      After changing the ROOT logger level to DEBUG the problem was reproduced and it was determined an OutOfMemoryError was being thrown:

      2017-03-28 21:26:06,353+0000 DEBUG [qtp1560565746-42] admin com.sonatype.nexus.repository.npm.internal.NpmHandlers - [putPackage] repository: uwp tokens: {packageScope=itg, packageName=webstack}
      2017-03-28 21:26:06,355+0000 DEBUG [qtp1560565746-42] admin org.sonatype.nexus.blobstore.file.internal.FileBlobStore - Writing blob tmp$3203ab6f-0137-4616-91a6-3ce772e49ebf to /nexus-data/blobs/default/content/tmp/tmp$3203ab6f-0137-4616-91a6-3ce772e49ebf.bytes
      2017-03-28 21:26:06,391+0000 DEBUG [AccessLogWriter] *SYSTEM com.sonatype.nexus.licensing.internal.access.AccessLogWriter - Wrote 1 rows
      2017-03-28 21:26:08,578+0000 DEBUG [nexus_QuartzSchedulerThread] *SYSTEM org.sonatype.nexus.quartz.internal.orient.JobStoreImpl - Acquire next triggers: noLaterThan=1490736398577, maxCount=1, timeWindow=0
      2017-03-28 21:26:09,579+0000 DEBUG [qtp1560565746-42] admin org.sonatype.nexus.common.property.PropertiesFile - Storing: /nexus-data/blobs/default/content/tmp/tmp$3203ab6f-0137-4616-91a6-3ce772e49ebf.587140a0-f99c-4cad-89a5-2dbd2b44b652.properties
      2017-03-28 21:26:09,581+0000 DEBUG [qtp1560565746-42] admin org.sonatype.nexus.repository.storage.StorageTxImpl - Transitioning: OPEN -> ACTIVE
      2017-03-28 21:26:09,581+0000 DEBUG [qtp1560565746-42] admin org.sonatype.nexus.repository.storage.StorageTxImpl - Transitioned: ACTIVE
      2017-03-28 21:26:09,581+0000 DEBUG [qtp1560565746-42] admin com.sonatype.nexus.repository.npm.internal.NpmHostedFacetImpl - Storing package: @itg/webstack
      2017-03-28 21:26:09,859+0000 DEBUG [nexus-httpclient-eviction-thread] *SYSTEM org.sonatype.nexus.internal.httpclient.SharedHttpClientConnectionManager - Closing expired connections
      2017-03-28 21:26:09,859+0000 DEBUG [nexus-httpclient-eviction-thread] *SYSTEM org.sonatype.nexus.internal.httpclient.SharedHttpClientConnectionManager - Closing connections idle longer than 30000 MILLISECONDS
      2017-03-28 21:26:10,283+0000 DEBUG [qtp1560565746-46] *UNKNOWN org.apache.shiro.web.servlet.SimpleCookie - Found 'NXSESSIONID' cookie value [c888ee23-5e86-4049-a7e8-0cb5b6d14757]
      2017-03-28 21:26:10,284+0000 DEBUG [qtp1560565746-46] uxteam com.softwarementors.extjs.djn.router.processor.poll.PollRequestProcessor - Request data (POLL)=>anonymousUsername=0164dd50523969de34f4d8d75d6cfb46e269fecd&uiSettings=059e1973fddfadb8cf4427d23ea5fe51198a3427&serverId=70042a042d1d9725ccdc1f531f64cc04cddc1648&analytics=ac0b77a721ddea2e2231fd1b213b4080a09e075e&activeBundles=a14e668e3aa94ba43c5265fa76070b0f940bbee9&license=ffbea1347377d561a92c4c981b84374e3cddf5b1&audit=ac0b77a721ddea2e2231fd1b213b4080a09e075e&permissions=c3178ca8aa6bf114cb8b2d59a09be94915dd53e1&migration=ac0b77a721ddea2e2231fd1b213b4080a09e075e&browseableformats=78028ac5d7afe60917fe88d8734b614665628989&user=5af6359a60e883b221026902300355ca7276809f&db=dc2b0c34765896e5b30abc6af5161718ee033ff1&status=04ffe184b3c52621f741f75c3765961e325245f5 Event name='rapture_State_get'
      2017-03-28 21:26:10,284+0000 DEBUG [qtp1560565746-46] uxteam org.sonatype.nexus.extdirect.internal.ExtDirectServlet - Creating instance of action class 'org.sonatype.nexus.rapture.internal.state.StateComponent' mapped to 'rapture_State
      2017-03-28 21:26:10,284+0000 DEBUG [qtp1560565746-46] uxteam org.sonatype.nexus.extdirect.internal.ExtDirectServlet - Invoking action method: rapture_State.rapture_State_get, java-method: org.sonatype.nexus.rapture.internal.state.StateComponent.getState
      2017-03-28 21:26:10,290+0000 DEBUG [qtp1560565746-46] uxteam org.sonatype.nexus.rapture.internal.security.SecurityComponent - Calculating permissions
      2017-03-28 21:26:10,293+0000 DEBUG [qtp1560565746-46] uxteam com.softwarementors.extjs.djn.Timer -   - Java method dispatch time (StateComponent.rapture_State_get): 8.63 ms.
      2017-03-28 21:26:10,294+0000 DEBUG [qtp1560565746-46] uxteam com.softwarementors.extjs.djn.router.processor.poll.PollRequestProcessor - ResponseData data (POLL)=>{"data":{"success":true,"data":{}},"name":"rapture_State_get","type":"event"}
      2017-03-28 21:26:10,294+0000 DEBUG [qtp1560565746-46] uxteam com.softwarementors.extjs.djn.Timer - Total servlet processing time: 9.6 ms.
      2017-03-28 21:26:10,986+0000 DEBUG [file-blobstore-metrics-2-thread-1] *SYSTEM org.sonatype.nexus.common.property.PropertiesFile - Storing: /nexus-data/blobs/default/99F177D0-34BD076E-72732585-7A28CC73-89EF2E26-metrics.properties
      2017-03-28 21:26:10,986+0000 DEBUG [qtp1560565746-42] admin org.sonatype.nexus.repository.storage.StorageTxImpl - Transitioning: ACTIVE -> CLOSED
      2017-03-28 21:26:10,987+0000 DEBUG [qtp1560565746-42] admin org.sonatype.nexus.repository.storage.StorageTxImpl - Transitioned: CLOSED
      2017-03-28 21:26:10,988+0000 DEBUG [qtp1560565746-42] admin org.sonatype.nexus.blobstore.file.internal.FileBlobStore - Hard deleting blob tmp$3203ab6f-0137-4616-91a6-3ce772e49ebf
      2017-03-28 21:26:10,988+0000 DEBUG [qtp1560565746-42] admin org.sonatype.nexus.common.property.PropertiesFile - Loading: /nexus-data/blobs/default/content/tmp/tmp$3203ab6f-0137-4616-91a6-3ce772e49ebf.properties
      2017-03-28 21:26:11,014+0000 DEBUG [qtp1560565746-42] admin org.sonatype.nexus.blobstore.file.internal.FileBlobStore - Deleted /nexus-data/blobs/default/content/tmp/tmp$3203ab6f-0137-4616-91a6-3ce772e49ebf.bytes
      2017-03-28 21:26:11,014+0000 DEBUG [qtp1560565746-42] admin org.sonatype.nexus.blobstore.file.internal.FileBlobStore - Deleted /nexus-data/blobs/default/content/tmp/tmp$3203ab6f-0137-4616-91a6-3ce772e49ebf.properties
      2017-03-28 21:26:11,020+0000 DEBUG [qtp1560565746-42] *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 com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82) [com.google.inject:4.1.0]
      	at org.sonatype.nexus.repository.httpbridge.internal.ExhaustRequestFilter.doFilter(ExhaustRequestFilter.java:71) [na:na]
      	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82) [com.google.inject:4.1.0]
      	at com.sonatype.nexus.licensing.internal.LicensingRedirectFilter.doFilter(LicensingRedirectFilter.java:112) [na:na]
      	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82) [com.google.inject:4.1.0]
      	at com.codahale.metrics.servlet.AbstractInstrumentedFilter.doFilter(AbstractInstrumentedFilter.java:97) [na:na]
      	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82) [com.google.inject:4.1.0]
      	at org.sonatype.nexus.internal.web.ErrorPageFilter.doFilter(ErrorPageFilter.java:68) [na:na]
      	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82) [com.google.inject:4.1.0]
      	at org.sonatype.nexus.internal.web.EnvironmentFilter.doFilter(EnvironmentFilter.java:102) [org.sonatype.nexus.base:3.2.1.01]
      	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82) [com.google.inject:4.1.0]
      	at org.sonatype.nexus.internal.web.HeaderPatternFilter.doFilter(HeaderPatternFilter.java:98) [org.sonatype.nexus.base:3.2.1.01]
      	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82) [com.google.inject:4.1.0]
      	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.2.1.01]
      	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_112]
      Caused by: java.lang.OutOfMemoryError: Java heap space
      	at java.util.Arrays.copyOfRange(Arrays.java:3664) [na:1.8.0_112]
      	at java.lang.String.<init>(String.java:207) [na:1.8.0_112]
      	at java.lang.StringBuilder.toString(StringBuilder.java:407) [na:1.8.0_112]
      	at com.fasterxml.jackson.core.util.TextBuffer.contentsAsString(TextBuffer.java:356) [na:na]
      	at com.fasterxml.jackson.core.json.UTF8StreamJsonParser._finishAndReturnString(UTF8StreamJsonParser.java:2466) [na:na]
      	at com.fasterxml.jackson.core.json.UTF8StreamJsonParser.getText(UTF8StreamJsonParser.java:315) [na:na]
      	at com.fasterxml.jackson.databind.deser.std.UntypedObjectDeserializer$Vanilla.deserialize(UntypedObjectDeserializer.java:514) [na:na]
      	at com.fasterxml.jackson.databind.deser.std.UntypedObjectDeserializer$Vanilla.mapObject(UntypedObjectDeserializer.java:638) [na:na]
      	at com.fasterxml.jackson.databind.deser.std.UntypedObjectDeserializer$Vanilla.deserialize(UntypedObjectDeserializer.java:496) [na:na]
      	at com.fasterxml.jackson.databind.deser.std.UntypedObjectDeserializer$Vanilla.mapObject(UntypedObjectDeserializer.java:629) [na:na]
      	at com.fasterxml.jackson.databind.deser.std.UntypedObjectDeserializer$Vanilla.deserialize(UntypedObjectDeserializer.java:496) [na:na]
      	at com.fasterxml.jackson.databind.deser.std.MapDeserializer._readAndBindStringKeyMap(MapDeserializer.java:507) [na:na]
      	at com.fasterxml.jackson.databind.deser.std.MapDeserializer.deserialize(MapDeserializer.java:352) [na:na]
      	at com.fasterxml.jackson.databind.deser.std.MapDeserializer.deserialize(MapDeserializer.java:27) [na:na]
      	at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:3789) [na:na]
      	at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:2906) [na:na]
      	at com.sonatype.nexus.repository.npm.internal.NpmJsonUtils.parse(NpmJsonUtils.java:69) [na:na]
      	at com.sonatype.nexus.repository.npm.internal.NpmFacetUtils.parse(NpmFacetUtils.java:94) [na:na]
      	at com.sonatype.nexus.repository.npm.internal.NpmHostedFacetImpl.putPackageRoot(NpmHostedFacetImpl.java:98) [na:na]
      	at org.sonatype.nexus.transaction.TransactionalWrapper.proceedWithTransaction(TransactionalWrapper.java:56) [na:na]
      	at org.sonatype.nexus.transaction.TransactionInterceptor.invoke(TransactionInterceptor.java:54) [na:na]
      	at com.sonatype.nexus.repository.npm.internal.NpmHostedFacetImpl.putPackage(NpmHostedFacetImpl.java:81) [na:na]
      	at com.sonatype.nexus.repository.npm.internal.NpmHandlers$3.handle(NpmHandlers.java:172) [na:na]
      	at org.sonatype.nexus.repository.view.Context.proceed(Context.java:80) [na:na]
      	at org.sonatype.nexus.repository.storage.UnitOfWorkHandler.handle(UnitOfWorkHandler.java:39) [na:na]
      2017-03-28 21:26:12,800+0000 DEBUG [file-blobstore-metrics-2-thread-1] *SYSTEM org.sonatype.nexus.common.property.PropertiesFile - Storing: /nexus-data/blobs/default/99F177D0-34BD076E-72732585-7A28CC73-89EF2E26-metrics.properties
      

      Expected

      • Nexus should ALWAYS attempt to log java.lang.Error derivatives at ERROR log levels at the shallowest stack depth
      • logging java.lang.Error should not depend on some higher level log statement
      • one should not have to enable DEBUG log levels to notice an OutOfMemoryError

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              jtom Joe Tom
              Reporter:
              plynch Peter Lynch
              Last Updated By:
              Peter Lynch
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved:
                Date of First Response:

                  tigCommentSecurity.panel-title