Skip to content

Commit

Permalink
SLVS-1722 Log extra properties of SLCore log events (#5924)
Browse files Browse the repository at this point in the history 
[SLVS-1722](https://sonarsource.atlassian.net/browse/SLVS-1722)



[SLVS-1722]:
https://sonarsource.atlassian.net/browse/SLVS-1722?atlOrigin=eyJpIjoiNWRkNTljNzYxNjVmNDY3MDlhMDU5Y2ZhYzA5YTRkZjUiLCJwIjoiZ2l0aHViLWNvbS1KU1cifQ
  • Loading branch information
@georgii-borovinskikh-sonarsource @vnaskos-sonar
georgii-borovinskikh-sonarsource authored and vnaskos-sonar committed Jan 10, 2025
1 parent e8648b5 commit c5487fe
Show file tree
Hide file tree
Showing 7 changed files with 185 additions and 62 deletions.
102 changes: 90 additions & 12 deletions src/SLCore.Listeners.UnitTests/Logging/LoggerListenerTests.cs
View file
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] some Message" : "[SLCore] some Message");
}

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

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

[TestMethod]
public void Log_AddsArgumentProperties()
{
var customizedLogger = Substitute.For<ILogger>();
var logger = Substitute.For<ILogger>();
logger.ForContext(SLCoreStrings.SLCoreName).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).WriteLine(Arg.Is<MessageLevelContext>(ctx => ctx.VerboseContext.SequenceEqual(new []{"loggerName1", "configScopeId1", "threadName1"})), Arg.Any<string>());
customizedLogger.Received(1).WriteLine(Arg.Is<MessageLevelContext>(ctx => ctx.VerboseContext.SequenceEqual(new []{"loggerName2", "configScopeId2", "threadName2"})), Arg.Any<string>());
}

[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] 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] [loggerName > configScopeId > threadName] message",
"""
[DEBUG] [SLCore] [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] [loggerName > threadName] message");
}
}
}
29 changes: 29 additions & 0 deletions src/SLCore.Listeners.UnitTests/Logging/LoggerSerializationTests.cs
View file
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>());
}
}
}
30 changes: 13 additions & 17 deletions src/SLCore.Listeners/Implementation/LoggerListener.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -27,32 +27,28 @@ namespace SonarLint.VisualStudio.SLCore.Listeners.Implementation;

[Export(typeof(ISLCoreListener))]
[PartCreationPolicy(CreationPolicy.Shared)]
public class LoggerListener : ILoggerListener
[method: ImportingConstructor]
public class LoggerListener(ILogger logger) : ILoggerListener
{
private readonly ILogger logger;

[ImportingConstructor]
public LoggerListener(ILogger logger)
{
this.logger = logger;
}
private readonly ILogger logger = logger.ForContext(SLCoreStrings.SLCoreName);

public void Log(LogParams parameters)
{
var message = "[SLCORE] " + parameters.message;
var additionalContext = new MessageLevelContext {VerboseContext = [parameters.loggerName, parameters.configScopeId, parameters.threadName]};

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

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

if (parameters.stackTrace != null)
{
logger.LogVerbose(additionalContext, parameters.stackTrace);
}
}
}
8 changes: 8 additions & 0 deletions src/SLCore/Listener/Logger/LogParams.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -26,6 +26,14 @@ 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;

// private final Instant loggedAt; is ignored

[JsonConverter(typeof(StringEnumConverter))]
public LogLevel level;
Expand Down
Loading

0 comments on commit c5487fe

Please sign in to comment.