Nim icon indicating copy to clipboard operation
Nim copied to clipboard

Async stack traces are very verbose.

Open treeform opened this issue 3 years ago • 6 comments

Here is an example of one of my async stack traces:

C:\p\bencher\src\server.nim(990) server
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1961) waitFor
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1653) poll
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(419) runOnce
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(234) processPendingCallbacks
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(31) processRequestNimAsyncContinue
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asynchttpserver.nim(330) processRequestIter
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(232) cb
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(28) cbNimAsyncContinue
C:\p\bencher\src\server.nim(971) cbIter
C:\p\bencher\src\server.nim(496) runs
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\system\fatal.nim(53) sysFatal
[[reraised from:
C:\p\bencher\src\server.nim(990) server
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1961) waitFor
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1653) poll
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(419) runOnce
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(234) processPendingCallbacks
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(31) processRequestNimAsyncContinue
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(131) processRequestIter
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncfutures.nim(389) read
]]
[[reraised from:
C:\p\bencher\src\server.nim(990) server
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1961) waitFor
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1653) poll
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(419) runOnce
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(234) processPendingCallbacks
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(28) processClientNimAsyncContinue
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(131) processClientIter
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncfutures.nim(389) read
]]
[[reraised from:
C:\p\bencher\src\server.nim(990) server
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1961) waitFor
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1653) poll
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(419) runOnce
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(234) processPendingCallbacks
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncfutures.nim(437) asyncCheckCallback
]]
Error: unhandled exception: index 1000 not in 0 .. 13
Async traceback:
  C:\p\bencher\src\server.nim(990)                                              server
  C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1961)  waitFor
  C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1653)  poll
  C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(419)   runOnce
  C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(234)   processPendingCallbacks
  C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(31)       processRequestNimAsyncContinue      
  C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asynchttpserver.nim(330) processRequestIter
  C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(232)      cb
  C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(28)       cbNimAsyncContinue
  C:\p\bencher\src\server.nim(971)                                              cbIter
  C:\p\bencher\src\server.nim(496)                                              runs
  C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\system\fatal.nim(53)          sysFatal
  #[
    C:\p\bencher\src\server.nim(990)                                              server
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1961)  waitFor
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1653)  poll
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(419)   runOnce
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(234)   processPendingCallbacks
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(31)       processRequestNimAsyncContinue
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(131)      processRequestIter
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncfutures.nim(389)    read
  ]#
  #[
    C:\p\bencher\src\server.nim(990)                                              server
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1961)  waitFor
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1653)  poll
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(419)   runOnce
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(234)   processPendingCallbacks
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(28)       processClientNimAsyncContinue
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(131)      processClientIter
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncfutures.nim(389)    read
  ]#
Exception message: index 1000 not in 0 .. 13
 [IndexDefect]

I expect a stack traces that looks some thing like this:

C:\p\bencher\src\server.nim(990) server
C:\p\bencher\src\server.nim(971) cbIter
C:\p\bencher\src\server.nim(496) runs
Error: unhandled exception: index 1000 not in 0 .. 13
 [IndexDefect]

That's right the function is only 3 async layers deep.

Maybe it would be helpful to mark async functions, so its easier to follow:

C:\p\bencher\src\server.nim(990) {.async.} server
C:\p\bencher\src\server.nim(971) {.async.} cbIter
C:\p\bencher\src\server.nim(496) {.async.} runs
Error: unhandled exception: index 1000 not in 0 .. 13
 [IndexDefect]

Currently even debugging simple async stack traces is very hard.

treeform avatar Jun 26 '22 17:06 treeform

Please provide an example program.

Araq avatar Jun 27 '22 09:06 Araq

Examples are not hard to come by, here is a contrived one

import std/asyncdispatch

proc test() {.async.} =
  raise newException(ValueError, "Async error")

waitFor test()

The error will grow with the size of your program so this one is pretty small

SirOlaf avatar Jun 27 '22 13:06 SirOlaf

Exactly, here is another example that is more like my error:

import std/asynchttpserver, std/asyncdispatch

proc main {.async.} =
  var server = newAsyncHttpServer()

  proc cb(req: Request) {.async.} =
    var f: seq[int]
    echo f[1] # <- index error

  server.listen(Port(31337))
  echo "goto http://localhost:31337"

  while true:
    if server.shouldAcceptRequest():
      await server.acceptRequest(cb)

waitFor main()

The error is:

