fix: Format and log audit-level messages only when audit logging is enabled. (#1734)

Author: tippmar-nr

src/Agent/NewRelic/Agent/Core/DataTransport/HttpCollectorWire.cs

@@ -156,10 +156,14 @@ public string SendData(string method, ConnectionInfo connectionInfo, string seri
             }
         }
 
-        private static void AuditLog(Direction direction, Source source, string uri)
+        private void AuditLog(Direction direction, Source source, string uri)
         {
-            var message = string.Format(AuditLogFormat, direction, source, Strings.ObfuscateLicenseKeyInAuditLog(uri, LicenseKeyParameterName));
-            Logging.AuditLog.Log(message);
+            if (Logging.AuditLog.IsAuditLogEnabled)
+            {
+                var message = string.Format(AuditLogFormat, direction, source,
+                    Strings.ObfuscateLicenseKeyInAuditLog(uri, LicenseKeyParameterName));
+                Logging.AuditLog.Log(message);
+            }
         }
 
         private Uri GetUri(string method, ConnectionInfo connectionInfo)

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

@@ -10,27 +10,43 @@ namespace NewRelic.Agent.Core.Logging
     public static class AuditLog
     {
         // a lazy ILogger instance that injects an "Audit" property
-        private static Lazy<ILogger> _lazyAuditLogger = new Lazy<ILogger>(() =>
-            Serilog.Log.Logger.ForContext(LogLevelExtensions.AuditLevel, LogLevelExtensions.AuditLevel));
+        private static Lazy<ILogger> _lazyAuditLogger = LazyAuditLogger();
+
+        public static bool IsAuditLogEnabled { get; set; } //setter is public only for unit tests, not expected to be use anywhere else
+
+        // for unit tests only
+        public static void ResetLazyLogger()
+        {
+            _lazyAuditLogger = LazyAuditLogger();
+        }
+
+        private static Lazy<ILogger> LazyAuditLogger()
+        {
+            return new Lazy<ILogger>(() =>
+                Serilog.Log.Logger.ForContext(LogLevelExtensions.AuditLevel, LogLevelExtensions.AuditLevel));
+        }
 
         /// <summary>
         /// Logs <paramref name="message"/> at the AUDIT level. This log level should be used only as dictated by the security team to satisfy auditing requirements.
         /// </summary>
         public static void Log(string message)
         {
+            if (IsAuditLogEnabled)
                 // use Fatal log level to ensure audit log messages never get filtered due to level restrictions
                 _lazyAuditLogger.Value.Fatal(message);
         }
 
-        internal static LoggerConfiguration IncludeOnlyAuditLog(this LoggerConfiguration loggerConfiguration)
+        public static LoggerConfiguration IncludeOnlyAuditLog(this LoggerConfiguration loggerConfiguration)
         {
-            return loggerConfiguration.Filter.ByIncludingOnly($"{LogLevelExtensions.AuditLevel} is not null");
+            IsAuditLogEnabled = true; // set a flag so Log() can short-circuit when audit log is not enabled
 
-            //return loggerConfiguration.Filter.ByIncludingOnly(logEvent =>
-            //    logEvent.Properties.ContainsKey(LogLevelExtensions.AuditLevel));
+            return loggerConfiguration.Filter.ByIncludingOnly($"{LogLevelExtensions.AuditLevel} is not null");
         }
-        internal static LoggerConfiguration ExcludeAuditLog(this LoggerConfiguration loggerConfiguration)
+
+        public static LoggerConfiguration ExcludeAuditLog(this LoggerConfiguration loggerConfiguration)
         {
+            IsAuditLogEnabled = false; // set a flag so Log() can short-circuit when audit log is not enabled
+
             return loggerConfiguration.Filter.ByIncludingOnly($"{LogLevelExtensions.AuditLevel} is null");
         }
     }

tests/Agent/UnitTests/Core.UnitTest/DataTransport/HttpCollectorWireTests.cs

@@ -15,6 +15,8 @@
 using System.Threading.Tasks;
 using System.Threading;
 using NewRelic.Agent.Core.Exceptions;
+using NewRelic.Agent.Core.Logging;
+using Serilog;
 using Telerik.JustMock;
 
 namespace NewRelic.Agent.Core.DataTransport
@@ -26,13 +28,17 @@ public class HttpCollectorWireTests
         private IAgentHealthReporter _agentHealthReporter;
         private IHttpClientFactory _httpClientFactory;
         private MockHttpMessageHandler _mockHttpMessageHandler;
