The timers generate internal errors in Dapr 1.15.3

[vlardn]

Expected Behavior

Actor timers should not generate any internal errors in the app or the daprd sidecar.

Actual Behavior

Our .NET Core 9 app has a few actor timers and running in Azure Kubernetes Service with 2 replicas.

After upgrading to Dapr from 1.14.4 to 1.15.3 and after some time passed the app (.NET Core 9) started to log errors (from overridden Actor.OnActorMethodFailedAsync method) with the the same frequency as configured timers but despite these errors, the timer methods in the app still get called as expected:

2025-04-24 13:40:04.115 | backend-55497cb86d-mgnkl | Actor TimerMethod FireTimerAsync finished
2025-04-24 13:40:04.304 | backend-55497cb86d-mgnkl | Actor TimerMethod FireTimerAsync starting
2025-04-24 13:40:04.306 | backend-55497cb86d-mgnkl | Actor TimerMethod FireTimerAsync failed: Object reference not set to an instance of an object.; System.NullReferenceException: Object reference not set to an instance of an object.
   at Dapr.Actors.Runtime.ActorManager.<>c__DisplayClass25_0.<<FireTimerAsync>g__RequestFunc|0>d.MoveNext()
--- End of stack trace from previous location ---
   at Dapr.Actors.Runtime.ActorManager.DispatchInternalAsync[T](ActorId actorId, ActorMethodContext actorMethodContext, Func`3 actorFunc, CancellationToken cancellationToken)
2025-04-24 13:40:05.001 | backend-55497cb86d-mgnkl | Actor TimerMethod FireTimerAsync starting
2025-04-24 13:40:05.067 | backend-55497cb86d-mgnkl | Actor TimerMethod FireTimerAsync finished
2025-04-24 13:40:05.309 | backend-55497cb86d-mgnkl | Actor TimerMethod FireTimerAsync starting
2025-04-24 13:40:05.311 | backend-55497cb86d-mgnkl | Actor TimerMethod FireTimerAsync failed: Object reference not set to an instance of an object.; System.NullReferenceException: Object reference not set to an instance of an object.
   at Dapr.Actors.Runtime.ActorManager.<>c__DisplayClass25_0.<<FireTimerAsync>g__RequestFunc|0>d.MoveNext()
--- End of stack trace from previous location ---
   at Dapr.Actors.Runtime.ActorManager.DispatchInternalAsync[T](ActorId actorId, ActorMethodContext actorMethodContext, Func`3 actorFunc, CancellationToken cancellationToken)
2025-04-24 13:40:06.001 | backend-55497cb86d-mgnkl | Actor TimerMethod FireTimerAsync starting
2025-04-24 13:40:06.027 | backend-55497cb86d-mgnkl | Actor TimerMethod FireTimerAsync finished

The daprd sidecar logs on another pod backend-55497cb86d-c6hfk:

