Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Unhandled message generates 2 info messages but only one of them is visible in the log #6532

Closed
brah-mcdude opened this issue Mar 20, 2023 · 1 comment · Fixed by #6730
Closed
Labels

Comments

@brah-mcdude
Copy link
Contributor

brah-mcdude commented Mar 20, 2023

I modified the following test:
From:

        [Fact]
        public async Task Unhandled_message_should_produce_info_message()
        {
            await EventFilter
                .Info(new Regex("^Unhandled message from"))
                .ExpectOneAsync(() => {
                    _unhandledMessageActor.Tell("whatever");
                    return Task.CompletedTask;
                });
        }

To:

        [Fact]
        public async Task Unhandled_message_should_produce_info_message()
        {
            await EventFilter
                .Info() /// <<<< I just removed the Regex expression
                .ExpectOneAsync(() => {
                    _unhandledMessageActor.Tell("whatever");
                    return Task.CompletedTask;
                });
        }

This caused the test to fail.

Test log:

        

Akka.TestKit.Tests.TestEventListenerTests.UnhandledMessageEventFilterTests.Unhandled_message_should_produce_info_message
   Source: UnhandledMessageEventFilterTests.cs line 32
   Duration:2.2 sec

  Message: 
Received 1 message too many. Expected 1 message but received 2 that matched filter [Info]
Expected: True
Actual:   False

  Stack Trace: 
