address multiple structured logging violations (#2249)

src/Elastic.Apm/Api/Service.cs

@@ -103,7 +103,7 @@ static bool CheckForLoadedAssembly(string name)
 			else if (CheckForLoadedAssembly("Elastic.Apm.StartupHook.Loader"))
 				activationMethod = Consts.ActivationMethodStartupHook;
 
-			logger.Info()?.Log($"Detected agent activation method: {activationMethod}");
+			logger.Info()?.Log("Detected agent activation method: {ActivationMethod}", activationMethod);
 			service.Agent.ActivationMethod = activationMethod;
 		}
 

src/Elastic.Apm/BackendComm/BackendCommUtils.cs

@@ -221,13 +221,13 @@ private static HttpClientHandler CreateHttpClientHandler(IConfiguration configur
 			logger.Info()?.Log("CreateHttpClientHandler - Setting ServerCertificateCustomValidationCallback");
 
 			httpClientHandler.SslProtocols |= SslProtocols.Tls12;
-			logger.Info()?.Log($"CreateHttpClientHandler - SslProtocols: {httpClientHandler.SslProtocols}");
+			logger.Info()?.Log("CreateHttpClientHandler - SslProtocols: {SslProtocols}", httpClientHandler.SslProtocols);
 #else
 			// We don't set the ServerCertificateCustomValidationCallback on ServicePointManager here as it would
 			// apply to the whole AppDomain and that may not be desired. A consumer can set this themselves if they
 			// need custom validation behaviour.
 			ServicePointManager.SecurityProtocol |= SecurityProtocolType.Tls12;
-			logger.Info()?.Log($"CreateHttpClientHandler - SslProtocols: {ServicePointManager.SecurityProtocol}");
+			logger.Info()?.Log("CreateHttpClientHandler - SslProtocols: {SslProtocols}", ServicePointManager.SecurityProtocol);
 #endif
 			return httpClientHandler;
 		}

src/Elastic.Apm/Config/ConfigurationKeyValue.cs

@@ -48,6 +48,10 @@ private string ValueForLogging
 		}
 
 
+
+		public void Log<T>(T state, Action<T, string, string, string, string> logCallback) =>
+			logCallback(state, $"{Type,13}", Option.ToNormalizedName(), ValueForLogging, ReadFrom);
+
 		public override string ToString() => $"{Type,13}->{Option.ToNormalizedName()}: '{ValueForLogging}' ({ReadFrom})";
 	}
 

src/Elastic.Apm/Config/ConfigurationLogger.cs

@@ -65,15 +65,15 @@ public static void PrintAgentLogPreamble(IApmLogger logger, IConfigurationReader
 				var info = logger.Info()!.Value;
 				var version = Assembly.GetExecutingAssembly().GetCustomAttribute<AssemblyInformationalVersionAttribute>().InformationalVersion;
 				info.Log("********************************************************************************");
-				info.Log($"Elastic APM .NET Agent, version: {version}");
-				info.Log($"Process ID: {Process.GetCurrentProcess().Id}");
-				info.Log($"Process Name: {Process.GetCurrentProcess().ProcessName}");
-				info.Log($"Command line arguments: '{string.Join(", ", System.Environment.GetCommandLineArgs())}'");
-				info.Log($"Operating System: {RuntimeInformation.OSDescription}");
-				info.Log($"CPU architecture: {RuntimeInformation.OSArchitecture}");
-				info.Log($"Host: {System.Environment.MachineName}");
-				info.Log($"Time zone: {TimeZoneInfo.Local}");
-				info.Log($"Runtime: {RuntimeInformation.FrameworkDescription}");
+				info.Log("Elastic APM .NET Agent, version: {ApmAgentVersion}", version);
+				info.Log("Process ID: {ProcessId}", Process.GetCurrentProcess().Id);
+				info.Log("Process Name: {ProcessName}", Process.GetCurrentProcess().ProcessName);
+				info.Log("Command line arguments: '{ProcessArguments}'", string.Join(", ", System.Environment.GetCommandLineArgs()));
+				info.Log("Operating System: {OSDescription}", RuntimeInformation.OSDescription);
+				info.Log("CPU architecture: {OSArchitecture}", RuntimeInformation.OSArchitecture);
+				info.Log("Host: {HostName}", System.Environment.MachineName);
+				info.Log("Time zone: {TimeZone}", TimeZoneInfo.Local);
+				info.Log("Runtime: {RunTime}", RuntimeInformation.FrameworkDescription);
 				PrintAgentConfiguration(logger, configurationReader);
 			}
 			catch (Exception e)
