From 4c53585feed3b65db0c4ca9226e3965d6681424b Mon Sep 17 00:00:00 2001 From: Delisa Mason Date: Fri, 18 Dec 2020 21:02:40 +0000 Subject: [PATCH 1/4] test: remove spaces from test case names its just easier than escaping --- features/fixtures/app/main.go | 22 +++++++++---------- features/plain_features/endpoint.feature | 6 ++--- features/plain_features/handled.feature | 6 ++--- .../plain_features/multieventsession.feature | 4 ++-- .../plain_features/sessioncontext.feature | 2 +- features/plain_features/synchronous.feature | 4 ++-- 6 files changed, 22 insertions(+), 22 deletions(-) diff --git a/features/fixtures/app/main.go b/features/fixtures/app/main.go index d8e9af37..8e53b34f 100644 --- a/features/fixtures/app/main.go +++ b/features/fixtures/app/main.go @@ -45,11 +45,11 @@ func configureBasicBugsnag(testcase string) { } switch testcase { - case "endpoint legacy": + case "endpoint-legacy": config.Endpoint = os.Getenv("BUGSNAG_ENDPOINT") - case "endpoint notify": + case "endpoint-notify": config.Endpoints = bugsnag.Endpoints{Notify: os.Getenv("BUGSNAG_ENDPOINT")} - case "endpoint session": + case "endpoint-session": config.Endpoints = bugsnag.Endpoints{Sessions: os.Getenv("BUGSNAG_ENDPOINT")} default: config.Endpoints = bugsnag.Endpoints{ @@ -75,9 +75,9 @@ func main() { switch *test { case "unhandled": unhandledCrash() - case "handled", "endpoint legacy", "endpoint notify", "endpoint session": + case "handled", "endpoint-legacy", "endpoint-notify", "endpoint-session": handledError() - case "handled with callback": + case "handled-with-callback": handledCallbackError() case "session": session() @@ -91,19 +91,19 @@ func main() { filtered() case "recover": dontDie() - case "session and error": + case "session-and-error": sessionAndError() - case "send and exit": + case "send-and-exit": sendAndExit() case "user": user() - case "multiple handled": + case "multiple-handled": multipleHandled() - case "multiple unhandled": + case "multiple-unhandled": multipleUnhandled() - case "make unhandled with callback": + case "make-unhandled-with-callback": handledToUnhandled() - case "nested error": + case "nested-error": nestedHandledError() default: log.Println("Not a valid test flag: " + *test) diff --git a/features/plain_features/endpoint.feature b/features/plain_features/endpoint.feature index 4dee79f3..24f7dc15 100644 --- a/features/plain_features/endpoint.feature +++ b/features/plain_features/endpoint.feature @@ -6,16 +6,16 @@ Background: And I have built the service "app" Scenario: An error report is sent successfully using the legacy endpoint - When I run the go service "app" with the test case "endpoint legacy" + When I run the go service "app" with the test case "endpoint-legacy" Then I wait to receive a request And the request is a valid error report with api key "a35a2a72bd230ac0aa0f52715bbdc6aa" Scenario: An error report is sent successfully using the notify endpoint only - When I run the go service "app" with the test case "endpoint notify" + When I run the go service "app" with the test case "endpoint-notify" Then I wait to receive a request And the request is a valid error report with api key "a35a2a72bd230ac0aa0f52715bbdc6aa" Scenario: Configuring Bugsnag will panic if the sessions endpoint is configured without the notify endpoint - When I run the go service "app" with the test case "endpoint session" + When I run the go service "app" with the test case "endpoint-session" And I wait for 3 second Then I should receive no requests diff --git a/features/plain_features/handled.feature b/features/plain_features/handled.feature index 60ede41b..b8595d59 100644 --- a/features/plain_features/handled.feature +++ b/features/plain_features/handled.feature @@ -28,7 +28,7 @@ Scenario: A handled error sends a report with a custom name And the "file" of stack frame 0 equals "main.go" Scenario: Sending an event using a callback to modify report contents - When I run the go service "app" with the test case "handled with callback" + When I run the go service "app" with the test case "handled-with-callback" Then I wait to receive a request And the request is a valid error report with api key "a35a2a72bd230ac0aa0f52715bbdc6aa" And the event "unhandled" is false @@ -41,7 +41,7 @@ Scenario: Sending an event using a callback to modify report contents And the "lineNumber" of stack frame 1 equals 0 Scenario: Marking an error as unhandled in a callback - When I run the go service "app" with the test case "make unhandled with callback" + When I run the go service "app" with the test case "make-unhandled-with-callback" Then I wait to receive a request And the request is a valid error report with api key "a35a2a72bd230ac0aa0f52715bbdc6aa" And the event "unhandled" is true @@ -52,7 +52,7 @@ Scenario: Marking an error as unhandled in a callback And stack frame 0 contains a local function spanning 255 to 258 Scenario: Unwrapping the causes of a handled error - When I run the go service "app" with the test case "nested error" + When I run the go service "app" with the test case "nested-error" Then I wait to receive a request And the request is a valid error report with api key "a35a2a72bd230ac0aa0f52715bbdc6aa" And the event "unhandled" is false diff --git a/features/plain_features/multieventsession.feature b/features/plain_features/multieventsession.feature index 162784a8..e9e4dbc1 100644 --- a/features/plain_features/multieventsession.feature +++ b/features/plain_features/multieventsession.feature @@ -7,7 +7,7 @@ Background: And I set environment variable "AUTO_CAPTURE_SESSIONS" to "false" Scenario: Handled errors know about previous reported handled errors - When I run the go service "app" with the test case "multiple handled" + When I run the go service "app" with the test case "multiple-handled" And I wait to receive 2 requests And the request 0 is a valid error report with api key "a35a2a72bd230ac0aa0f52715bbdc6aa" And the request 1 is a valid error report with api key "a35a2a72bd230ac0aa0f52715bbdc6aa" @@ -15,7 +15,7 @@ Scenario: Handled errors know about previous reported handled errors And the event handled sessions count equals 2 for request 1 Scenario: Unhandled errors know about previous reported handled errors - When I run the go service "app" with the test case "multiple unhandled" + When I run the go service "app" with the test case "multiple-unhandled" And I wait to receive 2 requests And the request 0 is a valid error report with api key "a35a2a72bd230ac0aa0f52715bbdc6aa" And the request 1 is a valid error report with api key "a35a2a72bd230ac0aa0f52715bbdc6aa" diff --git a/features/plain_features/sessioncontext.feature b/features/plain_features/sessioncontext.feature index 24fd788b..0b986395 100644 --- a/features/plain_features/sessioncontext.feature +++ b/features/plain_features/sessioncontext.feature @@ -6,7 +6,7 @@ Background: And I have built the service "app" Scenario: An error report contains a session count when part of a session - When I run the go service "app" with the test case "session and error" + When I run the go service "app" with the test case "session-and-error" Then I wait to receive 2 requests after the start up session And the request 0 is a valid error report with api key "a35a2a72bd230ac0aa0f52715bbdc6aa" And the request 1 is a valid session report with api key "a35a2a72bd230ac0aa0f52715bbdc6aa" diff --git a/features/plain_features/synchronous.feature b/features/plain_features/synchronous.feature index fe553e1e..0a132c48 100644 --- a/features/plain_features/synchronous.feature +++ b/features/plain_features/synchronous.feature @@ -8,13 +8,13 @@ Background: Scenario: An error report is sent asynchrously but exits immediately so is not sent Given I set environment variable "SYNCHRONOUS" to "false" - When I run the go service "app" with the test case "send and exit" + When I run the go service "app" with the test case "send-and-exit" And I wait for 3 second Then I should receive no requests Scenario: An error report is report synchronously so it will send before exiting Given I set environment variable "SYNCHRONOUS" to "true" - When I run the go service "app" with the test case "send and exit" + When I run the go service "app" with the test case "send-and-exit" Then I wait to receive 1 requests And the request is a valid error report with api key "a35a2a72bd230ac0aa0f52715bbdc6aa" From 98c249dc048eb0e86a73869770300c3ec2fdf543 Mon Sep 17 00:00:00 2001 From: Delisa Mason Date: Thu, 17 Dec 2020 15:12:03 +0000 Subject: [PATCH 2/4] test: add test case for an unrecovered panic add an init script to launch go and handle process teardown --- features/fixtures/app/Dockerfile | 7 ++++--- features/fixtures/app/run.sh | 25 +++++++++++++++++++++++++ features/plain_features/panics.feature | 23 +++++++++++++++++++++++ features/steps/go_steps.rb | 24 +++++++++++++++++++++++- 4 files changed, 75 insertions(+), 4 deletions(-) create mode 100755 features/fixtures/app/run.sh create mode 100644 features/plain_features/panics.feature diff --git a/features/fixtures/app/Dockerfile b/features/fixtures/app/Dockerfile index 4577c6e5..f176f21a 100644 --- a/features/fixtures/app/Dockerfile +++ b/features/fixtures/app/Dockerfile @@ -1,9 +1,7 @@ ARG GO_VERSION FROM golang:${GO_VERSION}-alpine -RUN apk update && \ - apk upgrade && \ - apk add git +RUN apk update && apk upgrade && apk add git bash ENV GOPATH /app @@ -15,3 +13,6 @@ RUN go get . ./sessions ./headers ./errors # Copy test scenarios COPY ./app /app/src/test WORKDIR /app/src/test + +RUN chmod +x run.sh +CMD ["/app/src/test/run.sh"] diff --git a/features/fixtures/app/run.sh b/features/fixtures/app/run.sh new file mode 100755 index 00000000..3a98cd7e --- /dev/null +++ b/features/fixtures/app/run.sh @@ -0,0 +1,25 @@ +#!/usr/bin/env bash + +# SIGTERM or SIGINT trapped (likely SIGTERM from docker), pass it onto app +# process +function _term_or_init { + kill -TERM "$APP_PID" 2>/dev/null + wait $APP_PID +} + +# The bugsnag notifier monitor process needs at least 300ms, in order to ensure +# that it can send its notify +function _exit { + sleep 1 +} + +trap _term_or_init SIGTERM SIGINT +trap _exit EXIT + +PROC="${@:1}" +$PROC & + +# Wait on the app process to ensure that this script is able to trap the SIGTERM +# signal +APP_PID=$! +wait $APP_PID diff --git a/features/plain_features/panics.feature b/features/plain_features/panics.feature new file mode 100644 index 00000000..27eda495 --- /dev/null +++ b/features/plain_features/panics.feature @@ -0,0 +1,23 @@ +Feature: Panic handling + + Background: + Given I set environment variable "API_KEY" to "a35a2a72bd230ac0aa0f52715bbdc6aa" + And I configure the bugsnag endpoint + And I have built the service "app" + And I set environment variable "AUTO_CAPTURE_SESSIONS" to "false" + + Scenario: Capturing a panic + When I run the go service "app" with the test case "unhandled" + Then I wait to receive a request + And the request is a valid error report with api key "a35a2a72bd230ac0aa0f52715bbdc6aa" + And the event "unhandled" is true + And the event "severity" equals "error" + And the event "severityReason.type" equals "unhandledPanic" + And the exception "errorClass" equals "panic" + And the exception "message" is one of: + | interface conversion: interface is struct {}, not string | + | interface conversion: interface {} is struct {}, not string | + And the in-project frames of the stacktrace are: + | file | method | + | main.go | unhandledCrash.func1 | + | main.go | unhandledCrash | diff --git a/features/steps/go_steps.rb b/features/steps/go_steps.rb index 0fed1494..5851a4ce 100644 --- a/features/steps/go_steps.rb +++ b/features/steps/go_steps.rb @@ -30,7 +30,7 @@ end When("I run the go service {string} with the test case {string}") do |service, testcase| - run_service_with_command(service, "go run main.go -test=\"#{testcase}\"") + run_service_with_command(service, "./run.sh go run main.go -test=\"#{testcase}\"") end Then(/^I wait to receive a request after the start up session$/) do @@ -61,6 +61,21 @@ assert_equal(request_count, stored_requests.size, "#{stored_requests.size} requests received") end +Then("the in-project frames of the stacktrace are:") do |table| + body = find_request(0)[:body] + stacktrace = body["events"][0]["exceptions"][0]["stacktrace"] + found = 0 # counts matching frames and ensures ordering is correct + expected = table.hashes.length + stacktrace.each do |frame| + if found < expected and frame["inProject"] and + frame["file"] == table.hashes[found]["file"] and + frame["method"] == table.hashes[found]["method"] + found = found + 1 + end + end + assert_equal(found, expected, "expected #{expected} matching frames but found #{found}. stacktrace:\n#{stacktrace}") +end + Then("stack frame {int} contains a local function spanning {int} to {int}") do |frame, val, old_val| # Old versions of Go put the line number on the end of the function if ['1.7', '1.8'].include? ENV['GO_VERSION'] @@ -69,3 +84,10 @@ step "the \"lineNumber\" of stack frame #{frame} equals #{val}" end end + +Then("the exception {string} is one of:") do |key, table| + body = find_request(0)[:body] + exception = body["events"][0]["exceptions"][0] + options = table.raw.flatten + assert(options.include?(exception[key]), "expected '#{key}' to be one of #{options}") +end From b7e13d207e0af527c6397391ca5f9634e29396ad Mon Sep 17 00:00:00 2001 From: Delisa Mason Date: Wed, 16 Dec 2020 16:19:25 +0000 Subject: [PATCH 3/4] feat: capture 'fatal error' crashes as panics --- CHANGELOG.md | 7 +++++ errors/error.go | 4 +-- errors/parse_panic.go | 22 +++++++++---- errors/parse_panic_test.go | 63 ++++++++++++++++++++++++++++++++++++++ 4 files changed, 88 insertions(+), 8 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 07144359..e0d6d6a5 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,12 @@ # Changelog +## TBD + +### Enhancements + +* Support capturing "fatal error"-style panics from go, such as from concurrent + map read/writes, out of memory errors, and nil goroutines. + ## 1.8.0 (2020-12-03) ### Enhancements diff --git a/errors/error.go b/errors/error.go index 61ba0b41..3d30168d 100644 --- a/errors/error.go +++ b/errors/error.go @@ -154,8 +154,8 @@ func (err *Error) StackFrames() []StackFrame { // TypeName returns the type this error. e.g. *errors.stringError. func (err *Error) TypeName() string { - if _, ok := err.Err.(uncaughtPanic); ok { - return "panic" + if p, ok := err.Err.(uncaughtPanic); ok { + return p.typeName } if name := reflect.TypeOf(err.Err).String(); len(name) > 0 { return name diff --git a/errors/parse_panic.go b/errors/parse_panic.go index cc37052d..1e1652c0 100644 --- a/errors/parse_panic.go +++ b/errors/parse_panic.go @@ -5,7 +5,10 @@ import ( "strings" ) -type uncaughtPanic struct{ message string } +type uncaughtPanic struct { + typeName string + message string +} func (p uncaughtPanic) Error() string { return p.message @@ -15,20 +18,27 @@ func (p uncaughtPanic) Error() string { // that panicked. This is particularly useful with https://github.com/mitchellh/panicwrap. func ParsePanic(text string) (*Error, error) { lines := strings.Split(text, "\n") + prefixes := []string{"panic:", "fatal error:"} state := "start" var message string + var typeName string var stack []StackFrame for i := 0; i < len(lines); i++ { line := lines[i] if state == "start" { - if strings.HasPrefix(line, "panic: ") { - message = strings.TrimPrefix(line, "panic: ") - state = "seek" - } else { + for _, prefix := range prefixes { + if strings.HasPrefix(line, prefix) { + message = strings.TrimSpace(strings.TrimPrefix(line, prefix)) + typeName = prefix[:len(prefix) - 1] + state = "seek" + break + } + } + if state == "start" { return nil, Errorf("bugsnag.panicParser: Invalid line (no prefix): %s", line) } @@ -68,7 +78,7 @@ func ParsePanic(text string) (*Error, error) { } if state == "done" || state == "parsing" { - return &Error{Err: uncaughtPanic{message}, frames: stack}, nil + return &Error{Err: uncaughtPanic{typeName, message}, frames: stack}, nil } return nil, Errorf("could not parse panic: %v", text) } diff --git a/errors/parse_panic_test.go b/errors/parse_panic_test.go index f9ed7845..42bce988 100644 --- a/errors/parse_panic_test.go +++ b/errors/parse_panic_test.go @@ -140,3 +140,66 @@ func TestParsePanic(t *testing.T) { } } } + +var concurrentMapReadWrite = `fatal error: concurrent map read and map write + +goroutine 1 [running]: +runtime.throw(0x10766f5, 0x21) + /usr/local/Cellar/go/1.15.5/libexec/src/runtime/panic.go:1116 +0x72 fp=0xc00003a6c8 sp=0xc00003a698 pc=0x102d592 +runtime.mapaccess1_faststr(0x1066fc0, 0xc000060000, 0x10732e0, 0x1, 0xc000100088) + /usr/local/Cellar/go/1.15.5/libexec/src/runtime/map_faststr.go:21 +0x465 fp=0xc00003a738 sp=0xc00003a6c8 pc=0x100e9c5 +main.concurrentWrite() + /myapps/go/fatalerror/main.go:14 +0x7a fp=0xc00003a778 sp=0xc00003a738 pc=0x105d83a +main.main() + /myapps/go/fatalerror/main.go:41 +0x25 fp=0xc00003a788 sp=0xc00003a778 pc=0x105d885 +runtime.main() + /usr/local/Cellar/go/1.15.5/libexec/src/runtime/proc.go:204 +0x209 fp=0xc00003a7e0 sp=0xc00003a788 pc=0x102fd49 +runtime.goexit() + /usr/local/Cellar/go/1.15.5/libexec/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc00003a7e8 sp=0xc00003a7e0 pc=0x105a4a1 + +goroutine 5 [runnable]: +main.concurrentWrite.func1(0xc000060000) + /myapps/go/fatalerror/main.go:10 +0x4c +created by main.concurrentWrite + /myapps/go/fatalerror/main.go:8 +0x4b +` + +func TestParseFatalError(t *testing.T) { + + Err, err := ParsePanic(concurrentMapReadWrite) + + if err != nil { + t.Fatal(err) + } + + if Err.TypeName() != "fatal error" { + t.Errorf("Wrong type: %s", Err.TypeName()) + } + + if Err.Error() != "concurrent map read and map write" { + t.Errorf("Wrong message: '%s'", Err.Error()) + } + + if Err.StackFrames()[0].Func() != nil { + t.Errorf("Somehow managed to find a func...") + } + + var result = []StackFrame{ + StackFrame{File: "/usr/local/Cellar/go/1.15.5/libexec/src/runtime/panic.go", LineNumber: 1116, Name: "throw", Package: "runtime"}, + StackFrame{File: "/usr/local/Cellar/go/1.15.5/libexec/src/runtime/map_faststr.go", LineNumber: 21, Name: "mapaccess1_faststr", Package: "runtime"}, + StackFrame{File: "/myapps/go/fatalerror/main.go", LineNumber: 14, Name: "concurrentWrite", Package: "main"}, + StackFrame{File: "/myapps/go/fatalerror/main.go", LineNumber: 41, Name: "main", Package: "main"}, + StackFrame{File: "/usr/local/Cellar/go/1.15.5/libexec/src/runtime/proc.go", LineNumber: 204, Name: "main", Package: "runtime"}, + StackFrame{File: "/usr/local/Cellar/go/1.15.5/libexec/src/runtime/asm_amd64.s", LineNumber: 1374, Name: "goexit", Package: "runtime"}, + } + + if !reflect.DeepEqual(Err.StackFrames(), result) { + t.Errorf("Wrong stack for concurrent write fatal error:") + for i, frame := range result { + t.Logf("[%d] %#v", i, frame) + if len(Err.StackFrames()) > i { + t.Logf(" %#v", Err.StackFrames()[i]) + } + } + } +} From 3ee4ddaad77ea987635f324ef1d25941657f14cb Mon Sep 17 00:00:00 2001 From: Delisa Mason Date: Tue, 5 Jan 2021 11:36:55 +0000 Subject: [PATCH 4/4] Release v1.9.0 --- CHANGELOG.md | 2 +- bugsnag.go | 2 +- payload_test.go | 4 ++-- 3 files changed, 4 insertions(+), 4 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index e0d6d6a5..70c8aaea 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,6 +1,6 @@ # Changelog -## TBD +## 1.9.0 (2021-01-05) ### Enhancements diff --git a/bugsnag.go b/bugsnag.go index 0e6803e3..843cd9e9 100644 --- a/bugsnag.go +++ b/bugsnag.go @@ -21,7 +21,7 @@ import ( ) // VERSION defines the version of this Bugsnag notifier -const VERSION = "1.8.0" +const VERSION = "1.9.0" var panicHandlerOnce sync.Once var sessionTrackerOnce sync.Once diff --git a/payload_test.go b/payload_test.go index 22c6b566..45b0a444 100644 --- a/payload_test.go +++ b/payload_test.go @@ -11,12 +11,12 @@ import ( "github.com/bugsnag/bugsnag-go/sessions" ) -const expSmall = `{"apiKey":"","events":[{"app":{"releaseStage":""},"device":{"osName":"%s","runtimeVersions":{"go":"%s"}},"exceptions":[{"errorClass":"","message":"","stacktrace":null}],"metaData":{},"payloadVersion":"4","severity":"","unhandled":false}],"notifier":{"name":"Bugsnag Go","url":"https://github.com/bugsnag/bugsnag-go","version":"1.8.0"}}` +const expSmall = `{"apiKey":"","events":[{"app":{"releaseStage":""},"device":{"osName":"%s","runtimeVersions":{"go":"%s"}},"exceptions":[{"errorClass":"","message":"","stacktrace":null}],"metaData":{},"payloadVersion":"4","severity":"","unhandled":false}],"notifier":{"name":"Bugsnag Go","url":"https://github.com/bugsnag/bugsnag-go","version":"` + VERSION + `"}}` // The large payload has a timestamp in it which makes it awkward to assert against. // Instead, assert that the timestamp property exist, along with the rest of the expected payload const expLargePre = `{"apiKey":"166f5ad3590596f9aa8d601ea89af845","events":[{"app":{"releaseStage":"mega-production","type":"gin","version":"1.5.3"},"context":"/api/v2/albums","device":{"hostname":"super.duper.site","osName":"%s","runtimeVersions":{"go":"%s"}},"exceptions":[{"errorClass":"error class","message":"error message goes here","stacktrace":[{"method":"doA","file":"a.go","lineNumber":65},{"method":"fetchB","file":"b.go","lineNumber":99,"inProject":true},{"method":"incrementI","file":"i.go","lineNumber":651}]}],"groupingHash":"custom grouping hash","metaData":{"custom tab":{"my key":"my value"}},"payloadVersion":"4","session":{"startedAt":"` -const expLargePost = `,"severity":"info","severityReason":{"type":"unhandledError","attributes":{"framework":"gin"}},"unhandled":true,"user":{"id":"1234baerg134","name":"Kool Kidz on da bus","email":"typo@busgang.com"}}],"notifier":{"name":"Bugsnag Go","url":"https://github.com/bugsnag/bugsnag-go","version":"1.8.0"}}` +const expLargePost = `,"severity":"info","severityReason":{"type":"unhandledError","attributes":{"framework":"gin"}},"unhandled":true,"user":{"id":"1234baerg134","name":"Kool Kidz on da bus","email":"typo@busgang.com"}}],"notifier":{"name":"Bugsnag Go","url":"https://github.com/bugsnag/bugsnag-go","version":"` + VERSION + `"}}` func TestMarshalEmptyPayload(t *testing.T) { sessionTracker = sessions.NewSessionTracker(&sessionTrackingConfig)