Skip to content

Commit

Permalink
feat: Add more detail to "heartbeat" message in log. (#1884)
Browse files Browse the repository at this point in the history
  • Loading branch information
chynesNR committed Sep 13, 2023
1 parent 2e5c3d1 commit c0c1362
Show file tree
Hide file tree
Showing 4 changed files with 148 additions and 13 deletions.
Expand Up @@ -6,6 +6,12 @@ namespace NewRelic.Agent.Core.AgentHealth
public enum AgentHealthEvent
{
TransactionGarbageCollected,
WrapperShutdown
WrapperShutdown,
Transaction,
Log,
Custom,
Error,
Span,
InfiniteTracingSpan
}
}
47 changes: 36 additions & 11 deletions src/Agent/NewRelic/Agent/Core/AgentHealth/AgentHealthReporter.cs
Expand Up @@ -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;
Expand All @@ -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)
{
Expand All @@ -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<string> events = new List<string>();
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)
Expand Down Expand Up @@ -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

Expand All @@ -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

Expand All @@ -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

Expand Down Expand Up @@ -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

Expand Down Expand Up @@ -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);

}

Expand Down Expand Up @@ -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));

Expand Down
Expand Up @@ -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)
{
Expand Down
@@ -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<IMetricNameService>();
Mock.Arrange(() => metricNameService.RenameMetric(Arg.IsAny<string>())).Returns<string>(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"));
}
}
}
}

0 comments on commit c0c1362

Please sign in to comment.