diff --git a/src/Agent/NewRelic/Agent/Core/Core.csproj b/src/Agent/NewRelic/Agent/Core/Core.csproj index 7d993d9d02..5c9a4fc510 100644 --- a/src/Agent/NewRelic/Agent/Core/Core.csproj +++ b/src/Agent/NewRelic/Agent/Core/Core.csproj @@ -39,7 +39,6 @@ runtime; build; native; contentfiles; analyzers; buildtransitive - @@ -101,7 +100,6 @@ - @@ -126,8 +124,8 @@ - 20 - 17 + 19 + 16 diff --git a/src/Agent/NewRelic/Agent/Core/Logging/AuditLog.cs b/src/Agent/NewRelic/Agent/Core/Logging/AuditLog.cs index a1eacf8e0a..dfd84775e5 100644 --- a/src/Agent/NewRelic/Agent/Core/Logging/AuditLog.cs +++ b/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)); } } } diff --git a/src/Agent/NewRelic/Agent/Core/Logging/LoggerBootstrapper.cs b/src/Agent/NewRelic/Agent/Core/Logging/LoggerBootstrapper.cs index 7b1741cbd0..e8693156bb 100644 --- a/src/Agent/NewRelic/Agent/Core/Logging/LoggerBootstrapper.cs +++ b/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 /// /// /// The name of the file this appender will write to. - /// + /// /// This does not call appender.ActivateOptions or add the appender to the logger. - 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, diff --git a/src/Agent/NewRelic/Agent/Core/Logging/NrLogLevelEnricher.cs b/src/Agent/NewRelic/Agent/Core/Logging/NrLogLevelEnricher.cs index ae48b788fb..361e7d74b9 100644 --- a/src/Agent/NewRelic/Agent/Core/Logging/NrLogLevelEnricher.cs +++ b/src/Agent/NewRelic/Agent/Core/Logging/NrLogLevelEnricher.cs @@ -10,6 +10,7 @@ namespace NewRelic.Agent.Core /// /// Maps serilog log level to corresponding "legacy" log4net loglevel and adds the mapped value as a property named NRLogLevel /// + [NrExcludeFromCodeCoverage] internal class NrLogLevelEnricher : ILogEventEnricher { [NrExcludeFromCodeCoverage] diff --git a/src/Agent/NewRelic/Agent/Core/Logging/ProcessIdEnricher.cs b/src/Agent/NewRelic/Agent/Core/Logging/ProcessIdEnricher.cs index c5171e9c7f..bc2cffc980 100644 --- a/src/Agent/NewRelic/Agent/Core/Logging/ProcessIdEnricher.cs +++ b/src/Agent/NewRelic/Agent/Core/Logging/ProcessIdEnricher.cs @@ -8,14 +8,21 @@ namespace NewRelic.Agent.Core { + /// + /// Adds a pid property to the log event containing the current process id + /// [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); } } } diff --git a/src/Agent/NewRelic/Agent/Core/Logging/ThreadIdEnricher.cs b/src/Agent/NewRelic/Agent/Core/Logging/ThreadIdEnricher.cs index 5fbc34b31e..197e4878db 100644 --- a/src/Agent/NewRelic/Agent/Core/Logging/ThreadIdEnricher.cs +++ b/src/Agent/NewRelic/Agent/Core/Logging/ThreadIdEnricher.cs @@ -8,13 +8,21 @@ namespace NewRelic.Agent.Core { + /// + /// Adds a tid property to the log event containing the current managed thread id + /// [NrExcludeFromCodeCoverage] internal class ThreadIdEnricher : ILogEventEnricher { + + private static readonly ThreadLocal _tidProperty = new ThreadLocal(); + 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); } } } diff --git a/src/Agent/NewRelic/Agent/Core/Logging/UTCTimestampEnricher.cs b/src/Agent/NewRelic/Agent/Core/Logging/UTCTimestampEnricher.cs new file mode 100644 index 0000000000..91eef8bfb4 --- /dev/null +++ b/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 +{ + /// + /// Formats the current UTC time for logging in the agent + /// + [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}")); + } + } +} diff --git a/src/Agent/NewRelic/Agent/Extensions/Providers/Wrapper/Owin/Owin.csproj b/src/Agent/NewRelic/Agent/Extensions/Providers/Wrapper/Owin/Owin.csproj index e25d1f29e9..071bac15e0 100644 --- a/src/Agent/NewRelic/Agent/Extensions/Providers/Wrapper/Owin/Owin.csproj +++ b/src/Agent/NewRelic/Agent/Extensions/Providers/Wrapper/Owin/Owin.csproj @@ -5,6 +5,9 @@ NewRelic.Providers.Wrapper.Owin Owin 2 Wrapper Provider for New Relic .NET Agent + + NU1903 + diff --git a/src/Agent/NewRelic/Agent/Extensions/Providers/Wrapper/WebApi1/WebApi1.csproj b/src/Agent/NewRelic/Agent/Extensions/Providers/Wrapper/WebApi1/WebApi1.csproj index e22a38e318..5f12008b12 100644 --- a/src/Agent/NewRelic/Agent/Extensions/Providers/Wrapper/WebApi1/WebApi1.csproj +++ b/src/Agent/NewRelic/Agent/Extensions/Providers/Wrapper/WebApi1/WebApi1.csproj @@ -5,6 +5,9 @@ NewRelic.Providers.Wrapper.WebApi1 Web API 1 Wrapper Provider for New Relic .NET Agent + + NU1903 + diff --git a/tests/Agent/IntegrationTests/IntegrationTests/AgentLogs/LogFileFormatTests.cs b/tests/Agent/IntegrationTests/IntegrationTests/AgentLogs/LogFileFormatTests.cs new file mode 100644 index 0000000000..d001275456 --- /dev/null +++ b/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 + { + 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); + } + } +}