Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[Investigation - DO NOT MERGE] Added logging to suppressions - gold bar 3138 #3155

Closed
wants to merge 1 commit into from
Closed

[Investigation - DO NOT MERGE] Added logging to suppressions - gold bar 3138 #3155

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
21 changes: 21 additions & 0 deletions src/Integration.Vsix/Analysis/AnalysisConfigMonitor.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,9 @@

using System;
using System.ComponentModel.Composition;
using System.Diagnostics;
using System.Runtime.CompilerServices;
using System.Threading;
using SonarLint.VisualStudio.Core;
using SonarLint.VisualStudio.Core.Analysis;
using SonarLint.VisualStudio.Core.Binding;
Expand Down Expand Up @@ -80,12 +83,24 @@ private void OnSuppressionsUpdated(object sender, EventArgs e)
{
// NB assumes exception handling is done by the AnalysisRequester
logger.WriteLine(AnalysisStrings.ConfigMonitor_SuppressionsUpdated);

var timer = Stopwatch.StartNew();
Log("Raising analysis config changed event...");
RaiseConfigChangedEvent();
Log($"Event handling finished. Elapsed: {timer.ElapsedMilliseconds}ms");

timer = Stopwatch.StartNew();
Log("Requesting re-analysis...");
analysisRequester.RequestAnalysis();
Log($"Returned from requesting re-analysis. Elapsed: {timer.ElapsedMilliseconds}ms");
}

private void RaiseConfigChangedEvent()
{
if (ConfigChanged == null)
{
Log("No event listeners");
}
ConfigChanged?.Invoke(this, EventArgs.Empty);
}

Expand All @@ -112,5 +127,11 @@ public void Dispose()
Dispose(true);
}
#endregion

private void Log(string message, [CallerMemberName] string callerMemberName = null)
{
var text = $"[AnalysisConfig] [{callerMemberName}] [Thread: {Thread.CurrentThread.ManagedThreadId}, {DateTime.Now.ToString("hh:mm:ss.fff")}] {message}";
logger.WriteLine(text);
}
}
}
35 changes: 31 additions & 4 deletions src/Integration/Suppression/SonarQubeIssuesProvider.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,12 +23,14 @@
using System.Diagnostics;
using System.IO;
using System.Linq;
using System.Runtime.CompilerServices;
using System.Threading;
using System.Threading.Tasks;
using SonarLint.VisualStudio.Core;
using SonarLint.VisualStudio.Core.Suppression;
using SonarLint.VisualStudio.Core.SystemAbstractions;
using SonarLint.VisualStudio.Infrastructure.VS;
using SonarLint.VisualStudio.Integration.Helpers;
using SonarQube.Client;
using SonarQube.Client.Models;

Expand Down Expand Up @@ -93,6 +95,8 @@ internal SonarQubeIssuesProvider(ISonarQubeService sonarQubeService, string sona
refreshTimer.Elapsed += OnRefreshTimerElapsed;

this.initialFetch = DoInitialFetchAsync();

Log("Starting refresh timer");
refreshTimer.Start();
}

Expand All @@ -112,12 +116,16 @@ public void Dispose()

public IEnumerable<SonarQubeIssue> GetSuppressedIssues(string projectGuid, string filePath)
{
// Block the call while the cache is being built.
// Block the call while the cache is being built.
// If the task has already completed then this will return immediately
// (e.g. on subsequent calls)
// If we time out waiting for the initial fetch then we won't suppress any issues.
// We'll try to fetch the issues again when the timer elapses.

var timer = Stopwatch.StartNew();
Log("Waiting for initial fetch...");
this.initialFetch?.Wait(MillisecondsToWaitForInitialFetch);
Log($"Finished waiting for initial fetch. Elapsed: {timer.ElapsedMilliseconds}ms");

if (this.suppressedFileIssues == null ||
this.isDisposed)
Expand Down Expand Up @@ -150,8 +158,12 @@ public async Task<IEnumerable<SonarQubeIssue>> GetAllSuppressedIssuesAsync()
// (e.g. on subsequent calls)
// If we time out waiting for the initial fetch then we won't suppress any issues.
// We'll try to fetch the issues again when the timer elapses.


var timer = Stopwatch.StartNew();
Log("Waiting for initial fetch...");
this.initialFetch?.Wait(MillisecondsToWaitForInitialFetch);
Log($"Finished waiting for initial fetch. Elapsed: {timer.ElapsedMilliseconds}ms");

return allSuppressedIssues ?? Enumerable.Empty<SonarQubeIssue>();
}

