EventFilter exceptions count change after upgrade 1.3.17 -> 1.4.7

[snekbaev]

Hi,

Windows 10, .NET Framework 4.7.2

Noticed that several of my tests are failing after the upgrade. Not so long ago I've implemented another project which used 1.4.x and I think... I ran into the same issue but just adjusted the quantities and moved on, but recently upgraded the older project and ran into that again. In other words, the issue might have appeared earlier rather than in 1.4.7.

Actor:

public sealed class TestActor : UntypedActor
{
	private ILoggingAdapter Log { get; } = Context.GetLogger();

	protected override void PostRestart(Exception reason)
	{
		Log.Error(reason, "Restarted");

		base.PostRestart(reason);
	}

	protected override void OnReceive( object message )
	{
		switch (message)
		{
			case string msg:
				throw new InvalidOperationException( "I'm sailing away. Set an open course" );

			default:
				Unhandled( message );
				break;
		}
	}

	public static Props Props()
	{
		return Akka.Actor.Props.Create( () => new TestActor() );
	}
}

Test:

[Test]
public void TestEventFilter()
{
	var toSend = "Eric Cartman";

	var actor = ActorOf( Repro.TestActor.Props() );

	EventFilter.Exception<InvalidOperationException>( source: actor.Path.ToString() ).ExpectOne( () => actor.Tell( toSend ) );
}

passes with 1.3.17, but fails with 1.4.7 with:

Received 1 message too many. Expected 1 message but received 2 that matched filter [Error with Cause <System.InvalidOperationException> when Source == "akka://test/user/$a"]
   at Akka.TestKit.Internal.InternalEventFilterApplier.Intercept[T](Func`1 func, ActorSystem system, Nullable`1 timeout, Nullable`1 expectedOccurrences, MatchedEventHandler matchedEventHandler)
   at Akka.TestKit.Internal.InternalEventFilterApplier.InternalExpect(Action action, ActorSystem actorSystem, Int32 expectedCount, Nullable`1 timeout)

It seems that Log.Error(reason, "Restarted"); is responsible for the failure in 1.4.7, commenting it out makes the test pass. With 1.3.17 the test passes regardless whether that line exists or not.

Is that a regression or?

Thank you!

[Aaronontheweb]

@snekbaev we'll investigate - very possible that we changed some of the default logging inside the ActorCell. I don't think this is a bug but I do want to understand why it's happening.

[snekbaev]

if I remember correctly when I developed and wrote that test I was under assumption that EventFilter.Exception will contain any exception that happened in the actor regardless of logging. Some of my actors do have exactly the same PostRestart block and some don't, obviously, respective tests are a failing and passing with 1.4.7. If this change stays then tests need to know if logging is done inside the actor and have the code adjusted according, which is confusing... imho, unlike with 1.3.17 where logging does not effect EventFilter.Exception - single exception thrown and single expected.

But let's see first what you'll discover...

[Arkatufus]

I don't think I can make this backward compatible without breaking Akka.Remoting logging.

This is the original code: https://github.com/akkadotnet/akka.net/blob/v1.3/src/core/Akka/Event/Logging.cs#L92

This is the new code: https://github.com/akkadotnet/akka.net/blob/dev/src/core/Akka/Event/Logging.cs#L101-L116

[Arkatufus]

In essence, version 1.4 is more consistent regarding actor paths. Version 1.3 would use akka://actor.path path for the exception but uses akka://actor.path#uid for the Log.Error() call. Version 1.4 uses akka://actor.path for both, this is why the new code returns 2 error messages instead of one.

[snekbaev]

@Arkatufus how does one distinguish when exception happened and whether it was logged? I do have tests where I throw 2 exceptions and pass on the third attempt, i.e. retry tests. Does EventFilter need some changes to be able to distinguish a log entry vs a thrown exception?

[Arkatufus]

@snekbaev Both thrown exception and error log entries use the Error log event, published in the event bus, so there is no way to distinguish them out of the box if you also pass an exception into the Log.Error() function. One solution is to add a prefix to the message of your Log.Error() call and uses a custom event filter to catch them based on the prefixes, something like this:

eventFilter.Custom(logEvent => 
        logEvent is Error && 
        logEvent.Message is string msg && 
        msg.StartsWith("[Simpsons]"))
    .ExpectOne(() => {
        Log.Error(myException, "[Simpsons] Marge");
    });

[snekbaev]

@Arkatufus what if when exception is thrown internally it is marked as exception that occurred in the actor vs simply logged, then event filter, maybe, could distinguish those two? Is this a viable suggestion? I'd really like to have a way to test actor crash without logging on the way, especially without adding Simpsons into the mix :)

[Arkatufus]

@snekbaev Code wise, yes, it is doable, but we (the code maintainer) also have to consider code compliance with the original scala Akka source code. Ultimately, @Aaronontheweb as the main maintainer/owner has to approve of all features added that are outside of the original scala features.

[snekbaev]

@Arkatufus alright, as I don't know how it's in original source code, but that reply implies that scala Akka doesn't have a way to check for exceptions without logging and if logging is done - same situation like with v1.4. It's absolutely possible that I'm not seeing the full picture, yes, but it just feels to me that explicit logging shouldn't affect if I'm trying to test exceptions that occurred in the actor's life-cycle.

Maybe if we rephrase the original problem it will be clearer: how to test exceptions thrown in the actor so that explicit logging doesn't affect the tests.