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

SLVS-1722 Log extra properties of SLCore log events #5924

Draft
wants to merge 3 commits into
base: gb/log-context
Choose a base branch
from
Draft

SLVS-1722 Log extra properties of SLCore log events #5924

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
7460162
SLVS-1722 Log extra properties of SLCore log events
georgii-borovinskikh-sonarsource Dec 24, 2024
61b7920
add tests adn fix bugs
georgii-borovinskikh-sonarsource Dec 24, 2024
77eab71
deserialization tests
georgii-borovinskikh-sonarsource Dec 24, 2024
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
102 changes: 90 additions & 12 deletions src/SLCore.Listeners.UnitTests/Logging/LoggerListenerTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -28,16 +28,12 @@ namespace SonarLint.VisualStudio.SLCore.Listeners.UnitTests.Logging
public class LoggerListenerTests
{
[TestMethod]
public void MefCtor_CheckIsExported()
{
public void MefCtor_CheckIsExported() =>
MefTestHelpers.CheckTypeCanBeImported<LoggerListener, ISLCoreListener>(MefTestHelpers.CreateExport<ILogger>());
}

[TestMethod]
public void Mef_CheckIsSingleton()
{
public void Mef_CheckIsSingleton() =>
MefTestHelpers.CheckIsSingletonMefComponent<LoggerListener>();
}

[TestMethod]
[DataRow(LogLevel.ERROR, false)]
Expand All @@ -55,14 +51,96 @@ public void Log_LogInfoTraceAndDebugAsVerbose(LogLevel logLevel, bool verboseLog

testSubject.Log(param);

if (verboseLogs)
logger.AssertOutputStringExists(verboseLogs ? "[DEBUG] [SLCore > Logs] some Message" : "[SLCore > Logs] some Message");
}

[TestMethod]
public void Ctor_AddsProperties()
{
var logger = Substitute.For<ILogger>();
_ = new LoggerListener(logger);

logger.Received(1).ForContext(SLCoreStrings.SLCoreName, SLCoreStrings.SLCoreInternalLogContext);
}

[TestMethod]
public void Log_AddsArgumentProperties()
{
var customizedLogger = Substitute.For<ILogger>();
var logger = Substitute.For<ILogger>();
logger.ForContext(SLCoreStrings.SLCoreName, SLCoreStrings.SLCoreInternalLogContext).Returns(customizedLogger);
var testSubject = new LoggerListener(logger);

testSubject.Log(new LogParams{configScopeId = "configScopeId1", loggerName = "loggerName1", threadName = "threadName1"});
testSubject.Log(new LogParams{configScopeId = "configScopeId2", loggerName = "loggerName2", threadName = "threadName2"});

customizedLogger.Received(1).ForVerboseContext("loggerName1", "configScopeId1", "threadName1");
customizedLogger.Received(1).ForVerboseContext("loggerName2", "configScopeId2", "threadName2");
}

[TestMethod]
public void Log_ProducesCorrectFullFormat()
{
var testLogger = new TestLogger(logVerbose:false);
var testSubject = new LoggerListener(testLogger);

testSubject.Log(new LogParams
{
logger.AssertOutputStringExists("[DEBUG] [SLCORE] some Message");
}
else
loggerName = "loggerName",
configScopeId = "configScopeId",
threadName = "threadName",
message = "message",
stackTrace = """
stack
trace
"""
});

testLogger.AssertOutputStrings("[SLCore > Logs] message");
}

[TestMethod]
public void Log_ProducesCorrectFullVerboseFormat()
{
var testLogger = new TestLogger();
var testSubject = new LoggerListener(testLogger);

testSubject.Log(new LogParams
{
logger.AssertOutputStringExists("[SLCORE] some Message");
}
loggerName = "loggerName",
configScopeId = "configScopeId",
threadName = "threadName",
message = "message",
stackTrace = """
stack
trace
"""
});

testLogger.AssertOutputStrings(
"[SLCore > Logs] [loggerName > configScopeId > threadName] message",
"""
[DEBUG] [SLCore > Logs] [loggerName > configScopeId > threadName] stack
trace
""");
}

