Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

proposal: add interp.FilterStack() method to get interpreter stacktrace #1348

Draft
wants to merge 5 commits into
base: master
Choose a base branch
from

Conversation

bailsman
Copy link

@bailsman bailsman commented Dec 31, 2021

Related to the following tickets:

detailed call information on panic #531
Capture call stack #1040

Interpreter-level stack traces are now available using the new debug interface #1188 #1225
(using, I think, a much saner approach than I am about to propose)

However, it could still be useful to instead convert a runtime stack trace showing the full code path through both interpreted and binary code, without using the debug interface. For example:

// sample.go
package main

import (
        "github.com/traefik/yaegi/interp"
        "github.com/traefik/yaegi/stdlib"
        "reflect"
        "fmt"
        "os"
)

// Binary method to show that we can move between binary and interpreted frames
func Passthrough(f func()) {
        f()
}

type Debug struct {
        interp *interp.Interpreter
}

// Function we call from interpreted code to capture stack trace
func (d Debug) PrintStack(msg string) {
        filteredStack := d.interp.FilteredStack()
        fmt.Fprintf(os.Stderr, "%s\n%s\n", msg, string(filteredStack))
}

func main() {
        i := interp.New(interp.Options{})
        i.Use(stdlib.Symbols)

        customSymbols := map[string]map[string]reflect.Value{}
        customSymbols["sample/sample"] = map[string]reflect.Value{
                "Passthrough": reflect.ValueOf(Passthrough),
                "PrintStack": reflect.ValueOf(Debug{i}.PrintStack),
        }
        i.Use(customSymbols)

        defer func() {
                r := recover()
                if r != nil {
                        p := i.GetOldestPanicForErr(r)
                        if p != nil {
                                fmt.Fprintln(os.Stderr, p)
                        } else {
                                fmt.Fprintln(os.Stderr, r)
                        }
                }
        }()

        _, err := i.EvalPath("helper.go")
        if err != nil {
                panic(err)
        }

        v, err := i.Eval("helper.foo")
        if err != nil {
                panic(err)
        }

        foo := v.Interface().(func())
        foo()
}
// helper.go
package helper

import "sample"

type someStruct struct {
        funcField func()
}

func (s *someStruct) someMethod() {
        s.funcField()
}

func foo() {
        z := func() {
                bar()
        }
        sample.Passthrough((&someStruct{z}).someMethod)
}

func bar() {
        sample.PrintStack("Something went terribly wrong!")
        //panic("Something went terribly wrong!")
}

Run with go run sample.go

The normal runtime interpreter stacktrace is not ideal:

goroutine 1 [running]:
runtime/debug.Stack(0xc0002870e0, 0x10, 0x10)
        /usr/local/go/src/runtime/debug/stack.go:24 +0x9f
main.Debug.PrintStack(0xc0003a8000, 0xc0004a0041, 0x1e)
        /go/src/samplepanic/sample.go:22 +0x34
reflect.Value.call(0xdb12a0, 0xc000286270, 0x13, 0xee44e4, 0x4, 0xc00029e780, 0x1, 0x1, 0xc0004a00c0, 0xc000288bb0, ...)
        /usr/local/go/src/reflect/value.go:476 +0x8e7
reflect.Value.Call(0xdb12a0, 0xc000286270, 0x13, 0xc00029e780, 0x1, 0x1, 0xee1880, 0xc0001ac701, 0xc00029e780)
        /usr/local/go/src/reflect/value.go:337 +0xb9
github.com/traefik/yaegi/interp.callBin.func1(0xc0004a6fc0, 0xdb12a0, 0xc000286270, 0x13, 0xc00029e780, 0x1, 0x1, 0x710000c00048b5f0, 0x6, 0xc000099520)
        /go/src/yaegi/interp/run.go:1484 +0x67
github.com/traefik/yaegi/interp.callBin.func10(0xc0003aa4d0, 0xc000284370)
        /go/src/yaegi/interp/run.go:1661 +0x1c3
