From 64b0dbe82e41965b58aa5548056edf9cd511397c Mon Sep 17 00:00:00 2001 From: Tyrie Vella Date: Thu, 13 Aug 2026 09:40:42 -0700 Subject: [PATCH] Record HTTP status code on blob-hydration failure telemetry When an on-demand loose-blob download fails, GVFS emits a terminal telemetry error with a BlobHydrationFailureCategory. The DownloadFailed category is the transient or unclassified bucket. It collapses genuine auth failures (401, 400, 302) and transient failures (timeout 408, 5xx, pool-exhaustion 503) into one value. The HTTP status of the failing download is known in the code, but it only reaches the on-box log, not shipped telemetry. So telemetry cannot tell a real auth failure apart from a transient one. Carry the HTTP status of the last download attempt to the terminal failure event through an internal DownloadAttemptResult type. Add HttpStatusCode and HttpStatusName to the event metadata only when the failure is attributable to the download itself (DownloadFailed or ObjectNotOnServer), so an earlier attempt's status cannot attach to a later local-IO or copy failure. The public TryDownloadAndSaveObject return type does not change. Assisted-by: Claude Opus 4.8 Signed-off-by: Tyrie Vella --- GVFS/GVFS.Common/Git/GVFSGitObjects.cs | 87 ++++++++--- .../GVFS.UnitTests/Git/GVFSGitObjectsTests.cs | 146 +++++++++++++++++- 2 files changed, 208 insertions(+), 25 deletions(-) diff --git a/GVFS/GVFS.Common/Git/GVFSGitObjects.cs b/GVFS/GVFS.Common/Git/GVFSGitObjects.cs index b232e7b74..f8a314b2e 100644 --- a/GVFS/GVFS.Common/Git/GVFSGitObjects.cs +++ b/GVFS/GVFS.Common/Git/GVFSGitObjects.cs @@ -1,4 +1,4 @@ -using GVFS.Common.Http; +using GVFS.Common.Http; using GVFS.Common.Tracing; using System; using System.Collections.Concurrent; @@ -15,14 +15,14 @@ public class GVFSGitObjects : GitObjects private static readonly TimeSpan NegativeCacheTTL = TimeSpan.FromSeconds(30); private ConcurrentDictionary objectNegativeCache; - internal ConcurrentDictionary> inflightDownloads; + internal ConcurrentDictionary> inflightDownloads; public GVFSGitObjects(GVFSContext context, GitObjectsHttpRequestor objectRequestor) : base(context.Tracer, context.Enlistment, objectRequestor, context.FileSystem) { this.Context = context; this.objectNegativeCache = new ConcurrentDictionary(StringComparer.OrdinalIgnoreCase); - this.inflightDownloads = new ConcurrentDictionary>(StringComparer.OrdinalIgnoreCase); + this.inflightDownloads = new ConcurrentDictionary>(StringComparer.OrdinalIgnoreCase); } public enum RequestSource @@ -58,6 +58,28 @@ public enum BlobHydrationFailureCategory Unexpected, // Unclassified exception. } + /// + /// Carries the outcome of an object download together with the HTTP status of the last + /// download attempt. The public enum only records + /// success/not-found/error, which collapses genuine auth failures (401/400/302) and + /// transient failures (408/5xx/pool-exhaustion 503) into a single "error" outcome. The + /// status is retained here so the terminal blob-hydration telemetry can tell them apart. + /// + internal class DownloadAttemptResult + { + public DownloadAttemptResult(DownloadAndSaveObjectResult result, HttpStatusCode? httpStatusCode) + { + this.Result = result; + this.HttpStatusCode = httpStatusCode; + } + + public DownloadAndSaveObjectResult Result { get; } + + // The HTTP status of the last download attempt, or null when no HTTP response was + // received (for example an exhausted retry that ended in an exception). + public HttpStatusCode? HttpStatusCode { get; } + } + protected GVFSContext Context { get; private set; } public virtual bool TryCopyBlobContentStream( @@ -72,7 +94,7 @@ public virtual bool TryCopyBlobContentStream( // local copy) that is otherwise collapsed into the bool return value below. The // final category is also surfaced via the out parameter so the caller can tag its // own terminal telemetry with the same cause. - DownloadAndSaveObjectResult lastDownloadResult = DownloadAndSaveObjectResult.Error; + DownloadAttemptResult lastDownloadResult = null; bool downloadSucceededButCopyFailed = false; BlobHydrationFailureCategory capturedCategory = BlobHydrationFailureCategory.None; @@ -109,7 +131,7 @@ public virtual bool TryCopyBlobContentStream( { category = BlobHydrationFailureCategory.LocalCopyFailed; } - else if (lastDownloadResult == DownloadAndSaveObjectResult.ObjectNotOnServer) + else if (lastDownloadResult?.Result == DownloadAndSaveObjectResult.ObjectNotOnServer) { category = BlobHydrationFailureCategory.ObjectNotOnServer; } @@ -124,6 +146,22 @@ public virtual bool TryCopyBlobContentStream( capturedCategory = category; metadata.Add(nameof(BlobHydrationFailureCategory), category.ToString()); + // Surface the HTTP status of the last download attempt so telemetry can tell a + // genuine auth failure (401/400/302) apart from a transient one (408/5xx/503), + // both of which otherwise land in the DownloadFailed bucket. Only attach it when + // the failure is attributable to the download itself (DownloadFailed or + // ObjectNotOnServer). On the exception (LocalIO/NetworkUnavailable) and + // LocalCopyFailed paths lastDownloadResult can hold a status captured on an + // earlier attempt, so the status would be stale and misattribute the failure. + bool statusIsAttributable = + category == BlobHydrationFailureCategory.DownloadFailed || + category == BlobHydrationFailureCategory.ObjectNotOnServer; + if (statusIsAttributable && lastDownloadResult?.HttpStatusCode != null) + { + metadata.Add("HttpStatusCode", (int)lastDownloadResult.HttpStatusCode.Value); + metadata.Add("HttpStatusName", lastDownloadResult.HttpStatusCode.Value.ToString()); + } + string message = "TryCopyBlobContentStream: Failed to provide blob contents"; if (errorArgs.WillRetry) { @@ -149,7 +187,7 @@ public virtual bool TryCopyBlobContentStream( // Pass in false for retryOnFailure because the retrier in this method manages multiple attempts lastDownloadResult = this.TryDownloadAndSaveObject(sha, cancellationToken, requestSource, retryOnFailure: false); - if (lastDownloadResult == DownloadAndSaveObjectResult.Success) + if (lastDownloadResult.Result == DownloadAndSaveObjectResult.Success) { if (this.Context.Repository.TryCopyBlobContentStream(sha, writeAction)) { @@ -169,7 +207,7 @@ public virtual bool TryCopyBlobContentStream( public DownloadAndSaveObjectResult TryDownloadAndSaveObject(string objectId, RequestSource requestSource) { - return this.TryDownloadAndSaveObject(objectId, CancellationToken.None, requestSource, retryOnFailure: true); + return this.TryDownloadAndSaveObject(objectId, CancellationToken.None, requestSource, retryOnFailure: true).Result; } public bool TryGetBlobSizeLocally(string sha, out long length) @@ -182,7 +220,7 @@ public bool TryGetBlobSizeLocally(string sha, out long length) return this.GitObjectRequestor.QueryForFileSizes(objectIds, cancellationToken); } - private DownloadAndSaveObjectResult TryDownloadAndSaveObject( + private DownloadAttemptResult TryDownloadAndSaveObject( string objectId, CancellationToken cancellationToken, RequestSource requestSource, @@ -190,7 +228,7 @@ private DownloadAndSaveObjectResult TryDownloadAndSaveObject( { if (objectId == GVFSConstants.AllZeroSha) { - return DownloadAndSaveObjectResult.Error; + return new DownloadAttemptResult(DownloadAndSaveObjectResult.Error, httpStatusCode: null); } DateTime negativeCacheRequestTime; @@ -198,7 +236,7 @@ private DownloadAndSaveObjectResult TryDownloadAndSaveObject( { if (negativeCacheRequestTime > DateTime.Now.Subtract(NegativeCacheTTL)) { - return DownloadAndSaveObjectResult.ObjectNotOnServer; + return new DownloadAttemptResult(DownloadAndSaveObjectResult.ObjectNotOnServer, httpStatusCode: null); } this.objectNegativeCache.TryRemove(objectId, out negativeCacheRequestTime); @@ -210,9 +248,9 @@ private DownloadAndSaveObjectResult TryDownloadAndSaveObject( // captured by the Lazy factory. Subsequent coalesced callers inherit those // settings. In practice this is fine because the primary concurrent path // (NamedPipeMessage from git.exe) always uses CancellationToken.None. - Lazy newLazy = new Lazy( + Lazy newLazy = new Lazy( () => this.DoDownloadAndSaveObject(objectId, cancellationToken, requestSource, retryOnFailure)); - Lazy lazy = this.inflightDownloads.GetOrAdd(objectId, newLazy); + Lazy lazy = this.inflightDownloads.GetOrAdd(objectId, newLazy); if (!ReferenceEquals(lazy, newLazy)) { @@ -240,13 +278,13 @@ private DownloadAndSaveObjectResult TryDownloadAndSaveObject( /// .NET Framework 4.7.1. When we upgrade to .NET 10 (backlog), this can be /// replaced with ConcurrentDictionary.TryRemove(KeyValuePair). /// - private bool TryRemoveInflightDownload(string objectId, Lazy lazy) + private bool TryRemoveInflightDownload(string objectId, Lazy lazy) { - return ((ICollection>>)this.inflightDownloads) - .Remove(new KeyValuePair>(objectId, lazy)); + return ((ICollection>>)this.inflightDownloads) + .Remove(new KeyValuePair>(objectId, lazy)); } - private DownloadAndSaveObjectResult DoDownloadAndSaveObject( + private DownloadAttemptResult DoDownloadAndSaveObject( string objectId, CancellationToken cancellationToken, RequestSource requestSource, @@ -273,21 +311,32 @@ private DownloadAndSaveObjectResult DoDownloadAndSaveObject( return new RetryWrapper.CallbackResult(new GitObjectsHttpRequestor.GitObjectTaskResult(true)); }); + // Capture the HTTP status of the last download attempt when a response was received. + // On failure the requestor propagates the real status (e.g. 401/404/503); on an + // exhausted retry that ended in an exception output.Result is null and no status is + // known. A default (zero) status means the result carried no HTTP response, so it is + // treated as "no status". + HttpStatusCode? httpStatusCode = null; + if (output.Result != null && output.Result.HttpStatusCodeResult != 0) + { + httpStatusCode = output.Result.HttpStatusCodeResult; + } + if (output.Result != null) { if (output.Succeeded && output.Result.Success) { - return DownloadAndSaveObjectResult.Success; + return new DownloadAttemptResult(DownloadAndSaveObjectResult.Success, httpStatusCode); } if (output.Result.HttpStatusCodeResult == HttpStatusCode.NotFound) { this.objectNegativeCache.AddOrUpdate(objectId, DateTime.Now, (unused1, unused2) => DateTime.Now); - return DownloadAndSaveObjectResult.ObjectNotOnServer; + return new DownloadAttemptResult(DownloadAndSaveObjectResult.ObjectNotOnServer, httpStatusCode); } } - return DownloadAndSaveObjectResult.Error; + return new DownloadAttemptResult(DownloadAndSaveObjectResult.Error, httpStatusCode); } } } \ No newline at end of file diff --git a/GVFS/GVFS.UnitTests/Git/GVFSGitObjectsTests.cs b/GVFS/GVFS.UnitTests/Git/GVFSGitObjectsTests.cs index 205d2b4de..561536112 100644 --- a/GVFS/GVFS.UnitTests/Git/GVFSGitObjectsTests.cs +++ b/GVFS/GVFS.UnitTests/Git/GVFSGitObjectsTests.cs @@ -1,4 +1,4 @@ -using GVFS.Common; +using GVFS.Common; using GVFS.Common.Git; using GVFS.Common.Http; using GVFS.Common.Tracing; @@ -157,6 +157,124 @@ public void TerminalBlobHydrationFailureTagsObjectNotOnServer() terminalError.ShouldContain("\"BlobHydrationFailureCategory\":\"ObjectNotOnServer\""); } + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void TerminalBlobHydrationFailureRecordsHttpStatusCode() + { + MockFileSystemWithCallbacks fileSystem = new MockFileSystemWithCallbacks(); + fileSystem.OnFileExists = (path) => true; + fileSystem.OnOpenFileStream = (path, mode, access) => + { + if (access == FileAccess.Write) + { + return new MemoryStream(); + } + + throw new FileNotFoundException(); + }; + + MockHttpGitObjects httpObjects = new MockHttpGitObjects(); + + // Force the download to fail with 401. The DownloadFailed bucket collapses auth and + // transient failures, so the terminal event must also carry the HTTP status to tell + // a real 401 apart from a transient failure. + httpObjects.StatusCodeToReturn = HttpStatusCode.Unauthorized; + GVFSGitObjects dut = this.CreateTestableGVFSGitObjects(httpObjects, fileSystem, out MockTracer tracer); + + bool copied = dut.TryCopyBlobContentStream( + ValidTestObjectFileSha1, + new CancellationToken(), + GVFSGitObjects.RequestSource.FileStreamCallback, + (stream, length) => Assert.Fail("Should not be able to call copy stream callback"), + out GVFSGitObjects.BlobHydrationFailureCategory failureCategory); + copied.ShouldEqual(false); + + // A 401 is not classified as ObjectNotOnServer, so it lands in the neutral + // DownloadFailed bucket; the HTTP status is what distinguishes it. + failureCategory.ShouldEqual(GVFSGitObjects.BlobHydrationFailureCategory.DownloadFailed); + string terminalError = tracer.RelatedErrorEvents.First(e => e.Contains("Failed to provide blob contents")); + terminalError.ShouldContain("\"BlobHydrationFailureCategory\":\"DownloadFailed\""); + terminalError.ShouldContain("\"HttpStatusCode\":401"); + terminalError.ShouldContain("\"HttpStatusName\":\"Unauthorized\""); + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void TerminalBlobHydrationFailureRecordsTransientHttpStatusCode() + { + MockFileSystemWithCallbacks fileSystem = new MockFileSystemWithCallbacks(); + fileSystem.OnFileExists = (path) => true; + fileSystem.OnOpenFileStream = (path, mode, access) => + { + if (access == FileAccess.Write) + { + return new MemoryStream(); + } + + throw new FileNotFoundException(); + }; + + MockHttpGitObjects httpObjects = new MockHttpGitObjects(); + + // A transient 503 must also carry the HTTP status so it can be told apart from a real + // auth failure - both share the DownloadFailed category. + httpObjects.StatusCodeToReturn = HttpStatusCode.ServiceUnavailable; + GVFSGitObjects dut = this.CreateTestableGVFSGitObjects(httpObjects, fileSystem, out MockTracer tracer); + + bool copied = dut.TryCopyBlobContentStream( + ValidTestObjectFileSha1, + new CancellationToken(), + GVFSGitObjects.RequestSource.FileStreamCallback, + (stream, length) => Assert.Fail("Should not be able to call copy stream callback"), + out GVFSGitObjects.BlobHydrationFailureCategory failureCategory); + copied.ShouldEqual(false); + + failureCategory.ShouldEqual(GVFSGitObjects.BlobHydrationFailureCategory.DownloadFailed); + string terminalError = tracer.RelatedErrorEvents.First(e => e.Contains("Failed to provide blob contents")); + terminalError.ShouldContain("\"BlobHydrationFailureCategory\":\"DownloadFailed\""); + terminalError.ShouldContain("\"HttpStatusCode\":503"); + terminalError.ShouldContain("\"HttpStatusName\":\"ServiceUnavailable\""); + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void TerminalBlobHydrationFailureOmitsHttpStatusWhenDownloadHasNoStatus() + { + MockFileSystemWithCallbacks fileSystem = new MockFileSystemWithCallbacks(); + fileSystem.OnFileExists = (path) => true; + fileSystem.OnOpenFileStream = (path, mode, access) => + { + if (access == FileAccess.Write) + { + return new MemoryStream(); + } + + throw new FileNotFoundException(); + }; + + MockHttpGitObjects httpObjects = new MockHttpGitObjects(); + + // The download fails without an HTTP response (no status). The terminal event must NOT + // carry a status - in particular it must never emit "HttpStatusCode":0 for a status that + // was never received. + httpObjects.FailWithoutStatus = true; + GVFSGitObjects dut = this.CreateTestableGVFSGitObjects(httpObjects, fileSystem, out MockTracer tracer); + + bool copied = dut.TryCopyBlobContentStream( + ValidTestObjectFileSha1, + new CancellationToken(), + GVFSGitObjects.RequestSource.FileStreamCallback, + (stream, length) => Assert.Fail("Should not be able to call copy stream callback"), + out GVFSGitObjects.BlobHydrationFailureCategory failureCategory); + copied.ShouldEqual(false); + + failureCategory.ShouldEqual(GVFSGitObjects.BlobHydrationFailureCategory.DownloadFailed); + string terminalError = tracer.RelatedErrorEvents.First(e => e.Contains("Failed to provide blob contents")); + terminalError.ShouldContain("\"BlobHydrationFailureCategory\":\"DownloadFailed\""); + terminalError.ShouldNotContain(false, "HttpStatusCode"); + terminalError.ShouldNotContain(false, "HttpStatusName"); + } + [TestCase] [Category(CategoryConstants.ExceptionExpected)] public void TerminalBlobHydrationFailureTagsLocalCopyFailed() @@ -707,15 +825,15 @@ public void StragglingFinallyDoesNotRemoveNewInflightDownload() wave2Started.Wait(TimeSpan.FromSeconds(5)).ShouldBeTrue("Wave 2 download should have started"); // Capture wave 2's Lazy from the dictionary - Lazy wave2Lazy; + Lazy wave2Lazy; dut.inflightDownloads.TryGetValue(ValidTestObjectFileSha1, out wave2Lazy).ShouldBeTrue("Wave 2 Lazy should be in dictionary"); // Simulate a straggling wave-1 thread: create a different Lazy and try to remove it. // With value-aware removal, this must NOT remove wave 2's Lazy. - Lazy staleLazy = - new Lazy(() => GitObjects.DownloadAndSaveObjectResult.Success); - bool staleRemoved = ((ICollection>>)dut.inflightDownloads) - .Remove(new KeyValuePair>(ValidTestObjectFileSha1, staleLazy)); + Lazy staleLazy = + new Lazy(() => new GVFSGitObjects.DownloadAttemptResult(GitObjects.DownloadAndSaveObjectResult.Success, httpStatusCode: null)); + bool staleRemoved = ((ICollection>>)dut.inflightDownloads) + .Remove(new KeyValuePair>(ValidTestObjectFileSha1, staleLazy)); staleRemoved.ShouldBeFalse("Straggling finally must not remove wave 2's Lazy"); dut.inflightDownloads.ContainsKey(ValidTestObjectFileSha1).ShouldBeTrue("Wave 2 Lazy must survive"); @@ -796,6 +914,12 @@ private MockHttpGitObjects(MockGVFSEnlistment enlistment) public Stream InputStream { get; set; } public string MediaType { get; set; } public HttpStatusCode? StatusCodeToReturn { get; set; } + + // When true, TryDownloadObjects returns a failing result built from GitObjectTaskResult(bool), + // i.e. Result is non-null but carries no HTTP status (HttpStatusCodeResult == 0). This + // exercises the "download failed without a status" branch of the telemetry status capture. + public bool FailWithoutStatus { get; set; } + public byte[] ContentBytesToServe { get; set; } public static MemoryStream GetRandomStream(int size) @@ -837,6 +961,16 @@ public override RetryWrapper.InvocationResult TryDownloadOb result: new GitObjectTaskResult(this.StatusCodeToReturn.Value)); } + if (this.FailWithoutStatus) + { + // A download that failed without an HTTP response: Result is non-null but its + // HttpStatusCodeResult stays 0, so no status should reach telemetry. + return new RetryWrapper.InvocationResult( + 0, + error: null, + result: new GitObjectTaskResult(false)); + } + // Serve a fresh stream per call when ContentBytesToServe is set so the download // succeeds even across retries (InputStream would be consumed after the first read). Stream contentStream = this.ContentBytesToServe != null