Skip to content

Commit

Permalink
fix: Remap errors to warnings if logged inside ComponentDetection (#554)
Browse files Browse the repository at this point in the history
  • Loading branch information
DaveTryon authored Apr 16, 2024
1 parent c76868d commit 5c9396f
Show file tree
Hide file tree
Showing 6 changed files with 276 additions and 17 deletions.
6 changes: 6 additions & 0 deletions Microsoft.Sbom.sln
Original file line number Diff line number Diff line change
Expand Up @@ -47,6 +47,8 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Microsoft.Sbom.DotNetTool",
EndProject
Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Microsoft.Sbom.Extensions.DependencyInjection", "src\Microsoft.Sbom.Extensions.DependencyInjection\Microsoft.Sbom.Extensions.DependencyInjection.csproj", "{2EB7C6CC-5E40-4DAF-AF8B-D69736B601D9}"
EndProject
Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Microsoft.Sbom.Extensions.DependencyInjection.Tests", "test\Microsoft.Sbom.Extensions.DependencyInjection.Tests\Microsoft.Sbom.Extensions.DependencyInjection.Tests.csproj", "{EE4E2E03-7B4C-46E5-B9D2-89E84A18D787}"
EndProject
Global
GlobalSection(SolutionConfigurationPlatforms) = preSolution
Debug|Any CPU = Debug|Any CPU
Expand Down Expand Up @@ -101,6 +103,10 @@ Global
{2EB7C6CC-5E40-4DAF-AF8B-D69736B601D9}.Debug|Any CPU.Build.0 = Debug|Any CPU
{2EB7C6CC-5E40-4DAF-AF8B-D69736B601D9}.Release|Any CPU.ActiveCfg = Release|Any CPU
{2EB7C6CC-5E40-4DAF-AF8B-D69736B601D9}.Release|Any CPU.Build.0 = Release|Any CPU
{EE4E2E03-7B4C-46E5-B9D2-89E84A18D787}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
{EE4E2E03-7B4C-46E5-B9D2-89E84A18D787}.Debug|Any CPU.Build.0 = Debug|Any CPU
{EE4E2E03-7B4C-46E5-B9D2-89E84A18D787}.Release|Any CPU.ActiveCfg = Release|Any CPU
{EE4E2E03-7B4C-46E5-B9D2-89E84A18D787}.Release|Any CPU.Build.0 = Release|Any CPU
EndGlobalSection
GlobalSection(SolutionProperties) = preSolution
HideSolutionNode = FALSE
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,12 @@
<Nullable>enable</Nullable>
</PropertyGroup>

<ItemGroup>
<AssemblyAttribute Include="System.Runtime.CompilerServices.InternalsVisibleToAttribute">
<_Parameter1>$(AssemblyName).Tests, PublicKey=$(StrongNameSigningPublicKey)</_Parameter1>
</AssemblyAttribute>
</ItemGroup>

<ItemGroup>
<ProjectReference Include="..\Microsoft.Sbom.Api\Microsoft.Sbom.Api.csproj" />
<ProjectReference Include="..\Microsoft.Sbom.Common\Microsoft.Sbom.Common.csproj" />
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,62 @@
// Copyright (c) Microsoft. All rights reserved.
// Licensed under the MIT license. See LICENSE file in the project root for full license information.

namespace Microsoft.Sbom.Extensions.DependencyInjection;

using System;
using Serilog;
using Serilog.Events;

/// <summary>
/// A class to remap Errors logged from ComponentDetection assemblies to Warnings.
/// </summary>
public class RemapComponentDetectionErrorsToWarningsLogger : ILogger
{
private readonly ILogger logger;
private readonly Func<string?> stackTraceProvider;

/// <summary>
/// Initializes a new instance of the <see cref="RemapComponentDetectionErrorsToWarningsLogger"/> class.
/// Production constructor.
/// </summary>
public RemapComponentDetectionErrorsToWarningsLogger(ILogger logger)
: this(logger, () => Environment.StackTrace)
{
}

/// <summary>
/// Initializes a new instance of the <see cref="RemapComponentDetectionErrorsToWarningsLogger"/> class.
/// Testable constructor.
/// </summary>
/// <exception cref="ArgumentNullException"></exception>
internal RemapComponentDetectionErrorsToWarningsLogger(ILogger logger, Func<string?> stackTraceProvider)
{
this.logger = logger ?? throw new ArgumentNullException(nameof(logger));
this.stackTraceProvider = stackTraceProvider ?? throw new ArgumentNullException(nameof(stackTraceProvider));
}

/// <inheritdoc />
/// <remarks>If ComponentDetection is on the stack, remap and log Errors to Warnings.</remarks>
public void Write(LogEvent logEvent)
{
// For performance reasons, bypass StackTrace work for non-errors.
if (logEvent.Level == LogEventLevel.Error)
{
var stackTrace = stackTraceProvider();
if (stackTrace is not null && stackTrace.Contains("Microsoft.ComponentDetection."))
{
var warningLogEvent = new LogEvent(
logEvent.Timestamp,
LogEventLevel.Warning,
logEvent.Exception,
logEvent.MessageTemplate,
logEvent.Properties.Select(kvp => new LogEventProperty(kvp.Key, kvp.Value)));

logger.Write(warningLogEvent);
return;
}
}

logger.Write(logEvent);
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -200,23 +200,24 @@ public static IServiceCollection ConfigureLoggingProviders(this IServiceCollecti

private static ILogger CreateLogger(LogEventLevel logLevel)
{
return new LoggerConfiguration()
.MinimumLevel.ControlledBy(new LoggingLevelSwitch { MinimumLevel = logLevel })
.Filter.ByExcluding(Matching.FromSource("System.Net.Http.HttpClient"))
.Enrich.With<LoggingEnricher>()
.Enrich.FromLogContext()
.WriteTo.Map(
LoggingEnricher.LogFilePathPropertyName,
(logFilePath, wt) => wt.Async(x => x.File($"{logFilePath}")),
1) // sinkMapCountLimit
.WriteTo.Map<bool>(
LoggingEnricher.PrintStderrPropertyName,
(printLogsToStderr, wt) => wt.Logger(lc => lc
.WriteTo.Console(outputTemplate: Constants.LoggerTemplate, standardErrorFromLevel: printLogsToStderr ? LogEventLevel.Debug : null)
return new RemapComponentDetectionErrorsToWarningsLogger(
new LoggerConfiguration()
.MinimumLevel.ControlledBy(new LoggingLevelSwitch { MinimumLevel = logLevel })
.Filter.ByExcluding(Matching.FromSource("System.Net.Http.HttpClient"))
.Enrich.With<LoggingEnricher>()
.Enrich.FromLogContext()
.WriteTo.Map(
LoggingEnricher.LogFilePathPropertyName,
(logFilePath, wt) => wt.Async(x => x.File($"{logFilePath}")),
1) // sinkMapCountLimit
.WriteTo.Map<bool>(
LoggingEnricher.PrintStderrPropertyName,
(printLogsToStderr, wt) => wt.Logger(lc => lc
.WriteTo.Console(outputTemplate: Constants.LoggerTemplate, standardErrorFromLevel: printLogsToStderr ? LogEventLevel.Debug : null)

// Don't write the detection times table from DetectorProcessingService to the console, only the log file
.Filter.ByExcluding(Matching.WithProperty<string>("DetectionTimeLine", x => !string.IsNullOrEmpty(x)))),
1) // sinkMapCountLimit
.CreateLogger();
// Don't write the detection times table from DetectorProcessingService to the console, only the log file
.Filter.ByExcluding(Matching.WithProperty<string>("DetectionTimeLine", x => !string.IsNullOrEmpty(x)))),
1) // sinkMapCountLimit
.CreateLogger());
}
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,22 @@
<Project Sdk="Microsoft.NET.Sdk">

<PropertyGroup>
<IsPackable>false</IsPackable>
<SignAssembly>True</SignAssembly>
<RootNamespace>Microsoft.Sbom.DependencyInjection.Tests</RootNamespace>
<AssemblyOriginatorKeyFile>$(StrongNameSigningKeyFilePath)</AssemblyOriginatorKeyFile>
</PropertyGroup>

<PropertyGroup Condition="'$(Configuration)|$(Platform)'=='Debug|AnyCPU'">
<DefineConstants>TRACE</DefineConstants>
</PropertyGroup>

<ItemGroup>
<PackageReference Include="Serilog.Sinks.Console" />
</ItemGroup>

<ItemGroup>
<ProjectReference Include="..\..\src\Microsoft.Sbom.Extensions.DependencyInjection\Microsoft.Sbom.Extensions.DependencyInjection.csproj" />
</ItemGroup>

</Project>
Original file line number Diff line number Diff line change
@@ -0,0 +1,162 @@
// Copyright (c) Microsoft. All rights reserved.
// Licensed under the MIT license. See LICENSE file in the project root for full license information.

using System;
using System.Collections.Generic;
using System.IO;
using System.Linq;
using Microsoft.VisualStudio.TestTools.UnitTesting;
using Moq;
using Serilog;
using Serilog.Events;
using Serilog.Parsing;

namespace Microsoft.Sbom.Extensions.DependencyInjection.Tests;

[TestClass]
public class RemapComponentDetectionErrorsToWarningsLoggerTests
{
private const string TestPropertyKey = "TestPropertyKey";

private Mock<ILogger> loggerMock;
private Func<string> stackTraceProvider;
private ILogger testSubject;
private int testStackTraceCount;
private string? testStackTraceReturnValue;

// We need a concrete implementation of MessageTemplateToken
internal class TestMessageTemplateToken : MessageTemplateToken
{
public override int Length => throw new NotImplementedException();

public override void Render(IReadOnlyDictionary<string, LogEventPropertyValue> properties, TextWriter output, IFormatProvider formatProvider = null) => throw new NotImplementedException();
}

// We need a concrete implementation of LogEventPropertyValue
internal class TestLogEventPropertyValue : LogEventPropertyValue
{
public override void Render(TextWriter output, string format = null, IFormatProvider formatProvider = null) => throw new NotImplementedException();
}

[TestInitialize]
public void TestInit()
{
loggerMock = new Mock<ILogger>(MockBehavior.Strict);
stackTraceProvider = TestGetStackTrace;
testStackTraceCount = 0;
testStackTraceReturnValue = null;
testSubject = new RemapComponentDetectionErrorsToWarningsLogger(loggerMock.Object, stackTraceProvider);
}

[TestCleanup]
public void TestCleanup()
{
loggerMock.VerifyAll();
}

[TestMethod]
public void Constructor_LoggerIsNull_ThrowsNullArgumentException()
{
Assert.ThrowsException<ArgumentNullException>(() => new RemapComponentDetectionErrorsToWarningsLogger(null, stackTraceProvider));
}

[TestMethod]
public void Constructor_StackTraceProviderIsNull_ThrowsNullArgumentException()
{
Assert.ThrowsException<ArgumentNullException>(() => new RemapComponentDetectionErrorsToWarningsLogger(loggerMock.Object, null));
}

[TestMethod]
public void Write_LogEventLevelIsNotError_DoesNotCallStackTraceProvider_LogsEventAsSpecified()
{
var nonErrorLevels = Enum.GetValues(typeof(LogEventLevel)).Cast<LogEventLevel>().Where((x) => x != LogEventLevel.Error);
foreach (var level in nonErrorLevels)
{
var logEvent = GetLogEvent(level);
loggerMock.Setup(x => x.Write(logEvent)).Verifiable();

testSubject.Write(logEvent);

Assert.AreEqual(0, testStackTraceCount);

// The VerifyAll and Reset calls are needed here because we need to confirm them for _each iteration_ of the loop.
loggerMock.VerifyAll();
loggerMock.Reset();
}
}

[TestMethod]
public void Write_LogEventLevelIsError_StackTraceReturnsNull_LogsEventAsSpecified()
{
var logEvent = GetLogEvent(LogEventLevel.Error);
loggerMock.Setup(x => x.Write(logEvent)).Verifiable();

testSubject.Write(logEvent);

Assert.AreEqual(1, testStackTraceCount);
}

[TestMethod]
public void Write_LogEventLevelIsError_UsesDefaultStackTraceProvider_LogsEventAsSpecified()
{
var logEvent = GetLogEvent(LogEventLevel.Error);
loggerMock.Setup(x => x.Write(logEvent)).Verifiable();

// Use the production constructor here to force use of the default StackTraceProvider
new RemapComponentDetectionErrorsToWarningsLogger(loggerMock.Object).Write(logEvent);

Assert.AreEqual(0, testStackTraceCount);
}

[TestMethod]
public void Write_LogEventLevelIsError_StackTraceDoesNotContainComponentDetection_LogsEventAsSpecified()
{
var logEvent = GetLogEvent(LogEventLevel.Error);
loggerMock.Setup(x => x.Write(logEvent)).Verifiable();
testStackTraceReturnValue = "at Microsoft.Sbom.Foo.Bar";

testSubject.Write(logEvent);

Assert.AreEqual(1, testStackTraceCount);
}

[TestMethod]
public void Write_LogEventLevelIsError_StackTraceContainsComponentDetection_LogsEventAsWarning()
{
LogEvent actualEvent = null;
var logEvent = GetLogEvent(LogEventLevel.Error);
loggerMock.Setup(x => x.Write(It.IsAny<LogEvent>())).Callback<LogEvent>((l) => actualEvent = l).Verifiable();
testStackTraceReturnValue = "at Microsoft.ComponentDetection.Foo.Bar";

testSubject.Write(logEvent);

Assert.AreEqual(1, testStackTraceCount);

// Ensure that the LogEvent was correctly copied. Only the Level should be different
Assert.AreEqual(LogEventLevel.Warning, actualEvent.Level);
Assert.AreEqual(logEvent.Timestamp, actualEvent.Timestamp);
Assert.AreSame(logEvent.MessageTemplate, actualEvent.MessageTemplate);
Assert.AreEqual(logEvent.Properties.Count, actualEvent.Properties.Count);
Assert.AreEqual(1, actualEvent.Properties.Count);
Assert.IsInstanceOfType(logEvent.Properties[TestPropertyKey], typeof(TestLogEventPropertyValue));
Assert.AreSame(logEvent.Properties[TestPropertyKey], actualEvent.Properties[TestPropertyKey]);
}

// A helper function to return a LogEvent with the specified LogEventLevel
private LogEvent GetLogEvent(LogEventLevel logEventLevel)
{
return new LogEvent(
DateTimeOffset.Now,
logEventLevel,
null,
new MessageTemplate(new List<MessageTemplateToken> { new TestMessageTemplateToken() }),
new LogEventProperty[1] { new LogEventProperty(TestPropertyKey, new TestLogEventPropertyValue()) });
}

// A helper function to allow us to easily test the StackTraceProvider functionality
private string TestGetStackTrace()
{
testStackTraceCount++;
return testStackTraceReturnValue;
}
}

0 comments on commit 5c9396f

Please sign in to comment.