[NEXUS-11518] ProxyServiceException stack trace logged at WARN when remote responds with HTTP/1.1 401 Created: 11/04/16  Updated: 01/23/17  Resolved: 01/04/17

Status: Closed
Project: Dev - Nexus Repo
Component/s: Logging, Transport
Affects Version/s: 3.0.2
Fix Version/s: 3.2.1

Type: Bug Priority: Major
Reporter: Peter Lynch Assignee: Joe Tom
Resolution: Fixed Votes: 0
Labels: supportant
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: PNG File Screen Shot 2017-01-04 at 9.59.26 AM.png    
Issue Links:
Bonfire Testing
testing discovered NEXUS-11872 Deleting a repository with an item in... Closed
Relates
Last Updated By: Joe Tom
Date of First Response:
Story Points: 0.5
Sprint: Sprint 85, Sprint 86

 Description   

When the remote proxy repository responds with 401, a stack trace at WARN is on the logs.

2016-11-04 06:31:48,814-0700 WARN  [qtp1250484473-16157] admin org.sonatype.nexus.repository.maven.internal.proxy.MavenProxyFacet - Failed to fetch: com/ibm/analytics/entity/entity-model-content/1.0.15-SNAPSHOT/maven-metadata.xml
org.sonatype.nexus.repository.proxy.ProxyServiceException: HTTP/1.1 401 Unauthorized
	at org.sonatype.nexus.repository.proxy.ProxyFacetSupport.mayThrowProxyServiceException(ProxyFacetSupport.java:280) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.proxy.ProxyFacetSupport.fetch(ProxyFacetSupport.java:254) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.proxy.ProxyFacetSupport.fetch(ProxyFacetSupport.java:210) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.maven.internal.proxy.MavenProxyFacet.fetch(MavenProxyFacet.java:75) [na:na]
	at org.sonatype.nexus.repository.proxy.ProxyFacetSupport.get(ProxyFacetSupport.java:166) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.proxy.ProxyHandler.handle(ProxyHandler.java:49) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.Context.proceed(Context.java:79) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.storage.UnitOfWorkHandler.handle(UnitOfWorkHandler.java:39) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.Context.proceed(Context.java:79) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.handlers.ContentHeadersHandler.handle(ContentHeadersHandler.java:44) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.Context.proceed(Context.java:79) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.cache.NegativeCacheHandler.handle(NegativeCacheHandler.java:50) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.Context.proceed(Context.java:79) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.handlers.ConditionalRequestHandler.handle(ConditionalRequestHandler.java:72) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.Context.proceed(Context.java:79) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.handlers.ExceptionHandler.handle(ExceptionHandler.java:41) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.Context.proceed(Context.java:79) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.security.SecurityHandler.handle(SecurityHandler.java:45) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.Context.proceed(Context.java:79) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.handlers.TimingHandler.handle(TimingHandler.java:46) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.Context.proceed(Context.java:79) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.Context.start(Context.java:102) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.Router.dispatch(Router.java:58) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.ConfigurableViewFacet.dispatch(ConfigurableViewFacet.java:43) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.group.GroupHandler.getAll(GroupHandler.java:147) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.maven.internal.group.MergingGroupHandler.doGet(MergingGroupHandler.java:70) [org.sonatype.nexus.plugins.nexus-repository-maven:3.0.2.02]
	at org.sonatype.nexus.repository.group.GroupHandler.handle(GroupHandler.java:79) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.Context.proceed(Context.java:79) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.storage.UnitOfWorkHandler.handle(UnitOfWorkHandler.java:39) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.Context.proceed(Context.java:79) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.handlers.ContentHeadersHandler.handle(ContentHeadersHandler.java:44) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.Context.proceed(Context.java:79) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.handlers.ConditionalRequestHandler.handle(ConditionalRequestHandler.java:72) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.Context.proceed(Context.java:79) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.handlers.ExceptionHandler.handle(ExceptionHandler.java:41) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.Context.proceed(Context.java:79) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.security.SecurityHandler.handle(SecurityHandler.java:45) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.Context.proceed(Context.java:79) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.handlers.TimingHandler.handle(TimingHandler.java:46) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.Context.proceed(Context.java:79) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.Context.start(Context.java:102) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.Router.dispatch(Router.java:58) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.view.ConfigurableViewFacet.dispatch(ConfigurableViewFacet.java:43) [org.sonatype.nexus.repository:3.0.2.02]
	at org.sonatype.nexus.repository.httpbridge.internal.ViewServlet.dispatchAndSend(ViewServlet.java:198) [org.sonatype.nexus.plugins.nexus-repository-httpbridge:3.0.2.02]
	at org.sonatype.nexus.repository.httpbridge.internal.ViewServlet.doService(ViewServlet.java:160) [org.sonatype.nexus.plugins.nexus-repository-httpbridge:3.0.2.02]
	at org.sonatype.nexus.repository.httpbridge.internal.ViewServlet.service(ViewServlet.java:117) [org.sonatype.nexus.plugins.nexus-repository-httpbridge:3.0.2.02]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) [javax.servlet-api:3.1.0]
	at com.google.inject.servlet.ServletDefinition.doServiceImpl(ServletDefinition.java:287) [com.google.inject:4.0.0]
	at com.google.inject.servlet.ServletDefinition.doService(ServletDefinition.java:277) [com.google.inject:4.0.0]
	at com.google.inject.servlet.ServletDefinition.service(ServletDefinition.java:182) [com.google.inject:4.0.0]
	at com.google.inject.servlet.DynamicServletPipeline.service(DynamicServletPipeline.java:71) [com.google.inject:4.0.0]
	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:85) [com.google.inject:4.0.0]
	at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:112) [org.apache.shiro.web:1.2.4]
	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82) [com.google.inject:4.0.0]
	at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:112) [org.apache.shiro.web:1.2.4]
	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82) [com.google.inject:4.0.0]
	at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:61) [org.apache.shiro.web:1.2.4]
	at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108) [org.apache.shiro.web:1.2.4]
	at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137) [org.apache.shiro.web:1.2.4]
	at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125) [org.apache.shiro.web:1.2.4]
	at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:66) [org.apache.shiro.web:1.2.4]
	at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108) [org.apache.shiro.web:1.2.4]
	at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137) [org.apache.shiro.web:1.2.4]
	at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125) [org.apache.shiro.web:1.2.4]
	at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:66) [org.apache.shiro.web:1.2.4]
	at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108) [org.apache.shiro.web:1.2.4]
	at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137) [org.apache.shiro.web:1.2.4]
	at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125) [org.apache.shiro.web:1.2.4]
	at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:66) [org.apache.shiro.web:1.2.4]
	at org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:449) [org.apache.shiro.web:1.2.4]
	at org.sonatype.nexus.security.SecurityFilter.executeChain(SecurityFilter.java:85) [org.sonatype.nexus.security:3.0.2.02]
	at org.apache.shiro.web.servlet.AbstractShiroFilter$1.call(AbstractShiroFilter.java:365) [org.apache.shiro.web:1.2.4]
	at org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:90) [org.apache.shiro.core:1.2.4]
	at org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:83) [org.apache.shiro.core:1.2.4]
	at org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:383) [org.apache.shiro.core:1.2.4]
	at org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:362) [org.apache.shiro.web:1.2.4]
	at org.sonatype.nexus.security.SecurityFilter.doFilterInternal(SecurityFilter.java:101) [org.sonatype.nexus.security:3.0.2.02]
	at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125) [org.apache.shiro.web:1.2.4]
	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82) [com.google.inject:4.0.0]
	at com.codahale.metrics.servlet.AbstractInstrumentedFilter.doFilter(AbstractInstrumentedFilter.java:97) [com.codahale.metrics.servlet:3.0.2]
	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82) [com.google.inject:4.0.0]
	at org.sonatype.nexus.internal.web.ErrorPageFilter.doFilter(ErrorPageFilter.java:63) [org.sonatype.nexus.base:3.0.2.02]
	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82) [com.google.inject:4.0.0]
	at org.sonatype.nexus.internal.web.EnvironmentFilter.doFilter(EnvironmentFilter.java:97) [org.sonatype.nexus.base:3.0.2.02]
	at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82) [com.google.inject:4.0.0]
	at com.google.inject.servlet.DynamicFilterPipeline.dispatch(DynamicFilterPipeline.java:104) [com.google.inject:4.0.0]
	at com.google.inject.servlet.GuiceFilter$1.call(GuiceFilter.java:133) [com.google.inject:4.0.0]
	at com.google.inject.servlet.GuiceFilter$1.call(GuiceFilter.java:130) [com.google.inject:4.0.0]
	at com.google.inject.servlet.GuiceFilter$Context.call(GuiceFilter.java:203) [com.google.inject:4.0.0]
	at com.google.inject.servlet.GuiceFilter.doFilter(GuiceFilter.java:130) [com.google.inject:4.0.0]
	at org.sonatype.nexus.bootstrap.osgi.DelegatingFilter.doFilter(DelegatingFilter.java:73) [org.sonatype.nexus.bootstrap:3.0.2.02]
	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.ssl.SslConnection.onFillable(SslConnection.java:197) [org.eclipse.jetty.io: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_92]

This is not desireable. One does not need a full stack trace at WARN level for a 401 response from the remote.

Expected

Log a message at WARN level if the outbound request failed because the expected response code did not match the received response code, with a simple message showing expected code and received HTTP status line.
If the same Logger is at DEBUG levels, print the same message using the WARN logger, but also include the full stack trace.



 Comments   
Comment by Joe Tom [ 01/04/17 ]

These logging statements are now severely trimmed down unless on DEBUG level or higher. Thanks!

Generated at Tue Oct 23 20:54:14 UTC 2018 using JIRA 7.3.3#73014-sha1:d5be8da522213be2ca9ad7b043c51da6e4cc9754.