fix: Remove dependency on Serilog.Expressions. (#2083) (#2082)

Author: tippmar-nr

src/Agent/NewRelic/Agent/Core/Core.csproj

@@ -39,7 +39,6 @@
       <IncludeAssets>runtime; build; native; contentfiles; analyzers; buildtransitive</IncludeAssets>
     </PackageReference>
     <PackageReference Include="Serilog" Version="3.0.1" />
-    <PackageReference Include="Serilog.Expressions" Version="3.4.1" />
     <PackageReference Include="Serilog.Sinks.Async" Version="1.5.0" />
     <PackageReference Include="Serilog.Sinks.Console" Version="4.1.0" />
     <PackageReference Include="Serilog.Sinks.Debug" Version="2.0.0" />
@@ -101,7 +100,6 @@
       <ILRepackInclude Include="@(PossibleRefsForILRepack)" Condition="'%(FileName)' == 'NewRelic.Parsing'" />
       <ILRepackInclude Include="@(PossibleRefsForILRepack)" Condition="'%(FileName)' == 'Newtonsoft.Json'" />
       <ILRepackInclude Include="@(PossibleRefsForILRepack)" Condition="'%(FileName)' == 'Serilog'" />
-      <ILRepackInclude Include="@(PossibleRefsForILRepack)" Condition="'%(FileName)' == 'Serilog.Expressions'" />
       <ILRepackInclude Include="@(PossibleRefsForILRepack)" Condition="'%(FileName)' == 'Serilog.Sinks.Async'" />
       <ILRepackInclude Include="@(PossibleRefsForILRepack)" Condition="'%(FileName)' == 'Serilog.Sinks.Console'" />
       <ILRepackInclude Include="@(PossibleRefsForILRepack)" Condition="'%(FileName)' == 'Serilog.Sinks.Debug'" />
@@ -126,8 +124,8 @@
     </ItemGroup>
 
     <PropertyGroup>
-      <ILRepackIncludeCount Condition="'$(TargetFramework)' == 'net462'">20</ILRepackIncludeCount>
-      <ILRepackIncludeCount Condition="'$(TargetFramework)' == 'netstandard2.0'">17</ILRepackIncludeCount>
+      <ILRepackIncludeCount Condition="'$(TargetFramework)' == 'net462'">19</ILRepackIncludeCount>
+      <ILRepackIncludeCount Condition="'$(TargetFramework)' == 'netstandard2.0'">16</ILRepackIncludeCount>
     </PropertyGroup>
 
     <Error Text="ILRepack of $(AssemblyName) ($(TargetFramework)) failed. A dependency is missing. Expected $(ILRepackIncludeCount) dependencies but found @(ILRepackInclude-&gt;Count())." Condition="@(ILRepackInclude-&gt;Count()) != $(ILRepackIncludeCount)" />

src/Agent/NewRelic/Agent/Core/Logging/AuditLog.cs

@@ -38,12 +38,12 @@ public static void Log(string message)
 
         public static LoggerConfiguration IncludeOnlyAuditLog(this LoggerConfiguration loggerConfiguration)
         {
-            return loggerConfiguration.Filter.ByIncludingOnly($"{LogLevelExtensions.AuditLevel} is not null");
+            return loggerConfiguration.Filter.ByIncludingOnly(logEvent => logEvent.Properties.ContainsKey(LogLevelExtensions.AuditLevel));
         }
 
         public static LoggerConfiguration ExcludeAuditLog(this LoggerConfiguration loggerConfiguration)
         {
-            return loggerConfiguration.Filter.ByIncludingOnly($"{LogLevelExtensions.AuditLevel} is null");
+            return loggerConfiguration.Filter.ByIncludingOnly(logEvent => !logEvent.Properties.ContainsKey(LogLevelExtensions.AuditLevel));
         }
     }
 }

src/Agent/NewRelic/Agent/Core/Logging/LoggerBootstrapper.cs

@@ -7,10 +7,8 @@
 using System.Text;
 using Serilog;
 using Serilog.Core;
-using Serilog.Formatting;
 using Logger = NewRelic.Agent.Core.Logging.Logger;
 using NewRelic.Agent.Core.Logging;
-using Serilog.Templates;
 using Serilog.Events;
 #if NETSTANDARD2_0
 using System.Runtime.InteropServices;
@@ -25,8 +23,9 @@ public static class LoggerBootstrapper
         //private static ILayout AuditLogLayout = new PatternLayout("%utcdate{yyyy-MM-dd HH:mm:ss,fff} NewRelic %level: %message\r\n");
         //private static ILayout FileLogLayout = new PatternLayout("%utcdate{yyyy-MM-dd HH:mm:ss,fff} NewRelic %6level: [pid: %property{pid}, tid: %property{threadid}] %message\r\n");
 
-        private static ExpressionTemplate AuditLogLayout = new ExpressionTemplate("{UtcDateTime(@t):yyyy-MM-dd HH:mm:ss,fff} NewRelic Audit: {@m}\n");
-        private static ExpressionTemplate FileLogLayout = new ExpressionTemplate("{UtcDateTime(@t):yyyy-MM-dd HH:mm:ss,fff} NewRelic {NRLogLevel,6}: [pid: {pid}, tid: {tid}] {@m}\n{@x}");
+        private const string AuditLogLayout = "{UTCTimestamp} NewRelic Audit: {Message:l}\n";
+
+        private const string FileLogLayout = "{UTCTimestamp} NewRelic {NRLogLevel,6}: [pid: {pid}, tid: {tid}] {Message:l}\n{Exception:l}";
 
         private static LoggingLevelSwitch _loggingLevelSwitch = new LoggingLevelSwitch();
 
@@ -40,7 +39,7 @@ public static void UpdateLoggingLevel(string newLogLevel)
         public static void Initialize()
         {
             var startupLoggerConfig = new LoggerConfiguration()
-                .Enrich.With(new ThreadIdEnricher(), new ProcessIdEnricher(), new NrLogLevelEnricher())
+                .Enrich.With(new ThreadIdEnricher(), new ProcessIdEnricher(), new NrLogLevelEnricher(), new UTCTimestampEnricher())
                 .MinimumLevel.Information()
                 .ConfigureInMemoryLogSink()
                 .ConfigureEventLogSink();
@@ -61,8 +60,8 @@ public static void ConfigureLogger(ILogConfig config)
 
             var loggerConfig = new LoggerConfiguration()
                 .MinimumLevel.ControlledBy(_loggingLevelSwitch)
+                .Enrich.With(new ThreadIdEnricher(), new ProcessIdEnricher(), new NrLogLevelEnricher(), new UTCTimestampEnricher())
                 .ConfigureAuditLogSink(config)
-                .Enrich.With(new ThreadIdEnricher(), new ProcessIdEnricher(), new NrLogLevelEnricher())
                 .ConfigureFileSink(config)
                 .ConfigureDebugSink();
 
@@ -167,7 +166,7 @@ private static LoggerConfiguration ConfigureDebugSink(this LoggerConfiguration l
                 {
                     configuration
                         .ExcludeAuditLog()
-                        .WriteTo.Debug(FileLogLayout);
+                        .WriteTo.Debug(outputTemplate: FileLogLayout);
                 });
 #endif
             return loggerConfiguration;
@@ -184,7 +183,7 @@ private static LoggerConfiguration ConfigureConsoleSink(this LoggerConfiguration
                     {
                         configuration
                             .ExcludeAuditLog()
-                            .WriteTo.Console(FileLogLayout);
+                            .WriteTo.Console(outputTemplate: FileLogLayout);
                     })
                 );
         }
