Skip to content

Commit

Permalink
stack backtrace: fix alignment and skipping
Browse files Browse the repository at this point in the history 
runtime.Stack() returns a stack that includes one additional line with
goroutine information (tested with Go 1.12.6, probably was already done
like that for quite a while).

PruneStack then returned a pruned stack that started with a source
code line instead of the function name and that did not skip all
intermediate entries.

Example:

 Stack:
	"runtime/debug.Stack(0x0, 0x0, 0x0)",
	"\t/nvme/gopath/go/src/runtime/debug/stack.go:24 +0xa1",
	"k8s.io/kubernetes/vendor/github.com/onsi/ginkgo/internal/codeloc...+39 more",
	"\t/nvme/gopath/src/k8s.io/kubernetes/vendor/github.com/onsi/ginkg...+49 more",
	"k8s.io/kubernetes/vendor/github.com/onsi/ginkgo.Fail(0xc00052677...+32 more",
	"\t/nvme/gopath/src/k8s.io/kubernetes/vendor/github.com/onsi/ginkg...+25 more",
	"k8s.io/kubernetes/test/e2e/framework/ginkgowrapper.Fail(0xc00052...+35 more",
	"\t/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/ginkgowra...+25 more",
	"k8s.io/kubernetes/test/e2e/framework/log.Fail(0xc00038e1e0, 0x4f...+25 more",
	"\t/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logge...+14 more",
	"k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/asserti...+103 more",
	"\t/nvme/gopath/src/k8s.io/kubernetes/vendor/github.com/onsi/gomeg...+43 more",
	"k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/asserti...+95 more",
	"\t/nvme/gopath/src/k8s.io/kubernetes/vendor/github.com/onsi/gomeg...+42 more",
	"k8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.5()",
        ...
 Skip: 5

 Resulting stack (for some other example):
            /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger.go:51 +0x143
      k8s.io/kubernetes/test/e2e/framework/log.Failf(...)
            /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger.go:43
