search

muoncore / newton

Extend Muon into the world of Spring. Implement Muon apis, especially around events to provide DDD patterns natively in Spring Boot
http://muoncore.io
GNU Lesser General Public License v3.0
12 stars 5 forks source link

Sagas are being started more than once for the same event #46

Closed bobjana closed 7 years ago

bobjana commented 7 years ago

Given: Device registration causing a DeviceCreatedEvent to be raised Then: DeviceActivationSaga.start() is called twice

2017-06-22 15:27:56.376 DEBUG 18188 --- [ool-33-thread-1] mu.cibecs.core.DeviceRegistrationSaga    : Started registration saga for device: 594bc5dc1221a0470ca0b5ef
2017-06-22 15:27:56.376  WARN 18188 --- [ool-10-thread-1] m.c.common.tenant.TenantContextHolder    : Using legacy TenantContextHolder.
2017-06-22 15:27:56.376  WARN 18188 --- [ool-10-thread-1] m.c.common.tenant.TenantContextHolder    : Using legacy TenantContextHolder.
2017-06-22 15:27:56.376  INFO 18188 --- [      channel-4] nClusterAwareTrackingSubscriptionManager : Event{eventType='DeviceEndpointDetailsUpdatedEvent', streamName='core-service/Device', schema='null', causedById=null, causedByRelation='null', service='core-service', orderId=1304, eventTime=1498138076080}
2017-06-22 15:27:56.392  WARN 18188 --- [ool-10-thread-1] m.c.common.tenant.TenantContextHolder    : Using legacy TenantContextHolder.
2017-06-22 15:27:56.392  INFO 18188 --- [      channel-4] nClusterAwareTrackingSubscriptionManager : Event{eventType='DeviceEndpointDetailsUpdatedEvent', streamName='core-service/Device', schema='null', causedById=null, causedByRelation='null', service='core-service', orderId=1304, eventTime=1498138076080}
2017-06-22 15:27:56.392  WARN 18188 --- [ool-10-thread-1] m.c.common.tenant.TenantContextHolder    : Using legacy TenantContextHolder.
2017-06-22 15:27:56.392  WARN 18188 --- [ool-10-thread-1] m.c.common.tenant.TenantContextHolder    : Using legacy TenantContextHolder.
2017-06-22 15:27:56.392  WARN 18188 --- [ool-10-thread-1] m.c.common.tenant.TenantContextHolder    : Using legacy TenantContextHolder.
2017-06-22 15:27:56.392  WARN 18188 --- [ool-10-thread-1] m.c.common.tenant.TenantContextHolder    : Using legacy TenantContextHolder.
2017-06-22 15:27:56.392  WARN 18188 --- [ool-10-thread-1] m.c.common.tenant.TenantContextHolder    : Using legacy TenantContextHolder.
2017-06-22 15:27:56.392  WARN 18188 --- [ool-10-thread-1] m.c.common.tenant.TenantContextHolder    : Using legacy TenantContextHolder.
2017-06-22 15:27:56.407  WARN 18188 --- [ool-10-thread-1] m.c.common.tenant.TenantContextHolder    : Using legacy TenantContextHolder.
2017-06-22 15:27:56.407  INFO 18188 --- [      channel-4] nClusterAwareTrackingSubscriptionManager : Event{eventType='DeviceEndpointDetailsUpdatedEvent', streamName='core-service/Device', schema='null', causedById=null, causedByRelation='null', service='core-service', orderId=1304, eventTime=1498138076080}
2017-06-22 15:27:56.407  WARN 18188 --- [ool-10-thread-1] m.c.common.tenant.TenantContextHolder    : Using legacy TenantContextHolder.
2017-06-22 15:27:56.407  WARN 18188 --- [ool-10-thread-1] m.c.common.tenant.TenantContextHolder    : Using legacy TenantContextHolder.
2017-06-22 15:27:56.407  WARN 18188 --- [ool-10-thread-1] m.c.common.tenant.TenantContextHolder    : Using legacy TenantContextHolder.
2017-06-22 15:27:56.407  WARN 18188 --- [ool-10-thread-1] m.c.common.tenant.TenantContextHolder    : Using legacy TenantContextHolder.
2017-06-22 15:27:56.407  WARN 18188 --- [ool-10-thread-1] m.c.common.tenant.TenantContextHolder    : Using legacy TenantContextHolder.
2017-06-22 15:27:56.407  WARN 18188 --- [ool-10-thread-1] m.c.common.tenant.TenantContextHolder    : Using legacy TenantContextHolder.
2017-06-22 15:27:56.422  INFO 18188 --- [ool-33-thread-1] io.muoncore.newton.saga.SagaFactory      : Creating new saga of type class mu.cibecs.core.DeviceRegistrationSaga with payload DeviceCreatedEvent(id=594bc5dc1221a0470ca0b5ef, apiToken=eyJhbGciOiJIUzI1NiJ9.eyJleHBpcmVzIjo5MjIzMzcyMDM2ODU0Nzc1ODA3LCJjbGllbnRUeXBlIjoiREVWSUNFX1BST1RFQ1RJT04iLCJ0ZW5hbnROYW1lIjpudWxsLCJkaXNwbGF5TmFtZSI6bnVsbCwicm9sZXMiOlsiREVWSUNFX1BST1RFQ1RJT04iXSwidGVuYW50SWQiOiI1OGVjZWYwOWM1NDg5NGNiNzliOWUyMzkiLCJwcmluY2lwYWxJZCI6IjU5NGJjNWRjMTIyMWEwNDcwY2EwYjVlZiIsImV4cCI6OTIyMzM3MjAzNjg1NDc3NSwidXNlcm5hbWUiOiI1OTRiYzVkYzEyMjFhMDQ3MGNhMGI1ZWYifQ.mHJ-AY3bhcqxPtQL2znEYrCn7sQxfro9v4u9vKeuDgI)
2017-06-22 15:27:56.422  WARN 18188 --- [ool-10-thread-1] m.c.common.tenant.TenantContextHolder    : Using legacy TenantContextHolder.
2017-06-22 15:27:56.422  INFO 18188 --- [      channel-4] nClusterAwareTrackingSubscriptionManager : Event{eventType='DeviceEndpointDetailsUpdatedEvent', streamName='core-service/Device', schema='null', causedById=null, causedByRelation='null', service='core-service', orderId=1304, eventTime=1498138076080}
2017-06-22 15:27:56.424  WARN 18188 --- [ool-10-thread-1] m.c.common.tenant.TenantContextHolder    : Using legacy TenantContextHolder.
2017-06-22 15:27:56.424  INFO 18188 --- [      channel-4] nClusterAwareTrackingSubscriptionManager : Event{eventType='DeviceEndpointDetailsUpdatedEvent', streamName='core-service/Device', schema='null', causedById=null, causedByRelation='null', service='core-service', orderId=1304, eventTime=1498138076080}
2017-06-22 15:27:56.425 DEBUG 18188 --- [ool-33-thread-1] mu.cibecs.core.DeviceRegistrationSaga    : Started registration saga for device: 594bc5dc1221a0470ca0b5ef
screen shot 2017-06-22 at 3 29 04 pm
daviddawson commented 7 years ago