C:\p\try\asyncstacktrace.nim(17) asyncstacktrace
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1961) waitFor
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1653) poll
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(419) runOnce
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(234) processPendingCallbacks
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(31) processRequestNimAsyncContinue
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asynchttpserver.nim(330) processRequestIter
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(232) cb
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(28) cbNimAsyncContinue
C:\p\try\asyncstacktrace.nim(8) cbIter
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\system\fatal.nim(53) sysFatal
[[reraised from:
C:\p\try\asyncstacktrace.nim(17) asyncstacktrace
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1961) waitFor
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1653) poll
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(419) runOnce
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(234) processPendingCallbacks
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(31) processRequestNimAsyncContinue
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(131) processRequestIter
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncfutures.nim(389) read
]]
[[reraised from:
C:\p\try\asyncstacktrace.nim(17) asyncstacktrace
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1961) waitFor
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1653) poll
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(419) runOnce
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(234) processPendingCallbacks
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(28) processClientNimAsyncContinue
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(131) processClientIter
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncfutures.nim(389) read
]]
[[reraised from:
C:\p\try\asyncstacktrace.nim(17) asyncstacktrace
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1961) waitFor
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1653) poll
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(419) runOnce
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(234) processPendingCallbacks
C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncfutures.nim(437) asyncCheckCallback
]]
Error: unhandled exception: index out of bounds, the container is empty
Async traceback:
  C:\p\try\asyncstacktrace.nim(17)                                              asyncstacktrace
  C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1961)  waitFor
  C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1653)  poll
  C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(419)   runOnce
  C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(234)   processPendingCallbacks
  C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(31)       processRequestNimAsyncContinue
  C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asynchttpserver.nim(330) processRequestIter
  C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(232)      cb
  C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(28)       cbNimAsyncContinue
  C:\p\try\asyncstacktrace.nim(8)                                               cbIter
  C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\system\fatal.nim(53)          sysFatal
  #[
    C:\p\try\asyncstacktrace.nim(17)                                              asyncstacktrace
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1961)  waitFor
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1653)  poll
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(419)   runOnce
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(234)   processPendingCallbacks
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(31)       processRequestNimAsyncContinue
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(131)      processRequestIter
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncfutures.nim(389)    read
  ]#
  #[
    C:\p\try\asyncstacktrace.nim(17)                                              asyncstacktrace
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1961)  waitFor
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(1653)  poll
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(419)   runOnce
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncdispatch.nim(234)   processPendingCallbacks
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(28)       processClientNimAsyncContinue
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncmacro.nim(131)      processClientIter
    C:\Users\me\.choosenim\toolchains\nim-1.6.6\lib\pure\asyncfutures.nim(389)    read
  ]#
Exception message: index out of bounds, the container is empty
 [IndexDefect]

while it should be some thing like this:

C:\p\try\asyncstacktrace.nim(17) waitFor
C:\p\try\asyncstacktrace.nim(15) acceptRequest
C:\p\try\asyncstacktrace.nim(8) cb
Exception message: index out of bounds, the container is empty
 [IndexDefect]

treeform avatar Jun 27 '22 17:06 treeform

Even doing a simple filter out of all standard lib lines and stopping at first #[ yield a pretty good result:

import std/asynchttpserver, std/asyncdispatch, strutils

proc main {.async.} =
  var server = newAsyncHttpServer()

  proc cb(req: Request) {.async.} =
    var f: seq[int]
    echo f[1] # <- index error

  server.listen(Port(31337))
  echo "goto http://localhost:31337"

  while true:
    if server.shouldAcceptRequest():
      await server.acceptRequest(cb)

try:
  waitFor main()
except:
  let msg = getCurrentExceptionMsg()
  for line in msg.split("\n"):
    var line = line.replace("\\", "/")
    if "/lib/pure/async" in line:
      continue
    if "#[" in line:
      break
    line.removeSuffix("Iter")
    echo line
index out of bounds, the container is empty
Async traceback:
  C:/p/try/asyncstacktrace.nim(18)                                              asyncstacktrace
  C:/p/try/asyncstacktrace.nim(8)                                               cb
  C:/Users/me/.choosenim/toolchains/nim-1.6.6/lib/system/fatal.nim(53)          sysFatal

A simple fix could make async way more usable.

treeform avatar Jun 27 '22 17:06 treeform

The last time I looked at this it required some additional compiler support IIRC. Basically the ability to get a data structure representing the stack trace instead of just text. We have getStackTraceEntries which provides this now.

Right now the stack trace output is the kitchen sink (every await point captures a trace), it should be possible to merge these into some nice stack traces. But I haven't delved too deep into this so there might be more complexity needed here.

dom96 avatar Jun 27 '22 23:06 dom96

I don't know if you need to go in all that fancy. Just filtering out junk from the stack trace is 80% there and would make a huge improvement:

  let msg = getCurrentExceptionMsg()
  for line in msg.split("\n"):
    var line = line.replace("\\", "/")
    if "/lib/pure/async" in line:
      continue
    if "#[" in line:
      break
    line.removeSuffix("Iter")
    echo line

If Nim just did that itself it would be great.

treeform avatar Jul 05 '22 17:07 treeform