+        private ILogger _mockILogger;
 
         [SetUp]
         public void SetUp()
         {
             _configuration = Mock.Create<IConfiguration>();
             _agentHealthReporter = Mock.Create<IAgentHealthReporter>();
             _httpClientFactory = Mock.Create<IHttpClientFactory>();
+
+            _mockILogger = Mock.Create<ILogger>();
+            Log.Logger = _mockILogger;
         }
 
         private HttpCollectorWire CreateHttpCollectorWire(Dictionary<string, string> requestHeadersMap = null)
@@ -306,6 +312,39 @@ public void SendData_ShouldDropPayload_WhenPayloadSizeExceedsMaxSize()
             Mock.Assert(() => _httpClientFactory.CreateClient(Arg.IsAny<IWebProxy>()), Occurs.Never());
             Assert.AreEqual(false, _mockHttpMessageHandler.SendAsyncInvoked);
         }
+
+        [TestCase(false)]
+        [TestCase(true)]
+        public void SendData_ShouldNotCallAuditLog_UnlessAuditLogIsEnabled(bool isEnabled)
+        {
+            // Arrange
+            AuditLog.ResetLazyLogger();
+            Mock.Arrange(() => _configuration.AgentLicenseKey).Returns("license_key");
+            Mock.Arrange(() => _configuration.CollectorMaxPayloadSizeInBytes).Returns(1024);
+
+            var connectionInfo = new ConnectionInfo(_configuration);
+            var serializedData = "{ \"key\": \"value\" }";
+            var httpResponse = new HttpResponseMessage(HttpStatusCode.OK)
+            {
+                Content = new StringContent("{}")
+            };
+
+            CreateMockHttpClient(httpResponse, false);
+
+            var collectorWire = CreateHttpCollectorWire();
+
+            var mockForContextLogger = Mock.Create<ILogger>();
+            Mock.Arrange(() => _mockILogger.ForContext(Arg.AnyString, Arg.AnyObject, false))
+                .Returns(() => mockForContextLogger);
+
+            AuditLog.IsAuditLogEnabled = isEnabled;
+
+            // Act
+            var _ = collectorWire.SendData("test_method", connectionInfo, serializedData, Guid.NewGuid());
+
+            // Assert
+            Mock.Assert(() => mockForContextLogger.Fatal(Arg.AnyString), isEnabled ? Occurs.Exactly(3) : Occurs.Never());
+        }
     }
 
     public class MockHttpMessageHandler : HttpMessageHandler

tests/Agent/UnitTests/Core.UnitTest/Logging/AuditLogTests.cs

@@ -0,0 +1,70 @@
+// Copyright 2020 New Relic, Inc. All rights reserved.
+// SPDX-License-Identifier: Apache-2.0
+
+using NUnit.Framework;
+using Serilog;
+using Serilog.Configuration;
+using Telerik.JustMock;
+
+namespace NewRelic.Agent.Core.Logging.Tests
+{
+    [TestFixture]
+    public class AuditLogTests
+    {
+        private ILogger _mockILogger;
+
+        [SetUp]
+        public void SetUp()
+        {
+            _mockILogger = Mock.Create<ILogger>();
+            Log.Logger = _mockILogger;
+
+            // reset state for each test
+            AuditLog.ResetLazyLogger();
+            AuditLog.IsAuditLogEnabled = false;
+        }
+
+        [TearDown]
+        public void TearDown()
+        {
+            AuditLog.ResetLazyLogger();
+        }
+
+        [Test]
+        public void IncludeOnlyAuditLog_EnablesAuditLog()
+        {
+            Assert.False(AuditLog.IsAuditLogEnabled);
+
+            var _ = new LoggerConfiguration().IncludeOnlyAuditLog();
+
+            Assert.True(AuditLog.IsAuditLogEnabled);
+        }
+
+        [Test]
+        public void ExcludeAuditLog_DisablesAuditLog()
+        {
+            AuditLog.IsAuditLogEnabled = true;
+
+            var _ = new LoggerConfiguration().ExcludeAuditLog();
+
+            Assert.False(AuditLog.IsAuditLogEnabled);
+        }
+
+        [TestCase(true)]
+        [TestCase(false)]
+        public void Log_OnlyLogsWhenAuditLogEnabled(bool logEnabled)
+        {
+            var mockForContextLogger = Mock.Create<ILogger>();
+            Mock.Arrange(() => _mockILogger.ForContext(Arg.AnyString, Arg.AnyObject, false))
+                .Returns(() => mockForContextLogger);
+        
+            AuditLog.IsAuditLogEnabled = logEnabled;
+
+            var message = "This is an audit message";
+
+            AuditLog.Log(message);
+
+            Mock.Assert(() => mockForContextLogger.Fatal(message), logEnabled ? Occurs.Once() : Occurs.Never());
+        }
+    }
+}