Resolve issue with missing logs

src/Agent/CHANGELOG.md

@@ -9,6 +9,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 ### New Features
 
 ### Fixes
+* Resolves an issue where log forwarding could drop logs in async scenarios. [#1174](https://github.com/newrelic/newrelic-dotnet-agent/pull/1201)
 
 ## [10.0.0] - 2022-07-19
 

src/Agent/NewRelic/Agent/Core/Agent.cs

@@ -406,7 +406,7 @@ public void RecordSupportabilityMetric(string metricName, int count)
             _agentHealthReporter.ReportSupportabilityCountMetric(metricName, count);
         }
 
-        public void RecordLogMessage(string frameworkName, object logEvent, Func<object,DateTime> getTimestamp, Func<object,object> getLevel, Func<object,string> getLogMessage, string spanId, string traceId)
+        public void RecordLogMessage(string frameworkName, object logEvent, Func<object, DateTime> getTimestamp, Func<object, object> getLevel, Func<object, string> getLogMessage, string spanId, string traceId)
         {
             _agentHealthReporter.ReportLogForwardingFramework(frameworkName);
 
@@ -424,7 +424,7 @@ public void RecordLogMessage(string frameworkName, object logEvent, Func<object,
             }
 
             // IOC container defaults to singleton so this will access the same aggregator
-            if (_configurationService.Configuration.LogEventCollectorEnabled) 
+            if (_configurationService.Configuration.LogEventCollectorEnabled)
             {
                 var logMessage = getLogMessage(logEvent);
                 if (string.IsNullOrWhiteSpace(logMessage))
@@ -437,15 +437,21 @@ public void RecordLogMessage(string frameworkName, object logEvent, Func<object,
                 if (transaction != null && transaction.IsValid)
                 {
                     // use transaction batching for messages in transactions
-                    transaction.LogEvents.Add(new LogEventWireModel(timestamp, logMessage, normalizedLevel, spanId, traceId));
+                    if (!transaction.AddLogEvent(new LogEventWireModel(timestamp, logMessage, normalizedLevel, spanId, traceId)))
+                    {
+                        // AddLogEvent returns false in the case that logs have already been harvested by transaction transform.
+                        // Fall back to collecting the log based on the information we have. Since the transaction was finalized,
+                        // the Priority should be correct.
+                        _logEventAggregator.Collect(new LogEventWireModel(timestamp, logMessage, normalizedLevel, spanId,
+                            traceId, transaction.Priority));
+                    }
                     return;
                 }
 
                 // non-transaction messages with proper sanitized priority value
                 _logEventAggregator.Collect(new LogEventWireModel(timestamp,
                     logMessage, normalizedLevel, spanId, traceId, _transactionService.CreatePriority()));
             }
-
         }
 
         #endregion

src/Agent/NewRelic/Agent/Core/Transactions/IInternalTransaction.cs

@@ -24,7 +24,6 @@ public interface IInternalTransaction : ITransaction, ITransactionExperimental
         /// parent segment (unless it is a root segment).
         /// </summary>
         IList<Segment> Segments { get; }
-        IList<LogEventWireModel> LogEvents { get; }
         ICandidateTransactionName CandidateTransactionName { get; }
         void RollupTransactionNameByStatusCodeIfNeeded();
         ITransactionMetadata TransactionMetadata { get; }
@@ -82,5 +81,19 @@ public interface IInternalTransaction : ITransaction, ITransactionExperimental
         ITransactionSegmentState GetTransactionSegmentState();
 
         void NoticeError(ErrorData errorData);
+
+        /// <summary>
+        /// Harvests the log events from the transaction. After doing this, no more logs can be added to the transaction.
+        /// </summary>
+        /// <returns>The accumulated logs on the first call, or null if logs have already been harvested</returns>
+        IList<LogEventWireModel> HarvestLogEvents();
+
+        /// <summary>
+        /// Attempts to add a log to the current transaction. Logs cannot be added after the transaction transform has
+        /// harvested logs.
+        /// </summary>
+        /// <param name="logEvent">The log event to add</param>
+        /// <returns>true if the log was added, false if the log was unable to be added</returns>
+        bool AddLogEvent(LogEventWireModel logEvent);
     }
 }

src/Agent/NewRelic/Agent/Core/Transactions/Transaction.cs

@@ -867,8 +867,26 @@ public ITransaction AddCustomAttribute(string key, object value)
             return this;
         }
 
