private void EmitRestoreTelemetryEvent(IEnumerable <NuGetProject> projects,
bool forceRestore,
RestoreOperationSource source,
DateTimeOffset startTime,
double duration,
PackageSourceTelemetry.Totals protocolDiagnosticTotals,
IntervalTracker intervalTimingTracker)
{
var sortedProjects = projects.OrderBy(
project => project.GetMetadata <string>(NuGetProjectMetadataKeys.UniqueName));
var projectIds = sortedProjects.Select(
project => project.GetMetadata <string>(NuGetProjectMetadataKeys.ProjectId)).ToArray();
var restoreTelemetryEvent = new RestoreTelemetryEvent(
_nuGetProjectContext.OperationId.ToString(),
projectIds,
forceRestore,
source,
startTime,
_status,
_packageCount,
_upToDateProjectCount,
_noOpProjectsCount,
DateTimeOffset.Now,
duration,
intervalTimingTracker);
TelemetryActivity.EmitTelemetryEvent(restoreTelemetryEvent);
var sources = _sourceRepositoryProvider.PackageSourceProvider.LoadPackageSources().ToList();
var sourceEvent = SourceTelemetry.GetRestoreSourceSummaryEvent(_nuGetProjectContext.OperationId, sources, protocolDiagnosticTotals);
TelemetryActivity.EmitTelemetryEvent(sourceEvent);
}
public void GetIntervals_When_one_interval_is_not_disposed_It_returns_empty()
{
var tracker = new IntervalTracker("Activity");
_ = tracker.Start("foo");
Assert.Equal(0, tracker.GetIntervals().Count());
}
public void GetIntervals_WhenNoIntervalsAreCaptured_ReturnsEmpty()
{
// Setup
var tracker = new IntervalTracker();
// Act - do nothing
// Assert
Assert.Equal(0, tracker.GetIntervals().Count());
}
public void RestoreTelemetryService_EmitRestoreEvent_IntervalsAreCaptured()
{
// Arrange
var first = "first";
var second = "second";
var telemetrySession = new Mock <ITelemetrySession>();
TelemetryEvent lastTelemetryEvent = null;
telemetrySession
.Setup(x => x.PostEvent(It.IsAny <TelemetryEvent>()))
.Callback <TelemetryEvent>(x => lastTelemetryEvent = x);
var tracker = new IntervalTracker("Activity");
using (tracker.Start(first))
{
}
using (tracker.Start(second))
{
}
var operationId = Guid.NewGuid().ToString();
var restoreTelemetryData = new RestoreTelemetryEvent(
operationId,
projectIds: new[] { Guid.NewGuid().ToString() },
forceRestore: false,
source: RestoreOperationSource.OnBuild,
startTime: DateTimeOffset.Now.AddSeconds(-3),
status: NuGetOperationStatus.Succeeded,
packageCount: 1,
noOpProjectsCount: 0,
upToDateProjectsCount: 0,
endTime: DateTimeOffset.Now,
duration: 2.10,
isSolutionLoadRestore: true,
tracker
);
var service = new NuGetVSTelemetryService(telemetrySession.Object);
// Act
service.EmitTelemetryEvent(restoreTelemetryData);
// Assert
Assert.NotNull(lastTelemetryEvent);
Assert.Equal(RestoreTelemetryEvent.RestoreActionEventName, lastTelemetryEvent.Name);
Assert.Equal(15, lastTelemetryEvent.Count);
Assert.Equal(restoreTelemetryData.OperationSource.ToString(), lastTelemetryEvent["OperationSource"].ToString());
Assert.Equal(restoreTelemetryData.NoOpProjectsCount, (int)lastTelemetryEvent["NoOpProjectsCount"]);
Assert.Equal(restoreTelemetryData[first], lastTelemetryEvent[first]);
Assert.Equal(restoreTelemetryData[second], lastTelemetryEvent[second]);
}
public void GetIntervals_WhenNoEndIntervalMeasureIsCalled_ReturnsEmpty()
{
// Setup
var tracker = new IntervalTracker();
// Act - do nothing
tracker.StartIntervalMeasure();
tracker.StartIntervalMeasure();
tracker.StartIntervalMeasure();
// Assert
Assert.Equal(0, tracker.GetIntervals().Count());
}
private void EmitRestoreTelemetryEvent(IEnumerable <NuGetProject> projects,
bool forceRestore,
RestoreOperationSource source,
DateTimeOffset startTime,
double duration,
PackageSourceTelemetry.Totals protocolDiagnosticTotals,
IntervalTracker intervalTimingTracker)
{
var sortedProjects = projects.OrderBy(
project => project.GetMetadata <string>(NuGetProjectMetadataKeys.UniqueName));
var projectIds = sortedProjects.Select(
project => project.GetMetadata <string>(NuGetProjectMetadataKeys.ProjectId)).ToArray();
var projectDictionary = sortedProjects
.GroupBy(x => x.ProjectStyle)
.ToDictionary(x => x.Key, y => y.Count());
var packageSourceMapping = PackageSourceMapping.GetPackageSourceMapping(_settings);
bool isPackageSourceMappingEnabled = packageSourceMapping?.IsEnabled ?? false;
var restoreTelemetryEvent = new RestoreTelemetryEvent(
_nuGetProjectContext.OperationId.ToString(),
projectIds,
forceRestore,
source,
startTime,
_status,
packageCount: _packageCount,
noOpProjectsCount: _noOpProjectsCount,
upToDateProjectsCount: _upToDateProjectCount,
unknownProjectsCount: projectDictionary.GetValueOrDefault(ProjectStyle.Unknown, 0), // appears in DependencyGraphRestoreUtility
projectJsonProjectsCount: projectDictionary.GetValueOrDefault(ProjectStyle.ProjectJson, 0),
packageReferenceProjectsCount: projectDictionary.GetValueOrDefault(ProjectStyle.PackageReference, 0),
legacyPackageReferenceProjectsCount: sortedProjects.Where(x => x.ProjectStyle == ProjectStyle.PackageReference && x is LegacyPackageReferenceProject).Count(),
cpsPackageReferenceProjectsCount: sortedProjects.Where(x => x.ProjectStyle == ProjectStyle.PackageReference && x is CpsPackageReferenceProject).Count(),
dotnetCliToolProjectsCount: projectDictionary.GetValueOrDefault(ProjectStyle.DotnetCliTool, 0), // appears in DependencyGraphRestoreUtility
packagesConfigProjectsCount: projectDictionary.GetValueOrDefault(ProjectStyle.PackagesConfig, 0),
DateTimeOffset.Now,
duration,
_trackingData,
intervalTimingTracker,
isPackageSourceMappingEnabled);
TelemetryActivity.EmitTelemetryEvent(restoreTelemetryEvent);
var sources = _sourceRepositoryProvider.PackageSourceProvider.LoadPackageSources().ToList();
var sourceEvent = SourceTelemetry.GetRestoreSourceSummaryEvent(_nuGetProjectContext.OperationId, sources, protocolDiagnosticTotals);
TelemetryActivity.EmitTelemetryEvent(sourceEvent);
}
public void GetIntervals_WhenStartIntervalIsNotCalled_IntervalsAreEmpty()
{
// Setup
var tracker = new IntervalTracker();
// Act - do nothing
tracker.EndIntervalMeasure("one");
tracker.EndIntervalMeasure("two");
// Assert
var allTimings = tracker.GetIntervals().ToList();
Assert.Equal(2, allTimings.Count);
Assert.True(allTimings.All(e => e.Item2.Equals(0)));
}
public void IntervalTracker_All_properly_disposed_intervals_are_captured()
{
var tracker = new IntervalTracker("Activity");
using (tracker.Start("first"))
{
}
using (tracker.Start("second"))
{
}
using (tracker.Start("third"))
{
}
var allTimings = tracker.GetIntervals().ToList();
Assert.Equal(3, allTimings.Count);
Assert.True(allTimings.Any(e => e.Item1.Equals("first")));
Assert.True(allTimings.Any(e => e.Item1.Equals("second")));
Assert.True(allTimings.Any(e => e.Item1.Equals("third")));
}
public void IntervalTracker_AllIntervalsAreCaptured()
{
// Setup
var tracker = new IntervalTracker();
// Act
tracker.StartIntervalMeasure();
tracker.EndIntervalMeasure("first");
tracker.StartIntervalMeasure();
tracker.EndIntervalMeasure("second");
tracker.StartIntervalMeasure();
tracker.EndIntervalMeasure("third");
// Assert
var allTimings = tracker.GetIntervals().ToList();
Assert.Equal(3, allTimings.Count);
Assert.True(allTimings.Any(e => e.Item1.Equals("first")));
Assert.True(allTimings.Any(e => e.Item1.Equals("second")));
Assert.True(allTimings.Any(e => e.Item1.Equals("third")));
}
private async Task RestorePackageSpecProjectsAsync(
List <IDependencyGraphProject> projects,
bool forceRestore,
bool isSolutionAvailable,
RestoreOperationSource restoreSource,
IntervalTracker intervalTracker,
CancellationToken token)
{
// Only continue if there are some build integrated type projects.
if (!(projects.Any(project => project is BuildIntegratedNuGetProject)))
{
return;
}
if (_packageRestoreConsent.IsGranted)
{
if (!isSolutionAvailable)
{
var globalPackagesFolder = SettingsUtility.GetGlobalPackagesFolder(_settings);
if (!Path.IsPathRooted(globalPackagesFolder))
{
var message = string.Format(
CultureInfo.CurrentCulture,
Resources.RelativeGlobalPackagesFolder,
globalPackagesFolder);
await _logger.WriteLineAsync(VerbosityLevel.Quiet, message);
// Cannot restore packages since globalPackagesFolder is a relative path
// and the solution is not available
return;
}
}
DependencyGraphCacheContext cacheContext;
DependencyGraphSpec originalDgSpec;
DependencyGraphSpec dgSpec;
IReadOnlyList <IAssetsLogMessage> additionalMessages;
using (intervalTracker.Start(RestoreTelemetryEvent.SolutionDependencyGraphSpecCreation))
{
// Cache p2ps discovered from DTE
cacheContext = new DependencyGraphCacheContext(_logger, _settings);
var pathContext = NuGetPathContext.Create(_settings);
// Get full dg spec
(originalDgSpec, additionalMessages) = await DependencyGraphRestoreUtility.GetSolutionRestoreSpecAndAdditionalMessages(_solutionManager, cacheContext);
}
using (intervalTracker.Start(RestoreTelemetryEvent.SolutionUpToDateCheck))
{
// Run solution based up to date check.
var projectsNeedingRestore = _solutionUpToDateChecker.PerformUpToDateCheck(originalDgSpec, _logger).AsList();
var specialReferencesCount = originalDgSpec.Projects
.Where(x => x.RestoreMetadata.ProjectStyle != ProjectStyle.PackageReference && x.RestoreMetadata.ProjectStyle != ProjectStyle.PackagesConfig && x.RestoreMetadata.ProjectStyle != ProjectStyle.ProjectJson)
.Count();
dgSpec = originalDgSpec;
// Only use the optimization results if the restore is not `force`.
// Still run the optimization check anyways to prep the cache.
if (!forceRestore)
{
// Update the dg spec.
dgSpec = originalDgSpec.WithoutRestores();
foreach (var uniqueProjectId in projectsNeedingRestore)
{
dgSpec.AddRestore(uniqueProjectId); // Fill DGSpec copy only with restore-needed projects
}
// Calculate the number of up to date projects
_upToDateProjectCount = originalDgSpec.Restore.Count - specialReferencesCount - projectsNeedingRestore.Count;
_noOpProjectsCount = _upToDateProjectCount;
}
}
using (intervalTracker.Start(RestoreTelemetryEvent.PackageReferenceRestoreDuration))
{
// Avoid restoring if all the projects are up to date, or the solution does not have build integrated projects.
if (DependencyGraphRestoreUtility.IsRestoreRequired(dgSpec))
{
// NOTE: During restore for build integrated projects,
// We might show the dialog even if there are no packages to restore
// When both currentStep and totalSteps are 0, we get a marquee on the dialog
await _logger.RunWithProgressAsync(
async (l, _, t) =>
{
// Display the restore opt out message if it has not been shown yet
await l.WriteHeaderAsync();
var sources = _sourceRepositoryProvider
.GetRepositories()
.ToList();
var providerCache = new RestoreCommandProvidersCache();
Action <SourceCacheContext> cacheModifier = (cache) => { };
var isRestoreOriginalAction = true;
var isRestoreSucceeded = true;
IReadOnlyList <RestoreSummary> restoreSummaries = null;
try
{
restoreSummaries = await DependencyGraphRestoreUtility.RestoreAsync(
_solutionManager,
dgSpec,
cacheContext,
providerCache,
cacheModifier,
sources,
_nuGetProjectContext.OperationId,
forceRestore,
isRestoreOriginalAction,
additionalMessages,
l,
t);
_packageCount += restoreSummaries.Select(summary => summary.InstallCount).Sum();
isRestoreSucceeded = restoreSummaries.All(summary => summary.Success == true);
_noOpProjectsCount += restoreSummaries.Where(summary => summary.NoOpRestore == true).Count();
_solutionUpToDateChecker.SaveRestoreStatus(restoreSummaries);
}
catch
{
isRestoreSucceeded = false;
throw;
}
finally
{
if (isRestoreSucceeded)
{
if (_noOpProjectsCount < restoreSummaries.Count)
{
_status = NuGetOperationStatus.Succeeded;
}
else
{
_status = NuGetOperationStatus.NoOp;
}
}
else
{
_status = NuGetOperationStatus.Failed;
}
}
},
token);
}
}
}
else if (restoreSource == RestoreOperationSource.Explicit)
{
await _logger.ShowErrorAsync(Resources.PackageRefNotRestoredBecauseOfNoConsent);
}
}
private async Task RestoreAsync(bool forceRestore, RestoreOperationSource restoreSource, CancellationToken token)
{
var startTime = DateTimeOffset.Now;
_status = NuGetOperationStatus.NoOp;
// start timer for telemetry event
var stopWatch = Stopwatch.StartNew();
var intervalTracker = new IntervalTracker(RestoreTelemetryEvent.RestoreActionEventName);
var projects = Enumerable.Empty <NuGetProject>();
_packageRestoreManager.PackageRestoredEvent += PackageRestoreManager_PackageRestored;
_packageRestoreManager.PackageRestoreFailedEvent += PackageRestoreManager_PackageRestoreFailedEvent;
var sources = _sourceRepositoryProvider.GetRepositories();
using (var packageSourceTelemetry = new PackageSourceTelemetry(sources, _nuGetProjectContext.OperationId, PackageSourceTelemetry.TelemetryAction.Restore))
{
try
{
token.ThrowIfCancellationRequested();
string solutionDirectory;
bool isSolutionAvailable;
using (intervalTracker.Start(RestoreTelemetryEvent.RestoreOperationChecks))
{
solutionDirectory = _solutionManager.SolutionDirectory;
isSolutionAvailable = await _solutionManager.IsSolutionAvailableAsync();
// Get the projects from the SolutionManager
// Note that projects that are not supported by NuGet, will not show up in this list
projects = (await _solutionManager.GetNuGetProjectsAsync()).ToList();
if (projects.Any() && solutionDirectory == null)
{
_status = NuGetOperationStatus.Failed;
await _logger.ShowErrorAsync(Resources.SolutionIsNotSaved);
await _logger.WriteLineAsync(VerbosityLevel.Minimal, Resources.SolutionIsNotSaved);
return;
}
}
using (intervalTracker.Start(RestoreTelemetryEvent.PackagesConfigRestore))
{
// Check if there are any projects that are not INuGetIntegratedProject, that is,
// projects with packages.config. OR
// any of the deferred project is type of packages.config, If so, perform package restore on them
if (projects.Any(project => !(project is INuGetIntegratedProject)))
{
await RestorePackagesOrCheckForMissingPackagesAsync(
projects,
solutionDirectory,
isSolutionAvailable,
restoreSource,
token);
}
}
var dependencyGraphProjects = projects
.OfType <IDependencyGraphProject>()
.ToList();
await RestorePackageSpecProjectsAsync(
dependencyGraphProjects,
forceRestore,
isSolutionAvailable,
restoreSource,
intervalTracker,
token);
// TODO: To limit risk, we only publish the event when there is a cross-platform PackageReference
// project in the solution. Extending this behavior to all solutions is tracked here:
// NuGet/Home#4478
if (projects.OfType <CpsPackageReferenceProject>().Any())
{
_restoreEventsPublisher.OnSolutionRestoreCompleted(
new SolutionRestoredEventArgs(_status, solutionDirectory));
}
}
catch (OperationCanceledException)
{
_status = NuGetOperationStatus.Cancelled;
throw;
}
catch
{
_status = NuGetOperationStatus.Failed;
throw;
}
finally
{
_packageRestoreManager.PackageRestoredEvent -= PackageRestoreManager_PackageRestored;
_packageRestoreManager.PackageRestoreFailedEvent -= PackageRestoreManager_PackageRestoreFailedEvent;
await packageSourceTelemetry.SendTelemetryAsync();
stopWatch.Stop();
var duration = stopWatch.Elapsed;
// Do not log any restore message if user disabled restore.
if (_packageRestoreConsent.IsGranted)
{
await _logger.WriteSummaryAsync(_status, duration);
}
else
{
_logger.LogDebug(Resources.PackageRefNotRestoredBecauseOfNoConsent);
}
var protocolDiagnosticsTotals = packageSourceTelemetry.GetTotals();
// Emit telemetry event for restore operation
EmitRestoreTelemetryEvent(
projects,
forceRestore,
restoreSource,
startTime,
duration.TotalSeconds,
protocolDiagnosticsTotals,
intervalTracker);
}
}
}
public void RestoreTelemetryService_EmitRestoreEvent_IntervalsAreCaptured(string _packageSourceMapping)
{
// Arrange
var first = "first";
var second = "second";
var telemetrySession = new Mock <ITelemetrySession>();
TelemetryEvent lastTelemetryEvent = null;
telemetrySession
.Setup(x => x.PostEvent(It.IsAny <TelemetryEvent>()))
.Callback <TelemetryEvent>(x => lastTelemetryEvent = x);
var tracker = new IntervalTracker("Activity");
using (tracker.Start(first))
{
}
using (tracker.Start(second))
{
}
var operationId = Guid.NewGuid().ToString();
var packageSourceMapping = string.IsNullOrEmpty(_packageSourceMapping) ? null : PackageSourceMappingUtility.GetpackageSourceMapping(_packageSourceMapping);
bool isPackageSourceMappingEnabled = packageSourceMapping?.IsEnabled ?? false;
var restoreTelemetryData = new RestoreTelemetryEvent(
operationId,
projectIds: new[] { Guid.NewGuid().ToString() },
forceRestore: false,
source: RestoreOperationSource.OnBuild,
startTime: DateTimeOffset.Now.AddSeconds(-3),
status: NuGetOperationStatus.Succeeded,
packageCount: 1,
noOpProjectsCount: 0,
upToDateProjectsCount: 0,
unknownProjectsCount: 0,
projectJsonProjectsCount: 0,
packageReferenceProjectsCount: 1,
legacyPackageReferenceProjectsCount: 0,
cpsPackageReferenceProjectsCount: 1,
dotnetCliToolProjectsCount: 0,
packagesConfigProjectsCount: 0,
endTime: DateTimeOffset.Now,
duration: 2.10,
additionalTrackingData: new Dictionary <string, object>()
{
{ nameof(RestoreTelemetryEvent.IsSolutionLoadRestore), true }
},
tracker,
isPackageSourceMappingEnabled: isPackageSourceMappingEnabled);
var service = new NuGetVSTelemetryService(telemetrySession.Object);
// Act
service.EmitTelemetryEvent(restoreTelemetryData);
// Assert
Assert.NotNull(lastTelemetryEvent);
Assert.Equal(RestoreTelemetryEvent.RestoreActionEventName, lastTelemetryEvent.Name);
Assert.Equal(23, lastTelemetryEvent.Count);
Assert.Equal(restoreTelemetryData.OperationSource.ToString(), lastTelemetryEvent["OperationSource"].ToString());
Assert.Equal(restoreTelemetryData.NoOpProjectsCount, (int)lastTelemetryEvent["NoOpProjectsCount"]);
Assert.Equal(restoreTelemetryData[first], lastTelemetryEvent[first]);
Assert.Equal(restoreTelemetryData[second], lastTelemetryEvent[second]);
}
private async Task RestorePackageSpecProjectsAsync(
List <IDependencyGraphProject> projects,
bool forceRestore,
bool isSolutionAvailable,
RestoreOperationSource restoreSource,
IntervalTracker intervalTracker,
CancellationToken token)
{
// Only continue if there are some build integrated type projects.
if (!(projects.Any(project => project is BuildIntegratedNuGetProject)))
{
return;
}
if (_packageRestoreConsent.IsGranted)
{
if (!isSolutionAvailable)
{
var globalPackagesFolder = SettingsUtility.GetGlobalPackagesFolder(_settings);
if (!Path.IsPathRooted(globalPackagesFolder))
{
var message = string.Format(
CultureInfo.CurrentCulture,
Resources.RelativeGlobalPackagesFolder,
globalPackagesFolder);
await _logger.WriteLineAsync(VerbosityLevel.Quiet, message);
// Cannot restore packages since globalPackagesFolder is a relative path
// and the solution is not available
return;
}
}
intervalTracker.StartIntervalMeasure();
// Cache p2ps discovered from DTE
var cacheContext = new DependencyGraphCacheContext(_logger, _settings);
var pathContext = NuGetPathContext.Create(_settings);
// Get full dg spec
var(dgSpec, additionalMessages) = await DependencyGraphRestoreUtility.GetSolutionRestoreSpecAndAdditionalMessages(_solutionManager, cacheContext);
intervalTracker.EndIntervalMeasure(RestoreTelemetryEvent.SolutionDependencyGraphSpecCreation);
intervalTracker.StartIntervalMeasure();
// Avoid restoring solutions with zero potential PackageReference projects.
if (DependencyGraphRestoreUtility.IsRestoreRequired(dgSpec))
{
// NOTE: During restore for build integrated projects,
// We might show the dialog even if there are no packages to restore
// When both currentStep and totalSteps are 0, we get a marquee on the dialog
await _logger.RunWithProgressAsync(
async (l, _, t) =>
{
// Display the restore opt out message if it has not been shown yet
await l.WriteHeaderAsync();
var sources = _sourceRepositoryProvider
.GetRepositories()
.ToList();
var providerCache = new RestoreCommandProvidersCache();
Action <SourceCacheContext> cacheModifier = (cache) => { };
var isRestoreOriginalAction = true;
var restoreSummaries = await DependencyGraphRestoreUtility.RestoreAsync(
_solutionManager,
dgSpec,
cacheContext,
providerCache,
cacheModifier,
sources,
_nuGetProjectContext.OperationId,
forceRestore,
isRestoreOriginalAction,
additionalMessages,
l,
t);
_packageCount += restoreSummaries.Select(summary => summary.InstallCount).Sum();
var isRestoreFailed = restoreSummaries.Any(summary => summary.Success == false);
_noOpProjectsCount = restoreSummaries.Where(summary => summary.NoOpRestore == true).Count();
if (isRestoreFailed)
{
_status = NuGetOperationStatus.Failed;
}
else if (_noOpProjectsCount < restoreSummaries.Count)
{
_status = NuGetOperationStatus.Succeeded;
}
},
token);
}
intervalTracker.EndIntervalMeasure(RestoreTelemetryEvent.PackageReferenceRestoreDuration);
}
else if (restoreSource == RestoreOperationSource.Explicit)
{
_logger.ShowError(Resources.PackageRefNotRestoredBecauseOfNoConsent);
}
}
public void GetIntervals_When_no_intervals_are_captured_It_returns_empty()
{
var tracker = new IntervalTracker("Activity");
Assert.Equal(0, tracker.GetIntervals().Count());
}