=>    k8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.2.1(...)
            /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:41
      k8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.2()
            /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:42 +0x52
      k8s.io/kubernetes/vendor/github.com/onsi/ginkgo/internal/leafnodes.(*runner).runSync(0xc00029b020, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
            /nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:65 +0x1c8
      testing.tRunner(0xc000358600, 0x19818c0)
            /nvme/gopath/go/src/testing/testing.go:865 +0xc0
      created by testing.(*T).Run
            /nvme/gopath/go/src/testing/testing.go:916 +0x35a

It should start with the line marked with =>. To achieve that,
the goroutine line must be removed and the caller must use the right skip
count.
  • Loading branch information
@pohly @blgm
pohly authored and blgm committed Aug 28, 2019
1 parent 8f97b93 commit 66915d6
Show file tree
Hide file tree
Showing 2 changed files with 79 additions and 33 deletions.
18 changes: 17 additions & 1 deletion internal/codelocation/code_location.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -15,15 +15,31 @@ func New(skip int) types.CodeLocation {
return types.CodeLocation{FileName: file, LineNumber: line, FullStackTrace: stackTrace}
}

// PruneStack removes references to functions that are internal to Ginkgo
// and the Go runtime from a stack string and a certain number of stack entries
// at the beginning of the stack. The stack string has the format
// as returned by runtime/debug.Stack. The leading goroutine information is
// optional and always removed if present. Beware that runtime/debug.Stack
// adds itself as first entry, so typically skip must be >= 1 to remove that
// entry.
func PruneStack(fullStackTrace string, skip int) string {
stack := strings.Split(fullStackTrace, "\n")
// Ensure that the even entries are the method names and the
// the odd entries the source code information.
if len(stack) > 0 && strings.HasPrefix(stack[0], "goroutine ") {
// Ignore "goroutine 29 [running]:" line.
stack = stack[1:]
}
// The "+1" is for skipping over the initial entry, which is
// runtime/debug.Stack() itself.
if len(stack) > 2*(skip+1) {
stack = stack[2*(skip+1):]
}
prunedStack := []string{}
re := regexp.MustCompile(`\/ginkgo\/|\/pkg\/testing\/|\/pkg\/runtime\/`)
for i := 0; i < len(stack)/2; i++ {
if !re.Match([]byte(stack[i*2])) {
// We filter out based on the source code file name.
if !re.Match([]byte(stack[i*2+1])) {
prunedStack = append(prunedStack, stack[i*2])
prunedStack = append(prunedStack, stack[i*2+1])
}
Expand Down
94 changes: 62 additions & 32 deletions internal/codelocation/code_location_test.go
View file
Original file line number Diff line number Diff line change
@@ -1,31 +1,36 @@
package codelocation_test

import (
"fmt"
"runtime"
"runtime/debug"
"strings"

. "github.com/onsi/ginkgo"
"github.com/onsi/ginkgo/internal/codelocation"
"github.com/onsi/ginkgo/types"
. "github.com/onsi/gomega"
)

var _ = Describe("CodeLocation", func() {
var (
codeLocation types.CodeLocation
expectedFileName string
expectedLineNumber int
)
var (
codeLocation types.CodeLocation
expectedFileName string
expectedLineNumber int
fullStackTrace string
)

caller0 := func() {
codeLocation = codelocation.New(1)
}
func caller0() {
fullStackTrace = string(debug.Stack())
codeLocation = codelocation.New(1)
}

caller1 := func() {
_, expectedFileName, expectedLineNumber, _ = runtime.Caller(0)
expectedLineNumber += 2
caller0()
}
func caller1() {
_, expectedFileName, expectedLineNumber, _ = runtime.Caller(0)
expectedLineNumber += 2
caller0()
}

var _ = Describe("CodeLocation", func() {
BeforeEach(func() {
caller1()
})
Expand All @@ -41,40 +46,65 @@ var _ = Describe("CodeLocation", func() {
})
})

//There's no better way than to test this private method as it
//goes out of its way to prune out ginkgo related code in the stack trace
Describe("PruneStack", func() {
It("should remove any references to ginkgo and pkg/testing and pkg/runtime", func() {
input := `/Skip/me
Skip: skip()
// Hard-coded string, loosely based on what debug.Stack() produces.
input := `Skip: skip()
/Skip/me
Skip: skip()
/Users/whoever/gospace/src/github.com/onsi/ginkgo/whatever.go:10 (0x12314)
/Skip/me
Something: Func()
/Users/whoever/gospace/src/github.com/onsi/ginkgo/whatever_else.go:10 (0x12314)
/Users/whoever/gospace/src/github.com/onsi/ginkgo/whatever.go:10 (0x12314)
SomethingInternalToGinkgo: Func()
/usr/goroot/pkg/strings/oops.go:10 (0x12341)
/Users/whoever/gospace/src/github.com/onsi/ginkgo/whatever_else.go:10 (0x12314)
Oops: BlowUp()
/Users/whoever/gospace/src/mycode/code.go:10 (0x12341)
/usr/goroot/pkg/strings/oops.go:10 (0x12341)
MyCode: Func()
/Users/whoever/gospace/src/mycode/code_test.go:10 (0x12341)
/Users/whoever/gospace/src/mycode/code.go:10 (0x12341)
MyCodeTest: Func()
/Users/whoever/gospace/src/mycode/code_suite_test.go:12 (0x37f08)
/Users/whoever/gospace/src/mycode/code_test.go:10 (0x12341)
TestFoo: RunSpecs(t, "Foo Suite")
/usr/goroot/pkg/testing/testing.go:12 (0x37f08)
/Users/whoever/gospace/src/mycode/code_suite_test.go:12 (0x37f08)
TestingT: Blah()
/usr/goroot/pkg/runtime/runtime.go:12 (0x37f08)
/usr/goroot/pkg/testing/testing.go:12 (0x37f08)
Something: Func()
/usr/goroot/pkg/runtime/runtime.go:12 (0x37f08)
`
prunedStack := codelocation.PruneStack(input, 1)
Ω(prunedStack).Should(Equal(`/usr/goroot/pkg/strings/oops.go:10 (0x12341)
Oops: BlowUp()
/Users/whoever/gospace/src/mycode/code.go:10 (0x12341)
Ω(prunedStack).Should(Equal(`Oops: BlowUp()
/usr/goroot/pkg/strings/oops.go:10 (0x12341)
MyCode: Func()
/Users/whoever/gospace/src/mycode/code_test.go:10 (0x12341)
/Users/whoever/gospace/src/mycode/code.go:10 (0x12341)
MyCodeTest: Func()
/Users/whoever/gospace/src/mycode/code_suite_test.go:12 (0x37f08)
TestFoo: RunSpecs(t, "Foo Suite")`))
/Users/whoever/gospace/src/mycode/code_test.go:10 (0x12341)
TestFoo: RunSpecs(t, "Foo Suite")
/Users/whoever/gospace/src/mycode/code_suite_test.go:12 (0x37f08)`))
})

It("should skip correctly for a Go runtime stack", func() {
// Actual string from debug.Stack(), something like:
// "goroutine 5 [running]:",
// "runtime/debug.Stack(0x0, 0x0, 0x0)",
// "\t/nvme/gopath/go/src/runtime/debug/stack.go:24 +0xa1",
// "github.com/onsi/ginkgo/internal/codelocation_test.caller0()",
// "\t/work/gopath.ginkgo/src/github.com/onsi/XXXXXX/internal/codeloc...+36 more",
// "github.com/onsi/ginkgo/internal/codelocation_test.caller1()",
// "\t/work/gopath.ginkgo/src/github.com/onsi/XXXXXX/internal/codeloc...+36 more",
// "github.com/onsi/ginkgo/internal/codelocation_test.glob..func1.1(...+1 more",
// "\t/work/gopath.ginkgo/src/github.com/onsi/XXXXXX/internal/codeloc...+36 more",
//
// To avoid pruning of our test functions
// above, we change the expected filename (= this file) into
// something that isn't special for PruneStack().
fakeFileName := "github.com/onsi/XXXXXX/internal/codelocation/code_location_test.go"
mangledStackTrace := strings.Replace(fullStackTrace,
expectedFileName,
fakeFileName,
-1)
stack := strings.Split(codelocation.PruneStack(mangledStackTrace, 1), "\n")
Ω(len(stack)).To(BeNumerically(">=", 2), "not enough entries in stack: %s", stack)
Ω(stack[0]).To(Equal("github.com/onsi/ginkgo/internal/codelocation_test.caller1()"))
Ω(strings.TrimLeft(stack[1], " \t")).To(HavePrefix(fmt.Sprintf("%s:%d ", fakeFileName, expectedLineNumber)))
})
})
})

0 comments on commit 66915d6

Please sign in to comment.