Methods to troubleshoot UnobservedPromiseException

[drew-512]

Hi Tim and friends,

I'm getting a UnobservedPromiseException show up a minute or two after I've stopped Unity when GC catches up. This means I have zero info on where or why my code is not resolving a deferred promise.

Is there any way to have PROMISE_DEBUG record the top of stack trace when a deferred promise is created? Another idea would be to allow a debug label (string) to be attached to a promise. In non-debug mode, the string is just dropped and not part of a promise struct, but in debug mode it would travel around with the promise allowing the developer to see its origin.

Drew

[timcassell]

Hi Drew,

UnobservedPromiseException means a promise was not awaited or forgotten. If a deferred was left pending, it would instead be a UnhandledDeferredException.

The exception message should explain how to enable causality traces to find the culprit. You need to be in DEBUG mode and set Promise.Config.DebugCausalityTracer = Promise.TraceLevel.All.

[drew-512]

Ah, ok thanks for the correction there.

I did have Promise.TraceLevel.All set, however it's unclear what I need to look at for help. There are a ton of fields and the ones that are interesting like the stack trace are truncated by VSCode.

What and where should I look for more information?

[timcassell]

Oh, it looks you even enabled developer mode! That shouldn't be necessary for you, that's really for me to debug the internal promise code. You should disable that to get a cleaner causality trace (it strips internal promise frames if it's disabled).

The information you're looking for is in the Stacktrace of the UnhandledException, in this case the one that contains the UnobservedPromiseException as its InnerException.

[timcassell]

I think VS has options to view the entire stacktrace if you right-click it. Otherwise, you could try grabbing the ToString() of the entire exception, which should include all of the stacktrace information.

[timcassell]

Also, when it's printed to the console in Unity, it should include the full stacktrace there. If it's truncated in the console, you can view the full thing in the log file (the console can open it directly from the ... dropdown).

[drew-512]

I wasn't getting any info from Unity since the exception was happening when play mode was starting (when GC was likely happening from the last play). This means any exception msgs pushed to Unity were being cleared as play mode begins. Meanwhile, VSCode / C# is still highly unimpressive with strings in the debugger. I ended up just putting in some lines that print the stack trace to a Debug.Log message. Given this somewhat likely scenario (where GC occurring right before entering play mode), perhaps an enhancement here makes sense.

Anyway, the offender suprisingly is await Promise.SwitchToForeground(), made from an async void proc that exits during app shutdown (play mode exit):

async void sessionReader(NetworkStream stream) {
    await Promise.SwitchToBackground();
    string logMsg = null;
    try {
        var hdr = new byte[TxMsg.TxHeaderSz];
        int bytesRead;                     

        while ((bytesRead = stream.Read(hdr, 0, TxMsg.TxHeaderSz)) == TxMsg.TxHeaderSz) {
            var tx = TxMsg.Acquire(hdr);
            if ((bytesRead = stream.Read(tx.TxStore, TxMsg.TxBodyOfs, tx.TxBodyLen)) != tx.TxBodyLen) {
                throw new Exception($"Failed to read TxMsg body: {bytesRead} != {tx.TxBodyLen}");
            }
            handleIncomingTx(tx);
        }
    } catch (Exception ex) {
        logMsg = ex.ToString();
    }

    // Cancel the writer if the reader stops
    Cancel();

    await Promise.SwitchToForeground();
    if (logMsg != null) {
        Logger.Warn(logMsg);
    }

    // Tell controller we're fully disconnected
    _client.OnConnectionClosed();
}

[timcassell]

I wasn't getting any info from Unity since the exception was happening when play mode was starting (when GC was likely happening from the last play). This means any exception msgs pushed to Unity were being cleared as play mode begins.

You can fix that by disabling clear on play mode.

Anyway, the offender suprisingly is await Promise.SwitchToForeground(), made from an async void proc that exits during app shutdown (play mode exit):

I'm guessing that's because you have AppDomain reload disabled. The default exception handler ignores any further exceptions after OnApplicationQuit. Since it occurs when you start the game again, it no longer considers it to be in the quitting state, so it does log it.

I can't think of a nice way to handle that case, I'm open to suggestions.

[drew-512]

Hmm, is there any way to catch or prevent whatever is going on with that await Promise.SwitchToForeground()?

[timcassell]

Hmm, is there any way to catch or prevent whatever is going on with that await Promise.SwitchToForeground()?

Suffice to say, there's nothing wrong with your code, and you won't see this issue in production. This is purely a side effect of stopping and restarting code without resetting its run context (AppDomain reload here, process isolation in built player).

[timcassell]

Perhaps I could add an API like Promise.Manager.ResetRuntimeContext() that can be called from OnApplicationQuit or SubsystemRegistration. That would then ignore exceptions from every object created before ResetRuntimeContext was called.

[drew-512]

If it's interesting, Unity seems to be being mean to your exceptions.

[timcassell]

That looks like it's from throwing the exception on a ThreadPool thread after the default exception handler is removed from OnApplicationQuit. Kinda weird that they truncate the inner exceptions, but oh well. I guess their background thread exception handler just logs warning with the exception's message, rather than its full ToString.

[timcassell]

So I tried to repro that code in a test case, and it passes every time I run it. I debugged it and saw the promise was marked as awaited (as it should be). The only thing I can think of is the background thread is being aborted in the middle of the await. I'm unaware of Unity aborting background threads without the AppDomain being reloaded. Are you perhaps running your own background SynchronizationContext and aborting threads yourself?

private class StrongBox<T>
{
    public T value;
}

[MethodImpl(MethodImplOptions.NoInlining)]
private static async void RunAndSwitchContext(StrongBox<bool> box, SynchronizationContext context)
{
    await Promise.SwitchToBackground();
    box.value = true;
    await Promise.SwitchToContext(context);
    box.value = true;
}

[Test]
public void PromiseSwitchToContext_NeverExecuted_NoExceptions()
{
    // We're purposefully not completing the promise, to simulate Unity's enter/exit playmode.
    var box = new StrongBox<bool>();
    RunAndSwitchContext(box, new NeverExecutedSynchronizationContext());
    while (!box.value) { Thread.MemoryBarrier(); }
    box.value = false;
    Thread.Sleep(1000);
    Assert.False(box.value);

    TestHelper.GcCollectAndWaitForFinalizers();
}

[timcassell]

@drew-512 Can you confirm if aborting threads is the cause?

[drew-512]

Hi Tim,

Not aborting any threads. I start a reader and writer via await Promise.SwitchToBackground(); and only exit those threads (which I'm not regarding as aborting).

Can I test something specifically?

[timcassell]

So you're not setting anything in Promise.Config? Just using the default values? I'm trying to determine the root cause of the issue, and if it's not thread aborts, I can't think of what it might be.

[timcassell]

@drew-512 Could you possibly send me a repro project?

[drew-512]

If I'm hearing you right, you'd like a repro project of the shows a warning as in my Oct 18 post?

I have to sheepishly admit that I didn't event know about Promise.Config until your mention of it above (and so had not made any changes to that).

[timcassell]

If I'm hearing you right, you'd like a repro project of the shows a warning as in my Oct 18 post?

If possible, yes. I'm uncomfortable merging #303 without understanding the actual cause.

I have to sheepishly admit that I didn't event know about Promise.Config until your mention of it above (and so had not made any changes to that).

No worries, that's good to know. (Although if you had set Promise.TraceLevel.All, then you were using it. 😉)

[drew-512]

Sorry for the delay, been a tough go personally lately.

Ok, I'll use the latest release version (not branch)? What vars should I set exactly out of Promise.Config to give you the output or stack that you're looking for?

[timcassell]

You didn't change any defaults before so no need to do so now. I just need to be able to repro it like you had before, then I can start debugging it myself.

[timcassell]

Nevermind, I was able to reproduce it with this code in editor.

void Start()
{
    for (int i = 0; i < Environment.ProcessorCount; ++i)
    {
        Func().Forget();
    }
}

private async Promise Func()
{
    while (true)
    {
        await Promise.SwitchToBackground();
        Thread.Sleep(10);
        await Promise.SwitchToForeground();
    }
}

[timcassell]

Aha, looks like it was fixed in #306! To confirm, I added a try/catch:

try
{
    await Promise.SwitchToForeground();
}
catch (Exception e)
{
    Debug.LogException(e);
}

And that actually logs InvalidOperationException: SynchronizationOption.Foreground was provided, but Promise.Config.ForegroundContext was null. You should set Promise.Config.ForegroundContext at the start of your application (which may be as simple as 'Promise.Config.ForegroundContext = SynchronizationContext.Current;').

@drew-512 If you try latest master, it should be fixed. Thank you very much for the bug report, and please let me know if you hit any other issues!

[drew-512]

Yay, nice work! Switching to main!