github.com/traefik/yaegi/interp.runCfg(0xc0004a57a0, 0xc0004a70e0, 0xc0003aa4d0, 0xc0004a67e0, 0xc0004a57a0)
        /go/src/yaegi/interp/run.go:201 +0xbe
github.com/traefik/yaegi/interp.call.func9(0xc0003aa420, 0x417c3b)
        /go/src/yaegi/interp/run.go:1431 +0xe7f
github.com/traefik/yaegi/interp.runCfg(0xc0004a7b00, 0xc0004a57a0, 0xc0003aa420, 0xc0004a7b00, 0xc0004a7b00)
        /go/src/yaegi/interp/run.go:201 +0xbe
github.com/traefik/yaegi/interp.genFunctionWrapper.func2.1(0x1561e30, 0x0, 0x0, 0x1561e30, 0x400, 0x7f57962cff18)
        /go/src/yaegi/interp/run.go:1030 +0x55a
reflect.Value.call(0xda9f80, 0xc000282390, 0x193, 0xee44e4, 0x4, 0x1561e30, 0x0, 0x0, 0x8, 0xe3a760, ...)
        /usr/local/go/src/reflect/value.go:476 +0x8e7
reflect.Value.Call(0xda9f80, 0xc000282390, 0x193, 0x1561e30, 0x0, 0x0, 0xee1880, 0xc0001ad101, 0x1561e30)
        /usr/local/go/src/reflect/value.go:337 +0xb9
github.com/traefik/yaegi/interp.callBin.func1(0xc0004a4240, 0xda9f80, 0xc000282390, 0x193, 0x1561e30, 0x0, 0x0, 0x0, 0xda9f80, 0xc000282390)
        /go/src/yaegi/interp/run.go:1484 +0x67
github.com/traefik/yaegi/interp.callBin.func10(0xc0003aa370, 0xc000284280)
        /go/src/yaegi/interp/run.go:1661 +0x1c3
github.com/traefik/yaegi/interp.runCfg(0xc0004a6000, 0xc0004a4360, 0xc0003aa370, 0xc0003b3560, 0xc0004a6000)
        /go/src/yaegi/interp/run.go:201 +0xbe
github.com/traefik/yaegi/interp.genFunctionWrapper.func2.1(0x1561e30, 0x0, 0x0, 0x1561e30, 0x7f576f510438, 0x3a0)
        /go/src/yaegi/interp/run.go:1030 +0x55a
main.Passthrough(0xc00048bce0)
        /go/src/samplepanic/sample.go:13 +0x25
reflect.Value.call(0xdb0aa0, 0xf29628, 0x13, 0xee44e4, 0x4, 0xc00029e750, 0x1, 0x1, 0xda9f80, 0xc0001ad8d8, ...)
        /usr/local/go/src/reflect/value.go:476 +0x8e7
reflect.Value.Call(0xdb0aa0, 0xf29628, 0x13, 0xc00029e750, 0x1, 0x1, 0xda9f80, 0xc0003b3560, 0x0)
        /usr/local/go/src/reflect/value.go:337 +0xb9
github.com/traefik/yaegi/interp.callBin.func1(0xc0004a5b00, 0xdb0aa0, 0xf29628, 0x13, 0xc00029e750, 0x1, 0x1, 0x120, 0x120, 0x7f57962cff18)
        /go/src/yaegi/interp/run.go:1484 +0x67
github.com/traefik/yaegi/interp.callBin.func10(0xc0003aa160, 0xc0002842d0)
        /go/src/yaegi/interp/run.go:1661 +0x1c3
github.com/traefik/yaegi/interp.runCfg(0xc0004a46c0, 0xc0004a4fc0, 0xc0003aa160, 0xc0004a46c0, 0xc0004a46c0)
        /go/src/yaegi/interp/run.go:201 +0xbe
