Files
JMR-devandClaude Opus 4.8 45ac7236ee #17 Observability: OpenTelemetry logging + tracing + alerting
Instrument the Worker with OpenTelemetry traces + structured logs over OTLP,
plus alertable signals, via a minimal hand-rolled OTLP/HTTP exporter that fits
the TinyGo/Wasm Worker build.

New internal/telemetry package (build-tag-free, host-tested):
- Span/log shim: Telemetry provider, Span (attrs/status/events/end), Log
  (Info/Warn/Error), trace/span-id correlation, W3C-style ids from crypto/rand.
- Exporter seam: MemoryExporter (in-memory, for tests) and OTLPHTTPExporter
  (OTLP/HTTP JSON over net/http). No go.opentelemetry.io/otel/sdk dependency:
  the full OTEL-Go SDK + OTLP exporters pull in a large, reflection-heavy tree
  (protobuf, grpc) that bloats the Wasm binary and is unreliable under TinyGo.
  The shim uses only stdlib already proven under this project's js/wasm target
  (net/http per #26, encoding/json, crypto/rand). OTLP is the wire format, so
  any OTLP backend can ingest it.
- Behaviour-preserving by construction: instrumentation is threaded through
  context. Instrumented code pulls an optional *Telemetry from ctx; absent (or
  nil exporter) => every method is a no-op. No public signatures change
  (NewHandler, handler.New, publish.New/Publish, schedule.Run are untouched), so
  parallel work built on the current APIs keeps compiling.

Instrumentation:
- ingest: an "ingest.request" server span + correlated log per request,
  classifying accepted / rejected / rate_limited / error. Observe-only (wraps the
  response writer to read the status); the HTTP contract is unchanged. A 5xx
  (e.g. 503 storage-unavailable) sets the span to Error and emits the alertable
  ingest.error signal; 4xx client rejections are INFO, not alerts.
- publish: a "publish.run" span with per-report "publish.report" child spans and
  a log per report (published/failed). A failed report/run sets Error and emits
  alert.type=publish.run_failed. The per-run cap-hit (folding in the #14
  follow-up) is now emitted as a structured, alertable OTEL signal
  (alert.type=publish.cap_hit + counts), not merely a log line.
- schedule: a "schedule.run" span parenting the publish run; a list/publish
  failure emits alert.type=schedule.run_failed.

Config (OTLP endpoint TBD, issue #17):
- OTEL_EXPORTER_OTLP_ENDPOINT (plain var) - base OTLP/HTTP URL; empty => telemetry
  disabled (Worker behaves as before). /v1/traces and /v1/logs are appended.
- OTEL_EXPORTER_OTLP_HEADERS (Secrets Store secret) - auth header(s), never
  committed. OTEL_SERVICE_NAME (plain var) - service.name override.
- worker/telemetry_wasm.go builds the exporter lazily per run and injects the
  provider into the request/scheduled context; wrangler.jsonc gains only these
  OTEL keys.

Alerting: run-failure, cap-hit, and elevated-ingest-error are emitted as span
status=Error and structured log records carrying alert=true + a specific
alert.type, so a backend alert rule can key on them once the OTLP endpoint is
chosen.

Tests: host unit tests with the in-memory exporter assert the ingest spans+logs
for accepted/rejected/error, the publish run span + per-report spans + the
cap-hit and run-failed signals, the schedule run span + list-error alert, and
the OTLP/JSON encoding + HTTP round trip (httptest, no real backend). No-op
default verified. go vet ./... and go test ./... green; GOOS=js GOARCH=wasm
go build ./... compiles.

Closes #17

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
2026-07-02 17:14:21 -05:00

142 lines
4.6 KiB
Go

package schedule_test
import (
"context"
"errors"
"testing"
"github.com/JMR-dev/LibreMail-Bug-Report-Ingest/internal/schedule"
"github.com/JMR-dev/LibreMail-Bug-Report-Ingest/internal/telemetry"
)
func telemetryCtx() (context.Context, *telemetry.MemoryExporter) {
exp := telemetry.NewMemoryExporter()
return telemetry.NewContext(context.Background(), telemetry.New(exp)), exp
}
// TestScheduleRunEmitsSpan: a gated run emits a schedule.run span (OK) plus a
// "weekly trigger fired" log recording the pending count.
func TestScheduleRunEmitsSpan(t *testing.T) {
want := []string{"a", "b"}
lister := &fakeLister{ids: want}
pub := &recordingPublisher{}
ctx, exp := telemetryCtx()
ran, err := schedule.Run(ctx, fireInstant, lister, pub)
if err != nil || !ran {
t.Fatalf("Run = (%v, %v), want (true, nil)", ran, err)
}
span, ok := exp.SpanByName("schedule.run")
if !ok {
t.Fatal("no schedule.run span")
}
if span.Status.Code != telemetry.StatusOK {
t.Errorf("span status = %d, want OK", span.Status.Code)
}
if v, _ := telemetry.Attr(span.Attributes, "schedule.pending"); v != int64(2) {
t.Errorf("schedule.pending = %v, want 2", v)
}
if _, ok := telemetry.Attr(span.Attributes, "schedule.scheduled_for"); !ok {
t.Errorf("span missing schedule.scheduled_for")
}
firedLog := false
for _, l := range exp.Logs() {
if l.Body == "schedule: weekly trigger fired" {
firedLog = true
if l.SpanContext != span.SpanContext {
t.Errorf("fired log not correlated to schedule.run span")
}
}
}
if !firedLog {
t.Errorf("no weekly-trigger-fired log")
}
}
// TestScheduleGateClosedEmitsNothing: the sibling (no-op) fire starts no span and
// emits no telemetry — matching its do-nothing contract.
func TestScheduleGateClosedEmitsNothing(t *testing.T) {
lister := &fakeLister{ids: []string{"x"}}
pub := &recordingPublisher{}
ctx, exp := telemetryCtx()
ran, err := schedule.Run(ctx, notFireInstant, lister, pub)
if err != nil || ran {
t.Fatalf("Run = (%v, %v), want (false, nil)", ran, err)
}
if len(exp.Spans()) != 0 || len(exp.Logs()) != 0 {
t.Errorf("gate-closed fire emitted telemetry: %d spans, %d logs", len(exp.Spans()), len(exp.Logs()))
}
}
// TestScheduleListErrorEmitsAlert: a list failure sets the span to Error, emits
// the alert.type=schedule.run_failed signal, and still returns the wrapped error.
func TestScheduleListErrorEmitsAlert(t *testing.T) {
sentinel := errors.New("r2 list failed")
lister := &fakeLister{err: sentinel}
pub := &recordingPublisher{}
ctx, exp := telemetryCtx()
ran, err := schedule.Run(ctx, fireInstant, lister, pub)
if !ran || !errors.Is(err, sentinel) {
t.Fatalf("Run = (%v, %v), want (true, wraps sentinel)", ran, err)
}
span, _ := exp.SpanByName("schedule.run")
if span.Status.Code != telemetry.StatusError {
t.Errorf("span status = %d, want Error", span.Status.Code)
}
found := false
for _, l := range exp.Logs() {
if v, _ := telemetry.Attr(l.Attributes, telemetry.AttrAlertType); v == "schedule.run_failed" {
found = true
if l.Severity != telemetry.SeverityError {
t.Errorf("alert log severity = %v, want ERROR", l.Severity)
}
}
}
if !found {
t.Errorf("no schedule.run_failed alert log")
}
if len(pub.batches) != 0 {
t.Errorf("publisher called despite a list error")
}
}
// TestScheduleRunParentsPublisher: the ctx handed to the publisher carries the
// schedule.run span, so a publish.run span started from it is a child — the trace
// links the scheduled run to the publish run end to end.
func TestScheduleRunParentsPublisher(t *testing.T) {
ctx, exp := telemetryCtx()
var childTrace telemetry.TraceID
var childParent telemetry.SpanID
spy := publisherFunc(func(pctx context.Context, _ []string) error {
tel := telemetry.FromContext(pctx)
_, span := tel.StartSpan(pctx, "publish.run")
childTrace = span.SpanContext().TraceID
sc, _ := telemetry.SpanContextFromContext(pctx)
childParent = sc.SpanID
span.End()
return nil
})
ran, err := schedule.Run(ctx, fireInstant, &fakeLister{ids: []string{"a"}}, spy)
if err != nil || !ran {
t.Fatalf("Run = (%v, %v), want (true, nil)", ran, err)
}
run, _ := exp.SpanByName("schedule.run")
if childTrace != run.SpanContext.TraceID {
t.Errorf("publisher's span trace %s != schedule.run trace %s", childTrace, run.SpanContext.TraceID)
}
if childParent != run.SpanContext.SpanID {
t.Errorf("ctx active span in publisher = %s, want schedule.run span %s", childParent, run.SpanContext.SpanID)
}
}
// publisherFunc adapts a function to schedule.Publisher.
type publisherFunc func(context.Context, []string) error
func (f publisherFunc) Publish(ctx context.Context, ids []string) error { return f(ctx, ids) }