Skip to content

Commit 8437ea1

Browse files
authored
Add DownloadFileSB timeout and progress logging (#1597)
1 parent 0413210 commit 8437ea1

File tree

4 files changed

+126
-11
lines changed

4 files changed

+126
-11
lines changed

Directory.Build.props

Lines changed: 0 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -44,11 +44,8 @@
4444
<PackagesDir Condition="'$(NuGetPackageRoot)' != ''">$(NuGetPackageRoot)</PackagesDir>
4545
<PackagesDir Condition="'$(PackagesDir)' == ''">$(ProjectDir)packages/restored/</PackagesDir>
4646
<ArcadeBootstrapPackageDir>$(PackagesDir)ArcadeBootstrapPackage/</ArcadeBootstrapPackageDir>
47-
<!-- if we're not currently building, Visual Studio will still set this -->
48-
<SDK_VERSION Condition="'$(SDK_VERSION)' == ''">$(NETCoreSdkVersion)</SDK_VERSION>
4947
<DotNetSdkDir>$(DotNetCliToolDir)sdk/$(SDK_VERSION)/</DotNetSdkDir>
5048
<DotNetSdkResolversDir>$(DotNetSdkDir)SdkResolvers/</DotNetSdkResolversDir>
51-
<SdkReferenceDir>$(DotNetCliToolDir)sdk/$(SDK_VERSION)/</SdkReferenceDir>
5249
</PropertyGroup>
5350

5451
<!--

build.proj

Lines changed: 12 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -149,17 +149,27 @@
149149
<Target Name="DownloadSourceBuildReferencePackages"
150150
AfterTargets="Build"
151151
Condition="'$(OfflineBuild)' != 'true' and '$(OS)' != 'Windows_NT' and '$(SkipDownloadingReferencePackages)' != 'true'">
152+
<PropertyGroup Condition="'$(DownloadSourceBuildReferencePackagesTimeoutSeconds)' == ''">
153+
<DownloadSourceBuildReferencePackagesTimeoutSeconds>600</DownloadSourceBuildReferencePackagesTimeoutSeconds>
154+
</PropertyGroup>
155+
152156
<DownloadFileSB
153157
SourceUrl="$(ReferencePackagesTarballUrl)$(ReferencePackagesTarballName).$(PrivateSourceBuildReferencePackagesPackageVersion).tar.gz"
154-
DestinationFolder="$(ExternalTarballsDir)" />
158+
DestinationFolder="$(ExternalTarballsDir)"
159+
TimeoutSeconds="$(DownloadSourceBuildReferencePackagesTimeoutSeconds)" />
155160
</Target>
156161

157162
<Target Name="DownloadSourceBuiltArtifacts"
158163
AfterTargets="Build"
159164
Condition="'$(OfflineBuild)' != 'true' and '$(OS)' != 'Windows_NT' and '$(SkipDownloadingPreviouslySourceBuiltPackages)' != 'true'">
165+
<PropertyGroup Condition="'$(DownloadSourceBuiltArtifactsTimeoutSeconds)' == ''">
166+
<DownloadSourceBuiltArtifactsTimeoutSeconds>600</DownloadSourceBuiltArtifactsTimeoutSeconds>
167+
</PropertyGroup>
168+
160169
<DownloadFileSB
161170
SourceUrl="$(SourceBuiltArtifactsTarballUrl)$(SourceBuiltArtifactsTarballName).$(PrivateSourceBuiltArtifactsPackageVersion).tar.gz"
162-
DestinationFolder="$(ExternalTarballsDir)" />
171+
DestinationFolder="$(ExternalTarballsDir)"
172+
TimeoutSeconds="$(DownloadSourceBuiltArtifactsTimeoutSeconds)" />
163173
</Target>
164174

165175
<!-- After building, generate a prebuilt usage report. -->

tools-local/tasks/Directory.Build.props

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,20 @@
66
<Platform>AnyCPU</Platform>
77
</PropertyGroup>
88

9+
<PropertyGroup>
10+
<SdkReferenceDir Condition="'$(SDK_VERSION)' != ''">$(DotNetCliToolDir)sdk/$(SDK_VERSION)/</SdkReferenceDir>
11+
</PropertyGroup>
12+
13+
<!--
14+
If building in Visual Studio and the current SDK version isn't located in the repo (e.g. due to
15+
roll-forward using a global install) or SDK_VERSION isn't defined at all, try searching for any
16+
version to use as a fallback. The match just needs to be good enough to develop in: there isn't
17+
a scenario where we build a task in Visual Studio then try to run it.
18+
-->
19+
<PropertyGroup Condition="!Exists('$(SdkReferenceDir)') and '$(VisualStudioVersion)' != ''">
20+
<SdkReferenceDir>$(DotNetCliToolDir)sdk\*\</SdkReferenceDir>
21+
</PropertyGroup>
22+
923
<!--
1024
Use some assemblies from the SDK, instead of package references. This ensures they match what's
1125
found when the task is loaded by the SDK's MSBuild.