Expand All @@ -171,18 +183,23 @@ private string BuildModuleKey(string projectGuid)

private async void OnRefreshTimerElapsed(object sender, TimerEventArgs e)
{
Log("Refresh timer elapsed - synchronizing.");
await SynchronizeSuppressedIssuesAsync();
}

private async Task DoInitialFetchAsync()
{
Log("[Initial fetch] Starting ...");
await threadHandling.SwitchToBackgroundThread();
Log("[Initial fetch] Switched to background thread");

// We might not have connected to the server at this point so if necessary
// wait before trying to fetch the issues
Log("[Initial fetch] Checking for connection to server...");
int retryCount = 0;
while (!this.sonarQubeService.IsConnected && retryCount < 30)
{

Log($"[Initial fetch] Spinning - waiting for connection to service: {retryCount}");
if (this.isDisposed)
{
return;
Expand All @@ -191,16 +208,19 @@ private async Task DoInitialFetchAsync()
retryCount++;
}

Log("[Initial fetch] Connected.");
await SynchronizeSuppressedIssuesAsync();
Log("[Initial fetch] Finished.");
}

private async Task SynchronizeSuppressedIssuesAsync()
{
var timer = Stopwatch.StartNew();
Log("Synchronzing...");
try
{
if (!this.sonarQubeService.IsConnected)
{

this.logger.WriteLine(Resources.Strings.Suppressions_NotConnected);
return;
}
Expand Down Expand Up @@ -233,6 +253,7 @@ private async Task SynchronizeSuppressedIssuesAsync()
// Suppress the error - on a background thread so there isn't much else we can do
this.logger.WriteLine(Resources.Strings.Suppressions_ERROR_Fetching, ex.Message);
}
Log($"Finished Synchronizing. Elapsed: {timer.ElapsedMilliseconds}ms");
}

private string ProcessKey(Dictionary<string, string> keyToPath, SonarQubeIssue issue)
Expand All @@ -253,5 +274,11 @@ private string ProcessKey(Dictionary<string, string> keyToPath, SonarQubeIssue i

return filePathRelativeToRoot;
}

private void Log(string message, [CallerMemberName] string callerMemberName = null)
{
var text = $"[Suppressions] [{callerMemberName}] [Thread: {Thread.CurrentThread.ManagedThreadId}, {DateTime.Now.ToString("hh:mm:ss.fff")}] {message}";
logger.WriteLine(text);
}
}
}
61 changes: 55 additions & 6 deletions src/TypeScript/Analyzer/EslintBridgeAnalyzer.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,7 +20,10 @@