time="2025-04-24T10:44:00.029051165Z" level=debug msg="Probing app health" app_id=myapp instance=backend-55497cb86d-c6hfk scope=dapr.apphealth type=log ver=1.15.3-msft.2
time="2025-04-24T10:44:00.038464821Z" level=debug msg="App health probe successful: true" app_id=myapp instance=backend-55497cb86d-c6hfk scope=dapr.apphealth type=log ver=1.15.3-msft.2
time="2025-04-24T10:44:03.028819788Z" level=debug msg="Probing app health" app_id=myapp instance=backend-55497cb86d-c6hfk scope=dapr.apphealth type=log ver=1.15.3-msft.2
time="2025-04-24T10:44:03.029307406Z" level=debug msg="App health probe successful: true" app_id=myapp instance=backend-55497cb86d-c6hfk scope=dapr.apphealth type=log ver=1.15.3-msft.2
time="2025-04-24T10:44:04.170616081Z" level=error msg="Error executing timer: rpc error: code = Unknown desc = error from actor service: (500) " app_id=myapp instance=backend-55497cb86d-c6hfk scope=dapr.runtime.actors.timers.inmemory type=log ver=1.15.3-msft.2
time="2025-04-24T10:44:04.18271453Z" level=warning msg="Error processing operation DaprBuiltInActorNotFoundRetries. Retrying in 1s…" app_id=myapp instance=backend-55497cb86d-c6hfk scope=dapr.runtime type=log ver=1.15.3-msft.2
time="2025-04-24T10:44:04.182880036Z" level=debug msg="Error for operation DaprBuiltInActorNotFoundRetries was: rpc error: code = Unknown desc = error from actor service: (500) " app_id=myapp instance=backend-55497cb86d-c6hfk scope=dapr.runtime type=log ver=1.15.3-msft.2
time="2025-04-24T10:44:06.028734569Z" level=debug msg="Probing app health" app_id=myapp instance=backend-55497cb86d-c6hfk scope=dapr.apphealth type=log ver=1.15.3-msft.2
time="2025-04-24T10:44:06.029201586Z" level=debug msg="App health probe successful: true" app_id=myapp instance=backend-55497cb86d-c6hfk scope=dapr.apphealth type=log ver=1.15.3-msft.2
time="2025-04-24T10:44:09.028859858Z" level=debug msg="Probing app health" app_id=myapp instance=backend-55497cb86d-c6hfk scope=dapr.apphealth type=log ver=1.15.3-msft.2
time="2025-04-24T10:44:09.029491281Z" level=debug msg="App health probe successful: true" app_id=myapp instance=backend-55497cb86d-c6hfk scope=dapr.apphealth type=log ver=1.15.3-msft.2
time="2025-04-24T10:44:09.245511002Z" level=error msg="Error executing timer: rpc error: code = Unknown desc = error from actor service: (500) " app_id=myapp instance=backend-55497cb86d-c6hfk scope=dapr.runtime.actors.timers.inmemory type=log ver=1.15.3-msft.2
time="2025-04-24T10:44:09.254489835Z" level=warning msg="Error processing operation DaprBuiltInActorNotFoundRetries. Retrying in 1s…" app_id=myapp instance=backend-55497cb86d-c6hfk scope=dapr.runtime type=log ver=1.15.3-msft.2
time="2025-04-24T10:44:09.254837948Z" level=debug msg="Error for operation DaprBuiltInActorNotFoundRetries was: rpc error: code = Unknown desc = error from actor service: (500) " app_id=myapp instance=backend-55497cb86d-c6hfk scope=dapr.runtime type=log ver=1.15.3-msft.2
time="2025-04-24T10:44:12.028803257Z" level=debug msg="Probing app health" app_id=myapp instance=backend-55497cb86d-c6hfk scope=dapr.apphealth type=log ver=1.15.3-msft.2
time="2025-04-24T10:44:12.02966379Z" level=debug msg="App health probe successful: true" app_id=myapp instance=backend-55497cb86d-c6hfk scope=dapr.apphealth type=log ver=1.15.3-msft.2
time="2025-04-24T10:44:14.418807174Z" level=error msg="Error executing timer: rpc error: code = Unknown desc = error from actor service: (500) " app_id=myapp instance=backend-55497cb86d-c6hfk scope=dapr.runtime.actors.timers.inmemory type=log ver=1.15.3-msft.2
time="2025-04-24T10:44:14.426276255Z" level=warning msg="Error processing operation DaprBuiltInActorNotFoundRetries. Retrying in 1s…" app_id=myapp instance=backend-55497cb86d-c6hfk scope=dapr.runtime type=log ver=1.15.3-msft.2
time="2025-04-24T10:44:14.426464462Z" level=debug msg="Error for operation DaprBuiltInActorNotFoundRetries was: rpc error: code = Unknown desc = error from actor service: (500) " app_id=myapp instance=backend-55497cb86d-c6hfk scope=dapr.runtime type=log ver=1.15.3-msft.2
time="2025-04-24T10:44:15.028793672Z" level=debug msg="Probing app health" app_id=myapp instance=backend-55497cb86d-c6hfk scope=dapr.apphealth type=log ver=1.15.3-msft.2
time="2025-04-24T10:44:15.03086115Z" level=debug msg="App health probe successful: true" app_id=myapp instance=backend-55497cb86d-c6hfk scope=dapr.apphealth type=log ver=1.15.3-msft.2

As seen in the app logs, the actors with timers are located on the backend-55497cb86d-mgnkl pod but daprd timer rpc errors occurs on another pod - backend-55497cb86d-c6hfk.

I think the problem occurs because when Dapr moves an actor to another pod, it still keeps the timer on the old pod (in this case, backend-55497cb86d-c6hfk), which continues attempting to invoke the actor timer method on the new pod.

Deleting pod backend-55497cb86d-c6hfk (and auto-creating new one by k8s) helps to stop all these errors.

Steps to Reproduce the Problem

Release Note

RELEASE NOTE: FIX Bug in runtime.

[vlardn]

Similar errors were observed in dapr/dapr#7551

[WhitWaldo]

Could you please share what your timer registration code looks like? The 1.15.3 release fixed all the timer schedule deserialization errors I was aware of, but my guess is that there are more variations to add to the unit test battery.

[vlardn]

In our app we have 2 actors with 3 timers:

// 1st actor
protected override async Task OnActivateAsync()
{
    // ...
    await RegisterTimerAsync("Polling", nameof(PollingAsync), null, TimeSpan.FromSeconds(3), TimeSpan.FromMilliseconds(1000));
    await RegisterTimerAsync("CheckDb", nameof(CheckDbAsync), null, TimeSpan.FromMinutes(5), TimeSpan.FromMinutes(5));
}

// 2nd actor
protected override async Task OnActivateAsync()
{
    // ...
    await RegisterTimerAsync("Polling", nameof(PollingAsync), null, TimeSpan.FromSeconds(3), TimeSpan.FromMilliseconds(1000));
}