-        private readonly ConcurrentList<LogEventWireModel> _logEvents = new ConcurrentList<LogEventWireModel>();
-        public IList<LogEventWireModel> LogEvents { get => _logEvents; }
+        private ConcurrentList<LogEventWireModel> _logEvents = new ConcurrentList<LogEventWireModel>();
+
+        public IList<LogEventWireModel> HarvestLogEvents()
+        {
+            return Interlocked.Exchange(ref _logEvents, null);
+        }
+
+        public bool AddLogEvent(LogEventWireModel logEvent)
+        {
+            try
+            {
+                _logEvents.Add(logEvent);
+                return true;
+            }
+            catch (Exception)
+            {
+                // We will hit this if logs have been harvested from the transaction already...
+            }
+            return false;
+        }
 
         private readonly ConcurrentList<Segment> _segments = new ConcurrentList<Segment>();
         public IList<Segment> Segments { get => _segments; }

src/Agent/NewRelic/Agent/Core/Transformers/TransactionTransformer/TransactionTransformer.cs

@@ -20,6 +20,7 @@
 using System;
 using System.Collections.Generic;
 using System.Linq;
+using System.Threading;
 using static NewRelic.Agent.Core.WireModels.MetricWireModel;
 
 namespace NewRelic.Agent.Core.Transformers.TransactionTransformer
@@ -92,7 +93,7 @@ public void Transform(IInternalTransaction transaction)
 
             ComputeSampled(transaction);
             PrioritizeAndCollectLogEvents(transaction);
-
+            
             var immutableTransaction = transaction.ConvertToImmutableTransaction();
 
             // Note: Metric names are normally handled internally by the IMetricBuilder. However, transactionMetricName is an exception because (sadly) it is used for more than just metrics. For example, transaction events need to use metric name, as does RUM and CAT.
@@ -475,7 +476,7 @@ private bool ErrorCollectionEnabled()
 
         private void PrioritizeAndCollectLogEvents(IInternalTransaction transaction)
         {
-            _logEventAggregator.CollectWithPriority(transaction.LogEvents, transaction.Priority);
+            _logEventAggregator.CollectWithPriority(transaction.HarvestLogEvents(), transaction.Priority);
         }
     }
 }

tests/Agent/IntegrationTests/IntegrationTestHelpers/RemoteServiceFixtures/RemoteService.cs

@@ -218,6 +218,7 @@ public override void Start(string commandLineArguments, Dictionary<string, strin
             startInfo.EnvironmentVariables.Remove("NEWRELIC_LICENSEKEY");
             startInfo.EnvironmentVariables.Remove("NEW_RELIC_LICENSE_KEY");
             startInfo.EnvironmentVariables.Remove("NEW_RELIC_HOST");
+            startInfo.EnvironmentVariables.Remove("NEWRELIC_INSTALL_PATH");
 
             startInfo.EnvironmentVariables.Remove("CORECLR_ENABLE_PROFILING");
             startInfo.EnvironmentVariables.Remove("CORECLR_PROFILER");

tests/Agent/UnitTests/Core.UnitTest/Transactions/TransactionLogEventTests.cs

@@ -0,0 +1,46 @@
+// Copyright 2020 New Relic, Inc. All rights reserved.
+// SPDX-License-Identifier: Apache-2.0
+
+using System;
+using System.Collections.Generic;
+using System.Linq;
+using System.Text;
+using System.Threading.Tasks;
+using NewRelic.Agent.Core.Transformers.TransactionTransformer;
+using NewRelic.Agent.Core.WireModels;
+using NUnit.Framework;
+
+namespace NewRelic.Agent.Core.Transactions
+{
+    [TestFixture]
+    internal class TransactionLogEventTests
+    {
+        [Test]
+        public void CanAddAndHarvestLogFromTransaction()
+        {
+            var logEvent = new LogEventWireModel(1, "message1", "info", "spanid", "traceid");
+            var transaction = TestTransactions.CreateDefaultTransaction();
+
+            transaction.AddLogEvent(logEvent);
+            var harvestedLogs = transaction.HarvestLogEvents();
+
+            Assert.NotNull(harvestedLogs);
+            Assert.AreEqual(1, harvestedLogs.Count);
+            Assert.AreSame(logEvent, harvestedLogs.First());
+
+        }
+
+        [Test]
+        public void AddLogEventReturnsFalse_AfterLogEventsHarvested()
+        {
+            var logEvent = new LogEventWireModel(1, "message1", "info", "spanid", "traceid");
+            var transaction = TestTransactions.CreateDefaultTransaction();
+
+            transaction.HarvestLogEvents();
+
+            var result = transaction.AddLogEvent(logEvent);
+
+            Assert.False(result);
+        }
+    }
+}

tests/Agent/UnitTests/Core.UnitTest/Transformers/TransactionTransformer/TransactionTransformerTests.cs

@@ -1408,7 +1408,7 @@ public void PrioritizeAndCollectLogEvents_PriorityMatchesTransaction()
             var logEvent = new LogEventWireModel(1, "message1", "info", "spanid", "traceid");
 
             var transaction = TestTransactions.CreateDefaultTransaction();
-            transaction.LogEvents.Add(logEvent);
+            transaction.AddLogEvent(logEvent);
 
             _transactionTransformer.Transform(transaction);
 
@@ -1422,6 +1422,17 @@ public void PrioritizeAndCollectLogEvents_PriorityMatchesTransaction()
             Assert.AreEqual(transaction.Priority, handledLogEvent.Priority, $"{transaction.Priority} vs {handledLogEvent.Priority}");
         }
 
