Shard not receiving/handling EntityTerminated message after passivation about akka.net

[Aaronontheweb]

@Arkatufus was this resolved by the Akka.Cluster.Sharding.Delivery transparent handoff we added in v1.5.17? #7105

[Arkatufus]

No, I this this is a different problem altogether

[Arkatufus]

@briansain
this is really weird, the handoff stop message is designed to be sent once and only once. How are you getting 2 handoff message sent?
Are you using the same message types for different things? Is it possible for you to send us your logs?

[briansain]

No, just this use. The issue seems to be isolated with passivation, not nessarily rebalancing. I was able to recreate it locally with only 1 instance of my cluster (other than lighthouse).

I'm working on getting logs, I'll share them when I can.

[briansain]

[09:37:05 DBG Akka.Cluster.Sharding.Shard] SystemConfigManager: GetCurrentShardState, full state: [(entityGuid-ABC: Active(Ref))], active: [entityGuid-ABC]; shardId: [56]
[09:37:05 DBG Akka.Cluster.Sharding.Shard] EntityManager: GetCurrentShardState, full state: [(entityGuid-DEF: Active(Ref))], active: [entityGuid-DEF]
[09:37:05 DBG Akka.Cluster.Sharding.Shard] EntityManager: GetCurrentShardState, full state: [], active: []; shardId: [8]
[09:37:15 DBG Akka.Cluster.Sharding.Shard] SystemConfigManager: GetCurrentShardState, full state: [(entityGuid-ABC: Active(Ref))], active: [entityGuid-ABC]; shardId: [56]
[09:37:15 DBG Akka.Cluster.Sharding.Shard] EntityManager: GetCurrentShardState, full state: [(entityGuid-DEF: Active(Ref))], active: [entityGuid-DEF]
[09:37:15 DBG Akka.Cluster.Sharding.Shard] EntityManager: GetCurrentShardState, full state: [], active: []; shardId: [8]
[09:37:25 DBG Akka.Cluster.Sharding.Shard] SystemConfigManager: GetCurrentShardState, full state: [(entityGuid-ABC: Active(Ref))], active: [entityGuid-ABC]; shardId: [56]
[09:37:25 DBG Akka.Cluster.Sharding.Shard] EntityManager: GetCurrentShardState, full state: [(entityGuid-DEF: Active(Ref))], active: [entityGuid-DEF]
[09:37:25 DBG Akka.Cluster.Sharding.Shard] EntityManager: GetCurrentShardState, full state: [], active: []; shardId: [8]
[09:37:32 DBG DotNetCore.CAP.Processor.TransportCheckProcessor] Transport connection checking...
[09:37:32 DBG DotNetCore.CAP.Processor.TransportCheckProcessor] Transport connection healthy!
[09:37:33 DBG Akka.Cluster.Sharding.Shard] EntityManager: Passivating [1] idle entities
[09:37:33 DBG Akka.Cluster.Sharding.Shard] EntityManager: Passivation started for [entityGuid-DEF]
[09:37:33 DBG Akka.Cluster.Sharding.Shard] [entityGuid-DEF] passivating
[09:37:33 DBG EntityManager] EntityManager received GracefulStop; Self.Path: akka://company-system/system/sharding/EntityManager/56/entityGuid-DEF/$a; Number Children: 1
[09:37:33 INF Entity] entityGuid-DEF received GracefulStop message
[09:37:33 INF EntityManager] All Children Stopped, Stopping EntityManager for path akka://company-system/system/sharding/EntityManager/56/entityGuid-DEF/$a
[09:37:33 DBG Entity] AroundPostStop for entityGuid-DEF
[09:37:33 INF EntityManager] AroundPostStop for EntityManager
[09:37:35 DBG Akka.Cluster.Sharding.Shard] SystemConfigManager: GetCurrentShardState, full state: [(entityGuid-ABC: Active(Ref))], active: [entityGuid-ABC]; shardId: [56]
[09:37:35 DBG Akka.Cluster.Sharding.Shard] EntityManager: GetCurrentShardState, full state: [(entityGuid-DEF: Passivating(Ref))], active: [entityGuid-DEF]
[09:37:35 DBG Akka.Cluster.Sharding.Shard] EntityManager: GetCurrentShardState, full state: [], active: []; shardId: [8]
[09:37:45 DBG Akka.Cluster.Sharding.Shard] SystemConfigManager: GetCurrentShardState, full state: [(entityGuid-ABC: Active(Ref))], active: [entityGuid-ABC]; shardId: [56]
[09:37:45 DBG Akka.Cluster.Sharding.Shard] EntityManager: GetCurrentShardState, full state: [(entityGuid-DEF: Passivating(Ref))], active: [entityGuid-DEF]
[09:37:45 DBG Akka.Cluster.Sharding.Shard] EntityManager: GetCurrentShardState, full state: [], active: []; shardId: [8]
[09:37:55 DBG Akka.Cluster.Sharding.Shard] SystemConfigManager: GetCurrentShardState, full state: [(entityGuid-ABC: Active(Ref))], active: [entityGuid-ABC]; shardId: [56]
[09:37:55 DBG Akka.Cluster.Sharding.Shard] EntityManager: GetCurrentShardState, full state: [(entityGuid-DEF: Passivating(Ref))], active: [entityGuid-DEF]
[09:37:55 DBG Akka.Cluster.Sharding.Shard] EntityManager: GetCurrentShardState, full state: [], active: []; shardId: [8]
[09:38:02 DBG DotNetCore.CAP.Processor.TransportCheckProcessor] Transport connection checking...
[09:38:02 DBG DotNetCore.CAP.Processor.TransportCheckProcessor] Transport connection healthy!
[09:38:03 DBG Akka.Cluster.Sharding.Shard] EntityManager: Message of type [ApplyBillAdjustment] for entity [entityGuid-DEF] buffered
[09:38:05 DBG Akka.Cluster.Sharding.Shard] SystemConfigManager: GetCurrentShardState, full state: [(entityGuid-ABC: Active(Ref))], active: [entityGuid-ABC]; shardId: [56]
[09:38:05 DBG Akka.Cluster.Sharding.Shard] EntityManager: GetCurrentShardState, full state: [(entityGuid-DEF: Passivating(Ref))], active: [entityGuid-DEF]
[09:38:05 DBG Akka.Cluster.Sharding.Shard] EntityManager: GetCurrentShardState, full state: [], active: []; shardId: [8]
[09:38:15 DBG Akka.Cluster.Sharding.Shard] SystemConfigManager: GetCurrentShardState, full state: [(entityGuid-ABC: Active(Ref))], active: [entityGuid-ABC]; shardId: [56]
[09:38:15 DBG Akka.Cluster.Sharding.Shard] EntityManager: GetCurrentShardState, full state: [(entityGuid-DEF: Passivating(Ref))], active: [entityGuid-DEF]
[09:38:15 DBG Akka.Cluster.Sharding.Shard] EntityManager: GetCurrentShardState, full state: [], active: []; shardId: [8]
[09:38:25 DBG Akka.Cluster.Sharding.Shard] SystemConfigManager: GetCurrentShardState, full state: [(entityGuid-ABC: Active(Ref))], active: [entityGuid-ABC]; shardId: [56]
[09:38:25 DBG Akka.Cluster.Sharding.Shard] EntityManager: GetCurrentShardState, full state: [(entityGuid-DEF: Passivating(Ref))], active: [entityGuid-DEF]; shardId: [56]
[09:38:25 DBG Akka.Cluster.Sharding.Shard] EntityManager: GetCurrentShardState, full state: [], active: []; shardId: [8]

