feat!: trace and measure scans, on forge v1.12.9 and grove v1.8.0

AGENTS.md

@@ -87,7 +87,9 @@ For govulncheck, use CI's Go. CI always resolves the newest 1.26 patch, and an o
 | `store/storetest/` | The shared dashboard conformance suite |
 | `admin/` | `admin.Service`: validation, permissions, field schemas and audited retention between the contract and the scoped stores |
 | `plugin/` | Lifecycle hook interfaces and the registry |
-| `audit_hook/` (package `audithook`), `observability/` | Plugins for an audit trail and for metrics |
+| `audit_hook/` (package `audithook`) | Plugin for an audit trail |
+| `observability/` | Deprecated metrics plugin. It records nothing. Code that only builds and registers it still compiles; its old counter fields and hook methods are gone |
+| `internal/telemetry/` | The shared tracer, the span error helper and the labelled metric vectors the engine, plugin registry and admin service use |
 | `extension/` | The Forge extension, its `Config` and options |
 | `extension/contract/` | The `shield` dashboard contributor: `manifest.yaml`, handlers, and the claim-based actor resolver in `scope.go` |
 | `docs/` | The Fumadocs site |
@@ -107,7 +109,9 @@ IDs come from the `id` package (`id.NewInstinctID()` and friends). Don't build t
 
 `engine.New(opts...)` takes `type Option func(*Engine)` and returns `(*Engine, error)`. `extension.New(opts...)` takes `type Option func(*Extension)`. The extension reads YAML under `extensions.shield`, then `shield`, and merges it with the programmatic options. Its store comes from `WithStore`, a named grove DB (`WithGroveDatabase`), or the default `*grove.DB` in the container, chosen by driver name (`pg`, `sqlite`, `mongo`). With no store at all, `Health` reports that persistence is not configured. Shield mounts no HTTP routes of its own: `BasePath` is loaded and merged but nothing reads it, and `WithDisableRoutes` only stops the dashboard contract from registering.
 
-Logging uses `github.com/xraph/go-utils/log`, with `log.NewNoopLogger()` as the engine default.
+Logging uses `github.com/xraph/go-utils/log`, with `log.NewNoopLogger()` as the engine default. The Forge extension passes the app logger, and the engine passes its logger on to the plugin registry.
+
+Telemetry goes through `internal/telemetry`. Start spans from `telemetry.Tracer()` (scope `github.com/xraph/shield`), mark failures with `telemetry.Fail(span, "<class>", err)`, and never call `span.RecordError` or put an error message, scanned text, a tenant, app, subject or user-chosen name on a span or a label. Metrics take a go-utils `metrics.Metrics` through `engine.WithMetrics` (nil means off), and the extension wires `e.Metrics()`. Name them `shield_<object>_<verb>_total` or `shield_<operation>_duration_seconds`; Forge scrapes them with a `forge_` prefix. `docs/content/docs/guides/observability.mdx` lists every span and metric, so update it when you add one.
 
 ## Dependencies
 

README.md

@@ -134,7 +134,8 @@ Safety rules for an AI product change often and differ per customer. One tenant
 | PII handling with retention | A PII token vault (placeholder, type, your encrypted value, expiry), per-tenant deletion and age-based purge |
 | Evidence for audits | Compliance report records for the EU AI Act, NIST AI RMF and SOC 2 |
 | An admin UI with real permissions | A Forge dashboard contract where scope comes only from the signed-in user's claims, with optimistic concurrency on edits |
