Skip to content

Commit

Permalink
feat: Use structured logging for internal logs (#1903)
Browse files Browse the repository at this point in the history 
* First pass at internal structured logging

* Second pass

* PR feedback

* Strange compile error

* Trying to fix GHA error

* Revert back to original log level
  • Loading branch information
@chynesNR
chynesNR committed Sep 14, 2023
1 parent 213ff9e commit 0031700
Show file tree
Hide file tree
Showing 80 changed files with 334 additions and 553 deletions.
6 changes: 3 additions & 3 deletions src/Agent/NewRelic/Agent/Core/Agent.cs
View file
Expand Up @@ -213,7 +213,7 @@ bool ShouldRunExplain()
var vendorValidationResult = vendorValidateShouldExplain();
if (!vendorValidationResult.IsValid)
{
Log.DebugFormat("Failed vendor condition for executing explain plan: {0}", vendorValidationResult.ValidationMessage);
Log.Debug("Failed vendor condition for executing explain plan: {0}", vendorValidationResult.ValidationMessage);
return false;
}
}
Expand Down Expand Up @@ -281,7 +281,7 @@ public void HandleWrapperException(Exception exception)
return;
}

Log.Error($"An exception occurred in a wrapper: {exception}");
Log.Error(exception, "An exception occurred in a wrapper");
}

#endregion Error handling
Expand Down Expand Up @@ -336,7 +336,7 @@ public Stream TryGetStreamInjector(Stream stream, Encoding encoding, string cont
}
catch (Exception ex)
{
Log.Error($"RUM: Failed to build Browser Monitoring agent script: {ex}");
Log.Error(ex, "RUM: Failed to build Browser Monitoring agent script");
{
return null;
}
Expand Down
24 changes: 6 additions & 18 deletions src/Agent/NewRelic/Agent/Core/AgentHealth/AgentHealthReporter.cs
View file
Expand Up @@ -26,7 +26,7 @@ public class AgentHealthReporter : ConfigurationBasedService, IAgentHealthReport

private readonly IMetricBuilder _metricBuilder;
private readonly IScheduler _scheduler;
private readonly IList<RecurringLogData> _recurringLogDatas = new ConcurrentList<RecurringLogData>();
private readonly IList<string> _recurringLogData = new ConcurrentList<string>();
private readonly IDictionary<AgentHealthEvent, InterlockedCounter> _agentHealthEventCounters = new Dictionary<AgentHealthEvent, InterlockedCounter>();
private readonly ConcurrentDictionary<string, InterlockedCounter> _logLinesCountByLevel = new ConcurrentDictionary<string, InterlockedCounter>();
private readonly ConcurrentDictionary<string, InterlockedCounter> _logDeniedCountByLevel = new ConcurrentDictionary<string, InterlockedCounter>();
Expand Down Expand Up @@ -63,9 +63,9 @@ public override void Dispose()

private void LogPeriodicReport()
{
foreach (var data in _recurringLogDatas)
foreach (var logMessage in _recurringLogData)
{
data?.LogAction(data.Message);
Log.Debug(logMessage);
}

List<string> events = new List<string>();
Expand Down Expand Up @@ -252,7 +252,7 @@ public void ReportWrapperShutdown(IWrapper wrapper, Method method)
}

Log.Error($"Wrapper {wrapperName} is being disabled for {method.MethodName} due to too many consecutive exceptions. All other methods using this wrapper will continue to be instrumented. This will reduce the functionality of the agent until the agent is restarted.");
_recurringLogDatas.Add(new RecurringLogData(Log.Debug, $"Wrapper {wrapperName} was disabled for {method.MethodName} at {DateTime.Now} due to too many consecutive exceptions. All other methods using this wrapper will continue to be instrumented. This will reduce the functionality of the agent until the agent is restarted."));
_recurringLogData.Add($"Wrapper {wrapperName} was disabled for {method.MethodName} at {DateTime.Now} due to too many consecutive exceptions. All other methods using this wrapper will continue to be instrumented. This will reduce the functionality of the agent until the agent is restarted.");
}

public void ReportIfHostIsLinuxOs()
Expand Down Expand Up @@ -714,7 +714,7 @@ private void TrySend(MetricWireModel metric)