+        [Test]
+        public void CannotAddLogEventsToTransaction_AfterTransform()
+        {
+            var logEvent = new LogEventWireModel(1, "message1", "info", "spanid", "traceid");
+            var transaction = TestTransactions.CreateDefaultTransaction();
+
+            _transactionTransformer.Transform(transaction);
+
+            Assert.False(transaction.AddLogEvent(logEvent));
+        }
+
         #endregion
 
         #region Helpers

tests/Agent/UnitTests/Core.UnitTest/Wrapper/AgentWrapperApi/AgentWrapperApiTests.cs

@@ -1381,8 +1381,50 @@ public void RecordLogMessage_WithTransaction_Success()
             var xapi = _agent as IAgentExperimental;
             xapi.RecordLogMessage(loggingFramework, new object(), getTimestampFunc, getLevelFunc, getMessageFunc, spanId, traceId);
 
-            var logEvent = transaction.LogEvents?.FirstOrDefault();
-            Assert.AreEqual(1, transaction.LogEvents.Count);
+            var harvestedLogEvents = transaction.HarvestLogEvents();
+            var logEvent = harvestedLogEvents.FirstOrDefault();
+            Assert.AreEqual(1, harvestedLogEvents.Count);
+            Assert.IsNotNull(logEvent);
+            Assert.AreEqual(timestampUnix, logEvent.TimeStamp);
+            Assert.AreEqual(level, logEvent.Level);
+            Assert.AreEqual(message, logEvent.Message);
+            Assert.AreEqual(spanId, logEvent.SpanId);
+            Assert.AreEqual(traceId, logEvent.TraceId);
+            Assert.AreEqual(priority, logEvent.Priority);
+        }
+
+        [Test]
+        public void RecordLogMessage_WithTransaction_ThatHasHadLogsHarvested_FallsBackToLogAggregator()
+        {
+            Mock.Arrange(() => _configurationService.Configuration.LogEventCollectorEnabled)
+                .Returns(true);
+
+            var timestamp = DateTime.Now;
+            var timestampUnix = timestamp.ToUnixTimeMilliseconds();
+            var level = "DEBUG";
+            var message = "message";
+
+            Func<object, string> getLevelFunc = (l) => level;
+            Func<object, DateTime> getTimestampFunc = (l) => timestamp;
+            Func<object, string> getMessageFunc = (l) => message;
+
+            var spanId = "spanid";
+            var traceId = "traceid";
+            var loggingFramework = "testFramework";
+
+            SetupTransaction();
+            var transaction = _transactionService.GetCurrentInternalTransaction();
+            var priority = transaction.Priority;
+            transaction.HarvestLogEvents();
+
+            var xapi = _agent as IAgentExperimental;
+            xapi.RecordLogMessage(loggingFramework, new object(), getTimestampFunc, getLevelFunc, getMessageFunc, spanId, traceId);
+
+            var privateAccessor = new PrivateAccessor(_logEventAggregator);
+            var logEvents = privateAccessor.GetField("_logEvents") as ConcurrentPriorityQueue<PrioritizedNode<LogEventWireModel>>;
+
+            var logEvent = logEvents?.FirstOrDefault()?.Data;
+            Assert.AreEqual(1, logEvents.Count);
             Assert.IsNotNull(logEvent);
             Assert.AreEqual(timestampUnix, logEvent.TimeStamp);
             Assert.AreEqual(level, logEvent.Level);