I added to the log statement so that I can try and track down the extra "EntityManager"
One is for a proxy, another is the actual coordinator.

[briansain]

Here are some more logs with mailbox logging turned on. It seems like the EntityManager is Terminating, but it's not notifying its watchers. The Shard for EntityManager never received DeathWatchNotification, Terminated, or EntityTerminated.

[MAILBOX][2024-03-06T15:47:56.4172485-06:00][Thread 0028] [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a/entityGUID-DEF#1366094024] processing message <Signify.RCM.Billing.Domain.Common.GracefulStop> from [akka://company-system/system/sharding/EntityManager/56#2140002698]
[INFO][03/06/2024 21:47:56.418Z][Thread 0009][akka.tcp://company-system@computer:5054/system/sharding/EntityManager/56/entityGUID-DEF/$a] All Children Stopped, Stopping EntityManager for path akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a> from [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a#1746129115]
[MAILBOX][2024-03-06T15:47:56.4182292-06:00][Thread 0009] [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a#1746129115] having enqueued <Terminate>
[MAILBOX][2024-03-06T15:47:56.4183975-06:00][Thread 0069] [akka://company-system/user/petabridge.cmd-log-memorizer#397530626] processing message <[DEBUG][03/06/2024 21:47:56.418Z][Thread 0028][akka.tcp://company-system@computer:5054/system/sharding/EntityManager/56/entityGUID-DEF/$a/entityGUID-DEF] AroundPostStop for entityGUID-DEF> from [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a/entityGUID-DEF#1366094024]
[15:47:56 INF Signify.RCM.Billing.Domain.Aggregates.Bill.EntityManager] All Children Stopped, Stopping EntityManager for path akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a
[MAILBOX][2024-03-06T15:47:56.4184451-06:00][Thread 0009] [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a#1746129115] processing system message <Terminate> with [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a/entityGUID-DEF#1366094024]
[15:47:56 DBG Signify.RCM.Billing.Domain.Aggregates.Bill.Bill] AroundPostStop for entityGUID-DEF
[MAILBOX][2024-03-06T15:47:56.4192736-06:00][Thread 0009] [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a/entityGUID-DEF#1366094024] having enqueued <Unwatch>: [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a#1746129115] wants to unwatch [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a/entityGUID-DEF#1366094024]
[MAILBOX][2024-03-06T15:47:56.4196295-06:00][Thread 0009] [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a/entityGUID-DEF#1366094024] having enqueued <Terminate>
[MAILBOX][2024-03-06T15:47:56.4218334-06:00][Thread 0028] [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a/entityGUID-DEF#1366094024] Swapping mailbox to Akka.Actor.DeadLetterMailbox
[MAILBOX][2024-03-06T15:47:56.4231916-06:00][Thread 0028] [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a#1746129115] having enqueued <DeathWatchNotification>: [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a/entityGUID-DEF#1366094024], ExistenceConfirmed=True, AddressTerminated=False
[MAILBOX][2024-03-06T15:47:56.4233381-06:00][Thread 0009] [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a#1746129115] processing system message <DeathWatchNotification>: [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a/entityGUID-DEF#1366094024], ExistenceConfirmed=True, AddressTerminated=False with [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a/entityGUID-DEF#1366094024]
[MAILBOX][2024-03-06T15:47:56.4239739-06:00][Thread 0009] [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a#1746129115] Swapping mailbox to Akka.Actor.DeadLetterMailbox
[MAILBOX][2024-03-06T15:47:56.4240399-06:00][Thread 0009] [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF#943642015] having enqueued <DeathWatchNotification>: [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a#1746129115], ExistenceConfirmed=True, AddressTerminated=False
[15:47:56 INF Signify.RCM.Billing.Domain.Aggregates.Bill.EntityManager] AroundPostStop for EntityManager for path akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a
[MAILBOX][2024-03-06T15:47:56.4241969-06:00][Thread 0009] [akka://company-system/system/EventStreamUnsubscriber-1#208700217] having enqueued <DeathWatchNotification>: [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a#1746129115], ExistenceConfirmed=True, AddressTerminated=False
[MAILBOX][2024-03-06T15:47:56.4242203-06:00][Thread 0050] [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF#943642015] processing system message <DeathWatchNotification>: [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a#1746129115], ExistenceConfirmed=True, AddressTerminated=False with [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a#1746129115]
[MAILBOX][2024-03-06T15:47:56.4242987-06:00][Thread 0013] [akka://company-system/system/EventStreamUnsubscriber-1#208700217] processing system message <DeathWatchNotification>: [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a#1746129115], ExistenceConfirmed=True, AddressTerminated=False with 
[MAILBOX][2024-03-06T15:47:56.4244408-06:00][Thread 0013] [akka://company-system/system/EventStreamUnsubscriber-1#208700217] processing message <<Terminated>: [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a#1746129115] - ExistenceConfirmed=True> from [akka://company-system/system/sharding/EntityManager/56/entityGUID-DEF/$a#1746129115]
.....
.....
[MAILBOX][2024-03-06T15:48:26.0769473-06:00][Thread 0012] [akka://company-system/system/sharding/EntityManager/8#1620368583] processing message <Akka.Actor.Scheduler.ScheduledTellMsg> from [akka://company-system/system/sharding/EntityManager/8#1620368583]
[MAILBOX][2024-03-06T15:48:26.3059068-06:00][Thread 0013] [akka://company-system/system/sharding/domainReplicator#2009794634] processing message <Akka.Actor.Scheduler.ScheduledTellMsg> from [akka://company-system/system/sharding/domainReplicator#2009794634]
[15:48:26 DBG Akka.Cluster.Sharding.Shard] EntityManager: Passivating [1] idle entities
[15:48:26 DBG Akka.Cluster.Sharding.Shard] EntityManager: Passivation already in progress for [entityGUID-DEF]. Not sending stopMessage back to entity
[MAILBOX][2024-03-06T15:48:26.4238827-06:00][Thread 0039] [akka://company-system/system/endpointManager/reliableEndpointWriter-akka.tcp%3A%2F%2Fcompany-system%40localhost%3A5053-1/endpointWriter#1720846661] processing message <Akka.Actor.Scheduler.ScheduledTellMsg> from [akka://company-system/system/endpointManager/reliableEndpointWriter-akka.tcp%3A%2F%2Fcompany-system%40localhost%3A5053-1/endpointWriter#1720846661]
[MAILBOX][2024-03-06T15:48:26.4543635-06:00][Thread 0016] [akka://company-system/system/cluster/core/daemon/heartbeatSender#1913478643] processing message <Akka.Actor.Scheduler.ScheduledTellMsg> from [akka://company-system/system/cluster/core/daemon/heartbeatSender#1913478643]
[MAILBOX][2024-03-06T15:48:26.4545837-06:00][Thread 0040] [akka://company-system/system/endpointManager#726844289] processing message <Remote message [akka://company-system/system/cluster/core/daemon/heartbeatSender#1913478643] -> [akka.tcp://company-system@computer:2552/]> from [akka://company-system/system/cluster/core/daemon/heartbeatSender#1913478643]
[MAILBOX][2024-03-06T15:48:26.4546793-06:00][Thread 0040] [akka://company-system/system/endpointManager#726844289] processing message <Remote message [akka://company-system/system/cluster/core/daemon/heartbeatSender#1913478643] -> [akka.tcp://company-system@localhost:5053/]> from [akka://company-system/system/cluster/core/daemon/heartbeatSender#1913478643]

In our setup process, I've also initialized 2 different actor providers:

        .AddSetup(setup)
	//.WithPhobos(AkkaRunMode.AkkaCluster)
	.WithActors((sys, registry, dependencyResolver) =>

and then I commented the above out and replaced it with this:

	var setup = BootstrapSetup.Create()
		.WithConfig(akkaConfig)
		.WithActorRefProvider(ProviderSelection.Cluster.Instance);

I didn't have any success with either setup. I don't think it'll make a difference, and I wanted to mention it in case it was important.

[briansain]

Please disregard this issue. The problem lies with a 3rd-party framework that we're using on top of Akka .Net. I found the root of the issue over there and I'll handle it on that end.