Observability: see a problem, find it, explain it

// ContextHandler adds the trace and span IDs from the context to every log record, so a log line
// leads to its trace and a trace leads to its log lines. With a Clock it also stamps records
// with that clock, so a replay logs simulated time.
type ContextHandler struct {
  slog.Handler
  Clock Clock
}

// Handle adds trace_id and span_id, then passes the record on.
func (h ContextHandler) Handle(ctx context.Context, r slog.Record) error {
  if s := SpanFrom(ctx); s != nil {
    r.AddAttrs(slog.String("trace_id", s.TraceID.String()), slog.String("span_id", s.SpanID.String()))
  }
  if h.Clock != nil {
    r.Time = h.Clock.Now()
  }
  if err := h.Handler.Handle(ctx, r); err != nil {
    return fmt.Errorf("log: %w", err)
  }
  return nil
}

// ServeHTTP runs one request: a server span from the caller's trace context, a child span and
// a latency histogram per dependency call, RED metrics for the request, and one log line that
// carries the trace ID.
func (s *Service) ServeHTTP(w http.ResponseWriter, r *http.Request) {
  ctx, span := s.Tracer.Start(Extract(r.Context(), r.Header), r.Method+" "+r.URL.Path)
  route, tenant := r.URL.Path, r.Header.Get("X-Tenant")
  span.Attrs["route"], span.Attrs["tenant"] = route, tenant
  start := s.Clock.Now()

  deps, ok := s.Routes[route]
  status := http.StatusOK
  if !ok {
    status = http.StatusNotFound
  }
  if ok && s.Work != nil {
    s.Work(ctx)
  }
  for _, name := range deps {
    cctx, child := s.Tracer.Start(ctx, name)
    t0 := s.Clock.Now()
    err := s.Deps[name].Call(cctx, tenant)
    s.Metrics.Observe("dependency_duration_seconds", s.Clock.Now().Sub(t0).Seconds(), Label{"dep", name})
    child.Err = err != nil
    child.Finish()
    if err != nil {
      s.Log.WarnContext(cctx, "dependency failed", "dep", name, "tenant", tenant, "err", err.Error())
      status = http.StatusServiceUnavailable
      break
    }
  }
  w.WriteHeader(status)

  took := s.Clock.Now().Sub(start)
  code := strconv.Itoa(status)
  s.Metrics.Inc("http_requests_total", Label{"route", route}, Label{"code", code}, Label{"tenant", tenant})
  s.Metrics.Observe("http_request_duration_seconds", took.Seconds(), Label{"route", route}, Label{"tenant", tenant})
  level := slog.LevelInfo
  if status >= 500 {
    level = slog.LevelError
  }
  s.Log.Log(ctx, level, "request", "route", route, "tenant", tenant, "status", status, "duration_ms", took.Milliseconds())
  span.Err = status >= 500
  span.Attrs["status"] = code
  span.Finish()
}

// Traceparent formats the header: version 00, the 32-hex trace ID, the 16-hex parent span ID,
// and flags (01 = sampled). Example: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01
func (sc SpanContext) Traceparent() string {
  flags := "00"
  if sc.Sampled {
    flags = "01"
  }
  return "00-" + sc.TraceID.String() + "-" + sc.SpanID.String() + "-" + flags
}

// ParseTraceparent reads the header. An all-zero trace or span ID is invalid.
func ParseTraceparent(v string) (SpanContext, error) {
  parts := strings.Split(strings.TrimSpace(v), "-")
  if len(parts) != 4 || parts[0] != "00" || len(parts[1]) != 32 || len(parts[2]) != 16 || len(parts[3]) != 2 {
    return SpanContext{}, fmt.Errorf("%w: %q", ErrBadTraceparent, v)
  }
  var sc SpanContext
  if _, err := hex.Decode(sc.TraceID[:], []byte(parts[1])); err != nil {
    return SpanContext{}, fmt.Errorf("%w: trace ID: %w", ErrBadTraceparent, err)
  }
  if _, err := hex.Decode(sc.SpanID[:], []byte(parts[2])); err != nil {
    return SpanContext{}, fmt.Errorf("%w: span ID: %w", ErrBadTraceparent, err)
  }
  flags, err := hex.DecodeString(parts[3])
  if err != nil {
    return SpanContext{}, fmt.Errorf("%w: flags: %w", ErrBadTraceparent, err)
  }
  if sc.TraceID == (TraceID{}) || sc.SpanID.IsZero() {
    return SpanContext{}, fmt.Errorf("%w: zero ID", ErrBadTraceparent)
  }
  sc.Sampled = flags[0]&1 == 1
  return sc, nil
}

// Start begins a span. Its parent is the span already in ctx, or else the remote parent that
// Extract found in the request headers, or else none: a new trace.
func (t *Tracer) Start(ctx context.Context, name string) (context.Context, *Span) {
  s := &Span{Name: name, Service: t.Service, Start: t.Clock.Now(), Attrs: map[string]string{}, tracer: t}
  t.mu.Lock()
  binary.BigEndian.PutUint64(s.SpanID[:], t.rng.Uint64()|1)
  if p := SpanFrom(ctx); p != nil {
    s.TraceID, s.Parent = p.TraceID, p.SpanID
  } else if rc, ok := ctx.Value(remoteKey{}).(SpanContext); ok {
    s.TraceID, s.Parent = rc.TraceID, rc.SpanID
  } else {
    binary.BigEndian.PutUint64(s.TraceID[:8], t.rng.Uint64())
    binary.BigEndian.PutUint64(s.TraceID[8:], t.rng.Uint64()|1)
  }
  t.mu.Unlock()
  return context.WithValue(ctx, spanKey{}, s), s
}

// Inject writes the current span into outgoing headers.
func Inject(ctx context.Context, h http.Header) {
  if s := SpanFrom(ctx); s != nil {
    h.Set(TraceparentHeader, s.Context().Traceparent())
  }
}

// Extract reads the caller's span from incoming headers. A missing or bad header starts a new
// trace; it never fails the request.
func Extract(ctx context.Context, h http.Header) context.Context {
  sc, err := ParseTraceparent(h.Get(TraceparentHeader))
  if err != nil {
    return ctx
  }
  return context.WithValue(ctx, remoteKey{}, sc)
}

// get returns the series for name and labels. A new label set beyond the metric's limit goes
// into one overflow series instead, and the registry counts it as dropped.
func (r *Registry) get(name string, labels []Label, hist bool) *series {
  k := key(name, labels)
  if s, ok := r.series[k]; ok {
    return s
  }
  if r.perMetric[name] >= r.maxSeries {
    r.dropped++
    labels = []Label{OverflowLabel}
    k = key(name, labels)
    if s, ok := r.series[k]; ok {
      return s
    }
  }
  s := &series{name: name, labels: slices.Clone(labels)}
  if hist {
    s.hist = NewHistogram(r.buckets)
  }
  r.series[k] = s
  r.perMetric[name]++
  return s
}