diff --git a/Test/DurableTask.Core.Tests/TraceHelperTests.cs b/Test/DurableTask.Core.Tests/TraceHelperTests.cs index 8d52754fa..615d15187 100644 --- a/Test/DurableTask.Core.Tests/TraceHelperTests.cs +++ b/Test/DurableTask.Core.Tests/TraceHelperTests.cs @@ -14,8 +14,10 @@ #nullable enable namespace DurableTask.Core.Tests { + using System; using System.Collections.Generic; using System.Diagnostics; + using System.Diagnostics.Tracing; using DurableTask.Core.Entities.OperationFormat; using DurableTask.Core.Tracing; using Microsoft.VisualStudio.TestTools.UnitTesting; @@ -23,6 +25,7 @@ namespace DurableTask.Core.Tests using TraceActivityStatusCode = DurableTask.Core.Tracing.ActivityStatusCode; [TestClass] + [DoNotParallelize] public class TraceHelperTests { [TestMethod] @@ -64,6 +67,270 @@ public void EndActivitiesForEntityInvocationMarksFailures() Assert.AreEqual(DiagnosticsActivityStatusCode.Error, activities[0].Status); } + + [TestMethod] + public void TraceFactoriesRunOnlyWhenRequestedLevelIsEnabled() + { + using var listener = new CapturingEventListener(); + listener.Enable(EventLevel.Warning); + + var instance = new OrchestrationInstance + { + InstanceId = "instance", + ExecutionId = "execution", + }; + int traceFactoryCalls = 0; + int sessionFactoryCalls = 0; + int instanceFactoryCalls = 0; + + TraceHelper.Trace( + TraceEventType.Information, + "TraceFactory", + () => + { + traceFactoryCalls++; + return "trace payload"; + }); + TraceHelper.TraceSession( + TraceEventType.Information, + "SessionFactory", + "session", + () => + { + sessionFactoryCalls++; + return "session payload"; + }); + TraceHelper.TraceInstance( + TraceEventType.Information, + "InstanceFactory", + instance, + () => + { + instanceFactoryCalls++; + return "instance payload"; + }); + + Assert.AreEqual(0, traceFactoryCalls); + Assert.AreEqual(0, sessionFactoryCalls); + Assert.AreEqual(0, instanceFactoryCalls); + Assert.AreEqual(0, listener.Events.Count); + + listener.Enable(EventLevel.Informational); + + TraceHelper.Trace( + TraceEventType.Information, + "TraceFactory", + () => + { + traceFactoryCalls++; + return "trace payload"; + }); + TraceHelper.TraceSession( + TraceEventType.Information, + "SessionFactory", + "session", + () => + { + sessionFactoryCalls++; + return "session payload"; + }); + TraceHelper.TraceInstance( + TraceEventType.Information, + "InstanceFactory", + instance, + () => + { + instanceFactoryCalls++; + return "instance payload"; + }); + + Assert.AreEqual(1, traceFactoryCalls); + Assert.AreEqual(1, sessionFactoryCalls); + Assert.AreEqual(1, instanceFactoryCalls); + Assert.AreEqual(3, listener.Events.Count); + AssertEvent(listener.Events[0], "trace payload", "TraceFactory"); + AssertEvent(listener.Events[1], "session payload", "SessionFactory"); + AssertEvent(listener.Events[2], "instance payload", "InstanceFactory"); + } + + [TestMethod] + public void TraceFormattingRunsOnlyWhenRequestedLevelIsEnabled() + { + using var listener = new CapturingEventListener(); + listener.Enable(EventLevel.Warning); + + var instance = new OrchestrationInstance + { + InstanceId = "instance", + ExecutionId = "execution", + }; + var traceValue = new CountingValue("trace payload"); + var sessionValue = new CountingValue("session payload"); + var instanceValue = new CountingValue("instance payload"); + + TraceHelper.Trace(TraceEventType.Information, "TraceFormat", "{0}", traceValue); + TraceHelper.TraceSession(TraceEventType.Information, "SessionFormat", "session", "{0}", sessionValue); + TraceHelper.TraceInstance(TraceEventType.Information, "InstanceFormat", instance, "{0}", instanceValue); + + Assert.AreEqual(0, traceValue.ToStringCalls); + Assert.AreEqual(0, sessionValue.ToStringCalls); + Assert.AreEqual(0, instanceValue.ToStringCalls); + Assert.AreEqual(0, listener.Events.Count); + + listener.Enable(EventLevel.Informational); + + TraceHelper.Trace(TraceEventType.Information, "TraceFormat", "{0}", traceValue); + TraceHelper.TraceSession(TraceEventType.Information, "SessionFormat", "session", "{0}", sessionValue); + TraceHelper.TraceInstance(TraceEventType.Information, "InstanceFormat", instance, "{0}", instanceValue); + + Assert.AreEqual(1, traceValue.ToStringCalls); + Assert.AreEqual(1, sessionValue.ToStringCalls); + Assert.AreEqual(1, instanceValue.ToStringCalls); + Assert.AreEqual(3, listener.Events.Count); + AssertEvent(listener.Events[0], "trace payload", "TraceFormat"); + AssertEvent(listener.Events[1], "session payload", "SessionFormat"); + AssertEvent(listener.Events[2], "instance payload", "InstanceFormat"); + } + + [TestMethod] + public void TraceExceptionPayloadsRunOnlyWhenRequestedLevelIsEnabled() + { + using var listener = new CapturingEventListener(); + listener.Enable(EventLevel.Warning); + + var exception = new InvalidOperationException("failure"); + int factoryCalls = 0; + var formatValue = new CountingValue("format payload"); + + Exception factoryResult = TraceHelper.TraceException( + TraceEventType.Information, + "ExceptionFactory", + exception, + () => + { + factoryCalls++; + return "factory payload"; + }); + Exception formatResult = TraceHelper.TraceException( + TraceEventType.Information, + "ExceptionFormat", + exception, + "{0}", + formatValue); + + Assert.AreSame(exception, factoryResult); + Assert.AreSame(exception, formatResult); + Assert.AreEqual(0, factoryCalls); + Assert.AreEqual(0, formatValue.ToStringCalls); + Assert.AreEqual(0, listener.Events.Count); + + listener.Enable(EventLevel.Informational); + + factoryResult = TraceHelper.TraceException( + TraceEventType.Information, + "ExceptionFactory", + exception, + () => + { + factoryCalls++; + return "factory payload"; + }); + formatResult = TraceHelper.TraceException( + TraceEventType.Information, + "ExceptionFormat", + exception, + "{0}", + formatValue); + + Assert.AreSame(exception, factoryResult); + Assert.AreSame(exception, formatResult); + Assert.AreEqual(1, factoryCalls); + Assert.AreEqual(1, formatValue.ToStringCalls); + Assert.AreEqual(2, listener.Events.Count); + AssertEvent(listener.Events[0], FormatExceptionMessage("factory payload", exception), "ExceptionFactory"); + AssertEvent(listener.Events[1], FormatExceptionMessage("format payload", exception), "ExceptionFormat"); + } + + static void AssertEvent(CapturedEvent capturedEvent, string message, string eventType) + { + Assert.AreEqual(3, capturedEvent.EventId); + Assert.AreEqual(7, capturedEvent.PayloadCount); + Assert.AreEqual(message, capturedEvent.Message); + Assert.AreEqual(eventType, capturedEvent.EventType); + } + + static string FormatExceptionMessage(string message, Exception exception) + { + return message + "\nException: " + exception.GetType() + " : " + exception.Message + "\n\t" + + exception.StackTrace + "\nInner Exception: " + exception.InnerException?.ToString(); + } + + sealed class CountingValue + { + readonly string value; + + public CountingValue(string value) + { + this.value = value; + } + + public int ToStringCalls { get; private set; } + + public override string ToString() + { + this.ToStringCalls++; + return this.value; + } + } + + sealed class CapturedEvent + { + public CapturedEvent(int eventId, int payloadCount, string message, string eventType) + { + this.EventId = eventId; + this.PayloadCount = payloadCount; + this.Message = message; + this.EventType = eventType; + } + + public int EventId { get; } + + public int PayloadCount { get; } + + public string Message { get; } + + public string EventType { get; } + } + + sealed class CapturingEventListener : EventListener + { + readonly List events = new List(); + + public IReadOnlyList Events => this.events; + + public void Enable(EventLevel eventLevel) + { + this.EnableEvents(DefaultEventSource.Log, eventLevel, DefaultEventSource.Keywords.Diagnostics); + } + + public override void Dispose() + { + this.DisableEvents(DefaultEventSource.Log); + base.Dispose(); + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + if (eventData.EventSource == DefaultEventSource.Log && + eventData.Payload != null && + eventData.Payload.Count == 7 && + eventData.Payload[4] is string message && + eventData.Payload[6] is string eventType) + { + this.events.Add(new CapturedEvent(eventData.EventId, eventData.Payload.Count, message, eventType)); + } + } + } } } #endif diff --git a/src/DurableTask.Core/TaskOrchestrationDispatcher.cs b/src/DurableTask.Core/TaskOrchestrationDispatcher.cs index 751a64b78..649e7b47a 100644 --- a/src/DurableTask.Core/TaskOrchestrationDispatcher.cs +++ b/src/DurableTask.Core/TaskOrchestrationDispatcher.cs @@ -26,6 +26,7 @@ namespace DurableTask.Core using System; using System.Collections.Generic; using System.Diagnostics; + using System.Globalization; using System.Linq; using System.Threading; using System.Threading.Tasks; @@ -438,8 +439,10 @@ protected async Task OnProcessWorkItemAsync(TaskOrchestrationWorkItem work TraceEventType.Verbose, "TaskOrchestrationDispatcher-ExecuteUserOrchestration-Begin", runtimeState.OrchestrationInstance!, - "Executing user orchestration: {0}", - JsonDataConverter.Default.Serialize(runtimeState.GetOrchestrationRuntimeStateDump(), true)); + () => string.Format( + CultureInfo.InvariantCulture, + "Executing user orchestration: {0}", + JsonDataConverter.Default.Serialize(runtimeState.GetOrchestrationRuntimeStateDump(), true))); if (!versioningFailed) { @@ -472,9 +475,11 @@ protected async Task OnProcessWorkItemAsync(TaskOrchestrationWorkItem work TraceEventType.Information, "TaskOrchestrationDispatcher-ExecuteUserOrchestration-End", runtimeState.OrchestrationInstance!, - "Executed user orchestration. Received {0} orchestrator actions: {1}", - decisions.Count, - string.Join(", ", decisions.Select(d => d.Id + ":" + d.OrchestratorActionType))); + () => string.Format( + CultureInfo.InvariantCulture, + "Executed user orchestration. Received {0} orchestrator actions: {1}", + decisions.Count, + string.Join(", ", decisions.Select(d => d.Id + ":" + d.OrchestratorActionType)))); // TODO: Exception handling for invalid decisions, which is increasingly likely // when custom middleware is involved (e.g. out-of-process scenarios). diff --git a/src/DurableTask.Core/Tracing/DefaultEventSource.cs b/src/DurableTask.Core/Tracing/DefaultEventSource.cs index 1043330c6..21db14479 100644 --- a/src/DurableTask.Core/Tracing/DefaultEventSource.cs +++ b/src/DurableTask.Core/Tracing/DefaultEventSource.cs @@ -92,6 +92,24 @@ public static class Keywords /// public bool IsCriticalEnabled => IsEnabled(EventLevel.Critical, Keywords.Diagnostics); + [NonEvent] + internal bool IsEventEnabled(TraceEventType eventLevel) + { + switch (eventLevel) + { + case TraceEventType.Critical: + return IsCriticalEnabled; + case TraceEventType.Error: + return IsErrorEnabled; + case TraceEventType.Warning: + return IsWarningEnabled; + case TraceEventType.Information: + return IsInfoEnabled; + default: + return IsTraceEnabled; + } + } + /// /// Trace an event for the supplied event type and parameters /// diff --git a/src/DurableTask.Core/Tracing/TraceHelper.cs b/src/DurableTask.Core/Tracing/TraceHelper.cs index 532e67a56..13a7a0cb9 100644 --- a/src/DurableTask.Core/Tracing/TraceHelper.cs +++ b/src/DurableTask.Core/Tracing/TraceHelper.cs @@ -712,6 +712,11 @@ static string CreateEntitySpanName(string entityName, string operationName) /// public static void Trace(TraceEventType eventLevel, string eventType, Func generateMessage) { + if (!DefaultEventSource.Log.IsEventEnabled(eventLevel)) + { + return; + } + ExceptionHandlingWrapper( () => DefaultEventSource.Log.TraceEvent(eventLevel, Source, string.Empty, string.Empty, string.Empty, generateMessage(), eventType)); } @@ -721,6 +726,11 @@ public static void Trace(TraceEventType eventLevel, string eventType, Func public static void Trace(TraceEventType eventLevel, string eventType, string format, params object[] args) { + if (!DefaultEventSource.Log.IsEventEnabled(eventLevel)) + { + return; + } + ExceptionHandlingWrapper( () => DefaultEventSource.Log.TraceEvent(eventLevel, Source, string.Empty, string.Empty, string.Empty, FormatString(format, args), eventType)); } @@ -730,6 +740,11 @@ public static void Trace(TraceEventType eventLevel, string eventType, string for /// public static void TraceSession(TraceEventType eventLevel, string eventType, string sessionId, Func generateMessage) { + if (!DefaultEventSource.Log.IsEventEnabled(eventLevel)) + { + return; + } + ExceptionHandlingWrapper( () => DefaultEventSource.Log.TraceEvent(eventLevel, Source, string.Empty, string.Empty, sessionId, generateMessage(), eventType)); } @@ -739,6 +754,11 @@ public static void TraceSession(TraceEventType eventLevel, string eventType, str /// public static void TraceSession(TraceEventType eventLevel, string eventType, string sessionId, string format, params object[] args) { + if (!DefaultEventSource.Log.IsEventEnabled(eventLevel)) + { + return; + } + ExceptionHandlingWrapper( () => DefaultEventSource.Log.TraceEvent(eventLevel, Source, string.Empty, string.Empty, sessionId, FormatString(format, args), eventType)); } @@ -749,6 +769,11 @@ public static void TraceSession(TraceEventType eventLevel, string eventType, str public static void TraceInstance(TraceEventType eventLevel, string eventType, OrchestrationInstance orchestrationInstance, string format, params object[] args) { + if (!DefaultEventSource.Log.IsEventEnabled(eventLevel)) + { + return; + } + ExceptionHandlingWrapper( () => DefaultEventSource.Log.TraceEvent( eventLevel, @@ -766,6 +791,11 @@ public static void TraceInstance(TraceEventType eventLevel, string eventType, Or public static void TraceInstance(TraceEventType eventLevel, string eventType, OrchestrationInstance orchestrationInstance, Func generateMessage) { + if (!DefaultEventSource.Log.IsEventEnabled(eventLevel)) + { + return; + } + ExceptionHandlingWrapper( () => DefaultEventSource.Log.TraceEvent( eventLevel, @@ -880,6 +910,11 @@ public static ExceptionDispatchInfo TraceExceptionSession(TraceEventType eventLe static ExceptionDispatchInfo TraceExceptionCore(TraceEventType eventLevel, string eventType, string iid, string eid, ExceptionDispatchInfo exceptionDispatchInfo, string format, params object[] args) { + if (!DefaultEventSource.Log.IsEventEnabled(eventLevel)) + { + return exceptionDispatchInfo; + } + Exception exception = exceptionDispatchInfo.SourceException; string newFormat = format + "\nException: " + exception.GetType() + " : " + exception.Message + "\n\t" + @@ -895,6 +930,11 @@ static ExceptionDispatchInfo TraceExceptionCore(TraceEventType eventLevel, strin static Exception TraceExceptionCore(TraceEventType eventLevel, string eventType, string iid, string eid, Exception exception, Func generateMessage) { + if (!DefaultEventSource.Log.IsEventEnabled(eventLevel)) + { + return exception; + } + string newFormat = generateMessage() + "\nException: " + exception.GetType() + " : " + exception.Message + "\n\t" + exception.StackTrace + "\nInner Exception: " + exception.InnerException?.ToString(); diff --git a/src/DurableTask.ServiceBus/ServiceBusOrchestrationService.cs b/src/DurableTask.ServiceBus/ServiceBusOrchestrationService.cs index 30bcb81c2..ae451e033 100644 --- a/src/DurableTask.ServiceBus/ServiceBusOrchestrationService.cs +++ b/src/DurableTask.ServiceBus/ServiceBusOrchestrationService.cs @@ -550,7 +550,7 @@ public async Task LockNextTaskOrchestrationWorkItemAs TraceEventType.Information, "ServiceBusOrchestrationService-LockNextTaskOrchestrationWorkItem-MessageToProcess", session.SessionId, - GetFormattedLog( + () => GetFormattedLog( $@"{newMessages.Count} new messages to process: { string.Join(",", newMessages.Select(m => m.MessageId))}, max latency: { newMessages.Max(message => message.DeliveryLatency())}ms")); @@ -1364,7 +1364,7 @@ async Task FetchTrackingWorkItemAsync(TimeSpan receiveTimeout, TraceEventType.Information, "ServiceBusOrchestrationService-FetchTrackingWorkItem-Messages", session.SessionId, - GetFormattedLog($"{newMessages.Count} new tracking messages to process: {string.Join(",", newMessages.Select(m => m.MessageId))}")); + () => GetFormattedLog($"{newMessages.Count} new tracking messages to process: {string.Join(",", newMessages.Select(m => m.MessageId))}")); ServiceBusUtils.CheckAndLogDeliveryCount(newMessages, this.Settings.MaxTrackingDeliveryCount); @@ -1579,7 +1579,7 @@ void LogSentMessages(IMessageSession session, string messageType, IList GetFormattedLog($@"{messages.Count.ToString()} messages queued for {messageType}: { string.Join(",", messages.Select(m => { string scheduledTime = m.Message.ScheduledEnqueueTimeUtc > DateTime.MinValue