From b573d0a1cc5b8e18e39525b90d2bc22a12e359d6 Mon Sep 17 00:00:00 2001 From: Kuniwak Date: Thu, 9 Nov 2023 19:24:16 +0900 Subject: [PATCH 1/4] Repoduce not reporting when log at not main thread Reproducing steps: 1. Stay keep state not playing 2. Open the scene "Error" 3. Open an inspector for "AutopilotSettingsForFacingImmediatelyError" 4. Click Run Expected Behaviour: Stop playing and report the error to Slack. Actual Behaviour: Still playing and did not report to Slack. --- Runtime/Autopilot.cs | 5 +- ...ubThrowingErrorFromNotMainThreadOnClick.cs | 24 ++++ ...owingErrorFromNotMainThreadOnClick.cs.meta | 3 + Tests/TestAssets/StubClickAgentForTests.asset | 2 +- Tests/TestScenes/Error.unity | 119 ++++++++++++++++++ 5 files changed, 151 insertions(+), 2 deletions(-) create mode 100644 Tests/Runtime/TestDoubles/StubThrowingErrorFromNotMainThreadOnClick.cs create mode 100644 Tests/Runtime/TestDoubles/StubThrowingErrorFromNotMainThreadOnClick.cs.meta diff --git a/Runtime/Autopilot.cs b/Runtime/Autopilot.cs index c5f67cf..11c7cdf 100644 --- a/Runtime/Autopilot.cs +++ b/Runtime/Autopilot.cs @@ -49,6 +49,7 @@ public enum ExitCode private AutopilotSettings _settings; private float _startTime; + private void Start() { _state = AutopilotState.Instance; @@ -64,7 +65,7 @@ private void Start() _randomFactory = new RandomFactory(seed); _logger.Log($"Random seed is {seed}"); - + // NOTE: Registering logMessageReceived must be placed before DispatchByScene. // Because some agent can throw an error immediately, so reporter can miss the error if // registering logMessageReceived is placed after DispatchByScene. @@ -89,6 +90,7 @@ private void Start() _startTime = Time.realtimeSinceStartup; } + /// /// Terminate when ran specified time. /// @@ -100,6 +102,7 @@ private IEnumerator Lifespan(int timeoutSec) yield return UniTask.ToCoroutine(() => TerminateAsync(ExitCode.Normally)); } + /// /// Terminate autopilot /// diff --git a/Tests/Runtime/TestDoubles/StubThrowingErrorFromNotMainThreadOnClick.cs b/Tests/Runtime/TestDoubles/StubThrowingErrorFromNotMainThreadOnClick.cs new file mode 100644 index 0000000..ddaa1e0 --- /dev/null +++ b/Tests/Runtime/TestDoubles/StubThrowingErrorFromNotMainThreadOnClick.cs @@ -0,0 +1,24 @@ +// Copyright (c) 2023 DeNA Co., Ltd. +// This software is released under the MIT License. + +using System; +using System.Threading; +using System.Threading.Tasks; +using UnityEngine; +using UnityEngine.EventSystems; + +namespace DeNA.Anjin.TestDoubles +{ + /// + /// A test stub throw errors when clicked + /// + public class StubThrowingErrorFromNotMainThreadOnClick : MonoBehaviour, IPointerClickHandler + { + public void OnPointerClick(PointerEventData eventData) + { + Task.Run( + () => Debug.LogException(new Exception($"TEST on thread #{Thread.CurrentThread.ManagedThreadId}")) + ); + } + } +} diff --git a/Tests/Runtime/TestDoubles/StubThrowingErrorFromNotMainThreadOnClick.cs.meta b/Tests/Runtime/TestDoubles/StubThrowingErrorFromNotMainThreadOnClick.cs.meta new file mode 100644 index 0000000..37b8bb9 --- /dev/null +++ b/Tests/Runtime/TestDoubles/StubThrowingErrorFromNotMainThreadOnClick.cs.meta @@ -0,0 +1,3 @@ +fileFormatVersion: 2 +guid: c733c26bf53b475ea76992de2fcc418a +timeCreated: 1699513479 \ No newline at end of file diff --git a/Tests/TestAssets/StubClickAgentForTests.asset b/Tests/TestAssets/StubClickAgentForTests.asset index e17b788..ec34799 100644 --- a/Tests/TestAssets/StubClickAgentForTests.asset +++ b/Tests/TestAssets/StubClickAgentForTests.asset @@ -13,4 +13,4 @@ MonoBehaviour: m_Name: StubClickAgentForTests m_EditorClassIdentifier: description: - targetName: ThrowErrorFromMainThreadOnClick + targetName: ThrowErrorFromNotMainThreadOnClick diff --git a/Tests/TestScenes/Error.unity b/Tests/TestScenes/Error.unity index 9f41aef..bffe5cd 100644 --- a/Tests/TestScenes/Error.unity +++ b/Tests/TestScenes/Error.unity @@ -418,6 +418,124 @@ MonoBehaviour: serializedVersion: 2 m_Bits: 4294967295 m_MaxRayIntersections: 0 +--- !u!1 &1088446224 +GameObject: + m_ObjectHideFlags: 0 + m_CorrespondingSourceObject: {fileID: 0} + m_PrefabInstance: {fileID: 0} + m_PrefabAsset: {fileID: 0} + serializedVersion: 6 + m_Component: + - component: {fileID: 1088446228} + - component: {fileID: 1088446227} + - component: {fileID: 1088446226} + - component: {fileID: 1088446225} + - component: {fileID: 1088446229} + m_Layer: 0 + m_Name: ThrowErrorFromNotMainThreadOnClick + m_TagString: Untagged + m_Icon: {fileID: 0} + m_NavMeshLayer: 0 + m_StaticEditorFlags: 0 + m_IsActive: 1 +--- !u!65 &1088446225 +BoxCollider: + m_ObjectHideFlags: 0 + m_CorrespondingSourceObject: {fileID: 0} + m_PrefabInstance: {fileID: 0} + m_PrefabAsset: {fileID: 0} + m_GameObject: {fileID: 1088446224} + m_Material: {fileID: 0} + m_IncludeLayers: + serializedVersion: 2 + m_Bits: 0 + m_ExcludeLayers: + serializedVersion: 2 + m_Bits: 0 + m_LayerOverridePriority: 0 + m_IsTrigger: 0 + m_ProvidesContacts: 0 + m_Enabled: 1 + serializedVersion: 3 + m_Size: {x: 1, y: 1, z: 1} + m_Center: {x: 0, y: 0, z: 0} +--- !u!23 &1088446226 +MeshRenderer: + m_ObjectHideFlags: 0 + m_CorrespondingSourceObject: {fileID: 0} + m_PrefabInstance: {fileID: 0} + m_PrefabAsset: {fileID: 0} + m_GameObject: {fileID: 1088446224} + m_Enabled: 1 + m_CastShadows: 1 + m_ReceiveShadows: 1 + m_DynamicOccludee: 1 + m_StaticShadowCaster: 0 + m_MotionVectors: 1 + m_LightProbeUsage: 1 + m_ReflectionProbeUsage: 1 + m_RayTracingMode: 2 + m_RayTraceProcedural: 0 + m_RenderingLayerMask: 1 + m_RendererPriority: 0 + m_Materials: + - {fileID: 10303, guid: 0000000000000000f000000000000000, type: 0} + m_StaticBatchInfo: + firstSubMesh: 0 + subMeshCount: 0 + m_StaticBatchRoot: {fileID: 0} + m_ProbeAnchor: {fileID: 0} + m_LightProbeVolumeOverride: {fileID: 0} + m_ScaleInLightmap: 1 + m_ReceiveGI: 1 + m_PreserveUVs: 0 + m_IgnoreNormalsForChartDetection: 0 + m_ImportantGI: 0 + m_StitchLightmapSeams: 1 + m_SelectedEditorRenderState: 3 + m_MinimumChartSize: 4 + m_AutoUVMaxDistance: 0.5 + m_AutoUVMaxAngle: 89 + m_LightmapParameters: {fileID: 0} + m_SortingLayerID: 0 + m_SortingLayer: 0 + m_SortingOrder: 0 + m_AdditionalVertexStreams: {fileID: 0} +--- !u!33 &1088446227 +MeshFilter: + m_ObjectHideFlags: 0 + m_CorrespondingSourceObject: {fileID: 0} + m_PrefabInstance: {fileID: 0} + m_PrefabAsset: {fileID: 0} + m_GameObject: {fileID: 1088446224} + m_Mesh: {fileID: 10202, guid: 0000000000000000e000000000000000, type: 0} +--- !u!4 &1088446228 +Transform: + m_ObjectHideFlags: 0 + m_CorrespondingSourceObject: {fileID: 0} + m_PrefabInstance: {fileID: 0} + m_PrefabAsset: {fileID: 0} + m_GameObject: {fileID: 1088446224} + serializedVersion: 2 + m_LocalRotation: {x: 0, y: 0, z: 0, w: 1} + m_LocalPosition: {x: 1, y: 0, z: 0} + m_LocalScale: {x: 1, y: 1, z: 1} + m_ConstrainProportionsScale: 0 + m_Children: [] + m_Father: {fileID: 0} + m_LocalEulerAnglesHint: {x: 0, y: 0, z: 0} +--- !u!114 &1088446229 +MonoBehaviour: + m_ObjectHideFlags: 0 + m_CorrespondingSourceObject: {fileID: 0} + m_PrefabInstance: {fileID: 0} + m_PrefabAsset: {fileID: 0} + m_GameObject: {fileID: 1088446224} + m_Enabled: 1 + m_EditorHideFlags: 0 + m_Script: {fileID: 11500000, guid: c733c26bf53b475ea76992de2fcc418a, type: 3} + m_Name: + m_EditorClassIdentifier: --- !u!1 &1325883444 GameObject: m_ObjectHideFlags: 0 @@ -519,4 +637,5 @@ SceneRoots: - {fileID: 1025330167} - {fileID: 1325883446} - {fileID: 300655197} + - {fileID: 1088446228} - {fileID: 352512553} From ffd90d6f2ffd91fe5cbdbd5665b92ce18de4a5c1 Mon Sep 17 00:00:00 2001 From: Kuniwak Date: Fri, 10 Nov 2023 05:41:05 +0900 Subject: [PATCH 2/4] Treat logs from non-main threads --- Runtime/Autopilot.cs | 4 ++-- Runtime/Utilities/LogMessageHandler.cs | 3 +++ 2 files changed, 5 insertions(+), 2 deletions(-) diff --git a/Runtime/Autopilot.cs b/Runtime/Autopilot.cs index 11c7cdf..2734fc4 100644 --- a/Runtime/Autopilot.cs +++ b/Runtime/Autopilot.cs @@ -71,7 +71,7 @@ private void Start() // registering logMessageReceived is placed after DispatchByScene. _reporter = new SlackReporter(_settings, new SlackAPI()); _logMessageHandler = new LogMessageHandler(_settings, _reporter); - Application.logMessageReceived += _logMessageHandler.HandleLog; + Application.logMessageReceivedThreaded += _logMessageHandler.HandleLog; _dispatcher = new AgentDispatcher(_settings, _logger, _randomFactory); _dispatcher.DispatchByScene(SceneManager.GetActiveScene()); @@ -119,7 +119,7 @@ public async UniTask TerminateAsync(ExitCode exitCode, string logString = null, if (_logMessageHandler != null) { - Application.logMessageReceived -= _logMessageHandler.HandleLog; + Application.logMessageReceivedThreaded -= _logMessageHandler.HandleLog; } if (_state.settings != null && !string.IsNullOrEmpty(_state.settings.junitReportPath)) diff --git a/Runtime/Utilities/LogMessageHandler.cs b/Runtime/Utilities/LogMessageHandler.cs index 6da59d9..1a369e6 100644 --- a/Runtime/Utilities/LogMessageHandler.cs +++ b/Runtime/Utilities/LogMessageHandler.cs @@ -1,6 +1,7 @@ // Copyright (c) 2023 DeNA Co., Ltd. // This software is released under the MIT License. +using Cysharp.Threading.Tasks; using DeNA.Anjin.Reporters; using DeNA.Anjin.Settings; using UnityEngine; @@ -39,6 +40,8 @@ public async void HandleLog(string logString, string stackTrace, LogType type) return; } + // NOTE: HandleLog may called by non-main thread because it subscribe Application.logMessageReceivedThreaded + await UniTask.SwitchToMainThread(); await _reporter.PostReportAsync(logString, stackTrace, type, true); var autopilot = Object.FindObjectOfType(); From f891287ab9faee24f3258de14e8bfb30149bdcad Mon Sep 17 00:00:00 2001 From: Kuniwak Date: Fri, 10 Nov 2023 05:43:03 +0900 Subject: [PATCH 3/4] Cosmetic changes --- Runtime/Autopilot.cs | 4 ---- 1 file changed, 4 deletions(-) diff --git a/Runtime/Autopilot.cs b/Runtime/Autopilot.cs index 2734fc4..84a99c8 100644 --- a/Runtime/Autopilot.cs +++ b/Runtime/Autopilot.cs @@ -49,7 +49,6 @@ public enum ExitCode private AutopilotSettings _settings; private float _startTime; - private void Start() { _state = AutopilotState.Instance; @@ -90,7 +89,6 @@ private void Start() _startTime = Time.realtimeSinceStartup; } - /// /// Terminate when ran specified time. /// @@ -102,7 +100,6 @@ private IEnumerator Lifespan(int timeoutSec) yield return UniTask.ToCoroutine(() => TerminateAsync(ExitCode.Normally)); } - /// /// Terminate autopilot /// @@ -153,7 +150,6 @@ public async UniTask TerminateAsync(ExitCode exitCode, string logString = null, #endif } - /// /// Terminate autopilot /// From edc884d6f83436eef4e10f74e34fe4a6159d44b7 Mon Sep 17 00:00:00 2001 From: Kuniwak Date: Tue, 14 Nov 2023 10:23:50 +0900 Subject: [PATCH 4/4] fixup! Repoduce not reporting when log at not main thread --- .../TestDoubles/StubThrowingErrorFromNotMainThreadOnClick.cs | 1 + 1 file changed, 1 insertion(+) diff --git a/Tests/Runtime/TestDoubles/StubThrowingErrorFromNotMainThreadOnClick.cs b/Tests/Runtime/TestDoubles/StubThrowingErrorFromNotMainThreadOnClick.cs index ddaa1e0..7c3100c 100644 --- a/Tests/Runtime/TestDoubles/StubThrowingErrorFromNotMainThreadOnClick.cs +++ b/Tests/Runtime/TestDoubles/StubThrowingErrorFromNotMainThreadOnClick.cs @@ -12,6 +12,7 @@ namespace DeNA.Anjin.TestDoubles /// /// A test stub throw errors when clicked /// + [AddComponentMenu("")] public class StubThrowingErrorFromNotMainThreadOnClick : MonoBehaviour, IPointerClickHandler { public void OnPointerClick(PointerEventData eventData)