tools-local/tasks/Microsoft.DotNet.SourceBuild.Tasks.XPlat/DownloadFileSB.cs

Lines changed: 100 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -1,9 +1,10 @@
11
// Copyright (c) Microsoft. All rights reserved.
22
// Licensed under the MIT license. See LICENSE file in the project root for full license information.
33

4-
/// This task is sourced from https://github.com/microsoft/msbuild/blob/04e508c36f9c1fe826264aef7c26ffb8f16e9bdc/src/Tasks/DownloadFile.cs
5-
/// It alleviates the problem of time outs on DownloadFile Task. We are not the version of msbuild that has this fix, hence we have to locally
6-
/// build it to get rid of the issue.
4+
// This task is sourced from https://github.com/microsoft/msbuild/blob/04e508c36f9c1fe826264aef7c26ffb8f16e9bdc/src/Tasks/DownloadFile.cs
5+
// Contains further modifications in followup commits.
6+
// It alleviates the problem of time outs on DownloadFile Task. We are not the version of msbuild that has this fix, hence we have to locally
7+
// build it to get rid of the issue.
78

89
using Microsoft.Build.Framework;
910
using Microsoft.Build.Utilities;
@@ -63,6 +64,14 @@ public sealed class DownloadFileSB : BuildTask, ICancelableTask
6364
[Required]
6465
public string SourceUrl { get; set; }
6566

67+
/// <summary>
68+
/// Gets or sets the timeout for a successful download. If exceeded, the download continues
69+
/// for another two timeout durations before failing. This makes it sometimes possible to
70+
/// determine whether the timeout is just a little too short, or if the download would never
71+
/// have finished.
72+
/// </summary>
73+
public string TimeoutSeconds { get; set; }
74+
6675
/// <summary>
6776
/// Gets or sets a <see cref="HttpMessageHandler"/> to use. This is used by unit tests to mock a connection to a remote server.
6877
/// </summary>
@@ -88,10 +97,25 @@ private async Task<bool> ExecuteAsync()
8897
}
8998

9099
int retryAttemptCount = 0;
91-
100+
92101
CancellationToken cancellationToken = _cancellationTokenSource.Token;
93102

94-
while(true)
103+
var startTime = DateTime.UtcNow;
104+
105+
// Use the same API for the "success timeout" and the "would it ever succeed" timeout.
106+
var timeout = TimeSpan.Zero;
107+
var successCancellationTokenSource = new CancellationTokenSource();
108+
109+
if (double.TryParse(TimeoutSeconds, out double timeoutSeconds))
110+
{
111+
timeout = TimeSpan.FromSeconds(timeoutSeconds);
112+
Log.LogMessage(MessageImportance.High, $"DownloadFileSB timeout set to {timeout}");
113+
114+
successCancellationTokenSource.CancelAfter(timeout);
115+
_cancellationTokenSource.CancelAfter((int)(timeout.TotalMilliseconds * 3));
116+
}
117+
118+
while (true)
95119
{
96120
try
97121
{
@@ -129,6 +153,35 @@ private async Task<bool> ExecuteAsync()
129153
}
130154
}
131155

