From 02fbbb8d6c1322abea7c35a6c6cc1dce0a8d8a3b Mon Sep 17 00:00:00 2001 From: Lukas Wuttke Date: Fri, 14 Aug 2026 16:44:43 +0200 Subject: [PATCH 1/2] fix(telemetry): five review findings on the merged Go helper (backend#1897) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit cli#503 merged before its review was resolved. All five findings are real; each was reproduced against the merged code before anything changed, and each is mutation-proved. Nothing imports this package yet (#1907 is the consumer), so there is no production impact — but three of these would have shaped the first call sites, which is exactly when they would have been expensive. 1. RESOURCE-SCOPE KEYS WERE ACCEPTED AS RECORD ATTRIBUTES. One flat `otelAttrs` allowlist mixed the layers, so a call site could smuggle `service.name` into the record and contradict its own process identity — the cloud_RoleName cross-layer confusion, at the call site of the package meant to close it. `TestTheSinkReceivesResourceAndRecordSeparately` passed only because the caller happened not to pass one. Now two sets. `tracebloc.component`/`tracebloc.tenant.id` are included even though correctly prefixed — the namespace rule alone waved them past. And `event.name` is refused: it is Emit's first ARGUMENT, so accepting it let a caller replace the name after the grammar and failure-set checks had run. 2. THE PRIMITIVE SWITCH WAS NARROWER THAN GO'S SCALARS. A type switch matches the DYNAMIC type, so `case int64` never matched `time.Duration` — an idiomatic caller writing `Attrs{"tracebloc.elapsed": elapsed}` was told their duration was the retired extraData defect. Now switches on reflect.Kind, so int8/32, uint*, float32 and named types over them all pass. Added `Duration(d) int64` returning MILLISECONDS, and the reason is that time.Duration is an int64 kind and would otherwise pass as a raw nanosecond count — a number nobody reading a dashboard can interpret. 3. AN EMPTY service.instance.id WAS STAMPED. os.Hostname() returns "" on error. Omitted now: the "sent as empty rather than omitted" defect the record layer already refused, which the resource layer did not. 4. DELIVERY IGNORED Exports(). An emitter for an unrecognised env delivered anyway if a sink was installed, so "unknown never exports" lived in caller discipline at every #1907 call site. Gated now — validation still always runs, so a bad event fails in CI wherever the binary is built. 5. A BAD KEY WITH AN EMPTY VALUE PASSED SILENTLY. `normalise` continued on nil/empty BEFORE validating the key, so `Attrs{"experimentKey": nil}` raised nothing — contradicting this package's own "a malformed event must not pass silently". The key is validated first now; a GOOD key with an empty value is still dropped rather than rejected. Finding 1 is the same defect Bugbot found independently in the Python sibling (backend#1996); both are fixed the same way. 31 tests, 100% statement coverage, `make check` green. Six mutations, all caught. Co-Authored-By: Claude Opus 5 --- internal/telemetry/telemetry.go | 83 +++++++++++--- internal/telemetry/telemetry_test.go | 159 +++++++++++++++++++++++++++ 2 files changed, 228 insertions(+), 14 deletions(-) diff --git a/internal/telemetry/telemetry.go b/internal/telemetry/telemetry.go index 7c518ed..305d1bf 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,22 @@ 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 { continue } - if s, ok := value.(string); ok && s == "" { + if s, ok := value.(string); ok && strings.TrimSpace(s) == "" { continue } - if err := checkAttrKey(key); err != nil { - return nil, err - } if err := checkAttrValue(key, value); err != nil { return nil, err } @@ -229,7 +262,15 @@ func checkAttrKey(key string) error { "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 +286,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 +306,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..7636a93 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,161 @@ 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") + } +} From c3a9210a66ad6f985290aa7fcf8f0d809ba435af Mon Sep 17 00:00:00 2001 From: Lukas Wuttke Date: Fri, 14 Aug 2026 17:05:00 +0200 Subject: [PATCH 2/2] fix(telemetry): the omit rule must know what a string is, same as the value check MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Bugbot, and it is fallout from finding 2 in this same PR — the honest kind. I widened `checkAttrValue` to accept every string KIND so `type Reason string` would pass, and left the omit rule type-asserting to builtin `string`. So an empty named string was accepted as a value and never recognised as absent: `Attrs{"tracebloc.reason": Reason(" ")}` landed on the record, reopening §1.2 for exactly the callers the widening was for. The consequence is worse one line down. On a failure, an empty named `error.type` satisfies `checkFailureSet` by key presence alone — a failure that cannot be grouped, reported as one that can. That is the whole point of the required-error.type rule, defeated by a type assertion. `absentValue` now asks by reflect.Kind, the same question `checkAttrValue` asks, because the two have to agree on what a string is. Zero numbers and false bools stay data: they are measurements that happen to be falsey. Three tests — the drop, the failure-set consequence, and the other half (a named string with content arrives, 0 and false are kept). Mutation-proved: restoring the `value.(string)` assertion reddens two of them. The Python sibling had the same class in a different container (arrays bypassed both the omit and size rules); fixed there in backend#1996. Coverage stays 100%. `make check` green. Co-Authored-By: Claude Opus 5 --- internal/telemetry/telemetry.go | 25 +++++++++++-- internal/telemetry/telemetry_test.go | 55 ++++++++++++++++++++++++++++ 2 files changed, 76 insertions(+), 4 deletions(-) diff --git a/internal/telemetry/telemetry.go b/internal/telemetry/telemetry.go index 305d1bf..1795053 100644 --- a/internal/telemetry/telemetry.go +++ b/internal/telemetry/telemetry.go @@ -242,10 +242,7 @@ func normalise(attrs Attrs) (map[string]any, error) { } // §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 { - continue - } - if s, ok := value.(string); ok && strings.TrimSpace(s) == "" { + if absentValue(value) { continue } if err := checkAttrValue(key, value); err != nil { @@ -256,6 +253,26 @@ 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( diff --git a/internal/telemetry/telemetry_test.go b/internal/telemetry/telemetry_test.go index 7636a93..5667bd4 100644 --- a/internal/telemetry/telemetry_test.go +++ b/internal/telemetry/telemetry_test.go @@ -469,3 +469,58 @@ func TestAKeyIsValidatedEvenWhenItsValueIsDropped(t *testing.T) { 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") + } +}