diff --git a/src/Agent/NewRelic/Agent/Core/AgentHealth/AgentHealthEvent.cs b/src/Agent/NewRelic/Agent/Core/AgentHealth/AgentHealthEvent.cs index 825aac000..59ed0f028 100644 --- a/src/Agent/NewRelic/Agent/Core/AgentHealth/AgentHealthEvent.cs +++ b/src/Agent/NewRelic/Agent/Core/AgentHealth/AgentHealthEvent.cs @@ -6,6 +6,12 @@ namespace NewRelic.Agent.Core.AgentHealth public enum AgentHealthEvent { TransactionGarbageCollected, - WrapperShutdown + WrapperShutdown, + Transaction, + Log, + Custom, + Error, + Span, + InfiniteTracingSpan } } diff --git a/src/Agent/NewRelic/Agent/Core/AgentHealth/AgentHealthReporter.cs b/src/Agent/NewRelic/Agent/Core/AgentHealth/AgentHealthReporter.cs index a0dea3ea5..64f29e3f0 100644 --- a/src/Agent/NewRelic/Agent/Core/AgentHealth/AgentHealthReporter.cs +++ b/src/Agent/NewRelic/Agent/Core/AgentHealth/AgentHealthReporter.cs @@ -22,7 +22,7 @@ namespace NewRelic.Agent.Core.AgentHealth { public class AgentHealthReporter : ConfigurationBasedService, IAgentHealthReporter { - private static readonly TimeSpan _timeBetweenExecutions = TimeSpan.FromMinutes(1); + private static readonly TimeSpan _timeBetweenExecutions = TimeSpan.FromMinutes(2); private readonly IMetricBuilder _metricBuilder; private readonly IScheduler _scheduler; @@ -42,7 +42,7 @@ public AgentHealthReporter(IMetricBuilder metricBuilder, IScheduler scheduler) { _metricBuilder = metricBuilder; _scheduler = scheduler; - _scheduler.ExecuteEvery(LogRecurringLogs, _timeBetweenExecutions); + _scheduler.ExecuteEvery(LogPeriodicReport, _timeBetweenExecutions); var agentHealthEvents = Enum.GetValues(typeof(AgentHealthEvent)) as AgentHealthEvent[]; foreach (var agentHealthEvent in agentHealthEvents) { @@ -58,25 +58,28 @@ public AgentHealthReporter(IMetricBuilder metricBuilder, IScheduler scheduler) public override void Dispose() { base.Dispose(); - _scheduler.StopExecuting(LogRecurringLogs); + _scheduler.StopExecuting(LogPeriodicReport); } - private void LogRecurringLogs() + private void LogPeriodicReport() { foreach (var data in _recurringLogDatas) { data?.LogAction(data.Message); } - + + List events = new List(); foreach (var counter in _agentHealthEventCounters) { if (counter.Value != null && counter.Value.Value > 0) { var agentHealthEvent = counter.Key; var timesOccured = counter.Value.Exchange(0); - Log.Info($"Event {agentHealthEvent} has occurred {timesOccured} times in the last {_timeBetweenExecutions.TotalSeconds} seconds"); + events.Add(string.Format("{0} {1} {2}", timesOccured, agentHealthEvent, (timesOccured == 1) ? "event" : "events")); } } + var message = events.Count > 0 ? string.Join(", ", events) : "No events"; + Log.Info($"In the last {_timeBetweenExecutions.TotalMinutes} minutes: {message}"); } public void ReportSupportabilityCountMetric(string metricName, long count = 1) @@ -142,7 +145,11 @@ public void ReportTransactionEventCollected() public void ReportTransactionEventsRecollected(int count) => TrySend(_metricBuilder.TryBuildTransactionEventsRecollectedMetric(count)); - public void ReportTransactionEventsSent(int count) => TrySend(_metricBuilder.TryBuildTransactionEventsSentMetric(count)); + public void ReportTransactionEventsSent(int count) + { + TrySend(_metricBuilder.TryBuildTransactionEventsSentMetric(count)); + _agentHealthEventCounters[AgentHealthEvent.Transaction]?.Add(count); + } #endregion TransactionEvents @@ -165,7 +172,12 @@ public void ReportCustomEventCollected() public void ReportCustomEventsRecollected(int count) => TrySend(_metricBuilder.TryBuildCustomEventsRecollectedMetric(count)); // Note: Though not required by APM like the transaction event supportability metrics, this metric should still be created to maintain consistency - public void ReportCustomEventsSent(int count) => TrySend(_metricBuilder.TryBuildCustomEventsSentMetric(count)); + public void ReportCustomEventsSent(int count) + { + TrySend(_metricBuilder.TryBuildCustomEventsSentMetric(count)); + _agentHealthEventCounters[AgentHealthEvent.Custom]?.Add(count); + + } #endregion CustomEvents @@ -183,7 +195,11 @@ public void ReportCustomEventCollected() public void ReportErrorEventSeen() => TrySend(_metricBuilder.TryBuildErrorEventsSeenMetric()); - public void ReportErrorEventsSent(int count) => TrySend(_metricBuilder.TryBuildErrorEventsSentMetric(count)); + public void ReportErrorEventsSent(int count) + { + TrySend(_metricBuilder.TryBuildErrorEventsSentMetric(count)); + _agentHealthEventCounters[AgentHealthEvent.Error]?.Add(count); + } #endregion ErrorEvents @@ -381,7 +397,11 @@ public void CollectTraceContextSuccessMetrics() public void ReportSpanEventCollected(int count) => TrySend(_metricBuilder.TryBuildSpanEventsSeenMetric(count)); - public void ReportSpanEventsSent(int count) => TrySend(_metricBuilder.TryBuildSpanEventsSentMetric(count)); + public void ReportSpanEventsSent(int count) + { + TrySend(_metricBuilder.TryBuildSpanEventsSentMetric(count)); + _agentHealthEventCounters[AgentHealthEvent.Span]?.Add(count); + } #endregion Span @@ -429,6 +449,7 @@ public void ReportInfiniteTracingSpanEventsSent(long countSpans) _infiniteTracingSpanBatchSizeMin = Math.Min(_infiniteTracingSpanBatchSizeMin, countSpans); _infiniteTracingSpanBatchSizeMax = Math.Max(_infiniteTracingSpanBatchSizeMax, countSpans); } + _agentHealthEventCounters[AgentHealthEvent.InfiniteTracingSpan]?.Add((int)countSpans); } @@ -616,7 +637,11 @@ public void IncrementLogDeniedCount(string level) public void ReportLoggingEventCollected() => TrySend(_metricBuilder.TryBuildSupportabilityLoggingEventsCollectedMetric()); - public void ReportLoggingEventsSent(int count) => TrySend(_metricBuilder.TryBuildSupportabilityLoggingEventsSentMetric(count)); + public void ReportLoggingEventsSent(int count) + { + TrySend(_metricBuilder.TryBuildSupportabilityLoggingEventsSentMetric(count)); + _agentHealthEventCounters[AgentHealthEvent.Log]?.Add(count); + } public void ReportLoggingEventsDropped(int droppedCount)=> TrySend(_metricBuilder.TryBuildSupportabilityLoggingEventsDroppedMetric(droppedCount)); diff --git a/src/Agent/NewRelic/Agent/Core/Aggregators/MetricAggregator.cs b/src/Agent/NewRelic/Agent/Core/Aggregators/MetricAggregator.cs index 0d8f43853..eecb5f2cd 100644 --- a/src/Agent/NewRelic/Agent/Core/Aggregators/MetricAggregator.cs +++ b/src/Agent/NewRelic/Agent/Core/Aggregators/MetricAggregator.cs @@ -62,7 +62,7 @@ public override void Collect(IAllMetricStatsCollection metric) } protected override void Harvest() { - Log.Info("Metric harvest starting."); + Log.Finest("Metric harvest starting."); foreach (var source in _outOfBandMetricSources) { diff --git a/tests/Agent/UnitTests/Core.UnitTest/AgentHealth/AgentHealthHeartbeatTests.cs b/tests/Agent/UnitTests/Core.UnitTest/AgentHealth/AgentHealthHeartbeatTests.cs new file mode 100644 index 000000000..763382d02 --- /dev/null +++ b/tests/Agent/UnitTests/Core.UnitTest/AgentHealth/AgentHealthHeartbeatTests.cs @@ -0,0 +1,104 @@ +// Copyright 2020 New Relic, Inc. All rights reserved. +// SPDX-License-Identifier: Apache-2.0 + +using System; +using NewRelic.Agent.Core.Metrics; +using NewRelic.Agent.Core.Time; +using NewRelic.Agent.Core.WireModels; +using NewRelic.Testing.Assertions; +using NUnit.Framework; +using Telerik.JustMock; + +namespace NewRelic.Agent.Core.AgentHealth +{ + internal class FakeScheduler : IScheduler + { + protected Action _action; + public void ExecuteOnce(Action action, TimeSpan timeUntilExecution) + { + _action = action; + } + + public void ExecuteEvery(Action action, TimeSpan timeBetweenExecutions, TimeSpan? optionalInitialDelay = null) + { + _action = action; + } + + public void StopExecuting(Action action, TimeSpan? timeToWaitForInProgressAction = null) + { + _action = null; + } + + public void ForceExecute() + { + _action?.Invoke(); + } + } + + [TestFixture] + internal class AgentHealthHeartbeatTests + { + public static IMetricBuilder GetSimpleMetricBuilder() + { + var metricNameService = Mock.Create(); + Mock.Arrange(() => metricNameService.RenameMetric(Arg.IsAny())).Returns(name => name); + return new MetricWireModel.MetricBuilder(metricNameService); + } + + [Test] + public void HeartbeatTest() + { + var scheduler = new FakeScheduler(); + var reporter = new AgentHealthReporter(GetSimpleMetricBuilder(), scheduler); + using (var logger = new TestUtilities.Logging()) + { + // Make sure all the event types get seen in the log + reporter.ReportTransactionEventsSent(1); + reporter.ReportCustomEventsSent(2); + reporter.ReportErrorEventsSent(3); + reporter.ReportSpanEventsSent(4); + reporter.ReportInfiniteTracingSpanEventsSent(5); + reporter.ReportLoggingEventsSent(6); + + scheduler.ForceExecute(); + + NrAssert.Multiple( + () => Assert.IsTrue(logger.HasMessageThatContains("1 Transaction")), + () => Assert.IsTrue(logger.HasMessageThatContains("2 Custom")), + () => Assert.IsTrue(logger.HasMessageThatContains("3 Error")), + () => Assert.IsTrue(logger.HasMessageThatContains("4 Span")), + () => Assert.IsTrue(logger.HasMessageThatContains("5 InfiniteTracingSpan")), + () => Assert.IsTrue(logger.HasMessageThatContains("6 Log")), + () => Assert.IsFalse(logger.HasMessageThatContains("No events")) + ); + + // Make sure they all update their cumulative counts + for (int twice = 0; twice < 2; twice++) + { + reporter.ReportTransactionEventsSent(1); + reporter.ReportCustomEventsSent(2); + reporter.ReportErrorEventsSent(3); + reporter.ReportSpanEventsSent(4); + reporter.ReportInfiniteTracingSpanEventsSent(5); + reporter.ReportLoggingEventsSent(6); + } + + scheduler.ForceExecute(); + NrAssert.Multiple( + () => Assert.IsTrue(logger.HasMessageThatContains("2 Transaction")), + () => Assert.IsTrue(logger.HasMessageThatContains("4 Custom")), + () => Assert.IsTrue(logger.HasMessageThatContains("6 Error")), + () => Assert.IsTrue(logger.HasMessageThatContains("8 Span")), + () => Assert.IsTrue(logger.HasMessageThatContains("10 InfiniteTracingSpan")), + () => Assert.IsTrue(logger.HasMessageThatContains("12 Log")), + () => Assert.IsFalse(logger.HasMessageThatContains("No events")) + ); + + // Make sure they get cleared out between triggers + scheduler.ForceExecute(); + + Assert.IsTrue(logger.HasMessageThatContains("No events")); + } + } + } +}