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

UnauthenticatedException should not be logged as ERROR

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Minor
    • Resolution: Duplicate
    • Affects Version/s: 3.0.0-m7, 3.0.2
    • Fix Version/s: None
    • Component/s: Logging
    • Labels:
    • Story Points:
      1

      Description

      When someone has an old browser session and they are viewing the Nexus UI, and they need to be authenticated again, Nexus can spit ERROR level log messages in the log related to org.apache.shiro.authz.UnauthenticatedException.

      2016-09-28 14:39:27,809+0200 INFO  [jetty-main-1] *SYSTEM org.sonatype.nexus.bootstrap.jetty.JettyServer - 
      -------------------------------------------------
      
      Started Sonatype Nexus OSS 3.0.2-02
      
      -------------------------------------------------
      2016-09-28 14:40:05,548+0200 INFO  [qtp1884520425-161] *UNKNOWN org.apache.shiro.session.mgt.AbstractValidatingSessionManager - Enabling session validation scheduler...
      2016-09-28 14:40:05,565+0200 INFO  [qtp1884520425-161] *UNKNOWN org.sonatype.nexus.security.internal.AnonymousManagerImpl - Loaded configuration: AnonymousConfiguration{enabled=true, userId='anonymous', realmName='NexusAuthorizingRealm'}
      2016-09-28 14:40:20,363+0200 INFO  [qtp1884520425-651] *UNKNOWN com.sonatype.nexus.analytics.internal.EventSubmitterImpl - Service URL: https://analytics.sonatype.com
      2016-09-28 14:41:42,369+0200 ERROR [qtp1884520425-608] *UNKNOWN org.sonatype.nexus.extdirect.internal.ExtDirectServlet - Failed to invoke action method: coreui_Repository.coreui_Repository_readStatus, java-method: org.sonatype.nexus.coreui.RepositoryComponent.readStatus
      org.apache.shiro.authz.UnauthenticatedException: The current Subject is not authenticated.  Access denied.
      	at org.apache.shiro.authz.aop.AuthenticatedAnnotationHandler.assertAuthorized(AuthenticatedAnnotationHandler.java:53) [na:na]
      	at org.apache.shiro.authz.aop.AuthorizingAnnotationMethodInterceptor.assertAuthorized(AuthorizingAnnotationMethodInterceptor.java:84) [na:na]
      	at org.apache.shiro.authz.aop.AuthorizingAnnotationMethodInterceptor.invoke(AuthorizingAnnotationMethodInterceptor.java:67) [na:na]
      	at org.apache.shiro.guice.aop.AopAllianceMethodInterceptorAdapter.invoke(AopAllianceMethodInterceptorAdapter.java:36) [na:na]
      	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [na:1.8.0_92]
      	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) [na:1.8.0_92]
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [na:1.8.0_92]
      	at java.lang.reflect.Method.invoke(Method.java:498) [na:1.8.0_92]
      	at com.softwarementors.extjs.djn.router.dispatcher.DispatcherBase.invokeJavaMethod(DispatcherBase.java:142) [org.sonatype.nexus.extdirect:3.0.2.02]
      	at com.softwarementors.extjs.djn.router.dispatcher.DispatcherBase.invokeMethod(DispatcherBase.java:133) [org.sonatype.nexus.extdirect:3.0.2.02]
      	at org.sonatype.nexus.extdirect.internal.ExtDirectServlet$3.invokeMethod(ExtDirectServlet.java:221) [org.sonatype.nexus.extdirect:3.0.2.02]
      	at com.softwarementors.extjs.djn.router.dispatcher.DispatcherBase.dispatch(DispatcherBase.java:63) [org.sonatype.nexus.extdirect:3.0.2.02]
      	at com.softwarementors.extjs.djn.router.processor.poll.PollRequestProcessor.process(PollRequestProcessor.java:145) [org.sonatype.nexus.extdirect:3.0.2.02]
      	at org.sonatype.nexus.extdirect.internal.ExtDirectServlet$4.processPollRequest(ExtDirectServlet.java:315) [org.sonatype.nexus.extdirect:3.0.2.02]
      	at com.softwarementors.extjs.djn.servlet.DirectJNgineServlet.processRequest(DirectJNgineServlet.java:621) [org.sonatype.nexus.extdirect:3.0.2.02]
      	at com.softwarementors.extjs.djn.servlet.DirectJNgineServlet.doPost(DirectJNgineServlet.java:580) [org.sonatype.nexus.extdirect:3.0.2.02]
      	at org.sonatype.nexus.extdirect.internal.ExtDirectServlet.doPost(ExtDirectServlet.java:127) [org.sonatype.nexus.extdirect:3.0.2.02]
      	at com.softwarementors.extjs.djn.servlet.DirectJNgineServlet.doGet(DirectJNgineServlet.java:553) [org.sonatype.nexus.extdirect:3.0.2.02]
      	at javax.servlet.http.HttpServlet.service(HttpServlet.java:687) [javax.servlet-api:3.1.0]
      	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.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.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]
      Caused by: org.apache.shiro.authz.AuthorizationException: Not authorized to invoke method: public java.util.List org.sonatype.nexus.coreui.RepositoryComponent.readStatus(java.util.Map)
      	at org.apache.shiro.authz.aop.AuthorizingAnnotationMethodInterceptor.assertAuthorized(AuthorizingAnnotationMethodInterceptor.java:90) [na:na]
      	... 83 common frames omitted
      

      Expected

      • permission problems due to unauthenticated access should not be logged at ERROR level. This causes unwarranted concern from log scanners looking for more critical ERROR level server issues. It is completely normal in a server application that sessions sent from a browser can have been expired on the server. This is not an ERROR condition.

        Attachments

          Issue Links

            Activity

              People

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

                Dates

                Created:
                Updated:
                Resolved:
                Date of First Response:

                  tigCommentSecurity.panel-title