perf(security): log device binding once per Graph lookup, not per request

Measured on the first live enrollment: 136 agent requests produced exactly
ONE Graph call, because the 30-minute positive cache absorbed the rest. So
the check is not a throttling risk (the per-request Autopilot serial
validator made 25 calls in the same window) and the positive TTL needs no
change — raising it would only delay noticing a wiped or removed device.

What the 136 requests did cost was 136 log lines all saying the same thing.
Gate the shadow log on ServedFromCache so it emits one line per real lookup.
Cached repeats carry no new information: the reported age just counts up
mechanically from the same enrolledDateTime. Outcomes that are never cached
(Transient, NoDeviceIdInCert) keep logging every time, which is what an
anomaly warrants.

AsCacheHit() copies rather than marking the shared cached instance, so the
first real lookup is never mistaken for a cache hit and dropped.

Backend 4631/4631, 0 warnings.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

docs/backend/client-cert-tenant-binding.md

@@ -129,6 +129,19 @@ Outcomes: `Match`, `NotFound`, `NoDeviceIdInCert`, `PermissionMissing`, `Transie
 `Transient` is retried and left uncached — a missing grant or a foreign device is a state, not an
 outage.
 
+Graph cost is not a concern, and that is measured rather than assumed: the first live enrollment
+produced **136 requests and exactly one Graph call**, because the 30-minute positive cache absorbs
+the rest. For comparison, the per-request Autopilot serial validator made 25 calls in the same
+window. Lengthening the positive TTL would buy nothing and would delay noticing a device that has
+been wiped or removed; shortening the 5-minute negative TTL matters more, since that is how quickly
+a device object appearing late is picked up.
+
+What the 136 requests *did* cost was log lines saying the same thing 136 times, so the shadow log is
+gated on `IntuneDeviceBindingResult.ServedFromCache`: one line per real Graph lookup. Cached repeats
+add nothing — the reported age just counts up mechanically from the same `enrolledDateTime`.
+Outcomes that are never cached (`Transient`, `NoDeviceIdInCert`) still log every time, which is the
+right behaviour for an anomaly.
+
 The open question this preview exists to answer is a race, not an attack: a device object can in
 principle appear in Intune *after* the agent's first call, and enforcing before that is understood
 would reject legitimate enrollments. Every result therefore carries `enrolledDateTime`, and the log

docs/log.md

@@ -2,6 +2,8 @@
 
 ## 2026-08-24
 
+* **Update**: `backend/client-cert-tenant-binding.md` — stage 3 verified live (`ea6a375`, gktatooine): 136 requests, all `Match`, device object ~72 s older than the session start, so no enrollment race in that run. Measured Graph cost: **1 call for 136 requests** (30 min positive cache), versus 25 for the per-request Autopilot validator — the positive TTL needs no change. The shadow log is now gated on `ServedFromCache` (one line per real lookup instead of per request); never-cached outcomes still log every time.
+
 * **Update**: `backend/client-cert-tenant-binding.md` — stage 3, the cert-to-device binding: new `IntuneDeviceBindingValidator` resolves the Subject-CN managedDevice id against the tenant's own `deviceManagement/managedDevices` (point-GET, no filter literal), modelled on `CloudPcDeviceValidator` and wired fire-and-forget like the DevPrep shadow so a cold Graph round-trip never enters the agent request path. New GA-only tenant toggle `ValidateIntuneDeviceBinding` (shadow — never touches `deviceValidated`), new optional Graph feature `IntuneDeviceBinding` → `DeviceManagementManagedDevices.Read.All` in `GraphFeatureCatalog` + the customer grant script, and `enrolledAgeSeconds` on every log line so the enrollment race can be measured before this could ever become a gate. Grep marker: `CERT-DEVICE-BINDING-SHADOW`.
 
 * **Update**: `backend/client-cert-tenant-binding.md` — shadow telemetry moved off the dead `LogInformation` path: the `Match` outcome now rides on the request row as the `CertTenantBinding` dimension (`SecurityValidator` → `FunctionContext.Items` → `RequestTelemetryMiddleware`), which is unsampled and already exists per request, so the denominator costs nothing. Non-Match outcomes keep their Warning trace. Post-deploy verification of 249e39bc found zero rows across 32k requests — worker `LogInformation` never reaches App Insights (provider default rule Warning+), making "everything matched" indistinguishable from "never ran". `CertificateValidationResult.FromCache` removed with the sampling path it existed for.

src/Backend/AutopilotMonitor.Functions.Tests/IntuneDeviceBindingValidatorTests.cs

@@ -172,6 +172,46 @@ public class IntuneDeviceBindingValidatorTests
         Assert.False(result.IsValid);
     }
 
+    [Fact]
+    public void AsCacheHit_FlagsTheCopyAndLeavesTheCachedInstanceAlone()
+    {
+        // The cached instance is shared across every request for that device. Marking it in place
+        // would make the first (real) lookup look cached too, and the log gate would then drop the
+        // one line per lookup we actually want to keep.
+        var cached = new IntuneDeviceBindingResult
+        {
+            Outcome = IntuneDeviceBindingOutcome.Match,
+            IntuneDeviceId = DeviceId,
+            DeviceName = "TEST-DEVICE-01",
+            EnrolledDateTime = new DateTimeOffset(2026, 8, 24, 16, 51, 0, TimeSpan.Zero),
+        };
+
+        var hit = cached.AsCacheHit();
+
+        Assert.True(hit.ServedFromCache);
+        Assert.False(cached.ServedFromCache);
+        Assert.NotSame(cached, hit);
+
+        // Everything the log line reports must survive the copy.
+        Assert.Equal(cached.Outcome, hit.Outcome);
+        Assert.Equal(cached.IntuneDeviceId, hit.IntuneDeviceId);
+        Assert.Equal(cached.DeviceName, hit.DeviceName);
+        Assert.Equal(cached.EnrolledDateTime, hit.EnrolledDateTime);
+    }
+
+    [Fact]
+    public void FreshResult_IsNotFlaggedAsCached()
+    {
+        // A freshly parsed Graph response must be loggable — that is the one line per lookup.
+        var body = $$"""
+        { "id": "{{DeviceId}}", "deviceName": "TEST-DEVICE-01" }
+        """;
+
+        var result = IntuneDeviceBindingValidator.ParseManagedDeviceResponse(body, DeviceId);
+
+        Assert.False(result.ServedFromCache);
+    }
+
     [Fact]
     public void TransientOutcome_IsNeitherValidNorDefinitive()
     {

src/Backend/AutopilotMonitor.Functions/Security/IntuneDeviceBindingValidator.cs

@@ -82,7 +82,7 @@ namespace AutopilotMonitor.Functions.Security
             var cacheKey = BuildCacheKey(tenantId, normalizedId);
 
             if (_cache.TryGetValue(cacheKey, out IntuneDeviceBindingResult? cached) && cached != null)
-                return cached;
+                return cached.AsCacheHit();
 
             const int maxAttempts = 2;
             IntuneDeviceBindingResult? lastTransient = null;
@@ -324,5 +324,29 @@ namespace AutopilotMonitor.Functions.Security
         public DateTimeOffset? EnrolledDateTime { get; set; }
 
         public string? ErrorMessage { get; set; }
+
+        /// <summary>
+        /// True when this result came from the in-memory cache rather than a fresh Graph lookup.
+        /// Callers use it to log once per real lookup instead of once per request: a single
+        /// enrollment produced 136 requests but only one Graph call, so logging per request said
+        /// the same thing 136 times.
+        /// </summary>
+        public bool ServedFromCache { get; set; }
+
+        /// <summary>
+        /// Copy of this result marked as a cache hit, so the shared cached instance is never
+        /// mutated by a caller.
+        /// </summary>
+        internal IntuneDeviceBindingResult AsCacheHit() => new()
+        {
+            Outcome = Outcome,
+            IntuneDeviceId = IntuneDeviceId,
+            DeviceName = DeviceName,
+            AzureAdDeviceId = AzureAdDeviceId,
+            ManagementState = ManagementState,
+            EnrolledDateTime = EnrolledDateTime,
+            ErrorMessage = ErrorMessage,
+            ServedFromCache = true
+        };
     }
 }

src/Backend/AutopilotMonitor.Functions/Security/SecurityValidator.cs

@@ -495,6 +495,16 @@ namespace AutopilotMonitor.Functions.Security
                         TryGetIntuneDeviceIdFromCertSubject(bindingSubject, out var certDeviceId);
                         var binding = await bindingValidator.ValidateAsync(bindingTenant, certDeviceId, bindingSession);
 
+                        // One line per real Graph lookup, not per request. Measured on the first
+                        // live enrollment: 136 requests produced exactly ONE Graph call (the 30 min
+                        // positive cache did its job), so per-request logging repeated the same
+                        // finding 136 times. Cached repeats add nothing - the age just counts up
+                        // mechanically from the same enrolledDateTime. Uncached outcomes
+                        // (Transient, NoDeviceIdInCert) still log every time, which is what we want
+                        // for anomalies.
+                        if (binding.ServedFromCache)
+                            return;
+
                         // Age of the device object at request time: the discriminator between a
                         // genuine enrollment race (object created moments ago, or not yet) and a
                         // certificate that never belonged to this tenant.