Details
-
Type:
Bug
-
Status: New
-
Priority:
Major
-
Resolution: Unresolved
-
Affects Version/s: 3.34.0
-
Fix Version/s: None
-
Labels:
-
Notability: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)
Expected
Event handling code should not ERROR. It 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.