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>
240 lines
7.1 KiB
Go
240 lines
7.1 KiB
Go
package telemetry
|
|
|
|
import (
|
|
"context"
|
|
"errors"
|
|
"testing"
|
|
"time"
|
|
)
|
|
|
|
// fixedClock returns a clock function yielding a fixed instant.
|
|
func fixedClock(t time.Time) func() time.Time { return func() time.Time { return t } }
|
|
|
|
// seqIDs returns deterministic id generators: trace ids 0x..01, 0x..02, ...;
|
|
// span ids likewise, so tests can assert exact correlation.
|
|
func seqIDs() (func() TraceID, func() SpanID) {
|
|
var tn, sn byte
|
|
return func() TraceID {
|
|
tn++
|
|
return TraceID{15: tn}
|
|
}, func() SpanID {
|
|
sn++
|
|
return SpanID{7: sn}
|
|
}
|
|
}
|
|
|
|
func testProvider(t *testing.T) (*Telemetry, *MemoryExporter) {
|
|
t.Helper()
|
|
exp := NewMemoryExporter()
|
|
nt, ns := seqIDs()
|
|
tel := New(exp,
|
|
WithClock(fixedClock(time.Unix(1_700_000_000, 0).UTC())),
|
|
WithIDGenerator(nt, ns))
|
|
return tel, exp
|
|
}
|
|
|
|
func TestStartSpanExportsSpanData(t *testing.T) {
|
|
tel, exp := testProvider(t)
|
|
ctx, span := tel.StartSpan(context.Background(), "ingest.request",
|
|
WithSpanKind(SpanKindServer),
|
|
WithAttributes(String("http.request.method", "POST")))
|
|
span.SetAttributes(Int("http.response.status_code", 202))
|
|
span.SetStatus(StatusOK, "")
|
|
span.End()
|
|
_ = ctx
|
|
|
|
spans := exp.Spans()
|
|
if len(spans) != 1 {
|
|
t.Fatalf("got %d spans, want 1", len(spans))
|
|
}
|
|
s := spans[0]
|
|
if s.Name != "ingest.request" {
|
|
t.Errorf("name = %q, want ingest.request", s.Name)
|
|
}
|
|
if s.Kind != SpanKindServer {
|
|
t.Errorf("kind = %d, want %d", s.Kind, SpanKindServer)
|
|
}
|
|
if !s.SpanContext.IsValid() {
|
|
t.Errorf("span context invalid: %+v", s.SpanContext)
|
|
}
|
|
if !s.ParentSpanID.IsZero() {
|
|
t.Errorf("root span should have zero parent, got %s", s.ParentSpanID)
|
|
}
|
|
if s.Status.Code != StatusOK {
|
|
t.Errorf("status = %d, want OK", s.Status.Code)
|
|
}
|
|
if v, ok := Attr(s.Attributes, "http.request.method"); !ok || v != "POST" {
|
|
t.Errorf("method attr = %v (present=%v), want POST", v, ok)
|
|
}
|
|
if v, ok := Attr(s.Attributes, "http.response.status_code"); !ok || v != int64(202) {
|
|
t.Errorf("status_code attr = %v (present=%v), want int64 202", v, ok)
|
|
}
|
|
}
|
|
|
|
func TestNestedSpanSharesTraceAndParents(t *testing.T) {
|
|
tel, exp := testProvider(t)
|
|
ctx, parent := tel.StartSpan(context.Background(), "publish.run")
|
|
_, child := tel.StartSpan(ctx, "publish.report")
|
|
child.End()
|
|
parent.End()
|
|
|
|
spans := exp.Spans()
|
|
if len(spans) != 2 {
|
|
t.Fatalf("got %d spans, want 2", len(spans))
|
|
}
|
|
// Export order: child ended first.
|
|
c, p := spans[0], spans[1]
|
|
if c.SpanContext.TraceID != p.SpanContext.TraceID {
|
|
t.Errorf("child/parent trace ids differ: %s vs %s", c.SpanContext.TraceID, p.SpanContext.TraceID)
|
|
}
|
|
if c.ParentSpanID != p.SpanContext.SpanID {
|
|
t.Errorf("child parent = %s, want parent span id %s", c.ParentSpanID, p.SpanContext.SpanID)
|
|
}
|
|
if p.SpanContext.SpanID == c.SpanContext.SpanID {
|
|
t.Errorf("child and parent share a span id: %s", c.SpanContext.SpanID)
|
|
}
|
|
}
|
|
|
|
func TestLogCorrelatesWithActiveSpan(t *testing.T) {
|
|
tel, exp := testProvider(t)
|
|
ctx, span := tel.StartSpan(context.Background(), "ingest.request")
|
|
tel.Info(ctx, "ingest request accepted", String("ingest.outcome", "accepted"))
|
|
span.End()
|
|
|
|
logs := exp.Logs()
|
|
if len(logs) != 1 {
|
|
t.Fatalf("got %d logs, want 1", len(logs))
|
|
}
|
|
l := logs[0]
|
|
if l.Severity != SeverityInfo {
|
|
t.Errorf("severity = %v, want INFO", l.Severity)
|
|
}
|
|
if l.Body != "ingest request accepted" {
|
|
t.Errorf("body = %q", l.Body)
|
|
}
|
|
if l.SpanContext != span.SpanContext() {
|
|
t.Errorf("log span context %+v != span %+v (not correlated)", l.SpanContext, span.SpanContext())
|
|
}
|
|
if v, ok := Attr(l.Attributes, "ingest.outcome"); !ok || v != "accepted" {
|
|
t.Errorf("outcome attr = %v (present=%v)", v, ok)
|
|
}
|
|
}
|
|
|
|
func TestLogWithoutSpanHasNoCorrelation(t *testing.T) {
|
|
tel, exp := testProvider(t)
|
|
tel.Warn(context.Background(), "standalone warning")
|
|
logs := exp.Logs()
|
|
if len(logs) != 1 {
|
|
t.Fatalf("got %d logs, want 1", len(logs))
|
|
}
|
|
if logs[0].SpanContext.IsValid() {
|
|
t.Errorf("log outside a span should not correlate, got %+v", logs[0].SpanContext)
|
|
}
|
|
if logs[0].Severity != SeverityWarn {
|
|
t.Errorf("severity = %v, want WARN", logs[0].Severity)
|
|
}
|
|
}
|
|
|
|
func TestRecordError(t *testing.T) {
|
|
tel, exp := testProvider(t)
|
|
_, span := tel.StartSpan(context.Background(), "op")
|
|
span.RecordError(errors.New("boom"))
|
|
span.End()
|
|
s := exp.Spans()[0]
|
|
if s.Status.Code != StatusError {
|
|
t.Errorf("status = %d, want Error", s.Status.Code)
|
|
}
|
|
if len(s.Events) != 1 || s.Events[0].Name != "exception" {
|
|
t.Fatalf("want one exception event, got %+v", s.Events)
|
|
}
|
|
if v, ok := Attr(s.Events[0].Attributes, "exception.message"); !ok || v != "boom" {
|
|
t.Errorf("exception.message = %v (present=%v)", v, ok)
|
|
}
|
|
}
|
|
|
|
// TestDisabledProviderIsNoop is the behaviour-preserving guarantee: a nil
|
|
// provider (what FromContext returns when telemetry is not configured) and a
|
|
// New(nil) provider must be fully no-op and never panic, and StartSpan must
|
|
// return the context unchanged so downstream behaviour is identical.
|
|
func TestDisabledProviderIsNoop(t *testing.T) {
|
|
for _, tc := range []struct {
|
|
name string
|
|
tel *Telemetry
|
|
}{
|
|
{"nil provider", nil},
|
|
{"nil exporter", New(nil)},
|
|
} {
|
|
t.Run(tc.name, func(t *testing.T) {
|
|
if tc.tel.Enabled() {
|
|
t.Fatal("provider should report disabled")
|
|
}
|
|
base := context.Background()
|
|
ctx, span := tc.tel.StartSpan(base, "op", WithSpanKind(SpanKindServer))
|
|
if ctx != base {
|
|
t.Error("disabled StartSpan must return the context unchanged")
|
|
}
|
|
if span != nil {
|
|
t.Error("disabled StartSpan must return a nil span")
|
|
}
|
|
// None of these must panic on the nil span / disabled provider.
|
|
span.SetAttributes(String("k", "v"))
|
|
span.SetStatus(StatusError, "x")
|
|
span.RecordError(errors.New("e"))
|
|
span.AddEvent("ev")
|
|
span.End()
|
|
if sc := span.SpanContext(); sc.IsValid() {
|
|
t.Error("nil span should have an invalid span context")
|
|
}
|
|
tc.tel.Info(ctx, "msg")
|
|
tc.tel.Warn(ctx, "msg")
|
|
tc.tel.Error(ctx, "msg")
|
|
})
|
|
}
|
|
}
|
|
|
|
func TestFromContextRoundTrip(t *testing.T) {
|
|
tel, _ := testProvider(t)
|
|
ctx := NewContext(context.Background(), tel)
|
|
if got := FromContext(ctx); got != tel {
|
|
t.Errorf("FromContext = %p, want %p", got, tel)
|
|
}
|
|
if got := FromContext(context.Background()); got != nil {
|
|
t.Errorf("FromContext on a bare context = %p, want nil", got)
|
|
}
|
|
}
|
|
|
|
func TestAlertHelper(t *testing.T) {
|
|
kvs := Alert("publish.cap_hit")
|
|
if len(kvs) != 2 {
|
|
t.Fatalf("Alert returned %d attrs, want 2", len(kvs))
|
|
}
|
|
if v, ok := Attr(kvs, AttrAlert); !ok || v != true {
|
|
t.Errorf("alert marker = %v (present=%v), want true", v, ok)
|
|
}
|
|
if v, ok := Attr(kvs, AttrAlertType); !ok || v != "publish.cap_hit" {
|
|
t.Errorf("alert.type = %v (present=%v)", v, ok)
|
|
}
|
|
}
|
|
|
|
func TestSeverityString(t *testing.T) {
|
|
for sev, want := range map[Severity]string{
|
|
SeverityInfo: "INFO",
|
|
SeverityWarn: "WARN",
|
|
SeverityError: "ERROR",
|
|
} {
|
|
if got := sev.String(); got != want {
|
|
t.Errorf("Severity(%d).String() = %q, want %q", sev, got, want)
|
|
}
|
|
}
|
|
}
|
|
|
|
func TestEndIsIdempotent(t *testing.T) {
|
|
tel, exp := testProvider(t)
|
|
_, span := tel.StartSpan(context.Background(), "op")
|
|
span.End()
|
|
span.End() // second End must not double-export
|
|
if got := len(exp.Spans()); got != 1 {
|
|
t.Errorf("got %d spans after double End, want 1", got)
|
|
}
|
|
}
|