-| Hooks into your own systems | 15 lifecycle hooks, an audit bridge for [Chronicle](https://github.com/xraph/chronicle) and a metrics plugin |
+| Hooks into your own systems | 15 lifecycle hooks and an audit bridge for [Chronicle](https://github.com/xraph/chronicle) |
+| To see what it's doing | OpenTelemetry spans for every scan, plugin hook and PII purge, plus scan and hook metrics on Forge's `/_/metrics` |
 
 ## The safety model
 
@@ -173,16 +174,13 @@ The `extension` package registers Shield as a Forge extension. It reads `extensi
 import (
 	"github.com/xraph/forge"
 	shieldext "github.com/xraph/shield/extension"
-	"github.com/xraph/shield/observability"
 )
 
 app := forge.NewApp(forge.AppConfig{
 	Name:        "safety",
 	HTTPAddress: ":8080",
 	Extensions: []forge.Extension{
-		shieldext.New(
-			shieldext.WithPlugin(observability.NewMetricsExtension()),
-		),
+		shieldext.New(),
 	},
 })
 ```
@@ -207,7 +205,25 @@ The dashboard takes tenant and app from the signed-in user's `tenant_id` and `ap
 
 ## Lifecycle hooks
 
-Register a plugin with `engine.WithPlugin` (or `WithPlugin` on the extension). It can implement any of 15 hooks: scan started, completed, blocked and failed, one per layer (`OnInstinctTriggered`, `OnAwarenessDetected`, `OnBoundaryEnforced`, `OnValueViolated`, `OnJudgmentAssessed`, `OnReflexFired`), PII detected and redacted, policy evaluated, profile resolved, and shutdown. Today only the scan and shutdown hooks fire. `audithook.New(recorder)` (import path `github.com/xraph/shield/audit_hook`) writes them to an audit trail, and `observability.NewMetricsExtension()` counts them.
+Register a plugin with `engine.WithPlugin` (or `WithPlugin` on the extension). It can implement any of 15 hooks: scan started, completed, blocked and failed, one per layer (`OnInstinctTriggered`, `OnAwarenessDetected`, `OnBoundaryEnforced`, `OnValueViolated`, `OnJudgmentAssessed`, `OnReflexFired`), PII detected and redacted, policy evaluated, profile resolved, and shutdown. Today only the scan and shutdown hooks fire. `audithook.New(recorder)` (import path `github.com/xraph/shield/audit_hook`) writes them to an audit trail. A hook that returns an error is logged and counted, and the scan carries on.
+
+## Telemetry
+
+You don't wire anything in a Forge app. The extension hands `app.Metrics()` and the app logger to the engine, and spans go to the tracer provider `forge.New` installs. Outside Forge, pass a go-utils `metrics.Metrics` to `engine.WithMetrics` and install a global OpenTelemetry tracer provider.
+
+| Span | Kind | Attributes |
+| --- | --- | --- |
+| `scan content` | Internal | `shield.scan.id`, `shield.scan.direction`, `shield.scan.decision`, `shield.scan.blocked`, `shield.scan.findings`, `shield.scan.persisted` (only with a store) |
+| `run plugin hooks` | Internal, child of the scan | `shield.plugin.hook`, `shield.plugin.count`, `shield.plugin.failures` (on failure) |
+| `purge pii tokens` | Internal | `shield.retention.tokens_selected`, `shield.retention.tokens_deleted` |
+
+| Metric (as scraped) | Type | Labels |
+| --- | --- | --- |
+| `forge_shield_scans_completed_total` | counter | `direction` (`input`, `output`), `decision` (`allow`, `block`, `flag`, `redact`) |
+| `forge_shield_scan_duration_seconds` | histogram | `direction`, `decision` |
+| `forge_shield_plugin_hooks_failed_total` | counter | `hook` (`scan_started`, `scan_completed` and the other 13 hooks in snake case) |
+
+Scanned text, findings, tenants, apps and error messages never go on a span or a label. The [observability guide](https://www.xraph.com/docs/shield/guides/observability) has the details, including what changed for anyone scraping the old `shield.scan.*` counters.
 
 ## Documentation
 
@@ -216,7 +232,7 @@ Register a plugin with `engine.WithPlugin` (or `WithPlugin` on the extension). I
 | Overview | [Introduction](https://www.xraph.com/docs/shield), [architecture](https://www.xraph.com/docs/shield/architecture), [getting started](https://www.xraph.com/docs/shield/getting-started) |
 | Concepts | [Entities](https://www.xraph.com/docs/shield/concepts/entities), [multi-tenancy](https://www.xraph.com/docs/shield/concepts/multi-tenancy), [configuration](https://www.xraph.com/docs/shield/concepts/configuration), [errors](https://www.xraph.com/docs/shield/concepts/errors) |
 | Storage | [PostgreSQL](https://www.xraph.com/docs/shield/stores/postgres), [SQLite](https://www.xraph.com/docs/shield/stores/sqlite), [MongoDB](https://www.xraph.com/docs/shield/stores/mongo) |
-| Forge and plugins | [Forge extension](https://www.xraph.com/docs/shield/guides/forge-extension), [custom plugins](https://www.xraph.com/docs/shield/guides/custom-plugin) |
+| Forge and plugins | [Forge extension](https://www.xraph.com/docs/shield/guides/forge-extension), [custom plugins](https://www.xraph.com/docs/shield/guides/custom-plugin), [observability](https://www.xraph.com/docs/shield/guides/observability) |
 
 Some docs pages, including getting started, show scans that block and redact. They describe the design, not what the code does yet, so trust [Status](#status) over them. The Go API is on [pkg.go.dev](https://pkg.go.dev/github.com/xraph/shield).
 

admin/service.go

@@ -9,8 +9,12 @@ import (
 	"sync"
 	"time"
 
+	"go.opentelemetry.io/otel/attribute"
+	"go.opentelemetry.io/otel/trace"
+
 	"github.com/xraph/shield/engine"
 	"github.com/xraph/shield/id"
+	"github.com/xraph/shield/internal/telemetry"
 	"github.com/xraph/shield/store"
 )
 
@@ -423,17 +427,28 @@ func (s *Service) RetentionExecute(ctx context.Context, a Actor, key string) (in
 	if !ok {
 		return 0, fail("UNAVAILABLE", "PII retention is unavailable")
 	}
+	// The purge itself (audit, delete, audit) runs under its own span inside
+	// forge's dispatch span, so you can see which step failed and how many
+	// tokens went. The checks above are the dispatch span's business.
+	ctx, span := telemetry.Tracer().Start(ctx, "purge pii tokens", trace.WithAttributes(
+		attribute.Int("shield.retention.tokens_selected", len(p.TokenIDs)),
+	))
+	defer span.End()
 	event := AuditEvent{Subject: a.Subject, Scope: a.Scope, Action: "pii.retention.requested", TokenIDs: p.TokenIDs, Cutoff: p.Cutoff}
 	if err := s.audit(ctx, event); err != nil {
+		telemetry.Fail(span, "audit_failed", err)
 		return 0, fail("UNAVAILABLE", "Could not record retention audit; nothing was deleted")
 	}
 	n, err := db.DashboardDeleteTokens(ctx, a.Scope, p.Cutoff, p.TokenIDs)
 	if err != nil {
+		telemetry.Fail(span, "delete_failed", err)
 		return 0, err
 	}
+	span.SetAttributes(attribute.Int64("shield.retention.tokens_deleted", n))
 	event.Action = "pii.retention.completed"
 	event.Affected = n
 	if err = s.audit(ctx, event); err != nil {
+		telemetry.Fail(span, "completion_audit_failed", err)
 		return n, fail("INTERNAL", "Retention completed but its completion audit failed")
 	}
 	return n, nil

admin/telemetry_test.go

@@ -0,0 +1,175 @@
+package admin
+
+import (
+	"context"
+	"errors"
+	"strings"
+	"testing"
+	"time"
+
+	"go.opentelemetry.io/otel"
+	"go.opentelemetry.io/otel/attribute"
+	"go.opentelemetry.io/otel/codes"
+	sdktrace "go.opentelemetry.io/otel/sdk/trace"
+	"go.opentelemetry.io/otel/sdk/trace/tracetest"
+
+	"github.com/xraph/shield/id"
+	"github.com/xraph/shield/pii"
+	"github.com/xraph/shield/store"
+)
+
+const secret = "alice@example.com"
+
+func purgeSpans(t *testing.T) *tracetest.SpanRecorder {
+	t.Helper()
+	prev := otel.GetTracerProvider()
+	rec := tracetest.NewSpanRecorder()
+	otel.SetTracerProvider(sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(rec)))
+	t.Cleanup(func() { otel.SetTracerProvider(prev) })
+	return rec
+}
+
+func spanAttrs(s sdktrace.ReadOnlySpan) map[attribute.Key]attribute.Value {
+	m := map[attribute.Key]attribute.Value{}
+	for _, kv := range s.Attributes() {
+		m[kv.Key] = kv.Value
+	}
+	return m
+}
+
+func seedExpiredToken(t *testing.T, s *Service, a Actor) {
+	t.Helper()
+	expired := time.Now().Add(-time.Hour)
+	tok := &pii.Token{ID: id.NewPIITokenID(), ScanID: id.NewScanID(), TenantID: a.Scope.TenantID, PIIType: "email", Placeholder: "[EMAIL]", EncryptedValue: []byte(secret), ExpiresAt: &expired}
+	if err := s.db.(store.Store).StorePIITokens(context.Background(), []*pii.Token{tok}); err != nil {
+		t.Fatal(err)
+	}
+}
+
+func TestRetentionPurgeIsTraced(t *testing.T) {
+	s, a := serviceForTest(t)
+	a.Subject = secret
+	seedExpiredToken(t, s, a)
+	s.audit = func(context.Context, AuditEvent) error { return nil }
+	ctx := context.Background()
+	p, err := s.RetentionPreview(ctx, a)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	rec := purgeSpans(t)
+	if _, err = s.RetentionExecute(ctx, a, "missing"); err == nil {
+		t.Fatal("unknown preview executed")
+	}
+	if len(rec.Ended()) != 0 {
+		t.Fatal("a refused purge started a span; the dispatch span covers it")
+	}
+
+	n, err := s.RetentionExecute(ctx, a, p.ID)
+	if err != nil || n != 1 {
+		t.Fatal(n, err)
+	}
+	var purge sdktrace.ReadOnlySpan
+	for _, sp := range rec.Ended() {
+		if sp.Name() == "purge pii tokens" {
+			purge = sp
+		}
+	}
+	if purge == nil {
+		t.Fatal("no purge span")
+	}
+	at := spanAttrs(purge)
+	if at["shield.retention.tokens_selected"].AsInt64() != 1 || at["shield.retention.tokens_deleted"].AsInt64() != 1 {
+		t.Errorf("attributes = %v", at)
+	}
+	if purge.Status().Code == codes.Error {
+		t.Errorf("status = %v", purge.Status())
+	}
+	// The token delete goes through grove, which nests its span here.
+	children := 0
+	for _, sp := range rec.Ended() {
+		if sp == purge {
+			continue
+		}
+		if sp.Parent().SpanID() != purge.SpanContext().SpanID() {
+			t.Errorf("%q is not a child of the purge span", sp.Name())
+		}
+		children++
+	}
+	if children == 0 {
+		t.Error("the token delete left no span under the purge span")
+	}
+	assertClean(t, rec)
+}
+
+func TestRetentionPurgeSpanNamesTheFailedStep(t *testing.T) {
+	for _, tc := range []struct {
+		name  string
+		fail  int // which audit call fails, 1 or 2
+		class string
+	}{
+		{"request audit", 1, "audit_failed"},
+		{"completion audit", 2, "completion_audit_failed"},
+	} {
+		t.Run(tc.name, func(t *testing.T) {
+			s, a := serviceForTest(t)
+			seedExpiredToken(t, s, a)
+			calls := 0
+			s.audit = func(context.Context, AuditEvent) error {
+				calls++
+				if calls == tc.fail {
+					return errors.New("audit sink refused " + secret)
+				}
+				return nil
+			}
+			ctx := context.Background()
+			p, err := s.RetentionPreview(ctx, a)
+			if err != nil {
+				t.Fatal(err)
+			}
+			rec := purgeSpans(t)
+			if _, err = s.RetentionExecute(ctx, a, p.ID); err == nil {
+				t.Fatal("audit failure hidden")
+			}
+			var purge sdktrace.ReadOnlySpan
+			for _, sp := range rec.Ended() {
+				if sp.Name() == "purge pii tokens" {
+					purge = sp
+				}
+			}
+			if purge == nil {
+				t.Fatal("no purge span")
+			}
+			if purge.Status().Code != codes.Error || purge.Status().Description != tc.class {
+				t.Errorf("status = %v, want %s", purge.Status(), tc.class)
+			}
+			ev := purge.Events()
+			if len(ev) != 1 || ev[0].Name != "exception" || ev[0].Attributes[0].Value.AsString() != "*errors.errorString" {
+				t.Errorf("events = %+v", ev)
+			}
+			_, deleted := spanAttrs(purge)["shield.retention.tokens_deleted"]
+			if deleted != (tc.fail == 2) {
+				t.Errorf("tokens_deleted present = %v", deleted)
+			}
+			assertClean(t, rec)
+		})
+	}
+}
+
+func assertClean(t *testing.T, rec *tracetest.SpanRecorder) {
+	t.Helper()
+	for _, sp := range rec.Ended() {
+		kvs := append([]attribute.KeyValue{}, sp.Attributes()...)
+		for _, ev := range sp.Events() {
+			kvs = append(kvs, ev.Attributes...)
+		}
+		for _, kv := range kvs {
+			if strings.Contains(kv.Value.String(), secret) {
+				t.Errorf("span %q leaks %s in %s", sp.Name(), secret, kv.Key)
+			}
+		}
+		if strings.Contains(sp.Status().Description, secret) {
+			t.Errorf("span %q leaks %s in its status", sp.Name(), secret)
+		}
+	}
+}

docs/content/docs/api-reference/go-packages.mdx

@@ -41,7 +41,9 @@ The scan entry points. No evaluation layer runs yet.
 | `WithStore(s)` | Set composite store |
 | `WithPlugin(p)` | Register lifecycle plugin |
 | `WithConfig(cfg)` | Set engine configuration |
-| `WithLogger(l)` | Set a go-utils `log.Logger` |
+| `WithLogger(l)` | Set a go-utils `log.Logger`; plugin hook errors go to it too |
+| `WithMetrics(m)` | Record `shield_scans_completed_total`, `shield_scan_duration_seconds` and `shield_plugin_hooks_failed_total` on a go-utils `metrics.Metrics` |
+| `ScansCompletedMetric`, `ScanDurationMetric`, `ScanDurationBuckets` | The metric names and histogram bounds |
 
 ### `github.com/xraph/shield/scan`
 
@@ -179,10 +181,12 @@ Compliance report records for the EU AI Act, NIST AI RMF and SOC 2. Shield store
 
 ### `github.com/xraph/shield/plugin`
 
-The `Plugin` base interface, `Registry`, `NewRegistry` and all lifecycle hook interfaces: `ScanStarted`, `ScanCompleted`, `ScanBlocked`, `ScanFailed`, `InstinctTriggered`, `AwarenessDetected`, `JudgmentAssessed`, `ValueViolated`, `ReflexFired`, `BoundaryEnforced`, `PIIDetected`, `PIIRedacted`, `PolicyEvaluated`, `SafetyProfileResolved`, `Shutdown`. Only `ScanStarted`, `ScanCompleted` and `Shutdown` are emitted today.
+The `Plugin` base interface, `Registry` (with `NewRegistry`, `SetLogger` and `SetMetrics`), `HooksFailedMetric` and all lifecycle hook interfaces: `ScanStarted`, `ScanCompleted`, `ScanBlocked`, `ScanFailed`, `InstinctTriggered`, `AwarenessDetected`, `JudgmentAssessed`, `ValueViolated`, `ReflexFired`, `BoundaryEnforced`, `PIIDetected`, `PIIRedacted`, `PolicyEvaluated`, `SafetyProfileResolved`, `Shutdown`. Only `ScanStarted`, `ScanCompleted` and `Shutdown` are emitted today.
 
 ### `github.com/xraph/shield/observability`
 
+Deprecated. `MetricsExtension` implements no hooks and records nothing; use `engine.WithMetrics`. Its exported counter fields (`ScanStartedCount` and the rest) and its `On*` hook methods were removed in v1.8.0, so code that read them no longer compiles. Code that only builds and registers the plugin still does.
+
 ```go
 func NewMetricsExtension() *MetricsExtension
 func NewMetricsExtensionWithFactory(factory gu.MetricFactory) *MetricsExtension