[TestMethod]
public void Log_NullablePropertiesMissing_ProducesCorrectMessage()
{
var testLogger = new TestLogger();
var testSubject = new LoggerListener(testLogger);

testSubject.Log(new LogParams
{
loggerName = "loggerName",
configScopeId = null,
threadName = "threadName",
message = "message",
stackTrace = null
});

testLogger.AssertOutputStrings("[SLCore > Logs] [loggerName > threadName] message");
}
}
}
29 changes: 29 additions & 0 deletions src/SLCore.Listeners.UnitTests/Logging/LoggerSerializationTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,7 @@

namespace SonarLint.VisualStudio.SLCore.Listeners.UnitTests.Logging
{
[TestClass]
public class LoggerSerializationTests
{
[TestMethod]
Expand Down Expand Up @@ -56,5 +57,33 @@ public void DeSerializeLogParams_StringEnums(string level, LogLevel expectedLeve
result.message.Should().Be("Some Message");
result.level.Should().Be(expectedLevel);
}

[TestMethod]
public void DeserializeExtraProperties()
{
const string serialzied =
"""
{
"level": "ERROR",
"message": "Unable to load plugin ...\\storageRoot\\68747470733a2f2f736f6e6172636c6f75642e696f2f6f7267616e697a6174696f6e732f64756e63616e702d736f6e61722d74657374\\plugins\\sonarlint-license-plugin-8.0.0.58632-all.jar",
"configScopeId": "SLVS_Bound_VS2019",
"threadName": "SonarLint Server RPC request executor",
"loggerName": "sonarlint",
"stackTrace": "java.lang.IllegalStateException: Error while reading plugin manifest from jar: ...\\storageRoot\\68747470733a2f2f736f6e6172636c6f75642e696f2f6f7267616e697a6174696f6e732f64756e63616e702d736f6e61722d74657374\\plugins\\sonarlint-license-plugin-8.0.0.58632-all.jar\r\n\tat org.sonarsource.sonarlint.core.plugin.commons.loading.SonarPluginManifest.fromJar(SonarPluginManifest.java:105)\r\n\tat org.sonarsource.sonarlint.core.plugin.commons.loading.PluginInfo.create(PluginInfo.java:221)\r\n\tat org.sonarsource.sonarlint.core.plugin.commons.loading.SonarPluginRequirementsChecker.checkRequirements(SonarPluginRequirementsChecker.java:64)\r\n\tat org.sonarsource.sonarlint.core.plugin.commons.PluginsLoader.load(PluginsLoader.java:65)\r\n\tat org.sonarsource.sonarlint.core.plugin.PluginsService.loadPlugins(PluginsService.java:189)\r\n\tat org.sonarsource.sonarlint.core.plugin.PluginsService.loadPlugins(PluginsService.java:147)\r\n\tat org.sonarsource.sonarlint.core.plugin.PluginsService.getPlugins(PluginsService.java:136)\r\n\tat org.sonarsource.sonarlint.core.analysis.AnalysisEngineCache.lambda$getOrCreateConnectedEngine$2(AnalysisEngineCache.java:97)\r\n\tat java.base/java.util.concurrent.ConcurrentHashMap.computeIfAbsent(Unknown Source)\r\n\tat org.sonarsource.sonarlint.core.analysis.AnalysisEngineCache.getOrCreateConnectedEngine(AnalysisEngineCache.java:96)\r\n\tat org.sonarsource.sonarlint.core.analysis.AnalysisEngineCache.lambda$getOrCreateAnalysisEngine$1(AnalysisEngineCache.java:91)\r\n\tat java.base/java.util.Optional.map(Unknown Source)\r\n\tat org.sonarsource.sonarlint.core.analysis.AnalysisEngineCache.getOrCreateAnalysisEngine(AnalysisEngineCache.java:91)\r\n\tat org.sonarsource.sonarlint.core.analysis.AnalysisService.analyze(AnalysisService.java:647)\r\n\tat org.sonarsource.sonarlint.core.rpc.impl.AnalysisRpcServiceDelegate.lambda$analyzeFilesAndTrack$8(AnalysisRpcServiceDelegate.java:143)\r\n\tat org.sonarsource.sonarlint.core.rpc.impl.AbstractRpcServiceDelegate.lambda$requestAsync$0(AbstractRpcServiceDelegate.java:67)\r\n\tat org.sonarsource.sonarlint.core.rpc.impl.AbstractRpcServiceDelegate.computeWithLogger(AbstractRpcServiceDelegate.java:135)\r\n\tat org.sonarsource.sonarlint.core.rpc.impl.AbstractRpcServiceDelegate.lambda$requestAsync$1(AbstractRpcServiceDelegate.java:65)\r\n\tat java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(Unknown Source)\r\n\tat java.base/java.util.concurrent.CompletableFuture$Completion.run(Unknown Source)\r\n\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)\r\n\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)\r\n\tat java.base/java.lang.Thread.run(Unknown Source)\r\nCaused by: java.nio.file.NoSuchFileException: C:\\Users\\georgii.borovinskikh\\AppData\\Local\\SLVS_SLOOP\\storageRoot\\68747470733a2f2f736f6e6172636c6f75642e696f2f6f7267616e697a6174696f6e732f64756e63616e702d736f6e61722d74657374\\plugins\\sonarlint-license-plugin-8.0.0.58632-all.jar\r\n\tat java.base/sun.nio.fs.WindowsException.translateToIOException(Unknown Source)\r\n\tat java.base/sun.nio.fs.WindowsException.rethrowAsIOException(Unknown Source)\r\n\tat java.base/sun.nio.fs.WindowsException.rethrowAsIOException(Unknown Source)\r\n\tat java.base/sun.nio.fs.WindowsFileAttributeViews$Basic.readAttributes(Unknown Source)\r\n\tat java.base/sun.nio.fs.WindowsFileAttributeViews$Basic.readAttributes(Unknown Source)\r\n\tat java.base/sun.nio.fs.WindowsFileSystemProvider.readAttributes(Unknown Source)\r\n\tat java.base/java.nio.file.Files.readAttributes(Unknown Source)\r\n\tat java.base/java.util.zip.ZipFile$Source.get(Unknown Source)\r\n\tat java.base/java.util.zip.ZipFile$CleanableResource.<init>(Unknown Source)\r\n\tat java.base/java.util.zip.ZipFile.<init>(Unknown Source)\r\n\tat java.base/java.util.zip.ZipFile.<init>(Unknown Source)\r\n\tat java.base/java.util.jar.JarFile.<init>(Unknown Source)\r\n\tat java.base/java.util.jar.JarFile.<init>(Unknown Source)\r\n\tat java.base/java.util.jar.JarFile.<init>(Unknown Source)\r\n\tat org.sonarsource.sonarlint.core.plugin.commons.loading.SonarPluginManifest.fromJar(SonarPluginManifest.java:97)\r\n\t... 22 more\r\n",
"loggedAt": 1734968894643
}
""";
var expected = new LogParams
{
message = "Unable to load plugin ...\\storageRoot\\68747470733a2f2f736f6e6172636c6f75642e696f2f6f7267616e697a6174696f6e732f64756e63616e702d736f6e61722d74657374\\plugins\\sonarlint-license-plugin-8.0.0.58632-all.jar",
level = LogLevel.ERROR,
configScopeId = "SLVS_Bound_VS2019",
threadName = "SonarLint Server RPC request executor",
loggerName = "sonarlint",
stackTrace = "java.lang.IllegalStateException: Error while reading plugin manifest from jar: ...\\storageRoot\\68747470733a2f2f736f6e6172636c6f75642e696f2f6f7267616e697a6174696f6e732f64756e63616e702d736f6e61722d74657374\\plugins\\sonarlint-license-plugin-8.0.0.58632-all.jar\r\n\tat org.sonarsource.sonarlint.core.plugin.commons.loading.SonarPluginManifest.fromJar(SonarPluginManifest.java:105)\r\n\tat org.sonarsource.sonarlint.core.plugin.commons.loading.PluginInfo.create(PluginInfo.java:221)\r\n\tat org.sonarsource.sonarlint.core.plugin.commons.loading.SonarPluginRequirementsChecker.checkRequirements(SonarPluginRequirementsChecker.java:64)\r\n\tat org.sonarsource.sonarlint.core.plugin.commons.PluginsLoader.load(PluginsLoader.java:65)\r\n\tat org.sonarsource.sonarlint.core.plugin.PluginsService.loadPlugins(PluginsService.java:189)\r\n\tat org.sonarsource.sonarlint.core.plugin.PluginsService.loadPlugins(PluginsService.java:147)\r\n\tat org.sonarsource.sonarlint.core.plugin.PluginsService.getPlugins(PluginsService.java:136)\r\n\tat org.sonarsource.sonarlint.core.analysis.AnalysisEngineCache.lambda$getOrCreateConnectedEngine$2(AnalysisEngineCache.java:97)\r\n\tat java.base/java.util.concurrent.ConcurrentHashMap.computeIfAbsent(Unknown Source)\r\n\tat org.sonarsource.sonarlint.core.analysis.AnalysisEngineCache.getOrCreateConnectedEngine(AnalysisEngineCache.java:96)\r\n\tat org.sonarsource.sonarlint.core.analysis.AnalysisEngineCache.lambda$getOrCreateAnalysisEngine$1(AnalysisEngineCache.java:91)\r\n\tat java.base/java.util.Optional.map(Unknown Source)\r\n\tat org.sonarsource.sonarlint.core.analysis.AnalysisEngineCache.getOrCreateAnalysisEngine(AnalysisEngineCache.java:91)\r\n\tat org.sonarsource.sonarlint.core.analysis.AnalysisService.analyze(AnalysisService.java:647)\r\n\tat org.sonarsource.sonarlint.core.rpc.impl.AnalysisRpcServiceDelegate.lambda$analyzeFilesAndTrack$8(AnalysisRpcServiceDelegate.java:143)\r\n\tat org.sonarsource.sonarlint.core.rpc.impl.AbstractRpcServiceDelegate.lambda$requestAsync$0(AbstractRpcServiceDelegate.java:67)\r\n\tat org.sonarsource.sonarlint.core.rpc.impl.AbstractRpcServiceDelegate.computeWithLogger(AbstractRpcServiceDelegate.java:135)\r\n\tat org.sonarsource.sonarlint.core.rpc.impl.AbstractRpcServiceDelegate.lambda$requestAsync$1(AbstractRpcServiceDelegate.java:65)\r\n\tat java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(Unknown Source)\r\n\tat java.base/java.util.concurrent.CompletableFuture$Completion.run(Unknown Source)\r\n\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)\r\n\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)\r\n\tat java.base/java.lang.Thread.run(Unknown Source)\r\nCaused by: java.nio.file.NoSuchFileException: C:\\Users\\georgii.borovinskikh\\AppData\\Local\\SLVS_SLOOP\\storageRoot\\68747470733a2f2f736f6e6172636c6f75642e696f2f6f7267616e697a6174696f6e732f64756e63616e702d736f6e61722d74657374\\plugins\\sonarlint-license-plugin-8.0.0.58632-all.jar\r\n\tat java.base/sun.nio.fs.WindowsException.translateToIOException(Unknown Source)\r\n\tat java.base/sun.nio.fs.WindowsException.rethrowAsIOException(Unknown Source)\r\n\tat java.base/sun.nio.fs.WindowsException.rethrowAsIOException(Unknown Source)\r\n\tat java.base/sun.nio.fs.WindowsFileAttributeViews$Basic.readAttributes(Unknown Source)\r\n\tat java.base/sun.nio.fs.WindowsFileAttributeViews$Basic.readAttributes(Unknown Source)\r\n\tat java.base/sun.nio.fs.WindowsFileSystemProvider.readAttributes(Unknown Source)\r\n\tat java.base/java.nio.file.Files.readAttributes(Unknown Source)\r\n\tat java.base/java.util.zip.ZipFile$Source.get(Unknown Source)\r\n\tat java.base/java.util.zip.ZipFile$CleanableResource.<init>(Unknown Source)\r\n\tat java.base/java.util.zip.ZipFile.<init>(Unknown Source)\r\n\tat java.base/java.util.zip.ZipFile.<init>(Unknown Source)\r\n\tat java.base/java.util.jar.JarFile.<init>(Unknown Source)\r\n\tat java.base/java.util.jar.JarFile.<init>(Unknown Source)\r\n\tat java.base/java.util.jar.JarFile.<init>(Unknown Source)\r\n\tat org.sonarsource.sonarlint.core.plugin.commons.loading.SonarPluginManifest.fromJar(SonarPluginManifest.java:97)\r\n\t... 22 more\r\n"
};

JsonConvert.DeserializeObject<LogParams>(serialzied).Should().BeEquivalentTo(expected, options => options.ComparingByMembers<LogParams>());
}
}
}
21 changes: 11 additions & 10 deletions src/SLCore.Listeners/Implementation/LoggerListener.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -34,25 +34,26 @@ public class LoggerListener : ILoggerListener
[ImportingConstructor]
public LoggerListener(ILogger logger)
{
this.logger = logger;
this.logger = logger.ForContext(SLCoreStrings.SLCoreName, SLCoreStrings.SLCoreInternalLogContext);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it's enough to add just one context that is a string of type "SlCore Logs". It would occupies less space than [SLCore > Logs].

}