github.com/traefik/yaegi/interp.genFunctionWrapper.func2.1(0x1561e30, 0x0, 0x0, 0x1561e30, 0xc00028aa40, 0xda9f80)
        /go/src/yaegi/interp/run.go:1030 +0x55a
main.main()
        /go/src/samplepanic/sample.go:60 +0x49c

With the proposed FilterStack method, you can get a stacktrace that looks like this instead:

Something went terribly wrong!
goroutine 1 [running]:
main.Debug.PrintStack(0xc0003d4480, 0xc000600101, 0x1e)
        /go/src/sampledebug/sample.go:22 +0x45
helper.bar()
        helper.go:21:2
helper.foo.func1()
        helper.go:15:3
helper.(*someStruct).someMethod()
        helper.go:10:2
main.Passthrough(0xc000616a50)
        /go/src/sampledebug/sample.go:13 +0x25
helper.foo()
        helper.go:17:2
main.main()
        /go/src/sampledebug/sample.go:60 +0x495

You can follow the call path through both binary frames and interpreted frames. Yaegi runtime frames are filtered out and replaced by the interpreted code, making it easier to see what happened. This example now shows calling a debug function deliberately, but you can capture a panic in the same way.

How it works: by placing a handle value in the parameters to several strategic calls in the runtime we can then later parse a runtime stacktrace, look for the magic values in function parameters, and reconstruct the calling nodes.

Aside from being totally insane, this approach has several other disadvantages:

(1) I'm not sure if we can be confident that the runtime stack trace can always be parsed in this way (it might change, and might vary by platform and runtime version)

(2) Interpreter behavior and stack trace parsing code are now tightly coupled, perhaps forcing you go to back and fix the stack trace parsing with every little change to the interpreter.

(3) I don't know what effects this has on performance.

Also, FuncName() turned out to be much more complicated than I expected. I'm convinced there must be a simpler way to do this - perhaps with some help at parse time. I haven't extensively tested correctness either.

I've also modified runCfg so that it captures a filtered stack trace on every panic, which can then be retrieved by calling i.GetOldestPanicForErr(err), which returns an interp.Panic object. In this branch, yaegi now prints the filtered stacktrace rather than the normal runtime stacktrace by default, which you can try out by running it on anything that panics. The runtime stacktrace is still available programmatically as i.GetOldestPanicForErr(err).Stack.

We want to capture the oldest panic, before runCfg unwinds everything and we lose important context. However, at that point, we don't yet know whether it will be recovered or not. We store the panic in the Interpreter struct. This will cause incorrect behavior if the panic is recovered and GetOldestPanicForErr is never called, and then later the exact same error happens again but is not recovered. In that case we will return the wrong (old) stacktrace.

All in all, using the new debug functionality to achieve something like this would probably work out better in the long run, but because this might be useful to someone I figured I'd put it up for discussion.

@CLAassistant
Copy link

CLAassistant commented Dec 31, 2021

CLA assistant check
All committers have signed the CLA.

By placing a handle value on several strategic calls in the runtime
we can then later parse a runtime stacktrace, look for the magic
values in function parameters, and reconstruct the calling nodes.

We can use that to filter out all the yaegi runtime calls and
present the user with a stacktrace that includes only interpreted
frames.
this makes the filtered stack look identical to the regular go stacktrace
this allows calling code to interchange both types
interpreter may be entered (for example) from genFunctionWrapper
@bailsman bailsman force-pushed the FilterStack branch 2 times, most recently from eb2cc02 to fd96a6c Compare January 2, 2022 19:50
When a panic happens, we want to get the stack trace from the oldest
panic, before runCfg unwinds everything.

However, at that point we don't know yet whether we will be recovered.
As a silly kludge, currently storing the oldest panic in a list on the
Interpreter struct which can then be queried once we're ready.

The approach taken is not strictly correct: if a panic is recovered, and
never queried, and later the same error occurs again and then is not
recovered, the wrong call stack will be returned.
@yunbai002
Copy link

@mvertes Excuse me, when will this feature be officially released?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants