Search Unity

Question Unity LogAssert with async methods

Discussion in 'Testing & Automation' started by Kek_Chpeck, Nov 2, 2023.

  1. Kek_Chpeck

    Kek_Chpeck

    Joined:
    Feb 9, 2019
    Posts:
    16
    My goal is to implement a test, that can check if an error is logged, when it is happened in the
    async void
    method.

    I have this sample class for editor mode auto-testing in Unity3d:
    Code (CSharp):
    1.  
    2. public class AsyncLogTest
    3. {
    4.    [Test]
    5.    public void Test1()
    6.    {
    7.        ThrowException();
    8.        LogAssert.Expect(LogType.Exception, new Regex(".*"));
    9.    }
    10.    
    11.    [Test]
    12.    public void Test2()
    13.    {
    14.        DirectLog();
    15.        LogAssert.Expect(LogType.Exception, new Regex(".*"));
    16.    }
    17.  
    18.    [UnityTest]
    19.    public IEnumerator Test3()
    20.    {
    21.        LogAssert.ignoreFailingMessages = true;
    22.        ThrowException();
    23.        yield return null;
    24.        LogAssert.Expect(LogType.Exception, new Regex(".*"));
    25.    }
    26.  
    27.    [UnityTest]
    28.    public IEnumerator Test4()
    29.    {
    30.        ThrowException();
    31.        // Wait for 1 second
    32.        var stopwatch = new Stopwatch();
    33.        stopwatch.Start();
    34.        while (stopwatch.ElapsedMilliseconds < 1000)
    35.        {
    36.            yield return null;
    37.        }
    38.        stopwatch.Stop();
    39.        LogAssert.Expect(LogType.Exception, new Regex(".*"));
    40.    }
    41.  
    42.    [UnityTest]
    43.    public IEnumerator Test5()
    44.    {
    45.        LogAssert.ignoreFailingMessages = true;
    46.        ThrowException();
    47.        // Wait for 1 second
    48.        var stopwatch = new Stopwatch();
    49.        stopwatch.Start();
    50.        while (stopwatch.ElapsedMilliseconds < 1000)
    51.        {
    52.            yield return null;
    53.        }
    54.        stopwatch.Stop();
    55.        LogAssert.Expect(LogType.Exception, new Regex(".*"));
    56.    }
    57.  
    58.    public async void ThrowException()
    59.    {
    60.        throw new Exception();
    61.    }
    62.  
    63.    public async void DirectLog()
    64.    {
    65.        Debug.LogException(new Exception());
    66.    }
    67. }
    68.  
    The result of this tests is next:
    • Test1 - always fails due to
      Expected log did not appear: [Exception] Regex: .*.
    • Test2 - always success.
    • Test3 - sometimes fails, sometimes success. Fail reason -
      Expected log did not appear: [Exception] Regex: .*
    • Test4 - always fails due to
      Unhandled log message: '[Exception] Exception: Exception of type 'System.Exception' was thrown.'. Use UnityEngine.TestTools.LogAssert.Expect
    • Test 5 - always success.
    Also I can see the correct exception log in Unity3d console for all of these tests. Even for those, that fails.

    I can make some conclusions and raise some questions based on these results.

    • Firstly, looks like exceptions, that are thrown in async methods are not logged instantly, but written to some kind of buffer, and logged only when this buffer is purged. Also, this buffer purging does not depend on engine
      Update
      tick, or this dependency is not clear for me. I can say all of this because
      Test5
      , where I wait great amount of time success always, but
      Test3
      where I wait only for one engine tick is unstable and looks like this exceptions buffer can either be purged while this tick elapsed or not.
    • Secondly, for some reason, I have to specify
      LogAssert.ignoreFailingMessages = true;
      for exceptions logs, that are logged from this buffer, but I don't have to do it if exception logged explicitly.
      Test4
      and
      Test5
      results illustrate this well.
    So the question is how to make a test, that assert exception, raised in async method, logged? And make it most efficient. I mean, the case when I should wait a second is not suitable for auto-tests, of course. I expect, I can do something like this:
    Code (CSharp):
    1. [Test]
    2. public void Test()
    3. {
    4.     ThrowException();
    5.     UnityAPI.ForceLogAllAsyncExceptions(); // I imagine this method
    6.     LogAssert.Expect(LogType.Exception, new Regex(".*"));
    7. }
    Or any other solutions.
     
  2. nowsprinting

    nowsprinting

    Joined:
    Nov 3, 2014
    Posts:
    18
    Last edited: Nov 3, 2023
  3. Kek_Chpeck

    Kek_Chpeck

    Joined:
    Feb 9, 2019
    Posts:
    16
    What makes you think these tests fails due to exceptions? I thought I wrote reasons pretty clearly:
     
  4. sbergen

    sbergen

    Joined:
    Jan 12, 2015
    Posts:
    53
    There's no simple way to check/guarantee that an async void method has completed at any given time. In some of your cases, it's completing after the test has finished. The common guideline would be to not use async void methods, but if you really have to, then I'd suggest looking for solutions on "how to wait for an async void method to complete".
     
  5. Kek_Chpeck

    Kek_Chpeck

    Joined:
    Feb 9, 2019
    Posts:
    16
    What do you mean by method completing?
     
  6. Kek_Chpeck

    Kek_Chpeck

    Joined:
    Feb 9, 2019
    Posts:
    16
    sbergen I'm not sure what completing do you mean, but
    async
    methods without
    await
    always execute synchronously. I can add such kind of test to make you sure about it. This test does stably fail same way as
    Test1
    . And again I can see correct exception in editor log.
    Code (CSharp):
    1.         [Test]
    2.         public void Test6()
    3.         {
    4.             var t = new TaskCompletionSource<object>();
    5.             ThrowException(t);
    6.             t.Task.Wait();
    7.             LogAssert.Expect(LogType.Exception, new Regex(".*"));
    8.         }
    9.    
    10.         public async void ThrowException(TaskCompletionSource<object> t)
    11.         {
    12.             try
    13.             {
    14.                 throw new Exception();
    15.             }
    16.             finally
    17.             {
    18.                 t.SetResult(new object());
    19.             }
    20.         }
     
    Last edited: Nov 3, 2023
  7. sbergen

    sbergen

    Joined:
    Jan 12, 2015
    Posts:
    53
    First off, I was assuming you actually have some async code in the method you'd actually want to test: why would you use async void otherwise?

    Second, exception handling from async void methods gets dispatched to the synchronization context, which in Unity seems to happen asynchronously, even if you are already on the main thread. I've run into a few similar cases before, where certain async/await behaviours are slightly different in Unity than in .NET console applications at least.

    "Completed" was perhaps not the clearest term to use. Let's rather say that there's no simple way to know when all the side effects of an async void method have been fully applied.