From 8586f2039acf391e2d4db542933029661df5b57a Mon Sep 17 00:00:00 2001 From: Tyrie Vella Date: Mon, 19 Oct 2026 15:29:56 -0700 Subject: [PATCH 1/4] Bound HTTP body read waits and report transfer progress Stop pending response-body reads after 60 seconds without data. Preserve known error statuses, existing retries and cache fallback, and caller cancellation. Zero disables the read deadline. Load complete retry configuration through one entry point in every production consumer. Warn and use per-setting defaults for invalid or unreadable values instead of aborting. Preserve valid settings, active mount snapshots, and intentional command overrides. Report byte progress and read waits in local logs and telemetry. Correlate pack events and retry outcomes with response and request IDs. Number diagnostic samples and keep diagnostic writes outside the read-state lock. Guarantee response cleanup when diagnostics fail. Drain pending pack finalization work before retry after a failed read. Retain completed timestamps for the next request. Add unit tests for complete config loading, fallback, transport deadlines, cleanup, and diagnostic contracts. Add functional tests for a stalled CLI prefetch and invalid retry settings on a mounted enlistment. Document the deadline, configuration fallback, and diagnostic fields. Assisted-by: GPT-6.1 Sol Signed-off-by: Tyrie Vella --- GVFS/FastFetch/FastFetchVerb.cs | 5 +- GVFS/GVFS.Common/GVFSConstants.cs | 1 + GVFS/GVFS.Common/Git/GitAuthentication.cs | 4 +- GVFS/GVFS.Common/Git/GitObjects.cs | 164 ++-- .../Http/GitEndPointResponseData.cs | 120 +-- GVFS/GVFS.Common/Http/HttpRequestor.cs | 75 +- GVFS/GVFS.Common/Http/HttpResponseStream.cs | 390 +++++++++ GVFS/GVFS.Common/RetryConfig.cs | 127 ++- .../EnlistmentPerFixture/PrefetchVerbTests.cs | 155 ++++ GVFS/GVFS.Mount/InProcessMountVerb.cs | 6 +- .../ProfilingEnvironment.cs | 3 +- .../GVFS.UnitTests/Common/RetryConfigTests.cs | 244 ++++-- GVFS/GVFS.UnitTests/Git/GitObjectsTests.cs | 171 ++++ .../Http/GitObjectsHttpRequestorTests.cs | 44 +- .../GVFS.UnitTests/Http/HttpRequestorTests.cs | 14 + .../Http/HttpResponseStreamTests.cs | 743 ++++++++++++++++++ GVFS/GVFS.UnitTests/Mock/Common/MockTracer.cs | 9 +- GVFS/GVFS/CommandLine/CacheServerVerb.cs | 5 +- GVFS/GVFS/CommandLine/DehydrateVerb.cs | 6 +- GVFS/GVFS/CommandLine/GVFSVerb.cs | 20 +- docs/troubleshooting.md | 61 ++ 21 files changed, 2012 insertions(+), 355 deletions(-) create mode 100644 GVFS/GVFS.Common/Http/HttpResponseStream.cs create mode 100644 GVFS/GVFS.UnitTests/Http/HttpResponseStreamTests.cs diff --git a/GVFS/FastFetch/FastFetchVerb.cs b/GVFS/FastFetch/FastFetchVerb.cs index cf6add3aad..4f46d7fa3e 100644 --- a/GVFS/FastFetch/FastFetchVerb.cs +++ b/GVFS/FastFetch/FastFetchVerb.cs @@ -259,7 +259,10 @@ private int ExecuteWithExitCode() return ExitFailure; } - RetryConfig retryConfig = new RetryConfig(this.MaxAttempts, TimeSpan.FromMinutes(RetryConfig.FetchAndCloneTimeoutMinutes)); + RetryConfig.TryLoadFromGitConfig(tracer, enlistment, out RetryConfig retryConfig, out _); + retryConfig.MaxRetries = this.MaxAttempts; + retryConfig.Timeout = TimeSpan.FromMinutes(RetryConfig.FetchAndCloneTimeoutMinutes); + BlobPrefetcher prefetcher = this.GetFolderPrefetcher(tracer, enlistment, cacheServer, retryConfig); if (!BlobPrefetcher.TryLoadFolderList(enlistment, this.FolderList, this.FolderListFile, prefetcher.FolderList, readListFromStdIn: false, error: out error)) { diff --git a/GVFS/GVFS.Common/GVFSConstants.cs b/GVFS/GVFS.Common/GVFSConstants.cs index 088d771957..64ec277e82 100644 --- a/GVFS/GVFS.Common/GVFSConstants.cs +++ b/GVFS/GVFS.Common/GVFSConstants.cs @@ -28,6 +28,7 @@ public static class GitConfig public const string GVFSPrefix = "gvfs."; public const string MaxRetriesConfig = GVFSPrefix + "max-retries"; public const string TimeoutSecondsConfig = GVFSPrefix + "timeout-seconds"; + public const string ReadTimeoutSecondsConfig = GVFSPrefix + "read-timeout-seconds"; public const string GitStatusCacheBackoffConfig = GVFSPrefix + "status-cache-backoff-seconds"; public const string MaxActiveEnumerationsConfig = GVFSPrefix + "max-active-enumerations"; public const string MountId = GVFSPrefix + "mount-id"; diff --git a/GVFS/GVFS.Common/Git/GitAuthentication.cs b/GVFS/GVFS.Common/Git/GitAuthentication.cs index c35a11a823..694216a323 100644 --- a/GVFS/GVFS.Common/Git/GitAuthentication.cs +++ b/GVFS/GVFS.Common/Git/GitAuthentication.cs @@ -222,12 +222,14 @@ public bool TryGetCredentials(ITracer tracer, out string credentialString, out s /// public bool TryInitialize(ITracer tracer, Enlistment enlistment, out string errorMessage) { + RetryConfig.TryLoadFromGitConfig(tracer, enlistment, out RetryConfig retryConfig, out _); + // Delegate to the combined method, discarding the config result. // This avoids duplicating the anonymous-probe + credential-fetch logic. return this.TryInitializeAndQueryGVFSConfig( tracer, enlistment, - new RetryConfig(), + retryConfig, out _, out errorMessage, out _); diff --git a/GVFS/GVFS.Common/Git/GitObjects.cs b/GVFS/GVFS.Common/Git/GitObjects.cs index 19c1a0e608..89b054129a 100644 --- a/GVFS/GVFS.Common/Git/GitObjects.cs +++ b/GVFS/GVFS.Common/Git/GitObjects.cs @@ -157,6 +157,8 @@ public virtual bool TryDownloadPrefetchPacks(GitProcess gitProcess, long latestT { EventMetadata metadata = CreateEventMetadata(); metadata.Add("latestTimestamp", latestTimestamp); + long requestId = HttpRequestor.GetNewRequestId(); + metadata.Add("RequestId", requestId); using (ITracer activity = this.Tracer.StartActivity("TryDownloadPrefetchPacks", EventLevel.Informational, Keywords.Telemetry, metadata)) { @@ -168,7 +170,6 @@ public virtual bool TryDownloadPrefetchPacks(GitProcess gitProcess, long latestT * cloning a large repository, so it must be explicitly enabled for now. */ metadata.Add("trustPackIndexes", trustPackIndexes); - long requestId = HttpRequestor.GetNewRequestId(); List innerPackIndexes = null; RetryWrapper.InvocationResult result = this.GitObjectRequestor.TrySendProtocolRequest( requestId: requestId, @@ -215,6 +216,7 @@ public virtual bool TryDownloadPrefetchPacks(GitProcess gitProcess, long latestT activity.Stop(new EventMetadata { { "Area", EtwArea }, + { "RequestId", requestId }, { "Success", result.Succeeded }, { "Attempts", result.Attempts }, { "BytesDownloaded", bytesDownloaded }, @@ -741,106 +743,114 @@ private LooseObjectToWrite GetLooseObjectDestination(string sha) // Read each pack from the stream to a temp file, and start a task to index it. Task previousPackTask = Task.CompletedTask; - foreach (PrefetchPacksDeserializer.PackAndIndex packHandle in deserializer.EnumeratePacks()) + Exception exception = null; + try { - var pack = packHandle; // Capture packHandle in a new variable to avoid closure issues with async index task - long packLength; - - // Write the temp and index to a temp folder to avoid putting corrupt files in the pack folder - // As the files are validated and flushed they can be moved to the pack folder, along with a marker file. - // When the previous pack has completed, the marker file for the current pack is deleted. - // This allows users to access the most recent pack files as soon as they are ready even though - // the oldest, largest pack file may still be in progress, and it allows us to know on a future - // prefetch if the previous one was interrupted and needs to be started over. - string packName = string.Format("{0}-{1}-{2}.pack", GVFSConstants.PrefetchPackPrefix, pack.Timestamp, pack.UniqueId); - string packTempPath = Path.Combine(tempPackFolderPath, packName); - - EventMetadata data = CreateEventMetadata(); - data["timestamp"] = pack.Timestamp.ToString(); - data["uniqueId"] = pack.UniqueId; - activity.RelatedEvent(EventLevel.Informational, "Receiving Pack/Index", data); - - // Write the pack - // If it fails, TryWriteTempFile cleans up the file and we retry the prefetch - Task packFlushTask; - if (!this.TryWriteTempFile(activity, pack.PackStream, packTempPath, out packLength, out packFlushTask)) + foreach (PrefetchPacksDeserializer.PackAndIndex packHandle in deserializer.EnumeratePacks()) { + var pack = packHandle; // Capture packHandle in a new variable to avoid closure issues with async index task + long packLength; + + // Write the temp and index to a temp folder to avoid putting corrupt files in the pack folder + // As the files are validated and flushed they can be moved to the pack folder, along with a marker file. + // When the previous pack has completed, the marker file for the current pack is deleted. + // This allows users to access the most recent pack files as soon as they are ready even though + // the oldest, largest pack file may still be in progress, and it allows us to know on a future + // prefetch if the previous one was interrupted and needs to be started over. + string packName = string.Format("{0}-{1}-{2}.pack", GVFSConstants.PrefetchPackPrefix, pack.Timestamp, pack.UniqueId); + string packTempPath = Path.Combine(tempPackFolderPath, packName); + + EventMetadata data = CreateEventMetadata(); + data["timestamp"] = pack.Timestamp.ToString(); + data["uniqueId"] = pack.UniqueId; + data["ResponseId"] = response.ResponseId; + data["PackBytes"] = pack.PackStream.Length; + activity.RelatedEvent(EventLevel.Informational, "Receiving Pack/Index", data, Keywords.Telemetry); + + // Write the pack + // If it fails, TryWriteTempFile cleans up the file and we retry the prefetch + Task packFlushTask; + if (!this.TryWriteTempFile(activity, pack.PackStream, packTempPath, out packLength, out packFlushTask)) + { + bytesDownloaded += packLength; + allSucceeded = false; + break; + } + var currentOperation = new TempPrefetchPackAndIdx(pack.Timestamp, packName, packTempPath, packFlushTask); + tempPackOperations.Add(currentOperation); bytesDownloaded += packLength; - allSucceeded = false; - break; - } - var currentOperation = new TempPrefetchPackAndIdx(pack.Timestamp, packName, packTempPath, packFlushTask); - tempPackOperations.Add(currentOperation); - bytesDownloaded += packLength; - if (trustPackIndexes - && pack.IndexStream != null) - { - if (this.TryWriteTempFile(activity, pack.IndexStream, currentOperation.IndexTempPath, out var indexLength, out var indexFlushTask)) + if (trustPackIndexes + && pack.IndexStream != null) { - bytesDownloaded += indexLength; - currentOperation.ReadyTask = Task.WhenAll(currentOperation.ReadyTask, indexFlushTask); - previousPackTask = AddFinalizationTasks(currentOperation, previousPackTask); + if (this.TryWriteTempFile(activity, pack.IndexStream, currentOperation.IndexTempPath, out var indexLength, out var indexFlushTask)) + { + bytesDownloaded += indexLength; + currentOperation.ReadyTask = Task.WhenAll(currentOperation.ReadyTask, indexFlushTask); + previousPackTask = AddFinalizationTasks(currentOperation, previousPackTask); + } + else + { + bytesDownloaded += indexLength; + // we can try to build the index ourself, and if it's successful then on the retry we can pick up from that point. + var indexTask = StartPackIndexAsync(activity, packTempPath); + currentOperation.ReadyTask = Task.WhenAll(currentOperation.ReadyTask, indexTask); + previousPackTask = AddFinalizationTasks(currentOperation, previousPackTask); + + // but we need to stop trying to read from the download stream as that has failed. + allSucceeded = false; + break; + } } else { - bytesDownloaded += indexLength; - // we can try to build the index ourself, and if it's successful then on the retry we can pick up from that point. + + // Either we can't trust the index file from the server, or the server didn't provide one, so we will build our own. + // For performance, we run the index build in the background while we continue downloading the next pack. var indexTask = StartPackIndexAsync(activity, packTempPath); currentOperation.ReadyTask = Task.WhenAll(currentOperation.ReadyTask, indexTask); previousPackTask = AddFinalizationTasks(currentOperation, previousPackTask); - // but we need to stop trying to read from the download stream as that has failed. - allSucceeded = false; - break; - } - } - else - { - - // Either we can't trust the index file from the server, or the server didn't provide one, so we will build our own. - // For performance, we run the index build in the background while we continue downloading the next pack. - var indexTask = StartPackIndexAsync(activity, packTempPath); - currentOperation.ReadyTask = Task.WhenAll(currentOperation.ReadyTask, indexTask); - previousPackTask = AddFinalizationTasks(currentOperation, previousPackTask); - - // If the server provided an index stream, we still need to consume and handle any exceptions it even - // though we are otherwise ignoring it. - if (pack.IndexStream != null) - { - try + // If the server provided an index stream, we still need to consume and handle any exceptions it even + // though we are otherwise ignoring it. + if (pack.IndexStream != null) { - bytesDownloaded += pack.IndexStream.Length; - if (pack.IndexStream.CanSeek) + try { - pack.IndexStream.Seek(0, SeekOrigin.End); + bytesDownloaded += pack.IndexStream.Length; + if (pack.IndexStream.CanSeek) + { + pack.IndexStream.Seek(0, SeekOrigin.End); + } + else + { + pack.IndexStream.CopyTo(Stream.Null); + } } - else + catch (Exception e) { - pack.IndexStream.CopyTo(Stream.Null); + EventMetadata metadata = CreateEventMetadata(e); + activity.RelatedWarning(metadata, "Failed to read to end of index stream"); + allSucceeded = false; + break; } } - catch (Exception e) - { - EventMetadata metadata = CreateEventMetadata(e); - activity.RelatedWarning(metadata, "Failed to read to end of index stream"); - allSucceeded = false; - break; - } } } - } - Exception exception = null; - if (!this.WaitForPacks(tempPackOperations, ref latestTimestamp, out exception)) - { - allSucceeded = false; } + finally + { + if (!this.WaitForPacks(tempPackOperations, ref latestTimestamp, out exception)) + { + allSucceeded = false; + } - packIndexes.AddRange(tempPackOperations - .Where(x => x.ReadyTask.Status == TaskStatus.RanToCompletion) - .Select(x => x.IdxName)); + packIndexes.AddRange(tempPackOperations + .Where(x => x.ReadyTask.Status == TaskStatus.RanToCompletion) + .Select(x => x.IdxName)); + } if (allSucceeded) { diff --git a/GVFS/GVFS.Common/Http/GitEndPointResponseData.cs b/GVFS/GVFS.Common/Http/GitEndPointResponseData.cs index 9eb6164219..0f3e749508 100644 --- a/GVFS/GVFS.Common/Http/GitEndPointResponseData.cs +++ b/GVFS/GVFS.Common/Http/GitEndPointResponseData.cs @@ -5,7 +5,6 @@ using System.Net; using System.Net.Http; using System.Threading; -using System.Threading.Tasks; namespace GVFS.Common.Http { @@ -32,7 +31,12 @@ public GitEndPointResponseData(HttpStatusCode statusCode, Exception error, bool public GitEndPointResponseData(HttpStatusCode statusCode, string contentType, Stream responseStream, HttpResponseMessage message, Action onResponseDisposed) : this(statusCode, null, false, message, onResponseDisposed) { - this.Stream = responseStream == null ? null : new ReadErrorTrackingStream(responseStream); + this.Stream = responseStream == null + ? null + : responseStream as HttpResponseStream ?? new HttpResponseStream( + responseStream, + TimeSpan.FromSeconds(RetryConfig.DefaultReadTimeoutSeconds), + CancellationToken.None); this.ContentType = MapContentType(contentType); } @@ -44,9 +48,11 @@ public GitEndPointResponseData(HttpStatusCode statusCode, string contentType, St public Stream Stream { get; private set; } + public string ResponseId => (this.Stream as HttpResponseStream)?.ResponseId; + public bool StreamReadFailed { - get { return this.Stream is ReadErrorTrackingStream trackingStream && trackingStream.ReadFailed; } + get { return this.Stream is HttpResponseStream trackingStream && trackingStream.ReadFailed; } } public bool HasErrors @@ -129,26 +135,29 @@ public void Dispose(bool disposing) { if (disposing) { - if (this.message != null) - { - this.message.Dispose(); - this.message = null; - } - - if (this.Stream != null) + Stream stream = this.Stream; + HttpResponseMessage responseMessage = this.message; + Action releaseResponse = this.onResponseDisposed; + this.Stream = null; + this.message = null; + this.onResponseDisposed = null; + try { - this.Stream.Dispose(); - this.Stream = null; + stream?.Dispose(); } - - if (this.onResponseDisposed != null) + finally { - this.onResponseDisposed(); - this.onResponseDisposed = null; + try + { + responseMessage?.Dispose(); + } + finally + { + releaseResponse?.Invoke(); + } } } } - /// /// Convert from a string-based Content-Type to /// @@ -167,82 +176,5 @@ private static GitObjectContentType MapContentType(string contentType) } } - private sealed class ReadErrorTrackingStream : Stream - { - private readonly Stream innerStream; - - public ReadErrorTrackingStream(Stream innerStream) - { - this.innerStream = innerStream; - } - - public bool ReadFailed { get; private set; } - - public override bool CanRead => this.innerStream.CanRead; - - public override bool CanSeek => this.innerStream.CanSeek; - - public override bool CanWrite => this.innerStream.CanWrite; - - public override long Length => this.innerStream.Length; - - public override long Position - { - get { return this.innerStream.Position; } - set { this.innerStream.Position = value; } - } - - public override void Flush() => this.innerStream.Flush(); - - public override int Read(byte[] buffer, int offset, int count) => - this.TrackRead(() => this.innerStream.Read(buffer, offset, count)); - - public override int ReadByte() => this.TrackRead(this.innerStream.ReadByte); - - public override Task ReadAsync(byte[] buffer, int offset, int count, CancellationToken cancellationToken) => - this.TrackReadAsync(() => this.innerStream.ReadAsync(buffer, offset, count, cancellationToken)); - - public override long Seek(long offset, SeekOrigin origin) => this.innerStream.Seek(offset, origin); - - public override void SetLength(long value) => this.innerStream.SetLength(value); - - public override void Write(byte[] buffer, int offset, int count) => this.innerStream.Write(buffer, offset, count); - - protected override void Dispose(bool disposing) - { - if (disposing) - { - this.innerStream.Dispose(); - } - - base.Dispose(disposing); - } - - private T TrackRead(Func read) - { - try - { - return read(); - } - catch (Exception ex) when (!(ex is OperationCanceledException)) - { - this.ReadFailed = true; - throw; - } - } - - private async Task TrackReadAsync(Func> read) - { - try - { - return await read().ConfigureAwait(false); - } - catch (Exception ex) when (!(ex is OperationCanceledException)) - { - this.ReadFailed = true; - throw; - } - } - } } } diff --git a/GVFS/GVFS.Common/Http/HttpRequestor.cs b/GVFS/GVFS.Common/Http/HttpRequestor.cs index ee1558abf2..b67b937e9a 100644 --- a/GVFS/GVFS.Common/Http/HttpRequestor.cs +++ b/GVFS/GVFS.Common/Http/HttpRequestor.cs @@ -199,6 +199,15 @@ protected GitEndPointResponseData SendRequest( responseMetadata.Add("CacheName", GetSingleHeaderOrEmpty(response.Headers, "X-Cache-Name")); responseMetadata.Add("StatusCode", response.StatusCode); + EventMetadata bodyMetadata = new EventMetadata + { + { "RequestId", requestId }, + { "StatusCode", response.StatusCode }, + { "CacheName", GetCacheNameForTelemetry((string)responseMetadata["CacheName"]) }, + { "RequestAuthority", GetAuthorityForTelemetry(requestUri) }, + { "HeaderWaitMs", responseWaitTime.TotalMilliseconds }, + { "ContentLength", response.Content.Headers.ContentLength ?? -1 }, + }; if (response.StatusCode == HttpStatusCode.OK) { @@ -210,18 +219,45 @@ protected GitEndPointResponseData SendRequest( this.authentication.ApproveCredentials(this.Tracer, authString); } - Stream responseStream = response.Content.ReadAsStreamAsync().GetAwaiter().GetResult(); + Stream responseStream = response.Content.ReadAsStreamAsync(cancellationToken).GetAwaiter().GetResult(); gitEndPointResponseData = new GitEndPointResponseData( response.StatusCode, contentType, - responseStream, + new HttpResponseStream( + responseStream, + this.RetryConfig.ReadTimeout, + cancellationToken, + this.Tracer, + bodyMetadata), message: response, onResponseDisposed: () => availableConnections.Release()); } else { - errorMessage = response.Content.ReadAsStringAsync().GetAwaiter().GetResult(); + try + { + using (HttpResponseStream responseStream = new HttpResponseStream( + response.Content.ReadAsStreamAsync(cancellationToken).GetAwaiter().GetResult(), + this.RetryConfig.ReadTimeout, + cancellationToken, + this.Tracer, + bodyMetadata)) + using (StreamContent content = new StreamContent(responseStream)) + { + content.Headers.ContentType = response.Content.Headers.ContentType; + errorMessage = content.ReadAsStringAsync(cancellationToken).GetAwaiter().GetResult(); + } + } + catch (Exception e) when (e is IOException || e is HttpRequestException) + { + cancellationToken.ThrowIfCancellationRequested(); + this.Tracer.RelatedWarning( + new EventMetadata(bodyMetadata) { { "Exception", e.ToString() } }, + "The server returned an error status, but the response body read failed.", + Keywords.Network | Keywords.Telemetry); + errorMessage = "The response body read failed: " + (e.InnerException?.Message ?? e.Message); + } int statusInt = (int)response.StatusCode; bool shouldRetry = ShouldRetry(response.StatusCode); @@ -230,7 +266,7 @@ protected GitEndPointResponseData SendRequest( this.authentication.IsAnonymous) { shouldRetry = false; - errorMessage = "Anonymous request was rejected with a 401"; + errorMessage = "Anonymous request was rejected with a 401. " + errorMessage; } else if (ShouldRejectCredentials(response.StatusCode, errorMessage)) { @@ -294,17 +330,23 @@ protected GitEndPointResponseData SendRequest( responseMetadata.Add("connectionWaitTimeMS", $"{connectionWaitTimeElapsed.TotalMilliseconds:F4}"); responseMetadata.Add("responseWaitTimeMS", $"{responseWaitTime.TotalMilliseconds:F4}"); - this.Tracer.RelatedEvent(EventLevel.Informational, "NetworkResponse", responseMetadata); - - if (gitEndPointResponseData == null) + try { - // If gitEndPointResponseData is null there was an unhandled exception - if (response != null) + this.Tracer.RelatedEvent(EventLevel.Informational, "NetworkResponse", responseMetadata); + } + finally + { + if (gitEndPointResponseData == null) { - response.Dispose(); + try + { + response?.Dispose(); + } + finally + { + availableConnections.Release(); + } } - - availableConnections.Release(); } } @@ -383,6 +425,15 @@ internal static string GetAuthorityForTelemetry(Uri uri) return uri.Authority; } + internal static string GetCacheNameForTelemetry(string cacheName) + { + const int MaxCacheNameLength = 128; + return new string(cacheName.Take(MaxCacheNameLength).Select( + character => char.IsLetterOrDigit(character) || character == '-' || character == '_' || character == '.' + ? character + : '_').ToArray()); + } + private static string GetSingleHeaderOrEmpty(HttpHeaders headers, string headerName) { IEnumerable values; diff --git a/GVFS/GVFS.Common/Http/HttpResponseStream.cs b/GVFS/GVFS.Common/Http/HttpResponseStream.cs new file mode 100644 index 0000000000..f22691b9a2 --- /dev/null +++ b/GVFS/GVFS.Common/Http/HttpResponseStream.cs @@ -0,0 +1,390 @@ +#nullable enable + +using GVFS.Common.Tracing; +using System; +using System.Diagnostics; +using System.IO; +using System.Threading; +using System.Threading.Tasks; + +namespace GVFS.Common.Http +{ + internal sealed class HttpResponseStream : Stream + { + private const int FatalErrorExitCode = 1; + internal const int DefaultProgressIntervalSeconds = 30; + private const string ProgressEventName = "NetworkBodyProgress"; + private const string TimeoutEventName = "NetworkBodyReadTimeout"; + private const string TransferEventName = "NetworkBodyTransfer"; + + private readonly Stream _innerStream; + private readonly TimeSpan _readTimeout; + private readonly CancellationToken _requestCancellationToken; + private readonly ITracer? _tracer; + private readonly EventMetadata _requestMetadata; + private readonly TimeSpan _progressInterval; + private readonly Stopwatch _elapsed = Stopwatch.StartNew(); + private readonly object _gate = new object(); + + private CancellationTokenSource? _pendingRead; + private Timer? _progressTimer; + private long _readStarted; + private long _bytesRead; + private long _previousBytesRead; + private long _sampleSequence; + private double _readMilliseconds; + private double _maxReadMilliseconds; + private double _lastProgressMilliseconds; + private bool _reportedProgress; + private int _reportingProgress; + private volatile bool _disposed; + private TransferOutcome _outcome; + + public HttpResponseStream( + Stream innerStream, + TimeSpan readTimeout, + CancellationToken requestCancellationToken, + ITracer? tracer = null, + EventMetadata? requestMetadata = null, + TimeSpan? progressInterval = null) + { + ArgumentNullException.ThrowIfNull(innerStream); + if (readTimeout != Timeout.InfiniteTimeSpan && + (readTimeout <= TimeSpan.Zero || readTimeout.TotalMilliseconds > int.MaxValue)) + { + throw new ArgumentOutOfRangeException(nameof(readTimeout)); + } + + this._innerStream = innerStream; + this._readTimeout = readTimeout; + this._requestCancellationToken = requestCancellationToken; + this._tracer = tracer; + this._requestMetadata = requestMetadata == null ? new EventMetadata() : new EventMetadata(requestMetadata); + this._progressInterval = progressInterval ?? TimeSpan.FromSeconds(DefaultProgressIntervalSeconds); + if (this._progressInterval <= TimeSpan.Zero || this._progressInterval.TotalMilliseconds > int.MaxValue) + { + throw new ArgumentOutOfRangeException(nameof(progressInterval)); + } + + this.ResponseId = Guid.NewGuid().ToString("N"); + } + + public string ResponseId { get; } + + public bool ReadFailed { get; private set; } + + public override bool CanRead => this._innerStream.CanRead; + + public override bool CanSeek => this._innerStream.CanSeek; + + public override bool CanWrite => this._innerStream.CanWrite; + + public override long Length => this._innerStream.Length; + + public override long Position + { + get { return this._innerStream.Position; } + set { this._innerStream.Position = value; } + } + + private enum TransferOutcome + { + InProgress, + Completed, + TimedOut, + Canceled, + ReadError, + Closed, + } + + public override void Flush() => this._innerStream.Flush(); + + public override int Read(byte[] buffer, int offset, int count) + { + ArgumentNullException.ThrowIfNull(buffer); + // The protocol readers are synchronous. Use the cancellable transport read + // because HTTP response streams have no synchronous read deadline. + // Completion and deadline callbacks require managed thread-pool capacity. + return this.ReadAsync(buffer.AsMemory(offset, count), CancellationToken.None).AsTask().GetAwaiter().GetResult(); + } + + public override Task ReadAsync(byte[] buffer, int offset, int count, CancellationToken cancellationToken) + { + ArgumentNullException.ThrowIfNull(buffer); + return this.ReadAsync(buffer.AsMemory(offset, count), cancellationToken).AsTask(); + } + + public override async ValueTask ReadAsync(Memory buffer, CancellationToken cancellationToken = default) + { + cancellationToken.ThrowIfCancellationRequested(); + this._requestCancellationToken.ThrowIfCancellationRequested(); + + using (CancellationTokenSource readCancellation = CancellationTokenSource.CreateLinkedTokenSource( + cancellationToken, + this._requestCancellationToken)) + { + lock (this._gate) + { + ObjectDisposedException.ThrowIf(this._disposed, this); + if (this._pendingRead != null) + { + throw new InvalidOperationException("Another response body read is already in progress."); + } + + if (buffer.Length == 0) + { + return 0; + } + + this._pendingRead = readCancellation; + this._readStarted = Stopwatch.GetTimestamp(); + if (this._tracer != null && this._progressTimer == null && this._outcome == TransferOutcome.InProgress) + { + this._progressTimer = new Timer(this.ReportProgress, null, this._progressInterval, this._progressInterval); + } + } + + TransferOutcome outcome = TransferOutcome.InProgress; + Exception? readError = null; + readCancellation.CancelAfter(this._readTimeout); + try + { + int bytesRead = await this._innerStream.ReadAsync(buffer, readCancellation.Token).ConfigureAwait(false); + lock (this._gate) + { + this._bytesRead += bytesRead; + if (bytesRead > 0) + { + this._lastProgressMilliseconds = this._elapsed.Elapsed.TotalMilliseconds; + } + } + + if (bytesRead == 0) + { + outcome = TransferOutcome.Completed; + } + + return bytesRead; + } + catch (OperationCanceledException e) when ( + readCancellation.IsCancellationRequested && + !cancellationToken.IsCancellationRequested && + !this._requestCancellationToken.IsCancellationRequested && + !this._disposed) + { + this.ReadFailed = true; + outcome = TransferOutcome.TimedOut; + readError = new IOException( + $"No response body data arrived within {this._readTimeout.TotalSeconds} seconds.", + e); + throw readError; + } + catch (OperationCanceledException e) + { + outcome = TransferOutcome.Canceled; + readError = e; + throw; + } + catch (Exception e) + { + this.ReadFailed = true; + outcome = TransferOutcome.ReadError; + readError = e; + throw; + } + finally + { + readCancellation.CancelAfter(Timeout.InfiniteTimeSpan); + EventMetadata? finalReport = null; + lock (this._gate) + { + double readMilliseconds = Stopwatch.GetElapsedTime(this._readStarted).TotalMilliseconds; + this._readMilliseconds += readMilliseconds; + this._maxReadMilliseconds = Math.Max(this._maxReadMilliseconds, readMilliseconds); + this._pendingRead = null; + if (outcome != TransferOutcome.InProgress) + { + finalReport = this.Finish(outcome, readError); + } + } + + this.Trace(finalReport, outcome); + } + } + } + + public override long Seek(long offset, SeekOrigin origin) => this._innerStream.Seek(offset, origin); + + public override void SetLength(long value) => this._innerStream.SetLength(value); + + public override void Write(byte[] buffer, int offset, int count) => this._innerStream.Write(buffer, offset, count); + + protected override void Dispose(bool disposing) + { + try + { + if (disposing) + { + EventMetadata? finalReport = null; + bool disposeInner = false; + try + { + lock (this._gate) + { + if (this._disposed) + { + return; + } + + disposeInner = true; + this._disposed = true; + finalReport = this.Finish(TransferOutcome.Closed); + Timer? progressTimer = this._progressTimer; + this._progressTimer = null; + try + { + this._pendingRead?.Cancel(); + } + finally + { + progressTimer?.Dispose(); + } + } + } + finally + { + if (disposeInner) + { + try + { + this._innerStream.Dispose(); + } + finally + { + this.Trace(finalReport, TransferOutcome.Closed); + } + } + } + } + } + finally + { + base.Dispose(disposing); + } + } + + private void ReportProgress(object? state) + { + if (Interlocked.CompareExchange(ref this._reportingProgress, 1, 0) != 0) + { + return; + } + + try + { + EventMetadata? report = null; + lock (this._gate) + { + if (!this._disposed && this._outcome == TransferOutcome.InProgress) + { + this._reportedProgress = true; + report = this.CreateReport(); + } + } + + this.Trace(report, TransferOutcome.InProgress); + } + catch (ObjectDisposedException) when (this._disposed) + { + // A captured progress sample can outlive response and tracer teardown. + return; + } + catch (Exception e) + { + try + { + this._tracer?.RelatedError( + new EventMetadata { { "Exception", e.ToString() } }, + "The response body progress report failed."); + } + finally + { + Environment.Exit(FatalErrorExitCode); + } + } + finally + { + Volatile.Write(ref this._reportingProgress, 0); + } + } + + private EventMetadata? Finish(TransferOutcome outcome, Exception? readError = null) + { + if (this._outcome != TransferOutcome.InProgress) + { + return null; + } + + this._outcome = outcome; + this._progressTimer?.Change(Timeout.InfiniteTimeSpan, Timeout.InfiniteTimeSpan); + if (this._reportedProgress || + this._elapsed.Elapsed >= this._progressInterval || + outcome == TransferOutcome.TimedOut || + outcome == TransferOutcome.ReadError || + outcome == TransferOutcome.Canceled || + (outcome == TransferOutcome.Closed && this._pendingRead != null)) + { + return this.CreateReport(readError); + } + + return null; + } + + private void Trace(EventMetadata? report, TransferOutcome outcome) + { + if (report == null || this._tracer == null) + { + return; + } + + this._tracer.RelatedEvent( + outcome == TransferOutcome.TimedOut || outcome == TransferOutcome.ReadError + ? EventLevel.Warning + : EventLevel.Informational, + outcome == TransferOutcome.InProgress + ? ProgressEventName + : outcome == TransferOutcome.TimedOut ? TimeoutEventName : TransferEventName, + report, + Keywords.Network | Keywords.Telemetry); + } + + private EventMetadata CreateReport(Exception? readError = null) + { + double currentReadMilliseconds = this._pendingRead == null + ? 0 + : Stopwatch.GetElapsedTime(this._readStarted).TotalMilliseconds; + EventMetadata metadata = new EventMetadata(this._requestMetadata) + { + { "ResponseId", this.ResponseId }, + { "SampleSequence", ++this._sampleSequence }, + { "BytesRead", this._bytesRead }, + { "BytesSinceLastProgress", this._bytesRead - this._previousBytesRead }, + { "ElapsedMs", this._elapsed.Elapsed.TotalMilliseconds }, + { "ReadTimeMs", this._readMilliseconds + currentReadMilliseconds }, + { "MaxReadWaitMs", Math.Max(this._maxReadMilliseconds, currentReadMilliseconds) }, + { "CurrentReadWaitMs", currentReadMilliseconds }, + { "MillisecondsSinceLastByte", this._elapsed.Elapsed.TotalMilliseconds - this._lastProgressMilliseconds }, + { "ReadPending", this._pendingRead != null }, + { "ReadTimeoutMs", this._readTimeout.TotalMilliseconds }, + { "Outcome", this._outcome.ToString() }, + }; + if (readError != null) + { + metadata.Add("Exception", readError.ToString()); + } + + this._previousBytesRead = this._bytesRead; + return metadata; + } + } +} diff --git a/GVFS/GVFS.Common/RetryConfig.cs b/GVFS/GVFS.Common/RetryConfig.cs index 4462a18bcc..5fbdf35670 100644 --- a/GVFS/GVFS.Common/RetryConfig.cs +++ b/GVFS/GVFS.Common/RetryConfig.cs @@ -1,7 +1,8 @@ using GVFS.Common.Git; using GVFS.Common.Tracing; using System; -using System.Linq; +using System.ComponentModel; +using System.IO; namespace GVFS.Common { @@ -9,11 +10,12 @@ public class RetryConfig { public const int DefaultMaxRetries = 6; public const int DefaultTimeoutSeconds = 30; + public const int DefaultReadTimeoutSeconds = 60; public const int FetchAndCloneTimeoutMinutes = 10; private const string EtwArea = nameof(RetryConfig); - - private const int MinRetries = 0; + private const int MaxTimeoutSeconds = int.MaxValue / 1000; + private const int MaxConfiguredRetries = int.MaxValue - 3; private static readonly TimeSpan DefaultTimeout = TimeSpan.FromSeconds(DefaultTimeoutSeconds); @@ -28,7 +30,7 @@ public RetryConfig(int maxRetries, TimeSpan timeout) this.Timeout = timeout; } - public int MaxRetries { get; } + public int MaxRetries { get; set; } public int MaxAttempts { get { return this.MaxRetries + 1; } @@ -36,51 +38,31 @@ public int MaxAttempts public TimeSpan Timeout { get; set; } + public TimeSpan ReadTimeout { get; set; } = TimeSpan.FromSeconds(DefaultReadTimeoutSeconds); + public static bool TryLoadFromGitConfig(ITracer tracer, Enlistment enlistment, out RetryConfig retryConfig, out string error) { - return TryLoadFromGitConfig(tracer, new GitProcess(enlistment), out retryConfig, out error); + return TryLoadFromGitConfig(tracer, enlistment.CreateGitProcess(), out retryConfig, out error); } + /// + /// Invalid or unreadable retry settings use defaults and emit warnings. + /// public static bool TryLoadFromGitConfig(ITracer tracer, GitProcess git, out RetryConfig retryConfig, out string error) { - retryConfig = null; - - int maxRetries; - if (!TryLoadMaxRetries(git, out maxRetries, out error)) - { - if (tracer != null) - { - tracer.RelatedError( - new EventMetadata - { - { "Area", EtwArea }, - { "error", error } - }, - "TryLoadConfig: TryLoadMaxRetries failed"); - } - - return false; - } - - TimeSpan timeout; - if (!TryLoadTimeout(git, out timeout, out error)) + int maxRetries = LoadIntOrDefault( + tracer, git, GVFSConstants.GitConfig.MaxRetriesConfig, DefaultMaxRetries, 0, MaxConfiguredRetries); + int timeoutSeconds = LoadIntOrDefault( + tracer, git, GVFSConstants.GitConfig.TimeoutSecondsConfig, DefaultTimeoutSeconds, 1, MaxTimeoutSeconds); + int readTimeoutSeconds = LoadIntOrDefault( + tracer, git, GVFSConstants.GitConfig.ReadTimeoutSecondsConfig, DefaultReadTimeoutSeconds, 0, MaxTimeoutSeconds); + retryConfig = new RetryConfig(maxRetries, TimeSpan.FromSeconds(timeoutSeconds)) { - if (tracer != null) - { - tracer.RelatedError( - new EventMetadata - { - { "Area", EtwArea }, - { "maxRetries", maxRetries }, - { "error", error } - }, - "TryLoadConfig: TryLoadTimeout failed"); - } - - return false; - } - - retryConfig = new RetryConfig(maxRetries, timeout); + ReadTimeout = readTimeoutSeconds == 0 + ? System.Threading.Timeout.InfiniteTimeSpan + : TimeSpan.FromSeconds(readTimeoutSeconds), + }; + error = string.Empty; if (tracer != null) { @@ -91,6 +73,7 @@ public static bool TryLoadFromGitConfig(ITracer tracer, GitProcess git, out Retr { { "Area", EtwArea }, { "Timeout", retryConfig.Timeout }, + { "ReadTimeout", retryConfig.ReadTimeout }, { "MaxRetries", retryConfig.MaxRetries }, { TracingConstants.MessageKey.InfoMessage, "RetryConfigLoaded" } }); @@ -99,40 +82,44 @@ public static bool TryLoadFromGitConfig(ITracer tracer, GitProcess git, out Retr return true; } - private static bool TryLoadMaxRetries(GitProcess git, out int attempts, out string error) + private static int LoadIntOrDefault( + ITracer tracer, GitProcess git, string configName, int defaultValue, int minValue, int maxValue) { - return TryGetFromGitConfig( - git, - GVFSConstants.GitConfig.MaxRetriesConfig, - DefaultMaxRetries, - MinRetries, - out attempts, - out error); - } + string error; + Exception readException = null; + try + { + GitProcess.ConfigResult result = git.GetFromConfig(configName); + if (result.TryParseAsInt(defaultValue, minValue, out int value, out error) && value <= maxValue) + { + return value; + } - private static bool TryLoadTimeout(GitProcess git, out TimeSpan timeout, out string error) - { - timeout = TimeSpan.FromSeconds(0); - int timeoutSeconds; - if (!TryGetFromGitConfig( - git, - GVFSConstants.GitConfig.TimeoutSecondsConfig, - DefaultTimeoutSeconds, - 0, - out timeoutSeconds, - out error)) + if (string.IsNullOrEmpty(error)) + { + error = $"Invalid value {value} for setting {configName}, value must be between {minValue} and {maxValue}"; + } + } + catch (Exception e) when (e is IOException || e is Win32Exception) { - return false; + readException = e; + error = e.Message; } - timeout = TimeSpan.FromSeconds(timeoutSeconds); - return true; - } + EventMetadata metadata = new EventMetadata + { + { "Area", EtwArea }, + { "ConfigName", configName }, + { "DefaultValue", defaultValue }, + { "Error", error }, + }; + if (readException != null) + { + metadata.Add("Exception", readException.ToString()); + } - private static bool TryGetFromGitConfig(GitProcess git, string configName, int defaultValue, int minValue, out int value, out string error) - { - GitProcess.ConfigResult result = git.GetFromConfig(configName); - return result.TryParseAsInt(defaultValue, minValue, out value, out error); + tracer?.RelatedWarning(metadata, "The retry setting is invalid or unavailable. VFS for Git uses the default value.", Keywords.Telemetry); + return defaultValue; } } } diff --git a/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/PrefetchVerbTests.cs b/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/PrefetchVerbTests.cs index 34784e96b8..26f509b80e 100644 --- a/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/PrefetchVerbTests.cs +++ b/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/PrefetchVerbTests.cs @@ -7,6 +7,11 @@ using System.IO; using System.Linq; using System.Threading; +using System.Threading.Tasks; +using System.Collections.Generic; +using System.Net; +using System.Net.Sockets; +using System.Text; namespace GVFS.FunctionalTests.Tests.EnlistmentPerFixture { @@ -37,6 +42,156 @@ public PrefetchVerbTests() this.fileSystem = new SystemIORunner(); } + [TestCase] + public async Task StalledPrefetchHonorsConfiguredReadDeadline() + { + string[] keys = new[] + { + "gvfs.cache-server", "gvfs.prefetch.cache-server", + "gvfs.read-timeout-seconds", "gvfs.max-retries", + }; + Dictionary previous = this.ReadLocalConfig(keys); + + using CancellationTokenSource cancellation = new CancellationTokenSource(TimeSpan.FromSeconds(30)); + using TcpListener listener = new TcpListener(IPAddress.Loopback, 0); + listener.Start(); + int port = ((IPEndPoint)listener.LocalEndpoint).Port; + string endpoint = $"http://127.0.0.1:{port}"; + Task server = ServeStalledPrefetch(listener, cancellation.Token); + try + { + this.SetLocalConfig(keys[0], endpoint); + this.SetLocalConfig(keys[1], endpoint); + this.SetLocalConfig(keys[2], "1"); + this.SetLocalConfig(keys[3], "0"); + + ProcessResult result = await Task.Run(() => ProcessHelper.Run( + GVFSTestConfig.PathToGVFS, + "prefetch --commits", + this.Enlistment.RepoRoot, + timeoutMs: 20000)); + result.ExitCode.ShouldEqual(3, result.Output + result.Errors); + string log = Directory.GetFiles(Path.Combine(this.Enlistment.DotGVFSRoot, "logs"), "gvfs_prefetch_*.log") + .OrderByDescending(File.GetLastWriteTimeUtc) + .Select(File.ReadAllText) + .First(); + log.ShouldContain("NetworkBodyReadTimeout"); + log.ShouldContain("\"ReadTimeoutMs\":1000"); + log.ShouldContain("\"Outcome\":\"TimedOut\""); + } + finally + { + cancellation.Cancel(); + listener.Stop(); + try + { + await server.WaitAsync(TimeSpan.FromSeconds(5)); + } + catch (OperationCanceledException) when (cancellation.IsCancellationRequested) + { + } + finally + { + this.RestoreLocalConfig(previous); + } + } + } + + [TestCase] + public void InvalidRetrySettingsDoNotStopAMountedEnlistment() + { + Dictionary previous = this.ReadLocalConfig(new[] + { + "gvfs.max-retries", "gvfs.timeout-seconds", "gvfs.read-timeout-seconds", + }); + this.Enlistment.IsMounted().ShouldEqual(true); + try + { + foreach (string key in previous.Keys) + { + this.SetLocalConfig(key, "invalid"); + } + + ProcessResult result = ProcessHelper.Run( + GVFSTestConfig.PathToGVFS, + "prefetch --commits", + this.Enlistment.RepoRoot, + timeoutMs: 30000); + result.ExitCode.ShouldEqual(0, result.Output + result.Errors); + this.Enlistment.IsMounted().ShouldEqual(true); + string log = Directory.GetFiles(Path.Combine(this.Enlistment.DotGVFSRoot, "logs"), "gvfs_prefetch_*.log") + .OrderByDescending(File.GetLastWriteTimeUtc) + .Select(File.ReadAllText) + .First(); + log.ShouldContain("VFS for Git uses the default value."); + foreach (string key in previous.Keys) + { + log.ShouldContain("\"ConfigName\":\"" + key + "\""); + } + } + finally + { + this.RestoreLocalConfig(previous); + } + } + + private Dictionary ReadLocalConfig(IEnumerable keys) + { + Dictionary values = new Dictionary(); + foreach (string key in keys) + { + ProcessResult result = GitProcess.InvokeProcess(this.Enlistment.RepoRoot, "config --local --get " + key); + (result.ExitCode == 0 || result.ExitCode == 1).ShouldEqual(true, result.Errors); + values[key] = result.ExitCode == 0 ? result.Output.TrimEnd('\r', '\n') : null; + } + + return values; + } + + private void RestoreLocalConfig(Dictionary values) + { + foreach (KeyValuePair setting in values) + { + if (setting.Value == null) + { + ProcessResult result = GitProcess.InvokeProcess(this.Enlistment.RepoRoot, "config --local --unset-all " + setting.Key); + (result.ExitCode == 0 || result.ExitCode == 5).ShouldEqual(true, result.Errors); + } + else + { + this.SetLocalConfig(setting.Key, setting.Value); + } + } + } + + private void SetLocalConfig(string key, string value) + { + ProcessResult result = GitProcess.InvokeProcess( + this.Enlistment.RepoRoot, $"config --local {key} \"{value}\""); + result.ExitCode.ShouldEqual(0, result.Errors); + } + + private static async Task ServeStalledPrefetch(TcpListener listener, CancellationToken cancellationToken) + { + using TcpClient client = await listener.AcceptTcpClientAsync(cancellationToken); + using NetworkStream stream = client.GetStream(); + using (StreamReader reader = new StreamReader(stream, Encoding.ASCII, false, 1024, leaveOpen: true)) + { + string line; + do + { + line = await reader.ReadLineAsync(cancellationToken); + } + while (!string.IsNullOrEmpty(line)); + } + + byte[] headers = Encoding.ASCII.GetBytes( + "HTTP/1.1 200 OK\r\nContent-Type: application/x-gvfs-timestamped-packfiles-indexes\r\nContent-Length: 1024\r\n\r\n"); + await stream.WriteAsync(headers.AsMemory(), cancellationToken); + await stream.WriteAsync(new byte[] { (byte)'G' }.AsMemory(), cancellationToken); + await Task.Delay(Timeout.Infinite, cancellationToken); + } + [SetUp] public void DeletePrefetchCache() { diff --git a/GVFS/GVFS.Mount/InProcessMountVerb.cs b/GVFS/GVFS.Mount/InProcessMountVerb.cs index 16328f60d6..4dbe97e7da 100644 --- a/GVFS/GVFS.Mount/InProcessMountVerb.cs +++ b/GVFS/GVFS.Mount/InProcessMountVerb.cs @@ -132,11 +132,7 @@ public void Execute() }; string error; - RetryConfig retryConfig; - if (!RetryConfig.TryLoadFromGitConfig(tracer, enlistment, out retryConfig, out error)) - { - this.ReportErrorAndExit(tracer, "Failed to determine GVFS timeout and max retries: " + error); - } + RetryConfig.TryLoadFromGitConfig(tracer, enlistment, out RetryConfig retryConfig, out _); GitStatusCacheConfig gitStatusCacheConfig; if (!GitStatusCacheConfig.TryLoadFromGitConfig(tracer, enlistment, out gitStatusCacheConfig, out error)) diff --git a/GVFS/GVFS.PerfProfiling/ProfilingEnvironment.cs b/GVFS/GVFS.PerfProfiling/ProfilingEnvironment.cs index 65145acba5..b8d96eebb3 100644 --- a/GVFS/GVFS.PerfProfiling/ProfilingEnvironment.cs +++ b/GVFS/GVFS.PerfProfiling/ProfilingEnvironment.cs @@ -70,11 +70,12 @@ private FileSystemCallbacks CreateFileSystemCallbacks() this.Enlistment.InitializeCachePaths(localCacheRoot, gitObjectsRoot, blobSizesRoot); CacheServerInfo cacheServer = new CacheServerInfo(this.Context.Enlistment.RepoUrl, "None"); + RetryConfig.TryLoadFromGitConfig(this.Context.Tracer, this.Context.Enlistment, out RetryConfig retryConfig, out _); GitObjectsHttpRequestor objectRequestor = new GitObjectsHttpRequestor( this.Context.Tracer, this.Context.Enlistment, cacheServer, - new RetryConfig()); + retryConfig); this.gvfsDatabase = new GVFSDatabase(this.Context.FileSystem, this.Context.Enlistment.DotGVFSRoot, new SqliteDatabase()); GVFSGitObjects gitObjects = new GVFSGitObjects(this.Context, objectRequestor); diff --git a/GVFS/GVFS.UnitTests/Common/RetryConfigTests.cs b/GVFS/GVFS.UnitTests/Common/RetryConfigTests.cs index 0f8c45b26d..af6336edd0 100644 --- a/GVFS/GVFS.UnitTests/Common/RetryConfigTests.cs +++ b/GVFS/GVFS.UnitTests/Common/RetryConfigTests.cs @@ -1,111 +1,213 @@ using GVFS.Common; +using GVFS.Common.FileSystem; using GVFS.Common.Git; using GVFS.Tests.Should; using GVFS.UnitTests.Mock.Common; using GVFS.UnitTests.Mock.Git; using NUnit.Framework; using System; +using System.Collections.Generic; +using System.ComponentModel; +using System.IO; namespace GVFS.UnitTests.Common { [TestFixture] public class RetryConfigTests { - private const string ReadConfigFailureMessage = "Failed to read config"; - [TestCase] - public void TryLoadConfigFailsWhenGitFailsToReadConfig() + [TestCase(GitProcess.Result.SuccessCode)] + [TestCase(GitProcess.Result.GenericFailureCode)] + public void MissingOrBlankSettingsUseDefaultsWithoutWarnings(int exitCode) { - MockTracer tracer = new MockTracer(); - MockGitProcess gitProcess = new MockGitProcess(); - gitProcess.SetExpectedCommandResult("config gvfs.max-retries", () => new GitProcess.Result(string.Empty, ReadConfigFailureMessage, GitProcess.Result.GenericFailureCode)); - gitProcess.SetExpectedCommandResult("config gvfs.timeout-seconds", () => new GitProcess.Result(string.Empty, ReadConfigFailureMessage, GitProcess.Result.GenericFailureCode)); - - RetryConfig config; - string error; - RetryConfig.TryLoadFromGitConfig(tracer, gitProcess, out config, out error).ShouldEqual(false); - error.ShouldContain(ReadConfigFailureMessage); + using MockTracer tracer = new MockTracer(); + MockGitProcess git = new MockGitProcess(); + foreach (string key in new[] + { + "gvfs.max-retries", "gvfs.timeout-seconds", "gvfs.read-timeout-seconds", + }) + { + git.SetExpectedCommandResult("config " + key, + () => new GitProcess.Result(string.Empty, string.Empty, exitCode)); + } + + RetryConfig.TryLoadFromGitConfig(tracer, git, out RetryConfig config, out string error).ShouldEqual(true); + error.ShouldEqual(string.Empty); + config.MaxRetries.ShouldEqual(6); + config.MaxAttempts.ShouldEqual(7); + config.Timeout.ShouldEqual(TimeSpan.FromSeconds(30)); + config.ReadTimeout.ShouldEqual(TimeSpan.FromSeconds(60)); + tracer.RelatedWarningEvents.Count.ShouldEqual(0); + tracer.RelatedErrorEvents.Count.ShouldEqual(0); } [TestCase] - public void TryLoadConfigUsesDefaultValuesWhenEntriesNotInConfig() + public void CompleteLoaderReadsAllSettings() { - MockTracer tracer = new MockTracer(); - MockGitProcess gitProcess = new MockGitProcess(); - gitProcess.SetExpectedCommandResult("config gvfs.max-retries", () => new GitProcess.Result(string.Empty, string.Empty, GitProcess.Result.GenericFailureCode)); - gitProcess.SetExpectedCommandResult("config gvfs.timeout-seconds", () => new GitProcess.Result(string.Empty, string.Empty, GitProcess.Result.GenericFailureCode)); - - RetryConfig config; - string error; - RetryConfig.TryLoadFromGitConfig(tracer, gitProcess, out config, out error).ShouldEqual(true); + using MockTracer tracer = new MockTracer(); + MockGitProcess git = CreateGitProcess(); + RetryConfig.TryLoadFromGitConfig(tracer, git, out RetryConfig config, out string error).ShouldEqual(true); error.ShouldEqual(string.Empty); - config.MaxRetries.ShouldEqual(RetryConfig.DefaultMaxRetries); - config.MaxAttempts.ShouldEqual(config.MaxRetries + 1); - config.Timeout.ShouldEqual(TimeSpan.FromSeconds(RetryConfig.DefaultTimeoutSeconds)); + config.MaxRetries.ShouldEqual(9); + config.MaxAttempts.ShouldEqual(10); + config.Timeout.ShouldEqual(TimeSpan.FromSeconds(45)); + config.ReadTimeout.ShouldEqual(TimeSpan.FromSeconds(90)); + git.CommandsRun.ShouldContain(command => command == "config gvfs.max-retries"); + git.CommandsRun.ShouldContain(command => command == "config gvfs.timeout-seconds"); + git.CommandsRun.ShouldContain(command => command == "config gvfs.read-timeout-seconds"); } - [TestCase] - public void TryLoadConfigUsesDefaultValuesWhenEntriesAreBlank() + [TestCase("gvfs.max-retries", "-1", 6)] + [TestCase("gvfs.max-retries", "invalid", 6)] + [TestCase("gvfs.max-retries", "2147483647", 6)] + [TestCase("gvfs.timeout-seconds", "-1", 30)] + [TestCase("gvfs.timeout-seconds", "0", 30)] + [TestCase("gvfs.timeout-seconds", "invalid", 30)] + [TestCase("gvfs.timeout-seconds", "2147484", 30)] + [TestCase("gvfs.read-timeout-seconds", "-1", 60)] + [TestCase("gvfs.read-timeout-seconds", "invalid", 60)] + [TestCase("gvfs.read-timeout-seconds", "2147484", 60)] + [TestCase("gvfs.read-timeout-seconds", "2147483648", 60)] + public void InvalidSettingUsesOnlyItsOwnDefault(string key, string value, int expectedDefault) { - MockTracer tracer = new MockTracer(); - MockGitProcess gitProcess = new MockGitProcess(); - gitProcess.SetExpectedCommandResult("config gvfs.max-retries", () => new GitProcess.Result(string.Empty, string.Empty, GitProcess.Result.SuccessCode)); - gitProcess.SetExpectedCommandResult("config gvfs.timeout-seconds", () => new GitProcess.Result(string.Empty, string.Empty, GitProcess.Result.SuccessCode)); - - RetryConfig config; - string error; - RetryConfig.TryLoadFromGitConfig(tracer, gitProcess, out config, out error).ShouldEqual(true); + using MockTracer tracer = new MockTracer(); + MockGitProcess git = CreateGitProcess(); + git.SetExpectedCommandResult("config " + key, + () => new GitProcess.Result(value, string.Empty, GitProcess.Result.SuccessCode)); + + RetryConfig.TryLoadFromGitConfig(tracer, git, out RetryConfig config, out string error).ShouldEqual(true); error.ShouldEqual(string.Empty); - config.MaxRetries.ShouldEqual(RetryConfig.DefaultMaxRetries); - config.MaxAttempts.ShouldEqual(config.MaxRetries + 1); - config.Timeout.ShouldEqual(TimeSpan.FromSeconds(RetryConfig.DefaultTimeoutSeconds)); + config.MaxRetries.ShouldEqual(key == "gvfs.max-retries" ? 6 : 9); + config.Timeout.ShouldEqual(TimeSpan.FromSeconds(key == "gvfs.timeout-seconds" ? 30 : 45)); + config.ReadTimeout.ShouldEqual(TimeSpan.FromSeconds(key == "gvfs.read-timeout-seconds" ? 60 : 90)); + tracer.RelatedWarningEvents.Count.ShouldEqual(1); + tracer.RelatedWarningEvents[0].ShouldContain(key); + tracer.RelatedWarningEvents[0].ShouldContain("\"DefaultValue\":" + expectedDefault); + tracer.RelatedErrorEvents.Count.ShouldEqual(0); + } + + [TestCase("0", -1)] + [TestCase("1", 1000)] + [TestCase("2147483", 2147483000)] + public void CompleteLoaderSupportsReadTimeoutBounds(string value, int expectedMilliseconds) + { + using MockTracer tracer = new MockTracer(); + MockGitProcess git = CreateGitProcess(); + git.SetExpectedCommandResult("config gvfs.read-timeout-seconds", + () => new GitProcess.Result(value, string.Empty, GitProcess.Result.SuccessCode)); + RetryConfig.TryLoadFromGitConfig(tracer, git, out RetryConfig config, out _).ShouldEqual(true); + config.ReadTimeout.ShouldEqual(TimeSpan.FromMilliseconds(expectedMilliseconds)); + config.MaxRetries.ShouldEqual(9); + config.Timeout.ShouldEqual(TimeSpan.FromSeconds(45)); + tracer.RelatedWarningEvents.Count.ShouldEqual(0); } [TestCase] - public void TryLoadConfigEnforcesMinimumValuesOnMaxRetries() + public void ReadFailuresUseDefaultsWithoutAborting() { - MockTracer tracer = new MockTracer(); - MockGitProcess gitProcess = new MockGitProcess(); - gitProcess.SetExpectedCommandResult("config gvfs.max-retries", () => new GitProcess.Result("-1", string.Empty, GitProcess.Result.SuccessCode)); - gitProcess.SetExpectedCommandResult("config gvfs.timeout-seconds", () => new GitProcess.Result("30", string.Empty, GitProcess.Result.SuccessCode)); - - RetryConfig config; - string error; - RetryConfig.TryLoadFromGitConfig(tracer, gitProcess, out config, out error).ShouldEqual(false); - error.ShouldContain("Invalid value -1 for setting gvfs.max-retries, value must be greater than or equal to 0"); + using MockTracer tracer = new MockTracer(); + MockGitProcess git = CreateGitProcess(); + foreach (string key in new[] { "gvfs.max-retries", "gvfs.timeout-seconds", "gvfs.read-timeout-seconds" }) + { + git.SetExpectedCommandResult("config " + key, + () => new GitProcess.Result(string.Empty, "Failed to read config", GitProcess.Result.GenericFailureCode)); + } + + RetryConfig.TryLoadFromGitConfig(tracer, git, out RetryConfig config, out string error).ShouldEqual(true); + error.ShouldEqual(string.Empty); + config.MaxRetries.ShouldEqual(6); + config.Timeout.ShouldEqual(TimeSpan.FromSeconds(30)); + config.ReadTimeout.ShouldEqual(TimeSpan.FromSeconds(60)); + tracer.RelatedWarningEvents.Count.ShouldEqual(3); + tracer.RelatedErrorEvents.Count.ShouldEqual(0); + } + + [TestCase(false)] + [TestCase(true)] + public void ConfigReadExceptionsUseDefaultsAndKeepTheExceptionInDiagnostics(bool processError) + { + using MockTracer tracer = new MockTracer(); + MockGitProcess git = CreateGitProcess(new ThrowingGitProcess(processError)); + RetryConfig.TryLoadFromGitConfig(tracer, git, out RetryConfig config, out string error).ShouldEqual(true); + error.ShouldEqual(string.Empty); + config.MaxRetries.ShouldEqual(9); + config.Timeout.ShouldEqual(TimeSpan.FromSeconds(45)); + config.ReadTimeout.ShouldEqual(TimeSpan.FromSeconds(60)); + tracer.RelatedWarningEvents.Count.ShouldEqual(1); + tracer.RelatedWarningEvents[0].ShouldContain("\"Exception\":"); + tracer.RelatedWarningEvents[0].ShouldContain(processError ? "Win32Exception" : "IOException"); + tracer.RelatedErrorEvents.Count.ShouldEqual(0); } [TestCase] - public void TryLoadConfigEnforcesMinimumValuesOnTimeout() + public void LaterInvalidSettingsDoNotMutateAnExistingConfiguration() { - MockTracer tracer = new MockTracer(); - MockGitProcess gitProcess = new MockGitProcess(); - gitProcess.SetExpectedCommandResult("config gvfs.max-retries", () => new GitProcess.Result("3", string.Empty, GitProcess.Result.SuccessCode)); - gitProcess.SetExpectedCommandResult("config gvfs.timeout-seconds", () => new GitProcess.Result("-1", string.Empty, GitProcess.Result.SuccessCode)); - - RetryConfig config; - string error; - RetryConfig.TryLoadFromGitConfig(tracer, gitProcess, out config, out error).ShouldEqual(false); - error.ShouldContain("Invalid value -1 for setting gvfs.timeout-seconds, value must be greater than or equal to 0"); + using MockTracer tracer = new MockTracer(); + MockGitProcess git = CreateGitProcess(); + RetryConfig.TryLoadFromGitConfig(tracer, git, out RetryConfig existing, out _).ShouldEqual(true); + git.SetExpectedCommandResult("config gvfs.read-timeout-seconds", + () => new GitProcess.Result("invalid", string.Empty, GitProcess.Result.SuccessCode)); + + RetryConfig.TryLoadFromGitConfig(tracer, git, out RetryConfig reloaded, out _).ShouldEqual(true); + existing.ReadTimeout.ShouldEqual(TimeSpan.FromSeconds(90)); + reloaded.ReadTimeout.ShouldEqual(TimeSpan.FromSeconds(60)); + reloaded.MaxRetries.ShouldEqual(existing.MaxRetries); + reloaded.Timeout.ShouldEqual(existing.Timeout); } [TestCase] - public void TryLoadConfigUsesConfiguredValues() + public void CommandOverridesDoNotDiscardLoadedReadTimeout() { - int maxRetries = RetryConfig.DefaultMaxRetries + 1; - int timeoutSeconds = RetryConfig.DefaultTimeoutSeconds + 1; + using MockTracer tracer = new MockTracer(); + RetryConfig.TryLoadFromGitConfig(tracer, CreateGitProcess(), out RetryConfig config, out _).ShouldEqual(true); + config.MaxRetries = 2; + config.Timeout = TimeSpan.FromMinutes(10); + config.MaxRetries.ShouldEqual(2); + config.MaxAttempts.ShouldEqual(3); + config.Timeout.ShouldEqual(TimeSpan.FromMinutes(10)); + config.ReadTimeout.ShouldEqual(TimeSpan.FromSeconds(90)); + } - MockTracer tracer = new MockTracer(); - MockGitProcess gitProcess = new MockGitProcess(); - gitProcess.SetExpectedCommandResult("config gvfs.max-retries", () => new GitProcess.Result(maxRetries.ToString(), string.Empty, GitProcess.Result.SuccessCode)); - gitProcess.SetExpectedCommandResult("config gvfs.timeout-seconds", () => new GitProcess.Result(timeoutSeconds.ToString(), string.Empty, GitProcess.Result.SuccessCode)); + private static MockGitProcess CreateGitProcess(MockGitProcess git = null) + { + git = git ?? new MockGitProcess(); + foreach (KeyValuePair setting in new Dictionary + { + { "gvfs.max-retries", "9" }, + { "gvfs.timeout-seconds", "45" }, + { "gvfs.read-timeout-seconds", "90" }, + }) + { + git.SetExpectedCommandResult("config " + setting.Key, + () => new GitProcess.Result(setting.Value, string.Empty, GitProcess.Result.SuccessCode)); + } - RetryConfig config; - string error; - RetryConfig.TryLoadFromGitConfig(tracer, gitProcess, out config, out error).ShouldEqual(true); - error.ShouldEqual(string.Empty); - config.MaxRetries.ShouldEqual(maxRetries); - config.MaxAttempts.ShouldEqual(config.MaxRetries + 1); - config.Timeout.ShouldEqual(TimeSpan.FromSeconds(timeoutSeconds)); + return git; + } + + private class ThrowingGitProcess : MockGitProcess + { + private readonly bool processError; + + public ThrowingGitProcess(bool processError) + { + this.processError = processError; + } + + public override ConfigResult GetFromConfig( + string settingName, bool forceOutsideEnlistment = false, PhysicalFileSystem fileSystem = null) + { + if (settingName == "gvfs.read-timeout-seconds") + { + if (this.processError) + { + throw new Win32Exception("Could not start git"); + } + + throw new IOException("Could not read config"); + } + + return base.GetFromConfig(settingName, forceOutsideEnlistment, fileSystem); + } } } } diff --git a/GVFS/GVFS.UnitTests/Git/GitObjectsTests.cs b/GVFS/GVFS.UnitTests/Git/GitObjectsTests.cs index 78236a37bc..fc1f9686b1 100644 --- a/GVFS/GVFS.UnitTests/Git/GitObjectsTests.cs +++ b/GVFS/GVFS.UnitTests/Git/GitObjectsTests.cs @@ -14,6 +14,8 @@ using System.Net.Http.Headers; using System.Security; using System.Threading; +using System.Threading.Tasks; +using System.Linq; namespace GVFS.UnitTests.Git { @@ -185,6 +187,175 @@ public void UnsupportedPrefetchTelemetryReportsOnlyRequestAuthority() metadata["PrefetchEndpointUrl"].ShouldEqual("cache.example:8443"); } + [TestCase] + public void PrefetchPackTelemetryCorrelatesResponseAndRetrySummary() + { + using MockTracer tracer = new MockTracer(); + MockGVFSEnlistment enlistment = new MockGVFSEnlistment(); + using StreamingPrefetchRequestor requestor = new StreamingPrefetchRequestor(tracer, enlistment); + requestor.Streams.Enqueue(CreatePrefetchResponse(1)); + TestPrefetchGitObjects objects = new TestPrefetchGitObjects(tracer, enlistment, requestor); + + objects.TryDownloadPrefetchPacks(null, 0, true, out List indexes).ShouldEqual(true); + indexes.Count.ShouldEqual(1); + MockTracer activity = tracer.StartActivityTracer; + int packIndex = activity.RelatedEventNames.IndexOf("Receiving Pack/Index"); + (packIndex >= 0).ShouldEqual(true); + EventMetadata pack = activity.RelatedEventMetadata[packIndex]; + pack["ResponseId"].ShouldEqual(requestor.ResponseId); + pack["PackBytes"].ShouldEqual(1L); + ((activity.RelatedEventKeywords[packIndex] & Keywords.Telemetry) != 0).ShouldEqual(true); + EventMetadata start = tracer.StartMetadata.Single(metadata => metadata != null && metadata.ContainsKey("RequestId")); + EventMetadata stop = activity.StopMetadata.Single(); + start["RequestId"].ShouldEqual(requestor.RequestId); + stop["RequestId"].ShouldEqual(requestor.RequestId); + stop["Success"].ShouldEqual(true); + } + + [TestCase] + public async Task PrefetchHeaderFailureDrainsEarlierPackWorkBeforeRetry() + { + using MockTracer tracer = new MockTracer(); + MockGVFSEnlistment enlistment = new MockGVFSEnlistment(); + using StreamingPrefetchRequestor requestor = new StreamingPrefetchRequestor(tracer, enlistment); + using MemoryStream initialResponse = CreatePrefetchResponse(2); + using HeaderFailureStream firstResponse = new HeaderFailureStream(initialResponse.ToArray()); + requestor.Streams.Enqueue(firstResponse); + requestor.Streams.Enqueue(CreatePrefetchResponse(0)); + TaskCompletionSource flush = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + TestPrefetchGitObjects objects = new TestPrefetchGitObjects(tracer, enlistment, requestor) + { + FirstFlush = flush.Task, + }; + Task prefetch = Task.Run(() => objects.TryDownloadPrefetchPacks(null, 0, true, out List _)); + try + { + await firstResponse.Failed.Task.WaitAsync(TimeSpan.FromSeconds(5)); + await Task.Delay(100); + requestor.Requests.Count.ShouldEqual(1); + prefetch.IsCompleted.ShouldEqual(false); + } + finally + { + flush.TrySetResult(true); + } + + (await prefetch.WaitAsync(TimeSpan.FromSeconds(5))).ShouldEqual(true); + requestor.Requests.Count.ShouldEqual(2); + requestor.Requests[1].Query.ShouldEqual("?lastPackTimestamp=1"); + objects.Moves.ShouldEqual(2); + } + + private static MemoryStream CreatePrefetchResponse(ushort declaredPacks) + { + MemoryStream response = new MemoryStream(); + using (BinaryWriter writer = new BinaryWriter(response, System.Text.Encoding.UTF8, leaveOpen: true)) + { + writer.Write(new byte[] { (byte)'G', (byte)'P', (byte)'R', (byte)'E', (byte)' ', 1 }); + writer.Write(declaredPacks); + if (declaredPacks > 0) + { + writer.Write(1L); + writer.Write(1L); + writer.Write(1L); + writer.Write((byte)1); + writer.Write((byte)2); + } + } + + response.Position = 0; + return response; + } + + private class HeaderFailureStream : MemoryStream + { + public HeaderFailureStream(byte[] data) : base(data) + { + } + + public TaskCompletionSource Failed { get; } = new TaskCompletionSource( + TaskCreationOptions.RunContinuationsAsynchronously); + + public override ValueTask ReadAsync(Memory buffer, CancellationToken cancellationToken = default) + { + if (this.Position == this.Length) + { + this.Failed.TrySetResult(true); + throw new IOException("Next prefetch header failed"); + } + + return base.ReadAsync(buffer, cancellationToken); + } + } + + private class StreamingPrefetchRequestor : GitObjectsHttpRequestor + { + public StreamingPrefetchRequestor(MockTracer tracer, MockGVFSEnlistment enlistment) + : base(tracer, enlistment, new CacheServerInfo("mock://cache/server", "cache"), new RetryConfig(1)) + { + } + + public Queue Streams { get; } = new Queue(); + public List Requests { get; } = new List(); + public string ResponseId { get; private set; } + public long RequestId { get; private set; } + + protected override GitEndPointResponseData SendProtocolRequest( + long requestId, Uri requestUri, HttpMethod httpMethod, string requestContent, + CancellationToken cancellationToken, MediaTypeWithQualityHeaderValue acceptType = null) + { + this.RequestId = requestId; + this.Requests.Add(requestUri); + GitEndPointResponseData response = new GitEndPointResponseData( + HttpStatusCode.OK, GVFSConstants.MediaTypes.PrefetchPackFilesAndIndexesMediaType, + this.Streams.Dequeue(), null, null); + this.ResponseId = response.ResponseId; + return response; + } + } + + private class TestPrefetchGitObjects : GVFSGitObjects + { + private int moves; + private int writes; + + public TestPrefetchGitObjects(MockTracer tracer, MockGVFSEnlistment enlistment, GitObjectsHttpRequestor requestor) + : this(tracer, enlistment, requestor, new PrefetchFileSystem()) + { + } + + private TestPrefetchGitObjects(MockTracer tracer, MockGVFSEnlistment enlistment, + GitObjectsHttpRequestor requestor, MockFileSystemWithCallbacks filesystem) + : base(new GVFSContext(tracer, filesystem, null, enlistment), requestor) + { + filesystem.OnOpenFileStream = (path, mode, access) => new MemoryStream(); + filesystem.OnMoveFile = (source, target) => Interlocked.Increment(ref this.moves); + filesystem.OnFileExists = path => false; + } + + public Task FirstFlush { get; set; } = Task.CompletedTask; + public int Moves => this.moves; + + public override bool TryWriteTempFile(ITracer tracer, Stream source, string tempFilePath, + out long fileLength, out Task flushTask, bool throwOnError = false) + { + fileLength = source.Length; + source.CopyTo(Stream.Null); + flushTask = ++this.writes == 1 ? this.FirstFlush : Task.CompletedTask; + return true; + } + + public override string[] ReadPackFileNames(string packFolderPath, string prefixFilter = "") => Array.Empty(); + } + + private class PrefetchFileSystem : MockFileSystemWithCallbacks + { + public override void MoveAndOverwriteFile(string sourceFileName, string destinationFileName) + { + this.OnMoveFile(sourceFileName, destinationFileName); + } + } + private Stream OnOpenFileStream(string path, FileMode mode, FileAccess access) { this.openedPaths.Add(path); diff --git a/GVFS/GVFS.UnitTests/Http/GitObjectsHttpRequestorTests.cs b/GVFS/GVFS.UnitTests/Http/GitObjectsHttpRequestorTests.cs index ee89a68ae2..f1d284a54b 100644 --- a/GVFS/GVFS.UnitTests/Http/GitObjectsHttpRequestorTests.cs +++ b/GVFS/GVFS.UnitTests/Http/GitObjectsHttpRequestorTests.cs @@ -13,6 +13,7 @@ using System.Net.Http.Headers; using System.Text; using System.Threading; +using System.Threading.Tasks; namespace GVFS.UnitTests.Http { @@ -149,6 +150,34 @@ public void ResponseBodyReadFailureFallsBackToGlobalCacheServer() RetryCircuitBreaker.ConsecutiveFailures.ShouldEqual(0); } + [TestCase(false)] + [TestCase(true)] + public void ResponseBodyReadTimeoutUsesExistingRetryOrFallback(bool endpointOverrides) + { + TestGitObjectsHttpRequestor requestor = this.CreateRequestor( + maxRetries: endpointOverrides ? 0 : 1, + endpointOverrides: endpointOverrides); + requestor.RetryConfig.ReadTimeout = TimeSpan.FromMilliseconds(100); + requestor.EnqueueResponse(new StallingReadStream()); + requestor.EnqueueResponse(HttpStatusCode.OK); + + RetryWrapper.InvocationResult result = + requestor.TryDownloadObjects( + new[] { "0123456789abcdef" }, + onSuccess: (tryCount, response) => + { + response.Stream.ReadByte(); + return SuccessfulRequest(tryCount, response); + }, + onFailure: null, + preferBatchedLooseObjects: false); + + result.Succeeded.ShouldEqual(true); + requestor.RequestUris.Count.ShouldEqual(2); + requestor.TestTracer.RelatedEventNames.ShouldContain(name => name == "NetworkBodyReadTimeout"); + requestor.TestTracer.RelatedEventNames.Contains("CacheServerFallback").ShouldEqual(endpointOverrides); + } + [TestCase] public void ResponseBodyReadFailureReportedByHandlerFallsBackToGlobalCacheServer() { @@ -440,7 +469,7 @@ protected override GitEndPointResponseData SendProtocolRequest( return new GitEndPointResponseData( HttpStatusCode.OK, "application/json", - stream, + new HttpResponseStream(stream, this.RetryConfig.ReadTimeout, cancellationToken, this.TestTracer), message: null, onResponseDisposed: null); } @@ -468,7 +497,7 @@ protected override GitEndPointResponseData SendProtocolRequest( private class ThrowingReadStream : MemoryStream { - public override int ReadByte() + public override ValueTask ReadAsync(Memory buffer, CancellationToken cancellationToken = default) { throw new IOException("Response body read failed"); } @@ -476,10 +505,19 @@ public override int ReadByte() private class CancelingReadStream : MemoryStream { - public override int Read(byte[] buffer, int offset, int count) + public override ValueTask ReadAsync(Memory buffer, CancellationToken cancellationToken = default) { throw new OperationCanceledException("Response body read canceled"); } } + + private class StallingReadStream : MemoryStream + { + public override async ValueTask ReadAsync(Memory buffer, CancellationToken cancellationToken = default) + { + await Task.Delay(Timeout.Infinite, cancellationToken).ConfigureAwait(false); + return 0; + } + } } } diff --git a/GVFS/GVFS.UnitTests/Http/HttpRequestorTests.cs b/GVFS/GVFS.UnitTests/Http/HttpRequestorTests.cs index e81b81170d..a88d2fdd3b 100644 --- a/GVFS/GVFS.UnitTests/Http/HttpRequestorTests.cs +++ b/GVFS/GVFS.UnitTests/Http/HttpRequestorTests.cs @@ -84,5 +84,19 @@ public void AuthorityForTelemetryExcludesCredentialsAndRequestPath() HttpRequestor.GetAuthorityForTelemetry(uri).ShouldEqual("cache.example.com:8443"); } + + [TestCase("", "")] + [TestCase("cache-01_test.example", "cache-01_test.example")] + [TestCase("cache:\r\nname?secret", "cache___name_secret")] + public void CacheNameTelemetryContainsOnlyIdentityCharacters(string input, string expected) + { + HttpRequestor.GetCacheNameForTelemetry(input).ShouldEqual(expected); + } + + [TestCase] + public void CacheNameTelemetryHasABoundedLength() + { + HttpRequestor.GetCacheNameForTelemetry(new string('a', 1000)).ShouldEqual(new string('a', 128)); + } } } diff --git a/GVFS/GVFS.UnitTests/Http/HttpResponseStreamTests.cs b/GVFS/GVFS.UnitTests/Http/HttpResponseStreamTests.cs new file mode 100644 index 0000000000..f5e8e6bdb5 --- /dev/null +++ b/GVFS/GVFS.UnitTests/Http/HttpResponseStreamTests.cs @@ -0,0 +1,743 @@ +using GVFS.Common; +using GVFS.Common.Http; +using GVFS.Common.Tracing; +using GVFS.Tests.Should; +using GVFS.UnitTests.Mock.Common; +using GVFS.UnitTests.Mock.Git; +using NUnit.Framework; +using System; +using System.IO; +using System.Linq; +using System.Net; +using System.Net.Http; +using System.Net.Sockets; +using System.Text; +using System.Threading; +using System.Threading.Tasks; + +namespace GVFS.UnitTests.Http +{ + [TestFixture] + public class HttpResponseStreamTests + { + [TestCase] + public void DefaultReadTimeoutIsSixtySeconds() + { + new RetryConfig().ReadTimeout.ShouldEqual(TimeSpan.FromSeconds(60)); + new RetryConfig(1, TimeSpan.FromMinutes(10)).ReadTimeout.ShouldEqual(TimeSpan.FromSeconds(60)); + HttpResponseStream.DefaultProgressIntervalSeconds.ShouldEqual(30); + } + + [TestCase] + public void SynchronousReadTimesOut() + { + using (HttpResponseStream stream = CreateStream(new BlockingReadStream())) + { + IOException error = Assert.Throws(() => stream.Read(new byte[8], 0, 8).ShouldEqual(0)); + error.Message.ShouldContain("No response body data arrived"); + stream.ReadFailed.ShouldEqual(true); + } + } + + [TestCase] + public void ReadByteTimesOut() + { + using (HttpResponseStream stream = CreateStream(new BlockingReadStream())) + { + Assert.Throws(() => stream.ReadByte()); + stream.ReadFailed.ShouldEqual(true); + } + } + + [TestCase] + public void SpanReadTimesOut() + { + using (HttpResponseStream stream = CreateStream(new BlockingReadStream())) + { + Assert.Throws(() => stream.Read(new byte[8].AsSpan()).ShouldEqual(0)); + stream.ReadFailed.ShouldEqual(true); + } + } + + [TestCase] + public void ArrayReadAsyncTimesOut() + { + using (HttpResponseStream stream = CreateStream(new BlockingReadStream())) + { + Task read = stream.ReadAsync(new byte[8], 0, 8, CancellationToken.None); + Assert.ThrowsAsync(async () => await read.WaitAsync(TimeSpan.FromSeconds(5))); + stream.ReadFailed.ShouldEqual(true); + } + } + + [TestCase] + public void MemoryReadAsyncTimesOut() + { + using (HttpResponseStream stream = CreateStream(new BlockingReadStream())) + { + Task read = stream.ReadAsync(new byte[8].AsMemory()).AsTask(); + Assert.ThrowsAsync(async () => await read.WaitAsync(TimeSpan.FromSeconds(5))); + stream.ReadFailed.ShouldEqual(true); + } + } + + [TestCase] + public async Task SlowTransferContinuesBeyondTheReadTimeout() + { + using MockTracer tracer = new MockTracer(); + using (HttpResponseStream stream = CreateStream( + new SlowReadStream(12, TimeSpan.FromMilliseconds(50)), + tracer, + readTimeout: TimeSpan.FromMilliseconds(300))) + { + byte[] buffer = new byte[80 * 1024]; + int total = 0; + int read; + while ((read = await stream.ReadAsync(buffer.AsMemory())) != 0) + { + total += read; + } + + total.ShouldEqual(12); + stream.ReadFailed.ShouldEqual(false); + tracer.RelatedEventNames.ShouldNotContain(name => name == "NetworkBodyReadTimeout"); + EventMetadata summary = tracer.RelatedEventMetadata.Last(); + summary["Outcome"].ShouldEqual("Completed"); + summary["BytesRead"].ShouldEqual(12L); + ((double)summary["ElapsedMs"] > 300).ShouldEqual(true); + } + } + + [TestCase] + public async Task ConsumerPauseDoesNotTimeOutAndReportsNoPendingRead() + { + using MockTracer tracer = new MockTracer(); + using (HttpResponseStream stream = CreateStream(new MemoryStream(new byte[] { 1, 2 }), tracer)) + { + stream.ReadByte().ShouldEqual(1); + await Task.Delay(600); + stream.ReadByte().ShouldEqual(2); + stream.ReadByte().ShouldEqual(-1); + stream.ReadFailed.ShouldEqual(false); + tracer.RelatedEventNames.ShouldNotContain(name => name == "NetworkBodyReadTimeout"); + tracer.RelatedEventMetadata.ShouldContain( + metadata => (string)metadata["Outcome"] == "InProgress" && + (bool)metadata["ReadPending"] == false && + (long)metadata["BytesRead"] == 1); + } + } + + [TestCase(false)] + [TestCase(true)] + public async Task CallerCancellationIsNotAReadFailure(bool cancelRequest) + { + using MockTracer tracer = new MockTracer(); + using (CancellationTokenSource cancellation = new CancellationTokenSource()) + using (BlockingReadStream innerStream = new BlockingReadStream()) + using (HttpResponseStream stream = new HttpResponseStream( + innerStream, + TimeSpan.FromSeconds(60), + cancelRequest ? cancellation.Token : CancellationToken.None, + tracer)) + { + Task read = stream.ReadAsync( + new byte[8].AsMemory(), + cancelRequest ? CancellationToken.None : cancellation.Token).AsTask(); + await innerStream.ReadStarted.Task.WaitAsync(TimeSpan.FromSeconds(5)); + cancellation.Cancel(); + Assert.CatchAsync(async () => await read.WaitAsync(TimeSpan.FromSeconds(5))); + stream.ReadFailed.ShouldEqual(false); + tracer.RelatedEventMetadata.Last()["Outcome"].ShouldEqual("Canceled"); + tracer.RelatedEventLevels.Last().ShouldEqual(EventLevel.Informational); + } + } + + [TestCase] + public async Task DisposingCancelsPendingReadWithoutCallingItATimeout() + { + using MockTracer tracer = new MockTracer(); + using (BlockingReadStream innerStream = new BlockingReadStream()) + { + HttpResponseStream stream = CreateStream(innerStream, tracer, TimeSpan.FromSeconds(60)); + Task read = stream.ReadAsync(new byte[8].AsMemory()).AsTask(); + await innerStream.ReadStarted.Task.WaitAsync(TimeSpan.FromSeconds(5)); + stream.Dispose(); + Assert.CatchAsync(async () => await read.WaitAsync(TimeSpan.FromSeconds(5))); + stream.ReadFailed.ShouldEqual(false); + tracer.RelatedEventNames.ShouldNotContain(name => name == "NetworkBodyReadTimeout"); + tracer.RelatedEventMetadata.Last()["Outcome"].ShouldEqual("Closed"); + } + } + + [TestCase] + public void BlockedReadReportsProgressAndTimeoutWithMatchingResponseId() + { + using MockTracer tracer = new MockTracer(); + using (HttpResponseStream stream = CreateStream(new BlockingReadStream(), tracer)) + { + Assert.ThrowsAsync( + async () => await stream.ReadAsync(new byte[8].AsMemory()).AsTask().WaitAsync(TimeSpan.FromSeconds(5))); + tracer.RelatedEventNames.ShouldContain(name => name == "NetworkBodyProgress"); + tracer.RelatedEventNames.Last().ShouldEqual("NetworkBodyReadTimeout"); + tracer.RelatedEventMetadata.ShouldContain( + metadata => (bool)metadata["ReadPending"] && (double)metadata["CurrentReadWaitMs"] > 0); + foreach (EventMetadata metadata in tracer.RelatedEventMetadata) + { + metadata["ResponseId"].ShouldEqual(stream.ResponseId); + ((long)metadata["SampleSequence"] > 0).ShouldEqual(true); + metadata["RequestId"].ShouldEqual(42L); + metadata["CacheName"].ShouldEqual("test-cache"); + metadata["RequestAuthority"].ShouldEqual("cache.example:443"); + } + + EventMetadata timeout = tracer.RelatedEventMetadata.Last(); + timeout["Outcome"].ShouldEqual("TimedOut"); + timeout["BytesRead"].ShouldEqual(0L); + tracer.RelatedEventLevels.Last().ShouldEqual(EventLevel.Warning); + ((double)timeout["MaxReadWaitMs"] >= 200).ShouldEqual(true); + ((double)timeout["ReadTimeMs"] >= 200).ShouldEqual(true); + tracer.RelatedEventKeywords.ShouldContain( + keywords => (keywords & Keywords.Telemetry) == Keywords.Telemetry); + } + } + + [TestCase] + public void ReadTimeoutReportsBytesReceivedBeforeTheStall() + { + using (MockTracer tracer = new MockTracer()) + using (HttpResponseStream stream = CreateStream(new BlockingReadStream(new byte[] { 1, 2, 3 }), tracer)) + { + byte[] buffer = new byte[8]; + stream.Read(buffer, 0, buffer.Length).ShouldEqual(3); + Assert.Throws(() => stream.Read(buffer, 0, buffer.Length).ShouldEqual(0)); + EventMetadata timeout = tracer.RelatedEventMetadata.Last(); + timeout["Outcome"].ShouldEqual("TimedOut"); + timeout["BytesRead"].ShouldEqual(3L); + ((double)timeout["MillisecondsSinceLastByte"] >= 200).ShouldEqual(true); + ((string)timeout["Exception"]).ShouldContain("System.IO.IOException"); + } + } + + [TestCase(false)] + [TestCase(true)] + public async Task ProgressStopsAfterCompletionOrDisposal(bool readToEnd) + { + using MockTracer tracer = new MockTracer(); + HttpResponseStream stream = CreateStream(new MemoryStream(new byte[] { 1 }), tracer); + stream.ReadByte().ShouldEqual(1); + await Task.Delay(120); + if (readToEnd) + { + stream.ReadByte().ShouldEqual(-1); + } + + stream.Dispose(); + int eventCount = tracer.RelatedEventNames.Count; + await Task.Delay(120); + tracer.RelatedEventNames.Count.ShouldEqual(eventCount); + } + + [TestCase] + public async Task ZeroLengthReadsDoNotStartAReadOrCompleteTheTransfer() + { + using (BlockingReadStream innerStream = new BlockingReadStream()) + using (HttpResponseStream stream = CreateStream(innerStream)) + { + stream.Read(new byte[1], 0, 0).ShouldEqual(0); + (await stream.ReadAsync(Memory.Empty)).ShouldEqual(0); + innerStream.ReadStarted.Task.IsCompleted.ShouldEqual(false); + stream.ReadFailed.ShouldEqual(false); + Assert.Throws(() => stream.Read(null, 0, 0).ShouldEqual(0)); + Assert.Throws(() => stream.Read(new byte[1], 0, 2).ShouldEqual(0)); + } + } + + [TestCase] + public void FastTransfersDoNotEmitProgressEvents() + { + using MockTracer tracer = new MockTracer(); + using (HttpResponseStream stream = new HttpResponseStream( + new MemoryStream(new byte[] { 1 }), + TimeSpan.FromSeconds(60), + CancellationToken.None, + tracer)) + { + stream.ReadByte().ShouldEqual(1); + stream.ReadByte().ShouldEqual(-1); + } + + tracer.RelatedEventNames.Count.ShouldEqual(0); + } + + [TestCase] + public async Task RealHttpBodyReadTimesOutAfterHeadersAndPartialData() + { + using (MockTracer tracer = new MockTracer()) + using (CancellationTokenSource serverCancellation = new CancellationTokenSource(TimeSpan.FromSeconds(10))) + using (TcpListener listener = new TcpListener(IPAddress.Loopback, 0)) + using (HttpClient client = new HttpClient()) + { + listener.Start(); + Task server = ServeStalledResponse(listener, serverCancellation.Token); + try + { + int port = ((IPEndPoint)listener.LocalEndpoint).Port; + using (HttpResponseMessage response = await client.GetAsync( + $"http://127.0.0.1:{port}/body", + HttpCompletionOption.ResponseHeadersRead).WaitAsync(TimeSpan.FromSeconds(5))) + using (HttpResponseStream stream = CreateStream(await response.Content.ReadAsStreamAsync(), tracer)) + { + stream.ReadByte().ShouldEqual((int)'x'); + Assert.ThrowsAsync( + async () => await stream.ReadAsync(new byte[8].AsMemory()).AsTask().WaitAsync(TimeSpan.FromSeconds(5))); + stream.ReadFailed.ShouldEqual(true); + tracer.RelatedEventNames.Last().ShouldEqual("NetworkBodyReadTimeout"); + } + } + finally + { + serverCancellation.Cancel(); + listener.Stop(); + try + { + await server.WaitAsync(TimeSpan.FromSeconds(5)); + } + catch (OperationCanceledException) when (serverCancellation.IsCancellationRequested) + { + } + } + } + } + + [TestCase(HttpStatusCode.OK)] + [TestCase(HttpStatusCode.ServiceUnavailable)] + [TestCase(HttpStatusCode.Unauthorized)] + [TestCase(HttpStatusCode.NotFound)] + public async Task RequestorAppliesConfiguredReadTimeoutToSuccessAndErrorBodies(HttpStatusCode status) + { + using (MockTracer tracer = new MockTracer()) + using (CancellationTokenSource serverCancellation = new CancellationTokenSource(TimeSpan.FromSeconds(10))) + using (TcpListener listener = new TcpListener(IPAddress.Loopback, 0)) + using (LoopbackHttpRequestor requestor = new LoopbackHttpRequestor(tracer)) + { + listener.Start(); + Task server = ServeStalledResponse(listener, serverCancellation.Token, status); + try + { + int port = ((IPEndPoint)listener.LocalEndpoint).Port; + Uri uri = new Uri($"http://127.0.0.1:{port}/body?query-marker=not-for-telemetry"); + if (status == HttpStatusCode.OK) + { + using (GitEndPointResponseData response = requestor.Get(uri)) + { + response.Stream.ReadByte().ShouldEqual((int)'x'); + Assert.Throws(() => response.Stream.ReadByte()); + response.StreamReadFailed.ShouldEqual(true); + response.ResponseId.ShouldEqual((string)tracer.RelatedEventMetadata + .Last(metadata => metadata.ContainsKey("ResponseId"))["ResponseId"]); + } + } + else + { + using (GitEndPointResponseData response = requestor.Get(uri)) + { + response.StatusCode.ShouldEqual(status); + ((GitObjectsHttpException)response.Error).StatusCode.ShouldEqual(status); + response.Error.Message.ShouldContain("response body"); + response.Error.Message.ShouldContain("No response body data arrived"); + response.ShouldRetry.ShouldEqual(status == HttpStatusCode.ServiceUnavailable); + } + } + + int timeoutIndex = tracer.RelatedEventNames.IndexOf("NetworkBodyReadTimeout"); + (timeoutIndex >= 0).ShouldEqual(true); + EventMetadata timeout = tracer.RelatedEventMetadata[timeoutIndex]; + timeout["RequestId"].ShouldEqual(42L); + timeout["StatusCode"].ShouldEqual(status); + timeout["CacheName"].ShouldEqual("test-cache"); + timeout["RequestAuthority"].ShouldEqual($"127.0.0.1:{port}"); + timeout["BytesRead"].ShouldEqual(1L); + timeout["ReadTimeoutMs"].ShouldEqual(300D); + timeout.ContainsKey("ContentType").ShouldEqual(false); + GVFSJsonOptions.Serialize(timeout).Contains("query-marker", StringComparison.Ordinal).ShouldEqual(false); + } + finally + { + serverCancellation.Cancel(); + listener.Stop(); + try + { + await server.WaitAsync(TimeSpan.FromSeconds(5)); + } + catch (OperationCanceledException) when (serverCancellation.IsCancellationRequested) + { + } + } + } + } + + private static HttpResponseStream CreateStream( + Stream innerStream, + MockTracer tracer = null, + TimeSpan? readTimeout = null) + { + return new HttpResponseStream( + innerStream, + readTimeout ?? TimeSpan.FromMilliseconds(300), + CancellationToken.None, + tracer, + new EventMetadata + { + { "RequestId", 42L }, + { "CacheName", "test-cache" }, + { "RequestAuthority", "cache.example:443" }, + }, + progressInterval: TimeSpan.FromMilliseconds(30)); + } + + [TestCase] + public async Task StalledErrorBodyRetriesWithTheStatusAndReleasesItsConnectionPermit() + { + using MockTracer tracer = new MockTracer(); + using CancellationTokenSource cancellation = new CancellationTokenSource(TimeSpan.FromSeconds(10)); + using TcpListener listener = new TcpListener(IPAddress.Loopback, 0); + listener.Start(); + string endpoint = $"http://127.0.0.1:{((IPEndPoint)listener.LocalEndpoint).Port}"; + Task server = ServeRetriedError(listener, cancellation.Token); + using GitObjectsHttpRequestor requestor = new GitObjectsHttpRequestor( + tracer, new MockGVFSEnlistment(), new CacheServerInfo(endpoint, "test"), + new RetryConfig(1) { ReadTimeout = TimeSpan.FromMilliseconds(100) }); + try + { + RetryWrapper.InvocationResult result = + requestor.TrySendProtocolRequest( + 123, + (attempt, response) => + { + response.Stream.ReadByte().ShouldEqual(-1); + return new RetryWrapper.CallbackResult( + new GitObjectsHttpRequestor.GitObjectTaskResult(true)); + }, + onFailure: null, + method: HttpMethod.Get, + endPointGenerator: () => new Uri(endpoint), + requestBodyGenerator: () => null, + cancellationToken: CancellationToken.None); + result.Succeeded.ShouldEqual(true); + result.Attempts.ShouldEqual(2); + EventMetadata[] responses = tracer.RelatedEventMetadata + .Where(metadata => metadata.ContainsKey("availableConnections")).ToArray(); + responses.Length.ShouldEqual(2); + responses[0]["StatusCode"].ShouldEqual(HttpStatusCode.ServiceUnavailable); + responses[1]["StatusCode"].ShouldEqual(HttpStatusCode.OK); + responses[1]["availableConnections"].ShouldEqual(responses[0]["availableConnections"]); + } + finally + { + cancellation.Cancel(); + listener.Stop(); + try + { + await server.WaitAsync(TimeSpan.FromSeconds(5)); + } + catch (OperationCanceledException) when (cancellation.IsCancellationRequested) + { + } + } + } + + [TestCase] + public async Task ConfigProbeRetainsUnauthorizedStatusWhenItsBodyStalls() + { + using MockTracer tracer = new MockTracer(); + using CancellationTokenSource cancellation = new CancellationTokenSource(TimeSpan.FromSeconds(10)); + using TcpListener listener = new TcpListener(IPAddress.Loopback, 0); + listener.Start(); + string endpoint = $"http://127.0.0.1:{((IPEndPoint)listener.LocalEndpoint).Port}"; + Task server = ServeStalledResponse(listener, cancellation.Token, HttpStatusCode.Unauthorized); + using ConfigHttpRequestor requestor = new ConfigHttpRequestor( + tracer, new MockGVFSEnlistment("mock:\\repo", endpoint, "mock:\\git", new MockGitProcess()), + new RetryConfig(0) { ReadTimeout = TimeSpan.FromMilliseconds(100) }); + try + { + requestor.TryQueryGVFSConfig(false, out ServerGVFSConfig _, out HttpStatusCode? status, out string error) + .ShouldEqual(false); + status.ShouldEqual(HttpStatusCode.Unauthorized); + error.ShouldContain("401"); + error.ShouldContain("No response body data arrived"); + } + finally + { + cancellation.Cancel(); + listener.Stop(); + try + { + await server.WaitAsync(TimeSpan.FromSeconds(5)); + } + catch (OperationCanceledException) when (cancellation.IsCancellationRequested) + { + } + } + } + + private static async Task ServeRetriedError(TcpListener listener, CancellationToken cancellationToken) + { + for (int attempt = 0; attempt < 2; ++attempt) + { + using TcpClient client = await listener.AcceptTcpClientAsync(cancellationToken); + using NetworkStream stream = client.GetStream(); + using (StreamReader reader = new StreamReader(stream, Encoding.ASCII, false, 1024, leaveOpen: true)) + { + string line; + do + { + line = await reader.ReadLineAsync(cancellationToken); + } + while (!string.IsNullOrEmpty(line)); + } + + byte[] response = Encoding.ASCII.GetBytes(attempt == 0 + ? "HTTP/1.1 503 Unavailable\r\nContent-Length: 2\r\n\r\nx" + : "HTTP/1.1 200 OK\r\nContent-Length: 0\r\n\r\n"); + await stream.WriteAsync(response.AsMemory(), cancellationToken); + if (attempt == 0) + { + (await stream.ReadAsync(new byte[1].AsMemory(), cancellationToken)).ShouldEqual(0); + } + } + } + + [TestCase] + public async Task DisabledReadTimeoutStillHonorsCallerCancellation() + { + using CancellationTokenSource cancellation = new CancellationTokenSource(); + using HttpResponseStream stream = new HttpResponseStream( + new BlockingReadStream(), Timeout.InfiniteTimeSpan, cancellation.Token); + Task read = stream.ReadAsync(new byte[1].AsMemory()).AsTask(); + await Task.Delay(400); + read.IsCompleted.ShouldEqual(false); + cancellation.Cancel(); + Assert.CatchAsync(async () => await read.WaitAsync(TimeSpan.FromSeconds(5))); + stream.ReadFailed.ShouldEqual(false); + } + + [TestCase] + public async Task OverlappingAndDisposedReadsFailWithoutOverwritingPendingRead() + { + using BlockingReadStream innerStream = new BlockingReadStream(); + HttpResponseStream stream = CreateStream(innerStream, readTimeout: TimeSpan.FromSeconds(60)); + Task read = stream.ReadAsync(new byte[1].AsMemory()).AsTask(); + await innerStream.ReadStarted.Task.WaitAsync(TimeSpan.FromSeconds(5)); + Assert.ThrowsAsync(async () => (await stream.ReadAsync(new byte[1].AsMemory())).ShouldEqual(0)); + stream.Dispose(); + Assert.CatchAsync(async () => await read.WaitAsync(TimeSpan.FromSeconds(5))); + Assert.ThrowsAsync(async () => (await stream.ReadAsync(new byte[1].AsMemory())).ShouldEqual(0)); + } + + [TestCase] + public async Task BlockedProgressListenerDoesNotOwnTheReadStateGate() + { + using ManualResetEventSlim reporting = new ManualResetEventSlim(); + using ManualResetEventSlim release = new ManualResetEventSlim(); + using ManualResetEventSlim reported = new ManualResetEventSlim(); + using CallbackTracer tracer = new CallbackTracer(); + bool responseClosed = false; + tracer.Callback = name => + { + if (name == "NetworkBodyProgress") + { + reporting.Set(); + try + { + release.Wait(TimeSpan.FromSeconds(10)).ShouldEqual(true); + if (responseClosed) + { + throw new ObjectDisposedException("tracer"); + } + } + finally + { + reported.Set(); + } + } + }; + using HttpResponseStream stream = CreateStream(new BlockingReadStream(new byte[] { 1 }), tracer); + try + { + stream.ReadByte().ShouldEqual(1); + reporting.Wait(TimeSpan.FromSeconds(5)).ShouldEqual(true); + Assert.ThrowsAsync( + async () => await stream.ReadAsync(new byte[1].AsMemory()).AsTask().WaitAsync(TimeSpan.FromSeconds(5))); + stream.ReadFailed.ShouldEqual(true); + stream.Dispose(); + responseClosed = true; + } + finally + { + release.Set(); + reported.Wait(TimeSpan.FromSeconds(5)).ShouldEqual(true); + } + + await Task.Delay(50); + } + + [TestCase] + public void RawResponseStreamTracksReadFailuresAndIdentity() + { + using GitEndPointResponseData response = new GitEndPointResponseData( + HttpStatusCode.OK, "application/json", new FailingReadStream(), null, null); + string.IsNullOrEmpty(response.ResponseId).ShouldEqual(false); + Assert.Throws(() => response.Stream.ReadByte()); + response.StreamReadFailed.ShouldEqual(true); + } + + [TestCase] + public void ResponseDisposalReleasesPermitWhenFinalDiagnosticsThrow() + { + using CallbackTracer tracer = new CallbackTracer(); + tracer.Callback = name => + { + if (name != "NetworkBodyProgress") + { + throw new InvalidOperationException("diagnostic failure"); + } + }; + MemoryStream innerStream = new MemoryStream(new byte[] { 1 }); + HttpResponseStream stream = CreateStream(innerStream, tracer); + int releases = 0; + GitEndPointResponseData response = new GitEndPointResponseData( + HttpStatusCode.OK, "application/json", stream, new HttpResponseMessage(), () => ++releases); + stream.ReadByte().ShouldEqual(1); + Thread.Sleep(40); + Assert.Throws(() => response.Dispose()); + innerStream.CanRead.ShouldEqual(false); + response.Dispose(); + releases.ShouldEqual(1); + } + + [TestCase] + public async Task ProgressReportsCountOnlyBytesSinceThePreviousReport() + { + using MockTracer tracer = new MockTracer(); + using HttpResponseStream stream = CreateStream(new MemoryStream(new byte[] { 1, 2 }), tracer); + stream.ReadByte().ShouldEqual(1); + await Task.Delay(150); + stream.ReadByte().ShouldEqual(2); + await Task.Delay(150); + stream.ReadByte().ShouldEqual(-1); + EventMetadata[] reports = tracer.RelatedEventMetadata.ToArray(); + reports.Select(report => (long)report["SampleSequence"]).Distinct().Count().ShouldEqual(reports.Length); + reports.Sum(report => (long)report["BytesSinceLastProgress"]).ShouldEqual(2L); + reports.Count(report => (long)report["BytesSinceLastProgress"] == 1).ShouldEqual(2); + reports.OrderBy(report => (long)report["SampleSequence"]).Last()["Outcome"].ShouldEqual("Completed"); + } + + private class CallbackTracer : MockTracer + { + public Action Callback { get; set; } + + public override void RelatedEvent(EventLevel level, string eventName, EventMetadata metadata, Keywords keyword) + { + this.Callback?.Invoke(eventName); + base.RelatedEvent(level, eventName, metadata, keyword); + } + } + + private class FailingReadStream : MemoryStream + { + public override ValueTask ReadAsync(Memory buffer, CancellationToken cancellationToken = default) + { + throw new IOException("read failed"); + } + } + + private static async Task ServeStalledResponse( + TcpListener listener, + CancellationToken cancellationToken, + HttpStatusCode status = HttpStatusCode.OK) + { + using (TcpClient connection = await listener.AcceptTcpClientAsync(cancellationToken)) + using (NetworkStream stream = connection.GetStream()) + { + using (StreamReader request = new StreamReader(stream, Encoding.ASCII, false, 1024, leaveOpen: true)) + { + string line; + do + { + line = await request.ReadLineAsync(cancellationToken); + } + while (!string.IsNullOrEmpty(line)); + } + + byte[] response = Encoding.ASCII.GetBytes( + $"HTTP/1.1 {(int)status} Test\r\nContent-Length: 2\r\nX-Cache-Name: test-cache\r\n\r\nx"); + await stream.WriteAsync(response.AsMemory(), cancellationToken); + await Task.Delay(Timeout.Infinite, cancellationToken); + } + } + + private class LoopbackHttpRequestor : HttpRequestor + { + public LoopbackHttpRequestor(MockTracer tracer) + : base( + tracer, + new RetryConfig { ReadTimeout = TimeSpan.FromMilliseconds(300) }, + new MockGVFSEnlistment()) + { + } + + public GitEndPointResponseData Get(Uri uri) + { + return this.SendRequest(42, uri, HttpMethod.Get, null, CancellationToken.None); + } + } + + private class BlockingReadStream : MemoryStream + { + public BlockingReadStream(byte[] prefix = null) + : base(prefix ?? Array.Empty()) + { + } + + public TaskCompletionSource ReadStarted { get; } = + new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + + public override async ValueTask ReadAsync(Memory buffer, CancellationToken cancellationToken = default) + { + this.ReadStarted.TrySetResult(true); + if (this.Position < this.Length) + { + return await base.ReadAsync(buffer, cancellationToken).ConfigureAwait(false); + } + + await Task.Delay(Timeout.Infinite, cancellationToken).ConfigureAwait(false); + return 0; + } + } + + private class SlowReadStream : MemoryStream + { + private readonly TimeSpan delay; + private int remaining; + + public SlowReadStream(int bytes, TimeSpan delay) + { + this.remaining = bytes; + this.delay = delay; + } + + public override async ValueTask ReadAsync(Memory buffer, CancellationToken cancellationToken = default) + { + if (this.remaining == 0) + { + return 0; + } + + await Task.Delay(this.delay, cancellationToken).ConfigureAwait(false); + buffer.Span[0] = 1; + --this.remaining; + return 1; + } + } + } +} diff --git a/GVFS/GVFS.UnitTests/Mock/Common/MockTracer.cs b/GVFS/GVFS.UnitTests/Mock/Common/MockTracer.cs index 5dba402b91..95f0681445 100644 --- a/GVFS/GVFS.UnitTests/Mock/Common/MockTracer.cs +++ b/GVFS/GVFS.UnitTests/Mock/Common/MockTracer.cs @@ -17,10 +17,12 @@ public MockTracer() this.RelatedWarningEvents = new List(); this.RelatedErrorEvents = new List(); this.RelatedEventNames = new List(); + this.RelatedEventLevels = new List(); this.RelatedEventKeywords = new List(); this.RelatedEventMetadata = new List(); this.StopMetadata = new List(); this.TelemetryWarnings = new List(); + this.StartMetadata = new List(); } public MockTracer StartActivityTracer { get; private set; } @@ -33,12 +35,14 @@ public MockTracer() // Names of events reported via RelatedEvent (which, unlike RelatedInfo/Warning/Error, // do not otherwise get recorded). Lets tests assert a specific diagnostic event fired. public List RelatedEventNames { get; } + public List RelatedEventLevels { get; } public List RelatedEventKeywords { get; } public List RelatedEventMetadata { get; } // Metadata passed to each Stop() call, in order — lets tests assert on activity-summary // fields (e.g. HydrateFilesStage's FailureSignatureCounts) that Stop would otherwise discard. public List StopMetadata { get; } + public List StartMetadata { get; } // Warnings reported with Keywords.Telemetry, which a telemetry listener would ship off the machine. public List TelemetryWarnings { get; } @@ -51,6 +55,7 @@ public void WaitForRelatedEvent() public void RelatedEvent(EventLevel error, string eventName, EventMetadata metadata) { this.RelatedEventNames.Add(eventName); + this.RelatedEventLevels.Add(error); this.RelatedEventKeywords.Add(Keywords.None); this.RelatedEventMetadata.Add(metadata); if (eventName == this.WaitRelatedEventName) @@ -59,9 +64,10 @@ public void RelatedEvent(EventLevel error, string eventName, EventMetadata metad } } - public void RelatedEvent(EventLevel error, string eventName, EventMetadata metadata, Keywords keyword) + public virtual void RelatedEvent(EventLevel error, string eventName, EventMetadata metadata, Keywords keyword) { this.RelatedEventNames.Add(eventName); + this.RelatedEventLevels.Add(error); this.RelatedEventKeywords.Add(keyword); this.RelatedEventMetadata.Add(metadata); if (eventName == this.WaitRelatedEventName) @@ -151,6 +157,7 @@ public ITracer StartActivity(string activityName, EventLevel level, EventMetadat public ITracer StartActivity(string activityName, EventLevel level, Keywords startStopKeywords, EventMetadata metadata) { + this.StartMetadata.Add(metadata); this.StartActivityTracer = this.StartActivityTracer ?? new MockTracer(); return this.StartActivityTracer; } diff --git a/GVFS/GVFS/CommandLine/CacheServerVerb.cs b/GVFS/GVFS/CommandLine/CacheServerVerb.cs index 2e0735b762..c7c2580626 100644 --- a/GVFS/GVFS/CommandLine/CacheServerVerb.cs +++ b/GVFS/GVFS/CommandLine/CacheServerVerb.cs @@ -56,10 +56,11 @@ protected override void Execute(GVFSEnlistment enlistment) { this.BlockEmptyCacheServerUrl(this.CacheToSet); - RetryConfig retryConfig = new RetryConfig(RetryConfig.DefaultMaxRetries, TimeSpan.FromMinutes(RetryConfig.FetchAndCloneTimeoutMinutes)); - using (ITracer tracer = new JsonTracer(GVFSConstants.GVFSEtwProviderName, "CacheVerb")) { + RetryConfig retryConfig = this.GetRetryConfig( + tracer, enlistment, TimeSpan.FromMinutes(RetryConfig.FetchAndCloneTimeoutMinutes)); + CacheServerResolver cacheServerResolver = new CacheServerResolver(tracer, enlistment); ServerGVFSConfig serverGVFSConfig = null; string error = null; diff --git a/GVFS/GVFS/CommandLine/DehydrateVerb.cs b/GVFS/GVFS/CommandLine/DehydrateVerb.cs index 61d5968b8b..3588fbe921 100644 --- a/GVFS/GVFS/CommandLine/DehydrateVerb.cs +++ b/GVFS/GVFS/CommandLine/DehydrateVerb.cs @@ -231,11 +231,7 @@ from a parent of the folders list. this.ReportErrorAndExit(tracer, error); } - RetryConfig retryConfig; - if (!RetryConfig.TryLoadFromGitConfig(tracer, enlistment, out retryConfig, out error)) - { - this.ReportErrorAndExit(tracer, "Failed to determine GVFS timeout and max retries: " + error); - } + RetryConfig.TryLoadFromGitConfig(tracer, enlistment, out RetryConfig retryConfig, out _); string errorMessage; if (!this.TryAuthenticate(tracer, enlistment, out errorMessage)) diff --git a/GVFS/GVFS/CommandLine/GVFSVerb.cs b/GVFS/GVFS/CommandLine/GVFSVerb.cs index 84a4c678bf..aef557e7de 100644 --- a/GVFS/GVFS/CommandLine/GVFSVerb.cs +++ b/GVFS/GVFS/CommandLine/GVFSVerb.cs @@ -237,7 +237,7 @@ protected bool TryAuthenticate(ITracer tracer, GVFSEnlistment enlistment, out st /// /// Combines authentication and GVFS config query into a single operation, /// eliminating a redundant HTTP round-trip. If - /// is null, a default RetryConfig is used. + /// is null, all retry settings are loaded from git config. /// If the config query fails but a valid /// URL is available, auth succeeds but /// will be null (caller should handle this gracefully). @@ -252,12 +252,16 @@ protected bool TryAuthenticateAndQueryGVFSConfig( { ServerGVFSConfig config = null; string error = null; + if (retryConfig == null) + { + RetryConfig.TryLoadFromGitConfig(tracer, enlistment, out retryConfig, out _); + } bool result = this.ShowStatusWhileRunning( () => enlistment.Authentication.TryInitializeAndQueryGVFSConfig( tracer, enlistment, - retryConfig ?? new RetryConfig(), + retryConfig, out config, out error, out _), @@ -317,12 +321,7 @@ protected void ReportErrorAndExit(ITracer tracer, string error, params object[] protected RetryConfig GetRetryConfig(ITracer tracer, GVFSEnlistment enlistment, TimeSpan? timeoutOverride = null) { - RetryConfig retryConfig; - string error; - if (!RetryConfig.TryLoadFromGitConfig(tracer, enlistment, out retryConfig, out error)) - { - this.ReportErrorAndExit(tracer, "Failed to determine GVFS timeout and max retries: " + error); - } + RetryConfig.TryLoadFromGitConfig(tracer, enlistment, out RetryConfig retryConfig, out _); if (timeoutOverride.HasValue) { @@ -1185,10 +1184,7 @@ private void EnsureLocalCacheIsHealthy( { if (retryConfig == null) { - if (!RetryConfig.TryLoadFromGitConfig(tracer, enlistment, out retryConfig, out error)) - { - this.ReportErrorAndExit(tracer, "Failed to determine GVFS timeout and max retries: " + error); - } + RetryConfig.TryLoadFromGitConfig(tracer, enlistment, out retryConfig, out _); } serverGVFSConfig = this.QueryGVFSConfig(tracer, enlistment, retryConfig); diff --git a/docs/troubleshooting.md b/docs/troubleshooting.md index ea8bb4a80d..9c09780a1f 100644 --- a/docs/troubleshooting.md +++ b/docs/troubleshooting.md @@ -86,6 +86,67 @@ reoccurring. Please make sure you are on the latest version using `gvfs upgrade` before raising an issue. Please also keep your version of Windows updated as that is the only way to get updates to the ProjFS filesystem driver. +### Slow or stalled cache downloads + +If no data arrives for 60 seconds, VFS for Git stops the pending response-body read. +The existing retry policy controls further attempts. +The deadline applies to each pending read, not to the total download. +A large download can continue for hours while bytes arrive. +Time spent on disk writes or pack processing does not count against the read deadline. + +The `gvfs.read-timeout-seconds` setting controls this deadline independently of +the request-header timeout. It accepts whole seconds from 0 through 2147483. +Zero disables the response-body read deadline. Caller cancellation still applies. +If the server requires longer pauses between bytes, increase the deadline: + +```powershell +git config --global gvfs.read-timeout-seconds 120 +``` + +Do not use this setting to limit the total download time. +If the enlistment is mounted, remount it after a configuration change. +New clone, prefetch, cache-server, repair-authentication, and FastFetch operations +read the setting when they initialize their requests. +All request initialization paths load the complete retry configuration. +If a retry setting is invalid or unreadable, VFS for Git logs a warning and +uses the default for that setting. Other valid retry settings remain active. +Running mounts retain the configuration that they loaded at startup. +Later retry-setting errors do not stop an existing mount. + +Local GVFS logs contain `NetworkBodyProgress` reports every 30 seconds while a +response remains open. These reports also reach the configured telemetry pipe. +Fast transfers emit no additional progress reports. A slow transfer or a read +failure also emits a final outcome, with `NetworkBodyReadTimeout` for an idle timeout. + +Use `ResponseId` to match progress reports with final outcomes and +`Receiving Pack/Index` events. `RequestId`, `RequestAuthority`, and `CacheName` +identify the request and server without credentials or URL query parameters. +Sort reports for one response by `SampleSequence`. Diagnostic writes can delay +delivery after the client captures a sample. +Prefetch pack events also reach the telemetry pipe. +The `TryDownloadPrefetchPacks` summary contains `RequestId`, the attempt +count, and the final success result. + +| Field | Meaning | +| --- | --- | +| `BytesRead`, `BytesSinceLastProgress` | Total bytes and bytes since the previous report | +| `ElapsedMs` | Total time with the response open, including consumer work | +| `ReadTimeMs`, `MaxReadWaitMs` | Total time in body reads and the longest read wait | +| `ReadPending`, `CurrentReadWaitMs` | Whether a read is pending and its current wait | +| `MillisecondsSinceLastByte` | Time since the last successful nonempty read, including consumer work | +| `ReadTimeoutMs` | Configured read deadline in milliseconds, or -1 if disabled | +| `HeaderWaitMs`, `ContentLength` | Header wait and expected body bytes, or -1 for an unknown length | +| `ResponseId`, `RequestId` | Response identity and the request identity shared across retries | +| `SampleSequence` | Increasing sample number within one response | +| `Exception` | Full diagnostic exception for a failed or canceled read | +| `Outcome` | Progress, completion, timeout, cancellation, read error, or response closure | + +If `BytesRead` increases between reports, data still arrives. +If `ReadPending` is true and bytes do not increase, a transport read remains outstanding. +This wait also includes managed scheduling delay. It does not prove that the cache server or network caused the delay. +When `ReadPending` is false, a pause occurs in the consumer rather than in a network read. +Response closure alone does not prove that the client consumed the complete body. + ### TRY THIS FIRST: `gvfs repair` Some known issues can get your enlistment into a bad state. Running From 847ce53da1f0bad9e601fbb763ff1923447bc2de Mon Sep 17 00:00:00 2001 From: Tyrie Vella Date: Wed, 21 Oct 2026 12:41:23 -0700 Subject: [PATCH 2/4] Preserve cancellation and response ownership across HTTP retries Dispose prepared responses when final diagnostics throw. Keep the fixed anonymous 401 message and tolerate expected tracer teardown during body diagnostics. Preserve caller cancellation through stream copies and temporary-pack writes. Correlate fast pack transfers with retry summaries and report concurrent pack finalization failures. Return complete retry configuration from LoadFromGitConfig. Reuse the configuration during command authentication and retain per-field defaults and command overrides. Add unit tests for response ownership, completed error bodies, credentials, cancellation, configuration consumers, numeric boundaries, and diagnostic ordering. Extend functional tests to assert startup warnings after remount with invalid configuration. These tests disable prefetch offload and restore the original configuration. Document progress timing, configuration ranges, and offloaded prefetch ownership. Assisted-by: GPT-6.1 Sol Signed-off-by: Tyrie Vella --- GVFS/FastFetch/FastFetchVerb.cs | 5 +- GVFS/GVFS.Common/Git/GitAuthentication.cs | 2 +- GVFS/GVFS.Common/Git/GitObjects.cs | 26 +- GVFS/GVFS.Common/Http/HttpRequestor.cs | 15 +- GVFS/GVFS.Common/Http/HttpResponseStream.cs | 31 +- GVFS/GVFS.Common/RetryConfig.cs | 15 +- GVFS/GVFS.Common/StreamUtil.cs | 8 +- .../EnlistmentPerFixture/PrefetchVerbTests.cs | 29 +- GVFS/GVFS.Mount/InProcessMountVerb.cs | 2 +- .../ProfilingEnvironment.cs | 2 +- .../GVFS.UnitTests/Common/RetryConfigTests.cs | 73 +++- GVFS/GVFS.UnitTests/Common/StreamUtilTests.cs | 50 +++ GVFS/GVFS.UnitTests/Git/GitObjectsTests.cs | 57 ++- .../Http/HttpResponseStreamTests.cs | 356 ++++++++++++++++-- .../Mock/Common/MockGVFSEnlistment.cs | 5 +- GVFS/GVFS.UnitTests/Mock/Common/MockTracer.cs | 59 ++- GVFS/GVFS/CommandLine/DehydrateVerb.cs | 4 +- GVFS/GVFS/CommandLine/GVFSVerb.cs | 6 +- docs/troubleshooting.md | 24 +- 19 files changed, 647 insertions(+), 122 deletions(-) create mode 100644 GVFS/GVFS.UnitTests/Common/StreamUtilTests.cs diff --git a/GVFS/FastFetch/FastFetchVerb.cs b/GVFS/FastFetch/FastFetchVerb.cs index 4f46d7fa3e..379cf81805 100644 --- a/GVFS/FastFetch/FastFetchVerb.cs +++ b/GVFS/FastFetch/FastFetchVerb.cs @@ -252,14 +252,15 @@ private int ExecuteWithExitCode() }); string error; - if (!enlistment.Authentication.TryInitialize(tracer, enlistment, out error)) + RetryConfig retryConfig = RetryConfig.LoadFromGitConfig(tracer, enlistment); + if (!enlistment.Authentication.TryInitializeAndQueryGVFSConfig( + tracer, enlistment, retryConfig, out _, out error, out _)) { tracer.RelatedError(error); Console.WriteLine(error); return ExitFailure; } - RetryConfig.TryLoadFromGitConfig(tracer, enlistment, out RetryConfig retryConfig, out _); retryConfig.MaxRetries = this.MaxAttempts; retryConfig.Timeout = TimeSpan.FromMinutes(RetryConfig.FetchAndCloneTimeoutMinutes); diff --git a/GVFS/GVFS.Common/Git/GitAuthentication.cs b/GVFS/GVFS.Common/Git/GitAuthentication.cs index 694216a323..c24db57281 100644 --- a/GVFS/GVFS.Common/Git/GitAuthentication.cs +++ b/GVFS/GVFS.Common/Git/GitAuthentication.cs @@ -222,7 +222,7 @@ public bool TryGetCredentials(ITracer tracer, out string credentialString, out s /// public bool TryInitialize(ITracer tracer, Enlistment enlistment, out string errorMessage) { - RetryConfig.TryLoadFromGitConfig(tracer, enlistment, out RetryConfig retryConfig, out _); + RetryConfig retryConfig = RetryConfig.LoadFromGitConfig(tracer, enlistment); // Delegate to the combined method, discarding the config result. // This avoids duplicating the anonymous-probe + credential-fetch logic. diff --git a/GVFS/GVFS.Common/Git/GitObjects.cs b/GVFS/GVFS.Common/Git/GitObjects.cs index 89b054129a..26f4c3d298 100644 --- a/GVFS/GVFS.Common/Git/GitObjects.cs +++ b/GVFS/GVFS.Common/Git/GitObjects.cs @@ -173,7 +173,7 @@ public virtual bool TryDownloadPrefetchPacks(GitProcess gitProcess, long latestT List innerPackIndexes = null; RetryWrapper.InvocationResult result = this.GitObjectRequestor.TrySendProtocolRequest( requestId: requestId, - onSuccess: (tryCount, response) => this.DeserializePrefetchPacks(response, ref latestTimestamp, ref bytesDownloaded, ref innerPackIndexes, gitProcess, trustPackIndexes), + onSuccess: (tryCount, response) => this.DeserializePrefetchPacks(response, requestId, ref latestTimestamp, ref bytesDownloaded, ref innerPackIndexes, gitProcess, trustPackIndexes), onFailure: RetryWrapper.StandardErrorHandler(activity, requestId, "TryDownloadPrefetchPacks"), method: HttpMethod.Get, endPointGenerator: () => new Uri( @@ -367,6 +367,11 @@ public virtual bool TryWriteTempFile( this.CleanupTempFile(this.Tracer, tempFilePath); + if (ex is OperationCanceledException) + { + throw; + } + if (tracer != null) { EventMetadata metadata = CreateEventMetadata(ex); @@ -717,6 +722,7 @@ private LooseObjectToWrite GetLooseObjectDestination(string sha) /// private RetryWrapper.CallbackResult DeserializePrefetchPacks( GitEndPointResponseData response, + long requestId, ref long latestTimestamp, ref long bytesDownloaded, ref List packIndexes, @@ -744,6 +750,7 @@ private LooseObjectToWrite GetLooseObjectDestination(string sha) // Read each pack from the stream to a temp file, and start a task to index it. Task previousPackTask = Task.CompletedTask; Exception exception = null; + bool responseLoopExitedNormally = false; try { foreach (PrefetchPacksDeserializer.PackAndIndex packHandle in deserializer.EnumeratePacks()) @@ -764,6 +771,7 @@ private LooseObjectToWrite GetLooseObjectDestination(string sha) data["timestamp"] = pack.Timestamp.ToString(); data["uniqueId"] = pack.UniqueId; data["ResponseId"] = response.ResponseId; + data["RequestId"] = requestId; data["PackBytes"] = pack.PackStream.Length; activity.RelatedEvent(EventLevel.Informational, "Receiving Pack/Index", data, Keywords.Telemetry); @@ -828,7 +836,7 @@ private LooseObjectToWrite GetLooseObjectDestination(string sha) pack.IndexStream.CopyTo(Stream.Null); } } - catch (Exception e) + catch (Exception e) when (!(e is OperationCanceledException)) { EventMetadata metadata = CreateEventMetadata(e); activity.RelatedWarning(metadata, "Failed to read to end of index stream"); @@ -839,12 +847,26 @@ private LooseObjectToWrite GetLooseObjectDestination(string sha) } } + responseLoopExitedNormally = true; } finally { if (!this.WaitForPacks(tempPackOperations, ref latestTimestamp, out exception)) { allSucceeded = false; + if (!responseLoopExitedNormally) + { + activity.RelatedWarning( + new EventMetadata + { + { "Area", EtwArea }, + { "RequestId", requestId }, + { "ResponseId", response.ResponseId }, + { "Exception", exception.ToString() }, + }, + "Pack finalization failed while the response was interrupted.", + Keywords.Telemetry); + } } packIndexes.AddRange(tempPackOperations diff --git a/GVFS/GVFS.Common/Http/HttpRequestor.cs b/GVFS/GVFS.Common/Http/HttpRequestor.cs index b67b937e9a..0f9b66aa80 100644 --- a/GVFS/GVFS.Common/Http/HttpRequestor.cs +++ b/GVFS/GVFS.Common/Http/HttpRequestor.cs @@ -235,6 +235,7 @@ protected GitEndPointResponseData SendRequest( } else { + string bodyReadFailure = null; try { using (HttpResponseStream responseStream = new HttpResponseStream( @@ -256,7 +257,8 @@ protected GitEndPointResponseData SendRequest( new EventMetadata(bodyMetadata) { { "Exception", e.ToString() } }, "The server returned an error status, but the response body read failed.", Keywords.Network | Keywords.Telemetry); - errorMessage = "The response body read failed: " + (e.InnerException?.Message ?? e.Message); + bodyReadFailure = "The response body read failed: " + (e.InnerException?.Message ?? e.Message); + errorMessage = bodyReadFailure; } int statusInt = (int)response.StatusCode; @@ -266,7 +268,11 @@ protected GitEndPointResponseData SendRequest( this.authentication.IsAnonymous) { shouldRetry = false; - errorMessage = "Anonymous request was rejected with a 401. " + errorMessage; + errorMessage = "Anonymous request was rejected with a 401"; + if (bodyReadFailure != null) + { + errorMessage += ". " + bodyReadFailure; + } } else if (ShouldRejectCredentials(response.StatusCode, errorMessage)) { @@ -334,6 +340,11 @@ protected GitEndPointResponseData SendRequest( { this.Tracer.RelatedEvent(EventLevel.Informational, "NetworkResponse", responseMetadata); } + catch + { + gitEndPointResponseData?.Dispose(); + throw; + } finally { if (gitEndPointResponseData == null) diff --git a/GVFS/GVFS.Common/Http/HttpResponseStream.cs b/GVFS/GVFS.Common/Http/HttpResponseStream.cs index f22691b9a2..226718e1b8 100644 --- a/GVFS/GVFS.Common/Http/HttpResponseStream.cs +++ b/GVFS/GVFS.Common/Http/HttpResponseStream.cs @@ -294,11 +294,6 @@ private void ReportProgress(object? state) this.Trace(report, TransferOutcome.InProgress); } - catch (ObjectDisposedException) when (this._disposed) - { - // A captured progress sample can outlive response and tracer teardown. - return; - } catch (Exception e) { try @@ -347,15 +342,23 @@ private void Trace(EventMetadata? report, TransferOutcome outcome) return; } - this._tracer.RelatedEvent( - outcome == TransferOutcome.TimedOut || outcome == TransferOutcome.ReadError - ? EventLevel.Warning - : EventLevel.Informational, - outcome == TransferOutcome.InProgress - ? ProgressEventName - : outcome == TransferOutcome.TimedOut ? TimeoutEventName : TransferEventName, - report, - Keywords.Network | Keywords.Telemetry); + try + { + this._tracer.RelatedEvent( + outcome == TransferOutcome.TimedOut || outcome == TransferOutcome.ReadError + ? EventLevel.Warning + : EventLevel.Informational, + outcome == TransferOutcome.InProgress + ? ProgressEventName + : outcome == TransferOutcome.TimedOut ? TimeoutEventName : TransferEventName, + report, + Keywords.Network | Keywords.Telemetry); + } + catch (ObjectDisposedException) + { + // Maintenance responses can outlive the root tracer during unmount. + return; + } } private EventMetadata CreateReport(Exception? readError = null) diff --git a/GVFS/GVFS.Common/RetryConfig.cs b/GVFS/GVFS.Common/RetryConfig.cs index 5fbdf35670..7de0f1a617 100644 --- a/GVFS/GVFS.Common/RetryConfig.cs +++ b/GVFS/GVFS.Common/RetryConfig.cs @@ -14,7 +14,9 @@ public class RetryConfig public const int FetchAndCloneTimeoutMinutes = 10; private const string EtwArea = nameof(RetryConfig); + // HttpClient and the response stream accept signed millisecond deadlines. private const int MaxTimeoutSeconds = int.MaxValue / 1000; + // Leave room for the initial attempt and two endpoint-routing attempts. private const int MaxConfiguredRetries = int.MaxValue - 3; private static readonly TimeSpan DefaultTimeout = TimeSpan.FromSeconds(DefaultTimeoutSeconds); @@ -40,29 +42,30 @@ public int MaxAttempts public TimeSpan ReadTimeout { get; set; } = TimeSpan.FromSeconds(DefaultReadTimeoutSeconds); - public static bool TryLoadFromGitConfig(ITracer tracer, Enlistment enlistment, out RetryConfig retryConfig, out string error) + public static RetryConfig LoadFromGitConfig(ITracer tracer, Enlistment enlistment) { - return TryLoadFromGitConfig(tracer, enlistment.CreateGitProcess(), out retryConfig, out error); + ArgumentNullException.ThrowIfNull(enlistment); + return LoadFromGitConfig(tracer, enlistment.CreateGitProcess()); } /// /// Invalid or unreadable retry settings use defaults and emit warnings. /// - public static bool TryLoadFromGitConfig(ITracer tracer, GitProcess git, out RetryConfig retryConfig, out string error) + public static RetryConfig LoadFromGitConfig(ITracer tracer, GitProcess git) { + ArgumentNullException.ThrowIfNull(git); int maxRetries = LoadIntOrDefault( tracer, git, GVFSConstants.GitConfig.MaxRetriesConfig, DefaultMaxRetries, 0, MaxConfiguredRetries); int timeoutSeconds = LoadIntOrDefault( tracer, git, GVFSConstants.GitConfig.TimeoutSecondsConfig, DefaultTimeoutSeconds, 1, MaxTimeoutSeconds); int readTimeoutSeconds = LoadIntOrDefault( tracer, git, GVFSConstants.GitConfig.ReadTimeoutSecondsConfig, DefaultReadTimeoutSeconds, 0, MaxTimeoutSeconds); - retryConfig = new RetryConfig(maxRetries, TimeSpan.FromSeconds(timeoutSeconds)) + RetryConfig retryConfig = new RetryConfig(maxRetries, TimeSpan.FromSeconds(timeoutSeconds)) { ReadTimeout = readTimeoutSeconds == 0 ? System.Threading.Timeout.InfiniteTimeSpan : TimeSpan.FromSeconds(readTimeoutSeconds), }; - error = string.Empty; if (tracer != null) { @@ -79,7 +82,7 @@ public static bool TryLoadFromGitConfig(ITracer tracer, GitProcess git, out Retr }); } - return true; + return retryConfig; } private static int LoadIntOrDefault( diff --git a/GVFS/GVFS.Common/StreamUtil.cs b/GVFS/GVFS.Common/StreamUtil.cs index 68dc93749d..05d2219430 100644 --- a/GVFS/GVFS.Common/StreamUtil.cs +++ b/GVFS/GVFS.Common/StreamUtil.cs @@ -33,9 +33,9 @@ public static void CopyToWithBuffer(Stream source, Stream destination, byte[] bu { read = source.Read(buffer, 0, buffer.Length); } - catch (Exception ex) + catch (Exception ex) when (!(ex is OperationCanceledException)) { - // All exceptions potentially from network should be retried + // Network read failures can be retried. throw new RetryableException("Exception while reading stream. See inner exception for details.", ex); } @@ -71,9 +71,9 @@ public static int TryReadGreedy(Stream stream, byte[] buf, int offset, int count { read = stream.Read(buf, start, length); } - catch (Exception ex) + catch (Exception ex) when (!(ex is OperationCanceledException)) { - // All exceptions potentially from network should be retried + // Network read failures can be retried. throw new RetryableException("Exception while reading stream. See inner exception for details.", ex); } diff --git a/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/PrefetchVerbTests.cs b/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/PrefetchVerbTests.cs index 26f509b80e..2df774bdef 100644 --- a/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/PrefetchVerbTests.cs +++ b/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/PrefetchVerbTests.cs @@ -49,6 +49,7 @@ public async Task StalledPrefetchHonorsConfiguredReadDeadline() { "gvfs.cache-server", "gvfs.prefetch.cache-server", "gvfs.read-timeout-seconds", "gvfs.max-retries", + "gvfs.prefetch-offload", }; Dictionary previous = this.ReadLocalConfig(keys); @@ -64,6 +65,7 @@ public async Task StalledPrefetchHonorsConfiguredReadDeadline() this.SetLocalConfig(keys[1], endpoint); this.SetLocalConfig(keys[2], "1"); this.SetLocalConfig(keys[3], "0"); + this.SetLocalConfig(keys[4], "false"); ProcessResult result = await Task.Run(() => ProcessHelper.Run( GVFSTestConfig.PathToGVFS, @@ -100,14 +102,17 @@ public async Task StalledPrefetchHonorsConfiguredReadDeadline() [TestCase] public void InvalidRetrySettingsDoNotStopAMountedEnlistment() { - Dictionary previous = this.ReadLocalConfig(new[] + string[] retryKeys = new[] { "gvfs.max-retries", "gvfs.timeout-seconds", "gvfs.read-timeout-seconds", - }); + }; + Dictionary previous = this.ReadLocalConfig( + retryKeys.Concat(new[] { "gvfs.prefetch-offload" })); this.Enlistment.IsMounted().ShouldEqual(true); try { - foreach (string key in previous.Keys) + this.SetLocalConfig("gvfs.prefetch-offload", "false"); + foreach (string key in retryKeys) { this.SetLocalConfig(key, "invalid"); } @@ -124,14 +129,30 @@ public void InvalidRetrySettingsDoNotStopAMountedEnlistment() .Select(File.ReadAllText) .First(); log.ShouldContain("VFS for Git uses the default value."); - foreach (string key in previous.Keys) + foreach (string key in retryKeys) { log.ShouldContain("\"ConfigName\":\"" + key + "\""); } + + this.Enlistment.UnmountGVFS(); + this.Enlistment.MountGVFS(); + this.Enlistment.IsMounted().ShouldEqual(true); + string mountLog = Directory.GetFiles(Path.Combine(this.Enlistment.DotGVFSRoot, "logs"), "gvfs_mount_process_*.log") + .OrderByDescending(File.GetLastWriteTimeUtc) + .Select(GVFSHelpers.ReadAllTextFromWriteLockedFile) + .First(); + foreach (string key in retryKeys) + { + mountLog.ShouldContain("\"ConfigName\":\"" + key + "\""); + } } finally { this.RestoreLocalConfig(previous); + if (!this.Enlistment.IsMounted()) + { + this.Enlistment.MountGVFS(); + } } } diff --git a/GVFS/GVFS.Mount/InProcessMountVerb.cs b/GVFS/GVFS.Mount/InProcessMountVerb.cs index 4dbe97e7da..e3ffd3b2b1 100644 --- a/GVFS/GVFS.Mount/InProcessMountVerb.cs +++ b/GVFS/GVFS.Mount/InProcessMountVerb.cs @@ -132,7 +132,7 @@ public void Execute() }; string error; - RetryConfig.TryLoadFromGitConfig(tracer, enlistment, out RetryConfig retryConfig, out _); + RetryConfig retryConfig = RetryConfig.LoadFromGitConfig(tracer, enlistment); GitStatusCacheConfig gitStatusCacheConfig; if (!GitStatusCacheConfig.TryLoadFromGitConfig(tracer, enlistment, out gitStatusCacheConfig, out error)) diff --git a/GVFS/GVFS.PerfProfiling/ProfilingEnvironment.cs b/GVFS/GVFS.PerfProfiling/ProfilingEnvironment.cs index b8d96eebb3..d3831390d3 100644 --- a/GVFS/GVFS.PerfProfiling/ProfilingEnvironment.cs +++ b/GVFS/GVFS.PerfProfiling/ProfilingEnvironment.cs @@ -70,7 +70,7 @@ private FileSystemCallbacks CreateFileSystemCallbacks() this.Enlistment.InitializeCachePaths(localCacheRoot, gitObjectsRoot, blobSizesRoot); CacheServerInfo cacheServer = new CacheServerInfo(this.Context.Enlistment.RepoUrl, "None"); - RetryConfig.TryLoadFromGitConfig(this.Context.Tracer, this.Context.Enlistment, out RetryConfig retryConfig, out _); + RetryConfig retryConfig = RetryConfig.LoadFromGitConfig(this.Context.Tracer, this.Context.Enlistment); GitObjectsHttpRequestor objectRequestor = new GitObjectsHttpRequestor( this.Context.Tracer, this.Context.Enlistment, diff --git a/GVFS/GVFS.UnitTests/Common/RetryConfigTests.cs b/GVFS/GVFS.UnitTests/Common/RetryConfigTests.cs index af6336edd0..ad619d3547 100644 --- a/GVFS/GVFS.UnitTests/Common/RetryConfigTests.cs +++ b/GVFS/GVFS.UnitTests/Common/RetryConfigTests.cs @@ -1,7 +1,10 @@ using GVFS.Common; using GVFS.Common.FileSystem; using GVFS.Common.Git; +using GVFS.CommandLine; +using GVFS.Common.Tracing; using GVFS.Tests.Should; +using GVFS.UnitTests.Category; using GVFS.UnitTests.Mock.Common; using GVFS.UnitTests.Mock.Git; using NUnit.Framework; @@ -30,8 +33,7 @@ public void MissingOrBlankSettingsUseDefaultsWithoutWarnings(int exitCode) () => new GitProcess.Result(string.Empty, string.Empty, exitCode)); } - RetryConfig.TryLoadFromGitConfig(tracer, git, out RetryConfig config, out string error).ShouldEqual(true); - error.ShouldEqual(string.Empty); + RetryConfig config = RetryConfig.LoadFromGitConfig(tracer, git); config.MaxRetries.ShouldEqual(6); config.MaxAttempts.ShouldEqual(7); config.Timeout.ShouldEqual(TimeSpan.FromSeconds(30)); @@ -45,8 +47,7 @@ public void CompleteLoaderReadsAllSettings() { using MockTracer tracer = new MockTracer(); MockGitProcess git = CreateGitProcess(); - RetryConfig.TryLoadFromGitConfig(tracer, git, out RetryConfig config, out string error).ShouldEqual(true); - error.ShouldEqual(string.Empty); + RetryConfig config = RetryConfig.LoadFromGitConfig(tracer, git); config.MaxRetries.ShouldEqual(9); config.MaxAttempts.ShouldEqual(10); config.Timeout.ShouldEqual(TimeSpan.FromSeconds(45)); @@ -59,6 +60,7 @@ public void CompleteLoaderReadsAllSettings() [TestCase("gvfs.max-retries", "-1", 6)] [TestCase("gvfs.max-retries", "invalid", 6)] [TestCase("gvfs.max-retries", "2147483647", 6)] + [TestCase("gvfs.max-retries", "2147483645", 6)] [TestCase("gvfs.timeout-seconds", "-1", 30)] [TestCase("gvfs.timeout-seconds", "0", 30)] [TestCase("gvfs.timeout-seconds", "invalid", 30)] @@ -74,8 +76,7 @@ public void InvalidSettingUsesOnlyItsOwnDefault(string key, string value, int ex git.SetExpectedCommandResult("config " + key, () => new GitProcess.Result(value, string.Empty, GitProcess.Result.SuccessCode)); - RetryConfig.TryLoadFromGitConfig(tracer, git, out RetryConfig config, out string error).ShouldEqual(true); - error.ShouldEqual(string.Empty); + RetryConfig config = RetryConfig.LoadFromGitConfig(tracer, git); config.MaxRetries.ShouldEqual(key == "gvfs.max-retries" ? 6 : 9); config.Timeout.ShouldEqual(TimeSpan.FromSeconds(key == "gvfs.timeout-seconds" ? 30 : 45)); config.ReadTimeout.ShouldEqual(TimeSpan.FromSeconds(key == "gvfs.read-timeout-seconds" ? 60 : 90)); @@ -94,7 +95,7 @@ public void CompleteLoaderSupportsReadTimeoutBounds(string value, int expectedMi MockGitProcess git = CreateGitProcess(); git.SetExpectedCommandResult("config gvfs.read-timeout-seconds", () => new GitProcess.Result(value, string.Empty, GitProcess.Result.SuccessCode)); - RetryConfig.TryLoadFromGitConfig(tracer, git, out RetryConfig config, out _).ShouldEqual(true); + RetryConfig config = RetryConfig.LoadFromGitConfig(tracer, git); config.ReadTimeout.ShouldEqual(TimeSpan.FromMilliseconds(expectedMilliseconds)); config.MaxRetries.ShouldEqual(9); config.Timeout.ShouldEqual(TimeSpan.FromSeconds(45)); @@ -112,8 +113,7 @@ public void ReadFailuresUseDefaultsWithoutAborting() () => new GitProcess.Result(string.Empty, "Failed to read config", GitProcess.Result.GenericFailureCode)); } - RetryConfig.TryLoadFromGitConfig(tracer, git, out RetryConfig config, out string error).ShouldEqual(true); - error.ShouldEqual(string.Empty); + RetryConfig config = RetryConfig.LoadFromGitConfig(tracer, git); config.MaxRetries.ShouldEqual(6); config.Timeout.ShouldEqual(TimeSpan.FromSeconds(30)); config.ReadTimeout.ShouldEqual(TimeSpan.FromSeconds(60)); @@ -123,12 +123,12 @@ public void ReadFailuresUseDefaultsWithoutAborting() [TestCase(false)] [TestCase(true)] + [NUnit.Framework.Category(CategoryConstants.ExceptionExpected)] public void ConfigReadExceptionsUseDefaultsAndKeepTheExceptionInDiagnostics(bool processError) { using MockTracer tracer = new MockTracer(); MockGitProcess git = CreateGitProcess(new ThrowingGitProcess(processError)); - RetryConfig.TryLoadFromGitConfig(tracer, git, out RetryConfig config, out string error).ShouldEqual(true); - error.ShouldEqual(string.Empty); + RetryConfig config = RetryConfig.LoadFromGitConfig(tracer, git); config.MaxRetries.ShouldEqual(9); config.Timeout.ShouldEqual(TimeSpan.FromSeconds(45)); config.ReadTimeout.ShouldEqual(TimeSpan.FromSeconds(60)); @@ -143,11 +143,11 @@ public void LaterInvalidSettingsDoNotMutateAnExistingConfiguration() { using MockTracer tracer = new MockTracer(); MockGitProcess git = CreateGitProcess(); - RetryConfig.TryLoadFromGitConfig(tracer, git, out RetryConfig existing, out _).ShouldEqual(true); + RetryConfig existing = RetryConfig.LoadFromGitConfig(tracer, git); git.SetExpectedCommandResult("config gvfs.read-timeout-seconds", () => new GitProcess.Result("invalid", string.Empty, GitProcess.Result.SuccessCode)); - RetryConfig.TryLoadFromGitConfig(tracer, git, out RetryConfig reloaded, out _).ShouldEqual(true); + RetryConfig reloaded = RetryConfig.LoadFromGitConfig(tracer, git); existing.ReadTimeout.ShouldEqual(TimeSpan.FromSeconds(90)); reloaded.ReadTimeout.ShouldEqual(TimeSpan.FromSeconds(60)); reloaded.MaxRetries.ShouldEqual(existing.MaxRetries); @@ -158,15 +158,52 @@ public void LaterInvalidSettingsDoNotMutateAnExistingConfiguration() public void CommandOverridesDoNotDiscardLoadedReadTimeout() { using MockTracer tracer = new MockTracer(); - RetryConfig.TryLoadFromGitConfig(tracer, CreateGitProcess(), out RetryConfig config, out _).ShouldEqual(true); - config.MaxRetries = 2; - config.Timeout = TimeSpan.FromMinutes(10); - config.MaxRetries.ShouldEqual(2); - config.MaxAttempts.ShouldEqual(3); + MockGitProcess git = CreateGitProcess(); + RetryConfig config = new RetryConfigVerb().Load( + tracer, new MockGVFSEnlistment(git), TimeSpan.FromMinutes(10)); + config.MaxRetries.ShouldEqual(9); + config.MaxAttempts.ShouldEqual(10); config.Timeout.ShouldEqual(TimeSpan.FromMinutes(10)); config.ReadTimeout.ShouldEqual(TimeSpan.FromSeconds(90)); } + [TestCase] + public void LargestAcceptedValuesDoNotOverflowConsumerArithmetic() + { + using MockTracer tracer = new MockTracer(); + MockGitProcess git = CreateGitProcess(); + git.SetExpectedCommandResult("config gvfs.max-retries", + () => new GitProcess.Result("2147483644", string.Empty, 0)); + git.SetExpectedCommandResult("config gvfs.timeout-seconds", + () => new GitProcess.Result("2147483", string.Empty, 0)); + RetryConfig config = RetryConfig.LoadFromGitConfig(tracer, git); + checked(config.MaxAttempts + 2).ShouldEqual(int.MaxValue); + config.Timeout.ShouldEqual(TimeSpan.FromMilliseconds(2147483000)); + tracer.RelatedWarningEvents.Count.ShouldEqual(0); + } + + [TestCase] + [NUnit.Framework.Category(CategoryConstants.ExceptionExpected)] + public void CompleteLoaderRejectsMissingDependencies() + { + Assert.Throws(() => RetryConfig.LoadFromGitConfig(null, (GitProcess)null)); + Assert.Throws(() => RetryConfig.LoadFromGitConfig(null, (Enlistment)null)); + } + + private class RetryConfigVerb : GVFSVerb + { + public override string EnlistmentRootPathParameter { get; set; } + protected override string VerbName => "retry-config-test"; + public override void Execute() + { + } + + public RetryConfig Load(ITracer tracer, GVFSEnlistment enlistment, TimeSpan timeout) + { + return this.GetRetryConfig(tracer, enlistment, timeout); + } + } + private static MockGitProcess CreateGitProcess(MockGitProcess git = null) { git = git ?? new MockGitProcess(); diff --git a/GVFS/GVFS.UnitTests/Common/StreamUtilTests.cs b/GVFS/GVFS.UnitTests/Common/StreamUtilTests.cs new file mode 100644 index 0000000000..37cfcc66eb --- /dev/null +++ b/GVFS/GVFS.UnitTests/Common/StreamUtilTests.cs @@ -0,0 +1,50 @@ +using GVFS.Common; +using GVFS.Common.Http; +using GVFS.Tests.Should; +using GVFS.UnitTests.Category; +using NUnit.Framework; +using System; +using System.IO; +using System.Threading; + +namespace GVFS.UnitTests.Common +{ + [TestFixture] + public class StreamUtilTests + { + [TestCase(false)] + [TestCase(true)] + [Category(CategoryConstants.ExceptionExpected)] + public void BodyCancellationDoesNotBecomeARetryOrCircuitFailure(bool greedy) + { + RetryCircuitBreaker.Reset(); + using CancellationTokenSource cancellation = new CancellationTokenSource(); + using HttpResponseStream stream = new HttpResponseStream( + new MemoryStream(new byte[] { 1 }), TimeSpan.FromSeconds(60), cancellation.Token); + RetryWrapper retry = new RetryWrapper(1, cancellation.Token); + try + { + Assert.Catch(() => retry.Invoke(attempt => + { + cancellation.Cancel(); + if (greedy) + { + StreamUtil.TryReadGreedy(stream, new byte[1], 0, 1).ShouldEqual(1); + } + else + { + StreamUtil.CopyToWithBuffer(stream, Stream.Null); + } + + return new RetryWrapper.CallbackResult(true); + })); + RetryCircuitBreaker.ConsecutiveFailures.ShouldEqual(0); + stream.ReadFailed.ShouldEqual(false); + } + finally + { + RetryCircuitBreaker.Reset(); + } + } + } +} diff --git a/GVFS/GVFS.UnitTests/Git/GitObjectsTests.cs b/GVFS/GVFS.UnitTests/Git/GitObjectsTests.cs index fc1f9686b1..0f3ed2c503 100644 --- a/GVFS/GVFS.UnitTests/Git/GitObjectsTests.cs +++ b/GVFS/GVFS.UnitTests/Git/GitObjectsTests.cs @@ -3,6 +3,7 @@ using GVFS.Common.Http; using GVFS.Common.Tracing; using GVFS.Tests.Should; +using GVFS.UnitTests.Category; using GVFS.UnitTests.Mock.Common; using GVFS.UnitTests.Mock.FileSystem; using NUnit.Framework; @@ -203,6 +204,7 @@ public void PrefetchPackTelemetryCorrelatesResponseAndRetrySummary() (packIndex >= 0).ShouldEqual(true); EventMetadata pack = activity.RelatedEventMetadata[packIndex]; pack["ResponseId"].ShouldEqual(requestor.ResponseId); + pack["RequestId"].ShouldEqual(requestor.RequestId); pack["PackBytes"].ShouldEqual(1L); ((activity.RelatedEventKeywords[packIndex] & Keywords.Telemetry) != 0).ShouldEqual(true); EventMetadata start = tracer.StartMetadata.Single(metadata => metadata != null && metadata.ContainsKey("RequestId")); @@ -210,6 +212,8 @@ public void PrefetchPackTelemetryCorrelatesResponseAndRetrySummary() start["RequestId"].ShouldEqual(requestor.RequestId); stop["RequestId"].ShouldEqual(requestor.RequestId); stop["Success"].ShouldEqual(true); + tracer.SnapshotRelatedEvents().Any(record => record.Name.StartsWith("NetworkBody", StringComparison.Ordinal)) + .ShouldEqual(false); } [TestCase] @@ -246,6 +250,55 @@ public async Task PrefetchHeaderFailureDrainsEarlierPackWorkBeforeRetry() objects.Moves.ShouldEqual(2); } + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void InterruptedResponseAlsoReportsPackFinalizationFailure() + { + using MockTracer tracer = new MockTracer(); + MockGVFSEnlistment enlistment = new MockGVFSEnlistment(); + using StreamingPrefetchRequestor requestor = new StreamingPrefetchRequestor(tracer, enlistment); + using MemoryStream initial = CreatePrefetchResponse(2); + requestor.Streams.Enqueue(new HeaderFailureStream(initial.ToArray())); + requestor.Streams.Enqueue(CreatePrefetchResponse(0)); + TestPrefetchGitObjects objects = new TestPrefetchGitObjects(tracer, enlistment, requestor) + { + FirstFlush = Task.FromException(new IOException("pack finalization failed")), + }; + + objects.TryDownloadPrefetchPacks(null, 0, true, out List _).ShouldEqual(true); + tracer.StartActivityTracer.RelatedWarningEvents.ShouldContain( + warning => warning.Contains("pack finalization failed", StringComparison.Ordinal) && + warning.Contains("response was interrupted", StringComparison.Ordinal)); + requestor.Requests[1].Query.ShouldEqual("?lastPackTimestamp=0"); + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void TemporaryPackCancellationPropagatesWithoutAFailureWarning() + { + using MockTracer tracer = new MockTracer(); + MockFileSystemWithCallbacks filesystem = new MockFileSystemWithCallbacks + { + OnOpenFileStream = (path, mode, access) => new MemoryStream(), + OnFileExists = path => false, + }; + GitObjects objects = new GVFSGitObjects( + new GVFSContext(tracer, filesystem, null, new MockGVFSEnlistment()), null); + using Stream canceled = new CanceledReadStream(); + + Assert.Throws(() => objects.TryWriteTempFile( + tracer, canceled, "mock:\\canceled.pack", out long _, out Task _, throwOnError: false)); + tracer.RelatedWarningEvents.Count.ShouldEqual(0); + } + + private sealed class CanceledReadStream : MemoryStream + { + public override int Read(byte[] buffer, int offset, int count) + { + throw new OperationCanceledException(); + } + } + private static MemoryStream CreatePrefetchResponse(ushort declaredPacks) { MemoryStream response = new MemoryStream(); @@ -308,7 +361,9 @@ protected override GitEndPointResponseData SendProtocolRequest( this.Requests.Add(requestUri); GitEndPointResponseData response = new GitEndPointResponseData( HttpStatusCode.OK, GVFSConstants.MediaTypes.PrefetchPackFilesAndIndexesMediaType, - this.Streams.Dequeue(), null, null); + new HttpResponseStream(this.Streams.Dequeue(), this.RetryConfig.ReadTimeout, + cancellationToken, this.Tracer, new EventMetadata { { "RequestId", requestId } }), + null, null); this.ResponseId = response.ResponseId; return response; } diff --git a/GVFS/GVFS.UnitTests/Http/HttpResponseStreamTests.cs b/GVFS/GVFS.UnitTests/Http/HttpResponseStreamTests.cs index f5e8e6bdb5..f8cbe48eb4 100644 --- a/GVFS/GVFS.UnitTests/Http/HttpResponseStreamTests.cs +++ b/GVFS/GVFS.UnitTests/Http/HttpResponseStreamTests.cs @@ -1,7 +1,9 @@ using GVFS.Common; +using GVFS.Common.Git; using GVFS.Common.Http; using GVFS.Common.Tracing; using GVFS.Tests.Should; +using GVFS.UnitTests.Category; using GVFS.UnitTests.Mock.Common; using GVFS.UnitTests.Mock.Git; using NUnit.Framework; @@ -29,6 +31,7 @@ public void DefaultReadTimeoutIsSixtySeconds() } [TestCase] + [Category(CategoryConstants.ExceptionExpected)] public void SynchronousReadTimesOut() { using (HttpResponseStream stream = CreateStream(new BlockingReadStream())) @@ -40,6 +43,7 @@ public void SynchronousReadTimesOut() } [TestCase] + [Category(CategoryConstants.ExceptionExpected)] public void ReadByteTimesOut() { using (HttpResponseStream stream = CreateStream(new BlockingReadStream())) @@ -50,6 +54,7 @@ public void ReadByteTimesOut() } [TestCase] + [Category(CategoryConstants.ExceptionExpected)] public void SpanReadTimesOut() { using (HttpResponseStream stream = CreateStream(new BlockingReadStream())) @@ -60,6 +65,7 @@ public void SpanReadTimesOut() } [TestCase] + [Category(CategoryConstants.ExceptionExpected)] public void ArrayReadAsyncTimesOut() { using (HttpResponseStream stream = CreateStream(new BlockingReadStream())) @@ -71,6 +77,7 @@ public void ArrayReadAsyncTimesOut() } [TestCase] + [Category(CategoryConstants.ExceptionExpected)] public void MemoryReadAsyncTimesOut() { using (HttpResponseStream stream = CreateStream(new BlockingReadStream())) @@ -100,8 +107,8 @@ public async Task SlowTransferContinuesBeyondTheReadTimeout() total.ShouldEqual(12); stream.ReadFailed.ShouldEqual(false); - tracer.RelatedEventNames.ShouldNotContain(name => name == "NetworkBodyReadTimeout"); - EventMetadata summary = tracer.RelatedEventMetadata.Last(); + tracer.SnapshotRelatedEvents().ShouldNotContain(record => record.Name == "NetworkBodyReadTimeout"); + EventMetadata summary = LastBodyEvent(tracer, "Completed").Metadata; summary["Outcome"].ShouldEqual("Completed"); summary["BytesRead"].ShouldEqual(12L); ((double)summary["ElapsedMs"] > 300).ShouldEqual(true); @@ -119,16 +126,17 @@ public async Task ConsumerPauseDoesNotTimeOutAndReportsNoPendingRead() stream.ReadByte().ShouldEqual(2); stream.ReadByte().ShouldEqual(-1); stream.ReadFailed.ShouldEqual(false); - tracer.RelatedEventNames.ShouldNotContain(name => name == "NetworkBodyReadTimeout"); - tracer.RelatedEventMetadata.ShouldContain( - metadata => (string)metadata["Outcome"] == "InProgress" && - (bool)metadata["ReadPending"] == false && - (long)metadata["BytesRead"] == 1); + tracer.SnapshotRelatedEvents().ShouldNotContain(record => record.Name == "NetworkBodyReadTimeout"); + tracer.SnapshotRelatedEvents().ShouldContain( + record => (string)record.Metadata["Outcome"] == "InProgress" && + (bool)record.Metadata["ReadPending"] == false && + (long)record.Metadata["BytesRead"] == 1); } } [TestCase(false)] [TestCase(true)] + [Category(CategoryConstants.ExceptionExpected)] public async Task CallerCancellationIsNotAReadFailure(bool cancelRequest) { using MockTracer tracer = new MockTracer(); @@ -147,12 +155,12 @@ public async Task CallerCancellationIsNotAReadFailure(bool cancelRequest) cancellation.Cancel(); Assert.CatchAsync(async () => await read.WaitAsync(TimeSpan.FromSeconds(5))); stream.ReadFailed.ShouldEqual(false); - tracer.RelatedEventMetadata.Last()["Outcome"].ShouldEqual("Canceled"); - tracer.RelatedEventLevels.Last().ShouldEqual(EventLevel.Informational); + LastBodyEvent(tracer, "Canceled").Level.ShouldEqual(EventLevel.Informational); } } [TestCase] + [Category(CategoryConstants.ExceptionExpected)] public async Task DisposingCancelsPendingReadWithoutCallingItATimeout() { using MockTracer tracer = new MockTracer(); @@ -164,12 +172,13 @@ public async Task DisposingCancelsPendingReadWithoutCallingItATimeout() stream.Dispose(); Assert.CatchAsync(async () => await read.WaitAsync(TimeSpan.FromSeconds(5))); stream.ReadFailed.ShouldEqual(false); - tracer.RelatedEventNames.ShouldNotContain(name => name == "NetworkBodyReadTimeout"); - tracer.RelatedEventMetadata.Last()["Outcome"].ShouldEqual("Closed"); + tracer.SnapshotRelatedEvents().ShouldNotContain(record => record.Name == "NetworkBodyReadTimeout"); + LastBodyEvent(tracer, "Closed").Metadata["Outcome"].ShouldEqual("Closed"); } } [TestCase] + [Category(CategoryConstants.ExceptionExpected)] public void BlockedReadReportsProgressAndTimeoutWithMatchingResponseId() { using MockTracer tracer = new MockTracer(); @@ -177,11 +186,12 @@ public void BlockedReadReportsProgressAndTimeoutWithMatchingResponseId() { Assert.ThrowsAsync( async () => await stream.ReadAsync(new byte[8].AsMemory()).AsTask().WaitAsync(TimeSpan.FromSeconds(5))); - tracer.RelatedEventNames.ShouldContain(name => name == "NetworkBodyProgress"); - tracer.RelatedEventNames.Last().ShouldEqual("NetworkBodyReadTimeout"); - tracer.RelatedEventMetadata.ShouldContain( - metadata => (bool)metadata["ReadPending"] && (double)metadata["CurrentReadWaitMs"] > 0); - foreach (EventMetadata metadata in tracer.RelatedEventMetadata) + MockTracer.RecordedEvent[] records = tracer.SnapshotRelatedEvents(); + records.ShouldContain(record => record.Name == "NetworkBodyProgress"); + LastBodyEvent(tracer, "TimedOut").Name.ShouldEqual("NetworkBodyReadTimeout"); + records.ShouldContain( + record => (bool)record.Metadata["ReadPending"] && (double)record.Metadata["CurrentReadWaitMs"] > 0); + foreach (EventMetadata metadata in records.Select(record => record.Metadata)) { metadata["ResponseId"].ShouldEqual(stream.ResponseId); ((long)metadata["SampleSequence"] > 0).ShouldEqual(true); @@ -190,18 +200,19 @@ public void BlockedReadReportsProgressAndTimeoutWithMatchingResponseId() metadata["RequestAuthority"].ShouldEqual("cache.example:443"); } - EventMetadata timeout = tracer.RelatedEventMetadata.Last(); + EventMetadata timeout = LastBodyEvent(tracer, "TimedOut").Metadata; timeout["Outcome"].ShouldEqual("TimedOut"); timeout["BytesRead"].ShouldEqual(0L); - tracer.RelatedEventLevels.Last().ShouldEqual(EventLevel.Warning); + LastBodyEvent(tracer, "TimedOut").Level.ShouldEqual(EventLevel.Warning); ((double)timeout["MaxReadWaitMs"] >= 200).ShouldEqual(true); ((double)timeout["ReadTimeMs"] >= 200).ShouldEqual(true); - tracer.RelatedEventKeywords.ShouldContain( - keywords => (keywords & Keywords.Telemetry) == Keywords.Telemetry); + records.ShouldContain( + record => (record.Keyword & Keywords.Telemetry) == Keywords.Telemetry); } } [TestCase] + [Category(CategoryConstants.ExceptionExpected)] public void ReadTimeoutReportsBytesReceivedBeforeTheStall() { using (MockTracer tracer = new MockTracer()) @@ -210,7 +221,7 @@ public void ReadTimeoutReportsBytesReceivedBeforeTheStall() byte[] buffer = new byte[8]; stream.Read(buffer, 0, buffer.Length).ShouldEqual(3); Assert.Throws(() => stream.Read(buffer, 0, buffer.Length).ShouldEqual(0)); - EventMetadata timeout = tracer.RelatedEventMetadata.Last(); + EventMetadata timeout = LastBodyEvent(tracer, "TimedOut").Metadata; timeout["Outcome"].ShouldEqual("TimedOut"); timeout["BytesRead"].ShouldEqual(3L); ((double)timeout["MillisecondsSinceLastByte"] >= 200).ShouldEqual(true); @@ -232,12 +243,14 @@ public async Task ProgressStopsAfterCompletionOrDisposal(bool readToEnd) } stream.Dispose(); - int eventCount = tracer.RelatedEventNames.Count; + long terminalSequence = (long)LastBodyEvent(tracer, readToEnd ? "Completed" : "Closed").Metadata["SampleSequence"]; await Task.Delay(120); - tracer.RelatedEventNames.Count.ShouldEqual(eventCount); + tracer.SnapshotRelatedEvents().Max(record => (long)record.Metadata["SampleSequence"]) + .ShouldEqual(terminalSequence); } [TestCase] + [Category(CategoryConstants.ExceptionExpected)] public async Task ZeroLengthReadsDoNotStartAReadOrCompleteTheTransfer() { using (BlockingReadStream innerStream = new BlockingReadStream()) @@ -266,10 +279,11 @@ public void FastTransfersDoNotEmitProgressEvents() stream.ReadByte().ShouldEqual(-1); } - tracer.RelatedEventNames.Count.ShouldEqual(0); + tracer.SnapshotRelatedEvents().Length.ShouldEqual(0); } [TestCase] + [Category(CategoryConstants.ExceptionExpected)] public async Task RealHttpBodyReadTimesOutAfterHeadersAndPartialData() { using (MockTracer tracer = new MockTracer()) @@ -291,7 +305,7 @@ public async Task RealHttpBodyReadTimesOutAfterHeadersAndPartialData() Assert.ThrowsAsync( async () => await stream.ReadAsync(new byte[8].AsMemory()).AsTask().WaitAsync(TimeSpan.FromSeconds(5))); stream.ReadFailed.ShouldEqual(true); - tracer.RelatedEventNames.Last().ShouldEqual("NetworkBodyReadTimeout"); + LastBodyEvent(tracer, "TimedOut").Name.ShouldEqual("NetworkBodyReadTimeout"); } } finally @@ -313,6 +327,7 @@ public async Task RealHttpBodyReadTimesOutAfterHeadersAndPartialData() [TestCase(HttpStatusCode.ServiceUnavailable)] [TestCase(HttpStatusCode.Unauthorized)] [TestCase(HttpStatusCode.NotFound)] + [Category(CategoryConstants.ExceptionExpected)] public async Task RequestorAppliesConfiguredReadTimeoutToSuccessAndErrorBodies(HttpStatusCode status) { using (MockTracer tracer = new MockTracer()) @@ -333,8 +348,7 @@ public async Task RequestorAppliesConfiguredReadTimeoutToSuccessAndErrorBodies(H response.Stream.ReadByte().ShouldEqual((int)'x'); Assert.Throws(() => response.Stream.ReadByte()); response.StreamReadFailed.ShouldEqual(true); - response.ResponseId.ShouldEqual((string)tracer.RelatedEventMetadata - .Last(metadata => metadata.ContainsKey("ResponseId"))["ResponseId"]); + response.ResponseId.ShouldEqual((string)LastBodyEvent(tracer, "TimedOut").Metadata["ResponseId"]); } } else @@ -349,9 +363,7 @@ public async Task RequestorAppliesConfiguredReadTimeoutToSuccessAndErrorBodies(H } } - int timeoutIndex = tracer.RelatedEventNames.IndexOf("NetworkBodyReadTimeout"); - (timeoutIndex >= 0).ShouldEqual(true); - EventMetadata timeout = tracer.RelatedEventMetadata[timeoutIndex]; + EventMetadata timeout = LastBodyEvent(tracer, "TimedOut").Metadata; timeout["RequestId"].ShouldEqual(42L); timeout["StatusCode"].ShouldEqual(status); timeout["CacheName"].ShouldEqual("test-cache"); @@ -396,6 +408,7 @@ private static HttpResponseStream CreateStream( } [TestCase] + [Category(CategoryConstants.ExceptionExpected)] public async Task StalledErrorBodyRetriesWithTheStatusAndReleasesItsConnectionPermit() { using MockTracer tracer = new MockTracer(); @@ -425,7 +438,7 @@ public async Task StalledErrorBodyRetriesWithTheStatusAndReleasesItsConnectionPe cancellationToken: CancellationToken.None); result.Succeeded.ShouldEqual(true); result.Attempts.ShouldEqual(2); - EventMetadata[] responses = tracer.RelatedEventMetadata + EventMetadata[] responses = tracer.SnapshotRelatedEvents().Select(record => record.Metadata) .Where(metadata => metadata.ContainsKey("availableConnections")).ToArray(); responses.Length.ShouldEqual(2); responses[0]["StatusCode"].ShouldEqual(HttpStatusCode.ServiceUnavailable); @@ -447,6 +460,7 @@ public async Task StalledErrorBodyRetriesWithTheStatusAndReleasesItsConnectionPe } [TestCase] + [Category(CategoryConstants.ExceptionExpected)] public async Task ConfigProbeRetainsUnauthorizedStatusWhenItsBodyStalls() { using MockTracer tracer = new MockTracer(); @@ -480,6 +494,231 @@ public async Task ConfigProbeRetainsUnauthorizedStatusWhenItsBodyStalls() } } + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public async Task FinalResponseDiagnosticFailureReleasesThePreparedResponse() + { + using CallbackTracer tracer = new CallbackTracer(); + bool fail = true; + tracer.Callback = name => + { + if (name == "NetworkResponse" && fail) + { + fail = false; + throw new InvalidOperationException("diagnostic failure"); + } + }; + using CancellationTokenSource cancellation = new CancellationTokenSource(TimeSpan.FromSeconds(10)); + using TcpListener listener = new TcpListener(IPAddress.Loopback, 0); + listener.Start(); + Uri endpoint = new Uri($"http://127.0.0.1:{((IPEndPoint)listener.LocalEndpoint).Port}"); + Task server = ServeRetriedError(listener, cancellation.Token); + using LoopbackHttpRequestor requestor = new LoopbackHttpRequestor(tracer); + try + { + Assert.Throws(() => requestor.Get(endpoint)); + using (GitEndPointResponseData response = requestor.Get(endpoint)) + { + response.StatusCode.ShouldEqual(HttpStatusCode.OK); + response.Stream.ReadByte().ShouldEqual(-1); + } + + MockTracer.RecordedEvent[] responses = tracer.SnapshotRelatedEvents() + .Where(record => record.Name == "NetworkResponse").ToArray(); + responses.Length.ShouldEqual(2); + responses[1].Metadata["availableConnections"].ShouldEqual(responses[0].Metadata["availableConnections"]); + } + finally + { + cancellation.Cancel(); + listener.Stop(); + await ObserveServerCancellation(server, cancellation.Token); + } + } + + [TestCase] + public async Task AnonymousUnauthorizedBodyDoesNotReachTheErrorTelemetry() + { + using MockTracer tracer = new MockTracer(); + using CancellationTokenSource cancellation = new CancellationTokenSource(TimeSpan.FromSeconds(10)); + using TcpListener listener = new TcpListener(IPAddress.Loopback, 0); + listener.Start(); + Uri endpoint = new Uri($"http://127.0.0.1:{((IPEndPoint)listener.LocalEndpoint).Port}"); + Task server = ServeCompleteResponses(listener, cancellation.Token, + (HttpStatusCode.Unauthorized, "\u001b[31mRAW-BODY-MARKER", "text/plain; charset=utf-8")); + using GitObjectsHttpRequestor requestor = new GitObjectsHttpRequestor( + tracer, new MockGVFSEnlistment(), new CacheServerInfo(endpoint.AbsoluteUri, "test"), new RetryConfig(0)); + try + { + RetryWrapper.InvocationResult result = + requestor.TrySendProtocolRequest( + 123, + (attempt, response) => throw new InvalidOperationException("Unexpected success"), + RetryWrapper.StandardErrorHandler(tracer, 123, "test"), + HttpMethod.Get, + () => endpoint, + () => null, + CancellationToken.None); + result.Succeeded.ShouldEqual(false); + result.Error.Message.ShouldEqual("Anonymous request was rejected with a 401"); + tracer.RelatedErrorEvents.Count.ShouldEqual(1); + tracer.RelatedErrorEvents[0].ShouldContain("Anonymous request was rejected with a 401"); + tracer.RelatedErrorEvents[0].Contains("RAW-BODY-MARKER", StringComparison.Ordinal).ShouldEqual(false); + } + finally + { + cancellation.Cancel(); + listener.Stop(); + await ObserveServerCancellation(server, cancellation.Token); + } + } + + [TestCase(true)] + [TestCase(false)] + public async Task CompletedBadRequestBodyPreservesCharsetAndCredentialPolicy(bool authRequired) + { + using MockTracer tracer = new MockTracer(); + using CancellationTokenSource cancellation = new CancellationTokenSource(TimeSpan.FromSeconds(10)); + using TcpListener listener = new TcpListener(IPAddress.Loopback, 0); + listener.Start(); + string endpoint = $"http://127.0.0.1:{((IPEndPoint)listener.LocalEndpoint).Port}"; + string body = authRequired ? HttpRequestor.CacheServerAuthRequiredBadRequestMessage : "denied: caf\u00e9"; + Task server = ServeCompleteResponses(listener, cancellation.Token, + (HttpStatusCode.Unauthorized, "denied", "text/plain"), + (HttpStatusCode.OK, "{}", "application/json"), + (HttpStatusCode.BadRequest, body, "text/plain; charset=utf-8")); + MockGitProcess git = CreateCredentialGitProcess(endpoint); + GitAuthentication authentication = new GitAuthentication(git, endpoint); + MockGVFSEnlistment enlistment = new MockGVFSEnlistment( + "mock:\\repo", endpoint, "mock:\\git", git, authentication); + using LoopbackHttpRequestor requestor = new LoopbackHttpRequestor(tracer, enlistment); + try + { + authentication.TryInitializeAndQueryGVFSConfig( + tracer, enlistment, new RetryConfig(0, TimeSpan.FromSeconds(5)), + out _, out string error, out _).ShouldEqual(true, error); + authentication.IsAnonymous.ShouldEqual(false); + using (GitEndPointResponseData response = requestor.Get(new Uri(endpoint))) + { + response.StatusCode.ShouldEqual(HttpStatusCode.BadRequest); + response.ShouldRetry.ShouldEqual(false); + response.Error.Message.ShouldContain(body); + } + + bool rejected = git.CredentialRejections.TryGetValue(endpoint, out System.Collections.Generic.List rejections); + rejected.ShouldEqual(authRequired); + if (authRequired) + { + rejections.Count.ShouldEqual(1); + } + } + finally + { + cancellation.Cancel(); + listener.Stop(); + await ObserveServerCancellation(server, cancellation.Token); + } + } + + [TestCase] + public async Task AuthenticationInitializationLoadsAllRetrySettings() + { + using MockTracer tracer = new MockTracer(); + using CancellationTokenSource cancellation = new CancellationTokenSource(TimeSpan.FromSeconds(10)); + using TcpListener listener = new TcpListener(IPAddress.Loopback, 0); + listener.Start(); + string endpoint = $"http://127.0.0.1:{((IPEndPoint)listener.LocalEndpoint).Port}"; + Task server = ServeCompleteResponses(listener, cancellation.Token, + (HttpStatusCode.OK, "{}", "application/json")); + MockGitProcess git = CreateCredentialGitProcess(endpoint); + git.SetExpectedCommandResult("config gvfs.max-retries", () => new GitProcess.Result("0", string.Empty, 0)); + git.SetExpectedCommandResult("config gvfs.timeout-seconds", () => new GitProcess.Result("2", string.Empty, 0)); + git.SetExpectedCommandResult("config gvfs.read-timeout-seconds", () => new GitProcess.Result("1", string.Empty, 0)); + GitAuthentication authentication = new GitAuthentication(git, endpoint); + MockGVFSEnlistment enlistment = new MockGVFSEnlistment( + "mock:\\repo", endpoint, "mock:\\git", git, authentication); + try + { + authentication.TryInitialize(tracer, enlistment, out string error).ShouldEqual(true, error); + foreach (string key in new[] { "gvfs.max-retries", "gvfs.timeout-seconds", "gvfs.read-timeout-seconds" }) + { + git.CommandsRun.Count(command => command == "config " + key).ShouldEqual(1); + } + } + finally + { + cancellation.Cancel(); + listener.Stop(); + await ObserveServerCancellation(server, cancellation.Token); + } + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void DisposedRootTracerDoesNotChangeTheReadFailureOrExitTheProcess() + { + using JsonTracer tracer = new JsonTracer(GVFSConstants.GVFSEtwProviderName, "body-test", disableTelemetry: true); + using HttpResponseStream stream = new HttpResponseStream( + new BlockingReadStream(), TimeSpan.FromMilliseconds(200), CancellationToken.None, + tracer, progressInterval: TimeSpan.FromMilliseconds(20)); + tracer.Dispose(); + IOException failure = Assert.ThrowsAsync( + async () => await stream.ReadAsync(new byte[1].AsMemory()).AsTask().WaitAsync(TimeSpan.FromSeconds(5))); + failure.Message.ShouldContain("No response body data arrived"); + stream.ReadFailed.ShouldEqual(true); + } + + private static MockGitProcess CreateCredentialGitProcess(string endpoint) + { + MockGitProcess git = new MockGitProcess(); + git.SetExpectedCommandResult("config --get-urlmatch http " + endpoint, + () => new GitProcess.Result(string.Empty, string.Empty, 0)); + git.SetExpectedCommandResult("config gvfs.max-http-connections", + () => new GitProcess.Result(string.Empty, string.Empty, 1)); + const string Prefix = "-c credential.\"https://dev.azure.com\".useHttpPath=true credential "; + git.SetExpectedCommandResult(Prefix + "fill", + () => new GitProcess.Result("username=test-user\npassword=test-password\n", string.Empty, 0)); + git.SetExpectedCommandResult(Prefix + "approve", () => new GitProcess.Result(string.Empty, string.Empty, 0)); + git.SetExpectedCommandResult(Prefix + "reject", () => new GitProcess.Result(string.Empty, string.Empty, 0)); + return git; + } + + private static async Task ServeCompleteResponses(TcpListener listener, CancellationToken cancellationToken, + params (HttpStatusCode Status, string Body, string ContentType)[] responses) + { + foreach ((HttpStatusCode status, string body, string contentType) in responses) + { + using TcpClient client = await listener.AcceptTcpClientAsync(cancellationToken); + using NetworkStream stream = client.GetStream(); + using (StreamReader reader = new StreamReader(stream, Encoding.ASCII, false, 1024, leaveOpen: true)) + { + string line; + do + { + line = await reader.ReadLineAsync(cancellationToken); + } + while (!string.IsNullOrEmpty(line)); + } + + byte[] data = Encoding.UTF8.GetBytes(body); + byte[] headers = Encoding.ASCII.GetBytes( + $"HTTP/1.1 {(int)status} Test\r\nConnection: close\r\nContent-Type: {contentType}\r\nContent-Length: {data.Length}\r\n\r\n"); + await stream.WriteAsync(headers.AsMemory(), cancellationToken); + await stream.WriteAsync(data.AsMemory(), cancellationToken); + } + } + + private static async Task ObserveServerCancellation(Task server, CancellationToken cancellationToken) + { + try + { + await server.WaitAsync(TimeSpan.FromSeconds(5)); + } + catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested) + { + } + } + private static async Task ServeRetriedError(TcpListener listener, CancellationToken cancellationToken) { for (int attempt = 0; attempt < 2; ++attempt) @@ -508,6 +747,7 @@ private static async Task ServeRetriedError(TcpListener listener, CancellationTo } [TestCase] + [Category(CategoryConstants.ExceptionExpected)] public async Task DisabledReadTimeoutStillHonorsCallerCancellation() { using CancellationTokenSource cancellation = new CancellationTokenSource(); @@ -522,6 +762,7 @@ public async Task DisabledReadTimeoutStillHonorsCallerCancellation() } [TestCase] + [Category(CategoryConstants.ExceptionExpected)] public async Task OverlappingAndDisposedReadsFailWithoutOverwritingPendingRead() { using BlockingReadStream innerStream = new BlockingReadStream(); @@ -535,6 +776,7 @@ public async Task OverlappingAndDisposedReadsFailWithoutOverwritingPendingRead() } [TestCase] + [Category(CategoryConstants.ExceptionExpected)] public async Task BlockedProgressListenerDoesNotOwnTheReadStateGate() { using ManualResetEventSlim reporting = new ManualResetEventSlim(); @@ -582,6 +824,7 @@ public async Task BlockedProgressListenerDoesNotOwnTheReadStateGate() } [TestCase] + [Category(CategoryConstants.ExceptionExpected)] public void RawResponseStreamTracksReadFailuresAndIdentity() { using GitEndPointResponseData response = new GitEndPointResponseData( @@ -592,6 +835,7 @@ public void RawResponseStreamTracksReadFailuresAndIdentity() } [TestCase] + [Category(CategoryConstants.ExceptionExpected)] public void ResponseDisposalReleasesPermitWhenFinalDiagnosticsThrow() { using CallbackTracer tracer = new CallbackTracer(); @@ -616,30 +860,62 @@ public void ResponseDisposalReleasesPermitWhenFinalDiagnosticsThrow() } [TestCase] - public async Task ProgressReportsCountOnlyBytesSinceThePreviousReport() + public void ProgressReportsCountOnlyBytesSinceThePreviousReport() { - using MockTracer tracer = new MockTracer(); + using CallbackTracer tracer = new CallbackTracer(); + using ManualResetEventSlim first = new ManualResetEventSlim(); + using ManualResetEventSlim second = new ManualResetEventSlim(); + tracer.EventCallback = (name, metadata) => + { + if (name == "NetworkBodyProgress") + { + if ((long)metadata["BytesRead"] == 1) + { + first.Set(); + } + else if ((long)metadata["BytesRead"] == 2) + { + second.Set(); + } + } + }; using HttpResponseStream stream = CreateStream(new MemoryStream(new byte[] { 1, 2 }), tracer); stream.ReadByte().ShouldEqual(1); - await Task.Delay(150); + first.Wait(TimeSpan.FromSeconds(5)).ShouldEqual(true); stream.ReadByte().ShouldEqual(2); - await Task.Delay(150); + second.Wait(TimeSpan.FromSeconds(5)).ShouldEqual(true); stream.ReadByte().ShouldEqual(-1); - EventMetadata[] reports = tracer.RelatedEventMetadata.ToArray(); + EventMetadata[] reports = tracer.SnapshotRelatedEvents().Select(record => record.Metadata).ToArray(); reports.Select(report => (long)report["SampleSequence"]).Distinct().Count().ShouldEqual(reports.Length); reports.Sum(report => (long)report["BytesSinceLastProgress"]).ShouldEqual(2L); reports.Count(report => (long)report["BytesSinceLastProgress"] == 1).ShouldEqual(2); reports.OrderBy(report => (long)report["SampleSequence"]).Last()["Outcome"].ShouldEqual("Completed"); } + private static MockTracer.RecordedEvent LastBodyEvent(MockTracer tracer, string outcome) + { + return tracer.SnapshotRelatedEvents() + .Where(record => record.Metadata != null && + record.Metadata.TryGetValue("Outcome", out object value) && (string)value == outcome) + .OrderBy(record => (long)record.Metadata["SampleSequence"]) + .Last(); + } + private class CallbackTracer : MockTracer { public Action Callback { get; set; } + public Action EventCallback { get; set; } + + public override void RelatedEvent(EventLevel level, string eventName, EventMetadata metadata) + { + this.RelatedEvent(level, eventName, metadata, Keywords.None); + } public override void RelatedEvent(EventLevel level, string eventName, EventMetadata metadata, Keywords keyword) { - this.Callback?.Invoke(eventName); base.RelatedEvent(level, eventName, metadata, keyword); + this.EventCallback?.Invoke(eventName, metadata); + this.Callback?.Invoke(eventName); } } @@ -678,11 +954,11 @@ private static async Task ServeStalledResponse( private class LoopbackHttpRequestor : HttpRequestor { - public LoopbackHttpRequestor(MockTracer tracer) + public LoopbackHttpRequestor(MockTracer tracer, Enlistment enlistment = null) : base( tracer, - new RetryConfig { ReadTimeout = TimeSpan.FromMilliseconds(300) }, - new MockGVFSEnlistment()) + new RetryConfig(0, TimeSpan.FromSeconds(5)) { ReadTimeout = TimeSpan.FromMilliseconds(300) }, + enlistment ?? new MockGVFSEnlistment()) { } diff --git a/GVFS/GVFS.UnitTests/Mock/Common/MockGVFSEnlistment.cs b/GVFS/GVFS.UnitTests/Mock/Common/MockGVFSEnlistment.cs index 2292149b65..0df52b732e 100644 --- a/GVFS/GVFS.UnitTests/Mock/Common/MockGVFSEnlistment.cs +++ b/GVFS/GVFS.UnitTests/Mock/Common/MockGVFSEnlistment.cs @@ -17,8 +17,9 @@ public MockGVFSEnlistment() this.GitPackRoot = Path.Combine("mock:", "path", ".git", "objects", "pack"); } - public MockGVFSEnlistment(string enlistmentRoot, string repoUrl, string gitBinPath, MockGitProcess gitProcess) - : base(enlistmentRoot, repoUrl, gitBinPath, authentication: null) + public MockGVFSEnlistment(string enlistmentRoot, string repoUrl, string gitBinPath, + MockGitProcess gitProcess, GitAuthentication authentication = null) + : base(enlistmentRoot, repoUrl, gitBinPath, authentication) { this.gitProcess = gitProcess; } diff --git a/GVFS/GVFS.UnitTests/Mock/Common/MockTracer.cs b/GVFS/GVFS.UnitTests/Mock/Common/MockTracer.cs index 95f0681445..612cbea898 100644 --- a/GVFS/GVFS.UnitTests/Mock/Common/MockTracer.cs +++ b/GVFS/GVFS.UnitTests/Mock/Common/MockTracer.cs @@ -3,12 +3,14 @@ using System; using System.Collections.Generic; using System.Threading; +using System.Linq; namespace GVFS.UnitTests.Mock.Common { public class MockTracer : ITracer { private AutoResetEvent waitEvent; + private readonly object relatedEventsLock = new object(); public MockTracer() { @@ -52,28 +54,57 @@ public void WaitForRelatedEvent() this.waitEvent.WaitOne(); } - public void RelatedEvent(EventLevel error, string eventName, EventMetadata metadata) + public virtual void RelatedEvent(EventLevel error, string eventName, EventMetadata metadata) { - this.RelatedEventNames.Add(eventName); - this.RelatedEventLevels.Add(error); - this.RelatedEventKeywords.Add(Keywords.None); - this.RelatedEventMetadata.Add(metadata); - if (eventName == this.WaitRelatedEventName) + this.RecordEvent(error, eventName, metadata, Keywords.None); + } + + public virtual void RelatedEvent(EventLevel error, string eventName, EventMetadata metadata, Keywords keyword) + { + this.RecordEvent(error, eventName, metadata, keyword); + } + + public RecordedEvent[] SnapshotRelatedEvents() + { + lock (this.relatedEventsLock) { - this.waitEvent.Set(); + return this.RelatedEventNames.Select((name, index) => new RecordedEvent( + name, + this.RelatedEventLevels[index], + this.RelatedEventMetadata[index] == null ? null : new EventMetadata(this.RelatedEventMetadata[index]), + this.RelatedEventKeywords[index])).ToArray(); } } - public virtual void RelatedEvent(EventLevel error, string eventName, EventMetadata metadata, Keywords keyword) + private void RecordEvent(EventLevel level, string eventName, EventMetadata metadata, Keywords keyword) { - this.RelatedEventNames.Add(eventName); - this.RelatedEventLevels.Add(error); - this.RelatedEventKeywords.Add(keyword); - this.RelatedEventMetadata.Add(metadata); - if (eventName == this.WaitRelatedEventName) + lock (this.relatedEventsLock) { - this.waitEvent.Set(); + this.RelatedEventNames.Add(eventName); + this.RelatedEventLevels.Add(level); + this.RelatedEventKeywords.Add(keyword); + this.RelatedEventMetadata.Add(metadata); + if (eventName == this.WaitRelatedEventName) + { + this.waitEvent.Set(); + } + } + } + + public sealed class RecordedEvent + { + public RecordedEvent(string name, EventLevel level, EventMetadata metadata, Keywords keyword) + { + this.Name = name; + this.Level = level; + this.Metadata = metadata; + this.Keyword = keyword; } + + public string Name { get; } + public EventLevel Level { get; } + public EventMetadata Metadata { get; } + public Keywords Keyword { get; } } public void RelatedInfo(string message) diff --git a/GVFS/GVFS/CommandLine/DehydrateVerb.cs b/GVFS/GVFS/CommandLine/DehydrateVerb.cs index 3588fbe921..f3e7c6bef6 100644 --- a/GVFS/GVFS/CommandLine/DehydrateVerb.cs +++ b/GVFS/GVFS/CommandLine/DehydrateVerb.cs @@ -231,10 +231,10 @@ from a parent of the folders list. this.ReportErrorAndExit(tracer, error); } - RetryConfig.TryLoadFromGitConfig(tracer, enlistment, out RetryConfig retryConfig, out _); + RetryConfig retryConfig = RetryConfig.LoadFromGitConfig(tracer, enlistment); string errorMessage; - if (!this.TryAuthenticate(tracer, enlistment, out errorMessage)) + if (!this.TryAuthenticateAndQueryGVFSConfig(tracer, enlistment, retryConfig, out _, out errorMessage)) { this.ReportErrorAndExit(tracer, errorMessage); } diff --git a/GVFS/GVFS/CommandLine/GVFSVerb.cs b/GVFS/GVFS/CommandLine/GVFSVerb.cs index aef557e7de..d1a4348e1d 100644 --- a/GVFS/GVFS/CommandLine/GVFSVerb.cs +++ b/GVFS/GVFS/CommandLine/GVFSVerb.cs @@ -254,7 +254,7 @@ protected bool TryAuthenticateAndQueryGVFSConfig( string error = null; if (retryConfig == null) { - RetryConfig.TryLoadFromGitConfig(tracer, enlistment, out retryConfig, out _); + retryConfig = RetryConfig.LoadFromGitConfig(tracer, enlistment); } bool result = this.ShowStatusWhileRunning( @@ -321,7 +321,7 @@ protected void ReportErrorAndExit(ITracer tracer, string error, params object[] protected RetryConfig GetRetryConfig(ITracer tracer, GVFSEnlistment enlistment, TimeSpan? timeoutOverride = null) { - RetryConfig.TryLoadFromGitConfig(tracer, enlistment, out RetryConfig retryConfig, out _); + RetryConfig retryConfig = RetryConfig.LoadFromGitConfig(tracer, enlistment); if (timeoutOverride.HasValue) { @@ -1184,7 +1184,7 @@ private void EnsureLocalCacheIsHealthy( { if (retryConfig == null) { - RetryConfig.TryLoadFromGitConfig(tracer, enlistment, out retryConfig, out _); + retryConfig = RetryConfig.LoadFromGitConfig(tracer, enlistment); } serverGVFSConfig = this.QueryGVFSConfig(tracer, enlistment, retryConfig); diff --git a/docs/troubleshooting.md b/docs/troubleshooting.md index 9c09780a1f..a2b3e400fd 100644 --- a/docs/troubleshooting.md +++ b/docs/troubleshooting.md @@ -105,16 +105,30 @@ git config --global gvfs.read-timeout-seconds 120 Do not use this setting to limit the total download time. If the enlistment is mounted, remount it after a configuration change. -New clone, prefetch, cache-server, repair-authentication, and FastFetch operations -read the setting when they initialize their requests. +New clone, cache-server, repair-authentication, and FastFetch operations load the +settings during initialization. Non-offloaded prefetch also loads them in its CLI process. +If prefetch offload is enabled, prefetch uses the mount's startup configuration +and mount log. Remount the enlistment to change that configuration. All request initialization paths load the complete retry configuration. If a retry setting is invalid or unreadable, VFS for Git logs a warning and uses the default for that setting. Other valid retry settings remain active. Running mounts retain the configuration that they loaded at startup. Later retry-setting errors do not stop an existing mount. +Commands retain their explicit retry and header-timeout overrides. -Local GVFS logs contain `NetworkBodyProgress` reports every 30 seconds while a -response remains open. These reports also reach the configured telemetry pipe. +| Setting | Default | Configured values | +| --- | --- | --- | +| `gvfs.max-retries` | 6 | 0 through 2147483644 | +| `gvfs.timeout-seconds` | 30 seconds | 1 through 2147483 seconds | +| `gvfs.read-timeout-seconds` | 60 seconds | 0 through 2147483 seconds | + +Only the body-read setting uses zero to disable its deadline. + +Local GVFS logs contain `NetworkBodyProgress` reports that start 30 seconds after +the first body read. They stop at end-of-stream, timeout, cancellation, a read +failure, or response closure. These reports also reach the configured telemetry pipe. +Exact-length pack transfers do not always require an EOF read. Reports can +continue during pack finalization, with `ReadPending=false`. Fast transfers emit no additional progress reports. A slow transfer or a read failure also emits a final outcome, with `NetworkBodyReadTimeout` for an idle timeout. @@ -133,7 +147,7 @@ count, and the final success result. | `ElapsedMs` | Total time with the response open, including consumer work | | `ReadTimeMs`, `MaxReadWaitMs` | Total time in body reads and the longest read wait | | `ReadPending`, `CurrentReadWaitMs` | Whether a read is pending and its current wait | -| `MillisecondsSinceLastByte` | Time since the last successful nonempty read, including consumer work | +| `MillisecondsSinceLastByte` | Time since the last nonempty read, or response-stream creation before any bytes arrive | | `ReadTimeoutMs` | Configured read deadline in milliseconds, or -1 if disabled | | `HeaderWaitMs`, `ContentLength` | Header wait and expected body bytes, or -1 for an unknown length | | `ResponseId`, `RequestId` | Response identity and the request identity shared across retries | From f9db2e76a484be19e8b3c372d98d67b8fa7497a9 Mon Sep 17 00:00:00 2001 From: Tyrie Vella Date: Wed, 28 Oct 2026 15:49:35 -0700 Subject: [PATCH 3/4] fix: address review feedback - nonfatal body diagnostics Disable further response-body reports after an unexpected diagnostic failure. Attempt one warning through the tracer, then standard error if the tracer fails. Keep the read deadline, caller cancellation, and response cleanup active. Preserve the original read error when final diagnostics fail. Add unit tests for periodic and final diagnostic failures, report construction, warning fallback, listener failures, and continued reads. Assisted-by: GPT-6.1 Sol Signed-off-by: Tyrie Vella --- GVFS/GVFS.Common/Http/HttpResponseStream.cs | 125 +++++++++++---- .../Http/HttpResponseStreamTests.cs | 148 +++++++++++++++++- 2 files changed, 241 insertions(+), 32 deletions(-) diff --git a/GVFS/GVFS.Common/Http/HttpResponseStream.cs b/GVFS/GVFS.Common/Http/HttpResponseStream.cs index 226718e1b8..efa1b3a0d0 100644 --- a/GVFS/GVFS.Common/Http/HttpResponseStream.cs +++ b/GVFS/GVFS.Common/Http/HttpResponseStream.cs @@ -11,7 +11,6 @@ namespace GVFS.Common.Http { internal sealed class HttpResponseStream : Stream { - private const int FatalErrorExitCode = 1; internal const int DefaultProgressIntervalSeconds = 30; private const string ProgressEventName = "NetworkBodyProgress"; private const string TimeoutEventName = "NetworkBodyReadTimeout"; @@ -37,6 +36,7 @@ internal sealed class HttpResponseStream : Stream private double _lastProgressMilliseconds; private bool _reportedProgress; private int _reportingProgress; + private int _reportingDisabled; private volatile bool _disposed; private TransferOutcome _outcome; @@ -123,6 +123,7 @@ public override async ValueTask ReadAsync(Memory buffer, Cancellation cancellationToken, this._requestCancellationToken)) { + Exception? reportingError = null; lock (this._gate) { ObjectDisposedException.ThrowIf(this._disposed, this); @@ -138,12 +139,27 @@ public override async ValueTask ReadAsync(Memory buffer, Cancellation this._pendingRead = readCancellation; this._readStarted = Stopwatch.GetTimestamp(); - if (this._tracer != null && this._progressTimer == null && this._outcome == TransferOutcome.InProgress) + if (this._tracer != null && + this._progressTimer == null && + this._outcome == TransferOutcome.InProgress && + Volatile.Read(ref this._reportingDisabled) == 0) { - this._progressTimer = new Timer(this.ReportProgress, null, this._progressInterval, this._progressInterval); + try + { + this._progressTimer = new Timer(this.ReportProgress, null, this._progressInterval, this._progressInterval); + } + catch (Exception e) + { + reportingError = e; + } } } + if (reportingError != null) + { + this.DisableReporting(reportingError); + } + TransferOutcome outcome = TransferOutcome.InProgress; Exception? readError = null; readCancellation.CancelAfter(this._readTimeout); @@ -204,11 +220,11 @@ public override async ValueTask ReadAsync(Memory buffer, Cancellation this._pendingRead = null; if (outcome != TransferOutcome.InProgress) { - finalReport = this.Finish(outcome, readError); + finalReport = this.Finish(outcome, out reportingError, readError); } } - this.Trace(finalReport, outcome); + this.Trace(finalReport, outcome, reportingError); } } } @@ -226,6 +242,7 @@ protected override void Dispose(bool disposing) if (disposing) { EventMetadata? finalReport = null; + Exception? reportingError = null; bool disposeInner = false; try { @@ -238,7 +255,7 @@ protected override void Dispose(bool disposing) disposeInner = true; this._disposed = true; - finalReport = this.Finish(TransferOutcome.Closed); + finalReport = this.Finish(TransferOutcome.Closed, out reportingError); Timer? progressTimer = this._progressTimer; this._progressTimer = null; try @@ -261,7 +278,7 @@ protected override void Dispose(bool disposing) } finally { - this.Trace(finalReport, TransferOutcome.Closed); + this.Trace(finalReport, TransferOutcome.Closed, reportingError); } } } @@ -275,7 +292,8 @@ protected override void Dispose(bool disposing) private void ReportProgress(object? state) { - if (Interlocked.CompareExchange(ref this._reportingProgress, 1, 0) != 0) + if (Volatile.Read(ref this._reportingDisabled) != 0 || + Interlocked.CompareExchange(ref this._reportingProgress, 1, 0) != 0) { return; } @@ -285,7 +303,9 @@ private void ReportProgress(object? state) EventMetadata? report = null; lock (this._gate) { - if (!this._disposed && this._outcome == TransferOutcome.InProgress) + if (!this._disposed && + this._outcome == TransferOutcome.InProgress && + Volatile.Read(ref this._reportingDisabled) == 0) { this._reportedProgress = true; report = this.CreateReport(); @@ -296,16 +316,7 @@ private void ReportProgress(object? state) } catch (Exception e) { - try - { - this._tracer?.RelatedError( - new EventMetadata { { "Exception", e.ToString() } }, - "The response body progress report failed."); - } - finally - { - Environment.Exit(FatalErrorExitCode); - } + this.DisableReporting(e); } finally { @@ -313,31 +324,45 @@ private void ReportProgress(object? state) } } - private EventMetadata? Finish(TransferOutcome outcome, Exception? readError = null) + private EventMetadata? Finish(TransferOutcome outcome, out Exception? reportingError, Exception? readError = null) { + reportingError = null; if (this._outcome != TransferOutcome.InProgress) { return null; } this._outcome = outcome; - this._progressTimer?.Change(Timeout.InfiniteTimeSpan, Timeout.InfiniteTimeSpan); - if (this._reportedProgress || - this._elapsed.Elapsed >= this._progressInterval || - outcome == TransferOutcome.TimedOut || - outcome == TransferOutcome.ReadError || - outcome == TransferOutcome.Canceled || - (outcome == TransferOutcome.Closed && this._pendingRead != null)) + try { - return this.CreateReport(readError); + this._progressTimer?.Change(Timeout.InfiniteTimeSpan, Timeout.InfiniteTimeSpan); + if (Volatile.Read(ref this._reportingDisabled) == 0 && + (this._reportedProgress || + this._elapsed.Elapsed >= this._progressInterval || + outcome == TransferOutcome.TimedOut || + outcome == TransferOutcome.ReadError || + outcome == TransferOutcome.Canceled || + (outcome == TransferOutcome.Closed && this._pendingRead != null))) + { + return this.CreateReport(readError); + } + } + catch (Exception e) + { + reportingError = e; } return null; } - private void Trace(EventMetadata? report, TransferOutcome outcome) + private void Trace(EventMetadata? report, TransferOutcome outcome, Exception? reportingError = null) { - if (report == null || this._tracer == null) + if (reportingError != null) + { + this.DisableReporting(reportingError); + } + + if (report == null || this._tracer == null || Volatile.Read(ref this._reportingDisabled) != 0) { return; } @@ -359,6 +384,46 @@ private void Trace(EventMetadata? report, TransferOutcome outcome) // Maintenance responses can outlive the root tracer during unmount. return; } + catch (Exception e) + { + this.DisableReporting(e); + } + } + + private void DisableReporting(Exception error) + { + if (Interlocked.Exchange(ref this._reportingDisabled, 1) != 0) + { + return; + } + + Timer? timer; + lock (this._gate) + { + timer = this._progressTimer; + this._progressTimer = null; + } + + timer?.Dispose(); + const string Warning = "Response body diagnostics failed. Further reports for this response are disabled."; + try + { + this._tracer?.RelatedWarning( + new EventMetadata { { "ResponseId", this.ResponseId }, { "Exception", error.ToString() } }, + Warning, + Keywords.Network | Keywords.Telemetry); + } + catch (Exception) + { + try + { + Console.Error.WriteLine(Warning); + } + catch (Exception) + { + // A failed diagnostic sink must not interrupt the transfer. + } + } } private EventMetadata CreateReport(Exception? readError = null) diff --git a/GVFS/GVFS.UnitTests/Http/HttpResponseStreamTests.cs b/GVFS/GVFS.UnitTests/Http/HttpResponseStreamTests.cs index f8cbe48eb4..2eb95bc11e 100644 --- a/GVFS/GVFS.UnitTests/Http/HttpResponseStreamTests.cs +++ b/GVFS/GVFS.UnitTests/Http/HttpResponseStreamTests.cs @@ -6,6 +6,7 @@ using GVFS.UnitTests.Category; using GVFS.UnitTests.Mock.Common; using GVFS.UnitTests.Mock.Git; +using Moq; using NUnit.Framework; using System; using System.IO; @@ -836,7 +837,7 @@ public void RawResponseStreamTracksReadFailuresAndIdentity() [TestCase] [Category(CategoryConstants.ExceptionExpected)] - public void ResponseDisposalReleasesPermitWhenFinalDiagnosticsThrow() + public void ResponseDisposalReleasesPermitWhenFinalDiagnosticsFail() { using CallbackTracer tracer = new CallbackTracer(); tracer.Callback = name => @@ -853,10 +854,153 @@ public void ResponseDisposalReleasesPermitWhenFinalDiagnosticsThrow() HttpStatusCode.OK, "application/json", stream, new HttpResponseMessage(), () => ++releases); stream.ReadByte().ShouldEqual(1); Thread.Sleep(40); - Assert.Throws(() => response.Dispose()); + response.Dispose(); innerStream.CanRead.ShouldEqual(false); response.Dispose(); releases.ShouldEqual(1); + tracer.RelatedWarningEvents.Count.ShouldEqual(1); + } + + [TestCase(false)] + [TestCase(true)] + [Category(CategoryConstants.ExceptionExpected)] + public void DiagnosticFailureDoesNotReplaceTheReadTimeout(bool failReportConstruction) + { + Mock tracer = new Mock(); + using ManualResetEventSlim warningReported = new ManualResetEventSlim(); + int reports = 0; + EventMetadata warningMetadata = null; + string warningMessage = null; + tracer.Setup(item => item.RelatedEvent( + It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny())) + .Callback(() => + { + Interlocked.Increment(ref reports); + throw new InvalidOperationException("diagnostic failure"); + }); + tracer.Setup(item => item.RelatedWarning( + It.IsAny(), It.IsAny(), It.IsAny())) + .Callback((metadata, message, keyword) => + { + warningMetadata = metadata; + warningMessage = message; + warningReported.Set(); + }); + + using HttpResponseStream stream = new HttpResponseStream( + new BlockingReadStream(), TimeSpan.FromMilliseconds(200), CancellationToken.None, tracer.Object, + failReportConstruction ? new EventMetadata { { "ResponseId", "duplicate" } } : null, + TimeSpan.FromMilliseconds(20)); + IOException error = Assert.Throws(() => stream.ReadByte()); + error.Message.ShouldContain("No response body data arrived"); + stream.ReadFailed.ShouldEqual(true); + warningReported.Wait(TimeSpan.FromSeconds(5)).ShouldEqual(true); + warningMetadata["ResponseId"].ShouldEqual(stream.ResponseId); + warningMessage.ShouldContain("Further reports for this response are disabled."); + reports.ShouldEqual(failReportConstruction ? 0 : 1); + tracer.Verify(item => item.RelatedWarning( + It.IsAny(), It.IsAny(), It.IsAny()), Times.Once); + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void DiagnosticFailureDoesNotStopSubsequentReads() + { + Mock tracer = new Mock(); + using ManualResetEventSlim warningReported = new ManualResetEventSlim(); + tracer.Setup(item => item.RelatedEvent( + It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny())) + .Throws(new InvalidOperationException("diagnostic failure")); + tracer.Setup(item => item.RelatedWarning( + It.IsAny(), It.IsAny(), It.IsAny())) + .Callback(() => warningReported.Set()); + using HttpResponseStream stream = new HttpResponseStream( + new MemoryStream(new byte[] { 1, 2 }), TimeSpan.FromSeconds(1), CancellationToken.None, + tracer.Object, progressInterval: TimeSpan.FromMilliseconds(20)); + stream.ReadByte().ShouldEqual(1); + warningReported.Wait(TimeSpan.FromSeconds(5)).ShouldEqual(true); + stream.ReadByte().ShouldEqual(2); + stream.ReadByte().ShouldEqual(-1); + stream.ReadFailed.ShouldEqual(false); + tracer.Verify(item => item.RelatedEvent( + It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny()), Times.Once); + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void FinalReportConstructionFailurePreservesTheReadError() + { + using MockTracer tracer = new MockTracer(); + using HttpResponseStream stream = new HttpResponseStream( + new FailingReadStream(), TimeSpan.FromSeconds(1), CancellationToken.None, tracer, + new EventMetadata { { "ResponseId", "duplicate" } }); + Assert.Throws(() => stream.ReadByte()).Message.ShouldEqual("read failed"); + tracer.RelatedWarningEvents.Count.ShouldEqual(1); + tracer.SnapshotRelatedEvents().Length.ShouldEqual(0); + } + + [TestCase] + [NonParallelizable] + [Category(CategoryConstants.ExceptionExpected)] + public void DiagnosticWarningFailureUsesStandardErrorWithoutChangingTheRead() + { + Mock tracer = new Mock(); + tracer.Setup(item => item.RelatedEvent( + It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny())) + .Throws(new InvalidOperationException("diagnostic failure")); + tracer.Setup(item => item.RelatedWarning( + It.IsAny(), It.IsAny(), It.IsAny())) + .Throws(new IOException("warning failure")); + TextWriter previousError = Console.Error; + using StringWriter errorOutput = new StringWriter(); + try + { + Console.SetError(errorOutput); + using HttpResponseStream stream = new HttpResponseStream( + new FailingReadStream(), TimeSpan.FromSeconds(1), CancellationToken.None, tracer.Object); + Assert.Throws(() => stream.ReadByte()).Message.ShouldEqual("read failed"); + errorOutput.ToString().ShouldContain("Response body diagnostics failed."); + } + finally + { + Console.SetError(previousError); + } + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void FailedDiagnosticListenerDoesNotInterruptTheTransfer() + { + using JsonTracer tracer = new JsonTracer(GVFSConstants.GVFSEtwProviderName, "body-test", disableTelemetry: true); + using ManualResetEventSlim progress = new ManualResetEventSlim(); + tracer.AddEventListener(new FailingBodyListener(tracer, progress)); + using HttpResponseStream stream = new HttpResponseStream( + new MemoryStream(new byte[] { 1 }), TimeSpan.FromSeconds(1), CancellationToken.None, + tracer, progressInterval: TimeSpan.FromMilliseconds(20)); + stream.ReadByte().ShouldEqual(1); + progress.Wait(TimeSpan.FromSeconds(5)).ShouldEqual(true); + stream.ReadByte().ShouldEqual(-1); + stream.ReadFailed.ShouldEqual(false); + } + + private sealed class FailingBodyListener : GVFS.Common.Tracing.EventListener + { + private readonly ManualResetEventSlim progress; + + public FailingBodyListener(IEventListenerEventSink sink, ManualResetEventSlim progress) + : base(EventLevel.Informational, Keywords.Any, sink) + { + this.progress = progress; + } + + protected override void RecordMessageInternal(TraceEventMessage message) + { + if (message.EventName == "NetworkBodyProgress") + { + this.progress.Set(); + throw new IOException("diagnostic output failed"); + } + } } [TestCase] From 14b635f4a1f134a46ec7ff8f3d39409c65cc4da2 Mon Sep 17 00:00:00 2001 From: Tyrie Vella Date: Wed, 28 Oct 2026 15:49:52 -0700 Subject: [PATCH 4/4] fix: address review feedback - distinguish prefetch-only clone failure Return exit code 12 when clone succeeds but synchronous prefetch fails. Print a command that retries only prefetch. Preserve the failure code when a requested mount fails. Keep per-request retry budgets and the existing background-prefetch behavior. Add functional tests for stalled clone requests, retry recovery and exhaustion, the partial-success result, and mount-failure precedence. Document clone retry configuration, prefetch recovery, and best-effort body diagnostics. Assisted-by: GPT-6.1 Sol Signed-off-by: Tyrie Vella --- GVFS/GVFS.Common/ReturnCode.cs | 1 + .../Tests/EnlistmentPerFixture/CloneTests.cs | 253 ++++++++++++++++++ GVFS/GVFS/CommandLine/CloneVerb.cs | 11 +- docs/troubleshooting.md | 17 ++ 4 files changed, 279 insertions(+), 3 deletions(-) diff --git a/GVFS/GVFS.Common/ReturnCode.cs b/GVFS/GVFS.Common/ReturnCode.cs index 31842f396f..1df0e9bb4a 100644 --- a/GVFS/GVFS.Common/ReturnCode.cs +++ b/GVFS/GVFS.Common/ReturnCode.cs @@ -14,5 +14,6 @@ public enum ReturnCode AuthenticationError = 9, CredentialTimeout = 10, RemoteGvfsConfigError = 11, + CloneSucceededPrefetchFailed = 12, } } diff --git a/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/CloneTests.cs b/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/CloneTests.cs index b554cfb591..082be10ed6 100644 --- a/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/CloneTests.cs +++ b/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/CloneTests.cs @@ -6,6 +6,12 @@ using System; using System.Diagnostics; using System.IO; +using System.Linq; +using System.Net; +using System.Net.Sockets; +using System.Text; +using System.Threading; +using System.Threading.Tasks; namespace GVFS.FunctionalTests.Tests.EnlistmentPerFixture { @@ -88,4 +94,251 @@ private void SubfolderCloneShouldFail() result.Output.ShouldContain("You can't clone inside an existing GVFS repo"); } } + + [TestFixture] + [NonParallelizable] + public class CloneNetworkTests + { + private string seedRoot; + private string localCacheRoot; + + [OneTimeSetUp] + public void CreateObjectCache() + { + this.seedRoot = GVFSFunctionalTestEnlistment.GetUniqueEnlistmentRoot(); + Directory.CreateDirectory(this.seedRoot); + this.localCacheRoot = Path.Combine(this.seedRoot, "cache"); + ProcessStartInfo process = this.CreateCloneProcess( + this.seedRoot, GVFSTestConfig.RepoToClone, Path.Combine(this.seedRoot, "seed"), + "--branch", Properties.Settings.Default.Commitish, + "--local-cache-path", this.localCacheRoot, "--no-mount", "--no-prefetch"); + ProcessResult result = ProcessHelper.Run(process, timeoutMs: 75000); + result.ExitCode.ShouldEqual(0, result.Output + result.Errors); + } + + [OneTimeTearDown] + public void DeleteObjectCache() + { + RepositoryHelpers.DeleteTestDirectory(this.seedRoot); + } + + [TestCase(false)] + [TestCase(true)] + public async Task CloneRetriesStalledInfoRefsWithinTheRequestBudget(bool recover) + { + string root = GVFSFunctionalTestEnlistment.GetUniqueEnlistmentRoot(); + Directory.CreateDirectory(root); + using CancellationTokenSource cancellation = new CancellationTokenSource(TimeSpan.FromSeconds(45)); + using TcpListener listener = new TcpListener(IPAddress.Loopback, 0); + listener.Start(); + string endpoint = $"http://127.0.0.1:{((IPEndPoint)listener.LocalEndpoint).Port}"; + int infoRefsRequests = 0; + Task server = ServeCloneRequests(listener, cancellation.Token, path => + { + if (path.StartsWith("/gvfs/config", StringComparison.Ordinal)) + { + return ("application/json", Encoding.UTF8.GetBytes("{}")); + } + + path.ShouldContain("/info/refs"); + ++infoRefsRequests; + string reference = "1111111111111111111111111111111111111111 refs/heads/other\n"; + return ("application/x-git-upload-pack-advertisement", + recover && infoRefsRequests > 1 + ? Encoding.ASCII.GetBytes((reference.Length + 4).ToString("x4") + reference) + : null); + }); + try + { + ProcessStartInfo process = this.CreateCloneProcess( + root, endpoint, Path.Combine(root, "clone"), "--branch", "missing", "--no-mount", "--no-prefetch", + "--cache-server-url", "None"); + ProcessResult result = await Task.Run(() => ProcessHelper.Run(process, timeoutMs: 30000)); + result.ExitCode.ShouldEqual(3, result.Output + result.Errors); + string log = File.ReadAllText(Directory.GetFiles( + Path.Combine(root, "clone", ".gvfs", "logs"), "gvfs_clone_*.log").Single()); + log.ShouldContain("NetworkBodyReadTimeout"); + log.ShouldContain("\"ReadTimeoutMs\":1000"); + log.ShouldContain("\"AttemptNumber\":1"); + log.ShouldContain("\"WillRetry\":true"); + infoRefsRequests.ShouldEqual(2); + if (recover) + { + result.Output.ShouldContain("Remote branch missing not found"); + } + else + { + log.ShouldContain("\"AttemptNumber\":2"); + log.ShouldContain("\"WillRetry\":false"); + } + } + finally + { + cancellation.Cancel(); + listener.Stop(); + try + { + await ObserveCloneServer(server, cancellation.Token); + } + finally + { + RepositoryHelpers.DeleteTestDirectory(root); + } + } + } + + [TestCase(false)] + [TestCase(true)] + public async Task CloneDistinguishesPrefetchFailureFromMountFailure(bool failMount) + { + string root = GVFSFunctionalTestEnlistment.GetUniqueEnlistmentRoot(); + Directory.CreateDirectory(root); + string destination = Path.Combine(root, "clone"); + using CancellationTokenSource cancellation = new CancellationTokenSource(TimeSpan.FromSeconds(90)); + using TcpListener listener = new TcpListener(IPAddress.Loopback, 0); + listener.Start(); + string endpoint = $"http://127.0.0.1:{((IPEndPoint)listener.LocalEndpoint).Port}"; + int prefetchRequests = 0; + Task server = ServeCloneRequests(listener, cancellation.Token, path => + { + path.ShouldContain("/gvfs/prefetch"); + ++prefetchRequests; + if (failMount && prefetchRequests == 1) + { + GVFSHelpers.SaveDiskLayoutVersion(Path.Combine(destination, ".gvfs"), "999", "0"); + } + + return ("application/x-gvfs-timestamped-packfiles-indexes", null); + }); + try + { + ProcessStartInfo process = this.CreateCloneProcess( + root, GVFSTestConfig.RepoToClone, destination, + "--branch", Properties.Settings.Default.Commitish, + "--local-cache-path", this.localCacheRoot, + "--cache-server-url", endpoint); + if (!failMount) + { + process.ArgumentList.Add("--no-mount"); + } + + ProcessResult result = await Task.Run(() => ProcessHelper.Run(process, timeoutMs: 75000)); + result.ExitCode.ShouldEqual(failMount ? 3 : 12, result.Output + result.Errors); + result.Output.ShouldContain("Clone completed, but prefetch failed"); + result.Output.ShouldContain("Run 'gvfs prefetch --commits'"); + if (failMount) + { + result.Output.ShouldContain("disk layout"); + } + + (prefetchRequests > 0).ShouldEqual(true); + ProcessResult head = GitProcess.InvokeProcess(Path.Combine(destination, "src"), "rev-parse --verify HEAD"); + head.ExitCode.ShouldEqual(0, head.Errors); + head.Output.Trim().Length.ShouldEqual(40); + if (!failMount) + { + string prefetchLog = File.ReadAllText(Directory.GetFiles( + Path.Combine(destination, ".gvfs", "logs"), "gvfs_prefetch_*.log").Single()); + prefetchLog.ShouldContain("NetworkBodyReadTimeout"); + } + } + finally + { + cancellation.Cancel(); + listener.Stop(); + try + { + await ObserveCloneServer(server, cancellation.Token); + } + finally + { + new GVFSProcess(GVFSTestConfig.PathToGVFS, destination, this.localCacheRoot).Unmount(); + RepositoryHelpers.DeleteTestDirectory(root); + } + } + } + + private ProcessStartInfo CreateCloneProcess(string root, string repository, string destination, params string[] options) + { + string config = Path.Combine(root, "global.config"); + string originalGlobal = Environment.GetEnvironmentVariable("GIT_CONFIG_GLOBAL") ?? + Path.Combine(Environment.GetFolderPath(Environment.SpecialFolder.UserProfile), ".gitconfig"); + GitProcess.InvokeProcess(root, $"config --file \"{config}\" include.path \"{originalGlobal}\"") + .ExitCode.ShouldEqual(0); + foreach (string setting in new[] + { + "gvfs.read-timeout-seconds 1", + "gvfs.max-retries 1", + "gvfs.trust-pack-indexes true", + "gvfs.prefetch-offload false", + }) + { + GitProcess.InvokeProcess(root, $"config --file \"{config}\" {setting}").ExitCode.ShouldEqual(0); + } + + ProcessStartInfo process = new ProcessStartInfo(GVFSTestConfig.PathToGVFS) + { + UseShellExecute = false, + RedirectStandardOutput = true, + RedirectStandardError = true, + WorkingDirectory = root, + }; + process.Environment["GIT_CONFIG_GLOBAL"] = config; + process.ArgumentList.Add("clone"); + process.ArgumentList.Add(repository); + process.ArgumentList.Add(destination); + foreach (string option in options) + { + process.ArgumentList.Add(option); + } + + return process; + } + + private static async Task ServeCloneRequests( + TcpListener listener, + CancellationToken cancellationToken, + Func respond) + { + while (!cancellationToken.IsCancellationRequested) + { + using TcpClient client = await listener.AcceptTcpClientAsync(cancellationToken); + using NetworkStream stream = client.GetStream(); + string request; + using (StreamReader reader = new StreamReader(stream, Encoding.ASCII, false, 1024, leaveOpen: true)) + { + request = await reader.ReadLineAsync(cancellationToken); + string line; + do + { + line = await reader.ReadLineAsync(cancellationToken); + } + while (!string.IsNullOrEmpty(line)); + } + + (string contentType, byte[] body) = respond(request.Split(' ')[1]); + bool stall = body == null; + byte[] data = body ?? new byte[] { (byte)'G' }; + byte[] headers = Encoding.ASCII.GetBytes( + $"HTTP/1.1 200 OK\r\nConnection: close\r\nContent-Type: {contentType}\r\nContent-Length: {(stall ? 1024 : data.Length)}\r\n\r\n"); + await stream.WriteAsync(headers.AsMemory(), cancellationToken); + await stream.WriteAsync(data.AsMemory(), cancellationToken); + if (stall) + { + (await stream.ReadAsync(new byte[1].AsMemory(), cancellationToken)).ShouldEqual(0); + } + } + } + + private static async Task ObserveCloneServer(Task server, CancellationToken cancellationToken) + { + try + { + await server.WaitAsync(TimeSpan.FromSeconds(5)); + } + catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested) + { + } + } + } } diff --git a/GVFS/GVFS/CommandLine/CloneVerb.cs b/GVFS/GVFS/CommandLine/CloneVerb.cs index 2e9bb52762..fda0151823 100644 --- a/GVFS/GVFS/CommandLine/CloneVerb.cs +++ b/GVFS/GVFS/CommandLine/CloneVerb.cs @@ -333,8 +333,9 @@ public override void Execute() if (result != ReturnCode.Success) { - this.Output.WriteLine("\r\nError during prefetch @ {0}", fullEnlistmentRootPathParameter); - exitCode = (int)result; + this.Output.WriteLine("\r\nClone completed, but prefetch failed @ {0}", fullEnlistmentRootPathParameter); + this.Output.WriteLine("Run 'gvfs prefetch --commits' from '{0}' to retry prefetch.", fullEnlistmentRootPathParameter); + exitCode = (int)ReturnCode.CloneSucceededPrefetchFailed; } } else @@ -367,7 +368,7 @@ public override void Execute() } else { - this.Execute( + ReturnCode mountResult = this.Execute( enlistment, verb => { @@ -376,6 +377,10 @@ public override void Execute() verb.ResolvedCacheServer = cacheServer; verb.DownloadedGVFSConfig = serverGVFSConfig; }); + if (mountResult != ReturnCode.Success) + { + exitCode = (int)mountResult; + } } } else diff --git a/docs/troubleshooting.md b/docs/troubleshooting.md index a2b3e400fd..ae9f2a0b10 100644 --- a/docs/troubleshooting.md +++ b/docs/troubleshooting.md @@ -124,6 +124,18 @@ Commands retain their explicit retry and header-timeout overrides. Only the body-read setting uses zero to disable its deadline. +The retry configuration also applies to the network steps within `gvfs clone`. +Each request uses the existing retry policy. Clone does not add a second retry loop. + +If clone completes but synchronous prefetch fails, `gvfs clone` returns exit code 12. +The enlistment remains available. A requested mount failure takes precedence and returns its own failure code. + +From the enlistment directory, run `gvfs prefetch --commits` to retry only prefetch. +This command retains completed packs. Do not delete the enlistment or repeat clone for this result. + +The background-prefetch path still returns success after it starts prefetch. +That result does not mean that background prefetch completed. + Local GVFS logs contain `NetworkBodyProgress` reports that start 30 seconds after the first body read. They stop at end-of-stream, timeout, cancellation, a read failure, or response closure. These reports also reach the configured telemetry pipe. @@ -161,6 +173,11 @@ This wait also includes managed scheduling delay. It does not prove that the cac When `ReadPending` is false, a pause occurs in the consumer rather than in a network read. Response closure alone does not prove that the client consumed the complete body. +Response-body diagnostics are best-effort. An unexpected diagnostic failure disables further reports for that response, but does not stop the transfer. +The client attempts one warning through the tracer. +If the tracer fails, the client attempts a fixed warning through standard error. +The read deadline, cancellation, and response cleanup remain active. + ### TRY THIS FIRST: `gvfs repair` Some known issues can get your enlistment into a bad state. Running