stacktraces can now show custom runtime msgs per frame (#13351)

* stacktraces can now show custom runtime msgs
* improve tests/stdlib/tstackframes.nim
* fix test for --gc:arc
* test --stacktraceMsgs:on and --stacktraceMsgs:off
* --stacktracemsgs:off by default

changelog.md

@@ -150,6 +150,9 @@ echo f
 - `net.newContext` now performs SSL Certificate checking on Linux and OSX.
   Define `nimDisableCertificateValidation` to disable it globally.
 - new syntax for lvalue references: `var b {.byaddr.} = expr` enabled by `import pragmas`
+- new module `std/stackframes`, in particular `setFrameMsg` which enables
+  custom runtime annotation of stackframes, see #13351 for examples. Turn on/off via
+  `--stackTraceMsgs:on/off`
 
 ## Language additions
 

compiler/commands.nim

@@ -281,6 +281,7 @@ proc testCompileOption*(conf: ConfigRef; switch: string, info: TLineInfo): bool
   of "hints": result = contains(conf.options, optHints)
   of "threadanalysis": result = contains(conf.globalOptions, optThreadAnalysis)
   of "stacktrace": result = contains(conf.options, optStackTrace)
+  of "stacktracemsgs": result = contains(conf.options, optStackTraceMsgs)
   of "linetrace": result = contains(conf.options, optLineTrace)
   of "debugger": result = contains(conf.globalOptions, optCDebug)
   of "profiler": result = contains(conf.options, optProfiler)
@@ -531,6 +532,7 @@ proc processSwitch*(switch, arg: string, pass: TCmdLinePass, info: TLineInfo;
     if processOnOffSwitchOrList(conf, {optHints}, arg, pass, info): listHints(conf)
   of "threadanalysis": processOnOffSwitchG(conf, {optThreadAnalysis}, arg, pass, info)
   of "stacktrace": processOnOffSwitch(conf, {optStackTrace}, arg, pass, info)
+  of "stacktracemsgs": processOnOffSwitch(conf, {optStackTraceMsgs}, arg, pass, info)
   of "excessivestacktrace": processOnOffSwitchG(conf, {optExcessiveStackTrace}, arg, pass, info)
   of "linetrace": processOnOffSwitch(conf, {optLineTrace}, arg, pass, info)
   of "debugger":

compiler/condsyms.nim

@@ -114,3 +114,4 @@ proc initDefines*(symbols: StringTableRef) =
 
   defineSymbol("nimHasSinkInference")
   defineSymbol("nimNewIntegerOps")
+  defineSymbol("nimHasStacktraceMsgs")

compiler/options.nim

@@ -28,7 +28,9 @@ type                          # please make sure we have under 32 options
     optOverflowCheck, optNilCheck, optRefCheck,
     optNaNCheck, optInfCheck, optStaticBoundsCheck, optStyleCheck,
     optAssert, optLineDir, optWarns, optHints,
-    optOptimizeSpeed, optOptimizeSize, optStackTrace, # stack tracing support
+    optOptimizeSpeed, optOptimizeSize,
+    optStackTrace, # stack tracing support
+    optStackTraceMsgs, # enable custom runtime msgs via `setFrameMsg`
     optLineTrace,             # line tracing support (includes stack tracing)
     optByRef,                 # use pass by ref for objects
                               # (for interfacing with C)
@@ -325,7 +327,7 @@ const
 
   DefaultOptions* = {optObjCheck, optFieldCheck, optRangeCheck,
     optBoundsCheck, optOverflowCheck, optAssert, optWarns, optRefCheck,
-    optHints, optStackTrace, optLineTrace,
+    optHints, optStackTrace, optLineTrace, # consider adding `optStackTraceMsgs`
     optTrMacros, optNilCheck, optStyleCheck, optSinkInference}
   DefaultGlobalOptions* = {optThreadAnalysis,
     optExcessiveStackTrace, optListFullPaths}

compiler/semexprs.nim

@@ -10,6 +10,9 @@
 # this module does the semantic checking for expressions
 # included from sem.nim
 
+when defined(nimCompilerStackraceHints):
+  import std/stackframes
+
 const
   errExprXHasNoType = "expression '$1' has no type (or is ambiguous)"
   errXExpectsTypeOrValue = "'$1' expects a type or value"
@@ -2557,6 +2560,8 @@ proc shouldBeBracketExpr(n: PNode): bool =
           return true
 
 proc semExpr(c: PContext, n: PNode, flags: TExprFlags = {}): PNode =
+  when defined(nimCompilerStackraceHints):
+    setFrameMsg c.config$n.info & " " & $n.kind
   result = n
   if c.config.cmd == cmdIdeTools: suggestExpr(c, n)
   if nfSem in n.flags: return

doc/advopt.txt

@@ -92,6 +92,7 @@ Advanced options:
                             turn support for hot code reloading on|off
   --excessiveStackTrace:on|off
                             stack traces use full file paths
+  --stackTraceMsgs:on|off   enable user defined stack frame msgs via `setFrameMsg`
   --oldNewlines:on|off      turn on|off the old behaviour of "\n"
   --laxStrings:on|off       when turned on, accessing the zero terminator in
                             strings is allowed; only for backwards compatibility

lib/nimbase.h

@@ -489,6 +489,7 @@ struct TFrame_ {
   NCSTRING filename;
   NI16 len;
   NI16 calldepth;
+  NI frameMsgLen;
 };
 
 #define NIM_POSIX_INIT  __attribute__((constructor))

lib/std/stackframes.nim

@@ -0,0 +1,30 @@
+const NimStackTrace = compileOption("stacktrace")
+const NimStackTraceMsgs = compileOption("stacktraceMsgs")
+
+template procName*(): string =
+  ## returns current C/C++ function name
+  when defined(c) or defined(cpp):
+    var name {.inject.}: cstring
+    {.emit: "`name` = __func__;".}
+    $name
+
+template getPFrame*(): PFrame =
+  ## avoids a function call (unlike `getFrame()`)
+  block:
+    when NimStackTrace:
+      var framePtr {.inject.}: PFrame
+      {.emit: "`framePtr` = &FR_;".}
+      framePtr
+
+template setFrameMsg*(msg: string, prefix = " ") =
+  ## attach a msg to current `PFrame`. This can be called multiple times
+  ## in a given PFrame. Noop unless passing --stacktraceMsgs and --stacktrace
+  when NimStackTrace and NimStackTraceMsgs:
+    block:
+      var fr {.inject.}: PFrame
+      {.emit: "`fr` = &FR_;".}
+      # consider setting a custom upper limit on size (analog to stack overflow)
+      frameMsgBuf.setLen fr.frameMsgLen
+      frameMsgBuf.add prefix
+      frameMsgBuf.add msg
+      fr.frameMsgLen += prefix.len + msg.len

lib/system.nim

@@ -54,6 +54,23 @@ type
 
 include "system/basic_types"
 
+
+proc compileOption*(option: string): bool {.
+  magic: "CompileOption", noSideEffect.}
+  ## Can be used to determine an `on|off` compile-time option. Example:
+  ##
+  ## .. code-block:: Nim
+  ##   when compileOption("floatchecks"):
+  ##     echo "compiled with floating point NaN and Inf checks"
+
+proc compileOption*(option, arg: string): bool {.
+  magic: "CompileOptionArg", noSideEffect.}
+  ## Can be used to determine an enum compile-time option. Example:
+  ##
+  ## .. code-block:: Nim
+  ##   when compileOption("opt", "size") and compileOption("gc", "boehm"):
+  ##     echo "compiled with optimization for size and uses Boehm's GC"
+
 {.push warning[GcMem]: off, warning[Uninit]: off.}
 {.push hints: off.}
 
@@ -1040,22 +1057,6 @@ const
   # emit this flag
   # for string literals, it allows for some optimizations.
 
-proc compileOption*(option: string): bool {.
-  magic: "CompileOption", noSideEffect.}
-  ## Can be used to determine an `on|off` compile-time option. Example:
-  ##
-  ## .. code-block:: Nim
-  ##   when compileOption("floatchecks"):
-  ##     echo "compiled with floating point NaN and Inf checks"
-
-proc compileOption*(option, arg: string): bool {.
-  magic: "CompileOptionArg", noSideEffect.}
-  ## Can be used to determine an enum compile-time option. Example:
-  ##
-  ## .. code-block:: Nim
-  ##   when compileOption("opt", "size") and compileOption("gc", "boehm"):
-  ##     echo "compiled with optimization for size and uses Boehm's GC"
-
 const
   hasThreadSupport = compileOption("threads") and not defined(nimscript)
   hasSharedHeap = defined(boehmgc) or defined(gogc) # don't share heaps; every thread has its own
@@ -1891,6 +1892,7 @@ var
 type
   PFrame* = ptr TFrame  ## Represents a runtime frame of the call stack;
                         ## part of the debugger API.
+  # keep in sync with nimbase.h `struct TFrame_`
   TFrame* {.importc, nodecl, final.} = object ## The frame itself.
     prev*: PFrame       ## Previous frame; used for chaining the call stack.
     procname*: cstring  ## Name of the proc that is currently executing.
@@ -1898,6 +1900,8 @@ type
     filename*: cstring  ## Filename of the proc that is currently executing.
     len*: int16         ## Length of the inspectable slots.
     calldepth*: int16   ## Used for max call depth checking.
+    when NimStackTraceMsgs:
+      frameMsgLen*: int   ## end position in frameMsgBuf for this frame.
 
 when defined(js):
   proc add*(x: var string, y: cstring) {.asmNoStackFrame.} =

lib/system/exceptions.nim

@@ -1,3 +1,7 @@
+const NimStackTraceMsgs =
+  when defined(nimHasStacktraceMsgs): compileOption("stacktraceMsgs")
+  else: false
+
 type
   RootEffect* {.compilerproc.} = object of RootObj ## \
     ## Base effect class.
@@ -16,6 +20,11 @@ type
     procname*: cstring      ## Name of the proc that is currently executing.
     line*: int              ## Line number of the proc that is currently executing.
     filename*: cstring      ## Filename of the proc that is currently executing.
+    when NimStackTraceMsgs:
+      frameMsg*: string     ## When a stacktrace is generated in a given frame and
+                            ## rendered at a later time, we should ensure the stacktrace
+                            ## data isn't invalidated; any pointer into PFrame is
+                            ## subject to being invalidated so shouldn't be stored.
 
   Exception* {.compilerproc, magic: "Exception".} = object of RootObj ## \
     ## Base exception class.

lib/system/excpt.nim

@@ -53,6 +53,8 @@ type
     len: int
     prev: ptr GcFrameHeader
 
+when NimStackTraceMsgs:
+  var frameMsgBuf* {.threadvar.}: string
 var
   framePtr {.threadvar.}: PFrame
   excHandler {.threadvar.}: PSafePoint
@@ -224,10 +226,17 @@ proc auxWriteStackTrace(f: PFrame; s: var seq[StackTraceEntry]) =
     s[last] = StackTraceEntry(procname: it.procname,
                               line: it.line,
                               filename: it.filename)
+    when NimStackTraceMsgs:
+      let first = if it.prev == nil: 0 else: it.prev.frameMsgLen
+      if it.frameMsgLen > first:
+        s[last].frameMsg.setLen(it.frameMsgLen - first)
+        # somehow string slicing not available here
+        for i in first .. it.frameMsgLen-1:
+          s[last].frameMsg[i-first] = frameMsgBuf[i]
     it = it.prev
     dec last
 
-template addFrameEntry(s, f: untyped) =
+template addFrameEntry(s: var string, f: StackTraceEntry|PFrame) =
   var oldLen = s.len
   add(s, f.filename)
   if f.line > 0:
@@ -236,6 +245,12 @@ template addFrameEntry(s, f: untyped) =
     add(s, ')')
   for k in 1..max(1, 25-(s.len-oldLen)): add(s, ' ')
   add(s, f.procname)
+  when NimStackTraceMsgs:
+    when type(f) is StackTraceEntry:
+      add(s, f.frameMsg)
+    else:
+      var first = if f.prev == nil: 0 else: f.prev.frameMsgLen
+      for i in first..<f.frameMsgLen: add(s, frameMsgBuf[i])
   add(s, "\n")
 
 proc `$`(s: seq[StackTraceEntry]): string =
@@ -519,7 +534,12 @@ proc callDepthLimitReached() {.noinline.} =
   quit(1)
 
 proc nimFrame(s: PFrame) {.compilerRtl, inl, raises: [].} =
-  s.calldepth = if framePtr == nil: 0 else: framePtr.calldepth+1
+  if framePtr == nil:
+    s.calldepth = 0
+    when NimStackTraceMsgs: s.frameMsgLen = 0
+  else:
+    s.calldepth = framePtr.calldepth+1
+    when NimStackTraceMsgs: s.frameMsgLen = framePtr.frameMsgLen
   s.prev = framePtr
   framePtr = s
   if s.calldepth == nimCallDepthLimit: callDepthLimitReached()

tests/assert/tassert_c.nim

@@ -36,4 +36,4 @@ try:
 except AssertionError:
   let e = getCurrentException()
   let trace = e.getStackTrace
-  echo tmatch(trace, expected)
+  if tmatch(trace, expected): echo true else: echo "wrong trace:\n" & trace

tests/stdlib/mstackframes.nim

@@ -0,0 +1,38 @@
+import std/stackframes
+
+
+
+# line 5
+var count = 0
+
+proc main1(n: int) =
+  setFrameMsg $("main1", n)
+  if n > 0:
+    main1(n-1)
+
+proc main2(n: int) =
+  count.inc
+  setFrameMsg $("main2", n, count)
+  proc bar() =
+    setFrameMsg $("bar ",)
+    if n < 3: raise newException(CatchableError, "on purpose")
+  bar()
+  main2(n-1)
+
+proc main() =
+  var z = 0
+  setFrameMsg "\n  z: " & $z, prefix = ""
+  # multiple calls inside a frame are possible
+  z.inc
+  setFrameMsg "\n  z: " & $z, prefix = ""
+  try:
+    main2(5)
+  except CatchableError:
+    main1(10) # goes deep and then unwinds; sanity check to ensure `setFrameMsg` from inside
+              # `main1` won't invalidate the stacktrace; if StackTraceEntry.frameMsg
+              # were a reference instead of a copy, this would fail.
+    let e = getCurrentException()
+    let trace = e.getStackTrace
+    echo trace
+
+main()

tests/stdlib/tstackframes.nim

@@ -0,0 +1,34 @@
+import std/[strformat,os,osproc]
+import "$nim/compiler/unittest_light" # works even if moved by megatest
+
+proc main(opt: string, expected: string) =
+  const nim = getCurrentCompilerExe()
+  const file = currentSourcePath().parentDir / "mstackframes.nim"
+  let cmd = fmt"{nim} c -r --excessiveStackTrace:off --stacktraceMsgs:{opt} --hints:off {file}"
+  let (output, exitCode) = execCmdEx(cmd)
+  assertEquals output, expected
+  doAssert exitCode == 0
+
+main("on"): """
+mstackframes.nim(38)     mstackframes
+mstackframes.nim(29)     main
+  z: 0
+  z: 1
+mstackframes.nim(20)     main2 ("main2", 5, 1)
+mstackframes.nim(20)     main2 ("main2", 4, 2)
+mstackframes.nim(20)     main2 ("main2", 3, 3)
+mstackframes.nim(19)     main2 ("main2", 2, 4)
+mstackframes.nim(18)     bar ("bar ",)
+
+"""
+
+main("off"): """
+mstackframes.nim(38)     mstackframes
+mstackframes.nim(29)     main
+mstackframes.nim(20)     main2
+mstackframes.nim(20)     main2
+mstackframes.nim(20)     main2
+mstackframes.nim(19)     main2
+mstackframes.nim(18)     bar
+
+"""