@@ -248,9 +247,9 @@ private static LoggerConfiguration ConfigureAuditLogSink(this LoggerConfiguratio
         /// </summary>
         /// <param name="loggerConfiguration"></param>
         /// <param name="fileName">The name of the file this appender will write to.</param>
-        /// <param name="textFormatter"></param>
+        /// <param name="outputFormat"></param>
         /// <remarks>This does not call appender.ActivateOptions or add the appender to the logger.</remarks>
-        private static LoggerConfiguration ConfigureRollingLogSink(this LoggerConfiguration loggerConfiguration, string fileName, ITextFormatter textFormatter)
+        private static LoggerConfiguration ConfigureRollingLogSink(this LoggerConfiguration loggerConfiguration, string fileName, string outputFormat)
         {
             // check that the log file is accessible
             try
@@ -272,7 +271,7 @@ private static LoggerConfiguration ConfigureRollingLogSink(this LoggerConfigurat
                 return loggerConfiguration
                     .WriteTo
                     .File(path: fileName,
-                            formatter: textFormatter,
+                            outputTemplate:outputFormat,
                             fileSizeLimitBytes: 50 * 1024 * 1024,
                             encoding: Encoding.UTF8,
                             rollOnFileSizeLimit: true,

src/Agent/NewRelic/Agent/Core/Logging/NrLogLevelEnricher.cs

@@ -10,6 +10,7 @@ namespace NewRelic.Agent.Core
     /// <summary>
     /// Maps serilog log level to corresponding "legacy" log4net loglevel and adds the mapped value as a property named NRLogLevel
     /// </summary>
+    [NrExcludeFromCodeCoverage]
     internal class NrLogLevelEnricher : ILogEventEnricher
     {
         [NrExcludeFromCodeCoverage]

src/Agent/NewRelic/Agent/Core/Logging/ProcessIdEnricher.cs

@@ -8,14 +8,21 @@
 
 namespace NewRelic.Agent.Core
 {
+    /// <summary>
+    /// Adds a pid property to the log event containing the current process id
+    /// </summary>
     [NrExcludeFromCodeCoverage]
     internal class ProcessIdEnricher : ILogEventEnricher
     {
         private static int _pid = new ProcessStatic().GetCurrentProcess().Id;
 
+        private static LogEventProperty _prop;
+
         public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
         {
-            logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty("pid", _pid));
+            _prop ??= propertyFactory.CreateProperty("pid", _pid);
+
+            logEvent.AddPropertyIfAbsent(_prop);
         }
     }
 }

src/Agent/NewRelic/Agent/Core/Logging/ThreadIdEnricher.cs

@@ -8,13 +8,21 @@
 
 namespace NewRelic.Agent.Core
 {
+    /// <summary>
+    /// Adds a tid property to the log event containing the current managed thread id
+    /// </summary>
     [NrExcludeFromCodeCoverage]
     internal class ThreadIdEnricher : ILogEventEnricher
     {
+
+        private static readonly ThreadLocal<LogEventProperty> _tidProperty = new ThreadLocal<LogEventProperty>();
+
         public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
         {
-            logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty(
-                "tid", Thread.CurrentThread.ManagedThreadId));
+            if (!_tidProperty.IsValueCreated)
+                _tidProperty.Value = propertyFactory.CreateProperty("tid", Thread.CurrentThread.ManagedThreadId);
+
+            logEvent.AddPropertyIfAbsent(_tidProperty.Value);
         }
     }
 }

src/Agent/NewRelic/Agent/Core/Logging/UTCTimestampEnricher.cs

@@ -0,0 +1,24 @@
+// Copyright 2020 New Relic, Inc. All rights reserved.
+// SPDX-License-Identifier: Apache-2.0
+
+using System;
+using NewRelic.Core.CodeAttributes;
+using Serilog.Core;
+using Serilog.Events;
+
+namespace NewRelic.Agent.Core
+{
+    /// <summary>
+    /// Formats the current UTC time for logging in the agent
+    /// </summary>
+    [NrExcludeFromCodeCoverage]
+    public class UTCTimestampEnricher : ILogEventEnricher
+    {
+        public const string UTCTimestampPropertyName = "UTCTimestamp";
+        public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
+        {
+            logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty(UTCTimestampPropertyName,
+                $"{DateTimeOffset.UtcNow:yyy-MM-dd HH:mm:ss,fff}"));
+        }
+    }
+}

src/Agent/NewRelic/Agent/Extensions/Providers/Wrapper/Owin/Owin.csproj

@@ -5,6 +5,9 @@
     <AssemblyName>NewRelic.Providers.Wrapper.Owin</AssemblyName>
     <Description>Owin 2 Wrapper Provider for New Relic .NET Agent</Description>
   </PropertyGroup>
+<PropertyGroup>
+    <NoWarn>NU1903</NoWarn> <!-- Microsoft.Owin 2.0 has a high security vulnerability, but we have to reference that pacakage -->
+  </PropertyGroup>
   <ItemGroup>
     <PackageReference Include="Microsoft.Owin" Version="2.0.0" />
   </ItemGroup>

src/Agent/NewRelic/Agent/Extensions/Providers/Wrapper/WebApi1/WebApi1.csproj

@@ -5,6 +5,9 @@
     <AssemblyName>NewRelic.Providers.Wrapper.WebApi1</AssemblyName>
     <Description>Web API 1 Wrapper Provider for New Relic .NET Agent</Description>
   </PropertyGroup>
+  <PropertyGroup>
+    <NoWarn>NU1903</NoWarn> <!-- System.Net.Http 2.0 has a high security vulnerability, but we have to reference that pacakage -->
+  </PropertyGroup>
   <ItemGroup>
     <PackageReference Include="System.Net.Http" Version="2.0.20710.0" />
     <PackageReference Include="Microsoft.AspNet.WebApi.Client" Version="4.0.20710.0" />

tests/Agent/IntegrationTests/IntegrationTests/AgentLogs/LogFileFormatTests.cs

@@ -0,0 +1,52 @@
+// Copyright 2020 New Relic, Inc. All rights reserved.
+// SPDX-License-Identifier: Apache-2.0
+
+using System.IO;
+using System.Linq;
+using System.Text.RegularExpressions;
+using NewRelic.Agent.IntegrationTestHelpers;
+using Xunit;
+using Xunit.Abstractions;
+
+namespace NewRelic.Agent.IntegrationTests.AgentLogs
+{
+    [NetFrameworkTest]
+    public class LogFileFormatTests : NewRelicIntegrationTest<RemoteServiceFixtures.BasicMvcApplicationTestFixture>
+    {
+        private readonly RemoteServiceFixtures.BasicMvcApplicationTestFixture _fixture;
+
+        public LogFileFormatTests(RemoteServiceFixtures.BasicMvcApplicationTestFixture fixture, ITestOutputHelper output) : base(fixture)
+        {
+            _fixture = fixture;
+            _fixture.TestLogger = output;
+            _fixture.Actions
+            (
+                setupConfiguration: () =>
+                {
+                    var configPath = fixture.DestinationNewRelicConfigFilePath;
+                    var configModifier = new NewRelicConfigModifier(configPath);
+                    configModifier.ForceTransactionTraces();
+                },
+                exerciseApplication: () =>
+                {
+                    _fixture.Get();
+                }
+            );
+            _fixture.Initialize();
+        }
+
+        [Fact]
+        public void Test()
+        {
+            // get the first log line and validate it's in the expected format
+            var firstLogLine = _fixture.AgentLog.GetFileLines().First();
+
+            var match = Regex.Match(firstLogLine,
+                @"\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2},\d{3} NewRelic .{6}: \[pid: \d{1,}, tid: \d{1,}\] .*");
+
+            Assert.True(match.Success);
+            Assert.Single(match.Groups);
+            Assert.Equal(firstLogLine, match.Groups[0].Value);
+        }
+    }
+}