diff --git a/internal/telemetry/telemetry.go b/internal/telemetry/telemetry.go index 7c518ed..1795053 100644 --- a/internal/telemetry/telemetry.go +++ b/internal/telemetry/telemetry.go @@ -20,9 +20,11 @@ package telemetry import ( "fmt" + "reflect" "regexp" "sort" "strings" + "time" "github.com/tracebloc/cli/internal/api" ) @@ -75,12 +77,27 @@ var retired = map[string]bool{ "experimentKey": true, "experimentId": true, } -// otelAttrs are the only keys allowed outside the tracebloc. namespace (§1.1). -var otelAttrs = map[string]bool{ +// The two layers of §1, kept as two sets. One flat allowlist is what let a call +// site smuggle a resource key into the RECORD layer — the cross-layer confusion +// that made cloud_RoleName report a process name, reintroduced at the call site +// of the package meant to close it. + +// resourceScope is set once per process by New. A call site may never send one. +// tracebloc.component is listed even though it is correctly tracebloc.-prefixed: +// the namespace rule alone would wave it past. +var resourceScope = map[string]bool{ "service.name": true, "service.version": true, "service.instance.id": true, - "deployment.environment": true, "error.type": true, - "exception.type": true, "exception.message": true, "exception.stacktrace": true, - "event.name": true, + "deployment.environment": true, "tracebloc.component": true, + "tracebloc.tenant.id": true, +} + +// recordScope is the set of OTel names a call site MAY send. event.name is +// absent deliberately — it is Emit's first argument, and accepting it here +// would let a caller replace the name after the grammar and failure-set checks +// had already run against the real one. +var recordScope = map[string]bool{ + "error.type": true, "exception.type": true, "exception.message": true, + "exception.stacktrace": true, } // Attrs is one event's record attributes. Values are primitives (§1.2); a map @@ -110,8 +127,14 @@ func New(env, version, instanceID string) *Emitter { "service.name": Service, "tracebloc.component": Component, "service.version": normaliseVersion(version), - "service.instance.id": instanceID, }} + // §1.2 — omitted rather than stamped empty. os.Hostname() returns "" on + // error, and an empty service.instance.id is the "sent as empty rather than + // omitted" defect the record layer already refuses; the resource layer must + // hold the same line, or the rule only applies where it is easiest. + if id := strings.TrimSpace(instanceID); id != "" { + e.resource["service.instance.id"] = id + } if api.IsKnownEnv(env) { e.resource["deployment.environment"] = strings.ToLower(env) } @@ -165,7 +188,12 @@ func (e *Emitter) Emit(eventName string, attrs Attrs) error { return err } record["event.name"] = eventName - if e.sink != nil { + // Validation above ALWAYS runs; delivery does not. The "an unrecognised + // environment never exports" guarantee lived entirely in caller discipline + // — don't install a sink when !Exports() — even though the emitter already + // knows. A guarantee enforced by convention at every call site is a + // guarantee until the first call site forgets. + if e.sink != nil && e.Exports() { e.sink(e.Resource(), record) } return nil @@ -204,17 +232,19 @@ func CheckEventName(name string) error { func normalise(attrs Attrs) (map[string]any, error) { out := make(map[string]any, len(attrs)) for key, value := range attrs { + // The KEY is validated first, always — even when the value is about to + // be dropped. Skipping straight to `continue` let a retired or malformed + // key pass silently whenever it happened to carry an empty value + // (`Attrs{"experimentKey": nil}` raised nothing), which contradicts this + // package's own rule that a malformed event must not pass quietly. + if err := checkAttrKey(key); err != nil { + return nil, err + } // §1.2 — an absent value is omitted, never sent as nil or "". The // retired `traceback` key rode on every record and was empty on 99.8%. - if value == nil { + if absentValue(value) { continue } - if s, ok := value.(string); ok && s == "" { - continue - } - if err := checkAttrKey(key); err != nil { - return nil, err - } if err := checkAttrValue(key, value); err != nil { return nil, err } @@ -223,13 +253,41 @@ func normalise(attrs Attrs) (map[string]any, error) { return out, nil } +// absentValue applies §1.2's "there is nothing here" test. It asks the same +// question checkAttrValue asks — by KIND, not by concrete type — because the +// two must agree on what a string is. A `value.(string)` assertion here while +// checkAttrValue accepted any string kind let a named string type +// (`type Reason string`) carry an empty value onto the record, reopening the +// hole for exactly the callers the kind-based check was widened to serve. On a +// failure an empty named `error.type` would then satisfy checkFailureSet by key +// presence alone — a failure that cannot be grouped, reported as one that can +// (Bugbot). +// +// A zero number and a false bool are NOT absent: they are measurements that +// happen to be falsey, and dropping them would lose the records worth querying. +func absentValue(value any) bool { + if value == nil { + return true + } + v := reflect.ValueOf(value) + return v.Kind() == reflect.String && strings.TrimSpace(v.String()) == "" +} + func checkAttrKey(key string) error { if retired[key] { return fmt.Errorf( "telemetry: attribute %q is retired (contract §8.5) and must not be emitted; "+ "retired names are replaced, not renamed", key) } - if otelAttrs[key] { + if resourceScope[key] || key == "event.name" { + return fmt.Errorf( + "telemetry: attribute %q is RESOURCE scope (contract §1) and is set once per "+ + "process by New(); a call site may not send it. Accepting it would let one "+ + "record contradict its own process identity. event.name is Emit's first "+ + "argument, not an attribute: passing it would replace the name after the "+ + "grammar and failure-set checks had run", key) + } + if recordScope[key] { return nil } if !attrKeyRe.MatchString(key) { @@ -245,9 +303,17 @@ func checkAttrKey(key string) error { return nil } +// checkAttrValue applies §1.2. The accepted set is every Go scalar KIND, not a +// list of concrete types: a Go type switch matches the DYNAMIC type, so +// `case int64` does not match a time.Duration (a named type over int64) and an +// idiomatic caller would be told their duration was the retired extraData +// defect. Reflection asks the question that was actually meant. func checkAttrValue(key string, value any) error { - switch value.(type) { - case string, bool, int, int64, float64: + switch reflect.ValueOf(value).Kind() { + case reflect.String, reflect.Bool, + reflect.Int, reflect.Int8, reflect.Int16, reflect.Int32, reflect.Int64, + reflect.Uint, reflect.Uint8, reflect.Uint16, reflect.Uint32, reflect.Uint64, + reflect.Float32, reflect.Float64: return nil default: return fmt.Errorf( @@ -257,6 +323,12 @@ func checkAttrValue(key string, value any) error { } } +// Duration renders d for an attribute value. time.Duration IS an int64 kind and +// so would pass checkAttrValue as a raw nanosecond count — which is a number +// nobody reading a dashboard can interpret. Naming the unit at the call site is +// the point: use `telemetry.Duration(elapsed)` with a `…_ms` attribute key. +func Duration(d time.Duration) int64 { return d.Milliseconds() } + func checkFailureSet(eventName string, record map[string]any) error { parts := strings.Split(eventName, ".") if !failureOutcomes[parts[2]] { diff --git a/internal/telemetry/telemetry_test.go b/internal/telemetry/telemetry_test.go index 0f2a890..5667bd4 100644 --- a/internal/telemetry/telemetry_test.go +++ b/internal/telemetry/telemetry_test.go @@ -3,6 +3,7 @@ package telemetry import ( "strings" "testing" + "time" "github.com/tracebloc/cli/internal/api" ) @@ -310,3 +311,216 @@ func TestResourceIsACopy(t *testing.T) { t.Fatal("the resource is mutable from outside") } } + +// --- review findings on cli#503 (merged) ------------------------------------ + +func TestNoResourceScopeKeyMayComeFromACallSite(t *testing.T) { + // §1 — a call site that sets a resource attribute is a bug. One flat + // allowlist let a caller smuggle one into the RECORD layer, so a single + // record could contradict its own process identity: the cloud_RoleName + // cross-layer confusion, at the call site of the package meant to close it. + e := New(api.EnvProd, "0.10.7", "h") + for key := range resourceScope { + t.Run(key, func(t *testing.T) { + err := e.Emit("cli.command.succeeded", Attrs{key: "impostor"}) + if err == nil { + t.Fatalf("accepted resource-scope key %q from a call site", key) + } + if !strings.Contains(err.Error(), "RESOURCE scope") { + t.Fatalf("%q was rejected by another rule, so the layer check "+ + "is doing no work for it: %v", key, err) + } + }) + } +} + +func TestEventNameCannotBePassedAsAnAttribute(t *testing.T) { + // It is Emit's first argument. Accepting it would replace the name AFTER + // the grammar and failure-set checks ran against the real one — delivering + // a failure-shaped name that skipped §8.4. + e := New(api.EnvProd, "0.10.7", "h") + err := e.Emit("cli.command.succeeded", Attrs{"event.name": "cli.command.failed"}) + if err == nil { + t.Fatal("accepted event.name as an attribute") + } + // Asserting WHICH rule: event.name is also not tracebloc.-prefixed, so the + // namespace rule would reject it too, and a test that only checked "it + // errors" would pass with this guard deleted. + if !strings.Contains(err.Error(), "Emit's first argument") { + t.Fatalf("rejected by another rule: %v", err) + } +} + +func TestRecordScopeOTelKeysStillPass(t *testing.T) { + // The split must not become a blanket ban on OTel names. + e := New(api.EnvProd, "0.10.7", "h") + if err := e.Emit("cli.command.failed", Attrs{ + "error.type": "network", + "exception.type": "net.OpError", + "exception.message": "boom", + "exception.stacktrace": "goroutine 1…", + }); err != nil { + t.Fatalf("rejected record-scope OTel keys: %v", err) + } +} + +func TestGoScalarKindsAreAcceptedNotJustNamedTypes(t *testing.T) { + // A Go type switch matches the DYNAMIC type, so `case int64` does not match + // a time.Duration. An idiomatic caller in #1907 would have been told their + // duration was the retired extraData defect. + e := New(api.EnvProd, "0.10.7", "h") + for name, v := range map[string]any{ + "duration": 5 * time.Second, + "int32": int32(3), + "uint": uint(3), + "uint64": uint64(3), + "float32": float32(1.5), + "named": time.Duration(7), + } { + t.Run(name, func(t *testing.T) { + if err := e.Emit("cli.command.succeeded", Attrs{"tracebloc.v": v}); err != nil { + t.Fatalf("rejected a Go scalar %T: %v", v, err) + } + }) + } + // …and a genuine non-scalar is still refused. + if err := e.Emit("cli.command.succeeded", Attrs{ + "tracebloc.v": map[string]string{"a": "b"}, + }); err == nil { + t.Fatal("accepted a map — that is the extraData defect") + } +} + +func TestDurationHelperRendersMilliseconds(t *testing.T) { + // time.Duration passes checkAttrValue as a raw NANOSECOND count, which is a + // number nobody reading a dashboard can interpret. The helper names the unit. + if got := Duration(1500 * time.Millisecond); got != 1500 { + t.Fatalf("Duration = %d, want 1500", got) + } +} + +func TestAnEmptyInstanceIDIsOmittedNotStamped(t *testing.T) { + // os.Hostname() returns "" on error. An empty service.instance.id is the + // "sent as empty rather than omitted" defect the RECORD layer already + // refuses; the resource layer must hold the same line. + for _, id := range []string{"", " "} { + r := New(api.EnvProd, "0.10.7", id).Resource() + if v, ok := r["service.instance.id"]; ok { + t.Fatalf("stamped service.instance.id = %q for input %q", v, id) + } + } + if r := New(api.EnvProd, "0.10.7", "host-1").Resource(); r["service.instance.id"] != "host-1" { + t.Fatal("a real instance id was lost") + } +} + +func TestDeliveryIsGatedOnExports(t *testing.T) { + // The "unrecognised environment never exports" guarantee lived entirely in + // caller discipline, even though the emitter already knew. + u := New("staging", "0.10.7", "h") // not a known env + delivered := false + u.SetSink(func(map[string]string, map[string]any) { delivered = true }) + if err := u.Emit("cli.command.succeeded", Attrs{}); err != nil { + t.Fatalf("validation should still run: %v", err) + } + if delivered { + t.Fatal("delivered a record although Exports() is false") + } + + // …and validation still runs on that path, so a bad event fails in CI + // wherever the binary is built. + if err := u.Emit("cli.command.refreshed", Attrs{}); err == nil { + t.Fatal("a non-exporting emitter skipped validation") + } + + // The exporting path still delivers. + e := New(api.EnvProd, "0.10.7", "h") + got := false + e.SetSink(func(map[string]string, map[string]any) { got = true }) + if err := e.Emit("cli.command.succeeded", Attrs{}); err != nil || !got { + t.Fatalf("an exporting emitter did not deliver (err=%v)", err) + } +} + +func TestAKeyIsValidatedEvenWhenItsValueIsDropped(t *testing.T) { + // A retired or malformed key that happened to carry an empty value escaped + // every rule — contradicting this package's own "a malformed event must not + // pass silently". + e := New(api.EnvProd, "0.10.7", "h") + for name, attrs := range map[string]Attrs{ + "retired nil": {"experimentKey": nil}, + "retired empty": {"extraData": ""}, + "bad shape nil": {"tracebloc.clientID": nil}, + "unprefixed": {"cluster.name": ""}, + } { + t.Run(name, func(t *testing.T) { + if err := e.Emit("cli.command.succeeded", attrs); err == nil { + t.Fatalf("a bad key passed silently because its value was empty: %v", attrs) + } + }) + } + // A GOOD key with an empty value is still dropped, not an error. + var got map[string]any + e.SetSink(func(_ map[string]string, r map[string]any) { got = r }) + if err := e.Emit("cli.command.succeeded", Attrs{"tracebloc.note": ""}); err != nil { + t.Fatalf("a valid key with an empty value should be dropped, not rejected: %v", err) + } + if _, ok := got["tracebloc.note"]; ok { + t.Fatal("an empty value was sent rather than omitted") + } +} + +// A named string type is accepted by checkAttrValue (it is a string KIND), so +// the omit rule has to recognise it too. It did not: the drop type-asserted to +// builtin `string`, so `type Reason string; Reason("")` landed on the record — +// reopening §1.2 for exactly the callers the kind-based value check was widened +// to serve. +func TestAnEmptyNamedStringIsDroppedLikeAnEmptyString(t *testing.T) { + type Reason string + e := New(api.EnvProd, "0.10.7", "host-1") + var got map[string]any + e.SetSink(func(_ map[string]string, r map[string]any) { got = r }) + if err := e.Emit("cli.command.succeeded", Attrs{"tracebloc.reason": Reason(" ")}); err != nil { + t.Fatalf("Emit: %v", err) + } + if v, ok := got["tracebloc.reason"]; ok { + t.Errorf("an empty named string was emitted: %#v", v) + } +} + +// The consequence that makes it worth a test rather than a tidy-up: on a +// failure, an empty named error.type would satisfy the failure-set check by key +// presence alone — a failure that cannot be grouped, reported as one that can. +func TestAnEmptyNamedErrorTypeDoesNotSatisfyTheFailureCheck(t *testing.T) { + type Reason string + e := New(api.EnvProd, "0.10.7", "host-1") + if err := e.Emit("cli.command.failed", Attrs{"error.type": Reason("")}); err == nil { + t.Error("a failure with a blank named error.type was accepted") + } +} + +// The other half: a named string with real content must still arrive, and a +// zero number must not be mistaken for absence. +func TestNamedStringsAndZeroValuesStillArrive(t *testing.T) { + type Reason string + e := New(api.EnvProd, "0.10.7", "host-1") + var got map[string]any + e.SetSink(func(_ map[string]string, r map[string]any) { got = r }) + err := e.Emit("cli.command.succeeded", Attrs{ + "tracebloc.reason": Reason("timeout"), + "tracebloc.retries": 0, + "tracebloc.cached": false, + }) + if err != nil { + t.Fatalf("Emit: %v", err) + } + if got["tracebloc.reason"] != Reason("timeout") { + t.Errorf("named string lost: %#v", got["tracebloc.reason"]) + } + if _, ok := got["tracebloc.retries"]; !ok { + t.Error("0 was dropped as absent — it is a measurement, not an absence") + } + if _, ok := got["tracebloc.cached"]; !ok { + t.Error("false was dropped as absent") + } +}