if (_publishMetricDelegate == null)
{
Log.WarnFormat("No PublishMetricDelegate to flush metric '{0}' through.", metric.MetricName.Name);
Log.Warn("No PublishMetricDelegate to flush metric '{0}' through.", metric.MetricName.Name);
return;
}

Expand All @@ -724,7 +724,7 @@ private void TrySend(MetricWireModel metric)
}
catch (Exception ex)
{
Log.Error(ex);
Log.Error(ex, "TrySend() failed");
}
}
private bool TryGetCount(InterlockedCounter counter, out int metricCount)
Expand Down Expand Up @@ -811,17 +811,5 @@ protected override void OnConfigurationUpdated(ConfigurationUpdateSource configu
// Some one time metrics are reporting configured values, so we want to re-report them if the configuration changed
_oneTimeMetricsCollected = false;
}

private class RecurringLogData
{
public readonly Action<string> LogAction;
public readonly string Message;

public RecurringLogData(Action<string> logAction, string message)
{
LogAction = logAction;
Message = message;
}
}
}
}
2 changes: 1 addition & 1 deletion src/Agent/NewRelic/Agent/Core/AgentInstallConfiguration.cs
View file
Expand Up @@ -111,7 +111,7 @@ private static string GetAgentVersion()
}
catch (Exception ex)
{
Log.Error($"Failed to determine agent version. {ex}");
Log.Error(ex, "Failed to determine agent version.");
return "?.?.?.?";
}
}
Expand Down
18 changes: 9 additions & 9 deletions src/Agent/NewRelic/Agent/Core/AgentManager.cs
View file
Expand Up @@ -55,7 +55,7 @@ protected override IAgentManager CreateInstance()
{
try
{
Log.Error($"There was an error initializing the agent: {exception}");
Log.Error(exception, "There was an error initializing the agent");
return DisabledAgentManager;
}
catch
Expand Down Expand Up @@ -182,7 +182,7 @@ private void Initialize()

private void LogInitialized()
{
Log.InfoFormat("The New Relic .NET Agent v{0} started (pid {1}) on app domain '{2}'", AgentInstallConfiguration.AgentVersion, AgentInstallConfiguration.ProcessId, AgentInstallConfiguration.AppDomainAppVirtualPath ?? AgentInstallConfiguration.AppDomainName);
Log.Info("The New Relic .NET Agent v{0} started (pid {1}) on app domain '{2}'", AgentInstallConfiguration.AgentVersion, AgentInstallConfiguration.ProcessId, AgentInstallConfiguration.AppDomainAppVirtualPath ?? AgentInstallConfiguration.AppDomainName);
//Log here for debugging configuration issues
if (Log.IsDebugEnabled)
{
Expand Down Expand Up @@ -270,15 +270,15 @@ private void LogInitialized()
{
if (!string.IsNullOrEmpty(System.Environment.GetEnvironmentVariable(ev)))
{
Log.DebugFormat("Environment Variable {0} value: {1}", ev, System.Environment.GetEnvironmentVariable(ev));
Log.Debug("Environment Variable {0} value: {1}", ev, System.Environment.GetEnvironmentVariable(ev));
}
}

foreach (var evs in environmentVariablesSensitive)
{
if (!string.IsNullOrEmpty(System.Environment.GetEnvironmentVariable(evs)))
{
Log.DebugFormat("Environment Variable {0} is configured with a value. Not logging potentially sensitive value", evs);
Log.Debug("Environment Variable {0} is configured with a value. Not logging potentially sensitive value", evs);
}
}

Expand All @@ -288,12 +288,12 @@ private void LogInitialized()
#if NETFRAMEWORK
if (NewRelic.Core.DotnetVersion.IsUnsupportedDotnetFrameworkVersion(AgentInstallConfiguration.DotnetFrameworkVersion))
{
Log.WarnFormat("Unsupported installed .NET Framework version {0} dectected. Please use a version of .NET Framework >= 4.6.2.", AgentInstallConfiguration.DotnetFrameworkVersion);
Log.Warn("Unsupported installed .NET Framework version {0} dectected. Please use a version of .NET Framework >= 4.6.2.", AgentInstallConfiguration.DotnetFrameworkVersion);
}
#else
if (NewRelic.Core.DotnetVersion.IsUnsupportedDotnetCoreVersion(AgentInstallConfiguration.DotnetCoreVersion))
{
Log.WarnFormat("Unsupported .NET version {0} detected. Please use a version of .NET >= net6.", AgentInstallConfiguration.DotnetCoreVersion);
Log.Warn("Unsupported .NET version {0} detected. Please use a version of .NET >= net6.", AgentInstallConfiguration.DotnetCoreVersion);
}
#endif
}
Expand Down Expand Up @@ -340,7 +340,7 @@ public ITracer GetTracerImpl(string tracerFactoryName, uint tracerArguments, str
}
catch (Exception e)
{
Log.Error($"Tracer invocation error: {e}");
Log.Error(e, "Tracer invocation error");
return null;
}
}
Expand Down Expand Up @@ -375,11 +375,11 @@ private void Shutdown(bool cleanShutdown)

Log.Debug("Shutting down public agent services...");
StopServices();
Log.InfoFormat("The New Relic .NET Agent v{0} has shutdown (pid {1}) on app domain '{2}'", AgentInstallConfiguration.AgentVersion, AgentInstallConfiguration.ProcessId, AgentInstallConfiguration.AppDomainAppVirtualPath ?? AgentInstallConfiguration.AppDomainName);
Log.Info("The New Relic .NET Agent v{0} has shutdown (pid {1}) on app domain '{2}'", AgentInstallConfiguration.AgentVersion, AgentInstallConfiguration.ProcessId, AgentInstallConfiguration.AppDomainAppVirtualPath ?? AgentInstallConfiguration.AppDomainName);
}
catch (Exception e)
{
Log.Debug($"Shutdown error: {e}");
Log.Debug(e, "Shutdown error");
}
finally
{
Expand Down
2 changes: 1 addition & 1 deletion src/Agent/NewRelic/Agent/Core/Aggregators/MetricStatsCollectionQueue.cs
View file
Expand Up @@ -66,7 +66,7 @@ private void AddMetricsToCollection(ConcurrentQueue<MetricStatsCollection> stats
}
catch (Exception e)
{
Log.Warn($"Exception dequeueing/creating stats collection: {e}");
Log.Warn(e, "Exception dequeueing/creating stats collection");
}
finally
{
Expand Down
2 changes: 1 addition & 1 deletion src/Agent/NewRelic/Agent/Core/Aggregators/TransactionTraceAggregator.cs
View file
Expand Up @@ -106,7 +106,7 @@ private void LogUnencodedTraceData(IEnumerable<TransactionTraceWireModel> sample
{
if (sample != null)
{
Log.DebugFormat("TransactionTraceData: {0}", SerializeTransactionTraceData(sample));
Log.Debug("TransactionTraceData: {0}", SerializeTransactionTraceData(sample));
}
}
}
Expand Down
6 changes: 3 additions & 3 deletions src/Agent/NewRelic/Agent/Core/Api/AgentApiImplementation.cs
View file
Expand Up @@ -79,7 +79,7 @@ public void InitializePublicAgent(object publicAgent)
{
try
{
Log.Error($"Failed to initialize the Agent API: {ex}");
Log.Error(ex, "Failed to initialize the Agent API");
}
catch (Exception)//Swallow the error
{
Expand Down Expand Up @@ -728,7 +728,7 @@ private static string GetCustomMetricSuffix(string name)
{
if (_configurationService.Configuration.DistributedTracingEnabled)
{
Log.FinestFormat(DistributedTracingIsEnabledIgnoringCall, nameof(GetRequestMetadata));
Log.Finest(DistributedTracingIsEnabledIgnoringCall, nameof(GetRequestMetadata));
return Enumerable.Empty<KeyValuePair<string, string>>();
}

Expand All @@ -742,7 +742,7 @@ private static string GetCustomMetricSuffix(string name)
{
if (_configurationService.Configuration.DistributedTracingEnabled)
{
Log.FinestFormat(DistributedTracingIsEnabledIgnoringCall, nameof(GetResponseMetadata));
Log.Finest(DistributedTracingIsEnabledIgnoringCall, nameof(GetResponseMetadata));
return Enumerable.Empty<KeyValuePair<string, string>>();
}

Expand Down
6 changes: 3 additions & 3 deletions src/Agent/NewRelic/Agent/Core/Api/AgentBridgeApi.cs
View file
Expand Up @@ -40,7 +40,7 @@ public TransactionBridgeApi CurrentTransaction
{
try
{
Log.ErrorFormat("Failed to get CurrentTransaction: {0}", ex);
Log.Error(ex, "Failed to get CurrentTransaction");
}
catch (Exception)
{
Expand All @@ -67,7 +67,7 @@ public object TraceMetadata
{
try
{
Log.ErrorFormat("Failed to get TraceMetadata: {0}", ex);
Log.Error(ex, "Failed to get TraceMetadata");
}
catch (Exception)
{
Expand All @@ -93,7 +93,7 @@ public object TraceMetadata
{
try
{
Log.ErrorFormat("Error in GetLinkingMetadata: {0}", ex);
Log.Error(ex, "Error in GetLinkingMetadata");
}
catch (Exception)
{
Expand Down
2 changes: 1 addition & 1 deletion src/Agent/NewRelic/Agent/Core/Api/DistributedTraceApiModel.cs
View file
Expand Up @@ -35,7 +35,7 @@ string DecodePayload()
{
try
{
Log.ErrorFormat("Failed to get DistributedTraceApiModel.Text: {0}", ex);
Log.Error(ex, "Failed to get DistributedTraceApiModel.Text");
}
catch (Exception)
{
Expand Down
4 changes: 2 additions & 2 deletions src/Agent/NewRelic/Agent/Core/Api/SpanBridgeApi.cs
View file
Expand Up @@ -39,7 +39,7 @@ public object AddCustomAttribute(string key, object value)
{
try
{
Log.Error($"Error in AddCustomAttribute: {ex}");
Log.Error(ex, "Error in AddCustomAttribute");
}
catch (Exception)
{
Expand All @@ -62,7 +62,7 @@ public object SetName(string name)
{
try
{
Log.Error($"Error in SetName: {ex}");
Log.Error(ex, "Error in SetName");
}
catch (Exception)
{
Expand Down
10 changes: 5 additions & 5 deletions src/Agent/NewRelic/Agent/Core/Api/TransactionBridgeApi.cs
View file
Expand Up @@ -79,7 +79,7 @@ public void InsertDistributedTraceHeaders<T>(T carrier, Action<T, string, string
{
try
{
Log.ErrorFormat("Error in InsertDistributedTraceHeaders<T>(T, Action<T, string, string>): {0}", ex);
Log.Error(ex, "Error in InsertDistributedTraceHeaders<T>(T, Action<T, string, string>)");
}
catch (Exception)
{
Expand All @@ -102,7 +102,7 @@ public void AcceptDistributedTraceHeaders<T>(T carrier, Func<T, string, IEnumera
{
try
{
Log.ErrorFormat("Error in AcceptDistributedTraceHeaders<T>(T, Func<T, string, IEnumerable<string>>, TransportType): {0}", ex);
Log.Error(ex, "Error in AcceptDistributedTraceHeaders<T>(T, Func<T, string, IEnumerable<string>>, TransportType)");
}
catch (Exception)
{
Expand Down Expand Up @@ -138,7 +138,7 @@ public object AddCustomAttribute(string key, object value)
{
try
{
Log.Error($"Error in AddCustomAttribute: {ex}");
Log.Error(ex, "Error in AddCustomAttribute");
}
catch (Exception)
{
Expand Down Expand Up @@ -167,7 +167,7 @@ public SpanBridgeApi CurrentSpan
{
try
{
Log.ErrorFormat("Failed to get CurrentSpan: {0}", ex);
Log.Error(ex, "Failed to get CurrentSpan");
}
catch (Exception)
{
Expand Down Expand Up @@ -195,7 +195,7 @@ public void SetUserId(string userid)
{
try
{
Log.Error($"Error in SetUserId: {ex}");
Log.Error(ex, "Error in SetUserId");
}
catch (Exception)
{
Expand Down
2 changes: 1 addition & 1 deletion src/Agent/NewRelic/Agent/Core/Attributes/AttributeValueCollection.cs
View file
Expand Up @@ -286,7 +286,7 @@ public void MakeImmutable()
}
catch (Exception ex)
{
Log.Finest($"{attribVal.AttributeDefinition.Classification} Attribute '{attribVal.AttributeDefinition.Name}' was not recorded - exception occurred while resolving value (lazy) - {ex}");
Log.Finest(ex, "{attribVal.AttributeDefinition.Classification} Attribute '{attribVal.AttributeDefinition.Name}' was not recorded - exception occurred while resolving value (lazy)");
itemsToRemove.Add(attribVal);
}
}
Expand Down
4 changes: 2 additions & 2 deletions src/Agent/NewRelic/Agent/Core/BrowserMonitoring/BrowserMonitoringPrereqChecker.cs
View file
Expand Up @@ -82,7 +82,7 @@ private static bool IsHtmlContent(string contentType)
}
catch (Exception ex)
{
Log.Debug($"Unable to parse content type: {ex}");
Log.Debug(ex, "Unable to parse content type");
return false;
}
}
Expand Down Expand Up @@ -134,7 +134,7 @@ private static bool IsMatch(string path, Regex regex)
}
catch (Exception e)
{
Log.Error($"Exception attempting to validate request path for Browser Instrumentation blacklisting: {e}");
Log.Error(e, "Exception attempting to validate request path for Browser Instrumentation blacklisting");
return false;
}
}
Expand Down
2 changes: 1 addition & 1 deletion src/Agent/NewRelic/Agent/Core/BrowserMonitoring/BrowserMonitoringStreamInjector.cs
View file
Expand Up @@ -105,7 +105,7 @@ private void PassThroughStreamWriter(byte[] buffer, int offset, int count)
}
catch (Exception exception)
{
Log.Error($"Failed to inject JavaScript agent into response stream: {exception}");
Log.Error(exception, "Failed to inject JavaScript agent into response stream");
scriptInjected = false;
buffer = originalBuffer;
offset = originalOffset;
Expand Down
4 changes: 2 additions & 2 deletions src/Agent/NewRelic/Agent/Core/CallStack/CallStackManager.cs
View file
Expand Up @@ -61,14 +61,14 @@ private static ICallStackManagerFactory CreateFactory(IEnumerable<IContextStorag
var asyncLocalFactory = listOfFactories.FirstOrDefault(f => f.Type == ContextStorageType.AsyncLocal);
if (asyncLocalFactory != null)
{
Log.DebugFormat("Using async storage {0} for call stack with AsyncCallStackManagerFactory", asyncLocalFactory.GetType().FullName);
Log.Debug("Using async storage {0} for call stack with AsyncCallStackManagerFactory", asyncLocalFactory.GetType().FullName);
return new AsyncCallStackManagerFactory(asyncLocalFactory);
}

var callContextLogicalDataFactory = listOfFactories.FirstOrDefault(f => f.Type == ContextStorageType.CallContextLogicalData);
if (callContextLogicalDataFactory != null)
{
Log.DebugFormat("Using async storage {0} for call stack with AsyncCallStackManagerFactory", callContextLogicalDataFactory.GetType().FullName);
Log.Debug("Using async storage {0} for call stack with AsyncCallStackManagerFactory", callContextLogicalDataFactory.GetType().FullName);
return new AsyncCallStackManagerFactory(callContextLogicalDataFactory);
}

Expand Down
2 changes: 1 addition & 1 deletion src/Agent/NewRelic/Agent/Core/Commands/InstrumentationUpdateCommand.cs
View file
Expand Up @@ -52,7 +52,7 @@ private string InstrumentationUpdate(IDictionary<string, object> arguments)
}
catch (Exception e)
{
Log.Error(e);
Log.Error(e, "The instrumentation update was malformed");
return "The instrumentation update was malformed";
}
}
Expand Down
2 changes: 1 addition & 1 deletion src/Agent/NewRelic/Agent/Core/Commands/StopThreadProfilerCommand.cs
View file
Expand Up @@ -48,7 +48,7 @@ private string StopThreadProfilingSessions(IDictionary<string, object> arguments
}
catch (InvalidProfileIdException e)
{
Log.Error(e.Message);
Log.Error(e, "StopThreadProfilingSessions() failed");
return e.Message;
}

Expand Down

0 comments on commit 0031700

Please sign in to comment.