Skip to content
Permalink
Browse files

[fix] Ensure stackframes are skipped accurately

For session tracking we over-simplified the logic around when to skip
frames. This bug was not caught in our test suite. This commit fixes
these stackframe bugs, adds additional testing, and adds comments around
the locations where we skip stackframes to ensure this doesn't happen in
the future again.

Identified a bug in `(*Notifier).notify`, where the first frame would
always be from `(*Notifier).notify` itself. Skipping an additional frame
resolved this.

The test should highlight exactly what frames we expect for each of the
calls that would result in a report being sent. Apart from
`(*Notifier).Notify` these are consistent with the latest release.
That being said, whenever we're reporting panics (i.e. AutoNotify,
Recover) seem to be intentionally stripping off 2 low-level stackframes
(in the Go runtime) but also keeping 2. I am a bit confused by this, but
keeping for consistency.
  • Loading branch information...
kinbiko committed Oct 15, 2018
1 parent f457d2a commit 7ed74e99bf1c273954249d635dcb834151216b2f
Showing with 178 additions and 18 deletions.
  1. +32 −3 bugsnag.go
  2. +1 −1 bugsnag_test.go
  3. +1 −1 event.go
  4. +21 −11 notifier.go
  5. +123 −0 notifier_test.go
  6. +0 −2 testutil/json.go
@@ -2,6 +2,7 @@ package bugsnag

import (
"context"
"fmt"
"log"
"net/http"
"os"
@@ -63,7 +64,13 @@ func StartSession(ctx context.Context) context.Context {
// information about it in the dashboard, or set the severity of the
// notification.
func Notify(err error, rawData ...interface{}) error {
return defaultNotifier.Notify(err, rawData...)
if e := checkForEmptyError(err); e != nil {
return e
}
// Stripping one stackframe to not include this function in the stacktrace
// for a manual notification.
skipFrames := 1
return defaultNotifier.Notify(errors.New(err, skipFrames), rawData...)
}

// AutoNotify logs a panic on a goroutine and then repanics.
@@ -88,7 +95,12 @@ func AutoNotify(rawData ...interface{}) {
severity := defaultNotifier.getDefaultSeverity(rawData, SeverityError)
state := HandledState{SeverityReasonHandledPanic, severity, true, ""}
rawData = append([]interface{}{state}, rawData...)
defaultNotifier.NotifySync(errors.New(err, 2), true, rawData...)
// We strip the following stackframes as they don't add much info
// - runtime/$arch - e.g. runtime/asm_amd64.s#call32
// - runtime/panic.go#gopanic
// Panics have their own stacktrace, so no stripping of the current stack
skipFrames := 2
defaultNotifier.NotifySync(errors.New(err, skipFrames), true, rawData...)
sessionTracker.FlushSessions()
panic(err)
}
@@ -121,7 +133,12 @@ func Recover(rawData ...interface{}) {
severity := defaultNotifier.getDefaultSeverity(rawData, SeverityWarning)
state := HandledState{SeverityReasonHandledPanic, severity, false, ""}
rawData = append([]interface{}{state}, rawData...)
defaultNotifier.Notify(errors.New(err, 2), rawData...)
// We strip the following stackframes as they don't add much info
// - runtime/$arch - e.g. runtime/asm_amd64.s#call32
// - runtime/panic.go#gopanic
// Panics have their own stacktrace, so no stripping of the current stack
skipFrames := 2
defaultNotifier.Notify(errors.New(err, skipFrames), rawData...)
}
}

@@ -182,6 +199,18 @@ func HandlerFunc(h http.HandlerFunc, rawData ...interface{}) http.HandlerFunc {
}
}

// checkForEmptyError checks if the given error (to be reported to Bugsnag) is
// nil. If it is, then log an error messageand return another error wrapping
// this error message.
func checkForEmptyError(err error) error {
if err != nil {
return nil
}
msg := "attempted to notify Bugsnag without supplying an error. Bugsnag not notified"
Config.Logger.Printf("ERROR: " + msg)
return fmt.Errorf(msg)
}

