Improve async stacktraces (#24563)

This makes await point to the caller line instead of asyncmacro. It also
reworks the "Async traceback:" section of the traceback. Follow up PR
#21091 (issue #19931) so it works if there is asynchronous work done.

lib/pure/asyncfutures.nim

@@ -7,7 +7,7 @@
 #    distribution, for details about the copyright.
 #
 
-import std/[os, tables, strutils, times, heapqueue, options, deques, cstrutils, typetraits]
+import std/[os, sets, tables, strutils, times, heapqueue, options, deques, cstrutils, typetraits]
 
 import system/stacktraces
 
@@ -293,57 +293,47 @@ template getFilenameProcname(entry: StackTraceEntry): (string, string) =
   else:
     ($entry.filename, $entry.procname)
 
-proc getHint(entry: StackTraceEntry): string =
-  ## We try to provide some hints about stack trace entries that the user
-  ## may not be familiar with, in particular calls inside the stdlib.
-
+proc format(entry: StackTraceEntry): string =
   let (filename, procname) = getFilenameProcname(entry)
+  let left = "$#($#)" % [filename, $entry.line]
+  result = spaces(2) & "$# $#\n" % [left, procname]
 
-  result = ""
-  if procname == "processPendingCallbacks":
-    if cmpIgnoreStyle(filename, "asyncdispatch.nim") == 0:
-      return "Executes pending callbacks"
-  elif procname == "poll":
-    if cmpIgnoreStyle(filename, "asyncdispatch.nim") == 0:
-      return "Processes asynchronous completion events"
-
-  if procname.endsWith(NimAsyncContinueSuffix):
-    if cmpIgnoreStyle(filename, "asyncmacro.nim") == 0:
-      return "Resumes an async procedure"
+proc isInternal(entry: StackTraceEntry): bool =
+  # --excessiveStackTrace:off
+  const internals = [
+    "asyncdispatch.nim",
+    "asyncfutures.nim",
+    "threadimpl.nim",  # XXX ?
+  ]
+  let (filename, procname) = getFilenameProcname(entry)
+  for line in internals:
+    if filename.endsWith line:
+      return true
+  return false
 
 proc `$`*(stackTraceEntries: seq[StackTraceEntry]): string =
+  result = ""
   when defined(nimStackTraceOverride):
     let entries = addDebuggingInfo(stackTraceEntries)
   else:
     let entries = stackTraceEntries
-
-  result = ""
-  # 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
-
-  # Format the entries.
-  for entry in entries:
-    let (filename, procname) = getFilenameProcname(entry)
-
-    if procname == "" and entry.line == reraisedFromBegin:
-      break
-
-    let left = "$#($#)" % [filename, $entry.line]
-    result.add((spaces(2) & "$# $#\n") % [
-      left,
-      procname
-    ])
-    let hint = getHint(entry)
-    if hint.len > 0:
-      result.add(spaces(4) & "## " & hint & "\n")
+  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
 
 proc injectStacktrace[T](future: Future[T]) =
   when not defined(release):
@@ -356,7 +346,6 @@ proc injectStacktrace[T](future: Future[T]) =
       let start = exceptionMsg.find(header)
       exceptionMsg = exceptionMsg[0..<start]
 
-
     var newMsg = exceptionMsg & header
 
     let entries = getStackTraceEntries(future.error)

lib/pure/asyncmacro.nim

@@ -170,7 +170,8 @@ template await*[T](f: Future[T]): auto {.used.} =
   when compiles(yieldFuture):
     var internalTmpFuture: FutureBase = f
     yield internalTmpFuture
-    (cast[typeof(f)](internalTmpFuture)).read()
+    {.line: instantiationInfo(fullPaths = true).}:
+      (cast[typeof(f)](internalTmpFuture)).read()
   else:
     macro errorAsync(futureError: Future[T]) =
       error(

tests/async/tasync_traceback.nim

@@ -76,12 +76,7 @@ Exception message: b failure
 bar failure
 Async traceback:
   tasync_traceback\.nim\(\d+?\) tasync_traceback
-  asyncdispatch\.nim\(\d+?\) waitFor
-  asyncdispatch\.nim\(\d+?\) poll
-    ## Processes asynchronous completion events
-  asyncdispatch\.nim\(\d+?\) runOnce
-  asyncdispatch\.nim\(\d+?\) processPendingCallbacks
-    ## Executes pending callbacks
+  tasync_traceback\.nim\(\d+?\) foo \(Async\)
   tasync_traceback\.nim\(\d+?\) bar \(Async\)
 Exception message: bar failure
 

tests/async/tasync_traceback2.nim

@@ -0,0 +1,158 @@
+import std/asyncdispatch
+import std/re
+from std/strutils import dedent
+
+proc err() =
+  raise newException(ValueError, "the_error_msg")
+
+block:
+  proc recursion(i: int) {.async.} =
+    if i == 5:
+      err()
+    await sleepAsync(1)
+    await recursion(i+1)
+
+  proc main {.async.} =
+    await recursion(0)
+
+  try:
+    waitFor main()
+    doAssert false
+  except ValueError as err:
+    let expected = """
+      the_error_msg
+      Async traceback:
+        tasync_traceback2\.nim\(\d+\) tasync_traceback2
+        tasync_traceback2\.nim\(\d+\) main \(Async\)
+        tasync_traceback2\.nim\(\d+\) recursion \(Async\)
+        tasync_traceback2\.nim\(\d+\) recursion \(Async\)
+        tasync_traceback2\.nim\(\d+\) err
+      Exception message: the_error_msg
+      """.dedent
+    doAssert match(err.msg, re(expected)), err.getStackTrace & err.msg
+
+block:
+  proc baz() =
+    err()
+
+  proc bar() =
+    baz()
+
+  proc foo() {.async.} =
+    await sleepAsync(1)
+    bar()
+
+  proc main {.async.} =
+    await foo()
+
+  try:
+    waitFor main()
+    doAssert false
+  except ValueError as err:
+    let expected = """
+      the_error_msg
+      Async traceback:
+        tasync_traceback2\.nim\(\d+\) tasync_traceback2
+        tasync_traceback2\.nim\(\d+\) main \(Async\)
+        tasync_traceback2\.nim\(\d+\) foo \(Async\)
+        tasync_traceback2\.nim\(\d+\) bar
+        tasync_traceback2\.nim\(\d+\) baz
+        tasync_traceback2\.nim\(\d+\) err
+      Exception message: the_error_msg
+      """.dedent
+    doAssert match(err.msg, re(expected)), err.getStackTrace & err.msg
+
+block:  # async work
+  proc baz() {.async.} =
+    await sleepAsync(1)
+    raise newException(ValueError, "the_error_msg")
+
+  proc bar() {.async.} =
+    await sleepAsync(1)
+    await baz()
+
+  proc foo() {.async.} =
+    await sleepAsync(1)
+    await bar()
+
+  proc main {.async.} =
+    await foo()
+
+  try:
+    waitFor main()
+    doAssert false
+  except ValueError as err:
+    let expected = """
+      the_error_msg
+      Async traceback:
+        tasync_traceback2\.nim\(\d+\) tasync_traceback2
+        tasync_traceback2\.nim\(\d+\) main \(Async\)
+        tasync_traceback2\.nim\(\d+\) foo \(Async\)
+        tasync_traceback2\.nim\(\d+\) bar \(Async\)
+        tasync_traceback2\.nim\(\d+\) baz \(Async\)
+      Exception message: the_error_msg
+      """.dedent
+    doAssert match(err.msg, re(expected)), err.getStackTrace & err.msg
+
+block:  # interleaved async work
+  proc baz() {.async.} =
+    await sleepAsync(1)
+    raise newException(ValueError, "the_error_msg")
+
+  proc bar() {.async.} =
+    #await sleepAsync(1)
+    await baz()
+
+  proc foo() {.async.} =
+    await sleepAsync(1)
+    await bar()
+
+  proc main {.async.} =
+    await foo()
+
+  try:
+    waitFor main()
+    doAssert false
+  except ValueError as err:
+    let expected = """
+      the_error_msg
+      Async traceback:
+        tasync_traceback2\.nim\(\d+\) tasync_traceback2
+        tasync_traceback2\.nim\(\d+\) main \(Async\)
+        tasync_traceback2\.nim\(\d+\) foo \(Async\)
+        tasync_traceback2\.nim\(\d+\) bar \(Async\)
+        tasync_traceback2\.nim\(\d+\) baz \(Async\)
+      Exception message: the_error_msg
+      """.dedent
+    doAssert match(err.msg, re(expected)), err.getStackTrace & err.msg
+
+block:  # 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:
+    let expected = """
+      the_error_msg
+      Async traceback:
+        tasync_traceback2\.nim\(\d+\) tasync_traceback2
+        tasync_traceback2\.nim\(\d+\) main \(Async\)
+        tasync_traceback2\.nim\(\d+\) foo \(Async\)
+        tasync_traceback2\.nim\(\d+\) bar \(Async\)
+        tasync_traceback2\.nim\(\d+\) baz \(Async\)
+      Exception message: the_error_msg
+      """.dedent
+    doAssert match(err.msg, re(expected)), err.getStackTrace & err.msg
+
+echo "ok"