156+
var finishTime = DateTime.UtcNow;
157+
158+
if (successCancellationTokenSource.IsCancellationRequested)
159+
{
160+
string error = $"{TimeoutSeconds} second timeout exceeded";
161+
162+
if (!_cancellationTokenSource.IsCancellationRequested)
163+
{
164+
error +=
165+
$", but download completed after {finishTime - startTime}. " +
166+
$"Try increasing timeout from {TimeoutSeconds} if this is acceptable.";
167+
}
168+
else
169+
{
170+
error +=
171+
$", and didn't complete within leeway after {finishTime - startTime}. " +
172+
$"The download was likely never going to terminate. Investigate logs and " +
173+
$"add additional logging if necessary.";
174+
}
175+
176+
Log.LogError(error);
177+
}
178+
else
179+
{
180+
Log.LogMessage(
181+
MessageImportance.High,
182+
$"DownloadFileSB.Downloading Complete! Elapsed: {finishTime - startTime}");
183+
}
184+
132185
return !_cancellationTokenSource.IsCancellationRequested && !Log.HasLoggedErrors;
133186
}
134187

@@ -175,19 +228,58 @@ private async Task DownloadAsync(Uri uri, CancellationToken cancellationToken)
175228
return;
176229
}
177230

231+
var progressMonitorCancellationTokenSource = new CancellationTokenSource();
232+
CancellationToken progressMonitorToken = progressMonitorCancellationTokenSource.Token;
233+
178234
try
179235
{
180236
cancellationToken.ThrowIfCancellationRequested();
181237

238+
var startTime = DateTime.UtcNow;
239+
240+
var progressMonitor = Task.Run(
241+
async () =>
242+
{
243+
while (!progressMonitorToken.IsCancellationRequested)
244+
{
245+
destinationFile.Refresh();
246+
if (destinationFile.Exists)
247+
{
248+
long current = destinationFile.Length;
249+
long total = response.Content.Headers.ContentLength ?? 1;
250+
var elapsed = DateTime.UtcNow - startTime;
251+
double kbytesPerSecond = current / elapsed.TotalSeconds / 1000.0;
252+
253+
Log.LogMessage(
254+
MessageImportance.High,
255+
$"Progress... {elapsed}, " +
256+
$"current file size {current / (double)total:00.0%} " +
257+
$"({destinationFile.Length:#,0} / {total:#,0}) " +
258+
$"~ {kbytesPerSecond:#,0.00} kB/s");
259+
}
260+
await Task.Delay(TimeSpan.FromSeconds(5), progressMonitorToken);
261+
}
262+
},
263+
progressMonitorToken)
264+
.ConfigureAwait(false);
265+
182266
using (var target = new FileStream(destinationFile.FullName, FileMode.Create, FileAccess.Write, FileShare.None))
183267
{
184-
Log.LogMessage(MessageImportance.High, $"DownloadFileSB.Downloading {SourceUrl}", destinationFile.FullName, response.Content.Headers.ContentLength);
268+
Log.LogMessage(
269+
MessageImportance.High,
270+
$"DownloadFileSB.Downloading {SourceUrl} to " +
271+
$"{destinationFile.FullName}");
272+
273+
Log.LogMessage( MessageImportance.Low, $"All response headers:\n{response.Headers}");
274+
Log.LogMessage( MessageImportance.Low, $"All content headers:\n{response.Content.Headers}");
185275

186276
using (Stream responseStream = await response.Content.ReadAsStreamAsync().ConfigureAwait(false))
187277
{
188278
await responseStream.CopyToAsync(target, 1024, cancellationToken).ConfigureAwait(false);
189279
}
190280

281+
Log.LogMessage(MessageImportance.High, $"DownloadFileSB.StreamCopyComplete {SourceUrl}");
282+
191283
DownloadedFile = new TaskItem(destinationFile.FullName);
192284
}
193285
}
@@ -200,6 +292,8 @@ private async Task DownloadAsync(Uri uri, CancellationToken cancellationToken)
200292
// on success but we are concerned about the added I/O
201293
destinationFile.Delete();
202294
}
295+
296+
progressMonitorCancellationTokenSource.Cancel();
203297
}
204298
}
205299
}

0 commit comments

Comments
 (0)