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

Merged
merged 1 commit into from
Jan 8, 2025
Merged

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

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
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] 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
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>());
}
}
}
30 changes: 13 additions & 17 deletions src/SLCore.Listeners/Implementation/LoggerListener.cs
View file
Open in desktop
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)
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

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Don't really want to move this logic inside the logger. It's not really the logger's business IMO

{
logger.LogVerbose(additionalContext, parameters.stackTrace);
}
}
}
8 changes: 8 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,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;
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.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

added a comment


// private final Instant loggedAt; is ignored

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