From c1075d113fb13b586a216444946057f936c8d86a Mon Sep 17 00:00:00 2001 From: Dean Herbert Date: Tue, 28 Jun 2022 13:58:35 +0900 Subject: [PATCH] Add logging around current channel changes and join requests MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Tracking down a flaky test (https://teamcity.ppy.sh/buildConfiguration/Osu_Build/553?hideProblemsFromDependencies=false&expandBuildTestsSection=true&hideTestsFromDependencies=false): ```csharp TearDown : System.TimeoutException : "PM Channel 1 displayed" timed out --TearDown at osu.Framework.Testing.Drawables.Steps.UntilStepButton.<>c__DisplayClass11_0.<.ctor>b__0() at osu.Framework.Testing.Drawables.Steps.StepButton.PerformStep(Boolean userTriggered) at osu.Framework.Testing.TestScene.runNextStep(Action onCompletion, Action`1 onError, Func`2 stopCondition) --- End of stack trace from previous location --- at osu.Framework.Testing.TestSceneTestRunner.TestRunner.RunTestBlocking(TestScene test) at osu.Game.Tests.Visual.OsuTestScene.OsuTestSceneTestRunner.RunTestBlocking(TestScene test) in /opt/buildagent/work/ecd860037212ac52/osu.Game/Tests/Visual/OsuTestScene.cs:line 503 at osu.Framework.Testing.TestScene.RunTestsFromNUnit() ------- Stdout: ------- [runtime] 2022-06-27 23:18:55 [verbose]: ๐Ÿ’จ Class: TestSceneChatOverlay [runtime] 2022-06-27 23:18:55 [verbose]: ๐Ÿ”ถ Test: TestKeyboardNextChannel [runtime] 2022-06-27 23:18:55 [verbose]: Chat is now polling every 60000 ms [runtime] 2022-06-27 23:18:55 [verbose]: ๐Ÿ”ธ Step #1 Setup request handler [runtime] 2022-06-27 23:18:55 [verbose]: ๐Ÿ”ธ Step #2 Add test channels [runtime] 2022-06-27 23:18:55 [verbose]: ๐Ÿ”ธ Step #3 Show overlay with channels [runtime] 2022-06-27 23:18:55 [verbose]: Unhandled Request Type: osu.Game.Online.API.Requests.CreateChannelRequest [network] 2022-06-27 23:18:55 [verbose]: Failing request osu.Game.Online.API.Requests.CreateChannelRequest (System.InvalidOperationException: DummyAPIAccess cannot process this request.) [runtime] 2022-06-27 23:18:55 [verbose]: Unhandled Request Type: osu.Game.Online.API.Requests.CreateChannelRequest [network] 2022-06-27 23:18:55 [verbose]: Failing request osu.Game.Online.API.Requests.CreateChannelRequest (System.InvalidOperationException: DummyAPIAccess cannot process this request.) [runtime] 2022-06-27 23:18:55 [verbose]: ๐Ÿ”ธ Step #4 Select channel 1 [runtime] 2022-06-27 23:18:55 [verbose]: ๐Ÿ”ธ Step #5 Channel 1 is visible [runtime] 2022-06-27 23:18:55 [verbose]: ๐Ÿ”ธ Step #6 Press document next keys [runtime] 2022-06-27 23:18:55 [verbose]: ๐Ÿ”ธ Step #7 Channel 2 is visible [runtime] 2022-06-27 23:18:55 [verbose]: ๐Ÿ”ธ Step #8 Press document next keys [runtime] 2022-06-27 23:18:55 [verbose]: ๐Ÿ”ธ Step #9 PM Channel 1 displayed [network] 2022-06-27 23:18:55 [verbose]: Request to https://a.ppy.sh/587 failed with System.Net.WebException: NotFound. [network] 2022-06-27 23:18:55 [verbose]: Request to https://a.ppy.sh/503 failed with System.Net.WebException: NotFound. [runtime] 2022-06-27 23:19:05 [verbose]: ๐Ÿ’ฅ Failed (on attempt 5,550) [runtime] 2022-06-27 23:19:05 [verbose]: โณ Currently loading components (0) [runtime] 2022-06-27 23:19:05 [verbose]: ๐Ÿงต Task schedulers [runtime] 2022-06-27 23:19:05 [verbose]: LoadComponentsAsync (standard) concurrency:4 running:0 pending:0 [runtime] 2022-06-27 23:19:05 [verbose]: LoadComponentsAsync (long load) concurrency:4 running:0 pending:0 [runtime] 2022-06-27 23:19:05 [verbose]: ๐ŸŽฑ Thread pool [runtime] 2022-06-27 23:19:05 [verbose]: worker: min 1 max 32,767 available 32,766 [runtime] 2022-06-27 23:19:05 [verbose]: completion: min 1 max 1,000 available 1,000 [runtime] 2022-06-27 23:19:05 [debug]: Focus on "ChatTextBox" no longer valid as a result of unfocusIfNoLongerValid. [runtime] 2022-06-27 23:19:05 [debug]: Focus changed from ChatTextBox to nothing. ``` This kind of logging should be helpful: ```csharp [runtime] 2022-06-28 04:59:57 [verbose]: ๐Ÿ”ธ Step #5 Channel 1 is visible [runtime] 2022-06-28 04:59:57 [verbose]: ๐Ÿ”ธ Step #6 Press document next keys [runtime] 2022-06-28 04:59:57 [verbose]: Current channel changed to #channel-2 [runtime] 2022-06-28 04:59:57 [debug]: Pressed (DocumentNext) handled by TestSceneChatOverlay+TestChatOverlay. [runtime] 2022-06-28 04:59:57 [debug]: KeyDownEvent(PageDown, False) handled by ManualInputManager+LocalPlatformActionContainer. [runtime] 2022-06-28 04:59:57 [verbose]: ๐Ÿ”ธ Step #7 Channel 2 is visible [runtime] 2022-06-28 04:59:57 [verbose]: ๐Ÿ”ธ Step #8 Press document next keys [runtime] 2022-06-28 04:59:57 [verbose]: Current channel changed to test user 685 [runtime] 2022-06-28 04:59:57 [debug]: Pressed (DocumentNext) handled by TestSceneChatOverlay+TestChatOverlay. [runtime] 2022-06-28 04:59:57 [debug]: KeyDownEvent(PageDown, False) handled by ManualInputManager+LocalPlatformActionContainer. [runtime] 2022-06-28 04:59:57 [verbose]: ๐Ÿ”ธ Step #9 PM Channel 1 displayed [runtime] 2022-06-28 04:59:57 [verbose]: ๐Ÿ”ธ Step #10 Press document next keys [runtime] 2022-06-28 04:59:57 [verbose]: Current channel changed to test user 218 ``` --- .../Visual/Online/TestSceneChatOverlay.cs | 2 +- osu.Game/Online/Chat/ChannelManager.cs | 30 +++++++++++++++---- 2 files changed, 26 insertions(+), 6 deletions(-) diff --git a/osu.Game.Tests/Visual/Online/TestSceneChatOverlay.cs b/osu.Game.Tests/Visual/Online/TestSceneChatOverlay.cs index 73bad6e631..ff2817c439 100644 --- a/osu.Game.Tests/Visual/Online/TestSceneChatOverlay.cs +++ b/osu.Game.Tests/Visual/Online/TestSceneChatOverlay.cs @@ -472,8 +472,8 @@ namespace osu.Game.Tests.Visual.Online }); AddStep("Select channel 1", () => clickDrawable(getChannelListItem(testChannel1))); - waitForChannel1Visible(); + AddStep("Press document next keys", () => InputManager.Keys(PlatformAction.DocumentNext)); waitForChannel2Visible(); diff --git a/osu.Game/Online/Chat/ChannelManager.cs b/osu.Game/Online/Chat/ChannelManager.cs index 48dfaadfa5..ec84b0643d 100644 --- a/osu.Game/Online/Chat/ChannelManager.cs +++ b/osu.Game/Online/Chat/ChannelManager.cs @@ -133,12 +133,14 @@ namespace osu.Game.Online.Chat ?? JoinChannel(new Channel(user)); } - private void currentChannelChanged(ValueChangedEvent e) + private void currentChannelChanged(ValueChangedEvent channel) { - bool isSelectorChannel = e.NewValue is ChannelListing.ChannelListingChannel; + bool isSelectorChannel = channel.NewValue is ChannelListing.ChannelListingChannel; if (!isSelectorChannel) - JoinChannel(e.NewValue); + JoinChannel(channel.NewValue); + + Logger.Log($"Current channel changed to {channel.NewValue}"); } /// @@ -447,9 +449,17 @@ namespace osu.Game.Online.Chat return channel; case ChannelType.PM: + Logger.Log($"Attempting to join PM channel {channel}"); + var createRequest = new CreateChannelRequest(channel); + createRequest.Failure += e => + { + Logger.Log($"Failed to join PM channel {channel} ({e.Message})"); + }; createRequest.Success += resChannel => { + Logger.Log($"Joined PM channel {channel} ({resChannel.ChannelID})"); + if (resChannel.ChannelID.HasValue) { channel.Id = resChannel.ChannelID.Value; @@ -463,9 +473,19 @@ namespace osu.Game.Online.Chat break; default: + Logger.Log($"Attempting to join public channel {channel}"); + var req = new JoinChannelRequest(channel); - req.Success += () => joinChannel(channel, fetchInitialMessages); - req.Failure += _ => LeaveChannel(channel); + req.Success += () => + { + Logger.Log($"Joined public channel {channel}"); + joinChannel(channel, fetchInitialMessages); + }; + req.Failure += e => + { + Logger.Log($"Failed to join public channel {channel} ({e.Message})"); + LeaveChannel(channel); + }; api.Queue(req); return channel; }