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

Could not dispatch event for auditing at migration end because the session id was not valid

Details

    • 3

    Description

      A migration from NXRM 2 to NXRM 3 was taking place. The migration was ended in step 8 of 9, which as by design tries to record nxrm 3 Audit events for RepositoryStopped events.

      Recording these stop events failed because the event handling code tries to determine the userid making the request from a session object and the session could not be found. This is an example of what stack trace this causes when using NXRM 3.34.0.

      Notice that the user is known to be "admin" ( since the log message includes "admin" user id ) but the event code cannot find a matching session for that user. There was no logged session deletion recorded, however there were two login session creations logged 4 seconds apart, prior to migration being ended.

      2021-09-20 14:03:16,014+0000 INFO  [qtp1538102844-13380]  admin org.sonatype.nexus.rapture.internal.security.SessionServlet - Created session for user: admin
      
      2021-09-20 14:03:20,080+0000 INFO  [qtp1538102844-18562]  admin org.sonatype.nexus.rapture.internal.security.SessionServlet - Created session for user: admin
      
      2021-09-20 14:09:30,466+0000 ERROR [plan-executor-14-thread-10]  admin com.google.common.eventbus.EventBus.nexus - Could not dispatch event RepositoryStoppedEvent{repository=RepositoryImpl$$EnhancerByGuice$$522978809{type=hosted, format=maven2, name='agent-plugin-releases'}} to subscriber org.sonatype.nexus.repository.manager.internal.RepositoryAuditor@1f945939 method [public void org.sonatype.nexus.repository.manager.internal.RepositoryAuditor.on(org.sonatype.nexus.repository.RepositoryEvent)]
      org.apache.shiro.session.UnknownSessionException: There is no session with id [ea61d40b-f777-444e-800a-0bdc66df8b0a]
      	at org.apache.shiro.session.mgt.eis.AbstractSessionDAO.readSession(AbstractSessionDAO.java:170)
      	at org.apache.shiro.session.mgt.eis.CachingSessionDAO.readSession(CachingSessionDAO.java:261)
      	at org.apache.shiro.session.mgt.DefaultSessionManager.retrieveSessionFromDataSource(DefaultSessionManager.java:236)
      	at org.apache.shiro.session.mgt.DefaultSessionManager.retrieveSession(DefaultSessionManager.java:222)
      	at org.apache.shiro.session.mgt.AbstractValidatingSessionManager.doGetSession(AbstractValidatingSessionManager.java:118)
      	at org.apache.shiro.session.mgt.AbstractNativeSessionManager.lookupSession(AbstractNativeSessionManager.java:148)
      	at org.apache.shiro.session.mgt.AbstractNativeSessionManager.lookupRequiredSession(AbstractNativeSessionManager.java:152)
      	at org.apache.shiro.session.mgt.AbstractNativeSessionManager.getAttribute(AbstractNativeSessionManager.java:249)
      	at org.apache.shiro.session.mgt.DelegatingSession.getAttribute(DelegatingSession.java:141)
      	at org.apache.shiro.session.ProxiedSession.getAttribute(ProxiedSession.java:121)
      	at org.apache.shiro.subject.support.DelegatingSubject.getRunAsPrincipalsStack(DelegatingSubject.java:473)
      	at org.apache.shiro.subject.support.DelegatingSubject.getPrincipals(DelegatingSubject.java:157)
      	at org.apache.shiro.subject.support.DelegatingSubject.getPrincipal(DelegatingSubject.java:153)
      	at org.sonatype.nexus.security.UserIdHelper.get(UserIdHelper.java:55)
      	at org.sonatype.nexus.security.UserIdHelper.get(UserIdHelper.java:47)
      	at org.sonatype.nexus.audit.internal.InitiatorProviderImpl.get(InitiatorProviderImpl.java:57)
      	at org.sonatype.nexus.audit.internal.AuditRecorderImpl.record(AuditRecorderImpl.java:88)
      	at org.sonatype.nexus.audit.AuditorSupport.record(AuditorSupport.java:127)
      	at org.sonatype.nexus.repository.manager.internal.RepositoryAuditor.on(RepositoryAuditor.java:99)
      	at sun.reflect.GeneratedMethodAccessor536.invoke(Unknown Source)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.lang.reflect.Method.invoke(Method.java:498)
      	at com.google.common.eventbus.Subscriber.invokeSubscriberMethod(Subscriber.java:87)
      	at com.google.common.eventbus.Subscriber$1.run(Subscriber.java:72)
      	at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
      	at com.google.common.eventbus.Subscriber.dispatchEvent(Subscriber.java:67)
      	at com.google.common.eventbus.Dispatcher$ImmediateDispatcher.dispatch(Dispatcher.java:186)
      	at com.google.common.eventbus.EventBus.post(EventBus.java:212)
      	at org.sonatype.nexus.internal.event.EventManagerImpl.post(EventManagerImpl.java:127)
      	at org.sonatype.nexus.repository.manager.internal.RepositoryImpl.stop(RepositoryImpl.java:257)
      	at org.sonatype.nexus.repository.manager.internal.RepositoryImpl$$EnhancerByGuice$$522978809.GUICE$TRAMPOLINE(<generated>)
      	at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:74)
      	at org.sonatype.nexus.common.stateguard.MethodInvocationAction.run(MethodInvocationAction.java:39)
      	at org.sonatype.nexus.common.stateguard.StateGuard$TransitionImpl.run(StateGuard.java:193)
      	at org.sonatype.nexus.common.stateguard.TransitionsInterceptor.invoke(TransitionsInterceptor.java:57)
      	at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:75)
      	at com.google.inject.internal.InterceptorStackCallback.invoke(InterceptorStackCallback.java:55)
      	at org.sonatype.nexus.repository.manager.internal.RepositoryImpl$$EnhancerByGuice$$522978809.stop(<generated>)
      	at org.sonatype.nexus.repository.manager.internal.RepositoryManagerImpl.update(RepositoryManagerImpl.java:381)
      	at org.sonatype.nexus.repository.manager.internal.RepositoryManagerImpl$$EnhancerByGuice$$433484108.GUICE$TRAMPOLINE(<generated>)
      	at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:74)
      	at org.sonatype.nexus.common.stateguard.MethodInvocationAction.run(MethodInvocationAction.java:39)
      	at org.sonatype.nexus.common.stateguard.StateGuard$GuardImpl.run(StateGuard.java:272)
      	at org.sonatype.nexus.common.stateguard.GuardedInterceptor.invoke(GuardedInterceptor.java:54)
      	at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:75)
      	at com.google.inject.internal.InterceptorStackCallback.invoke(InterceptorStackCallback.java:55)
      	at org.sonatype.nexus.repository.manager.internal.RepositoryManagerImpl$$EnhancerByGuice$$433484108.update(<generated>)
      	at org.sonatype.nexus.repository.manager.RepositoryManager$update$1.call(Unknown Source)
      	at com.sonatype.nexus.migration.repository.RepositoryFinishStep.doRun(RepositoryFinishStep.groovy:125)
      	at com.sonatype.nexus.migration.plan.Step.run(Step.groovy:271)
      	at com.sonatype.nexus.migration.plan.Step$run$1.call(Unknown Source)
      	at com.sonatype.nexus.migration.plan.StepExecutor.runSync(StepExecutor.groovy:168)
      	at sun.reflect.GeneratedMethodAccessor316.invoke(Unknown Source)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.lang.reflect.Method.invoke(Method.java:498)
      	at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:98)
      	at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:325)
      	at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:352)
      	at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1034)
      	at org.codehaus.groovy.runtime.callsite.PogoMetaClassSite.callCurrent(PogoMetaClassSite.java:68)
      	at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:169)
      	at com.sonatype.nexus.migration.plan.StepExecutor$_runAsync_closure1.doCall(StepExecutor.groovy:197)
      	at com.sonatype.nexus.migration.plan.StepExecutor$_runAsync_closure1.doCall(StepExecutor.groovy)
      	at sun.reflect.GeneratedMethodAccessor375.invoke(Unknown Source)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.lang.reflect.Method.invoke(Method.java:498)
      	at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:98)
      	at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:325)
      	at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:264)
      	at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1034)
      	at groovy.lang.Closure.call(Closure.java:420)
      	at groovy.lang.Closure.call(Closure.java:414)
      	at groovy.lang.Closure.run(Closure.java:501)
      	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
      	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
      	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
      	at java.lang.Thread.run(Thread.java:748)
      
      

      Here is another example for the org.sonatype.nexus.internal.httpclient.HttpClientAuditor class with Repo 3.38.1 (PostgreSQL).

      rg --no-line-number '2022-05-20 03:19:10,906+0000 ERROR [plan-executor-15-thread-1]' -F -A100 nexus.log 
      2022-05-20 03:19:10,906+0000 ERROR [plan-executor-15-thread-1]  admin com.google.common.eventbus.EventBus.nexus - Could not dispatch event HttpClientConfigurationChangedEvent{configuration=HttpClientConfigurationData{connection=ConnectionConfiguration{timeout=40000 milliseconds, maximumRetries=3, userAgentSuffix=null, useTrustStore=null, enableCircularRedirects=null, enableCookies=null}, proxy=ProxyConfiguration{http=ProxyServerConfiguration{enabled=true, host='public0-proxy1-0-prd.data.example.com', port=8080, authentication=null}, https=null, nonProxyHosts=[localhost, 127.0.0.1]}, authentication=null}} to subscriber org.sonatype.nexus.internal.httpclient.HttpClientAuditor@103f5509 method [public void org.sonatype.nexus.internal.httpclient.HttpClientAuditor.on(org.sonatype.nexus.httpclient.config.HttpClientConfigurationChangedEvent)]
      org.apache.shiro.session.UnknownSessionException: There is no session with id [5b5a7f0c-c1f0-4b3d-87c8-eac0a199ca03]
      	at org.apache.shiro.session.mgt.eis.AbstractSessionDAO.readSession(AbstractSessionDAO.java:170)
      	at org.apache.shiro.session.mgt.eis.CachingSessionDAO.readSession(CachingSessionDAO.java:261)
      	at org.apache.shiro.session.mgt.DefaultSessionManager.retrieveSessionFromDataSource(DefaultSessionManager.java:236)
      	at org.apache.shiro.session.mgt.DefaultSessionManager.retrieveSession(DefaultSessionManager.java:222)
      	at org.apache.shiro.session.mgt.AbstractValidatingSessionManager.doGetSession(AbstractValidatingSessionManager.java:118)
      	at org.apache.shiro.session.mgt.AbstractNativeSessionManager.lookupSession(AbstractNativeSessionManager.java:148)
      	at org.apache.shiro.session.mgt.AbstractNativeSessionManager.lookupRequiredSession(AbstractNativeSessionManager.java:152)
      	at org.apache.shiro.session.mgt.AbstractNativeSessionManager.getAttribute(AbstractNativeSessionManager.java:249)
      	at org.apache.shiro.session.mgt.DelegatingSession.getAttribute(DelegatingSession.java:141)
      	at org.apache.shiro.session.ProxiedSession.getAttribute(ProxiedSession.java:121)
      	at org.apache.shiro.subject.support.DelegatingSubject.getRunAsPrincipalsStack(DelegatingSubject.java:473)
      	at org.apache.shiro.subject.support.DelegatingSubject.getPrincipals(DelegatingSubject.java:157)
      	at org.apache.shiro.subject.support.DelegatingSubject.getPrincipal(DelegatingSubject.java:153)
      	at org.sonatype.nexus.security.UserIdHelper.get(UserIdHelper.java:55)
      	at org.sonatype.nexus.security.UserIdHelper.get(UserIdHelper.java:47)
      	at org.sonatype.nexus.audit.internal.InitiatorProviderImpl.get(InitiatorProviderImpl.java:57)
      	at org.sonatype.nexus.audit.internal.AuditRecorderImpl.record(AuditRecorderImpl.java:88)
      	at org.sonatype.nexus.audit.AuditorSupport.record(AuditorSupport.java:127)
      	at org.sonatype.nexus.internal.httpclient.HttpClientAuditor.on(HttpClientAuditor.java:79)
      	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.lang.reflect.Method.invoke(Method.java:498)
      	at com.google.common.eventbus.Subscriber.invokeSubscriberMethod(Subscriber.java:87)
      	at com.google.common.eventbus.Subscriber$1.run(Subscriber.java:72)
      	at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
      	at com.google.common.eventbus.Subscriber.dispatchEvent(Subscriber.java:67)
      	at com.google.common.eventbus.Dispatcher$ImmediateDispatcher.dispatch(Dispatcher.java:186)
      	at com.google.common.eventbus.EventBus.post(EventBus.java:212)
      	at org.sonatype.nexus.internal.event.EventManagerImpl.post(EventManagerImpl.java:127)
      	at org.sonatype.nexus.internal.httpclient.HttpClientManagerImpl.setConfiguration(HttpClientManagerImpl.java:187)
      	at org.sonatype.nexus.internal.httpclient.HttpClientManagerImpl$$EnhancerByGuice$$925279419.GUICE$TRAMPOLINE(<generated>)
      	at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:74)
      	at org.sonatype.nexus.common.stateguard.MethodInvocationAction.run(MethodInvocationAction.java:39)
      	at org.sonatype.nexus.common.stateguard.StateGuard$GuardImpl.run(StateGuard.java:272)
      	at org.sonatype.nexus.common.stateguard.GuardedInterceptor.invoke(GuardedInterceptor.java:54)
      	at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:75)
      	at com.google.inject.internal.InterceptorStackCallback.invoke(InterceptorStackCallback.java:55)
      	at org.sonatype.nexus.internal.httpclient.HttpClientManagerImpl$$EnhancerByGuice$$925279419.setConfiguration(<generated>)
      	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.lang.reflect.Method.invoke(Method.java:498)
      	at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:98)
      	at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:325)
      	at groovy.lang.MetaClassImpl.setProperty(MetaClassImpl.java:2726)
      	at groovy.lang.MetaClassImpl.setProperty(MetaClassImpl.java:3785)
      	at org.codehaus.groovy.runtime.InvokerHelper.setProperty(InvokerHelper.java:217)
      	at org.codehaus.groovy.runtime.ScriptBytecodeAdapter.setProperty(ScriptBytecodeAdapter.java:497)
      	at com.sonatype.nexus.migration.config.ingesters.SystemHttpIngester.ingest(SystemHttpIngester.groovy:131)
      	at com.sonatype.nexus.migration.config.ConfigurationIngester$ingest.call(Unknown Source)
      	at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:47)
      	at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:116)
      	at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:120)
      	at com.sonatype.nexus.migration.config.ConfigurationStep.doRun(ConfigurationStep.groovy:68)
      	at com.sonatype.nexus.migration.plan.Step.run(Step.groovy:271)
      	at com.sonatype.nexus.migration.plan.Step$run$1.call(Unknown Source)
      	at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:47)
      	at com.sonatype.nexus.migration.plan.Step$run$1.call(Unknown Source)
      	at com.sonatype.nexus.migration.plan.StepExecutor.runSync(StepExecutor.groovy:168)
      	at sun.reflect.GeneratedMethodAccessor437.invoke(Unknown Source)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.lang.reflect.Method.invoke(Method.java:498)
      	at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite$PogoCachedMethodSiteNoUnwrapNoCoerce.invoke(PogoMetaMethodSite.java:210)
      	at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite.callCurrent(PogoMetaMethodSite.java:59)
      	at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCallCurrent(CallSiteArray.java:51)
      	at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite.callCurrent(PogoMetaMethodSite.java:64)
      	at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:169)
      	at com.sonatype.nexus.migration.plan.StepExecutor.runSingle(StepExecutor.groovy:184)
      	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.lang.reflect.Method.invoke(Method.java:498)
      	at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite$PogoCachedMethodSiteNoUnwrapNoCoerce.invoke(PogoMetaMethodSite.java:210)
      	at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite.callCurrent(PogoMetaMethodSite.java:59)
      	at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCallCurrent(CallSiteArray.java:51)
      	at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite.callCurrent(PogoMetaMethodSite.java:64)
      	at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:169)
      	at com.sonatype.nexus.migration.plan.StepExecutor.submit(StepExecutor.groovy:149)
      	at sun.reflect.GeneratedMethodAccessor435.invoke(Unknown Source)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.lang.reflect.Method.invoke(Method.java:498)
      	at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite$PogoCachedMethodSiteNoUnwrapNoCoerce.invoke(PogoMetaMethodSite.java:210)
      	at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite.callCurrent(PogoMetaMethodSite.java:59)
      	at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCallCurrent(CallSiteArray.java:51)
      	at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite.callCurrent(PogoMetaMethodSite.java:64)
      	at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:169)
      	at com.sonatype.nexus.migration.plan.StepExecutor.run(StepExecutor.groovy:100)
      	at com.sonatype.nexus.migration.plan.StepExecutor$run.call(Unknown Source)
      	at com.sonatype.nexus.migration.plan.Plan.runSteps(Plan.groovy:253)
      	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.lang.reflect.Method.invoke(Method.java:498)
      	at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:98)
      	at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:325)
      	at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:352)
      	at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1034)
      	at org.codehaus.groovy.runtime.callsite.PogoMetaClassSite.callCurrent(PogoMetaClassSite.java:68)
      

      Expected

      Event handling code should not ERROR. Audit events should get recorded, even if some data is missing. Auditing should log an audit event with what data it has, just because it cannot locate a session id does not warrant a failure. At the very least, it is not expected that a message is logged where the userid is known, when the cause of the logged ERROR message is that the session for that user is not known.

      Attachments

        Activity

          People

            Unassigned Unassigned
            plynch Peter Lynch
            Peter Lynch Peter Lynch
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

              Created:
              Updated:

              tigCommentSecurity.panel-title