Tonight, I again encountered a situation where all three of these timers started generating the above-mentioned errors :/. So it's not a rare problem.

PS. Regarding failing function Dapr.Actors.Runtime.ActorManager.FireTimerAsync: I'd added logging to OnActorMethodFailedAsync overriden function and checked that Host.ActorTypeInfo.ImplementationType is not null. So it really looks like the NullReferenceException occurs because DeserializeAsync returns null:

internal async Task FireTimerAsync(ActorId actorId, Stream requestBodyStream, CancellationToken cancellationToken = default)
{
    #pragma warning disable 0618
    var timerData = await DeserializeAsync(requestBodyStream);
    #pragma warning restore 0618

    // Create a Func to be invoked by common method.
    async Task<byte[]> RequestFunc(Actor actor, CancellationToken ct)
    {
        var actorType = actor.Host.ActorTypeInfo.ImplementationType;
        var methodInfo = actor.GetMethodInfoUsingReflection(actorType, timerData.Callback);

        var parameters = methodInfo.GetParameters();

        // The timer callback routine needs to return a type Task
        await (Task)(methodInfo.Invoke(actor, (parameters.Length == 0) ? null : new object[] { timerData.Data }));

        return default;
    }

    await this.DispatchInternalAsync(actorId, this.timerMethodContext, RequestFunc, cancellationToken);
}

[vlardn]

@WhitWaldo My question is: should the timer function be invoked only from its own sidecar and never from a foreign one?

[WhitWaldo]

The fundamental problem that broke all this with 1.15 is that the Dapr Actors (as implemented in the .NET SDK) were designed to be serialized using TimeSpan types. With 1.15, the actor reminders (and as I've since found out, timers) migrated to a new scheduling system that supports far more types of schedule options (covered here) and unfortunately, a great many of these don't represent nor can easily be converted into TimeSpan values. With 1.15.3, I accommodated the various @every and other @ prefixed values (though @midnight doesn't return a very helpful value) in a way that emphasized avoiding runtime errors over introducing a mid-release breaking change (e.g. how this is handled in the Jobs SDK).

I'll add some more variations to the unit tests I've got in place over the weekend and see if there's a set of these I missed in the last pass that resolves your issue and ping you when there's a new release out.

[WhitWaldo]

With regards to your follow up question, yes, the way you're invoking the timer function should be avoided. It's not intended to be a messaging channel for arbitrary invocations between actors and should be triggered only by the runtime.

[WhitWaldo]

Though since you have a tap into the raw stream, any chance you could share the string value in that inbound invocation so I can add it directly to my unit tests?

[vlardn]

Though since you have a tap into the raw stream, any chance you could share the string value in that inbound invocation so I can add it directly to my unit tests?

It will try to get it but it'll take day or so.

But I'm wondering what will happen if deserialization gets fixed at runtime? Does that mean we’ll get double the expected timer frequency because two timers will be running - one in the local daprd sidecar and another in the remote one?

[vlardn]

With regards to your follow up question, yes, the way you're invoking the timer function should be avoided. It's not intended to be a messaging channel for arbitrary invocations between actors and should be triggered only by the runtime.

Btw, I'm not who "invoking the timer function" - the runtime (daprd sidecar) doing this.

[vlardn]

Also, in the past few days, I’ve encountered situations where some of the three timers stopped triggering entirely after the actor was moved to a new pod. This is much more critical issue and most probably I would need to rollback prod to Dapr v1.14

[WhitWaldo]

Though since you have a tap into the raw stream, any chance you could share the string value in that inbound invocation so I can add it directly to my unit tests?

It will try to get it but it'll take day or so.

But I'm wondering what will happen if deserialization gets fixed at runtime? Does that mean we’ll get double the expected timer frequency because two timers will be running - one in the local daprd sidecar and another in the remote one?

Deserialization isn't performed by the runtime, but by the SDK. Timers should be exclusively registered using RegisterTimerAsync on the actor implementation and it will register the timer where it needs to be. Given that, I don't know what you mean by having two timers running (unless again, you're doing something you shouldn't be).

Btw, I'm not who "invoking the timer function" - the runtime (daprd sidecar) doing this.

Ok.. your comment left the impression that you were doing something funky with it. Timers are registered with the scheduler service and where they're triggered from is up to the runtime. The scheduler services will ensure it's called only as often as it's supposed to.

Also, in the past few days, I’ve encountered situations where some of the three timers stopped triggering entirely after the actor was moved to a new pod. This is much more critical issue and most probably I would need to rollback prod to Dapr v1.14

This is an entirely different issue and one that should be filed in dapr/dapr as timers are fired by the runtime calling into the actor on the SDK.

[vlardn]

Though since you have a tap into the raw stream, any chance you could share the string value in that inbound invocation so I can add it directly to my unit tests?

Here is the HTTP request content (coming from daprd sidecar, i.e. Dapr runtime) causing NullReferenceException:

{"callback":"","dueTime":"0h0m3s0ms","period":"0h0m1s0ms"}