using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.IO;
using System.Linq;
using System.Runtime.CompilerServices;
using System.Threading;
using System.Threading.Tasks;
using SonarLint.VisualStudio.Core;
Expand Down Expand Up @@ -73,32 +76,50 @@ public EslintBridgeAnalyzer(

public async Task<IReadOnlyCollection<IAnalysisIssue>> Analyze(string filePath, string tsConfig, CancellationToken cancellationToken)
{
var fileName = Path.GetFileName(filePath);
LogWithFileName($"sStarting analysis...");
var timer = Stopwatch.StartNew();

await EnsureEslintBridgeClientIsInitialized(cancellationToken);
var analysisResponse = await eslintBridgeClient.Analyze(filePath, tsConfig, cancellationToken);

if (LinterNotInitializedResponse(analysisResponse))
{
Log($"[{fileName}] Linter not initialized response received. Triggering initialization and re-analysis...");

LogWithFileName($"[Inner analysis] Start");
var innerTimer = Stopwatch.StartNew();

// The call to `EnsureEslintBridgeClientIsInitialized` above doesn't guarantee the client is correctly initialized (e.g. the external process might have crashed).
// So we still need to handle the "not initialised" case here.
RequireLinterUpdate();
await EnsureEslintBridgeClientIsInitialized(cancellationToken);
analysisResponse = await eslintBridgeClient.Analyze(filePath, tsConfig, cancellationToken);
LogWithFileName($"[Inner analysis] Stop. Elapsed: {timer.ElapsedMilliseconds}ms");
}

IReadOnlyCollection<IAnalysisIssue> issues;

if (analysisResponse.ParsingError != null)
{
LogParsingError(filePath, analysisResponse.ParsingError);
return Array.Empty<IAnalysisIssue>();
issues = Array.Empty<IAnalysisIssue>();
}

if (analysisResponse.Issues == null)
else if (analysisResponse.Issues == null)
{
return Array.Empty<IAnalysisIssue>();
issues = Array.Empty<IAnalysisIssue>();
}
else
{
LogWithFileName($"Converting issues... Running total: {timer.ElapsedMilliseconds}ms");
issues = ConvertIssues(filePath, analysisResponse.Issues);
LogWithFileName($"Finished converting issues. Running total: {timer.ElapsedMilliseconds}ms");
}

var issues = ConvertIssues(filePath, analysisResponse.Issues);

Log($"[{fileName}] Finished analysis. Elapsed: {timer.ElapsedMilliseconds}ms");
return issues;

void LogWithFileName(string message) => Log($"[{fileName}] {message}");
}

private static bool LinterNotInitializedResponse(AnalysisResponse analysisResponse)
Expand All @@ -109,20 +130,28 @@ private static bool LinterNotInitializedResponse(AnalysisResponse analysisRespon

private async Task EnsureEslintBridgeClientIsInitialized(CancellationToken cancellationToken)
{
Log("Ensuring eslintbridge is initialized...");
var timer = Stopwatch.StartNew();

try
{
Log("Waiting to acquire lock...");
serverInitLocker.WaitOne();
Log($"Lock acquired. Running total: {timer.ElapsedMilliseconds}ms");

if (shouldInitLinter)
{
Log("Calling InitLinter...");
await eslintBridgeClient.InitLinter(rulesProvider.GetActiveRulesConfiguration(), cancellationToken);
shouldInitLinter = false;
Log($"InitLinter finished. Running total: {timer.ElapsedMilliseconds}ms");
}
}
finally
{
serverInitLocker.Set();
}
Log($"eslintbridege is initialized. Elapsed: {timer.ElapsedMilliseconds}ms");
}

public void Dispose()
Expand All @@ -145,20 +174,34 @@ private async void ActiveSolutionTracker_ActiveSolutionChanged(object sender, Ac

private void AnalysisConfigMonitor_ConfigChanged(object sender, EventArgs e)
{
Log("Handling analysis config changed event...");
var timer = Stopwatch.StartNew();
RequireLinterUpdate();
Log($"Event handled. Elapsed: {timer.ElapsedMilliseconds}ms");
}

private async Task StopServer()
{
Log("Stopping server...");
var timer = Stopwatch.StartNew();

RequireLinterUpdate();
await eslintBridgeClient.Close();
Log($"Server stopped. Elapsed: {timer.ElapsedMilliseconds}ms");
}

private void RequireLinterUpdate()
{
Log("Start");
var timer = Stopwatch.StartNew();

Log("Waiting to acquire lock...");
serverInitLocker.WaitOne();
Log($"Lock acquired. Running total: {timer.ElapsedMilliseconds}ms");

shouldInitLinter = true;
serverInitLocker.Set();
Log($"Stop.Elapsed: {timer.ElapsedMilliseconds}ms");
}

/// <summary>
Expand All @@ -183,5 +226,11 @@ private void LogParsingError(string path, ParsingError parsingError)

private IReadOnlyCollection<IAnalysisIssue> ConvertIssues(string filePath, IEnumerable<Issue> analysisResponseIssues) =>
analysisResponseIssues.Select(x => issueConverter.Convert(filePath, x)).ToList();

private void Log(string message, [CallerMemberName] string callerMemberName = null)
{
var text = $"[{this.GetType().Name}] [{callerMemberName}] [Thread: {Thread.CurrentThread.ManagedThreadId}, {DateTime.Now.ToString("hh:mm:ss.fff")}] {message}";
logger.WriteLine(text);
}
}
}