суббота, 6 мая 2017 г.

What exactly does Debug.LogException in Unity

I noticed that sometimes Debug.LogException misses frames and/or adds wrong ones. So, I decided to test it. Results are below, tested in Unity 5.5.1f1.
Supppose, code:


class DelayedSomeCrashingScript : MonoBehaviour
{
    // click listener
    public void Crash1()
    {
        A();
    }

    private void A()
    {
        B();
    }

    private void B()
    {
        try
        {
            int[] elements = new int[5];
            int b = elements[2];
            int c = b + elements[6]; // IndexOutOfRangeException is here
            int d = c + elements[1];
        }
        catch (IndexOutOfRangeException exception)
        {
            UiLogger.Trace("exception.StackTrace:\n" + exception.StackTrace);
            string catchStackTrace = new StackTrace(0, true).ToString();
            UiLogger.Trace("catchStackTrace:\n" + catchStackTrace);
            UnityEngine.Debug.LogException(exception); // will see, what Unity logs with that call
            //UiLogger.DelayedLogException(exception); // calls Debug.LogException from some point in the future, using coroutine
        }
    }
}

Output:

exception.StackTrace:
  at DelayedSomeCrashingScript.B () [0x0000d] in C:\Playroom\UnityProjects\playunity\RxTest\Assets\Game\InternalApi\Crash\DelayedSomeCrashingScript.cs:33 

catchStackTrace:
   at DelayedSomeCrashingScript.B() in C:\Playroom\UnityProjects\playunity\RxTest\Assets\Game\InternalApi\Crash\DelayedSomeCrashingScript.cs:line 39
   at DelayedSomeCrashingScript.A() in C:\Playroom\UnityProjects\playunity\RxTest\Assets\Game\InternalApi\Crash\DelayedSomeCrashingScript.cs:line 24
   at DelayedSomeCrashingScript.Crash1() in C:\Playroom\UnityProjects\playunity\RxTest\Assets\Game\InternalApi\Crash\DelayedSomeCrashingScript.cs:line 19
   at UnityEngine.Events.InvokableCall.Invoke(System.Object[] args) in C:\buildslave\unity\build\Runtime\Export\UnityEvent.cs:line 153
   at UnityEngine.Events.InvokableCallList.Invoke(System.Object[] parameters) in C:\buildslave\unity\build\Runtime\Export\UnityEvent.cs:line 634
   at UnityEngine.Events.UnityEventBase.Invoke(System.Object[] parameters) in C:\buildslave\unity\build\Runtime\Export\UnityEvent.cs:line 769
   at UnityEngine.Events.UnityEvent.Invoke() in C:\buildslave\unity\build\Runtime\Export\UnityEvent_0.cs:line 53
   at UnityEngine.UI.Button.Press() in C:\buildslave\unity\build\Extensions\guisystem\UnityEngine.UI\UI\Core\Button.cs:line 35
   at UnityEngine.UI.Button.OnPointerClick(UnityEngine.EventSystems.PointerEventData eventData) in C:\buildslave\unity\build\Extensions\guisystem\UnityEngine.UI\UI\Core\Button.cs:line 44
   at UnityEngine.EventSystems.ExecuteEvents.Execute(IPointerClickHandler handler, UnityEngine.EventSystems.BaseEventData eventData) in C:\buildslave\unity\build\Extensions\guisystem\UnityEngine.UI\EventSystem\ExecuteEvents.cs:line 52
   at UnityEngine.EventSystems.ExecuteEvents.Execute(UnityEngine.GameObject target, UnityEngine.EventSystems.BaseEventData eventData, UnityEngine.EventSystems.EventFunction`1 functor) in C:\buildslave\unity\build\Extensions\guisystem\UnityEngine.UI\EventSystem\ExecuteEvents.cs:line 269
   at UnityEngine.EventSystems.StandaloneInputModule.ProcessMousePress(UnityEngine.EventSystems.MouseButtonEventData data) in C:\buildslave\unity\build\Extensions\guisystem\UnityEngine.UI\EventSystem\InputModules\StandaloneInputModule.cs:line 531
   at UnityEngine.EventSystems.StandaloneInputModule.ProcessMouseEvent(Int32 id) in C:\buildslave\unity\build\Extensions\guisystem\UnityEngine.UI\EventSystem\InputModules\StandaloneInputModule.cs:line 430
   at UnityEngine.EventSystems.StandaloneInputModule.ProcessMouseEvent() in C:\buildslave\unity\build\Extensions\guisystem\UnityEngine.UI\EventSystem\InputModules\StandaloneInputModule.cs:line 410
   at UnityEngine.EventSystems.StandaloneInputModule.Process() in C:\buildslave\unity\build\Extensions\guisystem\UnityEngine.UI\EventSystem\InputModules\StandaloneInputModule.cs:line 184
   at UnityEngine.EventSystems.EventSystem.Update() in C:\buildslave\unity\build\Extensions\guisystem\UnityEngine.UI\EventSystem\EventSystem.cs:line 287

OnLogMessageReceived
condition: IndexOutOfRangeException: Array index is out of range.
stacktrace:
DelayedSomeCrashingScript.B () (at Assets/Game/InternalApi/Crash/DelayedSomeCrashingScript.cs:33)
UnityEngine.Debug:LogException(Exception)
DelayedSomeCrashingScript:B() (at Assets/Game/InternalApi/Crash/DelayedSomeCrashingScript.cs:42)
DelayedSomeCrashingScript:A() (at Assets/Game/InternalApi/Crash/DelayedSomeCrashingScript.cs:24)
DelayedSomeCrashingScript:Crash1() (at Assets/Game/InternalApi/Crash/DelayedSomeCrashingScript.cs:19)
UnityEngine.EventSystems.EventSystem:Update()

type: Exception

And that's what is logged if we uncomment UiLogger.DelayedLogException(exception);


OnLogMessageReceived
condition: IndexOutOfRangeException: Array index is out of range.
stacktrace:
DelayedSomeCrashingScript.B () (at Assets/Game/InternalApi/Crash/DelayedSomeCrashingScript.cs:33)
UnityEngine.Debug:LogException(Exception)
<ExceptionReportRoutine>c__Iterator0:MoveNext() (at Assets/Plugins/DeepTest/InternalApi/UiLogger.cs:88)
UnityEngine.SetupCoroutine:InvokeMoveNext(IEnumerator, IntPtr)

type: Exception

We can see the following:
1. C#, indeed, sets the exception.StackTrace to delta between exception throw site and catch. As described here https://www.codeproject.com/Articles/121228/NET-Exception-stack-trace-has-no-frames-above-the
2. Debug.LogException adds frames to exception.StackTrace.

NOTE: Debug.LogException sums frames using following schema:
exception.StackTrace
+
frames between Debug.LogException call and some point in Unity framework's frames (so it does include all the user code, but sometimes exclude useful stack trace information like whether crash occured from button click or not)
+
EventSystem.Update() or EventSystem:Update()

NOTE: we get one restriction - Debug.Log must be used from catch or stack may get confusing (especially when logging from log coroutine as in stack above)

NOTE: tests were done in editor and android-release 4.4.2 (of course on android we have one difference - there were no file info, it's release without debug info after all)

Комментариев нет:

Отправить комментарий