From 543e7318591e681d0eba67eda0f55dd9b4bd60fb Mon Sep 17 00:00:00 2001 From: nitely Date: Sat, 29 Nov 2025 21:56:55 -0300 Subject: [PATCH 1/2] Port asyncdispatch stacktraces improvement --- chronos/internal/asyncfutures.nim | 136 +++++++++--------- docs/src/error_handling.md | 2 + tests/testall.nim | 6 +- tests/testasyncstacktrace.nim | 224 ++++++++++++++++++++++++++++++ 4 files changed, 304 insertions(+), 64 deletions(-) create mode 100644 tests/testasyncstacktrace.nim diff --git a/chronos/internal/asyncfutures.nim b/chronos/internal/asyncfutures.nim index e04dffe1e..ca0f70fa4 100644 --- a/chronos/internal/asyncfutures.nim +++ b/chronos/internal/asyncfutures.nim @@ -13,7 +13,7 @@ {.push raises: [].} -import std/[sequtils, macros] +import std/[sequtils, sets, macros] import stew/base10 import ./[asyncengine, raisesfutures] @@ -25,12 +25,13 @@ export when chronosStackTrace: import std/strutils - when defined(nimHasStacktracesModule): - import system/stacktraces - else: - const - reraisedFromBegin = -10 - reraisedFromEnd = -100 + +when defined(nimHasStacktracesModule): + import system/stacktraces +else: + const + reraisedFromBegin = -10 + reraisedFromEnd = -100 template LocCreateIndex*: auto {.deprecated: "LocationKind.Create".} = LocationKind.Create @@ -405,60 +406,72 @@ proc futureContinue*(fut: FutureBase) {.raises: [], gcsafe.} = {.pop.} -when chronosStackTrace: - template getFilenameProcname(entry: StackTraceEntry): (string, string) = - when compiles(entry.filenameStr) and compiles(entry.procnameStr): - # We can't rely on "entry.filename" and "entry.procname" still being valid - # cstring pointers, because the "string.data" buffers they pointed to might - # be already garbage collected (this entry being a non-shallow copy, - # "entry.filename" no longer points to "entry.filenameStr.data", but to the - # buffer of the original object). - (entry.filenameStr, entry.procnameStr) - else: - ($entry.filename, $entry.procname) - - proc `$`(stackTraceEntries: seq[StackTraceEntry]): string = - try: - when defined(nimStackTraceOverride) and declared(addDebuggingInfo): - let entries = addDebuggingInfo(stackTraceEntries) - else: - let entries = stackTraceEntries - - # Find longest filename & line number combo for alignment purposes. - var longestLeft = 0 - for entry in entries: - let (filename, procname) = getFilenameProcname(entry) - - if procname == "": continue - - let leftLen = filename.len + len($entry.line) - if leftLen > longestLeft: - longestLeft = leftLen - - var indent = 2 - # Format the entries. - for entry in entries: - let (filename, procname) = getFilenameProcname(entry) - - if procname == "": - if entry.line == reraisedFromBegin: - result.add(spaces(indent) & "#[\n") - indent.inc(2) - elif entry.line == reraisedFromEnd: - indent.dec(2) - result.add(spaces(indent) & "]#\n") - continue - - let left = "$#($#)" % [filename, $entry.line] - result.add((spaces(indent) & "$#$# $#\n") % [ - left, - spaces(longestLeft - left.len + 2), - procname - ]) - except ValueError as exc: - return exc.msg # Shouldn't actually happen since we set the formatting - # string +template getFilenameProcname(entry: StackTraceEntry): (string, string) = + when compiles(entry.filenameStr) and compiles(entry.procnameStr): + # We can't rely on "entry.filename" and "entry.procname" still being valid + # cstring pointers, because the "string.data" buffers they pointed to might + # be already garbage collected (this entry being a non-shallow copy, + # "entry.filename" no longer points to "entry.filenameStr.data", but to the + # buffer of the original object). + (entry.filenameStr, entry.procnameStr) + else: + ($entry.filename, $entry.procname) + +proc format(entry: StackTraceEntry): string = + let (filename, procname) = getFilenameProcname(entry) + result = filename + result.add '(' + result.add $entry.line + result.add ')' + result.add ' ' + result.add procname + result.add '\n' + +proc isInternal(entry: StackTraceEntry): bool = + template endsWith(a, b: string): bool = + let start = max(0, a.len - b.len) + toOpenArray(a, start, a.len - 1) == toOpenArray(b, 0, b.len - 1) + + # --excessiveStackTrace:off + const internals = [ + "asyncengine.nim", + "asyncfutures.nim", + # TODO: https://github.com/nim-lang/Nim/issues/24670 + "system.nim", + "threadimpl.nim" + ] + let (filename, procname) = getFilenameProcname(entry) + for line in internals: + if filename.endsWith line: + return true + false + +proc getAsyncStackTrace*(ex: ref Exception): string = + ## Returns `ex` stack trace. + result = "" + when defined(nimStackTraceOverride) and declared(addDebuggingInfo): + let entries = addDebuggingInfo(ex.getStackTraceEntries()) + else: + let entries = ex.getStackTraceEntries() + var seenEntries = initHashSet[StackTraceEntry]() + let L = entries.len-1 + var i = L + var j = 0 + while i >= 0: + if entries[i].line == reraisedFromBegin or i == 0: + j = i + int(i != 0) + while j < L: + if entries[j].line == reraisedFromBegin: + break + if entries[j].line >= 0 and not isInternal(entries[j]): + # this skips recursive calls sadly + if entries[j] notin seenEntries: + result.add format(entries[j]) + seenEntries.incl entries[j] + inc j + dec i +when chronosStackTrace: proc injectStacktrace(error: ref Exception) = const header = "\nAsync traceback:\n" @@ -471,8 +484,7 @@ when chronosStackTrace: var newMsg = exceptionMsg & header - let entries = getStackTraceEntries(error) - newMsg.add($entries) + newMsg.add error.getAsyncStackTrace() newMsg.add("Exception message: " & exceptionMsg & "\n") diff --git a/docs/src/error_handling.md b/docs/src/error_handling.md index 2b03dc2ae..e9376a31e 100644 --- a/docs/src/error_handling.md +++ b/docs/src/error_handling.md @@ -38,6 +38,8 @@ echo "fut3.state = ", fut3.state # "Failed" if fut3.failed(): echo "p3() failed: ", fut3.error.name, ": ", fut3.error.msg # prints "p3() failed: ValueError: ValueError inherits from CatchableError" + echo "stack trace: \n", fut3.error.getAsyncStackTrace() + # prints a pretty version of the full stack trace ``` You can put the `await` in a `try` block, to deal with that exception sooner: diff --git a/tests/testall.nim b/tests/testall.nim index 5013a2bcb..a1e5e2569 100644 --- a/tests/testall.nim +++ b/tests/testall.nim @@ -11,7 +11,8 @@ when (chronosEventEngine in ["epoll", "kqueue"]) or defined(windows): import testmacro, testsync, testsoon, testtime, testfut, testsignal, testaddress, testdatagram, teststream, testserver, testbugs, testnet, testasyncstream, testhttpserver, testshttpserver, testhttpclient, - testproc, testratelimit, testfutures, testthreadsync, testasyncsemaphore + testproc, testratelimit, testfutures, testthreadsync, testasyncsemaphore, + testasyncstacktrace # Must be imported last to check for Pending futures import testutils @@ -20,7 +21,8 @@ elif chronosEventEngine == "poll": import testmacro, testsync, testsoon, testtime, testfut, testaddress, testdatagram, teststream, testserver, testbugs, testnet, testasyncstream, testhttpserver, testshttpserver, testhttpclient, - testratelimit, testfutures, testthreadsync, testasyncsemaphore + testratelimit, testfutures, testthreadsync, testasyncsemaphore, + testasyncstacktrace # Must be imported last to check for Pending futures import testutils \ No newline at end of file diff --git a/tests/testasyncstacktrace.nim b/tests/testasyncstacktrace.nim new file mode 100644 index 000000000..674f906ee --- /dev/null +++ b/tests/testasyncstacktrace.nim @@ -0,0 +1,224 @@ +# Chronos Test Suite +# (c) Copyright 2018-Present +# Status Research & Development GmbH +# +# Licensed under either of +# Apache License, version 2.0, (LICENSE-APACHEv2) +# MIT license (LICENSE-MIT) + +{.used.} + +import std/[strscans, strutils] +import ../chronos + +proc stripped(content: string): string = + proc keepLastPart(s: var string, c: char) = + if c in {'/', '\\'}: + s.setLen 0 + elif c in "1234567890": + discard + else: + s.add c + + result = "" + var idx = 0 + while true: + var entry = "" + if scanp(content, idx, +((~{'\n', '\0'}) -> entry.keepLastPart($_)), '\n'): + result.add entry + result.add '\n' + else: + break + +proc err() = + raise newException(ValueError, "the_error_msg") + +template test(name: string, body: untyped): untyped = + block: + echo "[", name, ": OK]" + body + +const hasStackTrace = compileOption("stacktrace") + +test "recursion": + proc recursion(i: int) {.async.} = + if i == 5: + err() + await sleepAsync(1.milliseconds) + await recursion(i + 1) + + proc main() {.async.} = + await recursion(0) + + try: + waitFor main() + doAssert false + except ValueError as err: + let expected = + when hasStackTrace: + """ + testasyncstacktrace.nim() testasyncstacktrace + testasyncstacktrace.nim() main + testasyncstacktrace.nim() recursion + testasyncstacktrace.nim() recursion + testasyncstacktrace.nim() err + """.dedent + else: + """ + testasyncstacktrace.nim() err + testasyncstacktrace.nim() recursion + testasyncstacktrace.nim() main + """.dedent + doAssert err.getAsyncStackTrace().stripped == expected, + err.getAsyncStackTrace().stripped + +test "simple": + proc baz() = + err() + + proc bar() = + baz() + + proc foo() {.async.} = + await sleepAsync(1.milliseconds) + bar() + + proc main() {.async.} = + await foo() + + try: + waitFor main() + doAssert false + except ValueError as err: + let expected = + when hasStackTrace: + """ + testasyncstacktrace.nim() testasyncstacktrace + testasyncstacktrace.nim() main + testasyncstacktrace.nim() foo + testasyncstacktrace.nim() bar + testasyncstacktrace.nim() baz + testasyncstacktrace.nim() err + """.dedent + else: + """ + testasyncstacktrace.nim() err + testasyncstacktrace.nim() main + """.dedent + doAssert err.getAsyncStackTrace().stripped == expected, + err.getAsyncStackTrace().stripped + +test "async work": + proc baz() {.async.} = + await sleepAsync(1.milliseconds) + raise newException(ValueError, "the_error_msg") + + proc bar() {.async.} = + await sleepAsync(1.milliseconds) + await baz() + + proc foo() {.async.} = + await sleepAsync(1.milliseconds) + await bar() + + proc main() {.async.} = + await foo() + + try: + waitFor main() + doAssert false + except ValueError as err: + let expected = + when hasStackTrace: + """ + testasyncstacktrace.nim() testasyncstacktrace + testasyncstacktrace.nim() main + testasyncstacktrace.nim() foo + testasyncstacktrace.nim() bar + testasyncstacktrace.nim() baz + """.dedent + else: + """ + testasyncstacktrace.nim() baz + testasyncstacktrace.nim() bar + testasyncstacktrace.nim() foo + testasyncstacktrace.nim() main + """.dedent + doAssert err.getAsyncStackTrace().stripped == expected, + err.getAsyncStackTrace().stripped + +test "interleaved async work": + proc baz() {.async.} = + await sleepAsync(1.milliseconds) + raise newException(ValueError, "the_error_msg") + + proc bar() {.async.} = + #await sleepAsync(1.milliseconds) + await baz() + + proc foo() {.async.} = + await sleepAsync(1.milliseconds) + await bar() + + proc main() {.async.} = + await foo() + + try: + waitFor main() + doAssert false + except ValueError as err: + let expected = + when hasStackTrace: + """ + testasyncstacktrace.nim() testasyncstacktrace + testasyncstacktrace.nim() main + testasyncstacktrace.nim() foo + testasyncstacktrace.nim() bar + testasyncstacktrace.nim() baz + """.dedent + else: + """ + testasyncstacktrace.nim() baz + testasyncstacktrace.nim() bar + testasyncstacktrace.nim() foo + testasyncstacktrace.nim() main + """.dedent + doAssert err.getAsyncStackTrace().stripped == expected, + err.getAsyncStackTrace().stripped + +test "no async work": + proc baz() {.async.} = + raise newException(ValueError, "the_error_msg") + + proc bar() {.async.} = + await baz() + + proc foo() {.async.} = + await bar() + + proc main() {.async.} = + await foo() + + try: + waitFor main() + doAssert false + except ValueError as err: + poll() + let expected = + when hasStackTrace: + """ + testasyncstacktrace.nim() testasyncstacktrace + testasyncstacktrace.nim() main + testasyncstacktrace.nim() foo + testasyncstacktrace.nim() bar + testasyncstacktrace.nim() baz + """.dedent + else: + """ + testasyncstacktrace.nim() baz + testasyncstacktrace.nim() bar + testasyncstacktrace.nim() foo + testasyncstacktrace.nim() main + """.dedent + doAssert err.getAsyncStackTrace().stripped == expected, + err.getAsyncStackTrace().stripped From 994840503f2aef9a9b2e5275c23ab51f4a8f3979 Mon Sep 17 00:00:00 2001 From: nitely Date: Sat, 29 Nov 2025 22:19:19 -0300 Subject: [PATCH 2/2] wip --- chronos/internal/asyncfutures.nim | 1 + tests/testasyncstacktrace.nim | 16 ++++++++-------- 2 files changed, 9 insertions(+), 8 deletions(-) diff --git a/chronos/internal/asyncfutures.nim b/chronos/internal/asyncfutures.nim index ca0f70fa4..cd50f7427 100644 --- a/chronos/internal/asyncfutures.nim +++ b/chronos/internal/asyncfutures.nim @@ -437,6 +437,7 @@ proc isInternal(entry: StackTraceEntry): bool = "asyncengine.nim", "asyncfutures.nim", # TODO: https://github.com/nim-lang/Nim/issues/24670 + #"excpt.nim", "system.nim", "threadimpl.nim" ] diff --git a/tests/testasyncstacktrace.nim b/tests/testasyncstacktrace.nim index 674f906ee..f06caae47 100644 --- a/tests/testasyncstacktrace.nim +++ b/tests/testasyncstacktrace.nim @@ -44,7 +44,7 @@ test "recursion": proc recursion(i: int) {.async.} = if i == 5: err() - await sleepAsync(1.milliseconds) + await sleepAsync(100.milliseconds) await recursion(i + 1) proc main() {.async.} = @@ -80,7 +80,7 @@ test "simple": baz() proc foo() {.async.} = - await sleepAsync(1.milliseconds) + await sleepAsync(100.milliseconds) bar() proc main() {.async.} = @@ -110,15 +110,15 @@ test "simple": test "async work": proc baz() {.async.} = - await sleepAsync(1.milliseconds) + await sleepAsync(100.milliseconds) raise newException(ValueError, "the_error_msg") proc bar() {.async.} = - await sleepAsync(1.milliseconds) + await sleepAsync(100.milliseconds) await baz() proc foo() {.async.} = - await sleepAsync(1.milliseconds) + await sleepAsync(100.milliseconds) await bar() proc main() {.async.} = @@ -149,15 +149,15 @@ test "async work": test "interleaved async work": proc baz() {.async.} = - await sleepAsync(1.milliseconds) + await sleepAsync(100.milliseconds) raise newException(ValueError, "the_error_msg") proc bar() {.async.} = - #await sleepAsync(1.milliseconds) + #await sleepAsync(100.milliseconds) await baz() proc foo() {.async.} = - await sleepAsync(1.milliseconds) + await sleepAsync(100.milliseconds) await bar() proc main() {.async.} =