diff --git a/cli/azd/.vscode/cspell.yaml b/cli/azd/.vscode/cspell.yaml index 0d943815dd3..1cc9713d872 100644 --- a/cli/azd/.vscode/cspell.yaml +++ b/cli/azd/.vscode/cspell.yaml @@ -501,6 +501,10 @@ overrides: - filename: internal/cmd/up_graph.go words: - finalizer + - filename: docs/extensions/extension-telemetry.md + words: + - dcount + - isnotempty ignorePaths: - "**/*_test.go" - "**/mock*.go" diff --git a/cli/azd/cmd/telemetry_test.go b/cli/azd/cmd/telemetry_test.go index ff38f49e496..16feb81e7e9 100644 --- a/cli/azd/cmd/telemetry_test.go +++ b/cli/azd/cmd/telemetry_test.go @@ -238,6 +238,14 @@ func TestTelemetryFieldConstants(t *testing.T) { require.Equal(t, "extension.event", string(kv.Key)) require.Equal(t, "deploy.completed", kv.Value.AsString()) + dropped := fields.ExtensionUsageDropped.StringSlice( + []string{"contoso.tools@attribute_value_too_long"}, + ) + require.Equal(t, "extension.usage.dropped", string(dropped.Key)) + + droppedCount := fields.ExtensionUsageDroppedCount.Int64(2) + require.Equal(t, "extension.usage.dropped.count", string(droppedCount.Key)) + category := fields.ExtensionSourceCategory.String("local") require.Equal(t, "extension.source.category", string(category.Key)) diff --git a/cli/azd/docs/extensions/extension-telemetry.md b/cli/azd/docs/extensions/extension-telemetry.md index 192ddc85128..32a1406617d 100644 --- a/cli/azd/docs/extensions/extension-telemetry.md +++ b/cli/azd/docs/extensions/extension-telemetry.md @@ -134,7 +134,9 @@ extension author: Error messages do not echo attribute values. When a valid key has an oversized value, the key is included so you can identify the failing field; invalid keys -are not echoed. Use the status code plus your own call site to diagnose. +are not echoed. Use the status code plus your own call site to diagnose. Hosts +that support dropped-report telemetry also record the bounded reason described +in [Diagnosing dropped reports](#diagnosing-dropped-reports). ## When your event is not recorded @@ -146,7 +148,9 @@ Two outcomes are deliberately **not** errors. The call succeeds and | Your configured source does not match the verified official `azd` registry | Attribute values are never reviewed at runtime, so registry admission is what keeps unchecked content out of `azd`'s pipeline | | The per-invocation event budget is spent | `ReportUsage` can be called in a loop, and the per-event bounds do not limit how many events arrive | -Run `azd` with `--debug` to see which one applied. +Run `azd` with `--debug` to see which one applied. Hosts that support +dropped-report telemetry also record the bounded reason described in +[Diagnosing dropped reports](#diagnosing-dropped-reports). This means **your events are not recorded while you develop locally**, because an extension installed with `--source dev` or from a file path does not pass the @@ -154,6 +158,65 @@ gate. You can still verify your integration end to end: the call succeeds and `Accepted` comes back `false`. Because it is not an error, your code runs the same path in development as in production — do not branch on `Accepted`. +## Diagnosing dropped reports + +`azd` aggregates rejected and dropped calls on the command span that hosted the +extension. It records two fields: + +| Attribute | Meaning | +|---|---| +| `extension.usage.dropped` | Unique `@` values for the invocation | +| `extension.usage.dropped.count` | Total reports dropped during the invocation | + +The reason is always one of these host-defined values: + +| Reason | Cause | +|---|---| +| `event_name_invalid` | The event name is missing or exceeds 128 UTF-8 bytes | +| `attribute_count_exceeded` | The report contains more than 32 attributes | +| `attribute_key_invalid` | An attribute key is empty or exceeds 128 UTF-8 bytes | +| `attribute_value_too_long` | An attribute value exceeds 512 UTF-8 bytes | +| `not_installed` | The calling extension is not installed | +| `lookup_failed` | `azd` could not read the installed extension record | +| `source_check_failed` | `azd` could not verify the configured registry source | +| `source_ineligible` | The configured source is not the verified official registry | +| `budget_exhausted` | The invocation has already recorded 100 extension usage events | +| `unauthenticated` | The request did not contain validated extension claims | + +No event name, key, value, source, or other caller-controlled content is copied +into the signal. Repeated failures add to the count but do not add duplicate +values to the list, so a reporting loop cannot create an unbounded property. +The extension ID appears only after `azd` verifies the installed record against +the official registry source. Earlier failures use the fixed value +`unattributed`. + +Use this query to find how many invocations were affected by each extension and +reason: + +```kusto +requests +| where isnotempty(tostring(customDimensions["extension.usage.dropped"])) +| extend dropped = parse_json(tostring(customDimensions["extension.usage.dropped"])) +| mv-expand dropped +| extend parts = split(tostring(dropped), "@") +| summarize affected_invocations=dcount(operation_Id) + by extension_id=tostring(parts[0]), reason=tostring(parts[1]) +``` + +To inspect total volume separately, sum +`customMeasurements["extension.usage.dropped.count"]`. The fields appear only +on the command span that hosted the extension; synthetic phase spans created by +`azd up` do not copy them. The count covers all reasons in an invocation, so do +not assign it to one reason when the list contains several values. + +Accepted `ext.usage` spans and the command span share `operation_Id`. Use that +field with `extension.id` to compare affected invocations with invocations that +successfully recorded at least one report. + +For a long-running server command, such as `azd vs-server`, the invocation ends +when the `azd` process exits. Its aggregate therefore covers the process +lifetime rather than one RPC. + ## Where the data lands Each accepted event becomes an `ext.usage` span carrying `extension.id`, diff --git a/cli/azd/internal/cmd/up_graph.go b/cli/azd/internal/cmd/up_graph.go index 8f40f177158..978af16be0d 100644 --- a/cli/azd/internal/cmd/up_graph.go +++ b/cli/azd/internal/cmd/up_graph.go @@ -192,7 +192,7 @@ func (u *UpGraphAction) Run( // Apply usage attributes (e.g. EnvNameKey) at end so they include // any values set during Run. Globals (e.g. SubscriptionIdKey) are // applied automatically by wrapperSpan.End(). - usageAttrs := tracing.GetUsageAttributes() + usageAttrs := syntheticUpUsageAttributes() // Reflect the real package-phase outcome. Before this, the synthetic // span always closed with an Unset status (=> Success in the AppInsights @@ -800,6 +800,16 @@ func changedFlagNames(fs *pflag.FlagSet) []string { return names } +// syntheticUpUsageAttributes returns usage attributes for the synthetic +// cmd.package, cmd.provision, and cmd.deploy spans. Extension drop attributes +// stay on the hosting cmd.up span so invocation totals are not duplicated. +func syntheticUpUsageAttributes() []attribute.KeyValue { + return slices.DeleteFunc(tracing.GetUsageAttributes(), func(attr attribute.KeyValue) bool { + return attr.Key == fields.ExtensionUsageDropped.Key || + attr.Key == fields.ExtensionUsageDroppedCount.Key + }) +} + // initializeServices enumerates services, initializes the project, and ensures // that required service target tools are available. func (u *UpGraphAction) initializeServices(ctx context.Context) ([]*project.ServiceConfig, error) { diff --git a/cli/azd/internal/cmd/up_graph_telemetry_test.go b/cli/azd/internal/cmd/up_graph_telemetry_test.go index 4042ccc80af..6daf3d47995 100644 --- a/cli/azd/internal/cmd/up_graph_telemetry_test.go +++ b/cli/azd/internal/cmd/up_graph_telemetry_test.go @@ -10,10 +10,13 @@ import ( "testing" "time" + "github.com/azure/azure-dev/cli/azd/internal/tracing" + "github.com/azure/azure-dev/cli/azd/internal/tracing/fields" "github.com/azure/azure-dev/cli/azd/pkg/exegraph" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "go.opentelemetry.io/otel" + "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/codes" tracesdk "go.opentelemetry.io/otel/sdk/trace" "go.opentelemetry.io/otel/sdk/trace/tracetest" @@ -638,6 +641,28 @@ func TestEmitDeploySpan_ErrorPath(t *testing.T) { assert.True(t, end.Equal(span.EndTime()), "end = %s, want %s", span.EndTime(), end) } +func TestSyntheticUpUsageAttributesExcludeExtensionDrops(t *testing.T) { + tracing.ResetUsageAttributesForTest() + t.Cleanup(tracing.ResetUsageAttributesForTest) + + const retainedKey = attribute.Key("test.retained") + tracing.SetUsageAttributes( + retainedKey.String("value"), + fields.ExtensionUsageDropped.StringSlice([]string{"publisher.extension@budget_exhausted"}), + fields.ExtensionUsageDroppedCount.Int64(1), + ) + + attrs := syntheticUpUsageAttributes() + indexed := map[attribute.Key]attribute.Value{} + for _, attr := range attrs { + indexed[attr.Key] = attr.Value + } + + require.Contains(t, indexed, retainedKey) + assert.NotContains(t, indexed, fields.ExtensionUsageDropped.Key) + assert.NotContains(t, indexed, fields.ExtensionUsageDroppedCount.Key) +} + // TestEmitDeploySpan_OmittedWhenDeployDidNotRun verifies the other half of the // contract: when provisioning fails first and the deploy phase is skipped before // it starts, no cmd.deploy span is emitted — matching legacy `azd up`, where the diff --git a/cli/azd/internal/grpcserver/server.go b/cli/azd/internal/grpcserver/server.go index e4184ea2606..e7ed4743124 100644 --- a/cli/azd/internal/grpcserver/server.go +++ b/cli/azd/internal/grpcserver/server.go @@ -235,6 +235,9 @@ func (s *Server) tokenAuthInterceptor(serverInfo *ServerInfo) grpc.UnaryServerIn ) (any, error) { ctx, err := s.validateAuthToken(ctx, serverInfo) if err != nil { + if info.FullMethod == azdext.TelemetryService_ReportUsage_FullMethodName { + recordExtensionUsageDrop(unattributedExtensionId, extensionUsageDropReasonUnauthenticated) + } return nil, err } diff --git a/cli/azd/internal/grpcserver/server_test.go b/cli/azd/internal/grpcserver/server_test.go index 442ce8e6c8b..6d073b1d115 100644 --- a/cli/azd/internal/grpcserver/server_test.go +++ b/cli/azd/internal/grpcserver/server_test.go @@ -26,6 +26,7 @@ import ( "google.golang.org/protobuf/proto" "github.com/azure/azure-dev/cli/azd/internal" + "github.com/azure/azure-dev/cli/azd/internal/tracing" "github.com/azure/azure-dev/cli/azd/pkg/account" "github.com/azure/azure-dev/cli/azd/pkg/auth" "github.com/azure/azure-dev/cli/azd/pkg/azapi" @@ -187,6 +188,9 @@ func Test_Server_Start(t *testing.T) { }) t.Run("TelemetryMissingToken", func(t *testing.T) { + tracing.ResetUsageAttributesForTest() + t.Cleanup(tracing.ResetUsageAttributesForTest) + client, err := azdext.NewAzdClient(azdext.WithAddress(serverInfo.Address)) require.NoError(t, err) @@ -197,6 +201,8 @@ func Test_Server_Start(t *testing.T) { st, ok := status.FromError(err) require.True(t, ok) require.Equal(t, codes.Unauthenticated, st.Code()) + requireUsageDrop(t, unattributedExtensionId, + []extensionUsageDropReason{extensionUsageDropReasonUnauthenticated}, 1) }) } diff --git a/cli/azd/internal/grpcserver/telemetry_service.go b/cli/azd/internal/grpcserver/telemetry_service.go index 5497d7dcf75..ccc5bb9b726 100644 --- a/cli/azd/internal/grpcserver/telemetry_service.go +++ b/cli/azd/internal/grpcserver/telemetry_service.go @@ -43,6 +43,23 @@ const ( maxUsageEventsPerInvocation = 100 ) +type extensionUsageDropReason string + +const ( + extensionUsageDropReasonEventNameInvalid extensionUsageDropReason = "event_name_invalid" + extensionUsageDropReasonAttributeCountExceeded extensionUsageDropReason = "attribute_count_exceeded" + extensionUsageDropReasonAttributeKeyInvalid extensionUsageDropReason = "attribute_key_invalid" + extensionUsageDropReasonAttributeValueTooLong extensionUsageDropReason = "attribute_value_too_long" + extensionUsageDropReasonNotInstalled extensionUsageDropReason = "not_installed" + extensionUsageDropReasonLookupFailed extensionUsageDropReason = "lookup_failed" + extensionUsageDropReasonSourceCheckFailed extensionUsageDropReason = "source_check_failed" + extensionUsageDropReasonSourceIneligible extensionUsageDropReason = "source_ineligible" + extensionUsageDropReasonBudgetExhausted extensionUsageDropReason = "budget_exhausted" + extensionUsageDropReasonUnauthenticated extensionUsageDropReason = "unauthenticated" + + unattributedExtensionId = "unattributed" +) + // installedExtensionLookup resolves the installed extension record for a // signed extension id. *extensions.Manager satisfies it. type installedExtensionLookup interface { @@ -92,24 +109,24 @@ func (s *telemetryService) ReportUsage( ) (*azdext.ReportUsageResponse, error) { claims, err := extensions.GetClaimsFromContext(ctx) if err != nil { + recordExtensionUsageDrop(unattributedExtensionId, extensionUsageDropReasonUnauthenticated) return nil, status.Error(codes.Unauthenticated, "validated extension claims are required") } - if err := validateUsageRequest(req); err != nil { - return nil, err - } - extension, err := s.extensions.GetInstalled(extensions.FilterOptions{Id: claims.Subject}) if err != nil { if errors.Is(err, extensions.ErrInstalledExtensionNotFound) { + recordExtensionUsageDrop(unattributedExtensionId, extensionUsageDropReasonNotInstalled) return nil, status.Error(codes.PermissionDenied, "extension is not installed") } + recordExtensionUsageDrop(unattributedExtensionId, extensionUsageDropReasonLookupFailed) return nil, status.Error(codes.Internal, "failed to verify installed extension") } official, err := s.extensions.IsOfficialRegistrySource(ctx, extension.Source) if err != nil { + recordExtensionUsageDrop(unattributedExtensionId, extensionUsageDropReasonSourceCheckFailed) log.Printf( "telemetry: failed to verify source %q for %s: %v", extension.Source, extension.Id, err) @@ -117,6 +134,7 @@ func (s *telemetryService) ReportUsage( } if !official { + recordExtensionUsageDrop(unattributedExtensionId, extensionUsageDropReasonSourceIneligible) log.Printf( "telemetry: dropping usage event from %s installed from source %q", extension.Id, extension.Source) @@ -124,6 +142,11 @@ func (s *telemetryService) ReportUsage( return &azdext.ReportUsageResponse{Accepted: false}, nil } + if reason, err := validateUsageRequest(req); err != nil { + recordExtensionUsageDrop(extension.Id, reason) + return nil, err + } + attributes := []attribute.KeyValue{ fields.ExtensionId.String(extension.Id), fields.ExtensionVersion.String(extension.Version), @@ -141,6 +164,7 @@ func (s *telemetryService) ReportUsage( // a container singleton, which makes it a per-invocation budget // even when a composite command such as up runs several actions. if s.recorded.Add(1) > maxUsageEventsPerInvocation { + recordExtensionUsageDrop(extension.Id, extensionUsageDropReasonBudgetExhausted) log.Printf( "telemetry: dropping usage event %q from %s, limit of %d reached", req.EventName, extension.Id, maxUsageEventsPerInvocation) @@ -158,31 +182,40 @@ func (s *telemetryService) ReportUsage( return &azdext.ReportUsageResponse{Accepted: true}, nil } -func validateUsageRequest(req *azdext.ReportUsageRequest) error { +func recordExtensionUsageDrop(extensionId string, reason extensionUsageDropReason) { + tracing.AppendUsageAttributeUnique( + fields.ExtensionUsageDropped.String(extensionId + "@" + string(reason)), + ) + tracing.IncrementUsageAttribute(fields.ExtensionUsageDroppedCount.Int64(1)) +} + +func validateUsageRequest(req *azdext.ReportUsageRequest) (extensionUsageDropReason, error) { if req == nil || req.EventName == "" || len(req.EventName) > maxUsageEventNameBytes { - return status.Errorf(codes.InvalidArgument, + return extensionUsageDropReasonEventNameInvalid, status.Errorf(codes.InvalidArgument, "event name is required and must be at most %d UTF-8 bytes", maxUsageEventNameBytes) } if len(req.Attributes) > maxUsageAttributes { - return status.Errorf(codes.InvalidArgument, + return extensionUsageDropReasonAttributeCountExceeded, status.Errorf(codes.InvalidArgument, "event declares more than %d attributes", maxUsageAttributes) } - for key, value := range req.Attributes { + for key := range req.Attributes { if key == "" || len(key) > maxUsageKeyBytes { - return status.Errorf(codes.InvalidArgument, + return extensionUsageDropReasonAttributeKeyInvalid, status.Errorf(codes.InvalidArgument, "attribute keys are required and must be at most %d UTF-8 bytes", maxUsageKeyBytes) } + } + for key, value := range req.Attributes { if len(value) > maxUsageValueBytes { - return status.Errorf(codes.InvalidArgument, + return extensionUsageDropReasonAttributeValueTooLong, status.Errorf(codes.InvalidArgument, "attribute value for key %q must be at most %d UTF-8 bytes", key, maxUsageValueBytes) } } - return nil + return "", nil } diff --git a/cli/azd/internal/grpcserver/telemetry_service_test.go b/cli/azd/internal/grpcserver/telemetry_service_test.go index dd4c90b3171..15835191973 100644 --- a/cli/azd/internal/grpcserver/telemetry_service_test.go +++ b/cli/azd/internal/grpcserver/telemetry_service_test.go @@ -12,6 +12,7 @@ import ( "sync/atomic" "testing" + "github.com/azure/azure-dev/cli/azd/internal/tracing" "github.com/azure/azure-dev/cli/azd/internal/tracing/events" "github.com/azure/azure-dev/cli/azd/internal/tracing/fields" "github.com/azure/azure-dev/cli/azd/pkg/azdext" @@ -31,6 +32,7 @@ const testExtensionId = "azd.internal.telemetry" type stubExtensionLookup struct { extension *extensions.Extension err error + sourceErr error sourceConfigs map[string]*extensions.SourceConfig } @@ -52,6 +54,10 @@ func (s stubExtensionLookup) IsOfficialRegistrySource( ctx context.Context, name string, ) (bool, error) { + if s.sourceErr != nil { + return false, s.sourceErr + } + if s.sourceConfigs == nil { return strings.EqualFold(name, extensions.MainRegistryName), nil } @@ -149,6 +155,35 @@ func attributesOf(span tracesdk.ReadOnlySpan) map[attribute.Key]attribute.Value return indexed } +func requireUsageDrop( + t *testing.T, + extensionId string, + reasons []extensionUsageDropReason, + count int64, +) { + t.Helper() + + expected := make([]string, len(reasons)) + for i, reason := range reasons { + expected[i] = extensionId + "@" + string(reason) + } + requireUsageDropEntries(t, expected, count) +} + +func requireUsageDropEntries(t *testing.T, expected []string, count int64) { + t.Helper() + + attributes := map[attribute.Key]attribute.Value{} + for _, attr := range tracing.GetUsageAttributes() { + attributes[attr.Key] = attr.Value + } + + require.Contains(t, attributes, fields.ExtensionUsageDropped.Key) + require.Contains(t, attributes, fields.ExtensionUsageDroppedCount.Key) + require.ElementsMatch(t, expected, attributes[fields.ExtensionUsageDropped.Key].AsStringSlice()) + require.Equal(t, count, attributes[fields.ExtensionUsageDroppedCount.Key].AsInt64()) +} + func requireCode(t *testing.T, err error, expected codes.Code) { t.Helper() @@ -314,27 +349,33 @@ func Test_TelemetryService_RejectsPollutedMainSource(t *testing.T) { require.Empty(t, usageSpansIn(command.SpanContext().TraceID())) } -func Test_TelemetryService_ValidatesBeforeSourceGate(t *testing.T) { - t.Parallel() +func Test_TelemetryService_AppliesSourceGateBeforeValidation(t *testing.T) { + tracing.ResetUsageAttributesForTest() + t.Cleanup(tracing.ResetUsageAttributesForTest) extension := testExtension() extension.Source = "dev" service := newTelemetryService(stubExtensionLookup{extension: extension}) - _, err := callServiceWithContext(t, service, t.Context(), extension, + resp, err := callServiceWithContext(t, service, t.Context(), extension, &azdext.ReportUsageRequest{ EventName: "deploy.completed", Attributes: map[string]string{ "deploy.mode": strings.Repeat("v", maxUsageValueBytes+1), }, }) - requireCode(t, err, codes.InvalidArgument) + require.NoError(t, err) + require.False(t, resp.Accepted) require.Zero(t, service.recorded.Load()) + requireUsageDrop(t, unattributedExtensionId, + []extensionUsageDropReason{extensionUsageDropReasonSourceIneligible}, 1) - resp, err := callServiceWithContext(t, service, t.Context(), extension, + resp, err = callServiceWithContext(t, service, t.Context(), extension, &azdext.ReportUsageRequest{EventName: "deploy.completed"}) require.NoError(t, err) require.False(t, resp.Accepted) + requireUsageDrop(t, unattributedExtensionId, + []extensionUsageDropReason{extensionUsageDropReasonSourceIneligible}, 2) } func Test_TelemetryService_CapsEventsPerInvocation(t *testing.T) { @@ -447,6 +488,148 @@ func Test_TelemetryService_RecordsNoSpanWhenRejected(t *testing.T) { require.Empty(t, usageSpansIn(command.SpanContext().TraceID())) } +func Test_TelemetryService_RecordsOperationalDropReasons(t *testing.T) { + tests := []struct { + name string + lookup stubExtensionLookup + withoutClaims bool + recorded int64 + expectedCode codes.Code + expectedId string + expectedReason extensionUsageDropReason + }{ + { + name: "unauthenticated", + lookup: stubExtensionLookup{extension: testExtension()}, + withoutClaims: true, + expectedCode: codes.Unauthenticated, + expectedId: unattributedExtensionId, + expectedReason: extensionUsageDropReasonUnauthenticated, + }, + { + name: "not installed", + lookup: stubExtensionLookup{}, + expectedCode: codes.PermissionDenied, + expectedId: unattributedExtensionId, + expectedReason: extensionUsageDropReasonNotInstalled, + }, + { + name: "lookup failed", + lookup: stubExtensionLookup{ + err: errors.New("failed to read installed config"), + }, + expectedCode: codes.Internal, + expectedId: unattributedExtensionId, + expectedReason: extensionUsageDropReasonLookupFailed, + }, + { + name: "source check failed", + lookup: stubExtensionLookup{ + extension: testExtension(), + sourceErr: errors.New("failed to read source config"), + }, + expectedCode: codes.OK, + expectedId: unattributedExtensionId, + expectedReason: extensionUsageDropReasonSourceCheckFailed, + }, + { + name: "source ineligible", + lookup: stubExtensionLookup{ + extension: &extensions.Extension{ + Id: testExtensionId, + Version: "1.0.0", + Source: "dev", + }, + }, + expectedCode: codes.OK, + expectedId: unattributedExtensionId, + expectedReason: extensionUsageDropReasonSourceIneligible, + }, + { + name: "budget exhausted", + lookup: stubExtensionLookup{extension: testExtension()}, + recorded: maxUsageEventsPerInvocation, + expectedCode: codes.OK, + expectedId: testExtensionId, + expectedReason: extensionUsageDropReasonBudgetExhausted, + }, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + tracing.ResetUsageAttributesForTest() + t.Cleanup(tracing.ResetUsageAttributesForTest) + + service := newTelemetryService(test.lookup) + service.recorded.Store(test.recorded) + + ctx := t.Context() + if !test.withoutClaims { + ctx = extensions.WithClaimsContext(ctx, &extensions.ExtensionClaims{ + RegisteredClaims: jwt.RegisteredClaims{Subject: testExtensionId}, + }) + } + + resp, err := service.ReportUsage(ctx, &azdext.ReportUsageRequest{ + EventName: "deploy.completed", + }) + if test.expectedCode == codes.OK { + require.NoError(t, err) + require.False(t, resp.Accepted) + } else { + requireCode(t, err, test.expectedCode) + } + + requireUsageDrop(t, test.expectedId, []extensionUsageDropReason{test.expectedReason}, 1) + }) + } +} + +func Test_TelemetryService_AggregatesAndDeduplicatesDrops(t *testing.T) { + tracing.ResetUsageAttributesForTest() + t.Cleanup(tracing.ResetUsageAttributesForTest) + + extension := testExtension() + extension.Source = "dev" + ineligibleService := newTelemetryService(stubExtensionLookup{extension: extension}) + + for range 2 { + resp, err := callServiceWithContext(t, ineligibleService, t.Context(), extension, + &azdext.ReportUsageRequest{EventName: "deploy.completed"}) + require.NoError(t, err) + require.False(t, resp.Accepted) + } + + officialExtension := testExtension() + officialService := newTelemetryService(stubExtensionLookup{extension: officialExtension}) + _, err := callServiceWithContext(t, officialService, t.Context(), officialExtension, + &azdext.ReportUsageRequest{ + EventName: "deploy.completed", + Attributes: map[string]string{ + "deploy.mode": strings.Repeat("v", maxUsageValueBytes+1), + }, + }) + requireCode(t, err, codes.InvalidArgument) + + requireUsageDropEntries(t, []string{ + unattributedExtensionId + "@" + string(extensionUsageDropReasonSourceIneligible), + officialExtension.Id + "@" + string(extensionUsageDropReasonAttributeValueTooLong), + }, 3) +} + +func Test_TelemetryService_AcceptedReportDoesNotRecordDrop(t *testing.T) { + tracing.ResetUsageAttributesForTest() + t.Cleanup(tracing.ResetUsageAttributesForTest) + + resp, err := callWith(t, testExtension(), &azdext.ReportUsageRequest{ + EventName: "deploy.completed", + }) + + require.NoError(t, err) + require.True(t, resp.Accepted) + require.Empty(t, tracing.GetUsageAttributes()) +} + func Test_TelemetryService_RequiresClaims(t *testing.T) { t.Parallel() @@ -459,47 +642,80 @@ func Test_TelemetryService_RequiresClaims(t *testing.T) { } func Test_TelemetryService_RejectsInvalidRequests(t *testing.T) { - t.Parallel() - tooManyAttributes := map[string]string{} for i := range maxUsageAttributes + 1 { tooManyAttributes[fmt.Sprintf("key%d", i)] = "value" } - tests := map[string]*azdext.ReportUsageRequest{ - "nil": nil, - "missing eventName": {}, + tests := map[string]struct { + request *azdext.ReportUsageRequest + reason extensionUsageDropReason + }{ + "nil": { + reason: extensionUsageDropReasonEventNameInvalid, + }, + "missing eventName": { + request: &azdext.ReportUsageRequest{}, + reason: extensionUsageDropReasonEventNameInvalid, + }, "long eventName": { - EventName: strings.Repeat("e", maxUsageEventNameBytes+1), + request: &azdext.ReportUsageRequest{ + EventName: strings.Repeat("e", maxUsageEventNameBytes+1), + }, + reason: extensionUsageDropReasonEventNameInvalid, }, "empty key": { - EventName: "deploy.completed", - Attributes: map[string]string{"": "container"}, + request: &azdext.ReportUsageRequest{ + EventName: "deploy.completed", + Attributes: map[string]string{"": "container"}, + }, + reason: extensionUsageDropReasonAttributeKeyInvalid, }, "long key": { - EventName: "deploy.completed", - Attributes: map[string]string{ - strings.Repeat("k", maxUsageKeyBytes+1): "container", + request: &azdext.ReportUsageRequest{ + EventName: "deploy.completed", + Attributes: map[string]string{ + strings.Repeat("k", maxUsageKeyBytes+1): "container", + }, }, + reason: extensionUsageDropReasonAttributeKeyInvalid, }, "long value": { - EventName: "deploy.completed", - Attributes: map[string]string{ - "deploy.mode": strings.Repeat("v", maxUsageValueBytes+1), + request: &azdext.ReportUsageRequest{ + EventName: "deploy.completed", + Attributes: map[string]string{ + "deploy.mode": strings.Repeat("v", maxUsageValueBytes+1), + }, }, + reason: extensionUsageDropReasonAttributeValueTooLong, + }, + "invalid key takes precedence over long value": { + request: &azdext.ReportUsageRequest{ + EventName: "deploy.completed", + Attributes: map[string]string{ + "": "container", + "deploy.mode": strings.Repeat("v", maxUsageValueBytes+1), + }, + }, + reason: extensionUsageDropReasonAttributeKeyInvalid, }, "too many attributes": { - EventName: "deploy.completed", - Attributes: tooManyAttributes, + request: &azdext.ReportUsageRequest{ + EventName: "deploy.completed", + Attributes: tooManyAttributes, + }, + reason: extensionUsageDropReasonAttributeCountExceeded, }, } - for name, req := range tests { + for name, test := range tests { t.Run(name, func(t *testing.T) { - t.Parallel() + tracing.ResetUsageAttributesForTest() + t.Cleanup(tracing.ResetUsageAttributesForTest) - _, err := callWith(t, testExtension(), req) + _, err := callWith(t, testExtension(), test.request) requireCode(t, err, codes.InvalidArgument) + requireUsageDrop(t, testExtensionId, []extensionUsageDropReason{test.reason}, 1) }) } } diff --git a/cli/azd/internal/tracing/fields/fields.go b/cli/azd/internal/tracing/fields/fields.go index eb5b2830fea..efc86d5a25e 100644 --- a/cli/azd/internal/tracing/fields/fields.go +++ b/cli/azd/internal/tracing/fields/fields.go @@ -1227,6 +1227,21 @@ var ( Classification: SystemMetadata, Purpose: FeatureInsight, } + // ExtensionUsageDropped records each extension and fixed reason for which + // at least one usage report was dropped during the invocation. + ExtensionUsageDropped = AttributeKey{ + Key: attribute.Key("extension.usage.dropped"), + Classification: SystemMetadata, + Purpose: PerformanceAndHealth, + } + // ExtensionUsageDroppedCount is the total number of extension usage reports + // dropped during the invocation. + ExtensionUsageDroppedCount = AttributeKey{ + Key: attribute.Key("extension.usage.dropped.count"), + Classification: SystemMetadata, + Purpose: PerformanceAndHealth, + IsMeasurement: true, + } // The list of installed extensions, each formatted as "id@version". ExtensionsInstalled = AttributeKey{ Key: attribute.Key("extension.installed"), diff --git a/docs/architecture/adr-001-extension-telemetry-events.md b/docs/architecture/adr-001-extension-telemetry-events.md index 67953427285..96824ace969 100644 --- a/docs/architecture/adr-001-extension-telemetry-events.md +++ b/docs/architecture/adr-001-extension-telemetry-events.md @@ -72,6 +72,10 @@ records events from extensions admitted to the official registry.** best effort, so an author runs the same code path during local development as in production instead of having to swallow an error that only appears in one of them. The reason is written to the `azd` log, visible with `--debug`. +- Rejected and dropped calls are summarized on the command span as a unique, + bounded set of `@` values plus a total count. The host + chooses the reason from a fixed enum and never copies caller-controlled event + or attribute content into the signal. - `extension.source` is still recorded on the span. Once the verified source gate has passed it is a useful dimension rather than a filter. - Accepted events are recorded on an `ext.usage` span rather than being appended @@ -161,6 +165,19 @@ blanket ignore that also hides real bugs. The response already carries an `accepted` flag, so the outcome is stated rather than silent, and the drop reason goes to the `azd` log. +**Emit one span for every rejected or dropped report.** Rejected because the +extension controls call volume, and invalid calls deliberately do not spend the +accepted-event budget. A reporting loop would therefore create an unbounded +telemetry loop unless drop spans had a second budget, which would need its own +dropped-signal behavior. Per-drop rows would also make a looping extension +dominate the signal. A unique extension-and-reason set per invocation measures +affected users while a separate bounded measurement preserves total volume. +The extension ID is included only after the installed record passes the +official-source gate; failures before admission use a fixed `unattributed` +identity. The aggregate remains on the hosting command span rather than being +copied to synthetic `azd up` phase spans, which prevents one invocation from +multiplying its count downstream. + **Make telemetry a capability.** Rejected per review feedback: capabilities signal "this extension provides a customer-facing feature the host needs to call", not "this extension consumes a host service". diff --git a/docs/reference/telemetry-data.md b/docs/reference/telemetry-data.md index caff93eebd0..3b42a77df79 100644 --- a/docs/reference/telemetry-data.md +++ b/docs/reference/telemetry-data.md @@ -472,6 +472,8 @@ Emitted at provision start by the `microsoft.foundry` provisioning provider (the | `extension.id` | string | Extension identifier | | `extension.version` | string | Extension version | | `extension.event` | string | Extension-chosen event name on an `ext.usage` span | +| `extension.usage.dropped` | string[] | Unique `@` entries for extension usage reports dropped during the invocation | +| `extension.usage.dropped.count` | measurement | Total extension usage reports dropped during the invocation | | `ext.` | string | One extension-supplied attribute on an `ext.usage` span. The key after the `ext.` prefix and the value are chosen by the extension | | `ext.route` | string | Local-client route selected by `azure.ai.agents`: `inspector`, `playground`, or `suppressed` (`local_client.route.selected`) | | `ext.stage` | string | Agent Inspector funnel stage: currently `ui_ready` (`inspector.funnel.stage`) | @@ -501,9 +503,15 @@ content, and for having them privacy reviewed with their extension. Only extensions whose configured `azd` source matches the verified official registry name, type, and normalized URL produce these spans, which is what ties the recorded values to that privacy review. A report from any other install -source succeeds but records nothing, as does any report past the limit of 100 -spans per `azd` invocation. This is a configuration-based admission check, not -a cryptographic provenance guarantee. +source succeeds without producing an `ext.usage` span, as does any report past +the limit of 100 spans per `azd` invocation. This is a configuration-based +admission check, not a cryptographic provenance guarantee. Rejected and dropped +calls are summarized on the command span using `extension.usage.dropped` and +`extension.usage.dropped.count`. The list contains an extension ID only after +the installed record passes the official-source check; earlier failures use the +fixed `unattributed` value. It never contains caller-supplied event or attribute +content. These fields stay on the hosting command span and are not copied to +the synthetic phase spans emitted by `azd up`. Reviewed first-party extension usage events currently include: diff --git a/docs/specs/metrics-audit/feature-telemetry-matrix.md b/docs/specs/metrics-audit/feature-telemetry-matrix.md index a4dad469cf2..d15586d8c45 100644 --- a/docs/specs/metrics-audit/feature-telemetry-matrix.md +++ b/docs/specs/metrics-audit/feature-telemetry-matrix.md @@ -168,7 +168,7 @@ reserved field contracts. | **Agent troubleshoot middleware** | Triggered on command failure when troubleshooting is engaged | `agent.troubleshoot` | Error chain attributes, hashed error fields | Emitted from `cmd/middleware/error.go` | | **Up-graph performance** | `up` (graph execution) | (none — enriches the `up` command span) | `perf.provision_duration_ms`, `perf.deploy_duration_ms`, `perf.total_duration_ms` | Emitted from `internal/cmd/up_graph.go` after the graph completes; provision/deploy durations set only when those phases run | | **VS RPC** | `vs-server` long-running session | `vsrpc.*` (event prefix) | Per-RPC attributes documented in `telemetry-schema.md` | Long-running RPC server for VS integration | -| **Extension telemetry service** | Extension calls `ReportUsage` over the extension gRPC API | `ext.usage` | `extension.id`, `extension.version`, `extension.source`, `extension.event`, plus one `ext.` attribute per entry in the caller's attribute map | Telemetry requires no separate capability or declaration. Only extensions whose configured source matches the verified official `azd` registry name, type, and normalized URL are recorded — a call from any other source succeeds but is dropped, as is any call past 100 recorded events per `azd` invocation. Identity fields are derived from host-signed claims and the installed record, never from the request. Every caller key is prefixed with `ext.` so it cannot overwrite a host field, and the host bounds count and length only — it does not enumerate or pattern-check values | +| **Extension telemetry service** | Extension calls `ReportUsage` over the extension gRPC API | `ext.usage`; drop aggregates enrich the command span | Accepted reports: `extension.id`, `extension.version`, `extension.source`, `extension.event`, plus one `ext.` per caller attribute. Dropped reports: `extension.usage.dropped`, `extension.usage.dropped.count` | Telemetry requires no separate capability or declaration. Only extensions whose configured source matches the verified official `azd` registry name, type, and normalized URL are recorded. Calls from other sources and calls past the 100-event budget are dropped. All rejected and dropped paths append a unique `@` entry and increment a total count on the command span. Reasons are a fixed host enum, so caller content never enters the drop signal. Identity fields are derived from host-signed claims and the installed record, never from the request. Every caller key is prefixed with `ext.` so it cannot overwrite a host field, and the host bounds count and length only; it does not enumerate or pattern-check values | | **Azure AI Agents local-client routing** | `azd ai agent run` resolves the service and protocol profile | `ext.usage` with `extension.event=local_client.route.selected` | `ext.route` (`inspector`, `playground`, or `suppressed`) | Records one mutually exclusive route before client availability, agent startup, and client launch; suppression takes precedence and the event does not indicate launch success | | **Agent Inspector UI readiness** | Inspector SPA sends `setViewReady` after mounting | `ext.usage` with `extension.event=inspector.funnel.stage` | `ext.stage=ui_ready`, `ext.outcome=succeeded` | Emitted at most once per Inspector process; proves the SPA loaded, not that it connected to an agent | | **App detection** | `init`, `up` (fresh projects without `azure.yaml`, via `appdetect.Detect`) | `aspire.apphost.unsupported` | `aspire.apphost.language` (fixed enum — `typescript` / `python` / `go` / `java` / `rust`; not hashed) | Emitted from `internal/appdetect/dotnet_apphost.go` when an Aspire polyglot (non-C#) AppHost is detected; azd surfaces an actionable error referencing [#7138](https://github.com/Azure/azure-dev/issues/7138) instead of falling through to a generic source build | diff --git a/docs/specs/metrics-audit/telemetry-schema.md b/docs/specs/metrics-audit/telemetry-schema.md index 99cd7e26894..76794da3433 100644 --- a/docs/specs/metrics-audit/telemetry-schema.md +++ b/docs/specs/metrics-audit/telemetry-schema.md @@ -218,6 +218,8 @@ not emitted by azd spans. |-------|----------|----------------|---------|-------| | Extension ID | `extension.id` | SystemMetadata | FeatureInsight | | | Extension version | `extension.version` | SystemMetadata | FeatureInsight | | +| Dropped extension usage reports | `extension.usage.dropped` | SystemMetadata | PerformanceAndHealth | Unique `@` entries per invocation. The extension ID is included only after official-source admission; earlier failures use fixed `unattributed`. Reasons: `event_name_invalid`, `attribute_count_exceeded`, `attribute_key_invalid`, `attribute_value_too_long`, `not_installed`, `lookup_failed`, `source_check_failed`, `source_ineligible`, `budget_exhausted`, `unauthenticated` | +| Dropped extension usage report count | `extension.usage.dropped.count` | SystemMetadata | PerformanceAndHealth | **Measurement** — total dropped reports in the invocation | | Extension installed | `extension.installed` | SystemMetadata | FeatureInsight | List of installed extensions, each formatted `id@version` | | Installed extension source category | `extension.installed.source.category` | SystemMetadata | FeatureInsight | List formatted `id@category`; categories: `azd`, `dev`, `nightly`, `local`, `bundle`, `other`, `unknown` | | Extension version from | `extension.version.from` | SystemMetadata | FeatureInsight | Installed version before an update | @@ -244,10 +246,11 @@ guarantees about the whole class: | Rule | Enforcement | |------|-------------| -| Eligibility | Only extensions whose configured `azd` source matches the verified official registry name, type, and normalized URL produce `ext.usage` spans. A call from any other source succeeds but is dropped without recording | +| Eligibility | Only extensions whose configured `azd` source matches the verified official registry name, type, and normalized URL produce `ext.usage` spans. A call from any other source succeeds without producing an `ext.usage` span, while the command-span drop fields are still recorded | | Key namespace | Every caller-supplied key is prefixed with `ext.` by the host, so it can never overwrite a host-owned attribute | | Size | At most 32 attributes per event; event name and keys at most 128 UTF-8 bytes; values at most 512 UTF-8 bytes | -| Volume | At most 100 `ext.usage` spans per `azd` invocation across all extensions; calls beyond that are dropped without recording | +| Volume | At most 100 `ext.usage` spans per `azd` invocation across all extensions; calls beyond that produce no `ext.usage` span, while the command-span drop fields are still recorded | +| Drop observability | Rejected and dropped calls append one unique `@` value to `extension.usage.dropped` on the hosting command span and increment `extension.usage.dropped.count`. IDs appear only after official-source admission; earlier failures use fixed `unattributed`. Synthetic `azd up` phase spans do not copy these fields. Reasons are fixed by the host, and no caller-controlled event or attribute content is copied | | Values | Not enumerated or pattern-checked. The extension author owns what a value means and is responsible for keeping it low cardinality and free of customer content | | Classification | Always `SystemMetadata` | | Purpose | Always `FeatureInsight` |