diff --git a/e2e/go-plugin/README.md b/e2e/go-plugin/README.md index 22779df50a..2d9a81e7c6 100644 --- a/e2e/go-plugin/README.md +++ b/e2e/go-plugin/README.md @@ -20,6 +20,48 @@ cd observability-sdk/e2e/go-plugin export LAUNCHDARKLY_SDK_KEY="your-sdk-key-here" ``` +## Running against a backend on localhost + +The examples export to LaunchDarkly by default. The HTTP example also honours the +standard endpoint variable, so it can be pointed at a stack running locally. The +SDK exports OTLP over HTTP, which the local collector receives on port 4318 — not +4317, which is the gRPC port other SDKs use: + +```bash +export OTEL_EXPORTER_OTLP_ENDPOINT=http://localhost:4318 +export LAUNCHDARKLY_SDK_KEY="key-from-the-local-project" +``` + +Data is attributed to the project the SDK key belongs to, so this has to be a key +from the local stack rather than a real one, or the errors land somewhere you are +not looking. + +Then start the example and record one error of each shape: + +```bash +go run ./cmd/http & +until curl -s -o /dev/null localhost:8080/; do sleep 1; done +for route in plain stack wrapped goroutine; do curl -s "localhost:8080/error/$route"; done +``` + +The example is waited for because it has to compile and then wait for the +LaunchDarkly client before it starts serving. The errors reach the local backend a +few seconds later, once the SDK batches its spans out, and appear in the errors UI +as four separate error groups. + +What to look for on each of them: + +- The first frame is the application's own code. It should never be + `RecordError`, `recordSpanError` or anything else belonging to the SDK. +- Frames read as `package.(*Receiver).Method`, and a closure reads as + `Method.func1` rather than as a bare number. +- Each frame shows the source line that ran with the lines around it. A frame + reporting no source at all is expected for any code whose file is not on this + machine, which for a Go binary is the normal case anywhere but a dev box. + +If nothing arrives, the example logs its export failures, so check its output +first: a wrong port shows up there as `connection refused`. + ## Examples This project contains several examples, each demonstrating the LaunchDarkly Observability plugin with different Go frameworks and libraries: @@ -100,6 +142,10 @@ go run cmd/http/http.go **Endpoints:** - `GET /rolldice` - Rolls a dice and returns the result, with verbose output controlled by the `verbose-response` feature flag +- `GET /error/plain` - Records an error with no stack of its own, so the SDK has to capture one. The reported frames should start at the handler's helper, not inside the SDK +- `GET /error/stack` - Records a `pkg/errors` error, whose stack was captured where the error was created, three calls below the handler +- `GET /error/wrapped` - Records a wrapped error. The frames should reach the root cause, not stop at the wrap +- `GET /error/goroutine` - Records an error raised in nested closures on another goroutine, with no span to attach it to ### 5. Logrus Example (`cmd/logrus/`) @@ -143,4 +189,3 @@ go run cmd/preinit/preinit.go - Advanced initialization scenarios where you need observability before the LaunchDarkly client - Using observability features without a LaunchDarkly client (some features will be unavailable) - Custom initialization timing requirements - \ No newline at end of file diff --git a/e2e/go-plugin/cmd/http/http.go b/e2e/go-plugin/cmd/http/http.go index a853fd7523..a1dcd288fa 100644 --- a/e2e/go-plugin/cmd/http/http.go +++ b/e2e/go-plugin/cmd/http/http.go @@ -19,6 +19,7 @@ import ( appcontext "dice/internal/context" "dice/internal/dice" + "dice/internal/failure" "dice/internal/version" ) @@ -33,14 +34,21 @@ func run() (err error) { ctx, stop := signal.NotifyContext(context.Background(), os.Interrupt) defer stop() + options := []ldobserve.Option{ + ldobserve.WithEnvironment("test"), + ldobserve.WithServiceName("go-plugin-example"), + ldobserve.WithServiceVersion(version.Commit), + } + // The SDK sets its endpoint explicitly, so the standard environment variable + // has to be applied by hand for this example to reach a local stack. + if endpoint := os.Getenv("OTEL_EXPORTER_OTLP_ENDPOINT"); endpoint != "" { + options = append(options, ldobserve.WithOTLPEndpoint(endpoint)) + } + client, _ := ld.MakeCustomClient(os.Getenv("LAUNCHDARKLY_SDK_KEY"), ld.Config{ Plugins: []ldplugins.Plugin{ - ldobserve.NewObservabilityPlugin( - ldobserve.WithEnvironment("test"), - ldobserve.WithServiceName("go-plugin-example"), - ldobserve.WithServiceVersion(version.Commit), - ), + ldobserve.NewObservabilityPlugin(options...), }, }, 5*time.Second) @@ -92,6 +100,10 @@ func newHTTPHandler() http.Handler { // Register handlers.Als handleFunc("/rolldice", dice.Rolldice) + handleFunc("/error/plain", failure.Plain) + handleFunc("/error/stack", failure.WithStack) + handleFunc("/error/wrapped", failure.Wrapped) + handleFunc("/error/goroutine", failure.InGoroutine) // Add HTTP instrumentation for the whole server. handler := otelhttp.NewHandler( diff --git a/e2e/go-plugin/internal/failure/failure.go b/e2e/go-plugin/internal/failure/failure.go new file mode 100644 index 0000000000..0a1609f432 --- /dev/null +++ b/e2e/go-plugin/internal/failure/failure.go @@ -0,0 +1,113 @@ +// Package failure records the error shapes the SDK has to describe, so that the +// frames and source context reaching the UI can be checked against a running +// application rather than only a unit test. +package failure + +import ( + "context" + "fmt" + "io" + "log" + "net/http" + "sync" + + "github.com/pkg/errors" + + ldobserve "github.com/launchdarkly/observability-sdk/go" +) + +// workerSettings stands in for configuration loaded at startup. The missing +// timeout is what every route here trips over, so the source lines reported for +// the innermost frame are the same few lines of real code each time. +var workerSettings = map[string]int{"retries": 3} + +// Plain records an error that carries no stack of its own, which is what +// fmt.Errorf and the standard errors package produce. The SDK has to capture a +// stack while recording, so the innermost frame should be readTimeout below +// rather than the SDK's own recording code. +func Plain(w http.ResponseWriter, r *http.Request) { + if _, err := readTimeout(); err != nil { + ldobserve.RecordError(r.Context(), err) + respond(w, "recorded an error with no stack of its own") + return + } + respond(w, "worker config was complete, nothing to record") +} + +func readTimeout() (int, error) { + timeout, ok := workerSettings["timeout"] + if !ok { + return 0, fmt.Errorf("worker config has no timeout") + } + return timeout, nil +} + +// WithStack records an error from pkg/errors, which captures a stack when the +// error is created. The SDK reports that stack instead of the one it could +// capture here, so the frames should start at connectWorker, three calls below +// this handler. +func WithStack(w http.ResponseWriter, r *http.Request) { + if _, err := startWorker(); err != nil { + ldobserve.RecordError(r.Context(), err) + respond(w, "recorded an error carrying its own stack") + return + } + respond(w, "worker started, nothing to record") +} + +func startWorker() (int, error) { + return connectWorker() +} + +func connectWorker() (int, error) { + timeout, ok := workerSettings["timeout"] + if !ok { + return 0, errors.New("worker config has no timeout") + } + return timeout, nil +} + +// Wrapped records a wrapped error, Go's answer to a chained exception: one error +// for the root cause and another for the context around it. Both messages belong +// in the text stack trace, and the frames come from where the cause was created. +func Wrapped(w http.ResponseWriter, r *http.Request) { + if err := runWorker(); err != nil { + ldobserve.RecordError(r.Context(), err) + respond(w, "recorded a wrapped error") + return + } + respond(w, "worker ran, nothing to record") +} + +func runWorker() error { + if _, err := connectWorker(); err != nil { + return errors.Wrap(err, "could not start worker") + } + return nil +} + +// InGoroutine records an error from nested closures on another goroutine, the +// shape whose frames used to arrive named after bare ordinals ("2") or with a +// trailing "in goroutine N". Nothing carries the request span onto that +// goroutine, so the SDK also has to start a span of its own here. +func InGoroutine(w http.ResponseWriter, r *http.Request) { + var workers sync.WaitGroup + workers.Add(1) + go func() { + defer workers.Done() + func() { + if _, err := connectWorker(); err != nil { + ldobserve.RecordError(context.Background(), errors.Wrap(err, "worker goroutine failed")) + } + }() + }() + workers.Wait() + + respond(w, "recorded an error raised on another goroutine") +} + +func respond(w http.ResponseWriter, message string) { + if _, err := io.WriteString(w, message+"\n"); err != nil { + log.Printf("Write failed: %v\n", err) + } +} diff --git a/go/singleton.go b/go/singleton.go index e1501c139c..4280ecad10 100644 --- a/go/singleton.go +++ b/go/singleton.go @@ -5,7 +5,6 @@ import ( "fmt" "reflect" - "github.com/pkg/errors" "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/log" semconv "go.opentelemetry.io/otel/semconv/v1.34.0" @@ -39,6 +38,13 @@ func EndSpan(span trace.Span) { // If there is no active recording span, then a new span is created and the error is recorded in it. // If this function starts a span, then that span will be ended after the error is recorded. func RecordError(ctx context.Context, err error, tags ...attribute.KeyValue) context.Context { + if err == nil { + // Nothing to record, as in the other SDKs. Recording used to reach + // span.RecordError, which ignores a nil error but only after a span had + // been started for it. + return ctx + } + span := trace.SpanFromContext(ctx) if span.IsRecording() { recordSpanError(span, err, tags...) @@ -56,22 +62,33 @@ func RecordError(ctx context.Context, err error, tags ...attribute.KeyValue) con } func recordSpanError(span trace.Span, err error, tags ...attribute.KeyValue) { - type withStackTrace interface { - StackTrace() errors.StackTrace - } - - if stackErr, ok := err.(withStackTrace); ok { - stackTrace := fmt.Sprintf("%+v", stackErr.StackTrace()) - attributes := make([]attribute.KeyValue, 0, 3+len(tags)) + // A stack the error carries was captured where the error was created, which + // is closer to the failure than anything this function could capture. + if stack, ok := stackTraceOf(err); ok { + stackTrace := fmt.Sprintf("%+v", stack) + attributes := make([]attribute.KeyValue, 0, 4+len(tags)) attributes = append(attributes, semconv.ExceptionTypeKey.String(reflect.TypeOf(err).String()), semconv.ExceptionMessageKey.String(err.Error()), semconv.ExceptionStacktraceKey.String(stackTrace), ) + carried := structuredFrames(callersFromStackTrace(stack), err.Error()) + if structured, ok := structuredStacktraceAttribute(carried); ok { + attributes = append(attributes, structured) + } attributes = append(attributes, tags...) span.AddEvent(semconv.ExceptionEventName, trace.WithAttributes(attributes...)) } else { - span.RecordError(err, trace.WithStackTrace(true)) + options := []trace.EventOption{trace.WithStackTrace(true)} + attributes := make([]attribute.KeyValue, 0, 1+len(tags)) + if structured, ok := structuredStacktraceAttribute(framesAtRecordTime(err.Error())); ok { + attributes = append(attributes, structured) + } + attributes = append(attributes, tags...) + if len(attributes) > 0 { + options = append(options, trace.WithAttributes(attributes...)) + } + span.RecordError(err, options...) } } diff --git a/go/stacktrace.go b/go/stacktrace.go new file mode 100644 index 0000000000..b45f7e2450 --- /dev/null +++ b/go/stacktrace.go @@ -0,0 +1,261 @@ +package ldobserve + +import ( + "bufio" + "encoding/json" + "os" + "runtime" + "strings" + "unicode/utf8" + + "github.com/pkg/errors" + "go.opentelemetry.io/otel/attribute" +) + +// exceptionStructuredStacktraceKey holds the frames of an error as JSON, +// including the source lines around each reported line. Ingestion prefers it +// over the text stack trace in exception.stacktrace, which has nowhere to put +// source and which a Go trace is only readable enough to guess at. +const exceptionStructuredStacktraceKey = "exception.structured_stacktrace" + +const ( + // Lines of context on each side of the reported line. Matches the window the + // backend produces for the languages it symbolicates itself. + sourceContextLines = 5 + // Longest source line reported, matching the backend's own limit. Longer + // lines are cut rather than dropped. + maxSourceLineLength = 1000 + // Longest source line read at all. A line this long is generated code, and + // reading it costs more than the context is worth. + maxSourceLineBuffer = 1 << 20 + // Frames reported. Matches the backend's frame cap: it keeps the leading + // frames and drops the rest, so anything past this is discarded on arrival. + maxStructuredFrames = 64 + // Depth captured when the error carries no stack of its own. Deeper than the + // frames reported, so that dropping the instrumentation frames below still + // leaves a full trace. + maxCallers = maxStructuredFrames + 16 +) + +// instrumentationPackages are the packages that do the recording. Their frames +// sit on top of a stack captured at record time and describe the recording, not +// the failure: they are why an OTeL-captured Go trace opens with +// recordStackTrace and RecordError rather than with the code that broke. +// +//nolint:gochecknoglobals +var instrumentationPackages = []string{ + "github.com/launchdarkly/observability-sdk/go", + "go.opentelemetry.io/otel", +} + +// structuredFrame is one frame as ingestion expects it. The JSON names are the +// GraphQL ones and have to stay in step with the backend's ErrorTrace. +type structuredFrame struct { + FileName string `json:"fileName,omitempty"` + LineNumber int `json:"lineNumber,omitempty"` + FunctionName string `json:"functionName,omitempty"` + Error string `json:"error,omitempty"` + LinesBefore string `json:"linesBefore,omitempty"` + LineContent string `json:"lineContent,omitempty"` + LinesAfter string `json:"linesAfter,omitempty"` +} + +// structuredStacktraceAttribute encodes frames as the attribute ingestion reads. +// It reports false when there is nothing to describe, leaving the error to be +// recorded with its text stack trace alone. +func structuredStacktraceAttribute(frames []structuredFrame) (attribute.KeyValue, bool) { + if len(frames) == 0 { + return attribute.KeyValue{}, false + } + encoded, marshalErr := json.Marshal(frames) + if marshalErr != nil { + return attribute.KeyValue{}, false + } + return attribute.String(exceptionStructuredStacktraceKey, string(encoded)), true +} + +// stackTraceOf returns the stack of the innermost error in the chain that +// carries one. +// +// Wrapping captures a stack at every wrap, and the innermost is the one taken +// closest to the failure: it names the call that actually went wrong, which the +// wrap sites above it no longer reach. Taking the outermost instead loses the +// root cause, in the same way that reporting only the last exception of a +// Python chain does. +func stackTraceOf(err error) (errors.StackTrace, bool) { + type withStackTrace interface { + StackTrace() errors.StackTrace + } + + var deepest errors.StackTrace + for wrapped := err; wrapped != nil; wrapped = errors.Unwrap(wrapped) { + // An empty stack describes nothing, so it leaves the one found above it + // in place rather than replacing it. + if carrier, ok := wrapped.(withStackTrace); ok { + if stack := carrier.StackTrace(); len(stack) > 0 { + deepest = stack + } + } + } + return deepest, len(deepest) > 0 +} + +// callersFromStackTrace converts the stack an error captured when it was created +// into program counters. Those counters are the values runtime.Callers returned +// at that point, so they can be resolved the same way as a fresh capture. +func callersFromStackTrace(stack errors.StackTrace) []uintptr { + callers := make([]uintptr, 0, len(stack)) + for _, frame := range stack { + callers = append(callers, uintptr(frame)) + } + return callers +} + +// framesAtRecordTime describes the stack of the caller, for an error that +// carries no stack of its own. +// +// The frames on top of that stack are this SDK and the OTeL API doing the +// recording; they say nothing about the failure and are dropped, so the trace +// starts at the code that recorded the error. Only the leading run goes: once +// the stack reaches the application, a package of ours appearing again is a +// real caller. +// +// They are dropped from the resolved frames rather than from the counters, +// which also resolves the stack once instead of twice. runtime.Callers emits a +// counter per frame today, inlined calls included, but runtime.CallersFrames +// documents that several frames can share one counter -- so a counter index +// taken from a frame count is only as good as that behavior. +func framesAtRecordTime(message string) []structuredFrame { + callers := make([]uintptr, maxCallers) + // 2 skips runtime.Callers and this function. + captured := runtime.Callers(2, callers) + return framesFromCallers(callers[:captured], message, true) +} + +func isInstrumentationFunction(name string) bool { + for _, pkg := range instrumentationPackages { + if strings.HasPrefix(name, pkg+".") || strings.HasPrefix(name, pkg+"/") { + return true + } + } + return false +} + +// structuredFrames describes the stack an error carried. Every frame of it is +// reported: that stack was captured where the error was created, so all of it +// describes the failure and none of it is the recording. +func structuredFrames(callers []uintptr, message string) []structuredFrame { + return framesFromCallers(callers, message, false) +} + +// framesFromCallers resolves callers to frames, reading the source around each +// one where the file can be read. +func framesFromCallers( + callers []uintptr, message string, dropInstrumentation bool, +) []structuredFrame { + if len(callers) == 0 { + return nil + } + + frames := make([]structuredFrame, 0, len(callers)) + iterator := runtime.CallersFrames(callers) + instrumentation := dropInstrumentation + for len(frames) < maxStructuredFrames { + frame, more := iterator.Next() + instrumentation = instrumentation && isInstrumentationFunction(frame.Function) + if !instrumentation && (frame.Function != "" || frame.File != "") { + structured := structuredFrame{ + FileName: frame.File, + LineNumber: frame.Line, + FunctionName: shortFunctionName(frame.Function), + Error: message, + } + structured.LinesBefore, structured.LineContent, structured.LinesAfter = sourceContext(frame.File, frame.Line) + frames = append(frames, structured) + } + if !more { + break + } + } + return frames +} + +// shortFunctionName drops the module path from a fully qualified Go function +// name: "github.com/acme/worker.(*Kafka).Run.func1" becomes +// "worker.(*Kafka).Run.func1". The full path is too long to read in a frame, +// while the last segment alone is ambiguous for closures, where it is just an +// ordinal. +func shortFunctionName(name string) string { + if slash := strings.LastIndex(name, "/"); slash >= 0 { + return name[slash+1:] + } + return name +} + +// sourceContext returns the source around line in path, split the way the +// backend stores it: the lines before, the reported line, and the lines after. +// +// All three are empty when the source cannot be read, which is the normal case +// for a binary running without its source tree, a container built from scratch +// being the obvious one. Frames then carry what they always have. +func sourceContext(path string, line int) (before string, content string, after string) { + if path == "" || line <= 0 { + return "", "", "" + } + + first := line - sourceContextLines + if first < 1 { + first = 1 + } + lines, ok := readSourceLines(path, first, line+sourceContextLines) + if !ok { + return "", "", "" + } + + // The file can be shorter than the trace claims, if it changed since the + // binary was built. + reported := line - first + if reported >= len(lines) { + return "", "", "" + } + return strings.Join(lines[:reported], "\n"), lines[reported], strings.Join(lines[reported+1:], "\n") +} + +// readSourceLines returns lines first through last of path, stopping at the end +// of the file. It reports false when the file cannot be read to that point, +// which covers a missing file, an unreadable one, and one whose lines are too +// long to be worth reading. +func readSourceLines(path string, first, last int) ([]string, bool) { + //nolint:gosec // The path is one the runtime reported for a frame, not input. + file, err := os.Open(path) + if err != nil { + return nil, false + } + defer func() { _ = file.Close() }() + + scanner := bufio.NewScanner(file) + scanner.Buffer(nil, maxSourceLineBuffer) + + lines := make([]string, 0, last-first+1) + for number := 1; number <= last && scanner.Scan(); number++ { + if number >= first { + lines = append(lines, truncateSourceLine(scanner.Text())) + } + } + if scanner.Err() != nil { + return nil, false + } + return lines, true +} + +func truncateSourceLine(line string) string { + if len(line) <= maxSourceLineLength { + return line + } + // Cutting a fixed number of bytes can land inside a rune. + truncated := line[:maxSourceLineLength] + for len(truncated) > 0 && !utf8.ValidString(truncated) { + truncated = truncated[:len(truncated)-1] + } + return truncated +} diff --git a/go/stacktrace_record_test.go b/go/stacktrace_record_test.go new file mode 100644 index 0000000000..9d4f474c19 --- /dev/null +++ b/go/stacktrace_record_test.go @@ -0,0 +1,139 @@ +// This file is in the external test package on purpose: frames belonging to the +// SDK are dropped from the top of a recorded stack, so a test that wants to see +// itself reported has to sit outside the SDK, exactly where an application does. +package ldobserve_test + +import ( + "context" + "encoding/json" + "fmt" + "strings" + "testing" + + sdktrace "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/sdk/trace/tracetest" + semconv "go.opentelemetry.io/otel/semconv/v1.34.0" + + ldobserve "github.com/launchdarkly/observability-sdk/go" +) + +// frame mirrors the frame shape the SDK sends, so the test reads the payload the +// backend will read rather than the struct that produced it. +type frame struct { + FileName string `json:"fileName"` + LineNumber int `json:"lineNumber"` + FunctionName string `json:"functionName"` + Error string `json:"error"` + LinesBefore string `json:"linesBefore"` + LineContent string `json:"lineContent"` + LinesAfter string `json:"linesAfter"` +} + +// recordPlainError records an error that carries no stack of its own, so the SDK +// has to capture one here. +func recordPlainError(ctx context.Context) { + ldobserve.RecordError(ctx, fmt.Errorf("plain failure")) +} + +func recordedFrames(t *testing.T) []frame { + t.Helper() + + exporter := tracetest.NewInMemoryExporter() + provider := sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(sdktrace.NewSimpleSpanProcessor(exporter))) + defer provider.Shutdown(context.Background()) + + ctx, span := provider.Tracer("test").Start(context.Background(), "test-span") + recordPlainError(ctx) + span.End() + + spans := exporter.GetSpans() + if len(spans) != 1 { + t.Fatalf("expected 1 span, got %d", len(spans)) + } + events := spans[0].Events + if len(events) != 1 || events[0].Name != semconv.ExceptionEventName { + t.Fatalf("expected a single exception event, got %v", events) + } + + var payload string + for _, attr := range events[0].Attributes { + if attr.Key == "exception.structured_stacktrace" { + payload = attr.Value.AsString() + } + } + if payload == "" { + t.Fatal("expected the event to carry a structured stack trace") + } + + var frames []frame + if err := json.Unmarshal([]byte(payload), &frames); err != nil { + t.Fatalf("could not decode frames: %v", err) + } + if len(frames) == 0 { + t.Fatal("expected at least one frame") + } + return frames +} + +// The frames of the recording itself say nothing about the failure, and used to +// be all the top of a Go trace had to offer. +func TestRecordErrorReportsTheCallerFirst(t *testing.T) { + frames := recordedFrames(t) + + if !strings.HasSuffix(frames[0].FunctionName, ".recordPlainError") { + t.Errorf("expected the recording caller as the first frame, got %q", frames[0].FunctionName) + } + for _, f := range frames { + if strings.HasSuffix(f.FileName, "singleton.go") || strings.HasSuffix(f.FileName, "stacktrace.go") { + t.Errorf("expected no SDK frames, got %q in %q", f.FunctionName, f.FileName) + } + if strings.Contains(f.FileName, "go.opentelemetry.io") { + t.Errorf("expected no OTeL frames, got %q in %q", f.FunctionName, f.FileName) + } + } +} + +// Recording a nil error is a no-op in the other SDKs, and used to be one here +// too: it reached span.RecordError, which ignores it. Building a structured +// stack trace for every error put an err.Error() in front of that. +func TestRecordErrorIgnoresANilError(t *testing.T) { + exporter := tracetest.NewInMemoryExporter() + provider := sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(sdktrace.NewSimpleSpanProcessor(exporter))) + defer provider.Shutdown(context.Background()) + + ctx, span := provider.Tracer("test").Start(context.Background(), "test-span") + ldobserve.RecordError(ctx, nil) + span.End() + + // Recording without a span in the context is the other path, and starts one + // of its own. Neither may panic. + ldobserve.RecordError(context.Background(), nil) + + spans := exporter.GetSpans() + if len(spans) != 1 { + t.Fatalf("expected 1 span, got %d", len(spans)) + } + if len(spans[0].Events) != 0 { + t.Errorf("expected nothing to be recorded, got %v", spans[0].Events) + } +} + +func TestRecordErrorReportsSourceContext(t *testing.T) { + frames := recordedFrames(t) + + if !strings.HasSuffix(frames[0].FileName, "stacktrace_record_test.go") { + t.Errorf("expected the frame to point at this file, got %q", frames[0].FileName) + } + if !strings.Contains(frames[0].LineContent, `fmt.Errorf("plain failure")`) { + t.Errorf("expected the reported line to be the recorded one, got %q", frames[0].LineContent) + } + if !strings.Contains(frames[0].LinesBefore, "func recordPlainError(ctx context.Context) {") { + t.Errorf("expected the lines before to include the function signature, got %q", frames[0].LinesBefore) + } + if frames[0].LinesAfter == "" { + t.Error("expected lines after the reported line") + } + if frames[0].Error != "plain failure" { + t.Errorf("expected the frame to carry the error message, got %q", frames[0].Error) + } +} diff --git a/go/stacktrace_test.go b/go/stacktrace_test.go new file mode 100644 index 0000000000..6ed200fbf9 --- /dev/null +++ b/go/stacktrace_test.go @@ -0,0 +1,300 @@ +package ldobserve + +import ( + "encoding/json" + "fmt" + "os" + "path/filepath" + "strings" + "testing" + + "github.com/pkg/errors" +) + +// failInHelper returns an error carrying the stack of the line below, so that a +// frame under test points at source this test can predict. +func failInHelper() error { + return errors.New("boom") +} + +func framesFrom(t *testing.T, err error, callers []uintptr) []structuredFrame { + t.Helper() + + attr, ok := structuredStacktraceAttribute(structuredFrames(callers, err.Error())) + if !ok { + t.Fatal("expected a structured stack trace") + } + var frames []structuredFrame + if err := json.Unmarshal([]byte(attr.Value.AsString()), &frames); err != nil { + t.Fatalf("could not decode frames: %v", err) + } + if len(frames) == 0 { + t.Fatal("expected at least one frame") + } + return frames +} + +func numberedFile(t *testing.T, lines int) string { + t.Helper() + + var content strings.Builder + for line := 1; line <= lines; line++ { + fmt.Fprintf(&content, "line %d\n", line) + } + path := filepath.Join(t.TempDir(), "source.go") + if err := os.WriteFile(path, []byte(content.String()), 0o600); err != nil { + t.Fatalf("could not write source: %v", err) + } + return path +} + +func TestStructuredStacktraceUsesTheStackTheErrorCarries(t *testing.T) { + err := failInHelper() + stack, ok := stackTraceOf(err) + if !ok { + t.Fatal("expected the error to carry a stack") + } + + frames := framesFrom(t, err, callersFromStackTrace(stack)) + + // The stack was captured where the error was created, so the innermost frame + // is the helper rather than this test. + if !strings.HasSuffix(frames[0].FunctionName, ".failInHelper") { + t.Errorf("expected the innermost frame to be failInHelper, got %q", frames[0].FunctionName) + } + if !strings.HasSuffix(frames[0].FileName, "stacktrace_test.go") { + t.Errorf("expected the frame to point at this file, got %q", frames[0].FileName) + } + if frames[0].Error != "boom" { + t.Errorf("expected the frame to carry the error message, got %q", frames[0].Error) + } + if len(frames) < 2 { + t.Fatalf("expected the caller to be reported too, got %d frame(s)", len(frames)) + } + if !strings.HasSuffix(frames[1].FunctionName, ".TestStructuredStacktraceUsesTheStackTheErrorCarries") { + t.Errorf("expected the caller as the second frame, got %q", frames[1].FunctionName) + } +} + +// Wrapping captures a stack at every wrap, and only the innermost one reaches +// the call that failed. Reporting the outermost would drop the root cause, which +// is the whole point of having wrapped the error. +func TestStructuredStacktracePrefersTheInnermostStack(t *testing.T) { + err := errors.Wrap(failInHelper(), "could not start the worker") + + stack, ok := stackTraceOf(err) + if !ok { + t.Fatal("expected a stack somewhere in the chain") + } + frames := framesFrom(t, err, callersFromStackTrace(stack)) + + if !strings.HasSuffix(frames[0].FunctionName, ".failInHelper") { + t.Errorf("expected the root cause frame first, got %q", frames[0].FunctionName) + } + if frames[0].Error != "could not start the worker: boom" { + t.Errorf("expected the frame to carry the whole chain's message, got %q", frames[0].Error) + } +} + +// Wrapping with %w carries no stack of its own, so the chain has to be followed +// past it to find one. +func TestStructuredStacktraceLooksPastStandardWrapping(t *testing.T) { + err := fmt.Errorf("loading worker config: %w", failInHelper()) + + stack, ok := stackTraceOf(err) + if !ok { + t.Fatal("expected a stack somewhere in the chain") + } + frames := framesFrom(t, err, callersFromStackTrace(stack)) + + if !strings.HasSuffix(frames[0].FunctionName, ".failInHelper") { + t.Errorf("expected the root cause frame first, got %q", frames[0].FunctionName) + } +} + +// emptyStackError carries a StackTrace method that describes nothing, as an +// error type can when it captured no frames. +type emptyStackError struct{} + +func (emptyStackError) Error() string { return "boom" } + +func (emptyStackError) StackTrace() errors.StackTrace { return nil } + +func TestStructuredStacktraceKeepsAnOuterStackOverAnEmptyInnerOne(t *testing.T) { + err := errors.Wrap(emptyStackError{}, "could not start the worker") + + stack, ok := stackTraceOf(err) + if !ok { + t.Fatal("expected the wrap's stack to be used") + } + frames := framesFrom(t, err, callersFromStackTrace(stack)) + + if !strings.HasSuffix(frames[0].FunctionName, ".TestStructuredStacktraceKeepsAnOuterStackOverAnEmptyInnerOne") { + t.Errorf("expected the wrap site as the innermost frame, got %q", frames[0].FunctionName) + } +} + +func TestStructuredStacktraceIgnoresAnErrorWithoutAStack(t *testing.T) { + if _, ok := stackTraceOf(fmt.Errorf("no stack here")); ok { + t.Error("expected no stack to be found") + } +} + +func TestStructuredStacktraceReadsSourceAroundTheFrame(t *testing.T) { + err := failInHelper() + stack, _ := stackTraceOf(err) + + frame := framesFrom(t, err, callersFromStackTrace(stack))[0] + + if strings.TrimSpace(frame.LineContent) != `return errors.New("boom")` { + t.Errorf("expected the reported line to be the failing one, got %q", frame.LineContent) + } + // Indentation is kept, so the source reads as written. + if !strings.HasPrefix(frame.LineContent, "\t") { + t.Errorf("expected the reported line to keep its indentation, got %q", frame.LineContent) + } + before := strings.Split(frame.LinesBefore, "\n") + if last := before[len(before)-1]; last != "func failInHelper() error {" { + t.Errorf("expected the line before to be the function signature, got %q", last) + } + if first := strings.SplitN(frame.LinesAfter, "\n", 2)[0]; first != "}" { + t.Errorf("expected the line after to close the function, got %q", first) + } +} + +func TestSourceContextReportsAWindowOnEachSide(t *testing.T) { + path := numberedFile(t, 20) + + before, content, after := sourceContext(path, 10) + + if content != "line 10" { + t.Errorf("expected line 10, got %q", content) + } + if want := "line 5\nline 6\nline 7\nline 8\nline 9"; before != want { + t.Errorf("expected %q before, got %q", want, before) + } + if want := "line 11\nline 12\nline 13\nline 14\nline 15"; after != want { + t.Errorf("expected %q after, got %q", want, after) + } +} + +func TestSourceContextStopsAtTheEdgesOfTheFile(t *testing.T) { + path := numberedFile(t, 6) + + before, content, after := sourceContext(path, 2) + if content != "line 2" || before != "line 1" { + t.Errorf("expected the window to start at the first line, got %q before %q", before, content) + } + if want := "line 3\nline 4\nline 5\nline 6"; after != want { + t.Errorf("expected %q after, got %q", want, after) + } + + before, content, after = sourceContext(path, 6) + if content != "line 6" || after != "" { + t.Errorf("expected nothing after the last line, got %q after %q", after, content) + } + if want := "line 1\nline 2\nline 3\nline 4\nline 5"; before != want { + t.Errorf("expected %q before, got %q", want, before) + } +} + +// A binary outlives the source it was built from, so a frame can name a line +// that no longer exists. +func TestSourceContextIgnoresALineBeyondTheFile(t *testing.T) { + before, content, after := sourceContext(numberedFile(t, 6), 25) + + if before != "" || content != "" || after != "" { + t.Errorf("expected no source, got %q %q %q", before, content, after) + } +} + +// The normal case for a compiled binary: the source is not on the host. +func TestSourceContextIgnoresAMissingFile(t *testing.T) { + before, content, after := sourceContext(filepath.Join(t.TempDir(), "absent.go"), 3) + + if before != "" || content != "" || after != "" { + t.Errorf("expected no source, got %q %q %q", before, content, after) + } +} + +func TestSourceContextIgnoresAFrameWithoutAFile(t *testing.T) { + if before, content, after := sourceContext("", 3); before != "" || content != "" || after != "" { + t.Errorf("expected no source for an empty path, got %q %q %q", before, content, after) + } + if before, content, after := sourceContext("/tmp/whatever.go", 0); before != "" || content != "" || after != "" { + t.Errorf("expected no source for an unknown line, got %q %q %q", before, content, after) + } +} + +func TestTruncateSourceLine(t *testing.T) { + short := "package main" + if got := truncateSourceLine(short); got != short { + t.Errorf("expected a short line to be kept, got %q", got) + } + + long := truncateSourceLine(strings.Repeat("a", maxSourceLineLength+10)) + if len(long) != maxSourceLineLength { + t.Errorf("expected a long line to be cut to %d bytes, got %d", maxSourceLineLength, len(long)) + } + + // The cut lands inside the last rune, which has to be dropped whole. + runes := strings.Repeat("ф", maxSourceLineLength) + cut := truncateSourceLine(runes) + if len(cut) > maxSourceLineLength { + t.Errorf("expected at most %d bytes, got %d", maxSourceLineLength, len(cut)) + } + if !strings.HasPrefix(runes, cut) || strings.ContainsRune(cut, '\uFFFD') { + t.Errorf("expected a valid prefix of the line, got %q", cut) + } +} + +func TestShortFunctionName(t *testing.T) { + for _, tc := range []struct{ name, expected string }{ + {"github.com/acme/worker.(*Kafka).Run", "worker.(*Kafka).Run"}, + {"github.com/acme/worker.(*Kafka).Run.func1.2", "worker.(*Kafka).Run.func1.2"}, + {"net/http.HandlerFunc.ServeHTTP", "http.HandlerFunc.ServeHTTP"}, + {"main.main", "main.main"}, + {"", ""}, + } { + if got := shortFunctionName(tc.name); got != tc.expected { + t.Errorf("shortFunctionName(%q) = %q, expected %q", tc.name, got, tc.expected) + } + } +} + +func TestIsInstrumentationFunction(t *testing.T) { + for _, name := range []string{ + "github.com/launchdarkly/observability-sdk/go.RecordError", + "github.com/launchdarkly/observability-sdk/go/internal/otel.GetTracer", + "go.opentelemetry.io/otel/sdk/trace.(*recordingSpan).RecordError", + } { + if !isInstrumentationFunction(name) { + t.Errorf("expected %q to be recording machinery", name) + } + } + for _, name := range []string{ + // The external test package for this SDK, and anything else that merely + // starts the same way, is application code. + "github.com/launchdarkly/observability-sdk/go_test.TestRecordError", + "github.com/acme/worker.(*Kafka).Run", + "main.main", + } { + if isInstrumentationFunction(name) { + t.Errorf("expected %q to be application code", name) + } + } +} + +// Every function in this package is recording machinery by the same rule that +// applies to the SDK proper, so a stack captured here holds nothing else until +// it reaches the test harness underneath. +func TestFramesAtRecordTimeDropsTheRecordingFrames(t *testing.T) { + frames := framesAtRecordTime("boom") + + if len(frames) == 0 { + t.Fatal("expected the frames beneath the recording to survive") + } + if frames[0].FunctionName != "testing.tRunner" { + t.Errorf("expected the first frame beneath this package, got %q", frames[0].FunctionName) + } +}