Skip to content

Commit c0c1362

Browse files
chynesNRchynesNR
authored
feat: Add more detail to "heartbeat" message in log. (#1884)
1 parent 2e5c3d1 commit c0c1362

File tree

4 files changed

+148
-13
lines changed

4 files changed

+148
-13
lines changed

‎src/Agent/NewRelic/Agent/Core/AgentHealth/AgentHealthEvent.cs

+7-1
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,12 @@ namespace NewRelic.Agent.Core.AgentHealth
66
public enum AgentHealthEvent
77
{
88
TransactionGarbageCollected,
9-
WrapperShutdown
9+
WrapperShutdown,
10+
Transaction,
11+
Log,
12+
Custom,
13+
Error,
14+
Span,
15+
InfiniteTracingSpan
1016
}
1117
}

‎src/Agent/NewRelic/Agent/Core/AgentHealth/AgentHealthReporter.cs

+36-11
Original file line numberDiff line numberDiff line change
@@ -22,7 +22,7 @@ namespace NewRelic.Agent.Core.AgentHealth
2222
{
2323
public class AgentHealthReporter : ConfigurationBasedService, IAgentHealthReporter
2424
{
25-
private static readonly TimeSpan _timeBetweenExecutions = TimeSpan.FromMinutes(1);
25+
private static readonly TimeSpan _timeBetweenExecutions = TimeSpan.FromMinutes(2);
2626

2727
private readonly IMetricBuilder _metricBuilder;
2828
private readonly IScheduler _scheduler;
@@ -42,7 +42,7 @@ public AgentHealthReporter(IMetricBuilder metricBuilder, IScheduler scheduler)
4242
{
4343
_metricBuilder = metricBuilder;
4444
_scheduler = scheduler;
45-
_scheduler.ExecuteEvery(LogRecurringLogs, _timeBetweenExecutions);
45+
_scheduler.ExecuteEvery(LogPeriodicReport, _timeBetweenExecutions);
4646
var agentHealthEvents = Enum.GetValues(typeof(AgentHealthEvent)) as AgentHealthEvent[];
4747
foreach (var agentHealthEvent in agentHealthEvents)
4848
{
@@ -58,25 +58,28 @@ public AgentHealthReporter(IMetricBuilder metricBuilder, IScheduler scheduler)
5858
public override void Dispose()
5959
{
6060
base.Dispose();
61-
_scheduler.StopExecuting(LogRecurringLogs);
61+
_scheduler.StopExecuting(LogPeriodicReport);
6262
}
6363

64-
private void LogRecurringLogs()
64+
private void LogPeriodicReport()
6565
{
6666
foreach (var data in _recurringLogDatas)
6767
{
6868
data?.LogAction(data.Message);
6969
}
70-
70+
71+
List<string> events = new List<string>();
7172
foreach (var counter in _agentHealthEventCounters)
7273
{
7374
if (counter.Value != null && counter.Value.Value > 0)
7475
{
7576
var agentHealthEvent = counter.Key;
7677
var timesOccured = counter.Value.Exchange(0);
77-
Log.Info($"Event {agentHealthEvent} has occurred {timesOccured} times in the last {_timeBetweenExecutions.TotalSeconds} seconds");
78+
events.Add(string.Format("{0} {1} {2}", timesOccured, agentHealthEvent, (timesOccured == 1) ? "event" : "events"));
7879
}
7980
}
81+
var message = events.Count > 0 ? string.Join(", ", events) : "No events";
82+
Log.Info($"In the last {_timeBetweenExecutions.TotalMinutes} minutes: {message}");
8083
}
8184

8285
public void ReportSupportabilityCountMetric(string metricName, long count = 1)
@@ -142,7 +145,11 @@ public void ReportTransactionEventCollected()
142145

143146
public void ReportTransactionEventsRecollected(int count) => TrySend(_metricBuilder.TryBuildTransactionEventsRecollectedMetric(count));
144147

145-
public void ReportTransactionEventsSent(int count) => TrySend(_metricBuilder.TryBuildTransactionEventsSentMetric(count));
148+
public void ReportTransactionEventsSent(int count)
149+
{
150+
TrySend(_metricBuilder.TryBuildTransactionEventsSentMetric(count));
151+
_agentHealthEventCounters[AgentHealthEvent.Transaction]?.Add(count);
152+
}
146153

147154
#endregion TransactionEvents
148155

@@ -165,7 +172,12 @@ public void ReportCustomEventCollected()
165172
public void ReportCustomEventsRecollected(int count) => TrySend(_metricBuilder.TryBuildCustomEventsRecollectedMetric(count));
166173

167174
// Note: Though not required by APM like the transaction event supportability metrics, this metric should still be created to maintain consistency
168-
public void ReportCustomEventsSent(int count) => TrySend(_metricBuilder.TryBuildCustomEventsSentMetric(count));
175+
public void ReportCustomEventsSent(int count)
176+
{
177+
TrySend(_metricBuilder.TryBuildCustomEventsSentMetric(count));
178+
_agentHealthEventCounters[AgentHealthEvent.Custom]?.Add(count);
179+
180+
}
169181

170182
#endregion CustomEvents
171183

@@ -183,7 +195,11 @@ public void ReportCustomEventCollected()
183195

184196
public void ReportErrorEventSeen() => TrySend(_metricBuilder.TryBuildErrorEventsSeenMetric());
185197

186-
public void ReportErrorEventsSent(int count) => TrySend(_metricBuilder.TryBuildErrorEventsSentMetric(count));
198+
public void ReportErrorEventsSent(int count)
199+
{
200+
TrySend(_metricBuilder.TryBuildErrorEventsSentMetric(count));
201+
_agentHealthEventCounters[AgentHealthEvent.Error]?.Add(count);
202+
}
187203

188204
#endregion ErrorEvents
189205

@@ -381,7 +397,11 @@ public void CollectTraceContextSuccessMetrics()
381397

382398
public void ReportSpanEventCollected(int count) => TrySend(_metricBuilder.TryBuildSpanEventsSeenMetric(count));
383399

384-
public void ReportSpanEventsSent(int count) => TrySend(_metricBuilder.TryBuildSpanEventsSentMetric(count));
400+
public void ReportSpanEventsSent(int count)
401+
{
402+
TrySend(_metricBuilder.TryBuildSpanEventsSentMetric(count));
403+
_agentHealthEventCounters[AgentHealthEvent.Span]?.Add(count);
404+
}
385405

386406
#endregion Span
387407

@@ -429,6 +449,7 @@ public void ReportInfiniteTracingSpanEventsSent(long countSpans)
429449
_infiniteTracingSpanBatchSizeMin = Math.Min(_infiniteTracingSpanBatchSizeMin, countSpans);
430450
_infiniteTracingSpanBatchSizeMax = Math.Max(_infiniteTracingSpanBatchSizeMax, countSpans);
431451
}
452+
_agentHealthEventCounters[AgentHealthEvent.InfiniteTracingSpan]?.Add((int)countSpans);
432453

433454
}
434455

@@ -616,7 +637,11 @@ public void IncrementLogDeniedCount(string level)
616637

617638
public void ReportLoggingEventCollected() => TrySend(_metricBuilder.TryBuildSupportabilityLoggingEventsCollectedMetric());
618639

619-
public void ReportLoggingEventsSent(int count) => TrySend(_metricBuilder.TryBuildSupportabilityLoggingEventsSentMetric(count));
640+
public void ReportLoggingEventsSent(int count)
641+
{
642+
TrySend(_metricBuilder.TryBuildSupportabilityLoggingEventsSentMetric(count));
643+
_agentHealthEventCounters[AgentHealthEvent.Log]?.Add(count);
644+
}
620645

621646
public void ReportLoggingEventsDropped(int droppedCount)=> TrySend(_metricBuilder.TryBuildSupportabilityLoggingEventsDroppedMetric(droppedCount));
622647

‎src/Agent/NewRelic/Agent/Core/Aggregators/MetricAggregator.cs

+1-1
Original file line numberDiff line numberDiff line change
@@ -62,7 +62,7 @@ public override void Collect(IAllMetricStatsCollection metric)
6262
}
6363
protected override void Harvest()
6464
{
65-
Log.Info("Metric harvest starting.");
65+
Log.Finest("Metric harvest starting.");
6666

6767
foreach (var source in _outOfBandMetricSources)
6868
{

‎tests/Agent/UnitTests/Core.UnitTest/AgentHealth/AgentHealthHeartbeatTests.cs

+104
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,104 @@
1+
// Copyright 2020 New Relic, Inc. All rights reserved.
2+
// SPDX-License-Identifier: Apache-2.0
3+
4+
using System;
5+
using NewRelic.Agent.Core.Metrics;
6+
using NewRelic.Agent.Core.Time;
7+
using NewRelic.Agent.Core.WireModels;
8+
using NewRelic.Testing.Assertions;
9+
using NUnit.Framework;
10+
using Telerik.JustMock;
11+
12+
namespace NewRelic.Agent.Core.AgentHealth
13+
{
14+
internal class FakeScheduler : IScheduler
15+
{
16+
protected Action _action;
17+
public void ExecuteOnce(Action action, TimeSpan timeUntilExecution)
18+
{
19+
_action = action;
20+
}
21+
22+
public void ExecuteEvery(Action action, TimeSpan timeBetweenExecutions, TimeSpan? optionalInitialDelay = null)
23+
{
24+
_action = action;
25+
}
26+
27+
public void StopExecuting(Action action, TimeSpan? timeToWaitForInProgressAction = null)
28+
{
29+
_action = null;
30+
}
31+
32+
public void ForceExecute()
33+
{
34+
_action?.Invoke();
35+
}
36+
}
37+
38+
[TestFixture]
39+
internal class AgentHealthHeartbeatTests
40+
{
41+
public static IMetricBuilder GetSimpleMetricBuilder()
42+
{
43+
var metricNameService = Mock.Create<IMetricNameService>();
44+
Mock.Arrange(() => metricNameService.RenameMetric(Arg.IsAny<string>())).Returns<string>(name => name);
45+
return new MetricWireModel.MetricBuilder(metricNameService);
46+
}
47+
48+
[Test]
49+
public void HeartbeatTest()
50+
{
51+
var scheduler = new FakeScheduler();
52+
var reporter = new AgentHealthReporter(GetSimpleMetricBuilder(), scheduler);
53+
using (var logger = new TestUtilities.Logging())
54+
{
55+
// Make sure all the event types get seen in the log
56+
reporter.ReportTransactionEventsSent(1);
57+
reporter.ReportCustomEventsSent(2);
58+
reporter.ReportErrorEventsSent(3);
59+
reporter.ReportSpanEventsSent(4);
60+
reporter.ReportInfiniteTracingSpanEventsSent(5);
61+
reporter.ReportLoggingEventsSent(6);
62+
63+
scheduler.ForceExecute();
64+
65+
NrAssert.Multiple(
66+
() => Assert.IsTrue(logger.HasMessageThatContains("1 Transaction")),
67+
() => Assert.IsTrue(logger.HasMessageThatContains("2 Custom")),
68+
() => Assert.IsTrue(logger.HasMessageThatContains("3 Error")),
69+
() => Assert.IsTrue(logger.HasMessageThatContains("4 Span")),
70+
() => Assert.IsTrue(logger.HasMessageThatContains("5 InfiniteTracingSpan")),
71+
() => Assert.IsTrue(logger.HasMessageThatContains("6 Log")),
72+
() => Assert.IsFalse(logger.HasMessageThatContains("No events"))
73+
);
74+
75+
// Make sure they all update their cumulative counts
76+
for (int twice = 0; twice < 2; twice++)
77+
{
78+
reporter.ReportTransactionEventsSent(1);
79+
reporter.ReportCustomEventsSent(2);
80+
reporter.ReportErrorEventsSent(3);
81+
reporter.ReportSpanEventsSent(4);
82+
reporter.ReportInfiniteTracingSpanEventsSent(5);
83+
reporter.ReportLoggingEventsSent(6);
84+
}
85+
86+
scheduler.ForceExecute();
87+
NrAssert.Multiple(
88+
() => Assert.IsTrue(logger.HasMessageThatContains("2 Transaction")),
89+
() => Assert.IsTrue(logger.HasMessageThatContains("4 Custom")),
90+
() => Assert.IsTrue(logger.HasMessageThatContains("6 Error")),
91+
() => Assert.IsTrue(logger.HasMessageThatContains("8 Span")),
92+
() => Assert.IsTrue(logger.HasMessageThatContains("10 InfiniteTracingSpan")),
93+
() => Assert.IsTrue(logger.HasMessageThatContains("12 Log")),
94+
() => Assert.IsFalse(logger.HasMessageThatContains("No events"))
95+
);
96+
97+
// Make sure they get cleared out between triggers
98+
scheduler.ForceExecute();
99+
100+
Assert.IsTrue(logger.HasMessageThatContains("No events"));
101+
}
102+
}
103+
}
104+
}

0 commit comments

Comments
 (0)