diff --git a/GVFS/FastFetch/FastFetchVerb.cs b/GVFS/FastFetch/FastFetchVerb.cs index cf6add3aad..379cf81805 100644 --- a/GVFS/FastFetch/FastFetchVerb.cs +++ b/GVFS/FastFetch/FastFetchVerb.cs @@ -252,14 +252,18 @@ 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 retryConfig = new RetryConfig(this.MaxAttempts, TimeSpan.FromMinutes(RetryConfig.FetchAndCloneTimeoutMinutes)); + 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..c24db57281 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 retryConfig = RetryConfig.LoadFromGitConfig(tracer, enlistment); + // 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..26f4c3d298 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,11 +170,10 @@ 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, - 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( @@ -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 }, @@ -365,6 +367,11 @@ public virtual bool TryWriteTempFile( this.CleanupTempFile(this.Tracer, tempFilePath); + if (ex is OperationCanceledException) + { + throw; + } + if (tracer != null) { EventMetadata metadata = CreateEventMetadata(ex); @@ -715,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, @@ -741,106 +749,130 @@ 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; + bool responseLoopExitedNormally = false; + 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["RequestId"] = requestId; + 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) when (!(e is OperationCanceledException)) { - 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; + 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 - .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..0f9b66aa80 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,47 @@ 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(); + string bodyReadFailure = null; + 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); + bodyReadFailure = "The response body read failed: " + (e.InnerException?.Message ?? e.Message); + errorMessage = bodyReadFailure; + } int statusInt = (int)response.StatusCode; bool shouldRetry = ShouldRetry(response.StatusCode); @@ -231,6 +269,10 @@ protected GitEndPointResponseData SendRequest( { shouldRetry = false; errorMessage = "Anonymous request was rejected with a 401"; + if (bodyReadFailure != null) + { + errorMessage += ". " + bodyReadFailure; + } } else if (ShouldRejectCredentials(response.StatusCode, errorMessage)) { @@ -294,17 +336,28 @@ 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 + { + this.Tracer.RelatedEvent(EventLevel.Informational, "NetworkResponse", responseMetadata); + } + catch { - // If gitEndPointResponseData is null there was an unhandled exception - if (response != null) + gitEndPointResponseData?.Dispose(); + throw; + } + finally + { + if (gitEndPointResponseData == null) { - response.Dispose(); + try + { + response?.Dispose(); + } + finally + { + availableConnections.Release(); + } } - - availableConnections.Release(); } } @@ -383,6 +436,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..efa1b3a0d0 --- /dev/null +++ b/GVFS/GVFS.Common/Http/HttpResponseStream.cs @@ -0,0 +1,458 @@ +#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 + { + 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 int _reportingDisabled; + 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)) + { + Exception? reportingError = null; + 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 && + Volatile.Read(ref this._reportingDisabled) == 0) + { + 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); + 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, out reportingError, readError); + } + } + + this.Trace(finalReport, outcome, reportingError); + } + } + } + + 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; + Exception? reportingError = null; + bool disposeInner = false; + try + { + lock (this._gate) + { + if (this._disposed) + { + return; + } + + disposeInner = true; + this._disposed = true; + finalReport = this.Finish(TransferOutcome.Closed, out reportingError); + 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, reportingError); + } + } + } + } + } + finally + { + base.Dispose(disposing); + } + } + + private void ReportProgress(object? state) + { + if (Volatile.Read(ref this._reportingDisabled) != 0 || + Interlocked.CompareExchange(ref this._reportingProgress, 1, 0) != 0) + { + return; + } + + try + { + EventMetadata? report = null; + lock (this._gate) + { + if (!this._disposed && + this._outcome == TransferOutcome.InProgress && + Volatile.Read(ref this._reportingDisabled) == 0) + { + this._reportedProgress = true; + report = this.CreateReport(); + } + } + + this.Trace(report, TransferOutcome.InProgress); + } + catch (Exception e) + { + this.DisableReporting(e); + } + finally + { + Volatile.Write(ref this._reportingProgress, 0); + } + } + + private EventMetadata? Finish(TransferOutcome outcome, out Exception? reportingError, Exception? readError = null) + { + reportingError = null; + if (this._outcome != TransferOutcome.InProgress) + { + return null; + } + + this._outcome = outcome; + try + { + 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, Exception? reportingError = null) + { + if (reportingError != null) + { + this.DisableReporting(reportingError); + } + + if (report == null || this._tracer == null || Volatile.Read(ref this._reportingDisabled) != 0) + { + return; + } + + 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; + } + 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) + { + 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..7de0f1a617 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,14 @@ 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; + // 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); @@ -28,7 +32,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 +40,32 @@ public int MaxAttempts public TimeSpan Timeout { get; set; } - public static bool TryLoadFromGitConfig(ITracer tracer, Enlistment enlistment, out RetryConfig retryConfig, out string error) + public TimeSpan ReadTimeout { get; set; } = TimeSpan.FromSeconds(DefaultReadTimeoutSeconds); + + public static RetryConfig LoadFromGitConfig(ITracer tracer, Enlistment enlistment) { - return TryLoadFromGitConfig(tracer, new GitProcess(enlistment), out retryConfig, out error); + ArgumentNullException.ThrowIfNull(enlistment); + return LoadFromGitConfig(tracer, enlistment.CreateGitProcess()); } - public static bool TryLoadFromGitConfig(ITracer tracer, GitProcess git, out RetryConfig retryConfig, out string error) + /// + /// Invalid or unreadable retry settings use defaults and emit warnings. + /// + public static RetryConfig LoadFromGitConfig(ITracer tracer, GitProcess git) { - 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)) + 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 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), + }; if (tracer != null) { @@ -91,48 +76,53 @@ 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" } }); } - return true; + return retryConfig; } - 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.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.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/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.FunctionalTests/Tests/EnlistmentPerFixture/PrefetchVerbTests.cs b/GVFS/GVFS.FunctionalTests/Tests/EnlistmentPerFixture/PrefetchVerbTests.cs index 34784e96b8..2df774bdef 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,177 @@ 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", + "gvfs.prefetch-offload", + }; + 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"); + this.SetLocalConfig(keys[4], "false"); + + 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() + { + 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 + { + this.SetLocalConfig("gvfs.prefetch-offload", "false"); + foreach (string key in retryKeys) + { + 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 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(); + } + } + } + + 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..e3ffd3b2b1 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 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 65145acba5..d3831390d3 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 retryConfig = RetryConfig.LoadFromGitConfig(this.Context.Tracer, this.Context.Enlistment); 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..ad619d3547 100644 --- a/GVFS/GVFS.UnitTests/Common/RetryConfigTests.cs +++ b/GVFS/GVFS.UnitTests/Common/RetryConfigTests.cs @@ -1,111 +1,250 @@ 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; 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(GitProcess.Result.SuccessCode)] + [TestCase(GitProcess.Result.GenericFailureCode)] + public void MissingOrBlankSettingsUseDefaultsWithoutWarnings(int exitCode) + { + 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 config = RetryConfig.LoadFromGitConfig(tracer, git); + 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 TryLoadConfigFailsWhenGitFailsToReadConfig() + public void CompleteLoaderReadsAllSettings() + { + using MockTracer tracer = new MockTracer(); + MockGitProcess git = CreateGitProcess(); + RetryConfig config = RetryConfig.LoadFromGitConfig(tracer, git); + 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("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)] + [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) + { + using MockTracer tracer = new MockTracer(); + MockGitProcess git = CreateGitProcess(); + git.SetExpectedCommandResult("config " + key, + () => new GitProcess.Result(value, string.Empty, GitProcess.Result.SuccessCode)); + + 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)); + 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) { - 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 = CreateGitProcess(); + git.SetExpectedCommandResult("config gvfs.read-timeout-seconds", + () => new GitProcess.Result(value, string.Empty, GitProcess.Result.SuccessCode)); + RetryConfig config = RetryConfig.LoadFromGitConfig(tracer, git); + config.ReadTimeout.ShouldEqual(TimeSpan.FromMilliseconds(expectedMilliseconds)); + config.MaxRetries.ShouldEqual(9); + config.Timeout.ShouldEqual(TimeSpan.FromSeconds(45)); + tracer.RelatedWarningEvents.Count.ShouldEqual(0); } [TestCase] - public void TryLoadConfigUsesDefaultValuesWhenEntriesNotInConfig() + public void ReadFailuresUseDefaultsWithoutAborting() + { + 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 config = RetryConfig.LoadFromGitConfig(tracer, git); + 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)] + [NUnit.Framework.Category(CategoryConstants.ExceptionExpected)] + public void ConfigReadExceptionsUseDefaultsAndKeepTheExceptionInDiagnostics(bool processError) { - 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); - error.ShouldEqual(string.Empty); - config.MaxRetries.ShouldEqual(RetryConfig.DefaultMaxRetries); - config.MaxAttempts.ShouldEqual(config.MaxRetries + 1); - config.Timeout.ShouldEqual(TimeSpan.FromSeconds(RetryConfig.DefaultTimeoutSeconds)); + using MockTracer tracer = new MockTracer(); + MockGitProcess git = CreateGitProcess(new ThrowingGitProcess(processError)); + RetryConfig config = RetryConfig.LoadFromGitConfig(tracer, git); + 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 TryLoadConfigUsesDefaultValuesWhenEntriesAreBlank() + public void LaterInvalidSettingsDoNotMutateAnExistingConfiguration() { - 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); - error.ShouldEqual(string.Empty); - config.MaxRetries.ShouldEqual(RetryConfig.DefaultMaxRetries); - config.MaxAttempts.ShouldEqual(config.MaxRetries + 1); - config.Timeout.ShouldEqual(TimeSpan.FromSeconds(RetryConfig.DefaultTimeoutSeconds)); + using MockTracer tracer = new MockTracer(); + MockGitProcess git = CreateGitProcess(); + RetryConfig existing = RetryConfig.LoadFromGitConfig(tracer, git); + git.SetExpectedCommandResult("config gvfs.read-timeout-seconds", + () => new GitProcess.Result("invalid", string.Empty, GitProcess.Result.SuccessCode)); + + RetryConfig reloaded = RetryConfig.LoadFromGitConfig(tracer, git); + 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 TryLoadConfigEnforcesMinimumValuesOnMaxRetries() + public void CommandOverridesDoNotDiscardLoadedReadTimeout() { - 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(); + 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 TryLoadConfigEnforcesMinimumValuesOnTimeout() + public void LargestAcceptedValuesDoNotOverflowConsumerArithmetic() { - 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(); + 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] - public void TryLoadConfigUsesConfiguredValues() + [NUnit.Framework.Category(CategoryConstants.ExceptionExpected)] + public void CompleteLoaderRejectsMissingDependencies() { - int maxRetries = RetryConfig.DefaultMaxRetries + 1; - int timeoutSeconds = RetryConfig.DefaultTimeoutSeconds + 1; - - 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)); - - 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)); + 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(); + 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)); + } + + 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/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 78236a37bc..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; @@ -14,6 +15,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 +188,229 @@ 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["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")); + EventMetadata stop = activity.StopMetadata.Single(); + 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] + 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); + } + + [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(); + 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, + new HttpResponseStream(this.Streams.Dequeue(), this.RetryConfig.ReadTimeout, + cancellationToken, this.Tracer, new EventMetadata { { "RequestId", requestId } }), + 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..2eb95bc11e --- /dev/null +++ b/GVFS/GVFS.UnitTests/Http/HttpResponseStreamTests.cs @@ -0,0 +1,1163 @@ +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 Moq; +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] + [Category(CategoryConstants.ExceptionExpected)] + 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] + [Category(CategoryConstants.ExceptionExpected)] + public void ReadByteTimesOut() + { + using (HttpResponseStream stream = CreateStream(new BlockingReadStream())) + { + Assert.Throws(() => stream.ReadByte()); + stream.ReadFailed.ShouldEqual(true); + } + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + public void SpanReadTimesOut() + { + using (HttpResponseStream stream = CreateStream(new BlockingReadStream())) + { + Assert.Throws(() => stream.Read(new byte[8].AsSpan()).ShouldEqual(0)); + stream.ReadFailed.ShouldEqual(true); + } + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + 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] + [Category(CategoryConstants.ExceptionExpected)] + 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.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); + } + } + + [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.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(); + 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); + LastBodyEvent(tracer, "Canceled").Level.ShouldEqual(EventLevel.Informational); + } + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + 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.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(); + using (HttpResponseStream stream = CreateStream(new BlockingReadStream(), tracer)) + { + Assert.ThrowsAsync( + async () => await stream.ReadAsync(new byte[8].AsMemory()).AsTask().WaitAsync(TimeSpan.FromSeconds(5))); + 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); + metadata["RequestId"].ShouldEqual(42L); + metadata["CacheName"].ShouldEqual("test-cache"); + metadata["RequestAuthority"].ShouldEqual("cache.example:443"); + } + + EventMetadata timeout = LastBodyEvent(tracer, "TimedOut").Metadata; + timeout["Outcome"].ShouldEqual("TimedOut"); + timeout["BytesRead"].ShouldEqual(0L); + LastBodyEvent(tracer, "TimedOut").Level.ShouldEqual(EventLevel.Warning); + ((double)timeout["MaxReadWaitMs"] >= 200).ShouldEqual(true); + ((double)timeout["ReadTimeMs"] >= 200).ShouldEqual(true); + records.ShouldContain( + record => (record.Keyword & Keywords.Telemetry) == Keywords.Telemetry); + } + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + 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 = LastBodyEvent(tracer, "TimedOut").Metadata; + 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(); + long terminalSequence = (long)LastBodyEvent(tracer, readToEnd ? "Completed" : "Closed").Metadata["SampleSequence"]; + await Task.Delay(120); + tracer.SnapshotRelatedEvents().Max(record => (long)record.Metadata["SampleSequence"]) + .ShouldEqual(terminalSequence); + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + 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.SnapshotRelatedEvents().Length.ShouldEqual(0); + } + + [TestCase] + [Category(CategoryConstants.ExceptionExpected)] + 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); + LastBodyEvent(tracer, "TimedOut").Name.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)] + [Category(CategoryConstants.ExceptionExpected)] + 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)LastBodyEvent(tracer, "TimedOut").Metadata["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); + } + } + + EventMetadata timeout = LastBodyEvent(tracer, "TimedOut").Metadata; + 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] + [Category(CategoryConstants.ExceptionExpected)] + 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.SnapshotRelatedEvents().Select(record => record.Metadata) + .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] + [Category(CategoryConstants.ExceptionExpected)] + 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) + { + } + } + } + + [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) + { + 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] + [Category(CategoryConstants.ExceptionExpected)] + 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] + [Category(CategoryConstants.ExceptionExpected)] + 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] + [Category(CategoryConstants.ExceptionExpected)] + 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] + [Category(CategoryConstants.ExceptionExpected)] + 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] + [Category(CategoryConstants.ExceptionExpected)] + public void ResponseDisposalReleasesPermitWhenFinalDiagnosticsFail() + { + 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); + 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] + public void ProgressReportsCountOnlyBytesSinceThePreviousReport() + { + 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); + first.Wait(TimeSpan.FromSeconds(5)).ShouldEqual(true); + stream.ReadByte().ShouldEqual(2); + second.Wait(TimeSpan.FromSeconds(5)).ShouldEqual(true); + stream.ReadByte().ShouldEqual(-1); + 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) + { + base.RelatedEvent(level, eventName, metadata, keyword); + this.EventCallback?.Invoke(eventName, metadata); + this.Callback?.Invoke(eventName); + } + } + + 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, Enlistment enlistment = null) + : base( + tracer, + new RetryConfig(0, TimeSpan.FromSeconds(5)) { ReadTimeout = TimeSpan.FromMilliseconds(300) }, + enlistment ?? 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/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 5dba402b91..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() { @@ -17,10 +19,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 +37,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; } @@ -48,26 +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.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) + { + 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(); + } + } + + private void RecordEvent(EventLevel level, string eventName, EventMetadata metadata, Keywords keyword) + { + 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 void RelatedEvent(EventLevel error, string eventName, EventMetadata metadata, Keywords keyword) + public sealed class RecordedEvent { - this.RelatedEventNames.Add(eventName); - this.RelatedEventKeywords.Add(keyword); - this.RelatedEventMetadata.Add(metadata); - if (eventName == this.WaitRelatedEventName) + public RecordedEvent(string name, EventLevel level, EventMetadata metadata, Keywords keyword) { - this.waitEvent.Set(); + 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) @@ -151,6 +188,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/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/GVFS/GVFS/CommandLine/DehydrateVerb.cs b/GVFS/GVFS/CommandLine/DehydrateVerb.cs index 61d5968b8b..f3e7c6bef6 100644 --- a/GVFS/GVFS/CommandLine/DehydrateVerb.cs +++ b/GVFS/GVFS/CommandLine/DehydrateVerb.cs @@ -231,14 +231,10 @@ 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 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 84a4c678bf..d1a4348e1d 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 = RetryConfig.LoadFromGitConfig(tracer, enlistment); + } 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 retryConfig = RetryConfig.LoadFromGitConfig(tracer, enlistment); 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 = RetryConfig.LoadFromGitConfig(tracer, enlistment); } serverGVFSConfig = this.QueryGVFSConfig(tracer, enlistment, retryConfig); diff --git a/docs/troubleshooting.md b/docs/troubleshooting.md index ea8bb4a80d..ae9f2a0b10 100644 --- a/docs/troubleshooting.md +++ b/docs/troubleshooting.md @@ -86,6 +86,98 @@ 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, 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. + +| 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. + +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. +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. + +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 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 | +| `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. + +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