Details
-
Bug
-
Resolution: Unresolved
-
Major
-
None
-
3.34.0
-
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.