XunitAssertions.Fail(String format, Object[] args) line 26
<InterceptAsync>d__32`1.MoveNext() line 526
--- End of stack trace from previous location where exception was thrown ---
ExceptionDispatchInfo.Throw()
TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
ConfiguredTaskAwaiter.GetResult()
<InternalExpectAsync>d__36.MoveNext() line 602
--- End of stack trace from previous location where exception was thrown ---
ExceptionDispatchInfo.Throw()
TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
ConfiguredTaskAwaiter.GetResult()
<ExpectOneAsync>d__6.MoveNext() line 80
--- End of stack trace from previous location where exception was thrown ---
ExceptionDispatchInfo.Throw()
TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
TaskAwaiter.GetResult()
<Unhandled_message_should_produce_info_message>d__3.MoveNext() line 34
--- End of stack trace from previous location where exception was thrown ---
ExceptionDispatchInfo.Throw()
TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
--- End of stack trace from previous location where exception was thrown ---
ExceptionDispatchInfo.Throw()
TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
--- End of stack trace from previous location where exception was thrown ---
ExceptionDispatchInfo.Throw()
TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

Notice the message above:
Received 1 message too many. Expected 1 message but received 2 that matched filter [Info].
So actually, 2 info messages are generated.

When I run with logging enabled:

 ..Actors.Specs.MessageSpecs.MessageThatWillNotBeHandledSpec.Spec
   Source: MessageThatWillNotBeHandledSpec.cs line 35
   Duration:677 ms

  Standard Output:[DEBUG][03/20/2023 05:23:06.045Z][Thread 0010][EventStream] subscribing [akka://test/system/log-test#447241130] to channel Akka.Event.LogEvent
[DEBUG][03/20/2023 05:23:06.045Z][Thread 0118][EventStreamUnsubscriber] watching [akka://test/system/log-test#447241130] in order to unsubscribe from EventStream when it terminates
[DEBUG][03/20/2023 05:23:06.045Z][Thread 0010][akka://test/system/log-test] now watched by [akka://test/system/EventStreamUnsubscriber-2#883213924]
[DEBUG][03/20/2023 05:23:06.058Z][Thread 0296][akka://test/system/deadLetterListener] now watched by [akka://test/system/EventStreamUnsubscriber-2#883213924]
[DEBUG][03/20/2023 05:23:06.066Z][Thread 0036][akka://test/user] now supervising akka://test/user/$a
[DEBUG][03/20/2023 05:23:06.067Z][Thread 0287][akka://test/user/$a] Started (UnhandledMessageActor)
[DEBUG][03/20/2023 05:23:06.085Z][Thread 0294][akka://test/user/$a] Unhandled message from akka://test/system/testActor1 : whatever
[INFO][03/20/2023 05:23:06.086Z][Thread 0290][akka://test/user/$a] Message [String] from [akka://test/system/testActor1#551529727] to [akka://test/user/$a#37104401] was unhandled. [1] dead letters encountered. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'. Message content: whatever
[DEBUG][03/20/2023 05:23:06.113Z][Thread 0025][CoordinatedShutdown (akka://test)] Performing phase [before-service-unbind] with [0] tasks.
[DEBUG][03/20/2023 05:23:06.173Z][Thread 0290][CoordinatedShutdown (akka://test)] Performing phase [service-unbind] with [0] tasks.
[DEBUG][03/20/2023 05:23:06.173Z][Thread 0290][CoordinatedShutdown (akka://test)] Performing phase [service-requests-done] with [0] tasks.
[DEBUG][03/20/2023 05:23:06.173Z][Thread 0290][CoordinatedShutdown (akka://test)] Performing phase [service-stop] with [0] tasks.
[DEBUG][03/20/2023 05:23:06.173Z][Thread 0290][CoordinatedShutdown (akka://test)] Performing phase [before-cluster-shutdown] with [0] tasks.
[DEBUG][03/20/2023 05:23:06.173Z][Thread 0290][CoordinatedShutdown (akka://test)] Performing phase [cluster-sharding-shutdown-region] with [0] tasks.
[DEBUG][03/20/2023 05:23:06.173Z][Thread 0290][CoordinatedShutdown (akka://test)] Performing phase [cluster-leave] with [0] tasks.
[DEBUG][03/20/2023 05:23:06.173Z][Thread 0290][CoordinatedShutdown (akka://test)] Performing phase [cluster-exiting] with [0] tasks.
[DEBUG][03/20/2023 05:23:06.173Z][Thread 0290][CoordinatedShutdown (akka://test)] Performing phase [cluster-exiting-done] with [0] tasks.
[DEBUG][03/20/2023 05:23:06.173Z][Thread 0290][CoordinatedShutdown (akka://test)] Performing phase [cluster-shutdown] with [0] tasks.
[DEBUG][03/20/2023 05:23:06.173Z][Thread 0290][CoordinatedShutdown (akka://test)] Performing phase [before-actor-system-terminate] with [0] tasks.
[DEBUG][03/20/2023 05:23:06.184Z][Thread 0290][CoordinatedShutdown (akka://test)] Performing phase [actor-system-terminate] with [1] tasks: [terminate-system]
[DEBUG][03/20/2023 05:23:06.187Z][Thread 0290][ActorSystem(test)] System shutdown initiated
[DEBUG][03/20/2023 05:23:06.195Z][Thread 0150][akka://test/user] Stopping
[DEBUG][03/20/2023 05:23:06.195Z][Thread 0295][EventStream] unsubscribing [akka://test/system/deadLetterListener#820708298] from all channels
[DEBUG][03/20/2023 05:23:06.196Z][Thread 0186][EventStreamUnsubscriber] unwatching [akka://test/system/deadLetterListener#820708298] since has no subscriptions
[DEBUG][03/20/2023 05:23:06.200Z][Thread 0296][akka://test/user/$a] Stopped
[DEBUG][03/20/2023 05:23:06.201Z][Thread 0295][akka://test/system/deadLetterListener] Stopped
[DEBUG][03/20/2023 05:23:06.203Z][Thread 0169][akka://test/user] Stopped
[DEBUG][03/20/2023 05:23:06.207Z][Thread 0250][akka://test/system] received AutoReceiveMessage <Terminated>: [akka://test/user] - ExistenceConfirmed=True
[DEBUG][03/20/2023 05:23:06.210Z][Thread 0250][EventStream] subscribing [akka://all-systems/] to channel Akka.Event.Debug
[DEBUG][03/20/2023 05:23:06.210Z][Thread 0234][EventStreamUnsubscriber] watching [akka://all-systems/] in order to unsubscribe from EventStream when it terminates
[DEBUG][03/20/2023 05:23:06.212Z][Thread 0250][EventStream] subscribing [akka://all-systems/] to channel Akka.Event.Info
[DEBUG][03/20/2023 05:23:06.216Z][Thread 0234][EventStreamUnsubscriber] watching [akka://all-systems/] in order to unsubscribe from EventStream when it terminates
[DEBUG][03/20/2023 05:23:06.217Z][Thread 0250][EventStream] subscribing [akka://all-systems/] to channel Akka.Event.Warning

As can be seen, only one info message is visible.
The other info message that the filter catches, is not visible in the log.
So there is no way to know what it is.
Which is an issue for me.

Originally posted by @brah-mcdude in #6354 (comment)

@brah-mcdude
Copy link
Contributor Author

while debugging, i found the hidden message:
m = {[INFO][03/20/2023 02:25:09.055Z][Thread 0010][akka://test/user/$a] Unhandled message from [akka://test/system/testActor1#1866007314]: whatever}

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants