diff --git a/src/Cli/Microsoft.DotNet.Cli.Telemetry/Implementation/BreezePartialContent.cs b/src/Cli/Microsoft.DotNet.Cli.Telemetry/Implementation/BreezePartialContent.cs index 7f9fd55f917c..1719e134d69b 100644 --- a/src/Cli/Microsoft.DotNet.Cli.Telemetry/Implementation/BreezePartialContent.cs +++ b/src/Cli/Microsoft.DotNet.Cli.Telemetry/Implementation/BreezePartialContent.cs @@ -51,7 +51,7 @@ internal static class BreezePartialContent var retriableIndices = new HashSet(); foreach (var error in errors) { - if (s_retriableStatusCodes.Contains(error.StatusCode)) + if (IsRetriableStatusCode(error.StatusCode)) { retriableIndices.Add(error.Index); } @@ -86,4 +86,7 @@ internal static class BreezePartialContent return stream.Length == 0 ? null : stream.ToArray(); } + + internal static bool IsRetriableStatusCode(int statusCode) + => s_retriableStatusCodes.Contains(statusCode); } diff --git a/src/Cli/Microsoft.DotNet.Cli.Telemetry/Implementation/HttpTelemetryUploadTransport.cs b/src/Cli/Microsoft.DotNet.Cli.Telemetry/Implementation/HttpTelemetryUploadTransport.cs index 4b0fa0b02f4d..379f5118256e 100644 --- a/src/Cli/Microsoft.DotNet.Cli.Telemetry/Implementation/HttpTelemetryUploadTransport.cs +++ b/src/Cli/Microsoft.DotNet.Cli.Telemetry/Implementation/HttpTelemetryUploadTransport.cs @@ -65,11 +65,36 @@ public async Task TryUploadAsync(byte[] payload, Cancella // blob is done. Otherwise re-persist just the retriable envelopes. return retriable is null ? TelemetryUploadResult.Accepted - : TelemetryUploadResult.PartiallyAccepted(retriable); + : TelemetryUploadResult.PartiallyAccepted(retriable, GetRetryAfter(response)); } - // Throttling, server errors, etc.: retain the blob and retry it later. - return TelemetryUploadResult.Rejected; + // Retain only statuses that Azure Monitor defines as retriable. Treat permanent + // whole-request failures as terminal so one poison blob cannot block later telemetry. + if (!BreezePartialContent.IsRetriableStatusCode((int)response.StatusCode)) + { + return TelemetryUploadResult.PermanentlyRejected; + } + + return GetRetryAfter(response) is { } retryAfter + ? TelemetryUploadResult.RejectedAfter(retryAfter) + : TelemetryUploadResult.Rejected; + } + + private static TimeSpan? GetRetryAfter(HttpResponseMessage response) + { + var retryAfter = response.Headers.RetryAfter; + if (retryAfter?.Delta is { } delta) + { + return delta < TimeSpan.Zero ? TimeSpan.Zero : delta; + } + + if (retryAfter?.Date is { } date) + { + var delay = date - DateTimeOffset.UtcNow; + return delay < TimeSpan.Zero ? TimeSpan.Zero : delay; + } + + return null; } /// diff --git a/src/Cli/Microsoft.DotNet.Cli.Telemetry/Implementation/PersistentStorageTelemetryBackgroundWorker.cs b/src/Cli/Microsoft.DotNet.Cli.Telemetry/Implementation/PersistentStorageTelemetryBackgroundWorker.cs new file mode 100644 index 000000000000..f0261869140f --- /dev/null +++ b/src/Cli/Microsoft.DotNet.Cli.Telemetry/Implementation/PersistentStorageTelemetryBackgroundWorker.cs @@ -0,0 +1,88 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System.Diagnostics; +using System.Threading; + +namespace Microsoft.DotNet.Cli.Telemetry.Implementation; + +internal sealed class PersistentStorageTelemetryBackgroundWorker +{ + private readonly Func _drainAsync; + private int _started; + private CancellationTokenSource? _cancellation; + private Task? _task; + + public PersistentStorageTelemetryBackgroundWorker( + ITelemetryBlobStorage storage, + Uri ingestionTrackUri, + int leasePeriodMilliseconds, + int maxBlobsPerDrain) + : this(CreateDrainAsync(storage, ingestionTrackUri, leasePeriodMilliseconds, maxBlobsPerDrain)) + { + } + + internal PersistentStorageTelemetryBackgroundWorker(Func drainAsync) + { + _drainAsync = drainAsync; + } + + public void StartOnce() + { + if (Interlocked.Exchange(ref _started, 1) != 0) + { + return; + } + + _cancellation = new CancellationTokenSource(); + _task = Task.Run(() => DrainAsync(_cancellation.Token)); + } + + public bool Shutdown(int timeoutMilliseconds) + { + _cancellation?.Cancel(); + if (_task is null) + { + return true; + } + + try + { + return _task.Wait(timeoutMilliseconds); + } + catch (AggregateException) + { + return true; + } + } + + private async Task DrainAsync(CancellationToken cancellationToken) + { + try + { + await _drainAsync(cancellationToken).ConfigureAwait(false); + } + catch (OperationCanceledException) + { + } + catch (Exception e) + { + Debug.Fail(e.ToString()); + } + } + + private static Func CreateDrainAsync( + ITelemetryBlobStorage storage, + Uri ingestionTrackUri, + int leasePeriodMilliseconds, + int maxBlobsPerDrain) + { + var transport = new HttpTelemetryUploadTransport(ingestionTrackUri); + var uploader = new PersistentStorageTelemetryUploader( + storage, + transport, + leasePeriodMilliseconds, + maxBlobsPerDrain); + return cancellationToken => uploader.DrainAsync(cancellationToken); + } +} \ No newline at end of file diff --git a/src/Cli/Microsoft.DotNet.Cli.Telemetry/Implementation/PersistentStorageTelemetryUploader.cs b/src/Cli/Microsoft.DotNet.Cli.Telemetry/Implementation/PersistentStorageTelemetryUploader.cs index 566ce68a2b45..71f36d7aaf1b 100644 --- a/src/Cli/Microsoft.DotNet.Cli.Telemetry/Implementation/PersistentStorageTelemetryUploader.cs +++ b/src/Cli/Microsoft.DotNet.Cli.Telemetry/Implementation/PersistentStorageTelemetryUploader.cs @@ -45,9 +45,12 @@ public PersistentStorageTelemetryUploader( /// Leases, uploads, and deletes persisted blobs. Blobs that fail to upload are left for a /// later retry. This method never throws. /// - public async Task DrainAsync(CancellationToken cancellationToken) + public async Task DrainAsync(CancellationToken cancellationToken) { var processed = 0; + var forwardProgress = 0; + var shouldBackOff = false; + TimeSpan? retryAfter = null; // Retriable remainders from partially-accepted uploads. Persisted AFTER the enumeration // completes so we never mutate the storage collection while iterating it. List? retriableRemainders = null; @@ -92,6 +95,8 @@ public async Task DrainAsync(CancellationToken cancellationToken) { (retriableRemainders ??= []).Add(remainder); } + shouldBackOff = true; + retryAfter = result.RetryAfter; deleted = blob.TryDelete(); break; @@ -99,9 +104,17 @@ public async Task DrainAsync(CancellationToken cancellationToken) deleted = blob.TryDelete(); break; + case TelemetryUploadOutcome.PermanentlyRejected: + // Retrying cannot succeed. Delete this poison blob so later telemetry + // in the storage directory can continue draining. + deleted = blob.TryDelete(); + break; + case TelemetryUploadOutcome.Rejected: // Leave the blob in place; its lease will expire and a later invocation // will retry it. + shouldBackOff = true; + retryAfter = result.RetryAfter; break; } } @@ -113,16 +126,31 @@ public async Task DrainAsync(CancellationToken cancellationToken) } catch (Exception e) { - // Swallow per-blob failures and keep going; the blob is retried later. + // Network and storage failures are normally transient. Stop this pass and let the + // caller back off before trying the blob again rather than moving immediately to + // the rest of the backlog. Debug.Fail(e.ToString()); + shouldBackOff = true; } finally { - if (leased && !deleted) + if (deleted) + { + forwardProgress++; + } + else if (leased) { blob.TryRelease(); } } + + if (shouldBackOff) + { + // A retryable response normally indicates service throttling or a transient + // failure. Stop this pass rather than submitting every remaining blob to a + // service that has already asked us to retry. + break; + } } if (retriableRemainders is not null) @@ -132,5 +160,7 @@ public async Task DrainAsync(CancellationToken cancellationToken) _storage.TryPersist(remainder); } } + + return new TelemetryDrainResult(forwardProgress, shouldBackOff, retryAfter); } } diff --git a/src/Cli/Microsoft.DotNet.Cli.Telemetry/Implementation/TelemetryUploadResult.cs b/src/Cli/Microsoft.DotNet.Cli.Telemetry/Implementation/TelemetryUploadResult.cs index e8646a04beb7..ee8b020481bb 100644 --- a/src/Cli/Microsoft.DotNet.Cli.Telemetry/Implementation/TelemetryUploadResult.cs +++ b/src/Cli/Microsoft.DotNet.Cli.Telemetry/Implementation/TelemetryUploadResult.cs @@ -15,6 +15,10 @@ internal enum TelemetryUploadOutcome /// and should be persisted for a later retry. PartiallyAccepted, + /// The server permanently rejected the payload. Retrying cannot succeed, so the + /// blob should be deleted to avoid blocking later telemetry. + PermanentlyRejected, + /// The server did not accept the payload (throttling, server error, etc.). The /// blob should be retained and retried later. Rejected, @@ -28,10 +32,11 @@ internal enum TelemetryUploadOutcome /// internal readonly struct TelemetryUploadResult { - private TelemetryUploadResult(TelemetryUploadOutcome outcome, byte[]? retryPayload) + private TelemetryUploadResult(TelemetryUploadOutcome outcome, byte[]? retryPayload, TimeSpan? retryAfter) { Outcome = outcome; RetryPayload = retryPayload; + RetryAfter = retryAfter; } public TelemetryUploadOutcome Outcome { get; } @@ -42,10 +47,39 @@ private TelemetryUploadResult(TelemetryUploadOutcome outcome, byte[]? retryPaylo /// public byte[]? RetryPayload { get; } - public static TelemetryUploadResult Accepted { get; } = new(TelemetryUploadOutcome.Accepted, null); + /// + /// The server-provided delay before another upload attempt, when present. + /// + public TimeSpan? RetryAfter { get; } + + public static TelemetryUploadResult Accepted { get; } = new(TelemetryUploadOutcome.Accepted, null, null); + + public static TelemetryUploadResult Rejected { get; } = new(TelemetryUploadOutcome.Rejected, null, null); + + public static TelemetryUploadResult PermanentlyRejected { get; } = new(TelemetryUploadOutcome.PermanentlyRejected, null, null); + + public static TelemetryUploadResult RejectedAfter(TimeSpan retryAfter) + => new(TelemetryUploadOutcome.Rejected, null, retryAfter); + + public static TelemetryUploadResult PartiallyAccepted(byte[] retryPayload, TimeSpan? retryAfter = null) + => new(TelemetryUploadOutcome.PartiallyAccepted, retryPayload, retryAfter); +} + +/// +/// The result of one storage drain pass. +/// +internal readonly struct TelemetryDrainResult +{ + public TelemetryDrainResult(int forwardProgress, bool shouldBackOff, TimeSpan? retryAfter) + { + ForwardProgress = forwardProgress; + ShouldBackOff = shouldBackOff; + RetryAfter = retryAfter; + } + + public int ForwardProgress { get; } - public static TelemetryUploadResult Rejected { get; } = new(TelemetryUploadOutcome.Rejected, null); + public bool ShouldBackOff { get; } - public static TelemetryUploadResult PartiallyAccepted(byte[] retryPayload) - => new(TelemetryUploadOutcome.PartiallyAccepted, retryPayload); + public TimeSpan? RetryAfter { get; } } diff --git a/src/Cli/Microsoft.DotNet.Cli.Telemetry/PersistentStorageLogExporter.cs b/src/Cli/Microsoft.DotNet.Cli.Telemetry/PersistentStorageLogExporter.cs index 43276b62bb8a..64f2072d3d34 100644 --- a/src/Cli/Microsoft.DotNet.Cli.Telemetry/PersistentStorageLogExporter.cs +++ b/src/Cli/Microsoft.DotNet.Cli.Telemetry/PersistentStorageLogExporter.cs @@ -2,7 +2,6 @@ // The .NET Foundation licenses this file to you under the MIT license. using System.Diagnostics; -using System.Threading; using Microsoft.DotNet.Cli.Telemetry.Implementation; using OpenTelemetry; using OpenTelemetry.Logs; @@ -29,34 +28,34 @@ internal sealed class PersistentStorageLogExporter : BaseExporter { private readonly ITelemetryBlobStorage _storage; private readonly string _instrumentationKey; - private readonly Uri _ingestionTrackUri; - private readonly int _leasePeriodMilliseconds; - private readonly int _maxBlobsPerDrain; + private readonly PersistentStorageTelemetryBackgroundWorker? _backgroundWorker; private TelemetryResourceContext? _resourceContext; - // Guards against starting more than one background drain per exporter. - private int _drainStarted; - private CancellationTokenSource? _drainCts; - private Task? _drainTask; public PersistentStorageLogExporter( ITelemetryBlobStorage storage, string instrumentationKey, Uri ingestionTrackUri, int leasePeriodMilliseconds, - int maxBlobsPerDrain) + int maxBlobsPerDrain, + bool startBackgroundDrain = true) { _storage = storage; _instrumentationKey = instrumentationKey; - _ingestionTrackUri = ingestionTrackUri; - _leasePeriodMilliseconds = leasePeriodMilliseconds; - _maxBlobsPerDrain = maxBlobsPerDrain; + if (startBackgroundDrain) + { + _backgroundWorker = new PersistentStorageTelemetryBackgroundWorker( + storage, + ingestionTrackUri, + leasePeriodMilliseconds, + maxBlobsPerDrain); + } } public override ExportResult Export(in Batch batch) { try { - StartBackgroundDrainOnce(); + _backgroundWorker?.StartOnce(); var resource = _resourceContext ??= TelemetryResourceContextFactory.FromResource(ParentProvider?.GetResource()); var bytes = AzureMonitorLogSerializer.SerializeBatch(in batch, resource, _instrumentationKey); @@ -77,46 +76,6 @@ public override ExportResult Export(in Batch batch) protected override bool OnShutdown(int timeoutMilliseconds) { - _drainCts?.Cancel(); - if (_drainTask is not null) - { - try - { - return _drainTask.Wait(timeoutMilliseconds); - } - catch (AggregateException) - { - return true; - } - } - return true; - } - - private void StartBackgroundDrainOnce() - { - if (Interlocked.Exchange(ref _drainStarted, 1) != 0) - { - return; - } - - _drainCts = new CancellationTokenSource(); - var transport = new HttpTelemetryUploadTransport(_ingestionTrackUri); - var uploader = new PersistentStorageTelemetryUploader(_storage, transport, _leasePeriodMilliseconds, _maxBlobsPerDrain); - _drainTask = Task.Run(async () => - { - try - { - await uploader.DrainAsync(_drainCts.Token).ConfigureAwait(false); - } - catch (OperationCanceledException) - { - // Expected when shutdown is signalled. - } - catch (Exception e) - { - // Background telemetry drain must never surface errors. - Debug.Fail(e.ToString()); - } - }); + return _backgroundWorker?.Shutdown(timeoutMilliseconds) ?? true; } } diff --git a/src/Cli/Microsoft.DotNet.Cli.Telemetry/PersistentStorageLoggerOptionsExtensions.cs b/src/Cli/Microsoft.DotNet.Cli.Telemetry/PersistentStorageLoggerOptionsExtensions.cs index 30a7265e05e8..42c5b8fa63cc 100644 --- a/src/Cli/Microsoft.DotNet.Cli.Telemetry/PersistentStorageLoggerOptionsExtensions.cs +++ b/src/Cli/Microsoft.DotNet.Cli.Telemetry/PersistentStorageLoggerOptionsExtensions.cs @@ -48,7 +48,8 @@ public static OpenTelemetryLoggerOptions AddPersistentStorageExporter(this OpenT connectionString.InstrumentationKey, connectionString.TrackUri, telemetryOptions.LeasePeriodMilliseconds, - telemetryOptions.MaxBlobsPerDrain); + telemetryOptions.MaxBlobsPerDrain, + telemetryOptions.StartBackgroundDrain); return options.AddProcessor(new SimpleLogRecordExportProcessor(exporter)); } } diff --git a/src/Cli/Microsoft.DotNet.Cli.Telemetry/PersistentStorageTelemetryDrainer.cs b/src/Cli/Microsoft.DotNet.Cli.Telemetry/PersistentStorageTelemetryDrainer.cs new file mode 100644 index 000000000000..41aca6746012 --- /dev/null +++ b/src/Cli/Microsoft.DotNet.Cli.Telemetry/PersistentStorageTelemetryDrainer.cs @@ -0,0 +1,258 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System.Diagnostics; +using System.IO; +using System.Threading; +using Microsoft.DotNet.Cli.Telemetry.Implementation; + +namespace Microsoft.DotNet.Cli.Telemetry; + +/// +/// A standalone, out-of-band drainer for the persist-then-drain telemetry pipeline. It repeatedly +/// leases persisted telemetry blobs from a storage directory and POSTs them to Azure Monitor until +/// the storage is drained or a bounded lifetime elapses. +/// +/// This exists for hosts that persist telemetry with the background drain disabled +/// ( = ) +/// and instead deliver it from a separate, short-lived process — for example a detached child the +/// CLI spawns on exit so it can return immediately without waiting on the network. Because delivery +/// happens in that child, the persisting process never blocks on an HTTP POST, yet the current run's +/// telemetry is still delivered promptly rather than waiting for a future invocation. +/// +/// The drainer is safe to over-invoke: an exclusive-share lock file keyed on the storage +/// directory keeps a single instance active per directory, and blob leasing prevents any two +/// processes from uploading the same blob. It never throws. +/// +public static class PersistentStorageTelemetryDrainer +{ + // Brief pause between drain passes so that concurrent CLI invocations have a chance to persist + // new blobs (which this same drainer then delivers) and so a transient rejection does not spin + // the loop. Kept short because the loop already exits as soon as a pass makes no progress. + private static readonly TimeSpan s_interPassDelay = TimeSpan.FromMilliseconds(500); + private static readonly TimeSpan s_initialRetryDelay = TimeSpan.FromSeconds(1); + private static readonly TimeSpan s_maxRetryDelay = TimeSpan.FromSeconds(30); + private static readonly TimeSpan s_maxTaskDelay = TimeSpan.FromMilliseconds(uint.MaxValue - 1); + + // Name of the exclusive-share lock file that single-instances the drainer per storage directory. + private const string LockFileName = ".drain.lock"; + + /// + /// Drains persisted telemetry until the storage empties or + /// elapses (whichever comes first), then returns. Never throws. + /// + /// + /// The Application Insights connection string identifying the instrumentation key and ingestion + /// endpoint. When null, empty, or unparseable the drainer no-ops. + /// + /// + /// The directory persisted telemetry blobs are drained from. When null or empty the drainer + /// no-ops. Should match the + /// the persisting process wrote to. + /// + /// + /// An upper bound on how long the drainer runs. A non-positive value means no time bound (the + /// drainer then runs until the storage empties or fires). + /// + /// Cancels the drain. + /// + /// How long a blob is exclusively leased while it is being uploaded. + /// + /// The maximum number of blobs uploaded per pass. + public static async Task RunAsync( + string? connectionString, + string? storageDirectory, + TimeSpan maxLifetime, + CancellationToken cancellationToken = default, + int leasePeriodMilliseconds = 30_000, + int maxBlobsPerDrain = 200) + { + var parsedConnectionString = AzureMonitorConnectionString.Parse(connectionString); + if (parsedConnectionString is null || string.IsNullOrWhiteSpace(storageDirectory)) + { + return; + } + + FileStream? directoryLock = null; + try + { + directoryLock = TryAcquireDirectoryLock(storageDirectory!); + if (directoryLock is null) + { + // Another drainer is already active for this storage directory, or the platform + // does not support file locking. Skip this run. + return; + } + + var storage = new FileSystemTelemetryBlobStorage(storageDirectory!); + var transport = new HttpTelemetryUploadTransport(parsedConnectionString.TrackUri); + var uploader = new PersistentStorageTelemetryUploader(storage, transport, leasePeriodMilliseconds, maxBlobsPerDrain); + using var lifetimeCts = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken); + if (maxLifetime > TimeSpan.Zero) + { + lifetimeCts.CancelAfter(GetBoundedTaskDelay(maxLifetime)); + } + + await RunCoreAsync( + uploader, + maxLifetime, + lifetimeCts.Token, + static (delay, token) => Task.Delay(delay, token), + TimeProvider.System).ConfigureAwait(false); + } + catch (Exception e) + { + // Absolutely never surface telemetry errors to the host. + Debug.Fail(e.ToString()); + } + finally + { + // Releasing an OS file lock has no thread affinity, so unlike a named Mutex it is safe + // to dispose on whatever thread pool thread the async loop resumed on. The OS also drops + // the lock automatically if this process is killed before reaching here. + directoryLock?.Dispose(); + } + } + + internal static TimeSpan GetRetryDelay(int consecutiveRetryPasses, TimeSpan? serverRetryAfter) + { + if (serverRetryAfter is { } requestedDelay) + { + return GetBoundedTaskDelay( + requestedDelay < s_initialRetryDelay ? s_initialRetryDelay : requestedDelay); + } + + var exponent = Math.Clamp(consecutiveRetryPasses - 1, 0, 30); + var delayMilliseconds = s_initialRetryDelay.TotalMilliseconds * Math.Pow(2, exponent); + return TimeSpan.FromMilliseconds(Math.Min(delayMilliseconds, s_maxRetryDelay.TotalMilliseconds)); + } + + internal static TimeSpan GetBoundedTaskDelay(TimeSpan delay) + => delay > s_maxTaskDelay ? s_maxTaskDelay : delay; + + internal static async Task RunCoreAsync( + PersistentStorageTelemetryUploader uploader, + TimeSpan maxLifetime, + CancellationToken cancellationToken, + Func delayAsync, + TimeProvider timeProvider) + { + var startTimestamp = timeProvider.GetTimestamp(); + var consecutiveRetryPasses = 0; + + while (!cancellationToken.IsCancellationRequested) + { + var remainingLifetime = GetRemainingLifetime(maxLifetime, timeProvider, startTimestamp); + if (remainingLifetime is { } remaining && remaining <= TimeSpan.Zero) + { + break; + } + + TelemetryDrainResult result; + try + { + result = await uploader.DrainAsync(cancellationToken).ConfigureAwait(false); + } + catch (OperationCanceledException) + { + break; + } + catch (Exception e) + { + // The drainer must never surface errors. Stop on unexpected failure. + Debug.Fail(e.ToString()); + break; + } + + if (result.ForwardProgress == 0 && !result.ShouldBackOff) + { + // No forward progress: the storage is drained, or all remaining blobs are + // leased by another process or were rejected. Either way, stop. + break; + } + + var delay = s_interPassDelay; + if (result.ShouldBackOff) + { + consecutiveRetryPasses++; + delay = GetRetryDelay(consecutiveRetryPasses, result.RetryAfter); + } + else + { + consecutiveRetryPasses = 0; + } + + remainingLifetime = GetRemainingLifetime(maxLifetime, timeProvider, startTimestamp); + if (remainingLifetime is { } remainingDelay) + { + if (remainingDelay <= TimeSpan.Zero) + { + break; + } + + delay = TimeSpan.FromTicks(Math.Min(delay.Ticks, remainingDelay.Ticks)); + } + + try + { + await delayAsync(delay, cancellationToken).ConfigureAwait(false); + } + catch (OperationCanceledException) + { + break; + } + } + } + + private static TimeSpan? GetRemainingLifetime(TimeSpan maxLifetime, TimeProvider timeProvider, long startTimestamp) + { + if (maxLifetime <= TimeSpan.Zero) + { + return null; + } + + return maxLifetime - timeProvider.GetElapsedTime(startTimestamp); + } + + // Single-instance-per-directory guard for the drainer. Returns a held lock handle, or null when + // another drainer already owns the directory (or the platform cannot lock). + // + // Uses an exclusive-share lock file rather than a named Mutex because the drain loop awaits: a + // Mutex is thread-affine and must be released on the same thread that acquired it, but an async + // continuation can resume on any thread pool thread, so releasing/disposing it could throw. A + // file handle has no thread affinity, so it can be released on any thread, and the OS drops it if + // the process is killed mid-drain (no abandoned-lock recovery needed). + // + // On Windows, FileShare.None is a mandatory share-mode lock. On Unix it is an advisory flock, + // honored by every other .NET FileStream opener — which is the only contender here. On the rare + // filesystem that does not support locking, the runtime silently takes no lock and two drainers + // may run at once; that is harmless because blob leasing (an atomic rename) still prevents any + // blob from being uploaded twice. Exclusivity comes from holding the handle, not from the file + // existing, so a lock file left behind by a killed drainer is simply reopened and re-locked on + // the next run; it is intentionally not deleted on close. + internal static FileStream? TryAcquireDirectoryLock(string storageDirectory) + { + try + { + Directory.CreateDirectory(storageDirectory); + var lockPath = Path.Combine(storageDirectory, LockFileName); + return new FileStream( + lockPath, + FileMode.OpenOrCreate, + FileAccess.ReadWrite, + FileShare.None, + bufferSize: 1, + FileOptions.None); + } + catch (IOException) + { + // Sharing violation (Windows) or EWOULDBLOCK (Unix): another drainer holds the lock. + return null; + } + catch (UnauthorizedAccessException) + { + // Some platforms surface a sharing violation as an access denial. + return null; + } + } +} diff --git a/src/Cli/Microsoft.DotNet.Cli.Telemetry/PersistentStorageTelemetryOptions.cs b/src/Cli/Microsoft.DotNet.Cli.Telemetry/PersistentStorageTelemetryOptions.cs index c08c5f68b02d..33233da0d59a 100644 --- a/src/Cli/Microsoft.DotNet.Cli.Telemetry/PersistentStorageTelemetryOptions.cs +++ b/src/Cli/Microsoft.DotNet.Cli.Telemetry/PersistentStorageTelemetryOptions.cs @@ -37,4 +37,14 @@ public sealed class PersistentStorageTelemetryOptions /// even when a large backlog has accumulated. Remaining blobs are drained by later invocations. /// public int MaxBlobsPerDrain { get; set; } = 200; + + /// + /// Whether the exporter starts its own in-process background drain the first time it exports. + /// Defaults to , which is appropriate for a long-lived-enough CLI that + /// both persists and delivers telemetry in the same process. Set to + /// when delivery is handled out of band — for example by a separate detached drainer process + /// or by a later invocation of a frequently-run CLI — so the persisting process only writes + /// to storage and never spins up upload work of its own. + /// + public bool StartBackgroundDrain { get; set; } = true; } diff --git a/src/Cli/Microsoft.DotNet.Cli.Telemetry/PersistentStorageTraceExporter.cs b/src/Cli/Microsoft.DotNet.Cli.Telemetry/PersistentStorageTraceExporter.cs index 528a4e6f6a04..73e165d638d5 100644 --- a/src/Cli/Microsoft.DotNet.Cli.Telemetry/PersistentStorageTraceExporter.cs +++ b/src/Cli/Microsoft.DotNet.Cli.Telemetry/PersistentStorageTraceExporter.cs @@ -2,7 +2,6 @@ // The .NET Foundation licenses this file to you under the MIT license. using System.Diagnostics; -using System.Threading; using Microsoft.DotNet.Cli.Telemetry.Implementation; using OpenTelemetry; @@ -28,27 +27,27 @@ internal sealed class PersistentStorageTraceExporter : BaseExporter { private readonly ITelemetryBlobStorage _storage; private readonly string _instrumentationKey; - private readonly Uri _ingestionTrackUri; - private readonly int _leasePeriodMilliseconds; - private readonly int _maxBlobsPerDrain; + private readonly PersistentStorageTelemetryBackgroundWorker? _backgroundWorker; private TelemetryResourceContext? _resourceContext; - // Guards against starting more than one background drain per exporter. - private int _drainStarted; - private CancellationTokenSource? _drainCts; - private Task? _drainTask; public PersistentStorageTraceExporter( ITelemetryBlobStorage storage, string instrumentationKey, Uri ingestionTrackUri, int leasePeriodMilliseconds, - int maxBlobsPerDrain) + int maxBlobsPerDrain, + bool startBackgroundDrain = true) { _storage = storage; _instrumentationKey = instrumentationKey; - _ingestionTrackUri = ingestionTrackUri; - _leasePeriodMilliseconds = leasePeriodMilliseconds; - _maxBlobsPerDrain = maxBlobsPerDrain; + if (startBackgroundDrain) + { + _backgroundWorker = new PersistentStorageTelemetryBackgroundWorker( + storage, + ingestionTrackUri, + leasePeriodMilliseconds, + maxBlobsPerDrain); + } } public override ExportResult Export(in Batch batch) @@ -59,7 +58,7 @@ public override ExportResult Export(in Batch batch) // persisted by this and previous invocations. Doing this here (rather than at // construction) ties the drain to the exporter actually being started and keeps it // from running when telemetry is opted out (no spans are exported in that case). - StartBackgroundDrainOnce(); + _backgroundWorker?.StartOnce(); var resource = _resourceContext ??= TelemetryResourceContextFactory.FromResource(ParentProvider?.GetResource()); var bytes = AzureMonitorTelemetrySerializer.SerializeBatch(in batch, resource, _instrumentationKey); @@ -80,51 +79,6 @@ public override ExportResult Export(in Batch batch) protected override bool OnShutdown(int timeoutMilliseconds) { - // Signal the background drain to stop and wait for it to finish within the - // remaining shutdown budget. This ensures inflight HTTP POSTs are cancelled and - // the drain loop persists any retriable remainders before the process exits. - _drainCts?.Cancel(); - if (_drainTask is not null) - { - try - { - return _drainTask.Wait(timeoutMilliseconds); - } - catch (AggregateException) - { - // The drain swallows its own exceptions; this handles edge cases like - // ObjectDisposedException from the CTS during shutdown. - return true; - } - } - return true; - } - - private void StartBackgroundDrainOnce() - { - if (Interlocked.Exchange(ref _drainStarted, 1) != 0) - { - return; - } - - _drainCts = new CancellationTokenSource(); - var transport = new HttpTelemetryUploadTransport(_ingestionTrackUri); - var uploader = new PersistentStorageTelemetryUploader(_storage, transport, _leasePeriodMilliseconds, _maxBlobsPerDrain); - _drainTask = Task.Run(async () => - { - try - { - await uploader.DrainAsync(_drainCts.Token).ConfigureAwait(false); - } - catch (OperationCanceledException) - { - // Expected when shutdown is signalled. - } - catch (Exception e) - { - // Background telemetry drain must never surface errors. - Debug.Fail(e.ToString()); - } - }); + return _backgroundWorker?.Shutdown(timeoutMilliseconds) ?? true; } } diff --git a/src/Cli/Microsoft.DotNet.Cli.Telemetry/PersistentStorageTracerProviderBuilderExtensions.cs b/src/Cli/Microsoft.DotNet.Cli.Telemetry/PersistentStorageTracerProviderBuilderExtensions.cs index bfd482cd96f3..4dfb3896a089 100644 --- a/src/Cli/Microsoft.DotNet.Cli.Telemetry/PersistentStorageTracerProviderBuilderExtensions.cs +++ b/src/Cli/Microsoft.DotNet.Cli.Telemetry/PersistentStorageTracerProviderBuilderExtensions.cs @@ -47,7 +47,8 @@ public static TracerProviderBuilder AddPersistentStorageExporter(this TracerProv connectionString.InstrumentationKey, connectionString.TrackUri, options.LeasePeriodMilliseconds, - options.MaxBlobsPerDrain); + options.MaxBlobsPerDrain, + options.StartBackgroundDrain); return builder.AddProcessor(new SimpleActivityExportProcessor(exporter)); } } diff --git a/src/Common/CliFolderPathCalculatorCore.cs b/src/Common/CliFolderPathCalculatorCore.cs index 6072963efe3e..9f60be55c681 100644 --- a/src/Common/CliFolderPathCalculatorCore.cs +++ b/src/Common/CliFolderPathCalculatorCore.cs @@ -1,6 +1,10 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. +#if NETFRAMEWORK +using System.Runtime.InteropServices; +#endif + namespace Microsoft.DotNet.Configurer { class CliFolderPathCalculatorCore @@ -47,7 +51,7 @@ public CliFolderPathCalculatorCore(Func getEnvironmentVariable) // MSBuild tasks running with an isolated TaskEnvironment do not read ambient // process state. Mirror what Environment.GetFolderPath(SpecialFolder.UserProfile) // does internally: USERPROFILE on Windows, HOME on Unix. - var userProfileVariableName = RuntimeInformation.IsOSPlatform(OSPlatform.Windows) + var userProfileVariableName = IsWindows() ? "USERPROFILE" : "HOME"; home = _getEnvironmentVariable(userProfileVariableName); @@ -67,5 +71,14 @@ public CliFolderPathCalculatorCore(Func getEnvironmentVariable) return home; } + private static bool IsWindows() + { +#if NETFRAMEWORK + return RuntimeInformation.IsOSPlatform(OSPlatform.Windows); +#else + return OperatingSystem.IsWindows(); +#endif + } + } } diff --git a/src/Installer/dotnetup.Library/Constants.cs b/src/Installer/dotnetup.Library/Constants.cs index d4dd104a1af7..fabb117d9529 100644 --- a/src/Installer/dotnetup.Library/Constants.cs +++ b/src/Installer/dotnetup.Library/Constants.cs @@ -57,6 +57,7 @@ public static class Telemetry public const string DisableTraceExportEnvVar = "DOTNET_CLI_TELEMETRY_DISABLE_TRACE_EXPORT"; public const string DiskLogPathEnvVar = "DOTNET_CLI_TELEMETRY_LOG_PATH"; public const string EnableOtlpExporterEnvVar = "DOTNET_CLI_TELEMETRY_ENABLE_EXPORTER"; + public const string ForceLocalDeliveryEnvVar = "DOTNETUP_TELEMETRY_FORCE_LOCAL_DELIVERY"; /// /// Opt-in env var that enables network export of OTel spans via the @@ -71,5 +72,18 @@ public static class Telemetry /// Override for the on-exit flush budget, in milliseconds. /// public const string FlushTimeoutOverrideEnvVar = "DOTNETUP_TELEMETRY_FLUSH_TIMEOUT_MS"; + + /// + /// Override (ms) for the CI shutdown budget that bounds telemetry export POST wait time. + /// + public const string ShutdownTimeoutOverrideEnvVar = "DOTNET_CLI_TELEMETRY_SHUTDOWN_TIMEOUT_MS"; + + /// + /// A conditional telling dotnetup to focus on flushing telemetry as a detached process rather than execute as dotnetup. + /// + public const string DrainModeEnvVar = "DOTNETUP_TELEMETRY_DRAIN"; + + internal const string E2EConnectionStringEnvVar = "DOTNET_CLI_TELEMETRY_E2E_CONNECTION_STRING"; + internal const string TestShutdownBudgetPathEnvVar = "DOTNET_TESTHOOK_DOTNETUP_TELEMETRY_SHUTDOWN_BUDGET_PATH"; } } diff --git a/src/Installer/dotnetup.Library/DotnetupPaths.cs b/src/Installer/dotnetup.Library/DotnetupPaths.cs index e59da0f4a911..1ea7870c033c 100644 --- a/src/Installer/dotnetup.Library/DotnetupPaths.cs +++ b/src/Installer/dotnetup.Library/DotnetupPaths.cs @@ -1,6 +1,8 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. +using Microsoft.DotNet.Configurer; + namespace Microsoft.DotNet.Tools.Bootstrapper; /// @@ -120,11 +122,22 @@ public static string ManifestPath public static string TelemetrySentinelPath => Path.Combine(DataDirectory, TelemetrySentinelFileName); /// - /// Gets the path to the telemetry offline storage directory. The Azure - /// Monitor exporter uses this as its retry queue for telemetry that does - /// not drain over the network before the process exits. + /// Resolves the telemetry offline storage directory shared with the .NET SDK. + /// The SDK's environment override takes precedence over its default profile directory. /// - public static string TelemetryStorageDirectory => Path.Combine(DataDirectory, TelemetryStorageServiceFolderName); + internal static string ResolveTelemetryStorageDirectory(Func getEnvironmentVariable) + { + var environmentStoragePath = getEnvironmentVariable(Constants.Telemetry.StoragePathEnvVar); + if (!string.IsNullOrWhiteSpace(environmentStoragePath)) + { + return environmentStoragePath; + } + + var profileFolder = new CliFolderPathCalculatorCore(getEnvironmentVariable).GetDotnetUserProfileFolderPath(); + return !string.IsNullOrEmpty(profileFolder) + ? Path.Combine(profileFolder, TelemetryStorageServiceFolderName) + : throw new InvalidOperationException("Could not determine the .NET SDK telemetry storage directory."); + } /// /// Gets the path to the dotnetup telemetry disk log, or diff --git a/src/Installer/dotnetup.Library/Program.cs b/src/Installer/dotnetup.Library/Program.cs index f1202b97ec13..77a12043a3b1 100644 --- a/src/Installer/dotnetup.Library/Program.cs +++ b/src/Installer/dotnetup.Library/Program.cs @@ -18,6 +18,13 @@ public class DotnetupProgram { public static int Main(string[] args) { + // Detached telemetry-drainer fast path: deliver previously-persisted telemetry and exit, + // before any other work. See DotnetupTelemetryDrainProcess for the full delivery model. + if (DotnetupTelemetryDrainProcess.TryRunAsDrainer(out var drainExitCode)) + { + return drainExitCode; + } + // Apply the user's UI language before any output (honors DOTNET_CLI_UI_LANGUAGE/VSLANG, and // on Linux—where dotnetup runs invariant—detects the OS locale the runtime cannot). DotnetupUILanguage.Setup(); @@ -34,20 +41,7 @@ public static int Main(string[] args) // Uses the same AutomaticEncodingRestorer from the .NET SDK CLI. using AutomaticEncodingRestorer encodingRestorer = new(); ConfigureConsoleEncoding(); - - // Disable Spectre.Console line wrapping when output is redirected (piped), - // since wrapping is not useful for non-interactive consumers. - if (Console.IsOutputRedirected) - { - AnsiConsole.Profile.Width = int.MaxValue; - } - - // Set up callback to notify user when waiting for another dotnetup process. - // Write to stderr so piped stdout (e.g., print-env-script) is not corrupted. - ScopedMutex.OnWaitingForMutex = () => - { - Console.Error.WriteLine("Another dotnetup process is running. Waiting for it to finish..."); - }; + ConfigureConsoleOutput(); // Show first-run telemetry notice if needed FirstRunNotice.ShowIfFirstRun(DotnetupTelemetry.Instance.Enabled); @@ -137,4 +131,22 @@ private static void ConfigureConsoleEncoding() Console.OutputEncoding = new UTF8Encoding(encoderShouldEmitUTF8Identifier: false); } } + + /// + /// Configures console output behavior for the current invocation: disables Spectre.Console line + /// wrapping when output is redirected (piped), and routes the "waiting for another dotnetup + /// process" notice to stderr so piped stdout (e.g. print-env-script) is not corrupted. + /// + private static void ConfigureConsoleOutput() + { + if (Console.IsOutputRedirected) + { + AnsiConsole.Profile.Width = int.MaxValue; + } + + ScopedMutex.OnWaitingForMutex = () => + { + Console.Error.WriteLine("Another dotnetup process is running. Waiting for it to finish..."); + }; + } } diff --git a/src/Installer/dotnetup.Library/Telemetry/DotnetupTelemetry.cs b/src/Installer/dotnetup.Library/Telemetry/DotnetupTelemetry.cs index 4a7b0bb5f40a..6a8a694ed7f8 100644 --- a/src/Installer/dotnetup.Library/Telemetry/DotnetupTelemetry.cs +++ b/src/Installer/dotnetup.Library/Telemetry/DotnetupTelemetry.cs @@ -49,6 +49,11 @@ public sealed class DotnetupTelemetry : IDisposable private readonly ILogger? _logger; private readonly List _activities = []; + /// + /// True when telemetry needs to be drained from storage externally VS CI environments which wait to exit until a POST is complete + /// + private readonly bool _isLocalPersistDelivery; + /// /// Snapshot of process-level common properties (os.type, device.id, /// session.id, dev.build, ...). These also live on the OTel @@ -93,12 +98,13 @@ private DotnetupTelemetry() // telemetry-disabled (opt-out) path deterministically, without mutating // process-wide environment variables or depending on the Lazy singleton's // one-shot, construction-time env read. - internal DotnetupTelemetry(Func getEnvironmentVariable) + internal DotnetupTelemetry(Func getEnvironmentVariable, bool? isCIEnvironment = null) { SessionId = Guid.NewGuid().ToString(); - IsOneAndDoneEnvironment = TelemetryCommonProperties.IsCIEnvironment; + IsOneAndDoneEnvironment = !IsTruthy(getEnvironmentVariable(Constants.Telemetry.ForceLocalDeliveryEnvVar)) + && (isCIEnvironment ?? TelemetryCommonProperties.IsCIEnvironment); - Enabled = !IsTruthy(getEnvironmentVariable(Constants.Telemetry.TelemetryOptOutEnvVar)); + Enabled = !IsTelemetryOptedOut(getEnvironmentVariable); if (!Enabled) { @@ -114,16 +120,22 @@ internal DotnetupTelemetry(Func getEnvironmentVariable) var enablePerfTrace = IsTruthy(getEnvironmentVariable(Constants.Telemetry.EnablePerfTraceEnvVar)); var enableOtlpExporter = IsOtlpExporterEnabled(disableExport, getEnvironmentVariable); var debugConsole = getEnvironmentVariable("DOTNETUP_TELEMETRY_DEBUG") == "1"; - var storageDirectory = ResolveStorageDirectory(getEnvironmentVariable); + var connectionString = ResolveConnectionString(getEnvironmentVariable); + + var storageDirectory = DotnetupPaths.ResolveTelemetryStorageDirectory(getEnvironmentVariable); + var commonAttrs = BuildCommonAttributes(); _commonProperties = ToLogStateProperties(commonAttrs); var resource = BuildResource(commonAttrs); - _tracerProvider = BuildTracerProvider(resource, enablePerfTrace, enableOtlpExporter, disableExport, debugConsole, storageDirectory); - _services = BuildLoggingServices(resource, enableOtlpExporter, disableExport, debugConsole, storageDirectory); + _tracerProvider = BuildTracerProvider(resource, IsOneAndDoneEnvironment, enablePerfTrace, enableOtlpExporter, disableExport, debugConsole, storageDirectory, connectionString); + _services = BuildLoggingServices(resource, IsOneAndDoneEnvironment, enableOtlpExporter, disableExport, debugConsole, storageDirectory, connectionString); _loggerProvider = _services.GetService(); _loggerFactory = _services.GetRequiredService(); _logger = _loggerFactory.CreateLogger(Constants.Telemetry.BootstrapperSourceName); + + // Local runs persist synchronously and deliver via a detached drainer on exit. + _isLocalPersistDelivery = !IsOneAndDoneEnvironment && !disableExport && !string.IsNullOrWhiteSpace(storageDirectory); } catch (Exception) { @@ -132,12 +144,12 @@ internal DotnetupTelemetry(Func getEnvironmentVariable) } } - private static string ResolveStorageDirectory(Func getEnvironmentVariable) + internal static string ResolveConnectionString(Func getEnvironmentVariable) { - var environmentStoragePath = getEnvironmentVariable(Constants.Telemetry.StoragePathEnvVar); - return string.IsNullOrWhiteSpace(environmentStoragePath) - ? DotnetupPaths.TelemetryStorageDirectory - : environmentStoragePath; + var overrideValue = getEnvironmentVariable(Constants.Telemetry.E2EConnectionStringEnvVar); + return string.IsNullOrWhiteSpace(overrideValue) + ? Constants.Telemetry.ConnectionString + : overrideValue; } /// @@ -178,7 +190,7 @@ private static ResourceBuilder BuildResource(List> /// Builds the . /// Traces should be opt-in via DOTNETUP_CLI_GET_PERF_TRACE=1 because data-x does not ingest spans. /// - private TracerProvider BuildTracerProvider(ResourceBuilder resource, bool enablePerfTrace, bool enableOtlpExporter, bool disableExport, bool debugConsole, string storageDirectory) + private TracerProvider BuildTracerProvider(ResourceBuilder resource, bool isOneAndDone, bool enablePerfTrace, bool enableOtlpExporter, bool disableExport, bool debugConsole, string storageDirectory, string connectionString) { var builder = Sdk.CreateTracerProviderBuilder() .SetResourceBuilder(resource) @@ -198,12 +210,27 @@ private TracerProvider BuildTracerProvider(ResourceBuilder resource, bool enable { builder.AddOtlpExporter(); } - builder.AddAzureMonitorTraceExporter(o => + + if (isOneAndDone) { - o.ConnectionString = Constants.Telemetry.ConnectionString; - o.EnableLiveMetrics = false; - o.StorageDirectory = storageDirectory; - }); + // CI: Deliver telemetry before the program can fully exit as it will not rerun. + builder.AddAzureMonitorTraceExporter(o => + { + o.ConnectionString = connectionString; + o.EnableLiveMetrics = false; + o.StorageDirectory = storageDirectory; + }); + } + else + { + // Local: persist synchronously and let the detached drainer POST out of band. + builder.AddPersistentStorageExporter(o => + { + o.ConnectionString = connectionString; + o.StorageDirectory = storageDirectory; + o.StartBackgroundDrain = false; + }); + } } if (debugConsole) @@ -219,7 +246,7 @@ private TracerProvider BuildTracerProvider(ResourceBuilder resource, bool enable /// /// The AzMonitor log exporter routes data through the AppInsights traces table which is the only table data-x-platform ingests. /// - private static ServiceProvider BuildLoggingServices(ResourceBuilder resource, bool enableOtlpExporter, bool disableExport, bool debugConsole, string storageDirectory) + private static ServiceProvider BuildLoggingServices(ResourceBuilder resource, bool isOneAndDone, bool enableOtlpExporter, bool disableExport, bool debugConsole, string storageDirectory, string connectionString) { var services = new ServiceCollection(); services.AddLogging(lb => @@ -234,12 +261,25 @@ private static ServiceProvider BuildLoggingServices(ResourceBuilder resource, bo // OTLP is only for explicitly enabled local scenarios. if (!disableExport) { - o.AddAzureMonitorLogExporter(amo => + if (isOneAndDone) + { + o.AddAzureMonitorLogExporter(amo => + { + amo.ConnectionString = connectionString; + amo.EnableLiveMetrics = false; + amo.StorageDirectory = storageDirectory; + }); + } + else { - amo.ConnectionString = Constants.Telemetry.ConnectionString; - amo.EnableLiveMetrics = false; - amo.StorageDirectory = storageDirectory; - }); + o.AddPersistentStorageExporter(pso => + { + pso.ConnectionString = connectionString; + pso.StorageDirectory = storageDirectory; + pso.StartBackgroundDrain = false; + }); + } + if (enableOtlpExporter) { o.AddOtlpExporter(); @@ -371,120 +411,140 @@ private static void PropagateErrorToActivityChain(Activity? failingActivity, Exc } /// - /// Default flush budget (ms) for interactive / shell-startup exits. - /// Goal: Should not cause perceptible delay for humans. - /// Matches Aspire's CLI shutdown budget (TelemetryManager.ShutDownTimeoutMilliseconds = 200). + /// Default CI shutdown budget (ms) used when no override is set. One-and-done runs (CI / + /// piped / non-interactive) have no guaranteed next invocation to drain an offline store, so + /// they deliver inline: the tracer / logger provider Shutdown drains the Azure Monitor + /// batch exporter and waits for the in-flight HTTP POST, bounded by this budget. Matches the + /// dotnet CLI default (DOTNET_CLI_TELEMETRY_SHUTDOWN_TIMEOUT_MS). /// - private const int DefaultFlushTimeoutMs = 200; + private const int DefaultCiShutdownBudgetMs = 20000; /// - /// Durable flush budget (ms) for one-and-done environments (CI / piped / - /// non-interactive) that have no guaranteed next run to drain the offline store. + /// Teardown budget (ms) for local runs. Telemetry is already persisted synchronously as it is emitted, so shutdown only has to release the providers. + /// Based on existing flush delays such as in the Aspire CLI that have not caused detectable UX degradation /// - private const int DurableFlushTimeoutMs = 5000; + private const int LocalShutdownBudgetMs = 200; /// - /// True when the current invocation is the latency-critical shell-startup command (print-env-script) + /// Teardown budget (ms) for a successful shell-startup command. This command runs in the shell's startup path, where latency is especially visible. /// - private bool IsShellStartupCommand => - string.Equals(CurrentCommandName, "print-env-script", StringComparison.Ordinal); + private const int ShellStartupShutdownBudgetMs = 10; /// - /// Returns the ideal on-exit flush budget (ms) for the current run. + /// Teardown budget (ms) after a failed command. Allow extra time to persist the diagnostic telemetry before the process exits. /// - internal int GetFlushTimeoutMs(int exitCode) - { - var overrideValue = Environment.GetEnvironmentVariable(Constants.Telemetry.FlushTimeoutOverrideEnvVar); - if (!string.IsNullOrWhiteSpace(overrideValue) - && int.TryParse(overrideValue, NumberStyles.Integer, CultureInfo.InvariantCulture, out var forced) - && forced >= 0) - { - return forced; - } - - // Failures are essential to record and not expected in a typical use case, - // so we spend the durable budget even in interactive runs. This can hurt - // interactive exit latency on the error path; that tradeoff is deliberate - // until the persist-then-drain exporter lands and should be revisited then. - // Tracked by https://github.com/dotnet/sdk/issues/55184 (see PR #55211). - if (exitCode != 0) - { - return DurableFlushTimeoutMs; - } + private const int FailureShutdownBudgetMs = 400; - // Shell-startup hot path (don't slow down users shells) - if (IsShellStartupCommand) - { - return DefaultFlushTimeoutMs; - } + /// + /// True when the current invocation is the latency-critical shell-startup command + /// (env script, including its hidden print-env-script alias). + /// + private bool IsShellStartupCommand => + string.Equals(CurrentCommandName, "env script", StringComparison.Ordinal); - // Interactive foreground use: keep exit snappy. Redirected output is - // treated as non-interactive here, which is conservative: an agent or - // helper script driving dotnetup is redirected but effectively - // interactive and will pay the durable budget. Intentionally aggressive - // for now so we can measure delivery; revisit with the new exporter - // (https://github.com/dotnet/sdk/issues/55184). - if (!IsOneAndDoneEnvironment && !Console.IsOutputRedirected) + /// + /// Returns the CI shutdown budget (ms): the DOTNET_CLI_TELEMETRY_SHUTDOWN_TIMEOUT_MS + /// override (with the legacy DOTNETUP_TELEMETRY_FLUSH_TIMEOUT_MS as a fallback), else + /// . + /// + internal static int GetCiShutdownBudgetMs() + { + foreach (var name in new[] { Constants.Telemetry.ShutdownTimeoutOverrideEnvVar, Constants.Telemetry.FlushTimeoutOverrideEnvVar }) { - return DefaultFlushTimeoutMs; + var overrideValue = Environment.GetEnvironmentVariable(name); + if (!string.IsNullOrWhiteSpace(overrideValue) + && int.TryParse(overrideValue, NumberStyles.Integer, CultureInfo.InvariantCulture, out var forced) + && forced >= 0) + { + return forced; + } } - // CI / piped / non-interactive: one-and-done with no guaranteed next run to drain the offline store - return DurableFlushTimeoutMs; + return DefaultCiShutdownBudgetMs; } /// - /// Production flush entrypoint. Computes the budget from the process exit - /// code and the current environment (see ), - /// then drains the providers. Returns as soon as the queues are empty. + /// Returns the local shutdown budget (ms). Failures take precedence over the shell-startup fast path so their diagnostic telemetry has time to persist. + /// + internal int GetLocalShutdownBudgetMs(int exitCode) => + exitCode != 0 ? FailureShutdownBudgetMs : + IsShellStartupCommand ? ShellStartupShutdownBudgetMs : + LocalShutdownBudgetMs; + + /// + /// Production exit entrypoint. + /// + /// CI (one-and-done): shuts the providers down against the CI budget, which drains the Azure + /// Monitor batch exporter and awaits the in-flight HTTP POST so telemetry is delivered before + /// the process exits (see ). /// - /// Whatever doesn't drain in time falls back to the AzMonitor exporter's StorageDirectory retry queue. + /// Local: telemetry is already persisted synchronously, so shutdown just releases the providers. + /// A short-lived detached drainer is spawned to POST the persisted blobs. /// - /// The process exit code; a non-zero value selects the durable budget. + /// + /// The process exit code of dotnetup, to determine if it was a success or failure. + /// public void Flush(int exitCode) { - FlushCore(GetFlushTimeoutMs(exitCode)); + if (_isLocalPersistDelivery) + { + ShutdownProviders(GetLocalShutdownBudgetMs(exitCode)); + + // Skip the out-of-band drainer on the latency-critical shell-startup hot path; those + // blobs are delivered by the next dotnetup run or the SDK CLI sharing the store. + if (!IsShellStartupCommand) + { + DotnetupTelemetryDrainProcess.SpawnDetachedDrainer(); + } + + return; + } + + ShutdownProviders(GetCiShutdownBudgetMs()); } /// - /// Flushes with an explicit budget, bypassing environment classification. + /// Shuts the providers down with an explicit budget, bypassing environment classification. /// For tests and diagnostics only. /// internal void FlushWithTimeout(int timeoutMilliseconds) { - FlushCore(timeoutMilliseconds); + ShutdownProviders(timeoutMilliseconds); } /// - /// Flushes the providers against a single shared deadline. + /// Shuts the logger and tracer providers down against a single shared deadline. /// - private void FlushCore(int timeoutMilliseconds) + private void ShutdownProviders(int timeoutMilliseconds) { var budget = Math.Max(0, timeoutMilliseconds); + TelemetryTestHooks.TryWriteFile( + Constants.Telemetry.TestShutdownBudgetPathEnvVar, + $"ShutdownBudgetMs={budget}"); var deadline = Environment.TickCount64 + budget; try { // Logger first: the primary data-x signal. Each LogRecord is fully // decorated by BuildCompletionState at _logger.Log(...) time, so - // ForceFlush only has to drain an already-self-described queue. - _loggerProvider?.ForceFlush(budget); + // Shutdown only has to drain an already-self-described queue. + _loggerProvider?.Shutdown(budget); } catch { - // Never let telemetry flush failures crash the app. + // Never let telemetry shutdown failures crash the app. } try { - // Tracer gets the leftover budget so the two flushes share one + // Tracer gets the leftover budget so the two shutdowns share one // deadline rather than summing to 2× on a slow network. var remaining = (int)Math.Clamp(deadline - Environment.TickCount64, 0, budget); - _tracerProvider?.ForceFlush(remaining); + _tracerProvider?.Shutdown(remaining); } catch { - // Never let telemetry flush failures crash the app. + // Never let telemetry shutdown failures crash the app. } } @@ -683,6 +743,9 @@ private static bool IsTruthy(string? value) => string.Equals(value, "1", StringComparison.Ordinal) || string.Equals(value, "true", StringComparison.OrdinalIgnoreCase); + internal static bool IsTelemetryOptedOut(Func getEnvironmentVariable) => + IsTruthy(getEnvironmentVariable(Constants.Telemetry.TelemetryOptOutEnvVar)); + internal static bool IsOtlpExporterEnabled(bool disableExport) => IsOtlpExporterEnabled(disableExport, Environment.GetEnvironmentVariable); diff --git a/src/Installer/dotnetup.Library/Telemetry/DotnetupTelemetryDrainProcess.cs b/src/Installer/dotnetup.Library/Telemetry/DotnetupTelemetryDrainProcess.cs new file mode 100644 index 000000000000..dcf738c26da8 --- /dev/null +++ b/src/Installer/dotnetup.Library/Telemetry/DotnetupTelemetryDrainProcess.cs @@ -0,0 +1,101 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System.Diagnostics; +using Microsoft.DotNet.Cli.Telemetry; + +namespace Microsoft.DotNet.Tools.Bootstrapper.Telemetry; + +/// +/// A detached process for dotnetup's persist-then-drain telemetry to export without causing exit lag. +/// +internal static class DotnetupTelemetryDrainProcess +{ + /// + /// Upper bound on how long a detached drainer runs before giving up. + /// + private static readonly TimeSpan s_drainerLifetime = TimeSpan.FromMinutes(3); + + /// + /// When this process was launched as a detached drainer ( + /// == 1), best-effort drains persisted telemetry to Azure Monitor and returns + /// with exit code 0. Drain failures are intentionally swallowed + /// because telemetry delivery must not affect the host process. Otherwise returns + /// and does nothing. + /// + public static bool TryRunAsDrainer(out int exitCode) + { + exitCode = 0; + + if (!string.Equals(Environment.GetEnvironmentVariable(Constants.Telemetry.DrainModeEnvVar), "1", StringComparison.Ordinal)) + { + return false; + } + + if (DotnetupTelemetry.IsTelemetryOptedOut(Environment.GetEnvironmentVariable)) + { + return true; + } + + try + { + var storageDirectory = DotnetupPaths.ResolveTelemetryStorageDirectory(Environment.GetEnvironmentVariable); + var connectionString = DotnetupTelemetry.ResolveConnectionString(Environment.GetEnvironmentVariable); + + PersistentStorageTelemetryDrainer + .RunAsync(connectionString, storageDirectory, s_drainerLifetime) + .GetAwaiter() + .GetResult(); + } + catch + { + + } + return true; + } + + /// + /// Spawns a detached copy of the dotnetup executable in drain mode to deliver persisted + /// telemetry out of band, then returns without waiting. Best-effort: any failure is swallowed + /// and the persisted blobs are simply delivered by a later run instead. + /// + public static void SpawnDetachedDrainer() + { + try + { + var executablePath = Environment.ProcessPath; + + // Only relaunch the real dotnetup executable. Under test hosts or `dotnet exec` the process path is testhost/dotnet + if (string.IsNullOrEmpty(executablePath) || !IsBootstrapperExecutable(executablePath)) + { + return; + } + + var startInfo = new ProcessStartInfo + { + FileName = executablePath, + UseShellExecute = false, + CreateNoWindow = true, + WindowStyle = ProcessWindowStyle.Hidden, + // Give the child fresh stdio pipes instead of inheriting this process's console/redirect handles + RedirectStandardOutput = true, + RedirectStandardError = true, + RedirectStandardInput = true, + }; + startInfo.Environment[Constants.Telemetry.DrainModeEnvVar] = "1"; + + using var _ = Process.Start(startInfo); + } + catch + { + // Telemetry delivery must never crash or delay process exit. + } + } + + private static bool IsBootstrapperExecutable(string executablePath) + { + var name = Path.GetFileNameWithoutExtension(executablePath); + return string.Equals(name, "dotnetup", StringComparison.OrdinalIgnoreCase); + } + +} diff --git a/src/Installer/dotnetup.Library/Telemetry/TelemetryTestHooks.cs b/src/Installer/dotnetup.Library/Telemetry/TelemetryTestHooks.cs new file mode 100644 index 000000000000..5def70587865 --- /dev/null +++ b/src/Installer/dotnetup.Library/Telemetry/TelemetryTestHooks.cs @@ -0,0 +1,25 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +namespace Microsoft.DotNet.Tools.Bootstrapper.Telemetry; + +internal static class TelemetryTestHooks +{ + public static void TryWriteFile(string environmentVariableName, string content) + { + var path = Environment.GetEnvironmentVariable(environmentVariableName); + if (string.IsNullOrWhiteSpace(path)) + { + return; + } + + try + { + using var writer = new StreamWriter(new FileStream(path, FileMode.CreateNew, FileAccess.Write, FileShare.Read)); + writer.Write(content); + } + catch + { + } + } +} \ No newline at end of file diff --git a/src/Installer/dotnetup.Library/docs/dotnetup-telemetry.md b/src/Installer/dotnetup.Library/docs/dotnetup-telemetry.md index d7a1c6aec537..cbcb86705091 100644 --- a/src/Installer/dotnetup.Library/docs/dotnetup-telemetry.md +++ b/src/Installer/dotnetup.Library/docs/dotnetup-telemetry.md @@ -49,6 +49,12 @@ are not included because they may contain user-provided input. For more details on crash exception telemetry, see the [.NET CLI telemetry documentation](https://aka.ms/dotnet-cli-telemetry). +### Related Environment Variables + +- **`DOTNET_CLI_TELEMETRY_STORAGE_PATH`**: Overrides the directory used to persist telemetry locally before it is uploaded. +- **`DOTNET_CLI_TELEMETRY_SHUTDOWN_TIMEOUT_MS`**: Overrides the bounded `dotnetup` telemetry flush timeout to a custom limit. +- **`DOTNETUP_TELEMETRY_FORCE_LOCAL_DELIVERY`**: Uses local persist-and-detached-drain delivery even when CI is detected. Intended for diagnostics and end-to-end validation. + ## CI and LLM Agent Detection dotnetup uses the same CI environment detection and LLM agent detection as the diff --git a/src/Installer/dotnetup.Library/dotnetup.Library.csproj b/src/Installer/dotnetup.Library/dotnetup.Library.csproj index c88bcea4cf2e..652fb005a559 100644 --- a/src/Installer/dotnetup.Library/dotnetup.Library.csproj +++ b/src/Installer/dotnetup.Library/dotnetup.Library.csproj @@ -5,7 +5,7 @@ @@ -30,6 +30,7 @@ + @@ -68,6 +69,7 @@ + diff --git a/test/Microsoft.DotNet.Cli.Telemetry.Tests/HttpTelemetryUploadTransportTests.cs b/test/Microsoft.DotNet.Cli.Telemetry.Tests/HttpTelemetryUploadTransportTests.cs index bfae52f3254b..caaaa3c33da5 100644 --- a/test/Microsoft.DotNet.Cli.Telemetry.Tests/HttpTelemetryUploadTransportTests.cs +++ b/test/Microsoft.DotNet.Cli.Telemetry.Tests/HttpTelemetryUploadTransportTests.cs @@ -3,6 +3,7 @@ using System.IO.Compression; using System.Net; +using System.Net.Http.Headers; using System.Text; using Microsoft.DotNet.Cli.Telemetry.Implementation; @@ -41,6 +42,34 @@ public async Task ItReportsPartiallyAcceptedAndReslicesRetriableEnvelopesOn206() Encoding.UTF8.GetString(result.RetryPayload!).Should().Be("{\"env\":1}\n"); } + [TestMethod] + public async Task ItPropagatesRetryAfterOnRetriableResponse() + { + var expectedDelay = TimeSpan.FromSeconds(17); + var handler = new StubHandler(HttpStatusCode.ServiceUnavailable, retryAfter: expectedDelay); + var transport = new HttpTelemetryUploadTransport(TrackUri, handler); + + var result = await transport.TryUploadAsync([1, 2, 3], CancellationToken.None); + + result.Outcome.Should().Be(TelemetryUploadOutcome.Rejected); + result.RetryAfter.Should().Be(expectedDelay); + } + + [TestMethod] + public async Task ItPropagatesRetryAfterOnPartialAcceptance() + { + var expectedDelay = TimeSpan.FromSeconds(23); + var payload = Encoding.UTF8.GetBytes("{\"env\":0}\n"); + var body = "{\"itemsReceived\":1,\"itemsAccepted\":0,\"errors\":[{\"index\":0,\"statusCode\":500,\"message\":\"retry\"}]}"; + var handler = new StubHandler(HttpStatusCode.PartialContent, body, expectedDelay); + var transport = new HttpTelemetryUploadTransport(TrackUri, handler); + + var result = await transport.TryUploadAsync(payload, CancellationToken.None); + + result.Outcome.Should().Be(TelemetryUploadOutcome.PartiallyAccepted); + result.RetryAfter.Should().Be(expectedDelay); + } + [TestMethod] public async Task ItReportsAcceptedWhen206HasNoRetriableErrors() { @@ -67,7 +96,43 @@ public async Task ItReportsRejectedOnServerError() result.Outcome.Should().Be(TelemetryUploadOutcome.Rejected); } - private sealed class StubHandler(HttpStatusCode status, string? body = null) : HttpMessageHandler + [TestMethod] + [DataRow(HttpStatusCode.RequestTimeout)] + [DataRow(HttpStatusCode.TooManyRequests)] + [DataRow((HttpStatusCode)439)] + [DataRow(HttpStatusCode.InternalServerError)] + [DataRow(HttpStatusCode.ServiceUnavailable)] + public async Task ItReportsRejectedOnEveryRetriableWholeRequestFailure(HttpStatusCode statusCode) + { + var handler = new StubHandler(statusCode); + var transport = new HttpTelemetryUploadTransport(TrackUri, handler); + + var result = await transport.TryUploadAsync([1, 2, 3], CancellationToken.None); + + result.Outcome.Should().Be(TelemetryUploadOutcome.Rejected, + "retriable Breeze failures must retain the blob for another upload attempt"); + } + + [TestMethod] + [DataRow(HttpStatusCode.BadRequest)] + [DataRow(HttpStatusCode.Unauthorized)] + [DataRow(HttpStatusCode.Forbidden)] + [DataRow(HttpStatusCode.NotFound)] + public async Task ItReportsPermanentRejectionOnPermanentWholeRequestFailure(HttpStatusCode statusCode) + { + var handler = new StubHandler(statusCode); + var transport = new HttpTelemetryUploadTransport(TrackUri, handler); + + var result = await transport.TryUploadAsync([1, 2, 3], CancellationToken.None); + + result.Outcome.Should().Be(TelemetryUploadOutcome.PermanentlyRejected, + "permanent failures must be discarded so they do not block later blobs"); + } + + private sealed class StubHandler( + HttpStatusCode status, + string? body = null, + TimeSpan? retryAfter = null) : HttpMessageHandler { public string? RequestContentEncoding { get; private set; } public byte[]? DecompressedRequestBody { get; private set; } @@ -88,6 +153,10 @@ protected override async Task SendAsync(HttpRequestMessage { response.Content = new StringContent(body); } + if (retryAfter is not null) + { + response.Headers.RetryAfter = new RetryConditionHeaderValue(retryAfter.Value); + } return response; } } diff --git a/test/Microsoft.DotNet.Cli.Telemetry.Tests/PersistentStorageTelemetryBackgroundWorkerTests.cs b/test/Microsoft.DotNet.Cli.Telemetry.Tests/PersistentStorageTelemetryBackgroundWorkerTests.cs new file mode 100644 index 000000000000..3d08197f98a8 --- /dev/null +++ b/test/Microsoft.DotNet.Cli.Telemetry.Tests/PersistentStorageTelemetryBackgroundWorkerTests.cs @@ -0,0 +1,48 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using Microsoft.DotNet.Cli.Telemetry.Implementation; + +namespace Microsoft.DotNet.Cli.Telemetry.Tests; + +[TestClass] +public class PersistentStorageTelemetryBackgroundWorkerTests +{ + public TestContext TestContext { get; set; } + + [TestMethod] + public void StartOnce_StartsOnlyOneDrain() + { + int starts = 0; + var worker = new PersistentStorageTelemetryBackgroundWorker(_ => + { + Interlocked.Increment(ref starts); + return Task.CompletedTask; + }); + + worker.StartOnce(); + worker.StartOnce(); + + worker.Shutdown(1_000).Should().BeTrue(); + starts.Should().Be(1); + } + + [TestMethod] + public async Task Shutdown_CancelsAndWaitsForDrain() + { + var started = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + CancellationToken observedToken = default; + var worker = new PersistentStorageTelemetryBackgroundWorker(async cancellationToken => + { + observedToken = cancellationToken; + started.SetResult(); + await Task.Delay(Timeout.InfiniteTimeSpan, cancellationToken); + }); + + worker.StartOnce(); + await started.Task.WaitAsync(TimeSpan.FromSeconds(5), TestContext.CancellationToken); + + worker.Shutdown(1_000).Should().BeTrue(); + observedToken.IsCancellationRequested.Should().BeTrue(); + } +} \ No newline at end of file diff --git a/test/Microsoft.DotNet.Cli.Telemetry.Tests/PersistentStorageTelemetryDrainerTests.cs b/test/Microsoft.DotNet.Cli.Telemetry.Tests/PersistentStorageTelemetryDrainerTests.cs new file mode 100644 index 000000000000..d8c7981a6582 --- /dev/null +++ b/test/Microsoft.DotNet.Cli.Telemetry.Tests/PersistentStorageTelemetryDrainerTests.cs @@ -0,0 +1,142 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using Microsoft.DotNet.Cli.Telemetry.Implementation; + +namespace Microsoft.DotNet.Cli.Telemetry.Tests; + +[TestClass] +public class PersistentStorageTelemetryDrainerTests +{ + [TestMethod] + public async Task RunCoreAsync_EscalatesRetryDelaysAndHonorsRetryAfter() + { + var storage = new FakeBlobStorage(new FakeBlob([1])); + var transport = new FakeTransport( + TelemetryUploadResult.Rejected, + TelemetryUploadResult.Rejected, + TelemetryUploadResult.RejectedAfter(TimeSpan.FromSeconds(7)), + TelemetryUploadResult.Accepted); + var uploader = new PersistentStorageTelemetryUploader(storage, transport); + var clock = new FakeTimeProvider(); + var delays = new RecordingDelay(clock); + + await PersistentStorageTelemetryDrainer.RunCoreAsync( + uploader, + Timeout.InfiniteTimeSpan, + CancellationToken.None, + delays.DelayAsync, + clock); + + delays.RequestedDelays.Should().Equal( + TimeSpan.FromSeconds(1), + TimeSpan.FromSeconds(2), + TimeSpan.FromSeconds(7), + TimeSpan.FromMilliseconds(500)); + transport.UploadCount.Should().Be(4); + } + + [TestMethod] + public async Task RunCoreAsync_StopsAtLifetimeWithoutWaiting() + { + var storage = new FakeBlobStorage(new FakeBlob([1])); + var transport = new FakeTransport(TelemetryUploadResult.Rejected, TelemetryUploadResult.Rejected); + var uploader = new PersistentStorageTelemetryUploader(storage, transport); + var clock = new FakeTimeProvider(); + var delays = new RecordingDelay(clock); + + await PersistentStorageTelemetryDrainer.RunCoreAsync( + uploader, + TimeSpan.FromMilliseconds(1_500), + CancellationToken.None, + delays.DelayAsync, + clock); + + delays.RequestedDelays.Should().Equal(TimeSpan.FromSeconds(1), TimeSpan.FromMilliseconds(500)); + transport.UploadCount.Should().Be(2); + } + + [TestMethod] + public void TryAcquireDirectoryLock_AllowsOnlyOneActiveDrainer() + { + var directory = Path.Combine(Path.GetTempPath(), Guid.NewGuid().ToString("N")); + try + { + using (var firstLock = PersistentStorageTelemetryDrainer.TryAcquireDirectoryLock(directory)) + using (var secondLock = PersistentStorageTelemetryDrainer.TryAcquireDirectoryLock(directory)) + { + firstLock.Should().NotBeNull(); + secondLock.Should().BeNull(); + } + + } + finally + { + Directory.Delete(directory, recursive: true); + } + } + + private sealed class RecordingDelay(FakeTimeProvider clock) + { + public List RequestedDelays { get; } = []; + + public Task DelayAsync(TimeSpan delay, CancellationToken cancellationToken) + { + RequestedDelays.Add(delay); + clock.Advance(delay); + return Task.CompletedTask; + } + } + + private sealed class FakeTimeProvider : TimeProvider + { + private long _timestamp; + + public override long TimestampFrequency => TimeSpan.TicksPerSecond; + + public override long GetTimestamp() => _timestamp; + + public void Advance(TimeSpan delay) => _timestamp += delay.Ticks; + } + + private sealed class FakeBlobStorage(params FakeBlob[] blobs) : ITelemetryBlobStorage + { + public IEnumerable GetBlobs() => blobs.Where(blob => !blob.Deleted); + + public bool TryPersist(byte[] data) => true; + } + + private sealed class FakeBlob(byte[] data) : ITelemetryBlob + { + public bool Deleted { get; private set; } + + public bool TryLease(int leasePeriodMilliseconds) => !Deleted; + + public bool TryRead(out byte[]? buffer) + { + buffer = data; + return true; + } + + public bool TryRelease() => true; + + public bool TryDelete() + { + Deleted = true; + return true; + } + } + + private sealed class FakeTransport(params TelemetryUploadResult[] results) : ITelemetryUploadTransport + { + private readonly Queue _results = new(results); + + public int UploadCount { get; private set; } + + public Task TryUploadAsync(byte[] payload, CancellationToken cancellationToken) + { + UploadCount++; + return Task.FromResult(_results.Dequeue()); + } + } +} \ No newline at end of file diff --git a/test/Microsoft.DotNet.Cli.Telemetry.Tests/PersistentStorageTelemetryUploaderTests.cs b/test/Microsoft.DotNet.Cli.Telemetry.Tests/PersistentStorageTelemetryUploaderTests.cs index a0c634154b5c..345d3d23ffdf 100644 --- a/test/Microsoft.DotNet.Cli.Telemetry.Tests/PersistentStorageTelemetryUploaderTests.cs +++ b/test/Microsoft.DotNet.Cli.Telemetry.Tests/PersistentStorageTelemetryUploaderTests.cs @@ -49,6 +49,25 @@ public async Task ItRetainsBlobsWhenUploadFails() storage.Blobs.Single().Released.Should().BeTrue("failed uploads must be available to a later drain"); } + [TestMethod] + public async Task ItDeletesPermanentlyRejectedBlobAndContinuesDraining() + { + var permanentlyRejected = new FakeBlob([1, 2, 3]); + var accepted = new FakeBlob([4, 5, 6]); + var storage = new FakeBlobStorage(permanentlyRejected, accepted); + var transport = new SequenceTransport( + TelemetryUploadResult.PermanentlyRejected, + TelemetryUploadResult.Accepted); + var uploader = new PersistentStorageTelemetryUploader(storage, transport); + + var result = await uploader.DrainAsync(CancellationToken.None); + + transport.UploadCount.Should().Be(2); + permanentlyRejected.Deleted.Should().BeTrue(); + accepted.Deleted.Should().BeTrue("a poison blob must not block later telemetry"); + result.ShouldBackOff.Should().BeFalse(); + } + [TestMethod] public async Task ItReleasesLeaseWhenUploadIsCancelled() { @@ -102,13 +121,51 @@ public async Task ItPersistsRetriableRemainderAndDeletesBlobOnPartialAcceptance( var transport = new FakeTransport(TelemetryUploadResult.PartiallyAccepted(remainder)); var uploader = new PersistentStorageTelemetryUploader(storage, transport); - await uploader.DrainAsync(CancellationToken.None); + var result = await uploader.DrainAsync(CancellationToken.None); transport.UploadCount.Should().Be(1); // The original blob is deleted (its accepted portion was delivered)... storage.Blobs[0].Deleted.Should().BeTrue(); // ...and the retriable remainder is persisted as a fresh blob for a later retry. storage.Blobs.Should().ContainSingle(b => !b.Deleted && b.Data == remainder); + result.ShouldBackOff.Should().BeTrue(); + } + + [TestMethod] + public async Task ItStopsPassAndReportsRetryAfterOnRetryableResponse() + { + var expectedDelay = TimeSpan.FromSeconds(17); + var first = new FakeBlob([1, 2, 3]); + var second = new FakeBlob([4, 5, 6]); + var storage = new FakeBlobStorage(first, second); + var transport = new FakeTransport(TelemetryUploadResult.RejectedAfter(expectedDelay)); + var uploader = new PersistentStorageTelemetryUploader(storage, transport); + + var result = await uploader.DrainAsync(CancellationToken.None); + + transport.UploadCount.Should().Be(1, "the service has already asked this pass to retry later"); + first.Released.Should().BeTrue(); + second.Leased.Should().BeFalse(); + result.ForwardProgress.Should().Be(0); + result.ShouldBackOff.Should().BeTrue(); + result.RetryAfter.Should().Be(expectedDelay); + } + + [TestMethod] + public async Task ItStopsPassAndBacksOffWhenTransportThrows() + { + var first = new FakeBlob([1, 2, 3]); + var second = new FakeBlob([4, 5, 6]); + var storage = new FakeBlobStorage(first, second); + var uploader = new PersistentStorageTelemetryUploader(storage, new ThrowingTransport()); + + var result = await uploader.DrainAsync(CancellationToken.None); + + first.Released.Should().BeTrue(); + second.Leased.Should().BeFalse(); + result.ForwardProgress.Should().Be(0); + result.ShouldBackOff.Should().BeTrue(); + result.RetryAfter.Should().BeNull(); } private sealed class FakeBlobStorage(params FakeBlob[] blobs) : ITelemetryBlobStorage @@ -173,6 +230,19 @@ public Task TryUploadAsync(byte[] payload, CancellationTo } } + private sealed class SequenceTransport(params TelemetryUploadResult[] results) : ITelemetryUploadTransport + { + private readonly Queue _results = new(results); + + public int UploadCount { get; private set; } + + public Task TryUploadAsync(byte[] payload, CancellationToken cancellationToken) + { + UploadCount++; + return Task.FromResult(_results.Dequeue()); + } + } + private sealed class CancellingTransport(CancellationTokenSource cancellationSource) : ITelemetryUploadTransport { public Task TryUploadAsync(byte[] payload, CancellationToken cancellationToken) @@ -181,4 +251,10 @@ public Task TryUploadAsync(byte[] payload, CancellationTo return Task.FromCanceled(cancellationToken); } } + + private sealed class ThrowingTransport : ITelemetryUploadTransport + { + public Task TryUploadAsync(byte[] payload, CancellationToken cancellationToken) + => throw new HttpRequestException("Transient test failure."); + } } diff --git a/test/dotnetup.Tests/DotnetupTelemetryDrainProcessTests.cs b/test/dotnetup.Tests/DotnetupTelemetryDrainProcessTests.cs new file mode 100644 index 000000000000..3f3a9080a4e6 --- /dev/null +++ b/test/dotnetup.Tests/DotnetupTelemetryDrainProcessTests.cs @@ -0,0 +1,75 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using Microsoft.DotNet.Configurer; +using Microsoft.DotNet.Tools.Bootstrapper; +using Microsoft.DotNet.Tools.Bootstrapper.Telemetry; +using Microsoft.DotNet.Tools.Dotnetup.Tests; + +namespace Microsoft.DotNet.Tools.Bootstrapper.Tests; + +[TestClass] +public class DotnetupTelemetryDrainProcessTests +{ + [TestMethod] + public void ResolveTelemetryStorageDirectory_HonorsEnvOverride() + { + var expected = Path.Combine(Path.GetTempPath(), "custom-telemetry-storage"); + + var resolved = DotnetupPaths.ResolveTelemetryStorageDirectory( + name => name == Constants.Telemetry.StoragePathEnvVar ? expected : null); + + Assert.AreEqual(expected, resolved); + } + + [TestMethod] + public void ResolveTelemetryStorageDirectory_IgnoresWhitespaceOverride() + { + // A blank/whitespace override must not be treated as a real path. + var dotnetCliHome = Path.Combine(Path.GetTempPath(), "dotnet-cli-home"); + var resolved = DotnetupPaths.ResolveTelemetryStorageDirectory( + name => name switch + { + Constants.Telemetry.StoragePathEnvVar => " ", + CliFolderPathCalculatorCore.DotnetHomeVariableName => dotnetCliHome, + _ => null, + }); + + Assert.AreEqual( + Path.Combine(dotnetCliHome, CliFolderPathCalculatorCore.DotnetProfileDirectoryName, "TelemetryStorageService"), + resolved); + } + + [TestMethod] + public void ResolveTelemetryStorageDirectory_FallsBackToSdkDirectory() + { + var dotnetCliHome = Path.Combine(Path.GetTempPath(), "dotnet-cli-home"); + var resolved = DotnetupPaths.ResolveTelemetryStorageDirectory( + name => name == CliFolderPathCalculatorCore.DotnetHomeVariableName ? dotnetCliHome : null); + + Assert.IsFalse(string.IsNullOrWhiteSpace(resolved), "a storage directory must always resolve"); + Assert.AreEqual( + Path.Combine(dotnetCliHome, CliFolderPathCalculatorCore.DotnetProfileDirectoryName, "TelemetryStorageService"), + resolved); + } + + [TestMethod] + public void TryRunAsDrainer_ReturnsFalse_WhenDrainModeUnset() + { + // Unit tests never run with DOTNETUP_TELEMETRY_DRAIN=1, so this must be a no-op fast path + // that neither drains nor throws. + var ranAsDrainer = DotnetupTelemetryDrainProcess.TryRunAsDrainer(out var exitCode); + + Assert.IsFalse(ranAsDrainer); + Assert.AreEqual(0, exitCode); + } + + [TestMethod] + public void SpawnDetachedDrainer_DoesNotThrow_UnderTestHost() + { + // The test host's process path is not "dotnetup", so this must bail without spawning. + var exception = Record.Exception(DotnetupTelemetryDrainProcess.SpawnDetachedDrainer); + + Assert.IsNull(exception); + } +} diff --git a/test/dotnetup.Tests/Mocks/MockTelemetryIngestionServer.cs b/test/dotnetup.Tests/Mocks/MockTelemetryIngestionServer.cs new file mode 100644 index 000000000000..2be4d7c17c34 --- /dev/null +++ b/test/dotnetup.Tests/Mocks/MockTelemetryIngestionServer.cs @@ -0,0 +1,170 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System.Globalization; +using System.Net; +using System.Net.Sockets; +using System.Text; + +namespace Microsoft.DotNet.Tools.Dotnetup.Tests.Mocks; + +internal sealed class MockTelemetryIngestionServer : IDisposable +{ + private const int MaxHeaderBytes = 32 * 1024; + private const int MaxBodyBytes = 4 * 1024 * 1024; + private readonly TcpListener _listener = new(IPAddress.Loopback, 0); + private readonly CancellationTokenSource _cancellation = new(); + private readonly TaskCompletionSource _requestReceived = new(TaskCreationOptions.RunContinuationsAsynchronously); + private readonly Task _serverTask; + + public MockTelemetryIngestionServer() + { + _listener.Server.ExclusiveAddressUse = true; + _listener.Start(backlog: 1); + int port = ((IPEndPoint)_listener.LocalEndpoint).Port; + IngestionEndpoint = $"http://127.0.0.1:{port}/"; + _serverTask = ServeRequestsAsync(); + } + + public string IngestionEndpoint { get; } + + public Task WaitForRequestAsync(TimeSpan timeout) => _requestReceived.Task.WaitAsync(timeout); + + public void Dispose() + { + _cancellation.Cancel(); + _listener.Stop(); + _cancellation.Dispose(); + } + + private async Task ServeRequestsAsync() + { + try + { + while (!_cancellation.IsCancellationRequested) + { + using TcpClient client = await _listener.AcceptTcpClientAsync(_cancellation.Token); + if (client.Client.RemoteEndPoint is not IPEndPoint { Address: var address } + || !IPAddress.IsLoopback(address)) + { + continue; + } + + await ServeRequestAsync(client); + _requestReceived.TrySetResult(); + } + } + catch (OperationCanceledException) + { + } + catch (SocketException) when (_cancellation.IsCancellationRequested) + { + } + } + + private static async Task ServeRequestAsync(TcpClient client) + { + using NetworkStream stream = client.GetStream(); + if (await ReadHeadersAsync(stream)) + { + await ReadChunkedBodyAsync(stream); + } + + byte[] response = Encoding.ASCII.GetBytes( + "HTTP/1.1 200 OK\r\nContent-Length: 0\r\nConnection: close\r\n\r\n"); + await stream.WriteAsync(response); + await stream.FlushAsync(); + client.Client.Shutdown(SocketShutdown.Send); + } + + private static async Task ReadHeadersAsync(NetworkStream stream) + { + string requestLine = await ReadLineAsync(stream, 1024); + if (!requestLine.Equals("POST /v2.1/track HTTP/1.1", StringComparison.Ordinal)) + { + throw new InvalidDataException($"Unexpected telemetry request line: '{requestLine}'."); + } + + bool chunked = false; + int bytesRead = Encoding.ASCII.GetByteCount(requestLine) + 2; + while (true) + { + string line = await ReadLineAsync(stream, MaxHeaderBytes - bytesRead); + bytesRead += Encoding.ASCII.GetByteCount(line) + 2; + if (line.Length == 0) + { + return chunked; + } + + chunked |= line.Equals("Transfer-Encoding: chunked", StringComparison.OrdinalIgnoreCase); + } + } + + private static async Task ReadChunkedBodyAsync(NetworkStream stream) + { + int totalBytes = 0; + while (true) + { + string sizeLine = await ReadLineAsync(stream, 128); + int separator = sizeLine.IndexOf(';'); + string sizeText = separator < 0 ? sizeLine : sizeLine[..separator]; + int size = int.Parse(sizeText, NumberStyles.HexNumber, CultureInfo.InvariantCulture); + if (size == 0) + { + await ReadLineAsync(stream, MaxHeaderBytes); + return; + } + + totalBytes = checked(totalBytes + size); + if (totalBytes > MaxBodyBytes) + { + throw new InvalidDataException($"Telemetry request exceeded {MaxBodyBytes} bytes."); + } + + await ReadExactlyAsync(stream, size); + await ReadLineAsync(stream, 2); + } + } + + private static async Task ReadLineAsync(NetworkStream stream, int maxBytes) + { + var bytes = new List(); + while (true) + { + int value = await ReadByteAsync(stream); + if (value == '\n') + { + return Encoding.ASCII.GetString(bytes.ToArray()).TrimEnd('\r'); + } + + if (bytes.Count >= maxBytes) + { + throw new InvalidDataException($"HTTP line exceeded {maxBytes} bytes."); + } + + bytes.Add((byte)value); + } + } + + private static async Task ReadByteAsync(NetworkStream stream) + { + byte[] buffer = new byte[1]; + int read = await stream.ReadAsync(buffer); + return read == 0 ? throw new EndOfStreamException() : buffer[0]; + } + + private static async Task ReadExactlyAsync(NetworkStream stream, int length) + { + byte[] buffer = new byte[Math.Min(length, 8192)]; + while (length > 0) + { + int read = await stream.ReadAsync(buffer.AsMemory(0, Math.Min(length, buffer.Length))); + if (read == 0) + { + throw new EndOfStreamException(); + } + + length -= read; + } + } +} \ No newline at end of file diff --git a/test/dotnetup.Tests/TelemetryDrainE2ETests.cs b/test/dotnetup.Tests/TelemetryDrainE2ETests.cs new file mode 100644 index 000000000000..c173f053e9de --- /dev/null +++ b/test/dotnetup.Tests/TelemetryDrainE2ETests.cs @@ -0,0 +1,65 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using FluentAssertions; +using Microsoft.DotNet.Tools.Bootstrapper; +using Microsoft.DotNet.Tools.Dotnetup.Tests.Mocks; +using Microsoft.DotNet.Tools.Dotnetup.Tests.Utilities; + +namespace Microsoft.DotNet.Tools.Dotnetup.Tests; + +[TestClass] +public class TelemetryDrainE2ETests +{ + private static readonly TimeSpan s_timeout = TimeSpan.FromSeconds(20); + + [TestMethod] + public async Task NativeAotDrainMode_UploadsAndDeletesPersistedTelemetry() + { + DotnetupTestUtilities.GetNativeDotnetupExecutablePath(); + using var server = new MockTelemetryIngestionServer(); + using var environment = new TelemetryTestEnvironment(server.IngestionEndpoint); + + (int fixtureExitCode, string fixtureOutput) = environment.RunEnvScript(); + fixtureExitCode.Should().Be(0, fixtureOutput); + environment.TelemetryBlobPaths.Should().NotBeEmpty( + "the real persistent exporter should write the telemetry fixture"); + environment.EnvironmentVariables[Constants.Telemetry.DrainModeEnvVar] = "1"; + + (int exitCode, string output) = environment.RunDotnetup([]); + + exitCode.Should().Be(0, output); + await server.WaitForRequestAsync(s_timeout); + environment.TelemetryBlobPaths.Should().BeEmpty("accepted telemetry blobs should be deleted"); + } + + [TestMethod] + public async Task NativeAotNormalMode_SpawnsDetachedDrainerThatUploadsTelemetry() + { + DotnetupTestUtilities.GetNativeDotnetupExecutablePath(); + using var server = new MockTelemetryIngestionServer(); + using var environment = new TelemetryTestEnvironment(server.IngestionEndpoint); + + (int exitCode, string output) = environment.RunDotnetup(["--help"]); + + exitCode.Should().Be(0, output); + await server.WaitForRequestAsync(s_timeout); + await environment.WaitForTelemetryBlobsDeletedAsync(s_timeout); + environment.TelemetryBlobPaths.Should().BeEmpty("the detached child should delete accepted blobs"); + } + + [TestMethod] + public void NativeAotEnvScript_UsesShellStartupShutdownBudget() + { + DotnetupTestUtilities.GetNativeDotnetupExecutablePath(); + using var server = new MockTelemetryIngestionServer(); + using var environment = new TelemetryTestEnvironment(server.IngestionEndpoint); + environment.ConfigureShutdownBudgetObservation(); + + (int exitCode, string output) = environment.RunEnvScript(); + + exitCode.Should().Be(0, output); + output.Should().NotBeEmpty("env script should emit the requested PowerShell environment script"); + File.ReadAllText(environment.ShutdownBudgetPath).Should().Be("ShutdownBudgetMs=10"); + } +} \ No newline at end of file diff --git a/test/dotnetup.Tests/TelemetryTests.cs b/test/dotnetup.Tests/TelemetryTests.cs index 37044da5d057..8d147896bf1a 100644 --- a/test/dotnetup.Tests/TelemetryTests.cs +++ b/test/dotnetup.Tests/TelemetryTests.cs @@ -337,6 +337,66 @@ public void Flush_WithTimeout_DoesNotThrow() Assert.IsNull(exception); } + [TestMethod] + public void GetLocalShutdownBudgetMs_UsesShortBudgetForSuccessfulShellStartup() + { + using var telemetry = new DotnetupTelemetry(_ => "1"); + telemetry.StartTrackedCommand("env script"); + + Assert.AreEqual(10, telemetry.GetLocalShutdownBudgetMs(0)); + } + + [TestMethod] + public void GetLocalShutdownBudgetMs_UsesFailureBudgetForFailedShellStartup() + { + using var telemetry = new DotnetupTelemetry(_ => "1"); + telemetry.StartTrackedCommand("env script"); + + Assert.AreEqual(400, telemetry.GetLocalShutdownBudgetMs(1)); + } + + [TestMethod] + public void GetLocalShutdownBudgetMs_UsesDefaultBudgetForSuccessfulCommands() + { + using var telemetry = new DotnetupTelemetry(_ => "1"); + telemetry.StartTrackedCommand("install"); + + Assert.AreEqual(200, telemetry.GetLocalShutdownBudgetMs(0)); + } + + [TestMethod] + public void ForceLocalDelivery_OverridesCIEnvironmentClassification() + { + using var telemetry = new DotnetupTelemetry( + name => name == Constants.Telemetry.ForceLocalDeliveryEnvVar ? "1" : null, + isCIEnvironment: true); + + Assert.IsFalse(telemetry.IsOneAndDoneEnvironment); + } + + [TestMethod] + public void ResolveConnectionString_UsesE2EOverride() + { + const string expected = "InstrumentationKey=test;IngestionEndpoint=http://127.0.0.1/"; + + var actual = DotnetupTelemetry.ResolveConnectionString( + name => name == Constants.Telemetry.E2EConnectionStringEnvVar ? expected : null); + + Assert.AreEqual(expected, actual); + } + + [TestMethod] + [DataRow(null)] + [DataRow("")] + [DataRow(" ")] + public void ResolveConnectionString_UsesProductionDefaultForMissingOverride(string? overrideValue) + { + var actual = DotnetupTelemetry.ResolveConnectionString( + name => name == Constants.Telemetry.E2EConnectionStringEnvVar ? overrideValue : null); + + Assert.AreEqual(Constants.Telemetry.ConnectionString, actual); + } + [TestMethod] public void RecordException_AfterStartTrackedCommand_DoesNotThrow() { diff --git a/test/dotnetup.Tests/Utilities/DotnetupTestUtilities.cs b/test/dotnetup.Tests/Utilities/DotnetupTestUtilities.cs index aabbf8bede23..708d1d173846 100644 --- a/test/dotnetup.Tests/Utilities/DotnetupTestUtilities.cs +++ b/test/dotnetup.Tests/Utilities/DotnetupTestUtilities.cs @@ -318,6 +318,18 @@ public static string GetDotnetupExecutablePath() $"or 'dotnet build src/Installer/dotnetup/dotnetup.csproj -c {configuration}' for the managed binary."); } + public static string GetNativeDotnetupExecutablePath() + { + string path = GetDotnetupExecutablePath(); + if (!string.Equals(Path.GetFileName(Path.GetDirectoryName(path)), "publish", StringComparison.OrdinalIgnoreCase)) + { + throw new FileNotFoundException( + $"Native AOT dotnetup executable not found. Expected a published executable, but resolved '{path}'."); + } + + return path; + } + /// /// Runs the dotnetup executable as a separate process /// diff --git a/test/dotnetup.Tests/Utilities/TelemetryTestEnvironment.cs b/test/dotnetup.Tests/Utilities/TelemetryTestEnvironment.cs new file mode 100644 index 000000000000..76ba502e6339 --- /dev/null +++ b/test/dotnetup.Tests/Utilities/TelemetryTestEnvironment.cs @@ -0,0 +1,82 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using Microsoft.DotNet.Tools.Bootstrapper; + +namespace Microsoft.DotNet.Tools.Dotnetup.Tests.Utilities; + +internal sealed class TelemetryTestEnvironment : IDisposable +{ + private readonly TestEnvironment _testEnvironment = new(); + + public TelemetryTestEnvironment(string ingestionEndpoint) + { + StorageDirectory = Path.Combine(TempRoot, "telemetry"); + ShutdownBudgetPath = Path.Combine(TempRoot, "shutdown-budget.txt"); + EnvironmentVariables = new Dictionary + { + [Constants.Telemetry.TelemetryOptOutEnvVar] = "0", + [Constants.Telemetry.StoragePathEnvVar] = StorageDirectory, + [Constants.Telemetry.ForceLocalDeliveryEnvVar] = "1", + [Constants.Telemetry.DrainModeEnvVar] = "0", + ["DOTNET_TESTHOOK_DOTNETUP_DATA_DIR"] = Path.Combine(TempRoot, "data"), + [Constants.Telemetry.E2EConnectionStringEnvVar] = + $"InstrumentationKey=00000000-0000-0000-0000-000000000000;IngestionEndpoint={ingestionEndpoint}", + ["NO_PROXY"] = "127.0.0.1", + }; + } + + public string TempRoot => _testEnvironment.TempRoot; + public string StorageDirectory { get; } + public string ShutdownBudgetPath { get; } + public Dictionary EnvironmentVariables { get; } + + public string[] TelemetryBlobPaths => + Directory.Exists(StorageDirectory) + ? Directory.GetFiles(StorageDirectory, "*.blob*") + : []; + + public (int exitCode, string output) RunDotnetup(string[] args) => + DotnetupTestUtilities.RunDotnetupProcess( + args, + captureOutput: true, + workingDirectory: TempRoot, + environmentVariables: EnvironmentVariables); + + public (int exitCode, string output) RunEnvScript() => + RunDotnetup( + ["env", "script", "--shell", "pwsh", "--dotnet-install-path", _testEnvironment.InstallPath]); + + public void ConfigureShutdownBudgetObservation() => + EnvironmentVariables[Constants.Telemetry.TestShutdownBudgetPathEnvVar] = ShutdownBudgetPath; + + public async Task WaitForTelemetryBlobsDeletedAsync(TimeSpan timeout) + { + if (TelemetryBlobPaths.Length == 0) + { + return; + } + + var completion = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + using var watcher = new FileSystemWatcher(StorageDirectory, "*.blob*"); + FileSystemEventHandler onChange = (_, _) => + { + if (TelemetryBlobPaths.Length == 0) + { + completion.TrySetResult(); + } + }; + watcher.Deleted += onChange; + watcher.Renamed += (_, _) => onChange(null!, null!); + watcher.EnableRaisingEvents = true; + + if (TelemetryBlobPaths.Length == 0) + { + return; + } + + await completion.Task.WaitAsync(timeout); + } + + public void Dispose() => _testEnvironment.Dispose(); +} \ No newline at end of file