From f73015ad9ec6e977ca4b643ea9b03e164aeac431 Mon Sep 17 00:00:00 2001 From: Dominik Picheta Date: Fri, 24 Nov 2017 22:48:53 +0000 Subject: [PATCH 01/15] Implement some simple pattern-based transformation for async tracebacks. --- lib/pure/asyncfutures.nim | 79 ++++++++++++++++++++++++++++---- tests/async/tasync_traceback.nim | 46 +++++++++++++++++++ 2 files changed, 115 insertions(+), 10 deletions(-) create mode 100644 tests/async/tasync_traceback.nim diff --git a/lib/pure/asyncfutures.nim b/lib/pure/asyncfutures.nim index 4bd3227a11..d78c6bcb75 100644 --- a/lib/pure/asyncfutures.nim +++ b/lib/pure/asyncfutures.nim @@ -217,17 +217,76 @@ proc `callback=`*[T](future: Future[T], ## If future has already completed then ``cb`` will be called immediately. future.callback = proc () = cb(future) -proc injectStacktrace[T](future: Future[T]) = - # TODO: Come up with something better. - when not defined(release): - var msg = "" - msg.add("\n " & future.fromProc & "'s lead up to read of failed Future:") - - if not future.errorStackTrace.isNil and future.errorStackTrace != "": - msg.add("\n" & indent(future.errorStackTrace.strip(), 4)) +proc processEntries(entries: seq[StackTraceEntry]): seq[StackTraceEntry] = + proc get(entries: seq[StackTraceEntry], i: int): StackTraceEntry = + if i >= entries.len: + return StackTraceEntry(procName: "", line: 0, filename: "") else: - msg.add("\n Empty or nil stack trace.") - future.error.msg.add(msg) + return entries[i] + + result = @[] + var i = 0 + while i < entries.len: + var entry = entries[i] + + if entry.procName.isNil: + # Start of a re-raise traceback which we do not care for. + break + + # Detect this pattern: + # (procname: a, line: 393, filename: asyncmacro.nim) + # (procname: cb0, line: 34, filename: asyncmacro.nim) + # (procname: aIter, line: 40, filename: tasync_traceback.nim) + let second = get(entries, i+1) + let third = get(entries, i+2) + let fitsPattern = + cmpIgnoreStyle($entry.filename, "asyncmacro.nim") == 0 and + cmpIgnoreStyle($second.filename, "asyncmacro.nim") == 0 and + cmpIgnoreStyle($second.procName, "cb0") == 0 and + cmpIgnoreStyle($third.procName, $entry.procName & "iter") == 0 + + if fitsPattern: + entry = StackTraceEntry( + procName: entry.procName, + line: third.line, + filename: third.filename + ) + i.inc(2) + + result.add(entry) + i.inc + +proc injectStacktrace[T](future: Future[T]) = + when not defined(release): + const header = "Async traceback\n---------------\n" + + let originalMsg = future.error.msg + if header in originalMsg: + return + + let entries = getStackTraceEntries(future.error).processEntries() + future.error.msg = "\n" & header + + # Find longest filename & line number combo for alignment purposes. + var longestLeft = 0 + for entry in entries: + let left = $entry.filename & $entry.line + if left.len > longestLeft: + longestLeft = left.len + + # Format the entries. + for entry in entries: + let left = "$#($#)" % [$entry.filename, $entry.line] + future.error.msg.add("$1$2 $3\n" % [ + left, + spaces(longestLeft - left.len + 2), $entry.procName]) + + future.error.msg.add("Exception message: " & originalMsg & "\n") + future.error.msg.add("Exception type: ") + + # For debugging purposes TODO... + for entry in getStackTraceEntries(future.error): + future.error.msg.add "\n" & $entry proc read*[T](future: Future[T] | FutureVar[T]): T = ## Retrieves the value of ``future``. Future must be finished otherwise diff --git a/tests/async/tasync_traceback.nim b/tests/async/tasync_traceback.nim new file mode 100644 index 0000000000..dc9226617e --- /dev/null +++ b/tests/async/tasync_traceback.nim @@ -0,0 +1,46 @@ +discard """ + exitcode: 0 + output: "" +""" +import asyncdispatch + +# Tests to ensure our exception trace backs are friendly. + +# --- Simple test. --- +# +# What does this look like when it's synchronous? +# +# tasync_traceback.nim(23) tasync_traceback +# tasync_traceback.nim(21) a +# tasync_traceback.nim(18) b +# Error: unhandled exception: b failure [OSError] +# +# Good (not quite ideal, but gotta work within constraints) traceback, +# when exception is unhandled: +# +# +# +# +# <(the code responsible is in excpt:raiseExceptionAux)> +# Error: unhandled exception: b failure +# =============== +# Async traceback +# =============== +# +# tasync_traceback.nim(23) tasync_traceback +# +# tasync_traceback.nim(21) a +# tasync_traceback.nim(18) b + +proc b(): Future[int] {.async.} = + if true: + raise newException(OSError, "b failure") + +proc a(): Future[int] {.async.} = + return await b() + +let aFut = a() +# try: +discard waitFor aFut +# except Exception as exc: +# echo exc.msg From 9ca6afe73af8c187ea7786f7563ecc537ec31f51 Mon Sep 17 00:00:00 2001 From: Dominik Picheta Date: Sat, 25 Nov 2017 14:55:57 +0000 Subject: [PATCH 02/15] Refine the async tracebacks. --- lib/pure/asyncfutures.nim | 36 +++++++++++++++++++++++++------- tests/async/tasync_traceback.nim | 17 ++++++++++----- 2 files changed, 41 insertions(+), 12 deletions(-) diff --git a/lib/pure/asyncfutures.nim b/lib/pure/asyncfutures.nim index d78c6bcb75..d8385a9cbc 100644 --- a/lib/pure/asyncfutures.nim +++ b/lib/pure/asyncfutures.nim @@ -256,16 +256,31 @@ proc processEntries(entries: seq[StackTraceEntry]): seq[StackTraceEntry] = result.add(entry) i.inc +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. + result = "" + case ($entry.procName).normalize() + of "cb0": + if cmpIgnoreStyle($entry.filename, "asyncmacro.nim") == 0: + return "Resumes an async procedure" + of "processpendingcallbacks": + if cmpIgnoreStyle($entry.filename, "asyncdispatch.nim") == 0: + return "Executes pending callbacks" + of "poll": + if cmpIgnoreStyle($entry.filename, "asyncdispatch.nim") == 0: + return "Processes asynchronous completion events" + proc injectStacktrace[T](future: Future[T]) = when not defined(release): - const header = "Async traceback\n---------------\n" + const header = "Async traceback:\n" let originalMsg = future.error.msg if header in originalMsg: return let entries = getStackTraceEntries(future.error).processEntries() - future.error.msg = "\n" & header + future.error.msg = originalMsg & "\n" & header # Find longest filename & line number combo for alignment purposes. var longestLeft = 0 @@ -274,19 +289,26 @@ proc injectStacktrace[T](future: Future[T]) = if left.len > longestLeft: longestLeft = left.len + const indent = " " # Format the entries. for entry in entries: let left = "$#($#)" % [$entry.filename, $entry.line] - future.error.msg.add("$1$2 $3\n" % [ + future.error.msg.add("$#$#$# $#\n" % [ + indent, left, - spaces(longestLeft - left.len + 2), $entry.procName]) + spaces(longestLeft - left.len + 2), + $entry.procName + ]) + let hint = getHint(entry) + if hint.len > 0: + future.error.msg.add(indent & "└─" & hint & "\n") future.error.msg.add("Exception message: " & originalMsg & "\n") future.error.msg.add("Exception type: ") - # For debugging purposes TODO... - for entry in getStackTraceEntries(future.error): - future.error.msg.add "\n" & $entry + # # For debugging purposes + # for entry in getStackTraceEntries(future.error): + # future.error.msg.add "\n" & $entry proc read*[T](future: Future[T] | FutureVar[T]): T = ## Retrieves the value of ``future``. Future must be finished otherwise diff --git a/tests/async/tasync_traceback.nim b/tests/async/tasync_traceback.nim index dc9226617e..c69721f393 100644 --- a/tests/async/tasync_traceback.nim +++ b/tests/async/tasync_traceback.nim @@ -1,6 +1,13 @@ discard """ exitcode: 0 - output: "" + output: ''' +b failure +Async traceback: + tasync_traceback.nim(49) tasync_traceback + tasync_traceback.nim(47) a + tasync_traceback.nim(44) b +Exception message: b failure +Exception type:''' """ import asyncdispatch @@ -40,7 +47,7 @@ proc a(): Future[int] {.async.} = return await b() let aFut = a() -# try: -discard waitFor aFut -# except Exception as exc: -# echo exc.msg +try: + discard waitFor aFut +except Exception as exc: + echo exc.msg From a9a13e470b790442771e0003def074af69c715a5 Mon Sep 17 00:00:00 2001 From: Dominik Picheta Date: Sat, 25 Nov 2017 21:04:01 +0000 Subject: [PATCH 03/15] Go through the re-raise stacks for more detailed tracebacks. --- lib/pure/asyncfutures.nim | 55 +++++++++++++++++++++++++------- tests/async/tasync_traceback.nim | 47 +++++++++++++++++++++++++-- 2 files changed, 87 insertions(+), 15 deletions(-) diff --git a/lib/pure/asyncfutures.nim b/lib/pure/asyncfutures.nim index d8385a9cbc..f75859e4c0 100644 --- a/lib/pure/asyncfutures.nim +++ b/lib/pure/asyncfutures.nim @@ -217,6 +217,20 @@ proc `callback=`*[T](future: Future[T], ## If future has already completed then ``cb`` will be called immediately. future.callback = proc () = cb(future) +proc diff[T](a, b: seq[T]): (int, seq[T]) = + ## Iterates through both sequences until the items do not match, + ## returns the remainder of `b` after the last item that does not match + ## together with the index of the last match. + ## + ## .. code-block::nim + ## doAssert(diff(@[1,2,42,123], @[1,2,123,678,21]) == (1, @[123,678,21])) + var lastIndex = 0 + for i in 0 .. = entries.len: @@ -230,8 +244,21 @@ proc processEntries(entries: seq[StackTraceEntry]): seq[StackTraceEntry] = var entry = entries[i] if entry.procName.isNil: - # Start of a re-raise traceback which we do not care for. - break + # Start of a re-raise traceback which may contain more info. + # Find where the re-raised traceback ends. + assert entry.line == -10 # Signifies start of re-raise block. + var reRaiseEnd = i+1 + while reRaiseEnd < entries.len and not entries[reRaiseEnd].procName.isNil: + reRaiseEnd.inc() + assert entries[reRaiseEnd].procName.isNil + assert entries[reRaiseEnd].line == -100 # Signifies end of re-raise block. + let reRaisedEntries = processEntries(entries[i+1 .. reRaiseEnd-1]) + + let (lastIndex, remainder) = diff(result, reRaisedEntries) + for i in 0.. 0: - future.error.msg.add(indent & "└─" & hint & "\n") + newMsg.add(indent & "└─" & hint & "\n") - future.error.msg.add("Exception message: " & originalMsg & "\n") - future.error.msg.add("Exception type: ") + newMsg.add("Exception message: " & exceptionMsg & "\n") + newMsg.add("Exception type:") # # For debugging purposes # for entry in getStackTraceEntries(future.error): - # future.error.msg.add "\n" & $entry + # newMsg.add "\n" & $entry + future.error.msg = newMsg proc read*[T](future: Future[T] | FutureVar[T]): T = ## Retrieves the value of ``future``. Future must be finished otherwise diff --git a/tests/async/tasync_traceback.nim b/tests/async/tasync_traceback.nim index c69721f393..6ab7ef9153 100644 --- a/tests/async/tasync_traceback.nim +++ b/tests/async/tasync_traceback.nim @@ -3,10 +3,36 @@ discard """ output: ''' b failure Async traceback: - tasync_traceback.nim(49) tasync_traceback - tasync_traceback.nim(47) a - tasync_traceback.nim(44) b + tasync_traceback.nim(75) tasync_traceback + asyncmacro.nim(393) a + asyncmacro.nim(43) cb0 + └─Resumes an async procedure + asyncfutures.nim(211) callback= + asyncfutures.nim(190) addCallback + asyncfutures.nim(53) callSoon + asyncmacro.nim(34) cb0 + └─Resumes an async procedure + asyncmacro.nim(0) aIter + asyncfutures.nim(355) read + tasync_traceback.nim(73) a + tasync_traceback.nim(70) b Exception message: b failure +Exception type: + +bar failure +Async traceback: + tasync_traceback.nim(91) tasync_traceback + asyncdispatch.nim(1204) waitFor + asyncdispatch.nim(1253) poll + └─Processes asynchronous completion events + asyncdispatch.nim(181) processPendingCallbacks + └─Executes pending callbacks + asyncmacro.nim(34) cb0 + └─Resumes an async procedure + asyncmacro.nim(0) fooIter + asyncfutures.nim(355) read + tasync_traceback.nim(86) barIter +Exception message: bar failure Exception type:''' """ import asyncdispatch @@ -51,3 +77,18 @@ try: discard waitFor aFut except Exception as exc: echo exc.msg +echo() + +# From #6803 +proc bar(): Future[string] {.async.} = + await sleepAsync(100) + if true: + raise newException(OSError, "bar failure") + +proc foo(): Future[string] {.async.} = return await bar() + +try: + echo waitFor(foo()) +except Exception as exc: + echo exc.msg +echo() \ No newline at end of file From 3a790c9c7219e4f2e437ba60b959e402e62d2824 Mon Sep 17 00:00:00 2001 From: Dominik Picheta Date: Sun, 26 Nov 2017 13:45:58 +0000 Subject: [PATCH 04/15] Rename cb0 to asyncProcName_continue + other improvements to async tracebacks. --- lib/pure/asyncfutures.nim | 97 ++++++++++++++++++++------------ lib/pure/asyncmacro.nim | 13 +++-- tests/async/tasync_traceback.nim | 1 + 3 files changed, 70 insertions(+), 41 deletions(-) diff --git a/lib/pure/asyncfutures.nim b/lib/pure/asyncfutures.nim index f75859e4c0..086f9c729b 100644 --- a/lib/pure/asyncfutures.nim +++ b/lib/pure/asyncfutures.nim @@ -231,13 +231,9 @@ proc diff[T](a, b: seq[T]): (int, seq[T]) = break return (lastIndex, b[lastIndex .. ^1]) -proc processEntries(entries: seq[StackTraceEntry]): seq[StackTraceEntry] = - proc get(entries: seq[StackTraceEntry], i: int): StackTraceEntry = - if i >= entries.len: - return StackTraceEntry(procName: "", line: 0, filename: "") - else: - return entries[i] - +proc mergeEntries(entries: seq[StackTraceEntry]): seq[StackTraceEntry] = + ## Merges stack trace entries containing re-raise entries into one + ## continuous stack trace. result = @[] var i = 0 while i < entries.len: @@ -252,7 +248,7 @@ proc processEntries(entries: seq[StackTraceEntry]): seq[StackTraceEntry] = reRaiseEnd.inc() assert entries[reRaiseEnd].procName.isNil assert entries[reRaiseEnd].line == -100 # Signifies end of re-raise block. - let reRaisedEntries = processEntries(entries[i+1 .. reRaiseEnd-1]) + let reRaisedEntries = mergeEntries(entries[i+1 .. reRaiseEnd-1]) let (lastIndex, remainder) = diff(result, reRaisedEntries) for i in 0..= entries.len: + return StackTraceEntry(procName: "", line: 0, filename: "") + else: + return entries[i] + + result = @[] + var i = 0 + while i < entries.len: + var entry = entries[i] + # Detect this pattern: # (procname: a, line: 393, filename: asyncmacro.nim) - # (procname: cb0, line: 34, filename: asyncmacro.nim) + # (procname: a_continue, line: 34, filename: asyncmacro.nim) # (procname: aIter, line: 40, filename: tasync_traceback.nim) let second = get(entries, i+1) + let third = get(entries, i+2) let fitsPattern = cmpIgnoreStyle($entry.filename, "asyncmacro.nim") == 0 and cmpIgnoreStyle($second.filename, "asyncmacro.nim") == 0 and - cmpIgnoreStyle($second.procName, "cb0") == 0 and + ($second.procName).startsWith($entry.procName) and + ($second.procName).endsWith("continue") and cmpIgnoreStyle($third.procName, $entry.procName & "iter") == 0 if fitsPattern: @@ -287,10 +301,8 @@ 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. result = "" - case ($entry.procName).normalize() - of "cb0": - if cmpIgnoreStyle($entry.filename, "asyncmacro.nim") == 0: - return "Resumes an async procedure" + let name = ($entry.procName).normalize() + case name of "processpendingcallbacks": if cmpIgnoreStyle($entry.filename, "asyncdispatch.nim") == 0: return "Executes pending callbacks" @@ -298,6 +310,35 @@ proc getHint(entry: StackTraceEntry): string = if cmpIgnoreStyle($entry.filename, "asyncdispatch.nim") == 0: return "Processes asynchronous completion events" + if name.endsWith("continue"): + if cmpIgnoreStyle($entry.filename, "asyncmacro.nim") == 0: + return "Resumes an async procedure" + +proc `$`*(entries: seq[StackTraceEntry]): string = + result = "" + # Find longest filename & line number combo for alignment purposes. + var longestLeft = 0 + for entry in entries: + let left = $entry.filename & $entry.line + if left.len > longestLeft: + longestLeft = left.len + + const indent = 2 + # Format the entries. + for entry in entries: + let indentStr = spaces(indent) + + let left = "$#($#)" % [$entry.filename, $entry.line] + result.add("$#$#$# $#\n" % [ + indentStr, + left, + spaces(longestLeft - left.len + 2), + $entry.procName + ]) + let hint = getHint(entry) + if hint.len > 0: + result.add(indentStr & "└─" & hint & "\n") + proc injectStacktrace[T](future: Future[T]) = when not defined(release): const header = "\nAsync traceback:\n" @@ -309,29 +350,15 @@ proc injectStacktrace[T](future: Future[T]) = let start = exceptionMsg.find(header) exceptionMsg = exceptionMsg[0.. longestLeft: - longestLeft = left.len - - const indent = " " - # Format the entries. - for entry in entries: - let left = "$#($#)" % [$entry.filename, $entry.line] - newMsg.add("$#$#$# $#\n" % [ - indent, - left, - spaces(longestLeft - left.len + 2), - $entry.procName - ]) - let hint = getHint(entry) - if hint.len > 0: - newMsg.add(indent & "└─" & hint & "\n") + let entries = getStackTraceEntries(future.error).mergeEntries() + let shortEntries = entries.shortenEntries() + newMsg.add($shortEntries) + if entries.len > shortEntries.len: + newMsg.add("\nDetailed Async traceback:\n") + newMsg.add($entries) newMsg.add("Exception message: " & exceptionMsg & "\n") newMsg.add("Exception type:") diff --git a/lib/pure/asyncmacro.nim b/lib/pure/asyncmacro.nim index a8e378d5c4..85d44b9f4b 100644 --- a/lib/pure/asyncmacro.nim +++ b/lib/pure/asyncmacro.nim @@ -25,10 +25,10 @@ proc skipStmtList(node: NimNode): NimNode {.compileTime.} = result = node[0] template createCb(retFutureSym, iteratorNameSym, - name, futureVarCompletions: untyped) = + strName, identName, futureVarCompletions: untyped) = var nameIterVar = iteratorNameSym #{.push stackTrace: off.} - proc cb0 {.closure.} = + proc identName {.closure.} = try: if not nameIterVar.finished: var next = nameIterVar() @@ -36,11 +36,11 @@ template createCb(retFutureSym, iteratorNameSym, if not retFutureSym.finished: let msg = "Async procedure ($1) yielded `nil`, are you await'ing a " & "`nil` Future?" - raise newException(AssertionError, msg % name) + raise newException(AssertionError, msg % strName) else: {.gcsafe.}: {.push hint[ConvFromXtoItselfNotNeeded]: off.} - next.callback = (proc() {.closure, gcsafe.})(cb0) + next.callback = (proc() {.closure, gcsafe.})(identName) {.pop.} except: futureVarCompletions @@ -52,7 +52,7 @@ template createCb(retFutureSym, iteratorNameSym, else: retFutureSym.fail(getCurrentException()) - cb0() + identName() #{.pop.} proc generateExceptionCheck(futSym, tryStmt, rootReceiver, fromNode: NimNode): NimNode {.compileTime.} = @@ -389,9 +389,10 @@ proc asyncSingleProc(prc: NimNode): NimNode {.compileTime.} = outerProcBody.add(closureIterator) # -> createCb(retFuture) - #var cbName = newIdentNode("cb") + var cbName = genSym(nskProc, prcName & "_continue") var procCb = getAst createCb(retFutureSym, iteratorNameSym, newStrLitNode(prcName), + cbName, createFutureVarCompletions(futureVarIdents, nil)) outerProcBody.add procCb diff --git a/tests/async/tasync_traceback.nim b/tests/async/tasync_traceback.nim index 6ab7ef9153..5e4f1142f0 100644 --- a/tests/async/tasync_traceback.nim +++ b/tests/async/tasync_traceback.nim @@ -1,5 +1,6 @@ discard """ exitcode: 0 + disabled: "windows" output: ''' b failure Async traceback: From 391f877e6cc3ec36dc3d8977b519dabaa737108a Mon Sep 17 00:00:00 2001 From: Dominik Picheta Date: Sun, 26 Nov 2017 15:06:13 +0000 Subject: [PATCH 05/15] Attempt to provide simplified and detailed tracebacks --- lib/pure/asyncfutures.nim | 46 +++++++++++++++++++++++++++------------ 1 file changed, 32 insertions(+), 14 deletions(-) diff --git a/lib/pure/asyncfutures.nim b/lib/pure/asyncfutures.nim index 086f9c729b..d836e3ab7b 100644 --- a/lib/pure/asyncfutures.nim +++ b/lib/pure/asyncfutures.nim @@ -274,25 +274,43 @@ proc shortenEntries(entries: seq[StackTraceEntry]): seq[StackTraceEntry] = # Detect this pattern: # (procname: a, line: 393, filename: asyncmacro.nim) + # ... # (procname: a_continue, line: 34, filename: asyncmacro.nim) + # ... # (procname: aIter, line: 40, filename: tasync_traceback.nim) - let second = get(entries, i+1) + proc searchBackwards(entries: seq[StackTraceEntry], + current: StackTraceEntry): (int, StackTraceEntry) = + # Search backwards for the beginning of the pattern. + result[0] = 0 + if not ($current.procName).normalize().endsWith("iter"): + return - let third = get(entries, i+2) - let fitsPattern = - cmpIgnoreStyle($entry.filename, "asyncmacro.nim") == 0 and - cmpIgnoreStyle($second.filename, "asyncmacro.nim") == 0 and - ($second.procName).startsWith($entry.procName) and - ($second.procName).endsWith("continue") and - cmpIgnoreStyle($third.procName, $entry.procName & "iter") == 0 + # Find (procname: a, line: 393, filename: asyncmacro.nim) + let start = entries.len-1 + var counter = start + while counter >= 0: + if cmpIgnoreStyle($entries[counter].procName & "iter", + $current.procName) == 0: + break + counter.dec() - if fitsPattern: - entry = StackTraceEntry( - procName: entry.procName, - line: third.line, - filename: third.filename + # Return when no beginning of pattern is found. + if counter < 0: + return + + result[0] = start - counter + result[1] = StackTraceEntry( + procName: entries[result[0]].procName, + line: current.line, + filename: current.filename ) - i.inc(2) + + let (itemsToRemove, newEntry) = searchBackwards(result, entry) + + if itemsToRemove != 0: + entry = newEntry + # Remove the previous entries. + result.setLen(result.len-itemsToRemove) result.add(entry) i.inc From 6301e3354387ad1d4c84a69c7f9d934b337121b4 Mon Sep 17 00:00:00 2001 From: Dominik Picheta Date: Sun, 26 Nov 2017 15:09:34 +0000 Subject: [PATCH 06/15] Show only detailed async tracebacks. --- lib/pure/asyncfutures.nim | 64 +------------------------------- tests/async/tasync_traceback.nim | 27 +++++++++----- 2 files changed, 19 insertions(+), 72 deletions(-) diff --git a/lib/pure/asyncfutures.nim b/lib/pure/asyncfutures.nim index d836e3ab7b..54b967f90d 100644 --- a/lib/pure/asyncfutures.nim +++ b/lib/pure/asyncfutures.nim @@ -225,7 +225,7 @@ proc diff[T](a, b: seq[T]): (int, seq[T]) = ## .. code-block::nim ## doAssert(diff(@[1,2,42,123], @[1,2,123,678,21]) == (1, @[123,678,21])) var lastIndex = 0 - for i in 0 .. = entries.len: - return StackTraceEntry(procName: "", line: 0, filename: "") - else: - return entries[i] - - result = @[] - var i = 0 - while i < entries.len: - var entry = entries[i] - - # Detect this pattern: - # (procname: a, line: 393, filename: asyncmacro.nim) - # ... - # (procname: a_continue, line: 34, filename: asyncmacro.nim) - # ... - # (procname: aIter, line: 40, filename: tasync_traceback.nim) - proc searchBackwards(entries: seq[StackTraceEntry], - current: StackTraceEntry): (int, StackTraceEntry) = - # Search backwards for the beginning of the pattern. - result[0] = 0 - if not ($current.procName).normalize().endsWith("iter"): - return - - # Find (procname: a, line: 393, filename: asyncmacro.nim) - let start = entries.len-1 - var counter = start - while counter >= 0: - if cmpIgnoreStyle($entries[counter].procName & "iter", - $current.procName) == 0: - break - counter.dec() - - # Return when no beginning of pattern is found. - if counter < 0: - return - - result[0] = start - counter - result[1] = StackTraceEntry( - procName: entries[result[0]].procName, - line: current.line, - filename: current.filename - ) - - let (itemsToRemove, newEntry) = searchBackwards(result, entry) - - if itemsToRemove != 0: - entry = newEntry - # Remove the previous entries. - result.setLen(result.len-itemsToRemove) - - result.add(entry) - i.inc - 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. @@ -372,11 +316,7 @@ proc injectStacktrace[T](future: Future[T]) = var newMsg = exceptionMsg & header let entries = getStackTraceEntries(future.error).mergeEntries() - let shortEntries = entries.shortenEntries() - newMsg.add($shortEntries) - if entries.len > shortEntries.len: - newMsg.add("\nDetailed Async traceback:\n") - newMsg.add($entries) + newMsg.add($entries) newMsg.add("Exception message: " & exceptionMsg & "\n") newMsg.add("Exception type:") diff --git a/tests/async/tasync_traceback.nim b/tests/async/tasync_traceback.nim index 5e4f1142f0..525914ef3b 100644 --- a/tests/async/tasync_traceback.nim +++ b/tests/async/tasync_traceback.nim @@ -4,35 +4,42 @@ discard """ output: ''' b failure Async traceback: - tasync_traceback.nim(75) tasync_traceback + tasync_traceback.nim(83) tasync_traceback asyncmacro.nim(393) a - asyncmacro.nim(43) cb0 + asyncmacro.nim(43) a_continue └─Resumes an async procedure asyncfutures.nim(211) callback= asyncfutures.nim(190) addCallback asyncfutures.nim(53) callSoon - asyncmacro.nim(34) cb0 + asyncmacro.nim(34) a_continue └─Resumes an async procedure asyncmacro.nim(0) aIter - asyncfutures.nim(355) read - tasync_traceback.nim(73) a - tasync_traceback.nim(70) b + asyncfutures.nim(340) read + asyncmacro.nim(34) a_continue + └─Resumes an async procedure + tasync_traceback.nim(81) aIter + asyncmacro.nim(393) b + asyncmacro.nim(34) b_continue + └─Resumes an async procedure + tasync_traceback.nim(78) bIter Exception message: b failure Exception type: bar failure Async traceback: - tasync_traceback.nim(91) tasync_traceback + tasync_traceback.nim(99) tasync_traceback asyncdispatch.nim(1204) waitFor asyncdispatch.nim(1253) poll └─Processes asynchronous completion events asyncdispatch.nim(181) processPendingCallbacks └─Executes pending callbacks - asyncmacro.nim(34) cb0 + asyncmacro.nim(34) foo_continue └─Resumes an async procedure asyncmacro.nim(0) fooIter - asyncfutures.nim(355) read - tasync_traceback.nim(86) barIter + asyncfutures.nim(340) read + asyncmacro.nim(34) bar_continue + └─Resumes an async procedure + tasync_traceback.nim(94) barIter Exception message: bar failure Exception type:''' """ From 383c80971cee93496c5317b7464021ac99711176 Mon Sep 17 00:00:00 2001 From: Dominik Picheta Date: Sun, 26 Nov 2017 15:16:54 +0000 Subject: [PATCH 07/15] No need to recurse now that mergeEntries doesn't do any pattern matching. --- lib/pure/asyncfutures.nim | 3 ++- tests/async/tasync_traceback.nim | 4 ++-- 2 files changed, 4 insertions(+), 3 deletions(-) diff --git a/lib/pure/asyncfutures.nim b/lib/pure/asyncfutures.nim index 54b967f90d..a122e0c414 100644 --- a/lib/pure/asyncfutures.nim +++ b/lib/pure/asyncfutures.nim @@ -248,9 +248,10 @@ proc mergeEntries(entries: seq[StackTraceEntry]): seq[StackTraceEntry] = reRaiseEnd.inc() assert entries[reRaiseEnd].procName.isNil assert entries[reRaiseEnd].line == -100 # Signifies end of re-raise block. - let reRaisedEntries = mergeEntries(entries[i+1 .. reRaiseEnd-1]) + let reRaisedEntries = entries[i+1 .. reRaiseEnd-1] let (lastIndex, remainder) = diff(result, reRaisedEntries) + # Insert all the entries after lastIndex. for i in 0.. Date: Wed, 13 Dec 2017 09:46:42 +0100 Subject: [PATCH 08/15] optimized friendly stack traces --- lib/pure/asyncfutures.nim | 48 ++++++++++++++++----------------------- lib/pure/asyncmacro.nim | 2 ++ 2 files changed, 21 insertions(+), 29 deletions(-) diff --git a/lib/pure/asyncfutures.nim b/lib/pure/asyncfutures.nim index a122e0c414..5675f5399a 100644 --- a/lib/pure/asyncfutures.nim +++ b/lib/pure/asyncfutures.nim @@ -1,4 +1,4 @@ -import os, tables, strutils, times, heapqueue, options, deques +import os, tables, strutils, times, heapqueue, options, deques, cstrutils # TODO: This shouldn't need to be included, but should ideally be exported. type @@ -217,19 +217,15 @@ proc `callback=`*[T](future: Future[T], ## If future has already completed then ``cb`` will be called immediately. future.callback = proc () = cb(future) -proc diff[T](a, b: seq[T]): (int, seq[T]) = +proc diff[T](a, b: seq[T]; firstB, lastB: int): int = ## Iterates through both sequences until the items do not match, - ## returns the remainder of `b` after the last item that does not match + ## returns the remainder of `b[firstB..lastB]` after the last item that does not match ## together with the index of the last match. - ## - ## .. code-block::nim - ## doAssert(diff(@[1,2,42,123], @[1,2,123,678,21]) == (1, @[123,678,21])) - var lastIndex = 0 - for i in 0.. longestLeft: longestLeft = left.len - const indent = 2 + const indent = spaces(2) # Format the entries. for entry in entries: - let indentStr = spaces(indent) - let left = "$#($#)" % [$entry.filename, $entry.line] - result.add("$#$#$# $#\n" % [ - indentStr, + result.add((indent & "$#$# $#\n") % [ left, spaces(longestLeft - left.len + 2), $entry.procName ]) let hint = getHint(entry) if hint.len > 0: - result.add(indentStr & "└─" & hint & "\n") + result.add(indent & "└─" & hint & "\n") proc injectStacktrace[T](future: Future[T]) = when not defined(release): diff --git a/lib/pure/asyncmacro.nim b/lib/pure/asyncmacro.nim index 85d44b9f4b..8c679929d3 100644 --- a/lib/pure/asyncmacro.nim +++ b/lib/pure/asyncmacro.nim @@ -389,6 +389,8 @@ proc asyncSingleProc(prc: NimNode): NimNode {.compileTime.} = outerProcBody.add(closureIterator) # -> createCb(retFuture) + # NOTE: The "_continue" suffix is checked for in asyncfutures.nim to produce + # friendlier stack traces: var cbName = genSym(nskProc, prcName & "_continue") var procCb = getAst createCb(retFutureSym, iteratorNameSym, newStrLitNode(prcName), From b3055d8735ca012b77121c16bcf62e3f311084e8 Mon Sep 17 00:00:00 2001 From: Araq Date: Wed, 13 Dec 2017 13:36:10 +0100 Subject: [PATCH 09/15] attempt to get the stack trace logic right --- lib/pure/asyncfutures.nim | 29 +++++++++++++++-------------- 1 file changed, 15 insertions(+), 14 deletions(-) diff --git a/lib/pure/asyncfutures.nim b/lib/pure/asyncfutures.nim index 5675f5399a..ea7a798fc7 100644 --- a/lib/pure/asyncfutures.nim +++ b/lib/pure/asyncfutures.nim @@ -217,16 +217,6 @@ proc `callback=`*[T](future: Future[T], ## If future has already completed then ``cb`` will be called immediately. future.callback = proc () = cb(future) -proc diff[T](a, b: seq[T]; firstB, lastB: int): int = - ## Iterates through both sequences until the items do not match, - ## returns the remainder of `b[firstB..lastB]` after the last item that does not match - ## together with the index of the last match. - result = firstB - for i in 0.. 0 and e > i+1: + if result[last] != entries[e]: + newBlock = false + break + dec e + dec last + + if newBlock: + for j in i+1 ..< reRaiseEnd: result.add entries[j] + i = reRaiseEnd+1 continue From 1c2dee18d09c383bce51e9821f0f18656e71bb76 Mon Sep 17 00:00:00 2001 From: Araq Date: Wed, 13 Dec 2017 13:48:48 +0100 Subject: [PATCH 10/15] attempt to get the stack trace logic right; fix boundaries --- lib/pure/asyncfutures.nim | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/pure/asyncfutures.nim b/lib/pure/asyncfutures.nim index ea7a798fc7..f3b4234cc6 100644 --- a/lib/pure/asyncfutures.nim +++ b/lib/pure/asyncfutures.nim @@ -237,10 +237,10 @@ proc mergeEntries(entries: seq[StackTraceEntry]): seq[StackTraceEntry] = # either the nested block is new, then we insert it, or we discard it # completely. 'diff' is the wrong idea here. - var last = result.len + var last = result.len-1 var e = reRaiseEnd-1 var newBlock = true - while last > 0 and e > i+1: + while last >= 0 and e >= i+1: if result[last] != entries[e]: newBlock = false break From 3593a4bdd1899194ed7cd3d21160bccfa6abb2e1 Mon Sep 17 00:00:00 2001 From: Andreas Rumpf Date: Thu, 14 Dec 2017 10:54:49 +0100 Subject: [PATCH 11/15] made the logic correct --- lib/pure/asyncfutures.nim | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/lib/pure/asyncfutures.nim b/lib/pure/asyncfutures.nim index f3b4234cc6..6e64981fe6 100644 --- a/lib/pure/asyncfutures.nim +++ b/lib/pure/asyncfutures.nim @@ -239,10 +239,10 @@ proc mergeEntries(entries: seq[StackTraceEntry]): seq[StackTraceEntry] = # completely. 'diff' is the wrong idea here. var last = result.len-1 var e = reRaiseEnd-1 - var newBlock = true + var newBlock = false while last >= 0 and e >= i+1: if result[last] != entries[e]: - newBlock = false + newBlock = true break dec e dec last @@ -251,10 +251,9 @@ proc mergeEntries(entries: seq[StackTraceEntry]): seq[StackTraceEntry] = for j in i+1 ..< reRaiseEnd: result.add entries[j] i = reRaiseEnd+1 - continue - - result.add(entry) - i.inc + else: + result.add(entry) + i.inc proc getHint(entry: StackTraceEntry): string = ## We try to provide some hints about stack trace entries that the user From 7e6dc3679aaf463a957af7ff6bb34317c7656d4c Mon Sep 17 00:00:00 2001 From: Dominik Picheta Date: Wed, 27 Dec 2017 22:58:31 +0000 Subject: [PATCH 12/15] Simplify async traceback processing. --- lib/pure/asyncfutures.nim | 57 +++++++------------------ tests/async/tasync_traceback.nim | 72 +++++++++++++++++++------------- 2 files changed, 58 insertions(+), 71 deletions(-) diff --git a/lib/pure/asyncfutures.nim b/lib/pure/asyncfutures.nim index 6e64981fe6..bcc3ab613c 100644 --- a/lib/pure/asyncfutures.nim +++ b/lib/pure/asyncfutures.nim @@ -217,44 +217,6 @@ proc `callback=`*[T](future: Future[T], ## If future has already completed then ``cb`` will be called immediately. future.callback = proc () = cb(future) -proc mergeEntries(entries: seq[StackTraceEntry]): seq[StackTraceEntry] = - ## Merges stack trace entries containing re-raise entries into one - ## continuous stack trace. - result = @[] - var i = 0 - while i < entries.len: - var entry = entries[i] - - if entry.procName.isNil: - # Start of a re-raise traceback which may contain more info. - # Find where the re-raised traceback ends. - assert entry.line == -10 # Signifies start of re-raise block. - var reRaiseEnd = i+1 - while reRaiseEnd < entries.len and not entries[reRaiseEnd].procName.isNil: - reRaiseEnd.inc() - assert entries[reRaiseEnd].procName.isNil - assert entries[reRaiseEnd].line == -100 # Signifies end of re-raise block. - - # either the nested block is new, then we insert it, or we discard it - # completely. 'diff' is the wrong idea here. - var last = result.len-1 - var e = reRaiseEnd-1 - var newBlock = false - while last >= 0 and e >= i+1: - if result[last] != entries[e]: - newBlock = true - break - dec e - dec last - - if newBlock: - for j in i+1 ..< reRaiseEnd: result.add entries[j] - - i = reRaiseEnd+1 - else: - result.add(entry) - i.inc - 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. @@ -275,22 +237,33 @@ proc `$`*(entries: seq[StackTraceEntry]): string = # Find longest filename & line number combo for alignment purposes. var longestLeft = 0 for entry in entries: + if entry.procName.isNil: continue + let left = $entry.filename & $entry.line if left.len > longestLeft: longestLeft = left.len - const indent = spaces(2) + var indent = 2 # Format the entries. for entry in entries: + if entry.procName.isNil: + if entry.line == -10: + result.add(spaces(indent) & "#[\n") + indent.inc(2) + else: + indent.dec(2) + result.add(spaces(indent)& "]#\n") + continue + let left = "$#($#)" % [$entry.filename, $entry.line] - result.add((indent & "$#$# $#\n") % [ + result.add((spaces(indent) & "$#$# $#\n") % [ left, spaces(longestLeft - left.len + 2), $entry.procName ]) let hint = getHint(entry) if hint.len > 0: - result.add(indent & "└─" & hint & "\n") + result.add(spaces(indent+2) & "## " & hint & "\n") proc injectStacktrace[T](future: Future[T]) = when not defined(release): @@ -306,7 +279,7 @@ proc injectStacktrace[T](future: Future[T]) = var newMsg = exceptionMsg & header - let entries = getStackTraceEntries(future.error).mergeEntries() + let entries = getStackTraceEntries(future.error) newMsg.add($entries) newMsg.add("Exception message: " & exceptionMsg & "\n") diff --git a/tests/async/tasync_traceback.nim b/tests/async/tasync_traceback.nim index 9e4f749e54..08f7e7317d 100644 --- a/tests/async/tasync_traceback.nim +++ b/tests/async/tasync_traceback.nim @@ -4,42 +4,56 @@ discard """ output: ''' b failure Async traceback: - tasync_traceback.nim(83) tasync_traceback - asyncmacro.nim(393) a - asyncmacro.nim(43) a_continue - └─Resumes an async procedure - asyncfutures.nim(211) callback= - asyncfutures.nim(190) addCallback - asyncfutures.nim(53) callSoon + tasync_traceback.nim(97) tasync_traceback + asyncmacro.nim(395) a asyncmacro.nim(34) a_continue - └─Resumes an async procedure - asyncmacro.nim(0) aIter - asyncfutures.nim(341) read - asyncmacro.nim(34) a_continue - └─Resumes an async procedure - tasync_traceback.nim(81) aIter - asyncmacro.nim(393) b + ## Resumes an async procedure + tasync_traceback.nim(95) aIter + asyncmacro.nim(395) b asyncmacro.nim(34) b_continue - └─Resumes an async procedure - tasync_traceback.nim(78) bIter + ## Resumes an async procedure + tasync_traceback.nim(92) bIter + #[ + tasync_traceback.nim(97) tasync_traceback + asyncmacro.nim(395) a + asyncmacro.nim(43) a_continue + ## Resumes an async procedure + asyncfutures.nim(211) callback= + asyncfutures.nim(190) addCallback + asyncfutures.nim(53) callSoon + asyncmacro.nim(34) a_continue + ## Resumes an async procedure + asyncmacro.nim(0) aIter + asyncfutures.nim(304) read + ]# Exception message: b failure Exception type: bar failure Async traceback: - tasync_traceback.nim(99) tasync_traceback - asyncdispatch.nim(1204) waitFor - asyncdispatch.nim(1253) poll - └─Processes asynchronous completion events - asyncdispatch.nim(181) processPendingCallbacks - └─Executes pending callbacks - asyncmacro.nim(34) foo_continue - └─Resumes an async procedure - asyncmacro.nim(0) fooIter - asyncfutures.nim(341) read - asyncmacro.nim(34) bar_continue - └─Resumes an async procedure - tasync_traceback.nim(94) barIter + tasync_traceback.nim(113) tasync_traceback + asyncdispatch.nim(1492) waitFor + asyncdispatch.nim(1496) poll + ## Processes asynchronous completion events + asyncdispatch.nim(1262) runOnce + asyncdispatch.nim(183) processPendingCallbacks + ## Executes pending callbacks + asyncmacro.nim(34) bar_continue + ## Resumes an async procedure + tasync_traceback.nim(108) barIter + #[ + tasync_traceback.nim(113) tasync_traceback + asyncdispatch.nim(1492) waitFor + asyncdispatch.nim(1496) poll + ## Processes asynchronous completion events + asyncdispatch.nim(1262) runOnce + asyncdispatch.nim(183) processPendingCallbacks + ## Executes pending callbacks + asyncmacro.nim(34) foo_continue + ## Resumes an async procedure + asyncmacro.nim(0) fooIter + asyncfutures.nim(304) read + ]# Exception message: bar failure Exception type:''' """ From caecd60e252253f256717cf30a1dfd0372ce447b Mon Sep 17 00:00:00 2001 From: Dominik Picheta Date: Thu, 28 Dec 2017 13:52:23 +0000 Subject: [PATCH 13/15] Add more info in changelog about the #6223 change. --- changelog.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/changelog.md b/changelog.md index de4b2f251b..1c5848ce89 100644 --- a/changelog.md +++ b/changelog.md @@ -111,6 +111,8 @@ This now needs to be written as: - The ``[]`` proc for strings now raises an ``IndexError`` exception when the specified slice is out of bounds. See issue [#6223](https://github.com/nim-lang/Nim/issues/6223) for more details. + You can use ``substr(str, start, finish)`` to get the old behaviour back, + see [this commit](https://github.com/nim-lang/nimbot/commit/98cc031a27ea89947daa7f0bb536bcf86462941f) for an example. - ``strutils.split`` and ``strutils.rsplit`` with an empty string and a separator now returns that empty string. See issue [#4377](https://github.com/nim-lang/Nim/issues/4377). From e695f9d94e752fbf18012f9ee164af1ba0649fa1 Mon Sep 17 00:00:00 2001 From: Andreas Rumpf Date: Thu, 28 Dec 2017 19:48:21 +0100 Subject: [PATCH 14/15] make Nim compile with older nim versions --- compiler/semasgn.nim | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/compiler/semasgn.nim b/compiler/semasgn.nim index db08605cfb..67af6ade76 100644 --- a/compiler/semasgn.nim +++ b/compiler/semasgn.nim @@ -261,7 +261,7 @@ proc addParam(procType: PType; param: PSym) = rawAddSon(procType, param.typ) proc liftBody(c: PContext; typ: PType; kind: TTypeAttachedOp; - info: TLineInfo): PSym {.discardable.} = + info: TLineInfo): PSym = var a: TLiftCtx a.info = info a.c = c From 0a3cd6d9bacba524daab33578888b30ff17e773d Mon Sep 17 00:00:00 2001 From: Andreas Rumpf Date: Thu, 28 Dec 2017 19:54:55 +0100 Subject: [PATCH 15/15] fixes a serious poll() regression that caused poll() to ignore the timeout parameter --- lib/pure/asyncdispatch.nim | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/pure/asyncdispatch.nim b/lib/pure/asyncdispatch.nim index 23eb80b37b..b62cf2e9bb 100644 --- a/lib/pure/asyncdispatch.nim +++ b/lib/pure/asyncdispatch.nim @@ -1493,7 +1493,7 @@ proc poll*(timeout = 500) = ## Waits for completion events and processes them. Raises ``ValueError`` ## if there are no pending operations. This runs the underlying OS ## `epoll`:idx: or `kqueue`:idx: primitive only once. - discard runOnce() + discard runOnce(timeout) # Common procedures between current and upcoming asyncdispatch include includes.asynccommon