@@ -90,7 +90,8 @@ public static void PrintAgentConfiguration(IApmLogger logger, IConfigurationRead
 			{
 				var info = logger.Info()!.Value;
 				info.Log("********************************************************************************");
-				info.Log($"Agent Configuration (via '{configurationReader.Description ?? configurationReader.GetType().ToString()}'):");
+				info.Log("Agent Configuration (via '{ConfigurationProvider}'):"
+					, configurationReader.Description ?? configurationReader.GetType().ToString());
 
 				var activeConfiguration = OptionLoggingInstructions
 					.Select(instruction =>
@@ -107,7 +108,10 @@ public static void PrintAgentConfiguration(IApmLogger logger, IConfigurationRead
 					.ThenBy(t => string.IsNullOrEmpty(t.configuration.Value) ? 1 : 0);
 
 				foreach (var (_, configuration) in activeConfiguration)
-					info.Log($"{configuration}");
+				{
+					configuration.Log(info, static (l, type, name, value, origin) =>
+						l.Log("{Type}->{Name}: '{Value}' ({Origin})", type, name, value, origin));
+				}
 
 				info.Log("********************************************************************************");
 			}

src/Elastic.Apm/Features/AgentFeatures.cs

@@ -31,7 +31,8 @@ internal AgentFeatures(IApmLogger logger, string name, AgentFeature featureMask)
 		internal bool Check(AgentFeature agentFeature)
 		{
 			var enabled = (_enabledFeatures & agentFeature) == agentFeature;
-			_logger?.Trace()?.Log($"[Agent Feature] '{agentFeature}' enabled: {enabled.ToString(DateTimeFormatInfo.InvariantInfo)}");
+			_logger?.Trace()?.Log("[Agent Feature] '{AgentFeature}' enabled: {AgentFeatureEnabled}"
+				, agentFeature, enabled.ToString(DateTimeFormatInfo.InvariantInfo));
 			return enabled;
 		}
 

src/Elastic.Apm/Features/AgentFeaturesProvider.cs

@@ -24,7 +24,7 @@ internal static AgentFeatures Get(IApmLogger logger, IEnvironmentVariables envir
 					AgentFeatures = new AzureFunctionsAgentFeatures(logger);
 				else
 					AgentFeatures = new DefaultAgentFeatures(logger);
-				logger?.Trace()?.Log($"[Agent Features] Using '{AgentFeatures.Name}' feature set]");
+				logger?.Trace()?.Log("[Agent Features] Using '{AgentFeaturesName}' feature set]", AgentFeatures.Name);
 			}
 			return AgentFeatures;
 		}

src/Elastic.Apm/OpenTelemetry/ElasticActivityListener.cs

@@ -64,11 +64,12 @@ internal void Start(Tracer tracerInternal)
 		private Action<Activity> ActivityStarted =>
 			activity =>
 			{
-				_logger.Trace()?.Log($"ActivityStarted: name:{activity.DisplayName} id:{activity.Id} traceId:{activity.TraceId}");
-
 				if (KnownListeners.KnownListenersList.Contains(activity.DisplayName))
 					return;
 
+				_logger.Trace()?.Log("ActivityStarted: name:{DisplayName} id:{ActivityId} traceId:{TraceId}",
+					activity.DisplayName, activity.Id, activity.TraceId);
+
 				var spanLinks = new List<SpanLink>(activity.Links.Count());
 				if (activity.Links.Any())
 				{
@@ -146,7 +147,8 @@ private void CreateSpanForActivity(Activity activity, long timestamp, List<SpanL
 				}
 				activity.Stop();
 
-				_logger.Trace()?.Log($"ActivityStopped: name:{activity.DisplayName} id:{activity.Id} traceId:{activity.TraceId}");
+				_logger.Trace()?.Log("ActivityStopped: name:{DisplayName} id:{ActivityId} traceId:{TraceId}",
+					activity.DisplayName, activity.Id, activity.TraceId);
 
 				if (KnownListeners.KnownListenersList.Contains(activity.DisplayName))
 					return;

src/azure/Elastic.Apm.Azure.Functions/ApmMiddleware.cs

@@ -23,7 +23,7 @@ public class ApmMiddleware : IFunctionsWorkerMiddleware
 
 	public async Task Invoke(FunctionContext context, FunctionExecutionDelegate next)
 	{
-		Context.Logger.Trace()?.Log($"{nameof(Invoke)} - {context.FunctionDefinition.Name}");
+		Context.Logger.Trace()?.Log($"{nameof(Invoke)} - {{FunctionName}}", context.FunctionDefinition.Name);
 
 		var data = GetTriggerSpecificData(context);
 		await Agent.Tracer.CaptureTransaction(data.Name, ApiConstants.TypeRequest, async t =>

src/azure/Elastic.Apm.Azure.Functions/AzureFunctionsContext.cs

@@ -21,7 +21,7 @@ internal AzureFunctionsContext(string loggerScopeName)
 		UpdateServiceInformation(Agent.Instance.Service);
 		FaasIdPrefix =
 			$"/subscriptions/{MetaData.SubscriptionId}/resourceGroups/{MetaData.WebsiteResourceGroup}/providers/Microsoft.Web/sites/{MetaData.WebsiteSiteName}/functions/";
-		Logger.Trace()?.Log($"FaasIdPrefix: {FaasIdPrefix}");
+		Logger.Trace()?.Log("FaasIdPrefix: {FaasIdPrefix}", FaasIdPrefix);
 	}
 
 	internal IApmLogger Logger { get; }

src/azure/Elastic.Apm.Azure.Functions/AzureFunctionsDiagnosticListener.cs

@@ -27,7 +27,7 @@ public AzureFunctionsDiagnosticListener(ApmAgent agent) : base(agent) { }
 
 	protected override void HandleOnNext(KeyValuePair<string, object> kv)
 	{
-		Context.Logger.Trace()?.Log($"'{nameof(AzureFunctionsDiagnosticListener)}.{nameof(HandleOnNext)}': {kv.Key}");
+		Context.Logger.Trace()?.Log($"'{nameof(AzureFunctionsDiagnosticListener)}.{nameof(HandleOnNext)}': {{DiagnosticsEventName}}", kv.Key);
 		if (kv.Key == "Microsoft.AspNetCore.Hosting.HttpRequestIn.Start")
 			HandleRequestInStart(kv.Value as DefaultHttpContext);
 		else if (kv.Key == "Microsoft.AspNetCore.Hosting.HttpRequestIn.Stop")

src/integrations/Elastic.Apm.AspNetFullFramework/ElasticApmModule.cs

@@ -156,12 +156,16 @@ private void RestoreContextIfNeeded(HttpContextBase context)
 
 			if (Agent.Instance == null)
 			{
-				_logger.Trace()?.Log($"Agent.Instance is null during {nameof(OnExecuteRequestStep)}:{EventName()}. url: {urlPath}");
+				_logger.Trace()?
+					.Log("Agent.Instance is null during {RequestNotification}. url: {{UrlPath}}",
+						$"{nameof(OnExecuteRequestStep)}:{EventName()}", urlPath);
 				return;
 			}
 			if (Agent.Instance.Tracer == null)
 			{
-				_logger.Trace()?.Log($"Agent.Instance.Tracer is null during {nameof(OnExecuteRequestStep)}:{EventName()}. url: {urlPath}");
+				_logger.Trace()?
+					.Log("Agent.Instance.Tracer is null during {RequestNotification}. url: {{UrlPath}}",
+						$"{nameof(OnExecuteRequestStep)}:{EventName()}", urlPath);
 				return;
 			}
 			var transaction = Agent.Instance?.Tracer?.CurrentTransaction;
@@ -176,28 +180,33 @@ private void RestoreContextIfNeeded(HttpContextBase context)
 			var spanInApplicationInstance = context.Items[HttpContextCurrentExecutionSegmentsContainer.CurrentSpanKey] is not null;
 
 			_logger.Trace()?
-				.Log($"{nameof(ITracer.CurrentTransaction)} is null during {nameof(OnExecuteRequestStep)}:{EventName()}. url: {urlPath} "
-					+ $"(HttpContext.Current Span: {spanInCurrent}, Transaction: {transactionInCurrent})"
-					+ $"(ApplicationContext Span: {spanInApplicationInstance}, Transaction: {transactionInApplicationInstance})");
+				.Log($"{nameof(ITracer.CurrentTransaction)} is null during {{RequestNotification}}. url: {{UrlPath}}"
+					+ "(HttpContext.Current Span: {HttpContextCurrentHasSpan}, Transaction: {HttpContextCurrenHasTransaction})"
+					+ "(ApplicationContext Span: {ApplicationContextHasSpan}, Transaction: {ApplicationContextHasTransaction})",
+						$"{nameof(OnExecuteRequestStep)}:{EventName()}", urlPath, spanInCurrent, transactionInCurrent, spanInApplicationInstance, transactionInApplicationInstance
+				);
 
 			if (HttpContext.Current == null)
 			{
 				_logger.Trace()?
-					.Log($"HttpContext.Current is null during {nameof(OnExecuteRequestStep)}:{EventName()}. Unable to attempt to restore transaction. url: {urlPath}");
+					.Log("HttpContext.Current is null during {RequestNotification}. Unable to attempt to restore transaction. url: {UrlPath}",
+						$"{nameof(OnExecuteRequestStep)}:{EventName()}", urlPath);
 				return;
 			}
 
 			if (!transactionInCurrent && transactionInApplicationInstance)
 			{
 				HttpContext.Current.Items[HttpContextCurrentExecutionSegmentsContainer.CurrentTransactionKey] =
 					context.Items[HttpContextCurrentExecutionSegmentsContainer.CurrentTransactionKey];
-				_logger.Trace()?.Log($"Restored transaction to HttpContext.Current.Items {nameof(OnExecuteRequestStep)}:{EventName()}. url: {urlPath}");
+				_logger.Trace()?.Log("Restored transaction to HttpContext.Current.Items {RequestNotification}. url: {UrlPath}",
+						$"{nameof(OnExecuteRequestStep)}:{EventName()}", urlPath);
 			}
 			if (!spanInCurrent && spanInApplicationInstance)
 			{
 				HttpContext.Current.Items[HttpContextCurrentExecutionSegmentsContainer.CurrentSpanKey] =
 					context.Items[HttpContextCurrentExecutionSegmentsContainer.CurrentSpanKey];
-				_logger.Trace()?.Log($"Restored span to HttpContext.Current.Items {nameof(OnExecuteRequestStep)}:{EventName()}. url: {urlPath}");
+				_logger.Trace()?.Log("Restored span to HttpContext.Current.Items {RequestNotification}:{EventName()}. url: {UrlPath}",
+						$"{nameof(OnExecuteRequestStep)}:{EventName()}", urlPath);
 			}
 
 		}