public void Log(LogParams parameters)
{
var message = "[SLCORE] " + parameters.message;
var contextualizedLogger = logger.ForVerboseContext(parameters.loggerName, parameters.configScopeId, parameters.threadName);

switch (parameters.level)
{
case LogLevel.ERROR:
case LogLevel.WARN:
logger.WriteLine(message);
case LogLevel.ERROR or LogLevel.WARN:
contextualizedLogger.WriteLine(parameters.message);
break;

case LogLevel.INFO:
case LogLevel.DEBUG:
case LogLevel.TRACE:
logger.LogVerbose(message);
case LogLevel.INFO or LogLevel.DEBUG or LogLevel.TRACE:
contextualizedLogger.LogVerbose(parameters.message);
break;
}

if (parameters.stackTrace != null)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Move the null check inside the LogVerbose method

{
contextualizedLogger.LogVerbose(parameters.stackTrace);
}
}
}
6 changes: 6 additions & 0 deletions src/SLCore/Listener/Logger/LogParams.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -26,6 +26,12 @@ namespace SonarLint.VisualStudio.SLCore.Listener.Logger;
public class LogParams
{
public string message;
// nullable
public string configScopeId;
public string threadName;
public string loggerName;
// nullable
public string stackTrace;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We are missing the loggedAt property. Even if we don't use it for now, I think we should add it.


[JsonConverter(typeof(StringEnumConverter))]
public LogLevel level;
Expand Down
19 changes: 18 additions & 1 deletion src/SLCore/SLCoreStrings.Designer.cs
View file
Open in desktop

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

6 changes: 6 additions & 0 deletions src/SLCore/SLCoreStrings.resx
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -180,4 +180,10 @@
<data name="UnknowProxyType" xml:space="preserve">
<value>Proxy type can not be determined from scheme '{0}'. Returning HTTP proxy type.</value>
</data>
<data name="SLCoreName" xml:space="preserve">
<value>SLCore</value>
</data>
<data name="SLCoreInternalLogContext" xml:space="preserve">
<value>Logs</value>
</data>
</root>
7 changes: 4 additions & 3 deletions src/TestInfrastructure/Framework/TestLogger.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -32,15 +32,16 @@ public class TestLogger : ILogger, ILoggerWriter, ILoggerSettingsProvider

private readonly bool logToConsole;
private readonly bool logThreadId;
private readonly bool logVerbose;
private readonly ILogger logger;

public TestLogger(bool logToConsole = false, bool logThreadId = false)
public TestLogger(bool logToConsole = false, bool logThreadId = false, bool logVerbose = true)
{
// When executing tests in VS, the console output will automatically be captured by
// the test runner. The Properties window for the test result will have an "Output"
// link to show the output.
this.logToConsole = logToConsole;

this.logVerbose = logVerbose;
this.logThreadId = logThreadId;
logger = LoggerFactory.Default.Create(this, this);
}
Expand Down Expand Up @@ -121,7 +122,7 @@ void ILoggerWriter.WriteLine(string message)

LogMessageAdded?.Invoke(this, EventArgs.Empty);
}
bool ILoggerSettingsProvider.IsVerboseEnabled => true;
bool ILoggerSettingsProvider.IsVerboseEnabled => logVerbose;
bool ILoggerSettingsProvider.IsThreadIdEnabled => logThreadId;
}
}
Loading