func init() {
// Set up builtin middlewarez
OnBeforeNotify(httpRequestMiddleware)
@@ -492,7 +492,7 @@ func TestNotifyWithoutError(t *testing.T) {

select {
case r := <-reports:
t.Fatalf("Unexpected request made to bugsnag: %+v", r)
t.Fatalf("Unexpected request made to bugsnag: %+v", string(r))
default:
for _, exp := range []string{"ERROR", "error", "Bugsnag", "not notified"} {
if got := l.msg; !strings.Contains(got, exp) {
@@ -128,7 +128,7 @@ func newEvent(rawData []interface{}, notifier *Notifier) (*Event, *Configuration
switch datum := datum.(type) {

case error, errors.Error:
err = errors.New(datum.(error), 4)
err = errors.New(datum.(error), 1)
event.Error = err
event.ErrorClass = err.TypeName()
event.Message = err.Error()
@@ -1,8 +1,6 @@
package bugsnag

import (
"fmt"

"github.com/bugsnag/bugsnag-go/errors"
)

@@ -49,24 +47,31 @@ func (notifier *Notifier) FlushSessionsOnRepanic(shouldFlush bool) {
// or bugsnag.MetaData. Any bools in rawData overrides the
// notifier.Config.Synchronous flag.
func (notifier *Notifier) Notify(err error, rawData ...interface{}) (e error) {
return notifier.NotifySync(err, notifier.Config.Synchronous, rawData...)
if e := checkForEmptyError(err); e != nil {
return e
}
// Stripping one stackframe to not include this function in the stacktrace
// for a manual notification.
skipFrames := 1
return notifier.NotifySync(errors.New(err, skipFrames), notifier.Config.Synchronous, rawData...)
}

// NotifySync sends an error to Bugsnag. A boolean parameter specifies whether
// to send the report in the current context (by default false, i.e.
// asynchronous). Any other rawData you pass here will be sent to Bugsnag after
// being converted to JSON. E.g. bugsnag.SeverityError, bugsnag.Context, or
// bugsnag.MetaData.
func (notifier *Notifier) NotifySync(err error, sync bool, rawData ...interface{}) (e error) {
if err == nil {
msg := "attempted to notify Bugsnag without supplying an error. Bugsnag not notified"
notifier.Config.Logger.Printf("ERROR: " + msg)
return fmt.Errorf(msg)
func (notifier *Notifier) NotifySync(err error, sync bool, rawData ...interface{}) error {
if e := checkForEmptyError(err); e != nil {
return e
}
event, config := newEvent(append(rawData, err, sync), notifier)
// Stripping one stackframe to not include this function in the stacktrace
// for a manual notification.
skipFrames := 1
event, config := newEvent(append(rawData, errors.New(err, skipFrames), sync), notifier)

// Never block, start throwing away errors if we have too many.
e = middleware.Run(event, config, func() error {
e := middleware.Run(event, config, func() error {
return publisher.publishReport(&payload{event, config})
})

@@ -88,7 +93,12 @@ func (notifier *Notifier) AutoNotify(rawData ...interface{}) {
severity := notifier.getDefaultSeverity(rawData, SeverityError)
state := HandledState{SeverityReasonHandledPanic, severity, true, ""}
rawData = notifier.appendStateIfNeeded(rawData, state)
notifier.Notify(errors.New(err, 2), rawData...)
// We strip the following stackframes as they don't add much
// information but would mess with the grouping algorithm
// { "file": "github.com/bugsnag/bugsnag-go/notifier.go", "lineNumber": 116, "method": "(*Notifier).AutoNotify" },
// { "file": "runtime/asm_amd64.s", "lineNumber": 573, "method": "call32" },
skipFrames := 2
notifier.NotifySync(errors.New(err, skipFrames), true, rawData...)
panic(err)
}
}
@@ -0,0 +1,123 @@
package bugsnag_test

import (
"fmt"
"testing"

simplejson "github.com/bitly/go-simplejson"
"github.com/bugsnag/bugsnag-go"
. "github.com/bugsnag/bugsnag-go/testutil"
)

var bugsnaggedReports chan []byte

func notifierSetup(url string) *bugsnag.Notifier {
return bugsnag.New(bugsnag.Configuration{
APIKey: TestAPIKey,
Endpoints: bugsnag.Endpoints{Notify: url, Sessions: url + "/sessions"},
})
}

func crash(s interface{}) int {
return s.(int)
}

func TestStackframesAreSkippedCorrectly(t *testing.T) {
ts, reports := Setup()
bugsnaggedReports = reports
defer ts.Close()
notifier := notifierSetup(ts.URL)

bugsnag.Configure(bugsnag.Configuration{
APIKey: TestAPIKey,
Endpoints: bugsnag.Endpoints{Notify: ts.URL, Sessions: ts.URL + "/sessions"},
})

// Expect the following frames to be ignored for *.Notify
/*
{ "file": "$GOPATH/src/github.com/bugsnag/bugsnag-go/notifier_test.go", "method": "TestStackframesAreSkippedCorrectly.func1" },
{ "file": "testing/testing.go", "method": "tRunner" },
{ "file": "runtime/asm_amd64.s", "method": "goexit" }
*/

t.Run("notifier.Notify", func(st *testing.T) {
notifier.Notify(fmt.Errorf("oopsie"))
assertStackframeCount(st, 3)
})
t.Run("bugsnag.Notify", func(st *testing.T) {
bugsnag.Notify(fmt.Errorf("oopsie"))
assertStackframeCount(st, 3)
})

// Expect the following frames to be ignored for notifier.NotifySync
/*
{ "file": "$GOPATH/src/github.com/bugsnag/bugsnag-go/notifier_test.go", "method": "TestStackframesAreSkippedCorrectly.func2" },
{ "file": "testing/testing.go", "method": "tRunner" },
{ "file": "runtime/asm_amd64.s", "method": "goexit" }
*/

t.Run("notifier.NotifySync", func(st *testing.T) {
notifier.NotifySync(fmt.Errorf("oopsie"), true)
assertStackframeCount(st, 3)
})

// Expect the following frames to be ignored for *.AutoNotify
/*
{ "file": "runtime/panic.go", "method": "gopanic" },
{ "file": "runtime/iface.go", "method": "panicdottypeE" },
{ "file": "$GOPATH/src/github.com/bugsnag/bugsnag-go/notifier_test.go", "method": "TestStackframesAreSkippedCorrectly.func2.1" },
{ "file": "$GOPATH/src/github.com/bugsnag/bugsnag-go/notifier_test.go", "method": "TestStackframesAreSkippedCorrectly.func3" },
{ "file": "testing/testing.go", "method": "tRunner" },
{ "file": "runtime/asm_amd64.s", "method": "goexit" }
*/
t.Run("notifier.AutoNotify", func(st *testing.T) {
func() {
defer func() { recover() }()
defer notifier.AutoNotify()
crash("NaN")
}()
assertStackframeCount(st, 6)
})
t.Run("bugsnag.AutoNotify", func(st *testing.T) {
func() {
defer func() { recover() }()
defer bugsnag.AutoNotify()
crash("NaN")
}()
assertStackframeCount(st, 6)
})

// Expect the following frames to be ignored for *.Recover
/*
{ "file": "runtime/panic.go", "method": "gopanic" },
{ "file": "runtime/iface.go", "method": "panicdottypeE" },
{ "file": "$GOPATH/src/github.com/bugsnag/bugsnag-go/notifier_test.go", "method": "TestStackframesAreSkippedCorrectly.func4.1" },
{ "file": "$GOPATH/src/github.com/bugsnag/bugsnag-go/notifier_test.go", "method": "TestStackframesAreSkippedCorrectly.func4" },
{ "file": "testing/testing.go", "method": "tRunner" },
{ "file": "runtime/asm_amd64.s", "method": "goexit" }
*/
t.Run("notifier.Recover", func(st *testing.T) {
func() {
defer notifier.Recover()
crash("NaN")
}()
assertStackframeCount(st, 6)
})
t.Run("bugsnag.Recover", func(st *testing.T) {
func() {
defer bugsnag.Recover()
crash("NaN")
}()
assertStackframeCount(st, 6)
})
}

func assertStackframeCount(t *testing.T, expCount int) {
report, _ := simplejson.NewJson(<-bugsnaggedReports)
stacktrace := GetIndex(GetIndex(report, "events", 0), "exceptions", 0).Get("stacktrace")
if s := stacktrace.MustArray(); len(s) != expCount {
t.Errorf("Expected %d stackframe(s), but there were %d stackframes", expCount, len(s))
s, _ := stacktrace.EncodePretty()
t.Errorf(string(s))
}
}
@@ -2,7 +2,6 @@
package testutil

import (
"fmt"
"io/ioutil"
"net/http"
"net/http/httptest"
@@ -21,7 +20,6 @@ const TestAPIKey = "166f5ad3590596f9aa8d601ea89af845"
func Setup() (*httptest.Server, chan []byte) {
reports := make(chan []byte, 10)
return httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
fmt.Println("Bugsnag called")
if strings.Contains(r.URL.Path, "sessions") {
return
}

0 comments on commit 7ed74e9

Please sign in to comment.
You can’t perform that action at this time.