public async Task <TResult> RunAsync([CallerMemberName] string?caller = null)
{
using (_counter?.Start())
{
TraceOperationStarted(caller !);
var stopwatch = StopwatchSlim.Start();
try
{
// No need to run anything if the cancellation is requested already.
_context.Token.ThrowIfCancellationRequested();
var result = await AsyncOperation();
TraceOperationFinished(result, stopwatch.Elapsed, caller !);
return(result);
}
catch (Exception e)
{
var resultBase = new BoolResult(e);
if (_isCritical)
{
resultBase.MakeCritical();
}
MarkResultIsCancelledIfNeeded(resultBase, e);
TraceResultOperationFinished(resultBase, stopwatch.Elapsed, caller !);
throw;
}
}
}
public async Task SlowShutdownDoesntBlockUse()
{
var configuration = new ResourcePoolConfiguration()
{
MaximumAge = TimeSpan.FromSeconds(1),
GarbageCollectionPeriod = Timeout.InfiniteTimeSpan,
};
var testTime = StopwatchSlim.Start();
await RunTest <Key, SlowResource>(async (context, pool) =>
{
var key = new Key(0);
var timeToStartup = StopwatchSlim.Start();
await pool.UseAsync(context, key, wrapper =>
{
timeToStartup.Elapsed.TotalSeconds.Should().BeLessThan(1);
return(BoolResult.SuccessTask);
}).ShouldBeSuccess();
},
_ => new SlowResource(shutdownDelay: TimeSpan.FromSeconds(5)),
configuration);
// We should bear with shutdown slowness as we dispose the instance
testTime.Elapsed.TotalSeconds.Should().BeGreaterOrEqualTo(4.9);
}
private async Task <T> RunFuncAsync <T>(
RequestHeader header,
Func <RequestContext, IContentSession, Task <T> > taskFunc,
Func <RequestContext, string, T> failFunc,
CancellationToken token,
bool?traceStartAndStop = null,
bool obtainSession = true,
[CallerMemberName] string?caller = null)
{
bool trace = traceStartAndStop ?? _traceGrpcOperations;
var tracingContext = new Context(Guid.Parse(header.TraceId), Logger);
using var shutdownTracker = TrackShutdown(tracingContext, token);
var context = new RequestContext(startTime: DateTime.UtcNow, shutdownTracker.Context);
int sessionId = header.SessionId;
IContentSession?session = null;
if (obtainSession && !ContentSessionHandler.TryGetSession(sessionId, out session))
{
string message = $"Could not find session for session ID {sessionId}";
Logger.Info(message);
return(failFunc(context, message));
}
var sw = StopwatchSlim.Start();
// Detaching from the calling thread to (potentially) avoid IO Completion port thread exhaustion
await Task.Yield();
try
{
if (trace)
{
tracingContext.Debug($"Starting GRPC operation {caller} for session {sessionId}.");
}
var result = await taskFunc(context, session !);
if (trace)
{
tracingContext.Debug($"GRPC operation {caller} is finished in {sw.Elapsed.TotalMilliseconds}ms for session {sessionId}.");
}
return(result);
}
catch (TaskCanceledException)
{
var message = $"The GRPC server operation {caller} was canceled in {sw.Elapsed.TotalMilliseconds}ms.";
tracingContext.Info(message);
return(failFunc(context, message));
}
catch (Exception e)
{
tracingContext.Error($"GRPC server operation {caller} failed in {sw.Elapsed.TotalMilliseconds}ms. {e}");
return(failFunc(context, e.ToString()));
}
}
public async Task <TResult> RunAsync([CallerMemberName] string?caller = null)
{
using (_counter?.Start())
{
TraceOperationStarted(caller !);
var stopwatch = StopwatchSlim.Start();
try
{
var result = await AsyncOperation();
TraceOperationFinished(result, stopwatch.Elapsed, caller !);
return(result);
}
catch (Exception e)
{
var resultBase = new BoolResult(e);
if (_isCritical)
{
resultBase.MakeCritical();
}
TraceResultOperationFinished(resultBase, stopwatch.Elapsed, caller !);
throw;
}
}
}
/// <summary>
/// Synchronously acquire a semaphore
/// </summary>
/// <param name="semaphore">The semaphore to acquire</param>
public static SemaphoreReleaser AcquireSemaphore(this SemaphoreSlim semaphore)
{
Contract.Requires(semaphore != null);
var stopwatch = StopwatchSlim.Start();
semaphore.Wait();
return(new SemaphoreReleaser(semaphore, stopwatch.Elapsed));
}
public CopyTask(CopyOperationBase request, int priority, CancellationToken timeoutToken, CancellationToken cancelToken)
{
Request = request;
Priority = priority;
Stopwatch = StopwatchSlim.Start();
TimeoutToken = timeoutToken;
CancelToken = cancelToken;
}
private async Task <TResponse> PerformOperationAsync <TResponse>(
IGrpcRequest request,
Func <ServiceOperationContext, Task <TResponse> > taskFunc,
CancellationToken token,
[CallerMemberName] string operation = null) where TResponse : IGrpcResponse, new()
{
var stopwatch = StopwatchSlim.Start();
DateTime startTime = DateTime.UtcNow;
var cacheContext = new OperationContext(new Context(new Guid(request.Header.TraceId), Logger), token);
var sessionId = request.Header.SessionId;
if (!_cacheSessionHandler.TryGetSession(sessionId, out var session))
{
return(failure($"Could not find session for session ID {sessionId}"));
}
await Task.Yield();
try
{
var serviceOperationContext = new ServiceOperationContext(session, cacheContext, startTime);
var result = await taskFunc(serviceOperationContext);
if (result.Header == null)
{
result.Header = ResponseHeader.Success(startTime);
}
Logger.Info($"GRPC server operation '{operation}' succeeded by {stopwatch.Elapsed.TotalMilliseconds}ms.");
return(result);
}
catch (TaskCanceledException)
{
Logger.Info($"GRPC server operation '{operation}' is canceled by {stopwatch.Elapsed.TotalMilliseconds}ms.");
return(failure("The operation was canceled."));
}
catch (ResultPropagationException e)
{
Logger.Error(e, $"GRPC server operation '{operation}' failed by {stopwatch.Elapsed.TotalMilliseconds}ms. Error: {e}");
return(new TResponse {
Header = ResponseHeader.Failure(startTime, e.Result.ErrorMessage, e.Result.Diagnostics)
});
}
catch (Exception e)
{
Logger.Error(e, $"GRPC server operation '{operation}' failed by {stopwatch.Elapsed.TotalMilliseconds}ms. Error: {e}");
return(failure(e.ToString()));
}
TResponse failure(string errorMessage) => new TResponse
{
Header = ResponseHeader.Failure(startTime, errorMessage)
};
}
/// <summary>
/// Asynchronously acquire a semaphore
/// </summary>
/// <param name="semaphore">The semaphore to acquire</param>
/// <param name="cancellationToken">The cancellation token</param>
/// <returns>A disposable which will release the semaphore when it is disposed.</returns>
public static async Task <SemaphoreReleaser> AcquireAsync(this SemaphoreSlim semaphore, CancellationToken cancellationToken = default(CancellationToken))
{
Contract.Requires(semaphore != null);
var stopwatch = StopwatchSlim.Start();
await semaphore.WaitAsync(cancellationToken);
return(new SemaphoreReleaser(semaphore, stopwatch.Elapsed));
}
public virtual async Task <TResult> RunAsync([CallerMemberName] string?caller = null)
{
using (_counter?.Start())
{
TraceOperationStarted(caller !);
var stopwatch = StopwatchSlim.Start();
var result = await RunOperationAndConvertExceptionToErrorAsync(AsyncOperation);
TraceOperationFinished(result, stopwatch.Elapsed, caller !);
return(result);
}
}
public async Task <TResult> RunAsync([CallerMemberName] string?caller = null)
{
using (_counter?.Start())
{
TraceOperationStarted(caller !);
var stopwatch = StopwatchSlim.Start();
var result = await _asyncOperation();
TraceOperationFinished(result, stopwatch.Elapsed, caller !);
return(result);
}
}
public TResult Run([CallerMemberName] string?caller = null)
{
using (_counter?.Start())
{
TraceOperationStarted(caller !);
var stopwatch = StopwatchSlim.Start();
var result = RunOperationAndConvertExceptionToError(_operation);
TraceOperationFinished(result, stopwatch.Elapsed, caller !);
return(result);
}
}
protected async Task <TResult> PerformOperationAsync <TResult>(OperationContext context, Func <SessionContext, Task <TResult> > operation, Func <string>?startMessageFactory = null, [CallerMemberName] string?caller = null) where TResult : ResultBase
{
var stopwatch = StopwatchSlim.Start();
TraceStartIfEnabled(context, caller !, startMessageFactory);
try
{
var result = await performOperationCoreAsync();
TraceStopIfEnabled(context, result, stopwatch.Elapsed, caller !);
return(result);
}
catch (Exception e)
{
// This can be only ClientCanRetryException.
// Still tracing it explicitly.
var error = new ErrorResult(e).AsResult <TResult>();
TraceStopIfEnabled(context, error, stopwatch.Elapsed, caller !);
throw;
}
async Task <TResult> performOperationCoreAsync()
{
var sessionContext = await CreateSessionContextAsync(context, context.Token);
if (!sessionContext)
{
return(new ErrorResult(sessionContext).AsResult <TResult>());
}
try
{
return(await operation(sessionContext.Value));
}
catch (ResultPropagationException error)
{
return(new ErrorResult(error).AsResult <TResult>());
}
catch (Exception e) when(!(e is ClientCanRetryException))
{
return(new ErrorResult(e).AsResult <TResult>());
}
}
}
/// <summary>
/// Acquires an exclusive lock for the given key. <see cref="Release" /> must be called
/// subsequently in a 'finally' block.
/// </summary>
public async Task <LockHandle> AcquireAsync(TKey key)
{
StopwatchSlim stopwatch = StopwatchSlim.Start();
LockHandle thisHandle = new LockHandle(this, key);
while (true)
{
LockHandle currentHandle = _exclusiveLocks.GetOrAdd(key, thisHandle);
if (currentHandle != thisHandle)
{
await currentHandle.TaskCompletionSource.Task;
}
else
{
break;
}
}
return(thisHandle.WithDuration(stopwatch.Elapsed));
}
public Task SlowStartupBlocksUseThread()
{
var configuration = new ResourcePoolConfiguration()
{
MaximumAge = TimeSpan.FromSeconds(1),
GarbageCollectionPeriod = Timeout.InfiniteTimeSpan,
};
return(RunTest <Key, SlowResource>(async(context, pool) =>
{
var key = new Key(0);
var timeToStartup = StopwatchSlim.Start();
await pool.UseAsync(context, key, wrapper =>
{
// Don't use 5s, because we may wake up slightly earlier than that
timeToStartup.Elapsed.TotalSeconds.Should().BeGreaterOrEqualTo(4.9);
return BoolResult.SuccessTask;
}).ShouldBeSuccess();
},
_ => new SlowResource(startupDelay: TimeSpan.FromSeconds(5)),
configuration));
}
private async Task <TResponse> PerformOperationAsync <TResponse>(
IGrpcRequest request,
Func <ServiceOperationContext, Task <TResponse> > taskFunc,
CancellationToken token,
[CallerMemberName] string operation = null !) where TResponse : IGrpcResponse, new()
{
var sw = StopwatchSlim.Start();
DateTime startTime = DateTime.UtcNow;
using var shutdownTracker = TrackShutdown(new OperationContext(new Context(new Guid(request.Header.TraceId), Logger), token), token);
var tracingContext = shutdownTracker.Context;
var sessionId = request.Header.SessionId;
if (!_cacheSessionHandler.TryGetSession(sessionId, out var session))
{
return(failure($"Could not find session for session ID {sessionId}"));
}
await Task.Yield();
try
{
var serviceOperationContext = new ServiceOperationContext(session, tracingContext, startTime);
TraceGrpcOperationStarted(tracingContext, enabled: TraceGrpcOperations, operation, sessionId);
var result = await taskFunc(serviceOperationContext);
if (result.Header == null)
{
result.Header = ResponseHeader.Success(startTime);
}
TraceGrpcOperationFinished(tracingContext, enabled: TraceGrpcOperations, operation, sw.Elapsed, sessionId);
return(result);
}
catch (TaskCanceledException e)
{
var message = GetLogMessage(e, operation, sessionId);
Tracer.OperationFinished(tracingContext, FromException(e), sw.Elapsed, message, operation);
return(failure(message));
}
catch (ResultPropagationException e)
{
var message = GetLogMessage(e, operation, sessionId);
Tracer.OperationFinished(tracingContext, FromException(e), sw.Elapsed, message, operation);
return(new TResponse {
Header = ResponseHeader.Failure(startTime, e.Result.ErrorMessage, e.Result.Diagnostics)
});
}
catch (Exception e)
{
var message = GetLogMessage(e, operation, sessionId);
Tracer.OperationFinished(tracingContext, FromException(e), sw.Elapsed, message, operation);
return(failure(e.ToString()));
}
TResponse failure(string errorMessage) => new TResponse
{
Header = ResponseHeader.Failure(startTime, errorMessage)
};
}
public async Task <PushFileResult> PushFileAsync(OperationContext context, ContentHash hash, Stream stream, CopyOptions options)
{
using var cts = CancellationTokenSource.CreateLinkedTokenSource(context.Token);
var token = cts.Token;
bool exceptionThrown = false;
TimeSpan? headerResponseTime = null;
PushFileResult?result = null;
try
{
var startingPosition = stream.Position;
var pushRequest = new PushRequest(hash, traceId: context.TracingContext.Id);
var headers = pushRequest.GetMetadata();
using var call = _client.PushFile(options: GetDefaultGrpcOptions(headers, token));
var requestStream = call.RequestStream;
Metadata responseHeaders;
var stopwatch = StopwatchSlim.Start();
try
{
var timeout = GetResponseHeadersTimeout(options);
responseHeaders = await call.ResponseHeadersAsync.WithTimeoutAsync(timeout, token);
headerResponseTime = stopwatch.Elapsed;
}
catch (TimeoutException t)
{
cts.Cancel();
result = new PushFileResult(GetCopyResultCodeForGetResponseHeaderTimeout(), t);
return(result);
}
// If the remote machine couldn't be contacted, GRPC returns an empty
// header collection. To avoid an exception, exit early instead.
if (responseHeaders.Count == 0)
{
result = PushFileResult.ServerUnavailable();
return(result);
}
var pushResponse = PushResponse.FromMetadata(responseHeaders);
if (!pushResponse.ShouldCopy)
{
result = PushFileResult.Rejected(pushResponse.Rejection);
return(result);
}
// If we get a response before we finish streaming, it must be that the server cancelled the operation.
var responseStream = call.ResponseStream;
var responseMoveNext = responseStream.MoveNext(token);
var responseCompletedTask = responseMoveNext.ContinueWith(
t =>
{
// It is possible that the next operation in this method will fail
// causing stack unwinding that will dispose serverIsDoneSource.
//
// Then when responseMoveNext is done serverIsDoneSource is already disposed and
// serverIsDoneSource.Cancel will throw ObjectDisposedException.
// This exception is not observed because the stack could've been unwound before
// the result of this method is awaited.
IgnoreObjectDisposedException(() => cts.Cancel());
});
result = await _bandwidthChecker.CheckBandwidthAtIntervalAsync(
context,
innerToken => pushFileImplementation(stream, options, startingPosition, requestStream, responseStream, responseMoveNext, responseCompletedTask, innerToken),
options,
getErrorResult : diagnostics => PushFileResult.BandwidthTimeout(diagnostics));
return(result);
}
catch (RpcException r)
{
result = new PushFileResult(r);
return(result);
}
catch (Exception)
{
exceptionThrown = true;
throw;
}
finally
{
// Even though we don't expect exceptions in this method, we can't assume they won't happen.
// So asserting that the result is not null only when the method completes successfully or with a known errors.
Contract.Assert(exceptionThrown || result != null);
if (result != null)
{
result.HeaderResponseTime = headerResponseTime;
}
}
async Task <PushFileResult> pushFileImplementation(Stream stream, CopyOptions options, long startingPosition, IClientStreamWriter <PushFileRequest> requestStream, IAsyncStreamReader <PushFileResponse> responseStream, Task <bool> responseMoveNext, Task responseCompletedTask, CancellationToken token)
{
using (var primaryBufferHandle = _pool.Get())
using (var secondaryBufferHandle = _pool.Get())
{
await StreamContentAsync(stream, primaryBufferHandle.Value, secondaryBufferHandle.Value, requestStream, options, token);
}
token.ThrowIfCancellationRequested();
await requestStream.CompleteAsync();
await responseCompletedTask;
// Make sure that we only attempt to read response when it is available.
var responseIsAvailable = await responseMoveNext;
if (!responseIsAvailable)
{
return(new PushFileResult("Failed to get final response."));
}
var response = responseStream.Current;
var size = stream.Position - startingPosition;
return(response.Header.Succeeded
? PushFileResult.PushSucceeded(size)
: new PushFileResult(response.Header.ErrorMessage));
}
}
private async Task <CopyFileResult> CopyToCoreAsync(OperationContext context, ContentHash hash, CopyOptions options, Func <Stream> streamFactory, bool closeStream)
{
using var cts = CancellationTokenSource.CreateLinkedTokenSource(context.Token);
var token = cts.Token;
bool exceptionThrown = false;
TimeSpan? headerResponseTime = null;
CopyFileResult?result = null;
try
{
CopyFileRequest request = new CopyFileRequest()
{
TraceId = context.TracingContext.Id.ToString(),
HashType = (int)hash.HashType,
ContentHash = hash.ToByteString(),
Offset = 0,
Compression = _configuration.UseGzipCompression ? CopyCompression.Gzip : CopyCompression.None,
FailFastIfBusy = options.BandwidthConfiguration?.FailFastIfServerIsBusy ?? false,
};
using AsyncServerStreamingCall <CopyFileResponse> response = _client.CopyFile(request, options: GetDefaultGrpcOptions(token));
Metadata headers;
var stopwatch = StopwatchSlim.Start();
try
{
var connectionTimeout = GetResponseHeadersTimeout(options);
headers = await response.ResponseHeadersAsync.WithTimeoutAsync(connectionTimeout, token);
headerResponseTime = stopwatch.Elapsed;
}
catch (TimeoutException t)
{
// Trying to cancel the back end operation as well.
cts.Cancel();
result = new CopyFileResult(GetCopyResultCodeForGetResponseHeaderTimeout(), t);
return(result);
}
// If the remote machine couldn't be contacted, GRPC returns an empty
// header collection. GRPC would throw an RpcException when we tried
// to stream response, but by that time we would have created target
// stream. To avoid that, exit early instead.
if (headers.Count == 0)
{
result = new CopyFileResult(
CopyResultCode.ServerUnavailable,
$"Failed to connect to copy server {Key.Host} at port {Key.GrpcPort}.");
return(result);
}
// Parse header collection.
string? exception = null;
string? message = null;
CopyCompression compression = CopyCompression.None;
foreach (Metadata.Entry header in headers)
{
switch (header.Key)
{
case "exception":
exception = header.Value;
break;
case "message":
message = header.Value;
break;
case "compression":
Enum.TryParse(header.Value, out compression);
break;
}
}
// Process reported server-side errors.
if (exception != null)
{
Contract.Assert(message != null);
switch (exception)
{
case "ContentNotFound":
result = new CopyFileResult(CopyResultCode.FileNotFoundError, message);
return(result);
default:
result = new CopyFileResult(CopyResultCode.UnknownServerError, message);
return(result);
}
}
// We got headers back with no errors, so create the target stream.
Stream targetStream;
try
{
targetStream = streamFactory();
}
catch (Exception targetException)
{
result = new CopyFileResult(CopyResultCode.DestinationPathError, targetException);
return(result);
}
result = await _bandwidthChecker.CheckBandwidthAtIntervalAsync(
context,
innerToken => copyToCoreImplementation(response, compression, targetStream, innerToken),
options,
getErrorResult : diagnostics => new CopyFileResult(CopyResultCode.CopyBandwidthTimeoutError, diagnostics));
return(result);
}
catch (RpcException r)
{
result = CreateResultFromException(r);
return(result);
}
catch (Exception)
{
exceptionThrown = true;
throw;
}
finally
{
// Even though we don't expect exceptions in this method, we can't assume they won't happen.
// So asserting that the result is not null only when the method completes successfully or with a known errors.
Contract.Assert(exceptionThrown || result != null);
if (result != null)
{
result.HeaderResponseTime = headerResponseTime;
}
}
async Task <CopyFileResult> copyToCoreImplementation(AsyncServerStreamingCall <CopyFileResponse> response, CopyCompression compression, Stream targetStream, CancellationToken token)
{
// Copy the content to the target stream.
try
{
switch (compression)
{
case CopyCompression.None:
await StreamContentAsync(response.ResponseStream, targetStream, options, token);
break;
case CopyCompression.Gzip:
await StreamContentWithCompressionAsync(response.ResponseStream, targetStream, options, token);
break;
default:
throw new NotSupportedException($"CopyCompression {compression} is not supported.");
}
}
finally
{
if (closeStream)
{
#pragma warning disable AsyncFixer02 // A disposable object used in a fire & forget async call
targetStream.Dispose();
#pragma warning restore AsyncFixer02 // A disposable object used in a fire & forget async call
}
}
return(CopyFileResult.Success);
}
}
public CopyTask(CopyOperationBase request, int priority)
{
Request = request;
Priority = priority;
Stopwatch = StopwatchSlim.Start();
}
/// <nodoc />
internal OperationTracer(StopwatchSlim stopwatch)
{
_stopwatch = stopwatch;
}
/// <nodoc />
public OperationTracer Trace(Action operationStarted)
{
operationStarted?.Invoke();
return(new OperationTracer(StopwatchSlim.Start()));
}
private async Task <TResult> ExecuteAsync <TResult>(
OperationContext originalContext,
Func <OperationContext, CallOptions, IGlobalCacheService, Task <TResult> > executeAsync,
Func <TResult, string?> extraEndMessage,
string?extraStartMessage = null,
[CallerMemberName] string caller = null !)
where TResult : ResultBase
{
var attempt = -1;
using var contextWithShutdown = TrackShutdown(originalContext);
var context = contextWithShutdown.Context;
var callerAttempt = $"{caller}_Attempt";
return(await context.PerformOperationWithTimeoutAsync(
Tracer,
context =>
{
var callOptions = new CallOptions(
headers: new Metadata()
{
MetadataServiceSerializer.CreateContextIdHeaderEntry(context.TracingContext.TraceId)
},
deadline: _clock.UtcNow + _configuration.OperationTimeout,
cancellationToken: context.Token);
return _retryPolicy.ExecuteAsync(async() =>
{
await Task.Yield();
attempt++;
var stopwatch = StopwatchSlim.Start();
var clientCreationTime = TimeSpan.Zero;
var result = await context.PerformOperationAsync(Tracer, () =>
{
return _serviceClientFactory.UseAsync(context, service =>
{
clientCreationTime = stopwatch.Elapsed;
return executeAsync(context, callOptions, service);
});
},
extraStartMessage: extraStartMessage,
extraEndMessage: r => $"Attempt=[{attempt}] ClientCreationTimeMs=[{clientCreationTime.TotalMilliseconds}] {extraEndMessage(r)}",
caller: callerAttempt,
traceErrorsOnly: true);
await Task.Yield();
// Because we capture exceptions inside the PerformOperation, we need to make sure that they
// get propagated for the retry policy to kick in.
if (result.Exception != null)
{
result.ReThrow();
}
return result;
}, context.Token);
},
caller : caller,
traceErrorsOnly : true,
extraStartMessage : extraStartMessage,
extraEndMessage : r => $"Attempts=[{attempt + 1}] {extraEndMessage(r)}",
timeout : _configuration.OperationTimeout));
}