This is replicated by running SagaIntegrationTests.sagaCanBeStartedViaStartEvent

This also creates two instances of ComplexSaga.

daviddawson commented 7 years ago

Is this using the test event store or live/ photon lite?

bobjana commented 7 years ago

This is still an issue.

screen shot 2017-06-26 at 9 55 59 am
bobjana commented 7 years ago 
```2017-06-26 16:54:16.826  INFO 45297 --- [ool-33-thread-1] io.muoncore.newton.saga.SagaFactory      : Creating new saga of type class mu.cibecs.core.PolicyTeamAssignmentSaga with payload TeamAssignedToPolicyEvent(id=595120181221a0b0f1e288e7, policyId=5950fa1e1221a0b0f1e25f3f, oldPolicyId=Optional.empty)
2017-06-26 16:54:16.831 DEBUG 45297 --- [ool-33-thread-1] mu.cibecs.core.PolicyTeamAssignmentSaga  : Start policy-team assignment saga: 595120181221a0b0f1e288e7
2017-06-26 16:54:16.832 DEBUG 45297 --- [ool-33-thread-1] mu.cibecs.core.PolicyTeamAssignmentSaga  : Dispatch add team to policy command
2017-06-26 16:54:16.933 DEBUG 45297 --- [ool-33-thread-1] m.c.c.p.command.AddTeamToPolicyCommand   : Team '595120181221a0b0f1e288e7' added to policy '5950fa1e1221a0b0f1e25f3f' teams
2017-06-26 16:54:16.933  INFO 45297 --- [ool-33-thread-1] io.muoncore.newton.saga.SagaFactory      : Creating new saga of type class mu.cibecs.core.PolicyTeamAssignmentSaga with payload TeamAssignedToPolicyEvent(id=595120181221a0b0f1e288e7, policyId=5950fa1e1221a0b0f1e25f3f, oldPolicyId=Optional.empty)
2017-06-26 16:54:16.937 DEBUG 45297 --- [ool-33-thread-1] mu.cibecs.core.PolicyTeamAssignmentSaga  : Start policy-team assignment saga: 595120181221a0b0f1e288e7
2017-06-26 16:54:16.937 DEBUG 45297 --- [ool-33-thread-1] mu.cibecs.core.PolicyTeamAssignmentSaga  : Dispatch add team to policy command
2017-06-26 16:54:17.019 DEBUG 45297 --- [ool-33-thread-1] m.c.c.p.command.AddTeamToPolicyCommand   : Team '595120181221a0b0f1e288e7' added to policy '5950fa1e1221a0b0f1e25f3f' teams
2017-06-26 16:54:17.030 DEBUG 45297 --- [ool-33-thread-1] mu.cibecs.core.PolicyTeamAssignmentSaga  : Policy added team event processed

From the logs it's clear PolicyTeamAssignmentSaga is started twice for the same event - I don't see the reason why though....

[5:07 PM] dylan added and commented on this Plain Text snippet: Extended saga log 2017-06-26 17:06:06.966 DEBUG 46551 --- [ool-33-thread-1] i.m.newton.saga.SagaStreamManager : Will starts Sagas [class mu.cibecs.core.PolicyTeamAssignmentSaga, class mu.cibecs.core.PolicyTeamAssignmentSaga] 2017-06-26 17:06:06.966 INFO 46551 --- [ool-33-thread-1] io.muoncore.newton.saga.SagaFactory : Creating new saga of type class mu.cibecs.core.PolicyTeamAssignmentSaga with payload TeamAssignedToPolicyEvent(id=595122dd1221a0b5d72759d9, policyId=5950fa1e1221a0b0f1e25f3f, oldPolicyId=Optional.empty) 2017-06-26 17:06:06.983 DEBUG 46551 --- [ool-33-thread-1] mu.cibecs.core.PolicyTeamAssignmentSaga : Start policy-team assignment saga: 595122dd1221a0b5d72759d9 2017-06-26 17:06:06.984 DEBUG 46551 --- [ool-33-thread-1] mu.cibecs.core.PolicyTeamAssignmentSaga : Dispatch add team to policy command 2017-06-26 17:06:06.985 DEBUG 46551 --- [ool-33-thread-1] i.m.n.saga.mongo.MongoSagaRepository : Persisting saga interest SagaInterest(sagaClassName=mu.cibecs.core.PolicyTeamAssignmentSaga, className=mu.cibecs.core.policy.events.PolicyAddedTeamEvent, id=3cf2d0a9-e215-4b18-94ef-c69d314cbfe0, sagaId=5d2fced9-a36f-48ab-8e61-18506bda82f2, key=id, value=5950fa1e1221a0b0f1e25f3f) 2017-06-26 17:06:07.194 DEBUG 46551 --- [ool-33-thread-1] m.c.c.p.command.AddTeamToPolicyCommand : Team '595122dd1221a0b5d72759d9' added to policy '5950fa1e1221a0b0f1e25f3f' teams 2017-06-26 17:06:07.194 INFO 46551 --- [ool-33-thread-1] io.muoncore.newton.saga.SagaFactory : Creating new saga of type class mu.cibecs.core.PolicyTeamAssignmentSaga with payload TeamAssignedToPolicyEvent(id=595122dd1221a0b5d72759d9, policyId=5950fa1e1221a0b0f1e25f3f, oldPolicyId=Optional.empty) 2017-06-26 17:06:07.198 DEBUG 46551 --- [ool-33-thread-1] mu.cibecs.core.PolicyTeamAssignmentSaga : Start policy-team assignment saga: 595122dd1221a0b5d72759d9 2017-06-26 17:06:07.199 DEBUG 46551 --- [ool-33-thread-1] mu.cibecs.core.PolicyTeamAssignmentSaga : Dispatch add team to policy command 2017-06-26 17:06:07.199 DEBUG 46551 --- [ool-33-thread-1] i.m.n.saga.mongo.MongoSagaRepository : Persisting saga interest SagaInterest(sagaClassName=mu.cibecs.core.PolicyTeamAssignmentSaga, className=mu.cibecs.core.policy.events.PolicyAddedTeamEvent, id=e60ec463-f113-406d-b607-9b6b478f5baf, sagaId=08e7e215-28bb-4625-bfc7-cfe026ec10a3, key=id, value=5950fa1e1221a0b0f1e25f3f) 2017-06-26 17:06:07.370 DEBUG 46551 --- [ool-33-thread-1] m.c.c.p.command.AddTeamToPolicyCommand : Team '595122dd1221a0b5d72759d9' added to policy '5950fa1e1221a0b0f1e25f3f' teams 2017-06-26 17:06:07.372 DEBUG 46551 --- [ool-33-thread-1] i.m.newton.saga.SagaStreamManager : Checking if there is a Saga to be run for class mu.cibecs.core.team.events.TeamPolicyConfigurationChangedEvent 2017-06-26 17:06:07.372 DEBUG 46551 --- [ool-33-thread-1] i.m.newton.saga.SagaStreamManager : Will starts Sagas [] 2017-06-26 17:06:07.374 DEBUG 46551 --- [ool-33-thread-1] i.m.newton.saga.SagaStreamManager : Checking if there is a Saga to be run for class mu.cibecs.core.team.events.TeamPolicyConfigurationChangedEvent 2017-06-26 17:06:07.374 DEBUG 46551 --- [ool-33-thread-1] i.m.newton.saga.SagaStreamManager : Will starts Sagas [] 2017-06-26 17:06:07.376 DEBUG 46551 --- [ool-33-thread-1] i.m.newton.saga.SagaStreamManager : Checking if there is a Saga to be run for class mu.cibecs.core.policy.events.PolicyAddedTeamEvent 2017-06-26 17:06:07.376 DEBUG 46551 --- [ool-33-thread-1] i.m.newton.saga.SagaStreamManager : Will starts Sagas [] 2017-06-26 17:06:07.389 DEBUG 46551 --- [ool-33-thread-1] mu.cibecs.core.PolicyTeamAssignmentSaga : Policy added team event processed 2017-06-26 17:06:07.405 DEBUG 46551 --- [ool-33-thread-1] i.m.n.saga.mongo.MongoSagaRepository : Saga is complete, removed 1 interests 2017-06-26 17:06:07.420 DEBUG 46551 --- [ool-33-thread-1] io.muoncore.newton.saga.SagaEndCommand : Saga 5d2fced9-a36f-48ab-8e61-18506bda82f2 is ending, sending SagaEnd lifecycle event. 2017-06-26 17:06:07.452 DEBUG 46551 --- [ool-33-thread-1] io.muoncore.newton.saga.SagaEndCommand : Sent end saga lifecycle event - Event persisted 2017-06-26 17:06:07.455 DEBUG 46551 --- [ool-33-thread-1] mu.cibecs.core.PolicyTeamAssignmentSaga : Policy added team event processed 2017-06-26 17:06:07.457 DEBUG 46551 --- [ool-33-thread-1] i.m.n.saga.mongo.MongoSagaRepository : Saga is complete, removed 1 interests 2017-06-26 17:06:07.461 DEBUG 46551 --- [ool-33-thread-1] io.muoncore.newton.saga.SagaEndCommand : Saga 08e7e215-28bb-4625-bfc7-cfe026ec10a3 is ending, sending SagaEnd lifecycle event. 2017-06-26 17:06:07.485 DEBUG 46551 --- [ool-33-thread-1] io.muoncore.newton.saga.SagaEndCommand : Sent end saga lifecycle event - Event persisted 2017-06-26 17:06:07.485 DEBUG 46551 --- [ool-33-thread-1] i.m.newton.saga.SagaStreamManager : Checking if there is a Saga to be run for class mu.cibecs.core.policy.events.PolicyAddedTeamEvent 2017-06-26 17:06:07.485 DEBUG 46551 --- [ool-33-thread-1] i.m.newton.saga.SagaStreamManager : Will starts Sagas []


It seems sagaStartCache has a problem with equality:
`
SagaStreamManager    : Will starts Sagas [class mu.cibecs.core.PolicyTeamAssignmentSaga, class mu.cibecs.core.PolicyTeamAssignmentSaga]
`
bobjana commented 7 years ago

Changed internal SagaStartCache list -> set