From d0467cbfac7f06e3b5240d3e4094a0600c258b1e Mon Sep 17 00:00:00 2001 From: siport Date: Fri, 30 Jun 2017 11:33:05 -0700 Subject: [PATCH 1/6] Add missing docs, package info and bugfixes --- src/DurableTask.Core/Common/Utils.cs | 42 ++++++++ src/DurableTask.Core/FrameworkConstants.cs | 99 ++++++++++++++++++- src/DurableTask.Core/History/GenericEvent.cs | 14 +++ .../History/HistoryStateEvent.cs | 14 +++ .../OrchestrationStateInstanceFilter.cs | 17 ++++ .../OrchestrationStateNameVersionFilter.cs | 10 ++ .../OrchestrationStateQuery.cs | 7 +- .../OrchestrationStateQueryFilter.cs | 3 + .../OrchestrationStateStatusFilter.cs | 6 ++ .../OrchestrationStateTimeRangeFilter.cs | 14 +++ .../TaskActivityDispatcherSettings.cs | 3 + .../TaskOrchestrationDispatcherSettings.cs | 3 + .../Settings/TrackingDispatcherSettings.cs | 3 + src/DurableTask.Core/TaskHubClient.cs | 4 +- .../Tracing/DefaultEventSource.cs | 89 ++++++++++++++++- src/DurableTask.Core/Tracing/TraceHelper.cs | 54 ++++++++-- .../LocalOrchestrationService.cs | 39 ++++++++ src/DurableTask.Emulator/PeekLockQueue.cs | 2 +- .../ServiceBusConstants.cs | 2 + .../ServiceBusOrchestrationServiceSettings.cs | 6 +- .../Tracking/AzureTableInstanceStore.cs | 7 +- tools/DurableTask.props | 47 ++++++--- 22 files changed, 454 insertions(+), 31 deletions(-) diff --git a/src/DurableTask.Core/Common/Utils.cs b/src/DurableTask.Core/Common/Utils.cs index db7f3361c..86b413c33 100644 --- a/src/DurableTask.Core/Common/Utils.cs +++ b/src/DurableTask.Core/Common/Utils.cs @@ -25,15 +25,24 @@ namespace DurableTask.Core.Common using DurableTask.Core.Serializing; using Tracing; + /// + /// Utility Methods + /// public static class Utils { const int FullGzipHeaderLength = 10; + /// + /// Gets a safe maximim datetime value that accounts for timezone + /// public static readonly DateTime DateTimeSafeMaxValue = DateTime.MaxValue.Subtract(TimeSpan.FromDays(1)).ToUniversalTime(); static readonly byte[] GzipHeader = {0x1f, 0x8b}; + /// + /// Extension method to truncate a string to the supplied length + /// public static string Truncate(this string input, int maxLength) { if (!string.IsNullOrEmpty(input) && input.Length > maxLength) @@ -43,6 +52,9 @@ public static string Truncate(this string input, int maxLength) return input; } + /// + /// Serializes and appends the supplied object to the supplied stream + /// public static void WriteObjectToStream(Stream objectStream, object obj) { if (objectStream == null || !objectStream.CanWrite || !objectStream.CanSeek) @@ -57,6 +69,9 @@ public static void WriteObjectToStream(Stream objectStream, object obj) objectStream.Position = 0; } + /// + /// Writes the supplied string input to a MemoryStream, optionaly compressing the string + /// public static Stream WriteStringToStream(string input, bool compress, out long originalStreamSize) { Stream resultStream = new MemoryStream(); @@ -77,6 +92,9 @@ public static Stream WriteStringToStream(string input, bool compress, out long o return resultStream; } + /// + /// Reads and deserializes an Object from the supplied stream + /// public static T ReadObjectFromStream(Stream objectStream) { if (objectStream == null || !objectStream.CanRead || !objectStream.CanSeek) @@ -95,6 +113,9 @@ public static T ReadObjectFromStream(Stream objectStream) new JsonSerializerSettings {TypeNameHandling = TypeNameHandling.All}); } + /// + /// Returns true or false whether the supplied stream is a compressed stream + /// public static bool IsGzipStream(Stream stream) { if (stream == null || !stream.CanRead || !stream.CanSeek || stream.Length < FullGzipHeaderLength) @@ -171,6 +192,9 @@ public static async Task GetDecompressedStreamAsync(Stream input) return outputStream; } + /// + /// Returns true or false whether an exception is considered fatal + /// public static Boolean IsFatal(Exception exception) { if (exception is OutOfMemoryException || exception is StackOverflowException) @@ -180,6 +204,9 @@ public static Boolean IsFatal(Exception exception) return false; } + /// + /// Executes the supplied action until successful or the supplied number of attempts is reached + /// public static async Task ExecuteWithRetries(Func retryAction, string sessionId, string operation, int numberOfAttempts, int delayInAttemptsSecs) { @@ -209,6 +236,9 @@ public static async Task ExecuteWithRetries(Func retryAction, string sessi } } + /// + /// Executes the supplied action until successful or the supplied number of attempts is reached + /// public static async Task ExecuteWithRetries(Func> retryAction, string sessionId, string operation, int numberOfAttempts, int delayInAttemptsSecs) { @@ -242,6 +272,9 @@ public static async Task ExecuteWithRetries(Func> retryAction, str } + /// + /// Serializes the supplied exception to a string + /// public static string SerializeCause(Exception originalException, DataConverter converter) { if (originalException == null) @@ -268,6 +301,9 @@ public static string SerializeCause(Exception originalException, DataConverter c return details; } + /// + /// Retrieves the exception from a previously serialized exception + /// public static Exception RetrieveCause(string details, DataConverter converter) { if (converter == null) @@ -291,6 +327,9 @@ public static Exception RetrieveCause(string details, DataConverter converter) return cause; } + /// + /// Escapes the supplied input + /// public static string EscapeJson(string inputJson) { inputJson = inputJson.Replace("{", "{{"); @@ -301,6 +340,9 @@ public static string EscapeJson(string inputJson) return inputJson; } + /// + /// Builds a new OrchestrationState from the supplied OrchestrationRuntimeState + /// public static OrchestrationState BuildOrchestrationState(OrchestrationRuntimeState runtimeState) { return new OrchestrationState diff --git a/src/DurableTask.Core/FrameworkConstants.cs b/src/DurableTask.Core/FrameworkConstants.cs index c209b73d9..611e40c76 100644 --- a/src/DurableTask.Core/FrameworkConstants.cs +++ b/src/DurableTask.Core/FrameworkConstants.cs @@ -15,50 +15,147 @@ namespace DurableTask.Core { using System; + /// + /// Shared framework constants + /// public class FrameworkConstants { // tracking constants + /// + /// The content type of a Task Message + /// public const string TaskMessageContentType = "TaskMessage"; + + /// + /// The content type of a State Message + /// public const string StateMessageContentType = "StateMessage"; + + /// + /// The property name of a history event index + /// public const string HistoryEventIndexPropertyName = "HistoryEventIndex"; + /// + /// Id for a fake timer event + /// public const int FakeTimerIdToSplitDecision = -100; - public const int MaxDeliveryCount = 10; // task orchestration dispatcher default constants + /// + /// The default error backoff for transient errors task orchestrations in seconds + /// public const int OrchestrationTransientErrorBackOffSecs = 10; + + /// + /// The default error backoff for non-transient errors task orchestrations in seconds + /// public const int OrchestrationNonTransientErrorBackOffSecs = 120; + + /// + /// The default number of orchestration dispatchers + /// public const int OrchestrationDefaultDispatcherCount = 1; + + /// + /// The default max concurrent orchestration work items + /// public const int OrchestrationDefaultMaxConcurrentItems = 100; // task activity dispatcher default constants + /// + /// The default error backoff for transient errors task activities in seconds + /// public const int ActivityTransientErrorBackOffSecs = 10; + + /// + /// The default error backoff for non-transient errors task activities in seconds + /// public const int ActivityNonTransientErrorBackOffSecs = 120; + + /// + /// The default number of activity dispatchers + /// public const int ActivityDefaultDispatcherCount = 1; + + /// + /// The default max concurrent activity work items + /// public const int ActivityDefaultMaxConcurrentItems = 10; // tracking dispatcher default constants + /// + /// The default error backoff for transient errors tracking activities in seconds + /// public const int TrackingTransientErrorBackOffSecs = 10; + + /// + /// The default error backoff for non-transient errors tracking activities in seconds + /// public const int TrackingNonTransientErrorBackOffSecs = 120; + + /// + /// The default number of tracking dispatchers + /// public const int TrackingDefaultDispatcherCount = 1; + + /// + /// The default max concurrent tracking work items + /// public const int TrackingDefaultMaxConcurrentItems = 20; + + /// + /// The default setting for enabling tracking history events + /// public const bool TrackingTrackHistoryEvents = true; // Jumpstart constants + /// + /// The default timespan for the JumpStart interval + /// public static TimeSpan JumpStartDefaultInterval = TimeSpan.FromSeconds(5); + + /// + /// The default timespan for the JumpStart ignore window + /// public static TimeSpan JumpStartDefaultIgnoreWindow = TimeSpan.FromMinutes(10); // message content type constants + /// + /// The property name for compression type + /// public const string CompressionTypePropertyName = "CompressionType"; + + /// + /// The property value for compression type gzip + /// public const string CompressionTypeGzipPropertyValue = "gzip"; + + /// + /// The property value for compression type none + /// public const string CompressionTypeNonePropertyValue = "none"; // default settings for message size + /// + /// The default max message size before overflow + /// public const int MessageOverflowThresholdInBytesDefault = 170 * 1024; + + /// + /// The default max allowed message size + /// public const int MessageMaxSizeInBytesDefault = 10 * 1024 * 1024; // default settings for session size + /// + /// The default max session size before overflow + /// public const int SessionOverflowThresholdInBytesDefault = 230 * 1024; + + /// + /// The default max allowed session size + /// public const int SessionMaxSizeInBytesDefault = 10 * 1024 * 1024; } } \ No newline at end of file diff --git a/src/DurableTask.Core/History/GenericEvent.cs b/src/DurableTask.Core/History/GenericEvent.cs index 4fac2d0ba..4db9cd52b 100644 --- a/src/DurableTask.Core/History/GenericEvent.cs +++ b/src/DurableTask.Core/History/GenericEvent.cs @@ -15,17 +15,31 @@ namespace DurableTask.Core.History { using System.Runtime.Serialization; + /// + /// Generic History event + /// [DataContract] public class GenericEvent : HistoryEvent { + /// + /// String data for this event + /// [DataMember] public string Data; + /// + /// Creates a new GenericEvent with the supplied eventid and data + /// + /// The integer event id + /// The data for the event public GenericEvent(int eventId, string data) : base(eventId) { Data = data; } + /// + /// Gets the event type + /// public override EventType EventType { get { return EventType.GenericEvent; } diff --git a/src/DurableTask.Core/History/HistoryStateEvent.cs b/src/DurableTask.Core/History/HistoryStateEvent.cs index 8c88debe5..797b0cc3a 100644 --- a/src/DurableTask.Core/History/HistoryStateEvent.cs +++ b/src/DurableTask.Core/History/HistoryStateEvent.cs @@ -15,17 +15,31 @@ namespace DurableTask.Core.History { using System.Runtime.Serialization; + /// + /// History state event + /// [DataContract] public class HistoryStateEvent : HistoryEvent { + /// + /// Creates a new HistoryStateEvent with the supplied eventid and state + /// + /// The integer event id + /// The event state public HistoryStateEvent(int eventId, OrchestrationState state) : base(eventId) { State = state; } + /// + /// Gets the event type + /// public override EventType EventType => EventType.HistoryState; + /// + /// Gets the orchestration state + /// [DataMember] public OrchestrationState State { get; set; } } diff --git a/src/DurableTask.Core/OrchestrationStateInstanceFilter.cs b/src/DurableTask.Core/OrchestrationStateInstanceFilter.cs index a0afed126..4e28b079d 100644 --- a/src/DurableTask.Core/OrchestrationStateInstanceFilter.cs +++ b/src/DurableTask.Core/OrchestrationStateInstanceFilter.cs @@ -13,16 +13,33 @@ namespace DurableTask.Core { + /// + /// Filter for Orchestration instance filter + /// public class OrchestrationStateInstanceFilter : OrchestrationStateQueryFilter { + /// + /// Creates a new instance of the OrchestrationStateInstanceFilter with default settings + /// public OrchestrationStateInstanceFilter() { // default is exact match StartsWith = false; } + /// + /// Gets or sets the InstanceId for the filter + /// public string InstanceId { get; set; } + + /// + /// Gets or sets the ExecutionId for the filter + /// public string ExecutionId { get; set; } + + /// + /// Gets or sets the match type of either statrts with or exact match for the filter + /// public bool StartsWith { get; set; } } } \ No newline at end of file diff --git a/src/DurableTask.Core/OrchestrationStateNameVersionFilter.cs b/src/DurableTask.Core/OrchestrationStateNameVersionFilter.cs index d1ac66b1a..4db4668db 100644 --- a/src/DurableTask.Core/OrchestrationStateNameVersionFilter.cs +++ b/src/DurableTask.Core/OrchestrationStateNameVersionFilter.cs @@ -13,9 +13,19 @@ namespace DurableTask.Core { + /// + /// Filter for Orchestrationname and version + /// public class OrchestrationStateNameVersionFilter : OrchestrationStateQueryFilter { + /// + /// Gets or sets the Orchestration Name for the filter + /// public string Name { get; set; } + + /// + /// Gets or sets the Orchestration Version for the filter + /// public string Version { get; set; } } } \ No newline at end of file diff --git a/src/DurableTask.Core/OrchestrationStateQuery.cs b/src/DurableTask.Core/OrchestrationStateQuery.cs index 7af7d51f9..dce63e0ac 100644 --- a/src/DurableTask.Core/OrchestrationStateQuery.cs +++ b/src/DurableTask.Core/OrchestrationStateQuery.cs @@ -44,9 +44,14 @@ public OrchestrationStateQuery() FilterMap = new Dictionary(); } + /// + /// Gets the FilterMap for the query + /// public IDictionary FilterMap { get; private set; } - // returns + /// + /// Gets the primary_filter, collection_of(secondary_filters) for the query + /// public Tuple> GetFilters() { ICollection filters = FilterMap.Values; diff --git a/src/DurableTask.Core/OrchestrationStateQueryFilter.cs b/src/DurableTask.Core/OrchestrationStateQueryFilter.cs index 9a37b5b2b..6bfd0aa19 100644 --- a/src/DurableTask.Core/OrchestrationStateQueryFilter.cs +++ b/src/DurableTask.Core/OrchestrationStateQueryFilter.cs @@ -13,6 +13,9 @@ namespace DurableTask.Core { + /// + /// Abstract class for an orchestration state query filter + /// public abstract class OrchestrationStateQueryFilter { } diff --git a/src/DurableTask.Core/OrchestrationStateStatusFilter.cs b/src/DurableTask.Core/OrchestrationStateStatusFilter.cs index ed1a89ff1..35e7b1b88 100644 --- a/src/DurableTask.Core/OrchestrationStateStatusFilter.cs +++ b/src/DurableTask.Core/OrchestrationStateStatusFilter.cs @@ -13,8 +13,14 @@ namespace DurableTask.Core { + /// + /// Filter for Orchestration Status + /// public class OrchestrationStateStatusFilter : OrchestrationStateQueryFilter { + /// + /// Gets or sets the Status for the filter + /// public OrchestrationStatus Status { get; set; } } } \ No newline at end of file diff --git a/src/DurableTask.Core/OrchestrationStateTimeRangeFilter.cs b/src/DurableTask.Core/OrchestrationStateTimeRangeFilter.cs index c2fd8d112..5a5a82e8c 100644 --- a/src/DurableTask.Core/OrchestrationStateTimeRangeFilter.cs +++ b/src/DurableTask.Core/OrchestrationStateTimeRangeFilter.cs @@ -15,10 +15,24 @@ namespace DurableTask.Core { using System; + /// + /// Filter for Orchestration time range on a timerange type + /// public class OrchestrationStateTimeRangeFilter : OrchestrationStateQueryFilter { + /// + /// Gets or sets the StartTime for the filter + /// public DateTime StartTime { get; set; } + + /// + /// Gets or sets the EndTime for the filter + /// public DateTime EndTime { get; set; } + + /// + /// Gets or sets the time range filter type for the filter + /// public OrchestrationStateTimeRangeFilterType FilterType { get; set; } } } \ No newline at end of file diff --git a/src/DurableTask.Core/Settings/TaskActivityDispatcherSettings.cs b/src/DurableTask.Core/Settings/TaskActivityDispatcherSettings.cs index 7008bbd21..65bb292b8 100644 --- a/src/DurableTask.Core/Settings/TaskActivityDispatcherSettings.cs +++ b/src/DurableTask.Core/Settings/TaskActivityDispatcherSettings.cs @@ -18,6 +18,9 @@ namespace DurableTask.Core.Settings /// public class TaskActivityDispatcherSettings { + /// + /// Creates a new instance of the TaskActivityDispatcherSettings with the default settings + /// public TaskActivityDispatcherSettings() { TransientErrorBackOffSecs = FrameworkConstants.ActivityTransientErrorBackOffSecs; diff --git a/src/DurableTask.Core/Settings/TaskOrchestrationDispatcherSettings.cs b/src/DurableTask.Core/Settings/TaskOrchestrationDispatcherSettings.cs index e26b8709c..e415749e9 100644 --- a/src/DurableTask.Core/Settings/TaskOrchestrationDispatcherSettings.cs +++ b/src/DurableTask.Core/Settings/TaskOrchestrationDispatcherSettings.cs @@ -18,6 +18,9 @@ namespace DurableTask.Core.Settings /// public class TaskOrchestrationDispatcherSettings { + /// + /// Creates a new instance of the TaskOrchestrationDispatcherSettings with default settings + /// public TaskOrchestrationDispatcherSettings() { TransientErrorBackOffSecs = FrameworkConstants.OrchestrationTransientErrorBackOffSecs; diff --git a/src/DurableTask.Core/Settings/TrackingDispatcherSettings.cs b/src/DurableTask.Core/Settings/TrackingDispatcherSettings.cs index 891050f73..a39039567 100644 --- a/src/DurableTask.Core/Settings/TrackingDispatcherSettings.cs +++ b/src/DurableTask.Core/Settings/TrackingDispatcherSettings.cs @@ -20,6 +20,9 @@ namespace DurableTask.Core.Settings /// public class TrackingDispatcherSettings { + /// + /// Creates a new instance of the TrackingDispatcherSettings with default settings + /// public TrackingDispatcherSettings() { TransientErrorBackOffSecs = FrameworkConstants.TrackingTransientErrorBackOffSecs; diff --git a/src/DurableTask.Core/TaskHubClient.cs b/src/DurableTask.Core/TaskHubClient.cs index f9b839175..91414afae 100644 --- a/src/DurableTask.Core/TaskHubClient.cs +++ b/src/DurableTask.Core/TaskHubClient.cs @@ -373,7 +373,9 @@ async Task InternalCreateOrchestrationInstanceWithRaisedE }); } - await Task.WhenAll(taskMessages.Select(this.serviceClient.CreateTaskOrchestrationAsync)); + // Raised events and create orchestration calls use different methods so get handled separately + await Task.WhenAll(taskMessages.Where(t => !(t.Event is EventRaisedEvent)).Select(this.serviceClient.CreateTaskOrchestrationAsync)); + await this.serviceClient.SendTaskOrchestrationMessageBatchAsync(taskMessages.Where(t => (t.Event is EventRaisedEvent)).ToArray()); return orchestrationInstance; } diff --git a/src/DurableTask.Core/Tracing/DefaultEventSource.cs b/src/DurableTask.Core/Tracing/DefaultEventSource.cs index 36905a5fa..044a994f1 100644 --- a/src/DurableTask.Core/Tracing/DefaultEventSource.cs +++ b/src/DurableTask.Core/Tracing/DefaultEventSource.cs @@ -17,6 +17,9 @@ namespace DurableTask.Core.Tracing using System.Diagnostics; using System.Diagnostics.Tracing; + /// + /// Default event source for all DurableTask tracing + /// [EventSource( Name = "DurableTask-Core", Guid = "7DA4779A-152E-44A2-A6F2-F80D991A5BEE")] @@ -30,15 +33,21 @@ public class DefaultEventSource : EventSource const int ErrorEventId = 5; const int CriticalEventId = 6; - public static class Keywords + internal static class Keywords { public const EventKeywords Diagnostics = (EventKeywords)1L; } + /// + /// Gets the static instance of the DefaultEventSource + /// public static readonly DefaultEventSource Log = new DefaultEventSource(); readonly string processName; + /// + /// Creates a new instance of the DefaultEventSource + /// DefaultEventSource() { using (Process process = Process.GetCurrentProcess()) @@ -47,18 +56,39 @@ public static class Keywords } } + /// + /// Gets whether trace logs are enabled + /// public bool IsTraceEnabled => this.IsEnabled(EventLevel.Verbose, Keywords.Diagnostics); + /// + /// Gets whether debug logs are enabled + /// public bool IsDebugEnabled => this.IsEnabled(EventLevel.Verbose, Keywords.Diagnostics); + /// + /// Gets whether informational logs are enabled + /// public bool IsInfoEnabled => this.IsEnabled(EventLevel.Informational, EventKeywords.None); + /// + /// Gets whether warning logs are enabled + /// public bool IsWarningEnabled => this.IsEnabled(EventLevel.Warning, EventKeywords.None); + /// + /// Gets whether error logs are enabled + /// public bool IsErrorEnabled => this.IsEnabled(EventLevel.Error, EventKeywords.None); + /// + /// Gets whether critical logs are enabled + /// public bool IsCriticalEnabled => this.IsEnabled(EventLevel.Critical, EventKeywords.None); + /// + /// Trace an event for the supplied eventtype and parameters + /// [NonEvent] public void TraceEvent(TraceEventType eventType, string source, string instanceId, string executionId, string sessionId, string message) { @@ -82,18 +112,30 @@ public void TraceEvent(TraceEventType eventType, string source, string instanceI } } + /// + /// Trace an event for the supplied eventtype, exception and parameters + /// [NonEvent] public void TraceEvent(TraceEventType eventType, string source, string instanceId, string executionId, string sessionId, Exception exception) => this.TraceEvent(eventType, source, instanceId, executionId, sessionId, exception?.ToString() ?? string.Empty); + /// + /// Trace an event for the supplied parameters + /// [NonEvent] public void Trace(string source, string instanceId, string executionId, string sessionId, string message) => this.Trace(source, instanceId, executionId, sessionId, message, string.Empty); + /// + /// Trace an event for the supplied exception and parameters + /// [NonEvent] public void Trace(string source, string instanceId, string executionId, string sessionId, string message, Exception exception) => this.Trace(source, instanceId, executionId, sessionId, message, exception?.ToString() ?? string.Empty); + /// + /// Trace an event for the supplied parameters + /// [Event(TraceEventId, Level = EventLevel.Verbose, Keywords = Keywords.Diagnostics, Version = 2)] public void Trace(string source, string instanceId, string executionId, string sessionId, string message, string info) { @@ -103,14 +145,23 @@ public void Trace(string source, string instanceId, string executionId, string s } } + /// + /// Log debug event for the supplied parameters + /// [NonEvent] public void Debug(string source, string instanceId, string executionId, string sessionId, string message) => this.Debug(source, instanceId, executionId, sessionId, message, string.Empty); + /// + /// Log debug event for the supplied exception and parameters + /// [NonEvent] public void Debug(string source, string instanceId, string executionId, string sessionId, string message, Exception exception) => this.Debug(source, instanceId, executionId, sessionId, message, exception?.ToString() ?? string.Empty); + /// + /// Log debug event for the supplied parameters + /// [Event(DebugEventId, Level = EventLevel.Verbose, Keywords = Keywords.Diagnostics, Version = 2)] public void Debug(string source, string instanceId, string executionId, string sessionId, string message, string info) { @@ -120,14 +171,23 @@ public void Debug(string source, string instanceId, string executionId, string s } } + /// + /// Log informational event for the supplied parameters + /// [NonEvent] public void Info(string source, string instanceId, string executionId, string sessionId, string message) => this.Info(source, instanceId, executionId, sessionId, message, string.Empty); + /// + /// Log informational event for the supplied exception and parameters + /// [NonEvent] public void Info(string source, string instanceId, string executionId, string sessionId, string message, Exception exception) => this.Info(source, instanceId, executionId, sessionId, message, exception?.ToString() ?? string.Empty); + /// + /// Log informational event for the supplied parameters + /// [Event(InfoEventId, Level = EventLevel.Informational, Keywords = EventKeywords.None, Version = 2)] public void Info(string source, string instanceId, string executionId, string sessionId, string message, string info) { @@ -137,14 +197,23 @@ public void Info(string source, string instanceId, string executionId, string se } } + /// + /// Log warning event for the supplied parameters + /// [NonEvent] public void Warning(string source, string instanceId, string executionId, string sessionId, string message) => this.Warning(source, instanceId, executionId, sessionId, message, string.Empty); + /// + /// Log warning event for the supplied exception and parameters + /// [NonEvent] public void Warning(string source, string instanceId, string executionId, string sessionId, string message, Exception exception) => this.Warning(source, instanceId, executionId, sessionId, message, exception?.ToString() ?? string.Empty); + /// + /// Log warning event for the supplied parameters + /// [Event(WarningEventId, Level = EventLevel.Warning, Keywords = EventKeywords.None, Version = 2)] public void Warning(string source, string instanceId, string executionId, string sessionId, string message, string exception) { @@ -154,14 +223,23 @@ public void Warning(string source, string instanceId, string executionId, string } } + /// + /// Log error event for the supplied parameters + /// [NonEvent] public void Error(string source, string instanceId, string executionId, string sessionId, string message) => this.Error(source, instanceId, executionId, sessionId, message, string.Empty); + /// + /// Log error event for the supplied exception and parameters + /// [NonEvent] public void Error(string source, string instanceId, string executionId, string sessionId, string message, Exception exception) => this.Error(source, instanceId, executionId, sessionId, message, exception?.ToString() ?? string.Empty); + /// + /// Log error event for the supplied parameters + /// [Event(ErrorEventId, Level = EventLevel.Error, Keywords = EventKeywords.None, Version = 2)] public void Error(string source, string instanceId, string executionId, string sessionId, string message, string exception) { @@ -171,14 +249,23 @@ public void Error(string source, string instanceId, string executionId, string s } } + /// + /// Log critical event for the supplied parameters + /// [NonEvent] public void Critical(string source, string instanceId, string executionId, string sessionId, string message) => this.Critical(source, instanceId, executionId, sessionId, message, string.Empty); + /// + /// Log critical event for the supplied exception and parameters + /// [NonEvent] public void Critical(string source, string instanceId, string executionId, string sessionId, string message, Exception exception) => this.Critical(source, instanceId, executionId, sessionId, message, exception?.ToString() ?? string.Empty); + /// + /// Log critical event for the supplied parameters + /// [Event(CriticalEventId, Level = EventLevel.Critical, Keywords = EventKeywords.None, Version = 2)] public void Critical(string source, string instanceId, string executionId, string sessionId, string message, string exception) { diff --git a/src/DurableTask.Core/Tracing/TraceHelper.cs b/src/DurableTask.Core/Tracing/TraceHelper.cs index 7a517cdfd..03824c2b1 100644 --- a/src/DurableTask.Core/Tracing/TraceHelper.cs +++ b/src/DurableTask.Core/Tracing/TraceHelper.cs @@ -18,37 +18,52 @@ namespace DurableTask.Core.Tracing using System.Globalization; using DurableTask.Core.Common; + /// + /// Helper class for logging/tracing + /// public class TraceHelper { const string Source = "DurableTask"; - // simple tracing, no iid and eid + /// + /// Simple trace with no iid or eid + /// public static void Trace(TraceEventType eventType, Func generateMessage) { ExceptionHandlingWrapper( () => DefaultEventSource.Log.TraceEvent(eventType, Source, string.Empty, string.Empty, string.Empty, generateMessage())); } + /// + /// Simple trace with no iid or eid + /// public static void Trace(TraceEventType eventType, string format, params object[] args) { ExceptionHandlingWrapper( () => DefaultEventSource.Log.TraceEvent(eventType, Source, string.Empty, string.Empty, string.Empty, FormatString(format, args))); } - // have iid but no eid + /// + /// Trace with iid but no eid + /// public static void TraceSession(TraceEventType eventType, string sessionId, Func generateMessage) { ExceptionHandlingWrapper( () => DefaultEventSource.Log.TraceEvent(eventType, Source, string.Empty, string.Empty, sessionId, generateMessage())); } + /// + /// Trace with iid but no eid + /// public static void TraceSession(TraceEventType eventType, string sessionId, string format, params object[] args) { ExceptionHandlingWrapper( () => DefaultEventSource.Log.TraceEvent(eventType, Source, string.Empty, string.Empty, sessionId, FormatString(format, args))); } - // have both iid and eid + /// + /// Trace with iid and eid + /// public static void TraceInstance(TraceEventType eventType, OrchestrationInstance orchestrationInstance, string format, params object[] args) { @@ -62,6 +77,9 @@ public static void TraceInstance(TraceEventType eventType, OrchestrationInstance FormatString(format, args))); } + /// + /// Trace with iid and eid + /// public static void TraceInstance(TraceEventType eventType, OrchestrationInstance orchestrationInstance, Func generateMessage) { @@ -75,25 +93,35 @@ public static void TraceInstance(TraceEventType eventType, OrchestrationInstance generateMessage())); } - // simple exception tracing methods + /// + /// Trace an exception + /// public static Exception TraceException(TraceEventType eventType, Exception exception) { return TraceException(eventType, exception, string.Empty); } + /// + /// Trace an exception and message + /// public static Exception TraceException(TraceEventType eventType, Exception exception, Func generateMessage) { return TraceExceptionCore(eventType, string.Empty, string.Empty, exception, generateMessage); } + /// + /// Trace an exception and message + /// public static Exception TraceException(TraceEventType eventType, Exception exception, string format, params object[] args) { return TraceExceptionCore(eventType, string.Empty, string.Empty, exception, format, args); } - // instance tracing methods + /// + /// Trace an instance exception + /// public static Exception TraceExceptionInstance(TraceEventType eventType, OrchestrationInstance orchestrationInstance, Exception exception) { @@ -101,6 +129,9 @@ public static Exception TraceExceptionInstance(TraceEventType eventType, exception, string.Empty); } + /// + /// Trace an instance exception and message + /// public static Exception TraceExceptionInstance(TraceEventType eventType, OrchestrationInstance orchestrationInstance, Exception exception, Func generateMessage) { @@ -108,6 +139,9 @@ public static Exception TraceExceptionInstance(TraceEventType eventType, exception, generateMessage); } + /// + /// Trace an instance exception and message + /// public static Exception TraceExceptionInstance(TraceEventType eventType, OrchestrationInstance orchestrationInstance, Exception exception, string format, params object[] args) { @@ -115,18 +149,26 @@ public static Exception TraceExceptionInstance(TraceEventType eventType, exception, format, args); } - // session tracing methods -- execution id not available + /// + /// Trace a session exception without execution id + /// public static Exception TraceExceptionSession(TraceEventType eventType, string sessionId, Exception exception) { return TraceExceptionCore(eventType, sessionId, string.Empty, exception, string.Empty); } + /// + /// Trace a session exception and message without execution id + /// public static Exception TraceExceptionSession(TraceEventType eventType, string sessionId, Exception exception, Func generateMessage) { return TraceExceptionCore(eventType, sessionId, string.Empty, exception, generateMessage); } + /// + /// Trace a session exception and message without execution id + /// public static Exception TraceExceptionSession(TraceEventType eventType, string sessionId, Exception exception, string format, params object[] args) { diff --git a/src/DurableTask.Emulator/LocalOrchestrationService.cs b/src/DurableTask.Emulator/LocalOrchestrationService.cs index b297d011e..98a6f7b3b 100644 --- a/src/DurableTask.Emulator/LocalOrchestrationService.cs +++ b/src/DurableTask.Emulator/LocalOrchestrationService.cs @@ -50,6 +50,10 @@ public class LocalOrchestrationService : IOrchestrationService, IOrchestrationSe ConcurrentDictionary> orchestrationWaiters; + /// + /// Creates a new instance of the LocalOrchestrationService with default settings + /// + public LocalOrchestrationService() { this.orchestratorQueue = new PeekLockSessionQueue(); @@ -96,48 +100,57 @@ async Task TimerMessageSchedulerAsync() /******************************/ // management methods /******************************/ + /// public Task CreateAsync() { return CreateAsync(true); } + /// public Task CreateAsync(bool recreateInstanceStore) { return Task.FromResult(null); } + /// public Task CreateIfNotExistsAsync() { return Task.FromResult(null); } + /// public Task DeleteAsync() { return DeleteAsync(true); } + /// public Task DeleteAsync(bool deleteInstanceStore) { return Task.FromResult(null); } + /// public Task StartAsync() { Task.Run(() => TimerMessageSchedulerAsync()); return Task.FromResult(null); } + /// public Task StopAsync(bool isForced) { this.cancellationTokenSource.Cancel(); return Task.FromResult(null); } + /// public Task StopAsync() { return StopAsync(false); } + /// public bool IsTransientException(Exception exception) { return false; @@ -146,6 +159,7 @@ public bool IsTransientException(Exception exception) /******************************/ // client methods /******************************/ + /// public Task CreateTaskOrchestrationAsync(TaskMessage creationMessage) { ExecutionStartedEvent ee = creationMessage.Event as ExecutionStartedEvent; @@ -187,11 +201,13 @@ public Task CreateTaskOrchestrationAsync(TaskMessage creationMessage) return Task.FromResult(null); } + /// public Task SendTaskOrchestrationMessageAsync(TaskMessage message) { return SendTaskOrchestrationMessageBatchAsync(message); } + /// public Task SendTaskOrchestrationMessageBatchAsync(params TaskMessage[] messages) { foreach (var message in messages) @@ -202,6 +218,7 @@ public Task SendTaskOrchestrationMessageBatchAsync(params TaskMessage[] messages return Task.FromResult(null); } + /// public async Task WaitForOrchestrationAsync( string instanceId, string executionId, @@ -284,6 +301,7 @@ public async Task WaitForOrchestrationAsync( return await tcs.Task; } + /// public async Task GetOrchestrationStateAsync(string instanceId, string executionId) { OrchestrationState response; @@ -301,6 +319,7 @@ public async Task GetOrchestrationStateAsync(string instance return await Task.FromResult(response); } + /// public async Task> GetOrchestrationStateAsync(string instanceId, bool allExecutions) { IList response; @@ -321,11 +340,13 @@ public async Task> GetOrchestrationStateAsync(string i return await Task.FromResult(response); } + /// public Task GetOrchestrationHistoryAsync(string instanceId, string executionId) { throw new NotImplementedException(); } + /// public Task PurgeOrchestrationHistoryAsync(DateTime thresholdDateTimeUtc, OrchestrationStateTimeRangeFilterType timeRangeFilterType) { throw new NotImplementedException(); @@ -334,8 +355,10 @@ public Task PurgeOrchestrationHistoryAsync(DateTime thresholdDateTimeUtc, Orches /******************************/ // Task orchestration methods /******************************/ + /// public int MaxConcurrentTaskOrchestrationWorkItems => MaxConcurrentWorkItems; + /// public async Task LockNextTaskOrchestrationWorkItemAsync( TimeSpan receiveTimeout, CancellationToken cancellationToken) @@ -361,6 +384,7 @@ public async Task LockNextTaskOrchestrationWorkItemAs return wi; } + /// public Task CompleteTaskOrchestrationWorkItemAsync( TaskOrchestrationWorkItem workItem, OrchestrationRuntimeState newOrchestrationRuntimeState, @@ -450,21 +474,26 @@ public Task CompleteTaskOrchestrationWorkItemAsync( return Task.FromResult(0); } + /// public Task AbandonTaskOrchestrationWorkItemAsync(TaskOrchestrationWorkItem workItem) { this.orchestratorQueue.AbandonSession(workItem.InstanceId); return Task.FromResult(null); } + /// public Task ReleaseTaskOrchestrationWorkItemAsync(TaskOrchestrationWorkItem workItem) { return Task.FromResult(null); } + /// public int TaskActivityDispatcherCount => 1; + /// public int MaxConcurrentTaskActivityWorkItems => MaxConcurrentWorkItems; + /// public async Task ForceTerminateTaskOrchestrationAsync(string instanceId, string message) { var taskMessage = new TaskMessage @@ -476,32 +505,38 @@ public async Task ForceTerminateTaskOrchestrationAsync(string instanceId, string await SendTaskOrchestrationMessageAsync(taskMessage); } + /// public Task RenewTaskOrchestrationWorkItemLockAsync(TaskOrchestrationWorkItem workItem) { workItem.LockedUntilUtc = workItem.LockedUntilUtc.AddMinutes(5); return Task.FromResult(0); } + /// public bool IsMaxMessageCountExceeded(int currentMessageCount, OrchestrationRuntimeState runtimeState) { return false; } + /// public int GetDelayInSecondsAfterOnProcessException(Exception exception) { return 0; } + /// public int GetDelayInSecondsAfterOnFetchException(Exception exception) { return 0; } + /// public int TaskOrchestrationDispatcherCount => 1; /******************************/ // Task activity methods /******************************/ + /// public async Task LockNextTaskActivityWorkItem(TimeSpan receiveTimeout, CancellationToken cancellationToken) { TaskMessage taskMessage = await this.workerQueue.ReceiveMessageAsync(receiveTimeout, @@ -520,12 +555,14 @@ public async Task LockNextTaskActivityWorkItem(TimeSpan re }; } + /// public Task AbandonTaskActivityWorkItemAsync(TaskActivityWorkItem workItem) { this.workerQueue.AbandonMessageAsync(workItem.TaskMessage); return Task.FromResult(null); } + /// public Task CompleteTaskActivityWorkItemAsync(TaskActivityWorkItem workItem, TaskMessage responseMessage) { lock (this.thisLock) @@ -537,6 +574,7 @@ public Task CompleteTaskActivityWorkItemAsync(TaskActivityWorkItem workItem, Tas return Task.FromResult(null); } + /// public Task RenewTaskActivityWorkItemLockAsync(TaskActivityWorkItem workItem) { // AFFANDAR : TODO : add expiration if we want to unit test it @@ -568,6 +606,7 @@ OrchestrationRuntimeState DeserializeOrchestrationRuntimeState(byte[] stateBytes return new OrchestrationRuntimeState(events); } + /// public void Dispose() { this.Dispose(true); diff --git a/src/DurableTask.Emulator/PeekLockQueue.cs b/src/DurableTask.Emulator/PeekLockQueue.cs index b8843ceca..17b550294 100644 --- a/src/DurableTask.Emulator/PeekLockQueue.cs +++ b/src/DurableTask.Emulator/PeekLockQueue.cs @@ -20,7 +20,7 @@ namespace DurableTask.Emulator using System.Threading; using System.Threading.Tasks; - public class PeeklockQueue + internal class PeeklockQueue { List messages; HashSet lockTable; diff --git a/src/DurableTask.ServiceBus/ServiceBusConstants.cs b/src/DurableTask.ServiceBus/ServiceBusConstants.cs index b2d643996..670a7a68a 100644 --- a/src/DurableTask.ServiceBus/ServiceBusConstants.cs +++ b/src/DurableTask.ServiceBus/ServiceBusConstants.cs @@ -27,6 +27,8 @@ internal class ServiceBusConstants public const string StateMessageContentType = "StateMessage"; public const string HistoryEventIndexPropertyName = "HistoryEventIndex"; + public const int MaxDeliveryCount = 10; + // message blob key in message property // this property is a key to the message blob when it exceeds the message limit public const string MessageBlobKey = "MessageBlobKey"; diff --git a/src/DurableTask.ServiceBus/Settings/ServiceBusOrchestrationServiceSettings.cs b/src/DurableTask.ServiceBus/Settings/ServiceBusOrchestrationServiceSettings.cs index 4e3e239dc..0d3229c0d 100644 --- a/src/DurableTask.ServiceBus/Settings/ServiceBusOrchestrationServiceSettings.cs +++ b/src/DurableTask.ServiceBus/Settings/ServiceBusOrchestrationServiceSettings.cs @@ -27,9 +27,9 @@ public sealed class ServiceBusOrchestrationServiceSettings /// public ServiceBusOrchestrationServiceSettings() { - MaxTaskOrchestrationDeliveryCount = FrameworkConstants.MaxDeliveryCount; - MaxTaskActivityDeliveryCount = FrameworkConstants.MaxDeliveryCount; - MaxTrackingDeliveryCount = FrameworkConstants.MaxDeliveryCount; + MaxTaskOrchestrationDeliveryCount = ServiceBusConstants.MaxDeliveryCount; + MaxTaskActivityDeliveryCount = ServiceBusConstants.MaxDeliveryCount; + MaxTrackingDeliveryCount = ServiceBusConstants.MaxDeliveryCount; TaskOrchestrationDispatcherSettings = new TaskOrchestrationDispatcherSettings(); TaskActivityDispatcherSettings = new TaskActivityDispatcherSettings(); TrackingDispatcherSettings = new TrackingDispatcherSettings(); diff --git a/src/DurableTask.ServiceBus/Tracking/AzureTableInstanceStore.cs b/src/DurableTask.ServiceBus/Tracking/AzureTableInstanceStore.cs index 9adad9df9..56e0744f8 100644 --- a/src/DurableTask.ServiceBus/Tracking/AzureTableInstanceStore.cs +++ b/src/DurableTask.ServiceBus/Tracking/AzureTableInstanceStore.cs @@ -47,11 +47,8 @@ public AzureTableInstanceStore(string hubName, string tableConnectionString) { this.tableClient = new AzureTableClient(hubName, tableConnectionString); - // Workaround a bug in the Storage Emulator that throws exceptions for any date < 1600 so DateTime.Min cannot be used - if (tableConnectionString.Contains("UseDevelopmentStorage=true")) - { - DateTimeUtils.SetMinDateTimeForStorageEmulator(); - } + // Workaround an issue with Storage that throws exceptions for any date < 1600 so DateTime.Min cannot be used + DateTimeUtils.SetMinDateTimeForStorageEmulator(); } /// diff --git a/tools/DurableTask.props b/tools/DurableTask.props index d8ea10b0d..5768af44b 100644 --- a/tools/DurableTask.props +++ b/tools/DurableTask.props @@ -1,18 +1,41 @@ - - - pdbonly - True - v4.5.1 + + + pdbonly + True + v4.5.1 + true - - True - False - False - True - True - + + True + False + True + True + + + + + False + False + + + + + ..\..\build_output\packages + 2.0.0.1 + 2.0.0.1 + 2.0.0.1 + Microsoft + Durable Task Framework + This package provides a C# based durable task framework for writing long running applications. + http://www.apache.org/licenses/LICENSE-2.0 + Copyright Microsoft Corporation 2017 + https://github.com/Azure/durabletask/ + https://github.com/Azure/durabletask/ + ServiceBus;Service Bus;Azure;Task;Durable;Orchestration;Workflow;Activity;Reliable + + From 2d822532df709b0d5361a1a66cc8e1f0c1f7b006 Mon Sep 17 00:00:00 2001 From: siport Date: Fri, 30 Jun 2017 15:38:34 -0700 Subject: [PATCH 2/6] Add EventType to all tracing, fix trace formatting --- .../DurableTask.Test.Orchestrations.csproj | 5 + src/DurableTask.Core/Common/Utils.cs | 19 ++- .../IOrchestrationServiceInstanceStore.cs | 2 +- src/DurableTask.Core/RetryInterceptor.cs | 2 +- .../RuntimeStateStreamConverter.cs | 11 +- .../TaskActivityDispatcher.cs | 18 ++- .../TaskOrchestrationContext.cs | 1 + .../TaskOrchestrationDispatcher.cs | 85 +++++++++--- .../Tracing/DefaultEventSource.cs | 126 ++++++++++-------- src/DurableTask.Core/Tracing/TraceHelper.cs | 78 +++++------ src/DurableTask.Core/WorkItemDispatcher.cs | 86 +++++++----- .../Common/ServiceBusUtils.cs | 21 ++- .../ServiceBusOrchestrationService.cs | 67 +++++++--- .../Tracking/AzureTableClient.cs | 4 +- .../Tracking/AzureTableInstanceStore.cs | 4 +- .../Tracking/BlobStorageClientHelper.cs | 2 + .../Tracking/JumpStartManager.cs | 37 +++-- test/DurableTask.Core.Tests/CommonTests.cs | 10 +- .../DurableTask.Core.Tests.csproj | 3 +- 19 files changed, 368 insertions(+), 213 deletions(-) diff --git a/Test/DurableTask.Test.Orchestrations/DurableTask.Test.Orchestrations.csproj b/Test/DurableTask.Test.Orchestrations/DurableTask.Test.Orchestrations.csproj index fafab8a73..4a429674e 100644 --- a/Test/DurableTask.Test.Orchestrations/DurableTask.Test.Orchestrations.csproj +++ b/Test/DurableTask.Test.Orchestrations/DurableTask.Test.Orchestrations.csproj @@ -4,6 +4,11 @@ net451 + + + + + diff --git a/src/DurableTask.Core/Common/Utils.cs b/src/DurableTask.Core/Common/Utils.cs index 86b413c33..a0a543906 100644 --- a/src/DurableTask.Core/Common/Utils.cs +++ b/src/DurableTask.Core/Common/Utils.cs @@ -221,7 +221,10 @@ public static async Task ExecuteWithRetries(Func retryAction, string sessi } catch (Exception exception) when (!Utils.IsFatal(exception)) { - TraceHelper.TraceSession(TraceEventType.Warning, sessionId, + TraceHelper.TraceSession( + TraceEventType.Warning, + "ExecuteWithRetry-Failure", + sessionId, $"Error attempting operation {operation}. Attempt count: {numberOfAttempts - retryCount}. Exception: {exception.Message}\n\t{exception.StackTrace}"); lastException = exception; } @@ -231,8 +234,8 @@ public static async Task ExecuteWithRetries(Func retryAction, string sessi if (retryCount <= 0 && lastException != null) { - TraceHelper.Trace(TraceEventType.Error, "Exhausted all retries for operation " + operation); - throw TraceHelper.TraceExceptionSession(TraceEventType.Error, sessionId, lastException); + TraceHelper.Trace(TraceEventType.Error, "ExecuteWithRetry-RetriesExhausted", "Exhausted all retries for operation " + operation); + throw TraceHelper.TraceExceptionSession(TraceEventType.Error, "ExecuteWithRetryRetriesExhausted", sessionId, lastException); } } @@ -254,7 +257,10 @@ public static async Task ExecuteWithRetries(Func> retryAction, str } catch (Exception exception) when (!Utils.IsFatal(exception)) { - TraceHelper.TraceSession(TraceEventType.Warning, sessionId, + TraceHelper.TraceSession( + TraceEventType.Warning, + $"ExecuteWithRetry<{typeof(T)}>-Failure", + sessionId, $"Error attempting operation {operation}. Attempt count: {numberOfAttempts - retryCount}. Exception: {exception.Message}\n\t{exception.StackTrace}"); lastException = exception; } @@ -264,8 +270,9 @@ public static async Task ExecuteWithRetries(Func> retryAction, str if (retryCount <= 0 && lastException != null) { - TraceHelper.Trace(TraceEventType.Error, "Exhausted all retries for operation " + operation); - throw TraceHelper.TraceExceptionSession(TraceEventType.Error, sessionId, lastException); + var eventType = $"ExecuteWithRetry<{typeof(T)}>-Failure"; + TraceHelper.Trace(TraceEventType.Error, eventType, "Exhausted all retries for operation " + operation); + throw TraceHelper.TraceExceptionSession(TraceEventType.Error, eventType, sessionId, lastException); } return retVal; diff --git a/src/DurableTask.Core/IOrchestrationServiceInstanceStore.cs b/src/DurableTask.Core/IOrchestrationServiceInstanceStore.cs index bc607a4d0..209048380 100644 --- a/src/DurableTask.Core/IOrchestrationServiceInstanceStore.cs +++ b/src/DurableTask.Core/IOrchestrationServiceInstanceStore.cs @@ -102,7 +102,7 @@ public interface IOrchestrationServiceInstanceStore /// Deletes a list of jump start events from instance store /// /// List of jump start events to delete - Task DeleteJumpStartEntitesAsync(IEnumerable entities); + Task DeleteJumpStartEntitiesAsync(IEnumerable entities); /// /// Get a list of jump start events from instance store diff --git a/src/DurableTask.Core/RetryInterceptor.cs b/src/DurableTask.Core/RetryInterceptor.cs index 2fee0ccf6..2cc8bcf65 100644 --- a/src/DurableTask.Core/RetryInterceptor.cs +++ b/src/DurableTask.Core/RetryInterceptor.cs @@ -94,7 +94,7 @@ TimeSpan ComputeNextDelay(int attempt, DateTime firstAttempt, Exception failure) catch (Exception e) when (!Utils.IsFatal(e)) { // Catch any exceptions during ComputeNextDelay so we don't override original error with new error - TraceHelper.TraceExceptionInstance(TraceEventType.Error, context.OrchestrationInstance, e); + TraceHelper.TraceExceptionInstance(TraceEventType.Error, "RetryInterceptor-ComputeNextDelayException", context.OrchestrationInstance, e); } return nextDelay; diff --git a/src/DurableTask.Core/Serializing/RuntimeStateStreamConverter.cs b/src/DurableTask.Core/Serializing/RuntimeStateStreamConverter.cs index fe06fce38..ad5c134ca 100644 --- a/src/DurableTask.Core/Serializing/RuntimeStateStreamConverter.cs +++ b/src/DurableTask.Core/Serializing/RuntimeStateStreamConverter.cs @@ -71,7 +71,9 @@ public static async Task OrchestrationRuntimeStateToRawStream( if (runtimeState.CompressedSize > serviceBusSessionSettings.SessionOverflowThresholdInBytes) { - TraceHelper.TraceSession(TraceEventType.Information, + TraceHelper.TraceSession( + TraceEventType.Information, + "RuntimeStateStreamConverter-SessionStateThresholdExceeded", sessionId, $"Session state size of {runtimeState.CompressedSize} exceeded the termination threshold of {serviceBusSessionSettings.SessionOverflowThresholdInBytes} bytes." + $"Creating an OrchestrationSessionState instance with key for exteranl storage."); @@ -99,6 +101,7 @@ async static Task CreateStreamForExternalStorageAsync( string key = orchestrationServiceBlobStore.BuildSessionBlobKey(sessionId); TraceHelper.TraceSession( TraceEventType.Information, + "RuntimeStateStreamConverter-SaveSessionToStorage", sessionId, $"Saving the serialized stream in external storage with key {key}."); @@ -143,6 +146,7 @@ public static async Task RawStreamToRuntimeState(Stre { TraceHelper.TraceSession( TraceEventType.Information, + "RuntimeStateStreamConverter-StreamToRuntimeStateSize", sessionId, $"Size of session state is {newSessionStateSize}, compressed {rawSessionStateSize}"); return runtimeState; @@ -156,6 +160,7 @@ public static async Task RawStreamToRuntimeState(Stre TraceHelper.TraceSession( TraceEventType.Information, + "RuntimeStateStreamConverter-StreamToRuntimeStateLoadFromStorage", sessionId, $"Loading the serialzied stream from external storage with blob key {blobKey}."); @@ -171,6 +176,7 @@ static OrchestrationRuntimeState GetOrCreateInstanceState(Stream stateStream, st { TraceHelper.TraceSession( TraceEventType.Information, + "RuntimeStateStreamConverter-GetOrCreateInstanceStateNewSession", sessionId, "No session state exists, creating new session state."); runtimeState = new OrchestrationRuntimeState(); @@ -181,6 +187,7 @@ static OrchestrationRuntimeState GetOrCreateInstanceState(Stream stateStream, st { throw TraceHelper.TraceExceptionSession( TraceEventType.Error, + "RuntimeStateStreamConverter-GetOrCreateInstanceStatePartiallyConsumed", sessionId, new ArgumentException("Stream is partially consumed")); } @@ -228,6 +235,7 @@ static OrchestrationRuntimeState DeserializeToRuntimeStateWithFallback(string se { TraceHelper.TraceSession( TraceEventType.Warning, + "RuntimeStateStreamConverter-DeserializeToRuntimeStateFailed", sessionId, $"Failed to deserialize session state to OrchestrationSessionState object: {serializedState}. More info: {exception.StackTrace}"); try @@ -241,6 +249,7 @@ static OrchestrationRuntimeState DeserializeToRuntimeStateWithFallback(string se { TraceHelper.TraceSession( TraceEventType.Warning, + "RuntimeStateStreamConverter-DeserializeToRuntimeStateException", sessionId, $"Failed to deserialize session state to OrchestrationRuntimeState object: {serializedState}. More info: {e.StackTrace}"); diff --git a/src/DurableTask.Core/TaskActivityDispatcher.cs b/src/DurableTask.Core/TaskActivityDispatcher.cs index d908ba4ae..8688bb7dd 100644 --- a/src/DurableTask.Core/TaskActivityDispatcher.cs +++ b/src/DurableTask.Core/TaskActivityDispatcher.cs @@ -94,12 +94,16 @@ async Task OnProcessWorkItemAsync(TaskActivityWorkItem workItem) OrchestrationInstance orchestrationInstance = taskMessage.OrchestrationInstance; if (string.IsNullOrWhiteSpace(orchestrationInstance?.InstanceId)) { - throw TraceHelper.TraceException(TraceEventType.Error, + throw TraceHelper.TraceException( + TraceEventType.Error, + "TaskActivityDispatcher-MissingOrchestrationInstance", new InvalidOperationException("Message does not contain any OrchestrationInstance information")); } if (taskMessage.Event.EventType != EventType.TaskScheduled) { - throw TraceHelper.TraceException(TraceEventType.Critical, + throw TraceHelper.TraceException( + TraceEventType.Critical, + "TaskActivityDispatcher-UnsupportedEventType", new NotSupportedException("Activity worker does not support event of type: " + taskMessage.Event.EventType)); } @@ -132,13 +136,13 @@ await this.dispatchPipeline.RunAsync(dispatchContext, async _ => } catch (TaskFailureException e) { - TraceHelper.TraceExceptionInstance(TraceEventType.Error, taskMessage.OrchestrationInstance, e); + TraceHelper.TraceExceptionInstance(TraceEventType.Error, "TaskActivityDispatcher-ProcessTaskFailure", taskMessage.OrchestrationInstance, e); string details = IncludeDetails ? e.Details : null; eventToRespond = new TaskFailedEvent(-1, scheduledEvent.EventId, e.Message, details); } catch (Exception e) when (!Utils.IsFatal(e)) { - TraceHelper.TraceExceptionInstance(TraceEventType.Error, taskMessage.OrchestrationInstance, e); + TraceHelper.TraceExceptionInstance(TraceEventType.Error, "TaskActivityDispatcher-ProcessException", taskMessage.OrchestrationInstance, e); string details = IncludeDetails ? $"Unhandled exception while executing task: {e}\n\t{e.StackTrace}" : null; @@ -192,16 +196,16 @@ async void RenewUntil(TaskActivityWorkItem workItem, CancellationToken cancellat try { - TraceHelper.Trace(TraceEventType.Information, "Renewing lock for workitem id {0}", workItem.Id); + TraceHelper.Trace(TraceEventType.Information, "TaskActivityDispatcher-RenewLock", "Renewing lock for workitem id {0}", workItem.Id); workItem = await this.orchestrationService.RenewTaskActivityWorkItemLockAsync(workItem); renewAt = workItem.LockedUntilUtc.Subtract(TimeSpan.FromSeconds(30)); renewAt = AdjustRenewAt(renewAt); - TraceHelper.Trace(TraceEventType.Information, "Next renew for workitem id '{0}' at '{1}'", workItem.Id, renewAt); + TraceHelper.Trace(TraceEventType.Information, "TaskActivityDispatcher-RenewLockAt", "Next renew for workitem id '{0}' at '{1}'", workItem.Id, renewAt); } catch (Exception exception) when (!Utils.IsFatal(exception)) { // might have been completed - TraceHelper.TraceException(TraceEventType.Warning, exception, "Failed to renew lock for workitem {0}", workItem.Id); + TraceHelper.TraceException(TraceEventType.Warning, "TaskActivityDispatcher-RenewLockFailure", exception, "Failed to renew lock for workitem {0}", workItem.Id); break; } } diff --git a/src/DurableTask.Core/TaskOrchestrationContext.cs b/src/DurableTask.Core/TaskOrchestrationContext.cs index 1bbc469c6..02afb9d12 100644 --- a/src/DurableTask.Core/TaskOrchestrationContext.cs +++ b/src/DurableTask.Core/TaskOrchestrationContext.cs @@ -365,6 +365,7 @@ private void LogDuplicateEvent(string source, HistoryEvent historyEvent, int tas { TraceHelper.TraceSession( TraceEventType.Warning, + "TaskOrchestrationContext-DuplicateEvent", this.OrchestrationInstance.InstanceId, "Duplicate {0} Event: {1}, type: {2}, ts: {3}", source, diff --git a/src/DurableTask.Core/TaskOrchestrationDispatcher.cs b/src/DurableTask.Core/TaskOrchestrationDispatcher.cs index 096824976..942cad3f9 100644 --- a/src/DurableTask.Core/TaskOrchestrationDispatcher.cs +++ b/src/DurableTask.Core/TaskOrchestrationDispatcher.cs @@ -122,7 +122,10 @@ protected async Task OnProcessWorkItemAsync(TaskOrchestrationWorkItem workItem) if (!ReconcileMessagesWithState(workItem)) { // TODO : mark an orchestration as faulted if there is data corruption - TraceHelper.TraceSession(TraceEventType.Error, runtimeState.OrchestrationInstance?.InstanceId, + TraceHelper.TraceSession( + TraceEventType.Error, + "TaskOrchestrationDispatcher-DeletedOrchestration", + runtimeState.OrchestrationInstance?.InstanceId, "Received result for a deleted orchestration"); isCompleted = true; } @@ -130,13 +133,16 @@ protected async Task OnProcessWorkItemAsync(TaskOrchestrationWorkItem workItem) { TraceHelper.TraceInstance( TraceEventType.Verbose, + "TaskOrchestrationDispatcher-ExecuteUserOrchestration-Begin", runtimeState.OrchestrationInstance, "Executing user orchestration: {0}", DataConverter.Serialize(runtimeState.GetOrchestrationRuntimeStateDump(), true)); IList decisions = (await ExecuteOrchestrationAsync(runtimeState)).ToList(); - TraceHelper.TraceInstance(TraceEventType.Information, + TraceHelper.TraceInstance( + TraceEventType.Information, + "TaskOrchestrationDispatcher-ExecuteUserOrchestration-End", runtimeState.OrchestrationInstance, "Executed user orchestration. Received {0} orchestrator actions: {1}", decisions.Count(), @@ -144,8 +150,12 @@ protected async Task OnProcessWorkItemAsync(TaskOrchestrationWorkItem workItem) foreach (OrchestratorAction decision in decisions) { - TraceHelper.TraceInstance(TraceEventType.Information, runtimeState.OrchestrationInstance, - "Processing orchestrator action of type {0}", decision.OrchestratorActionType); + TraceHelper.TraceInstance( + TraceEventType.Information, + "TaskOrchestrationDispatcher-ProcessOrchestratorAction", + runtimeState.OrchestrationInstance, + "Processing orchestrator action of type {0}", + decision.OrchestratorActionType); switch (decision.OrchestratorActionType) { case OrchestratorActionType.ScheduleOrchestrator: @@ -184,7 +194,9 @@ protected async Task OnProcessWorkItemAsync(TaskOrchestrationWorkItem workItem) isCompleted = !continuedAsNew; break; default: - throw TraceHelper.TraceExceptionInstance(TraceEventType.Error, + throw TraceHelper.TraceExceptionInstance( + TraceEventType.Error, + "TaskOrchestrationDispatcher-UnsupportedDecisionType", runtimeState.OrchestrationInstance, new NotSupportedException("decision type not supported")); } @@ -196,12 +208,18 @@ protected async Task OnProcessWorkItemAsync(TaskOrchestrationWorkItem workItem) int totalMessages = messagesToSend.Count + subOrchestrationMessages.Count + timerMessages.Count; if (this.orchestrationService.IsMaxMessageCountExceeded(totalMessages, runtimeState)) { - TraceHelper.TraceInstance(TraceEventType.Information, runtimeState.OrchestrationInstance, + TraceHelper.TraceInstance( + TraceEventType.Information, + "TaskOrchestrationDispatcher-MaxMessageCountReached", + runtimeState.OrchestrationInstance, "MaxMessageCount reached. Adding timer to process remaining events in next attempt."); if (isCompleted || continuedAsNew) { - TraceHelper.TraceInstance(TraceEventType.Information, runtimeState.OrchestrationInstance, + TraceHelper.TraceInstance( + TraceEventType.Information, + "TaskOrchestrationDispatcher-OrchestrationAlreadyCompleted", + runtimeState.OrchestrationInstance, "Orchestration already completed. Skip adding timer for splitting messages."); break; } @@ -230,7 +248,7 @@ protected async Task OnProcessWorkItemAsync(TaskOrchestrationWorkItem workItem) if (isCompleted) { - TraceHelper.TraceSession(TraceEventType.Information, workItem.InstanceId, "Deleting session state"); + TraceHelper.TraceSession(TraceEventType.Information, "TaskOrchestrationDispatcher-DeletingSessionState", workItem.InstanceId, "Deleting session state"); if (newOrchestrationRuntimeState.ExecutionStartedEvent != null) { instanceState = Utils.BuildOrchestrationState(newOrchestrationRuntimeState); @@ -244,7 +262,10 @@ protected async Task OnProcessWorkItemAsync(TaskOrchestrationWorkItem workItem) if (continuedAsNew) { - TraceHelper.TraceSession(TraceEventType.Information, workItem.InstanceId, + TraceHelper.TraceSession( + TraceEventType.Information, + "TaskOrchestrationDispatcher-UpdatingStateForContinuation", + workItem.InstanceId, "Updating state for continuation"); newOrchestrationRuntimeState = new OrchestrationRuntimeState(); newOrchestrationRuntimeState.AddEvent(new OrchestratorStartedEvent(-1)); @@ -268,7 +289,10 @@ async Task> ExecuteOrchestrationAsync(Orchestrat TaskOrchestration taskOrchestration = objectManager.GetObject(runtimeState.Name, runtimeState.Version); if (taskOrchestration == null) { - throw TraceHelper.TraceExceptionInstance(TraceEventType.Error, runtimeState.OrchestrationInstance, + throw TraceHelper.TraceExceptionInstance( + TraceEventType.Error, + "TaskOrchestrationDispatcher-TypeMissing", + runtimeState.OrchestrationInstance, new TypeMissingException($"Orchestration not found: ({runtimeState.Name}, {runtimeState.Version})")); } @@ -296,7 +320,9 @@ bool ReconcileMessagesWithState(TaskOrchestrationWorkItem workItem) OrchestrationInstance orchestrationInstance = message.OrchestrationInstance; if (string.IsNullOrWhiteSpace(orchestrationInstance?.InstanceId)) { - throw TraceHelper.TraceException(TraceEventType.Error, + throw TraceHelper.TraceException( + TraceEventType.Error, + "TaskOrchestrationDispatcher-OrchestrationInstanceMissing", new InvalidOperationException("Message does not contain any OrchestrationInstance information")); } @@ -308,8 +334,12 @@ bool ReconcileMessagesWithState(TaskOrchestrationWorkItem workItem) return false; } - TraceHelper.TraceInstance(TraceEventType.Information, orchestrationInstance, - "Processing new event with Id {0} and type {1}", message.Event.EventId, + TraceHelper.TraceInstance( + TraceEventType.Information, + "TaskOrchestrationDispatcher-ProcessEvent", + orchestrationInstance, + "Processing new event with Id {0} and type {1}", + message.Event.EventId, message.Event.EventType); if (message.Event.EventType == EventType.ExecutionStarted) @@ -317,9 +347,13 @@ bool ReconcileMessagesWithState(TaskOrchestrationWorkItem workItem) if (workItem.OrchestrationRuntimeState.Events.Count > 1) { // this was caused due to a dupe execution started event, swallow this one - TraceHelper.TraceInstance(TraceEventType.Warning, orchestrationInstance, + TraceHelper.TraceInstance( + TraceEventType.Warning, + "TaskOrchestrationDispatcher-DuplicateStartEvent", + orchestrationInstance, "Duplicate start event. Ignoring event with Id {0} and type {1} ", - message.Event.EventId, message.Event.EventType); + message.Event.EventId, + message.Event.EventType); continue; } } @@ -329,9 +363,13 @@ bool ReconcileMessagesWithState(TaskOrchestrationWorkItem workItem) workItem.OrchestrationRuntimeState.OrchestrationInstance.ExecutionId)) { // eat up any events for previous executions - TraceHelper.TraceInstance(TraceEventType.Warning, orchestrationInstance, + TraceHelper.TraceInstance( + TraceEventType.Warning, + "TaskOrchestrationDispatcher-ExecutionIdMismatch", + orchestrationInstance, "ExecutionId of event does not match current executionId. Ignoring event with Id {0} and type {1} ", - message.Event.EventId, message.Event.EventType); + message.Event.EventId, + message.Event.EventType); continue; } @@ -363,11 +401,18 @@ static TaskMessage ProcessWorkflowCompletedTaskDecision( runtimeState.AddEvent(executionCompletedEvent); - TraceHelper.TraceInstance(runtimeState.OrchestrationStatus == OrchestrationStatus.Failed ? TraceEventType.Warning : TraceEventType.Information, + TraceHelper.TraceInstance( + runtimeState.OrchestrationStatus == OrchestrationStatus.Failed ? TraceEventType.Warning : TraceEventType.Information, + "TaskOrchestrationDispatcher-InstanceCompleted", runtimeState.OrchestrationInstance, "Instance Id '{0}' completed in state {1} with result: {2}", - runtimeState.OrchestrationInstance, runtimeState.OrchestrationStatus, completeOrchestratorAction.Result); - TraceHelper.TraceInstance(TraceEventType.Information, runtimeState.OrchestrationInstance, + runtimeState.OrchestrationInstance, + runtimeState.OrchestrationStatus, + completeOrchestratorAction.Result); + TraceHelper.TraceInstance( + TraceEventType.Information, + "TaskOrchestrationDispatcher-InstanceCompletionEvents", + runtimeState.OrchestrationInstance, () => Utils.EscapeJson(DataConverter.Serialize(runtimeState.Events, true))); // Check to see if we need to start a new execution diff --git a/src/DurableTask.Core/Tracing/DefaultEventSource.cs b/src/DurableTask.Core/Tracing/DefaultEventSource.cs index 044a994f1..56ec132aa 100644 --- a/src/DurableTask.Core/Tracing/DefaultEventSource.cs +++ b/src/DurableTask.Core/Tracing/DefaultEventSource.cs @@ -33,8 +33,14 @@ public class DefaultEventSource : EventSource const int ErrorEventId = 5; const int CriticalEventId = 6; - internal static class Keywords + /// + /// EventKeywords for the event source + /// + public static class Keywords { + /// + /// Diagnostic keyword + /// public const EventKeywords Diagnostics = (EventKeywords)1L; } @@ -69,45 +75,45 @@ internal static class Keywords /// /// Gets whether informational logs are enabled /// - public bool IsInfoEnabled => this.IsEnabled(EventLevel.Informational, EventKeywords.None); + public bool IsInfoEnabled => this.IsEnabled(EventLevel.Informational, Keywords.Diagnostics); /// /// Gets whether warning logs are enabled /// - public bool IsWarningEnabled => this.IsEnabled(EventLevel.Warning, EventKeywords.None); + public bool IsWarningEnabled => this.IsEnabled(EventLevel.Warning, Keywords.Diagnostics); /// /// Gets whether error logs are enabled /// - public bool IsErrorEnabled => this.IsEnabled(EventLevel.Error, EventKeywords.None); + public bool IsErrorEnabled => this.IsEnabled(EventLevel.Error, Keywords.Diagnostics); /// /// Gets whether critical logs are enabled /// - public bool IsCriticalEnabled => this.IsEnabled(EventLevel.Critical, EventKeywords.None); + public bool IsCriticalEnabled => this.IsEnabled(EventLevel.Critical, Keywords.Diagnostics); /// /// Trace an event for the supplied eventtype and parameters /// [NonEvent] - public void TraceEvent(TraceEventType eventType, string source, string instanceId, string executionId, string sessionId, string message) + public void TraceEvent(TraceEventType eventLevel, string source, string instanceId, string executionId, string sessionId, string message, string eventType) { - switch (eventType) + switch (eventLevel) { case TraceEventType.Critical: - this.Critical(source, instanceId, executionId, sessionId, message); + this.Critical(source, instanceId, executionId, sessionId, message, eventType); break; case TraceEventType.Error: - this.Error(source, instanceId, executionId, sessionId, message); + this.Error(source, instanceId, executionId, sessionId, message, eventType); break; case TraceEventType.Warning: - this.Warning(source, instanceId, executionId, sessionId, message); + this.Warning(source, instanceId, executionId, sessionId, message, eventType); break; case TraceEventType.Information: - this.Info(source, instanceId, executionId, sessionId, message); + this.Info(source, instanceId, executionId, sessionId, message, eventType); break; default: - this.Trace(source, instanceId, executionId, sessionId, message); + this.Trace(source, instanceId, executionId, sessionId, message, eventType); break; } } @@ -116,32 +122,32 @@ public void TraceEvent(TraceEventType eventType, string source, string instanceI /// Trace an event for the supplied eventtype, exception and parameters /// [NonEvent] - public void TraceEvent(TraceEventType eventType, string source, string instanceId, string executionId, string sessionId, Exception exception) => - this.TraceEvent(eventType, source, instanceId, executionId, sessionId, exception?.ToString() ?? string.Empty); + public void TraceEvent(TraceEventType eventLevel, string source, string instanceId, string executionId, string sessionId, Exception exception, string eventType) => + this.TraceEvent(eventLevel, source, instanceId, executionId, sessionId, exception?.ToString() ?? string.Empty, eventType); /// /// Trace an event for the supplied parameters /// [NonEvent] - public void Trace(string source, string instanceId, string executionId, string sessionId, string message) => - this.Trace(source, instanceId, executionId, sessionId, message, string.Empty); + public void Trace(string source, string instanceId, string executionId, string sessionId, string message, string eventType) => + this.Trace(source, instanceId, executionId, sessionId, message, string.Empty, eventType); /// /// Trace an event for the supplied exception and parameters /// [NonEvent] - public void Trace(string source, string instanceId, string executionId, string sessionId, string message, Exception exception) => - this.Trace(source, instanceId, executionId, sessionId, message, exception?.ToString() ?? string.Empty); + public void Trace(string source, string instanceId, string executionId, string sessionId, string message, Exception exception, string eventType) => + this.Trace(source, instanceId, executionId, sessionId, message, exception?.ToString() ?? string.Empty, eventType); /// /// Trace an event for the supplied parameters /// - [Event(TraceEventId, Level = EventLevel.Verbose, Keywords = Keywords.Diagnostics, Version = 2)] - public void Trace(string source, string instanceId, string executionId, string sessionId, string message, string info) + [Event(TraceEventId, Level = EventLevel.Verbose, Keywords = Keywords.Diagnostics, Version = 3)] + public void Trace(string source, string instanceId, string executionId, string sessionId, string message, string info, string eventType) { if (this.IsTraceEnabled) { - this.WriteEventInternal(TraceEventId, source, instanceId, executionId, sessionId, message, info); + this.WriteEventInternal(TraceEventId, source, instanceId, executionId, sessionId, message, info, eventType); } } @@ -149,25 +155,25 @@ public void Trace(string source, string instanceId, string executionId, string s /// Log debug event for the supplied parameters /// [NonEvent] - public void Debug(string source, string instanceId, string executionId, string sessionId, string message) => - this.Debug(source, instanceId, executionId, sessionId, message, string.Empty); + public void Debug(string source, string instanceId, string executionId, string sessionId, string message, string eventType) => + this.Debug(source, instanceId, executionId, sessionId, message, string.Empty, eventType); /// /// Log debug event for the supplied exception and parameters /// [NonEvent] - public void Debug(string source, string instanceId, string executionId, string sessionId, string message, Exception exception) => - this.Debug(source, instanceId, executionId, sessionId, message, exception?.ToString() ?? string.Empty); + public void Debug(string source, string instanceId, string executionId, string sessionId, string message, Exception exception, string eventType) => + this.Debug(source, instanceId, executionId, sessionId, message, exception?.ToString() ?? string.Empty, eventType); /// /// Log debug event for the supplied parameters /// - [Event(DebugEventId, Level = EventLevel.Verbose, Keywords = Keywords.Diagnostics, Version = 2)] - public void Debug(string source, string instanceId, string executionId, string sessionId, string message, string info) + [Event(DebugEventId, Level = EventLevel.Verbose, Keywords = Keywords.Diagnostics, Version = 3)] + public void Debug(string source, string instanceId, string executionId, string sessionId, string message, string info, string eventType) { if (this.IsDebugEnabled) { - this.WriteEventInternal(DebugEventId, source, instanceId, executionId, sessionId, message, info); + this.WriteEventInternal(DebugEventId, source, instanceId, executionId, sessionId, message, info, eventType); } } @@ -175,25 +181,25 @@ public void Debug(string source, string instanceId, string executionId, string s /// Log informational event for the supplied parameters /// [NonEvent] - public void Info(string source, string instanceId, string executionId, string sessionId, string message) => - this.Info(source, instanceId, executionId, sessionId, message, string.Empty); + public void Info(string source, string instanceId, string executionId, string sessionId, string message, string eventType) => + this.Info(source, instanceId, executionId, sessionId, message, string.Empty, eventType); /// /// Log informational event for the supplied exception and parameters /// [NonEvent] - public void Info(string source, string instanceId, string executionId, string sessionId, string message, Exception exception) => - this.Info(source, instanceId, executionId, sessionId, message, exception?.ToString() ?? string.Empty); + public void Info(string source, string instanceId, string executionId, string sessionId, string message, Exception exception, string eventType) => + this.Info(source, instanceId, executionId, sessionId, message, exception?.ToString() ?? string.Empty, eventType); /// /// Log informational event for the supplied parameters /// - [Event(InfoEventId, Level = EventLevel.Informational, Keywords = EventKeywords.None, Version = 2)] - public void Info(string source, string instanceId, string executionId, string sessionId, string message, string info) + [Event(InfoEventId, Level = EventLevel.Informational, Keywords = Keywords.Diagnostics, Version = 3)] + public void Info(string source, string instanceId, string executionId, string sessionId, string message, string info, string eventType) { if (this.IsInfoEnabled) { - this.WriteEventInternal(InfoEventId, source, instanceId, executionId, sessionId, message, info); + this.WriteEventInternal(InfoEventId, source, instanceId, executionId, sessionId, message, info, eventType); } } @@ -201,25 +207,25 @@ public void Info(string source, string instanceId, string executionId, string se /// Log warning event for the supplied parameters /// [NonEvent] - public void Warning(string source, string instanceId, string executionId, string sessionId, string message) => - this.Warning(source, instanceId, executionId, sessionId, message, string.Empty); + public void Warning(string source, string instanceId, string executionId, string sessionId, string message, string eventType) => + this.Warning(source, instanceId, executionId, sessionId, message, string.Empty, eventType); /// /// Log warning event for the supplied exception and parameters /// [NonEvent] - public void Warning(string source, string instanceId, string executionId, string sessionId, string message, Exception exception) => - this.Warning(source, instanceId, executionId, sessionId, message, exception?.ToString() ?? string.Empty); + public void Warning(string source, string instanceId, string executionId, string sessionId, string message, Exception exception, string eventType) => + this.Warning(source, instanceId, executionId, sessionId, message, exception?.ToString() ?? string.Empty, eventType); /// /// Log warning event for the supplied parameters /// - [Event(WarningEventId, Level = EventLevel.Warning, Keywords = EventKeywords.None, Version = 2)] - public void Warning(string source, string instanceId, string executionId, string sessionId, string message, string exception) + [Event(WarningEventId, Level = EventLevel.Warning, Keywords = Keywords.Diagnostics, Version = 3)] + public void Warning(string source, string instanceId, string executionId, string sessionId, string message, string exception, string eventType) { if (this.IsWarningEnabled) { - this.WriteEventInternal(WarningEventId, source, instanceId, executionId, sessionId, message, exception); + this.WriteEventInternal(WarningEventId, source, instanceId, executionId, sessionId, message, exception, eventType); } } @@ -227,25 +233,25 @@ public void Warning(string source, string instanceId, string executionId, string /// Log error event for the supplied parameters /// [NonEvent] - public void Error(string source, string instanceId, string executionId, string sessionId, string message) => - this.Error(source, instanceId, executionId, sessionId, message, string.Empty); + public void Error(string source, string instanceId, string executionId, string sessionId, string message, string eventType) => + this.Error(source, instanceId, executionId, sessionId, message, string.Empty, eventType); /// /// Log error event for the supplied exception and parameters /// [NonEvent] - public void Error(string source, string instanceId, string executionId, string sessionId, string message, Exception exception) => - this.Error(source, instanceId, executionId, sessionId, message, exception?.ToString() ?? string.Empty); + public void Error(string source, string instanceId, string executionId, string sessionId, string message, Exception exception, string eventType) => + this.Error(source, instanceId, executionId, sessionId, message, exception?.ToString() ?? string.Empty, eventType); /// /// Log error event for the supplied parameters /// - [Event(ErrorEventId, Level = EventLevel.Error, Keywords = EventKeywords.None, Version = 2)] - public void Error(string source, string instanceId, string executionId, string sessionId, string message, string exception) + [Event(ErrorEventId, Level = EventLevel.Error, Keywords = Keywords.Diagnostics, Version = 3)] + public void Error(string source, string instanceId, string executionId, string sessionId, string message, string exception, string eventType) { if (this.IsErrorEnabled) { - this.WriteEventInternal(ErrorEventId, source, instanceId, executionId, sessionId, message, exception); + this.WriteEventInternal(ErrorEventId, source, instanceId, executionId, sessionId, message, exception, eventType); } } @@ -253,30 +259,30 @@ public void Error(string source, string instanceId, string executionId, string s /// Log critical event for the supplied parameters /// [NonEvent] - public void Critical(string source, string instanceId, string executionId, string sessionId, string message) => - this.Critical(source, instanceId, executionId, sessionId, message, string.Empty); + public void Critical(string source, string instanceId, string executionId, string sessionId, string message, string eventType) => + this.Critical(source, instanceId, executionId, sessionId, message, string.Empty, eventType); /// /// Log critical event for the supplied exception and parameters /// [NonEvent] - public void Critical(string source, string instanceId, string executionId, string sessionId, string message, Exception exception) => - this.Critical(source, instanceId, executionId, sessionId, message, exception?.ToString() ?? string.Empty); + public void Critical(string source, string instanceId, string executionId, string sessionId, string message, Exception exception, string eventType) => + this.Critical(source, instanceId, executionId, sessionId, message, exception?.ToString() ?? string.Empty, eventType); /// /// Log critical event for the supplied parameters /// - [Event(CriticalEventId, Level = EventLevel.Critical, Keywords = EventKeywords.None, Version = 2)] - public void Critical(string source, string instanceId, string executionId, string sessionId, string message, string exception) + [Event(CriticalEventId, Level = EventLevel.Critical, Keywords = Keywords.Diagnostics, Version = 3)] + public void Critical(string source, string instanceId, string executionId, string sessionId, string message, string exception, string eventType) { if (this.IsCriticalEnabled) { - this.WriteEventInternal(CriticalEventId, source, instanceId, executionId, sessionId, message, exception); + this.WriteEventInternal(CriticalEventId, source, instanceId, executionId, sessionId, message, exception, eventType); } } [NonEvent] - unsafe void WriteEventInternal(int eventId, string source, string instanceId, string executionId, string sessionId, string message, string info) + unsafe void WriteEventInternal(int eventId, string source, string instanceId, string executionId, string sessionId, string message, string info, string eventType) { source = string.Concat(source, '-', this.processName); @@ -286,14 +292,16 @@ unsafe void WriteEventInternal(int eventId, string source, string instanceId, st MakeSafe(ref sessionId); MakeSafe(ref message); MakeSafe(ref info); + MakeSafe(ref eventType); - const int EventDataCount = 6; + const int EventDataCount = 7; fixed (char* chPtrSource = source) fixed (char* chPtrInstanceId = instanceId) fixed (char* chPtrExecutionId = executionId) fixed (char* chPtrSessionId = sessionId) fixed (char* chPtrMessage = message) fixed (char* chPtrInfo = info) + fixed (char* chPtrEventType = eventType) { EventData* data = stackalloc EventData[EventDataCount]; data[0].DataPointer = (IntPtr)chPtrSource; @@ -308,6 +316,8 @@ unsafe void WriteEventInternal(int eventId, string source, string instanceId, st data[4].Size = (message.Length + 1) * 2; data[5].DataPointer = (IntPtr)chPtrInfo; data[5].Size = (info.Length + 1) * 2; + data[6].DataPointer = (IntPtr)chPtrEventType; + data[6].Size = (eventType.Length + 1) * 2; // todo: use WriteEventWithRelatedActivityIdCore for correlation this.WriteEventCore(eventId, EventDataCount, data); diff --git a/src/DurableTask.Core/Tracing/TraceHelper.cs b/src/DurableTask.Core/Tracing/TraceHelper.cs index 03824c2b1..2324fd1a8 100644 --- a/src/DurableTask.Core/Tracing/TraceHelper.cs +++ b/src/DurableTask.Core/Tracing/TraceHelper.cs @@ -28,155 +28,157 @@ public class TraceHelper /// /// Simple trace with no iid or eid /// - public static void Trace(TraceEventType eventType, Func generateMessage) + public static void Trace(TraceEventType eventLevel, string eventType, Func generateMessage) { ExceptionHandlingWrapper( - () => DefaultEventSource.Log.TraceEvent(eventType, Source, string.Empty, string.Empty, string.Empty, generateMessage())); + () => DefaultEventSource.Log.TraceEvent(eventLevel, Source, string.Empty, string.Empty, string.Empty, generateMessage(), eventType)); } /// /// Simple trace with no iid or eid /// - public static void Trace(TraceEventType eventType, string format, params object[] args) + public static void Trace(TraceEventType eventLevel, string eventType, string format, params object[] args) { ExceptionHandlingWrapper( - () => DefaultEventSource.Log.TraceEvent(eventType, Source, string.Empty, string.Empty, string.Empty, FormatString(format, args))); + () => DefaultEventSource.Log.TraceEvent(eventLevel, Source, string.Empty, string.Empty, string.Empty, FormatString(format, args), eventType)); } /// /// Trace with iid but no eid /// - public static void TraceSession(TraceEventType eventType, string sessionId, Func generateMessage) + public static void TraceSession(TraceEventType eventLevel, string eventType, string sessionId, Func generateMessage) { ExceptionHandlingWrapper( - () => DefaultEventSource.Log.TraceEvent(eventType, Source, string.Empty, string.Empty, sessionId, generateMessage())); + () => DefaultEventSource.Log.TraceEvent(eventLevel, Source, string.Empty, string.Empty, sessionId, generateMessage(), eventType)); } /// /// Trace with iid but no eid /// - public static void TraceSession(TraceEventType eventType, string sessionId, string format, params object[] args) + public static void TraceSession(TraceEventType eventLevel, string eventType, string sessionId, string format, params object[] args) { ExceptionHandlingWrapper( - () => DefaultEventSource.Log.TraceEvent(eventType, Source, string.Empty, string.Empty, sessionId, FormatString(format, args))); + () => DefaultEventSource.Log.TraceEvent(eventLevel, Source, string.Empty, string.Empty, sessionId, FormatString(format, args), eventType)); } /// /// Trace with iid and eid /// - public static void TraceInstance(TraceEventType eventType, OrchestrationInstance orchestrationInstance, + public static void TraceInstance(TraceEventType eventLevel, string eventType, OrchestrationInstance orchestrationInstance, string format, params object[] args) { ExceptionHandlingWrapper( () => DefaultEventSource.Log.TraceEvent( - eventType, + eventLevel, Source, orchestrationInstance == null ? string.Empty : orchestrationInstance.InstanceId, orchestrationInstance == null ? string.Empty : orchestrationInstance.ExecutionId, string.Empty, - FormatString(format, args))); + FormatString(format, args), + eventType)); } /// /// Trace with iid and eid /// - public static void TraceInstance(TraceEventType eventType, OrchestrationInstance orchestrationInstance, + public static void TraceInstance(TraceEventType eventLevel, string eventType, OrchestrationInstance orchestrationInstance, Func generateMessage) { ExceptionHandlingWrapper( () => DefaultEventSource.Log.TraceEvent( - eventType, + eventLevel, Source, orchestrationInstance == null ? string.Empty : orchestrationInstance.InstanceId, orchestrationInstance == null ? string.Empty : orchestrationInstance.ExecutionId, string.Empty, - generateMessage())); + generateMessage(), + eventType)); } /// /// Trace an exception /// - public static Exception TraceException(TraceEventType eventType, Exception exception) + public static Exception TraceException(TraceEventType eventLevel, string eventType, Exception exception) { - return TraceException(eventType, exception, string.Empty); + return TraceException(eventLevel, eventType, exception, string.Empty); } /// /// Trace an exception and message /// - public static Exception TraceException(TraceEventType eventType, Exception exception, + public static Exception TraceException(TraceEventType eventLevel, string eventType, Exception exception, Func generateMessage) { - return TraceExceptionCore(eventType, string.Empty, string.Empty, exception, generateMessage); + return TraceExceptionCore(eventLevel, eventType, string.Empty, string.Empty, exception, generateMessage); } /// /// Trace an exception and message /// - public static Exception TraceException(TraceEventType eventType, Exception exception, string format, + public static Exception TraceException(TraceEventType eventLevel, string eventType, Exception exception, string format, params object[] args) { - return TraceExceptionCore(eventType, string.Empty, string.Empty, exception, format, args); + return TraceExceptionCore(eventLevel, eventType, string.Empty, string.Empty, exception, format, args); } /// /// Trace an instance exception /// - public static Exception TraceExceptionInstance(TraceEventType eventType, + public static Exception TraceExceptionInstance(TraceEventType eventLevel, string eventType, OrchestrationInstance orchestrationInstance, Exception exception) { - return TraceExceptionCore(eventType, orchestrationInstance.InstanceId, orchestrationInstance.ExecutionId, + return TraceExceptionCore(eventLevel, eventType, orchestrationInstance.InstanceId, orchestrationInstance.ExecutionId, exception, string.Empty); } /// /// Trace an instance exception and message /// - public static Exception TraceExceptionInstance(TraceEventType eventType, + public static Exception TraceExceptionInstance(TraceEventType eventLevel, string eventType, OrchestrationInstance orchestrationInstance, Exception exception, Func generateMessage) { - return TraceExceptionCore(eventType, orchestrationInstance.InstanceId, orchestrationInstance.ExecutionId, + return TraceExceptionCore(eventLevel, eventType, orchestrationInstance.InstanceId, orchestrationInstance.ExecutionId, exception, generateMessage); } /// /// Trace an instance exception and message /// - public static Exception TraceExceptionInstance(TraceEventType eventType, + public static Exception TraceExceptionInstance(TraceEventType eventLevel, string eventType, OrchestrationInstance orchestrationInstance, Exception exception, string format, params object[] args) { - return TraceExceptionCore(eventType, orchestrationInstance.InstanceId, orchestrationInstance.ExecutionId, + return TraceExceptionCore(eventLevel, eventType, orchestrationInstance.InstanceId, orchestrationInstance.ExecutionId, exception, format, args); } /// /// Trace a session exception without execution id /// - public static Exception TraceExceptionSession(TraceEventType eventType, string sessionId, Exception exception) + public static Exception TraceExceptionSession(TraceEventType eventLevel, string eventType, string sessionId, Exception exception) { - return TraceExceptionCore(eventType, sessionId, string.Empty, exception, string.Empty); + return TraceExceptionCore(eventLevel, eventType, sessionId, string.Empty, exception, string.Empty); } /// /// Trace a session exception and message without execution id /// - public static Exception TraceExceptionSession(TraceEventType eventType, string sessionId, Exception exception, + public static Exception TraceExceptionSession(TraceEventType eventLevel, string eventType, string sessionId, Exception exception, Func generateMessage) { - return TraceExceptionCore(eventType, sessionId, string.Empty, exception, generateMessage); + return TraceExceptionCore(eventLevel, eventType, sessionId, string.Empty, exception, generateMessage); } /// /// Trace a session exception and message without execution id /// - public static Exception TraceExceptionSession(TraceEventType eventType, string sessionId, Exception exception, + public static Exception TraceExceptionSession(TraceEventType eventLevel, string eventType, string sessionId, Exception exception, string format, params object[] args) { - return TraceExceptionCore(eventType, sessionId, string.Empty, exception, format, args); + return TraceExceptionCore(eventLevel, eventType, sessionId, string.Empty, exception, format, args); } // helper methods - static Exception TraceExceptionCore(TraceEventType eventType, string iid, string eid, Exception exception, + static Exception TraceExceptionCore(TraceEventType eventLevel, string eventType, string iid, string eid, Exception exception, string format, params object[] args) { string newFormat = format + "\nException: " + exception.GetType() + " : " + exception.Message + "\n\t" + @@ -184,12 +186,12 @@ static Exception TraceExceptionCore(TraceEventType eventType, string iid, string exception.InnerException?.ToString(); ExceptionHandlingWrapper( - () => DefaultEventSource.Log.TraceEvent(eventType, Source, iid, eid, string.Empty, FormatString(newFormat, args))); + () => DefaultEventSource.Log.TraceEvent(eventLevel, Source, iid, eid, string.Empty, FormatString(newFormat, args), eventType)); return exception; } - static Exception TraceExceptionCore(TraceEventType eventType, string iid, string eid, Exception exception, + static Exception TraceExceptionCore(TraceEventType eventLevel, string eventType, string iid, string eid, Exception exception, Func generateMessage) { string newFormat = generateMessage() + "\nException: " + exception.GetType() + " : " + exception.Message + @@ -197,7 +199,7 @@ static Exception TraceExceptionCore(TraceEventType eventType, string iid, string exception.InnerException?.ToString(); ExceptionHandlingWrapper( - () => DefaultEventSource.Log.TraceEvent(eventType, Source, iid, eid, string.Empty, newFormat)); + () => DefaultEventSource.Log.TraceEvent(eventLevel, Source, iid, eid, string.Empty, newFormat, eventType)); return exception; } @@ -216,7 +218,7 @@ static string FormatString(string formatted, params object[] args) catch (FormatException ex) { string message = string.Format(CultureInfo.InvariantCulture, "String FormatException for '{0}'. Args count: {1}. Exception: {2}", formatted, args.Length, ex); - DefaultEventSource.Log.TraceEvent(TraceEventType.Error, Source, string.Empty, string.Empty, string.Empty, message); + DefaultEventSource.Log.TraceEvent(TraceEventType.Error, Source, string.Empty, string.Empty, string.Empty, message, "LogFormattingFailed"); return formatted; } @@ -232,7 +234,7 @@ static void ExceptionHandlingWrapper(Action innerFunc) { try { - DefaultEventSource.Log.TraceEvent(TraceEventType.Error, Source, string.Empty, string.Empty, string.Empty, exception); + DefaultEventSource.Log.TraceEvent(TraceEventType.Error, Source, string.Empty, string.Empty, string.Empty, exception, "WriteEventFailed"); } catch (Exception anotherException) when (!Utils.IsFatal(anotherException)) { diff --git a/src/DurableTask.Core/WorkItemDispatcher.cs b/src/DurableTask.Core/WorkItemDispatcher.cs index c1a366d6d..47b37e6f1 100644 --- a/src/DurableTask.Core/WorkItemDispatcher.cs +++ b/src/DurableTask.Core/WorkItemDispatcher.cs @@ -19,7 +19,7 @@ namespace DurableTask.Core using System.Threading.Tasks; using DurableTask.Core.Common; using DurableTask.Core.Exceptions; - using Tracing; + using DurableTask.Core.Tracing; /// /// Dispatcher class for fetching and processing work items of the supplied type @@ -94,26 +94,11 @@ public WorkItemDispatcher( Func processWorkItem ) { - if (workItemIdentifier == null) - { - throw new ArgumentNullException(nameof(workItemIdentifier)); - } - - if (fetchWorkItem == null) - { - throw new ArgumentNullException(nameof(fetchWorkItem)); - } - - if (processWorkItem == null) - { - throw new ArgumentNullException(nameof(processWorkItem)); - } - this.name = name; id = Guid.NewGuid().ToString("N"); - this.workItemIdentifier = workItemIdentifier; - this.FetchWorkItem = fetchWorkItem; - this.ProcessWorkItem = processWorkItem; + this.workItemIdentifier = workItemIdentifier ?? throw new ArgumentNullException(nameof(workItemIdentifier)); + this.FetchWorkItem = fetchWorkItem ?? throw new ArgumentNullException(nameof(fetchWorkItem)); + this.ProcessWorkItem = processWorkItem ?? throw new ArgumentNullException(nameof(processWorkItem)); } /// @@ -129,12 +114,12 @@ public async Task StartAsync() { if (isStarted) { - throw TraceHelper.TraceException(TraceEventType.Error, new InvalidOperationException($"WorkItemDispatcher '{name}' has already started")); + throw TraceHelper.TraceException(TraceEventType.Error, "WorkItemDispatcherStart-AlreadyStarted", new InvalidOperationException($"WorkItemDispatcher '{name}' has already started")); } isStarted = true; - TraceHelper.Trace(TraceEventType.Information, $"WorkItemDispatcher('{name}') starting. Id {id}."); + TraceHelper.Trace(TraceEventType.Information, "WorkItemDispatcherStart", $"WorkItemDispatcher('{name}') starting. Id {id}."); for (var i = 0; i < DispatcherCount; i++) { var dispatcherId = i.ToString(); @@ -172,18 +157,18 @@ public async Task StopAsync(bool forced) isStarted = false; - TraceHelper.Trace(TraceEventType.Information, $"WorkItemDispatcher('{name}') stopping. Id {id}."); + TraceHelper.Trace(TraceEventType.Information, "WorkItemDispatcherStop-Begin", $"WorkItemDispatcher('{name}') stopping. Id {id}."); if (!forced) { int retryCount = 7; while ((concurrentWorkItemCount > 0 || activeFetchers > 0) && retryCount-- >= 0) { - TraceHelper.Trace(TraceEventType.Information, $"WorkItemDispatcher('{name}') waiting to stop. Id {id}. WorkItemCount: {concurrentWorkItemCount}, ActiveFetchers: {activeFetchers}"); + TraceHelper.Trace(TraceEventType.Information, "WorkItemDispatcherStop-Waiting", $"WorkItemDispatcher('{name}') waiting to stop. Id {id}. WorkItemCount: {concurrentWorkItemCount}, ActiveFetchers: {activeFetchers}"); await Task.Delay(4000); } } - TraceHelper.Trace(TraceEventType.Information, $"WorkItemDispatcher('{name}') stopped. Id {id}."); + TraceHelper.Trace(TraceEventType.Information, "WorkItemDispatcherStop-End", $"WorkItemDispatcher('{name}') stopped. Id {id}."); } finally { @@ -199,7 +184,9 @@ async Task DispatchAsync(string dispatcherId) { if (concurrentWorkItemCount >= MaxConcurrentWorkItems) { - TraceHelper.Trace(TraceEventType.Information, + TraceHelper.Trace( + TraceEventType.Information, + "WorkItemDispatcherDispatch-MaxOperations", GetFormattedLog(dispatcherId, $"Max concurrent operations ({concurrentWorkItemCount}) are already in progress. Waiting for {WaitIntervalOnMaxSessions}s for next accept.")); await Task.Delay(WaitIntervalOnMaxSessions); continue; @@ -210,11 +197,15 @@ async Task DispatchAsync(string dispatcherId) try { Interlocked.Increment(ref activeFetchers); - TraceHelper.Trace(TraceEventType.Information, + TraceHelper.Trace( + TraceEventType.Verbose, + "WorkItemDispatcherDispatch-StartFetch", GetFormattedLog(dispatcherId, $"Starting fetch with timeout of {DefaultReceiveTimeout} ({concurrentWorkItemCount}/{MaxConcurrentWorkItems} max)")); var timer = Stopwatch.StartNew(); workItem = await FetchWorkItem(DefaultReceiveTimeout); - TraceHelper.Trace(TraceEventType.Information, + TraceHelper.Trace( + TraceEventType.Verbose, + "WorkItemDispatcherDispatch-EndFetch", GetFormattedLog(dispatcherId, $"After fetch ({timer.ElapsedMilliseconds} ms) ({concurrentWorkItemCount}/{MaxConcurrentWorkItems} max)")); } catch (TimeoutException) @@ -223,7 +214,9 @@ async Task DispatchAsync(string dispatcherId) } catch (TaskCanceledException exception) { - TraceHelper.Trace(TraceEventType.Information, + TraceHelper.Trace( + TraceEventType.Information, + "WorkItemDispatcherDispatch-TaskCanceledException", GetFormattedLog(dispatcherId, $"TaskCanceledException while fetching workItem, should be harmless: {exception.Message}")); delaySecs = GetDelayInSecondsAfterOnFetchException(exception); } @@ -231,13 +224,18 @@ async Task DispatchAsync(string dispatcherId) { if (!isStarted) { - TraceHelper.Trace(TraceEventType.Information, + TraceHelper.Trace( + TraceEventType.Information, + "WorkItemDispatcherDispatch-HarmlessException", GetFormattedLog(dispatcherId, $"Harmless exception while fetching workItem after Stop(): {exception.Message}")); } else { // TODO : dump full node context here - TraceHelper.TraceException(TraceEventType.Warning, exception, + TraceHelper.TraceException( + TraceEventType.Warning, + "WorkItemDispatcherDispatch-Exception", + exception, GetFormattedLog(dispatcherId, $"Exception while fetching workItem: {exception.Message}")); delaySecs = GetDelayInSecondsAfterOnFetchException(exception); } @@ -284,23 +282,32 @@ async Task ProcessWorkItemAsync(WorkItemDispatcherContext context, object workIt { workItemId = workItemIdentifier(workItem); - TraceHelper.Trace(TraceEventType.Information, + TraceHelper.Trace( + TraceEventType.Information, + "WorkItemDispatcherProcess-Begin", GetFormattedLog(context.DispatcherId, $"Starting to process workItem {workItemId}")); await ProcessWorkItem(workItem); AdjustDelayModifierOnSuccess(); - TraceHelper.Trace(TraceEventType.Information, + TraceHelper.Trace( + TraceEventType.Information, + "WorkItemDispatcherProcess-End", GetFormattedLog(context.DispatcherId, $"Finished processing workItem {workItemId}")); abortWorkItem = false; } catch (TypeMissingException exception) { - TraceHelper.TraceException(TraceEventType.Error, exception, + TraceHelper.TraceException( + TraceEventType.Error, + "WorkItemDispatcherProcess-TypeMissingException", + exception, GetFormattedLog(context.DispatcherId, $"Exception while processing workItem {workItemId}")); - TraceHelper.Trace(TraceEventType.Error, + TraceHelper.Trace( + TraceEventType.Error, + "WorkItemDispatcherProcess-TypeMissingBackingOff", "Backing off after invalid operation by " + BackoffIntervalOnInvalidOperationSecs); // every time we hit invalid operation exception we back off the dispatcher @@ -308,13 +315,18 @@ async Task ProcessWorkItemAsync(WorkItemDispatcherContext context, object workIt } catch (Exception exception) when (!Utils.IsFatal(exception)) { - TraceHelper.TraceException(TraceEventType.Error, exception, + TraceHelper.TraceException( + TraceEventType.Error, + "WorkItemDispatcherProcess-Exception", + exception, GetFormattedLog(context.DispatcherId, $"Exception while processing workItem {workItemId}")); int delayInSecs = GetDelayInSecondsAfterOnProcessException(exception); if (delayInSecs > 0) { - TraceHelper.Trace(TraceEventType.Error, + TraceHelper.Trace( + TraceEventType.Error, + "WorkItemDispatcherProcess-BackingOff", "Backing off after exception by at least " + delayInSecs + " until " + CountDownToZeroDelay + " successful operations"); @@ -377,7 +389,7 @@ async Task ExceptionTraceWrapperAsync(Func asyncAction) catch (Exception exception) when (!Utils.IsFatal(exception)) { // eat and move on - TraceHelper.TraceException(TraceEventType.Error, exception); + TraceHelper.TraceException(TraceEventType.Error, "WorkItemDispatcher-ExceptionTraceError", exception); } } diff --git a/src/DurableTask.ServiceBus/Common/ServiceBusUtils.cs b/src/DurableTask.ServiceBus/Common/ServiceBusUtils.cs index 3d46586e6..eb8ac77c5 100644 --- a/src/DurableTask.ServiceBus/Common/ServiceBusUtils.cs +++ b/src/DurableTask.ServiceBus/Common/ServiceBusUtils.cs @@ -73,7 +73,10 @@ public static async Task GetBrokeredMessageFromObjectAsync( { Stream compressedStream = Utils.GetCompressedStream(rawStream); var rawLen = rawStream.Length; - TraceHelper.TraceInstance(TraceEventType.Information, instance, + TraceHelper.TraceInstance( + TraceEventType.Information, + "GetBrokeredMessageFromObject-CompressionStats", + instance, () => "Compression stats for " + (messageType ?? string.Empty) + " : " + brokeredMessage?.MessageId + @@ -153,6 +156,7 @@ static async Task GenerateBrokeredMessageWithBlobKeyPropertyAsy TraceHelper.TraceInstance( TraceEventType.Information, + "GenerateBrokeredMessageWithBlobKeyProperty-SaveToBlob", instance, () => $"Saving the message stream in blob storage using key {blobKey}."); await orchestrationServiceBlobStore.SaveStreamAsync(blobKey, stream); @@ -276,15 +280,22 @@ public static void CheckAndLogDeliveryCount(string sessionId, BrokeredMessage me { if (!string.IsNullOrEmpty(sessionId)) { - TraceHelper.TraceSession(TraceEventType.Critical, sessionId, + TraceHelper.TraceSession( + TraceEventType.Critical, + "MaxDeliveryCountApproaching-Session", + sessionId, "Delivery count for message with id {0} is {1}. Message will be deadlettered if processing continues to fail.", - message.MessageId, message.DeliveryCount); + message.MessageId, + message.DeliveryCount); } else { - TraceHelper.Trace(TraceEventType.Critical, + TraceHelper.Trace( + TraceEventType.Critical, + "MaxDeliveryCountApproaching", "Delivery count for message with id {0} is {1}. Message will be deadlettered if processing continues to fail.", - message.MessageId, message.DeliveryCount); + message.MessageId, + message.DeliveryCount); } } } diff --git a/src/DurableTask.ServiceBus/ServiceBusOrchestrationService.cs b/src/DurableTask.ServiceBus/ServiceBusOrchestrationService.cs index 397d687b8..75fe4c329 100644 --- a/src/DurableTask.ServiceBus/ServiceBusOrchestrationService.cs +++ b/src/DurableTask.ServiceBus/ServiceBusOrchestrationService.cs @@ -183,7 +183,7 @@ public async Task StopAsync(bool isForced) { this.cancellationTokenSource?.Cancel(); - TraceHelper.Trace(TraceEventType.Information, "Final Service Stats: {0}", this.ServiceStats.ToString()); + TraceHelper.Trace(TraceEventType.Information, "ServiceBusOrchestrationService-StatsFinal", "Final Service Stats: {0}", this.ServiceStats.ToString()); // TODO : call shutdown of any remaining orchestrationSessions and orchestrationMessages await Task.WhenAll( @@ -334,7 +334,9 @@ long GetQueueCount(string entityName) QueueDescription queueDescription = namespaceManager.GetQueue(entityName); if (queueDescription == null) { - throw TraceHelper.TraceException(TraceEventType.Error, + throw TraceHelper.TraceException( + TraceEventType.Error, + "ServiceBusOrchestrationService-QueueNotFound", new ArgumentException($"Queue {entityName} does not exist")); } return queueDescription.MessageCount; @@ -438,7 +440,10 @@ public async Task LockNextTaskOrchestrationWorkItemAs session.SessionId, "Receive Session Message Batch", this.Settings.MaxRetries, Settings.IntervalBetweenRetriesSecs)).ToList(); this.ServiceStats.OrchestrationDispatcherStats.MessagesReceived.Increment(newMessages.Count); - TraceHelper.TraceSession(TraceEventType.Information, session.SessionId, + TraceHelper.TraceSession( + TraceEventType.Information, + "ServiceBusOrchestrationService-LockNextTaskOrchestrationWorkItem-MessageToProcess", + session.SessionId, this.GetFormattedLog($@"{newMessages.Count()} new messages to process: { string.Join(",", newMessages.Select(m => m.MessageId))}, max latency: { newMessages.Max(message => message.DeliveryLatency())}ms")); @@ -463,7 +468,7 @@ public async Task LockNextTaskOrchestrationWorkItemAs if (!this.orchestrationSessions.TryAdd(session.SessionId, sessionState)) { var error = $"Duplicate orchestration session id '{session.SessionId}', id already exists in session list."; - TraceHelper.Trace(TraceEventType.Error, error); + TraceHelper.Trace(TraceEventType.Error, "ServiceBusOrchestrationService-LockNextTaskOrchestrationWorkItem-DuplicateSessionId", error); throw new OrchestrationFrameworkException(error); } @@ -546,7 +551,7 @@ public async Task RenewTaskOrchestrationWorkItemLockAsync(TaskOrchestrationWorkI return; } - TraceHelper.TraceSession(TraceEventType.Error, workItem.InstanceId, "Renew lock on orchestration session"); + TraceHelper.TraceSession(TraceEventType.Information, "ServiceBusOrchestrationService-RenewTaskOrchestrationWorkItem", workItem.InstanceId, "Renew lock on orchestration session"); await sessionState.Session.RenewLockAsync(); this.ServiceStats.OrchestrationDispatcherStats.SessionsRenewed.Increment(); workItem.LockedUntilUtc = sessionState.Session.LockedUntilUtc; @@ -585,6 +590,7 @@ public async Task CompleteTaskOrchestrationWorkItemAsync( Transaction.Current.TransactionCompleted += (o, e) => TraceHelper.TraceInstance( e.Transaction.TransactionInformation.Status == TransactionStatus.Committed ? TraceEventType.Information : TraceEventType.Error, + "ServiceBusOrchestrationService-CompleteTaskOrchestrationWorkItem-TransactionComplete", runtimeState.OrchestrationInstance, () => $@"Orchestration Transaction Completed { e.Transaction.TransactionInformation.LocalIdentifier @@ -593,6 +599,7 @@ public async Task CompleteTaskOrchestrationWorkItemAsync( TraceHelper.TraceInstance( TraceEventType.Information, + "ServiceBusOrchestrationService-CompleteTaskOrchestrationWorkItem-CreateTransaction", runtimeState.OrchestrationInstance, () => $@"Created new Orchestration Transaction - txnid: { Transaction.Current.TransactionInformation.LocalIdentifier @@ -684,7 +691,10 @@ public async Task CompleteTaskOrchestrationWorkItemAsync( { List trackingMessages = await CreateTrackingMessagesAsync(runtimeState, sessionState.SequenceNumber); - TraceHelper.TraceInstance(TraceEventType.Information, runtimeState.OrchestrationInstance, + TraceHelper.TraceInstance( + TraceEventType.Information, + "ServiceBusOrchestrationService-CompleteTaskOrchestrationWorkItem-TrackingMessages", + runtimeState.OrchestrationInstance, "Created {0} tracking messages", trackingMessages.Count); if (trackingMessages.Count > 0) @@ -699,6 +709,7 @@ public async Task CompleteTaskOrchestrationWorkItemAsync( TraceHelper.TraceInstance( TraceEventType.Information, + "ServiceBusOrchestrationService-CompleteTaskOrchestrationWorkItemMessages", runtimeState.OrchestrationInstance, () => { @@ -722,7 +733,10 @@ public async Task ReleaseTaskOrchestrationWorkItemAsync(TaskOrchestrationWorkIte // This is Ok, if we abandoned the message it will already be gone if (sessionState == null) { - TraceHelper.TraceSession(TraceEventType.Warning, workItem?.InstanceId, + TraceHelper.TraceSession( + TraceEventType.Warning, + "ServiceBusOrchestrationService-ReleaseTaskOrchestrationWorkItemFailed", + workItem?.InstanceId, $"DeleteSessionInstance failed, could already be aborted"); return; } @@ -742,7 +756,7 @@ public async Task AbandonTaskOrchestrationWorkItemAsync(TaskOrchestrationWorkIte return; } - TraceHelper.TraceSession(TraceEventType.Error, workItem.InstanceId, "Abandoning {0} messages due to workitem abort", sessionState.LockTokens.Keys.Count()); + TraceHelper.TraceSession(TraceEventType.Error, "ServiceBusOrchestrationService-AbandonTaskOrchestrationWorkItem", workItem.InstanceId, "Abandoning {0} messages due to workitem abort", sessionState.LockTokens.Keys.Count()); foreach (var lockToken in sessionState.LockTokens.Keys) { await sessionState.Session.AbandonAsync(lockToken); @@ -754,7 +768,7 @@ public async Task AbandonTaskOrchestrationWorkItemAsync(TaskOrchestrationWorkIte } catch (Exception ex) when (!Utils.IsFatal(ex)) { - TraceHelper.TraceExceptionSession(TraceEventType.Warning, workItem.InstanceId, ex, "Error while aborting session"); + TraceHelper.TraceExceptionSession(TraceEventType.Warning, "ServiceBusOrchestrationService-AbandonTaskOrchestrationWorkItemError", workItem.InstanceId, ex, "Error while aborting session"); } } @@ -783,7 +797,9 @@ public async Task LockNextTaskActivityWorkItem(TimeSpan re this.ServiceStats.ActivityDispatcherStats.MessagesReceived.Increment(); - TraceHelper.TraceSession(TraceEventType.Information, + TraceHelper.TraceSession( + TraceEventType.Information, + "ServiceBusOrchestrationService-LockNextTaskActivityWorkItem-Messages", receivedMessage.SessionId, GetFormattedLog($"New message to process: {receivedMessage.MessageId} [{receivedMessage.SequenceNumber}], latency: {receivedMessage.DeliveryLatency()}ms")); @@ -794,7 +810,7 @@ public async Task LockNextTaskActivityWorkItem(TimeSpan re if (!orchestrationMessages.TryAdd(receivedMessage.MessageId, receivedMessage)) { var error = $"Duplicate orchestration message id '{receivedMessage.MessageId}', id already exists in message list."; - TraceHelper.Trace(TraceEventType.Error, error); + TraceHelper.Trace(TraceEventType.Error, "ServiceBusOrchestrationService-DuplicateOrchestration",error); throw new OrchestrationFrameworkException(error); } @@ -874,6 +890,7 @@ public async Task CompleteTaskActivityWorkItemAsync(TaskActivityWorkItem workIte Transaction.Current.TransactionCompleted += (o, e) => TraceHelper.TraceInstance( e.Transaction.TransactionInformation.Status == TransactionStatus.Committed ? TraceEventType.Information : TraceEventType.Error, + "ServiceBusOrchestrationService-CompleteTaskActivityWorkItem-TransactionComplete", workItem.TaskMessage.OrchestrationInstance, () => $@"TaskActivity Transaction Completed { e.Transaction.TransactionInformation.LocalIdentifier @@ -882,6 +899,7 @@ public async Task CompleteTaskActivityWorkItemAsync(TaskActivityWorkItem workIte TraceHelper.TraceInstance( TraceEventType.Information, + "ServiceBusOrchestrationService-CompleteTaskActivityWorkItem-CreateTransaction", workItem.TaskMessage.OrchestrationInstance, () => $@"Created new TaskActivity Transaction - txnid: { Transaction.Current.TransactionInformation.LocalIdentifier @@ -904,7 +922,7 @@ await Task.WhenAll( public Task AbandonTaskActivityWorkItemAsync(TaskActivityWorkItem workItem) { var message = GetAndDeleteBrokeredMessageForWorkItem(workItem); - TraceHelper.Trace(TraceEventType.Information, $"Abandoning message {workItem?.Id}"); + TraceHelper.Trace(TraceEventType.Information, "ServiceBusOrchestrationService-AbandonTaskActivityWorkItem", $"Abandoning message {workItem?.Id}"); return message == null ? Task.FromResult(null) @@ -941,7 +959,7 @@ public async Task CreateTaskOrchestrationAsync(TaskMessage creationMessage) catch (Exception ex) when (!Utils.IsFatal(ex) && jumpStartEnabled) { // Ingore exception - TraceHelper.Trace(TraceEventType.Warning, $"Error while adding message to ServiceBus: {ex.ToString()}"); + TraceHelper.Trace(TraceEventType.Warning, "ServiceBusOrchestrationService-CreateTaskOrchestration-ServiceBusError", $"Error while adding message to ServiceBus: {ex.ToString()}"); } } @@ -1137,18 +1155,18 @@ public async Task PurgeOrchestrationHistoryAsync( DateTime thresholdDateTimeUtc, OrchestrationStateTimeRangeFilterType timeRangeFilterType) { - TraceHelper.Trace(TraceEventType.Information, $"Purging orchestration instances before: {thresholdDateTimeUtc}, Type: {timeRangeFilterType}"); + TraceHelper.Trace(TraceEventType.Information, "ServiceBusOrchestrationService-PurgeOrchestrationHistory-Start", $"Purging orchestration instances before: {thresholdDateTimeUtc}, Type: {timeRangeFilterType}"); if (this.BlobStore != null) { await this.BlobStore.PurgeExpiredBlobsAsync(thresholdDateTimeUtc); - TraceHelper.Trace(TraceEventType.Information, $"Blob storage is purged."); + TraceHelper.Trace(TraceEventType.Information, "ServiceBusOrchestrationService-BlobsPurged", $"Blob storage is purged."); } if (InstanceStore != null) { int purgedEvents = await InstanceStore.PurgeOrchestrationHistoryEventsAsync(thresholdDateTimeUtc, timeRangeFilterType); - TraceHelper.Trace(TraceEventType.Information, $"Purged {purgedEvents} orchestration histories"); + TraceHelper.Trace(TraceEventType.Information, "ServiceBusOrchestrationService-HistoryPurged", $"Purged {purgedEvents} orchestration histories"); } } @@ -1181,7 +1199,10 @@ async Task FetchTrackingWorkItemAsync(TimeSpan receiveTimeout) session.SessionId, "Receive Tracking Session Message Batch", Settings.MaxRetries, Settings.IntervalBetweenRetriesSecs)).ToList(); this.ServiceStats.TrackingDispatcherStats.MessagesReceived.Increment(newMessages.Count); - TraceHelper.TraceSession(TraceEventType.Information, session.SessionId, + TraceHelper.TraceSession( + TraceEventType.Information, + "ServiceBusOrchestrationService-FetchTrackingWorkItem-Messages", + session.SessionId, GetFormattedLog($"{newMessages.Count()} new tracking messages to process: {string.Join(",", newMessages.Select(m => m.MessageId))}")); ServiceBusUtils.CheckAndLogDeliveryCount(newMessages, Settings.MaxTrackingDeliveryCount); @@ -1347,7 +1368,7 @@ void TraceEntities( foreach (T entry in entities) { var idx = index; - TraceHelper.Trace(eventType, () => traceGenerator(idx, message, entry)); + TraceHelper.Trace(eventType, "ServiceBusOrchestrationService-Entities", () => traceGenerator(idx, message, entry)); index++; } } @@ -1394,7 +1415,8 @@ string GetFormattedLog(string input) void LogSentMessages(MessageSession session, string messageType, IList messages) { TraceHelper.TraceSession( - TraceEventType.Information, + TraceEventType.Information, + "ServiceBusOrchestrationService-SentMessageLog", session.SessionId, this.GetFormattedLog($@"{messages.Count().ToString()} messages queued for {messageType}: { string.Join(",", messages.Select(m => $"{m.Message.MessageId} <{m.Action?.Event.EventId.ToString()}>"))}")); @@ -1419,6 +1441,7 @@ async Task TrySetSessionStateAsync( { TraceHelper.TraceSession( TraceEventType.Error, + "ServiceBusOrchestrationService-SessionStateThresholdApproaching", workItem.InstanceId, $"Size of session state ({runtimeState.CompressedSize}B) is nearing session size limit of {Settings.SessionSettings.SessionOverflowThresholdInBytes}B"); } @@ -1461,7 +1484,7 @@ async Task TrySetSessionStateAsync( isSessionSizeThresholdExceeded = true; string reason = $"Session state size of {runtimeState.CompressedSize} exceeded the termination threshold of {Settings.SessionSettings.SessionMaxSizeInBytes} bytes. More info: {exception.StackTrace}"; - TraceHelper.TraceSession(TraceEventType.Critical, workItem.InstanceId, reason); + TraceHelper.TraceSession(TraceEventType.Critical, "ServiceBusOrchestrationService-SessionSizeExceeded", workItem.InstanceId, reason); BrokeredMessage forcedTerminateMessage = await CreateForcedTerminateMessageAsync(runtimeState.OrchestrationInstance.InstanceId, reason); await orchestratorQueueClient.SendAsync(forcedTerminateMessage); @@ -1479,8 +1502,8 @@ async Task ServiceMonitorAsync(CancellationToken cancellationToken) { await Task.Delay(TimeSpan.FromMinutes(1), cancellationToken); - TraceHelper.Trace(TraceEventType.Information, "Service Stats: {0}", this.ServiceStats.ToString()); - TraceHelper.Trace(TraceEventType.Information, "Active Session and Message Stats: Messages: {0}, Sessions: {1}", orchestrationMessages.Count, orchestrationSessions.Count); + TraceHelper.Trace(TraceEventType.Information, "ServiceBusOrchestrationService-ServiceStats", "Service Stats: {0}", this.ServiceStats.ToString()); + TraceHelper.Trace(TraceEventType.Information, "ServiceBusOrchestrationService-ServiceStats-Active", "Active Session and Message Stats: Messages: {0}, Sessions: {1}", orchestrationMessages.Count, orchestrationSessions.Count); } } diff --git a/src/DurableTask.ServiceBus/Tracking/AzureTableClient.cs b/src/DurableTask.ServiceBus/Tracking/AzureTableClient.cs index ee543212e..7a1950109 100644 --- a/src/DurableTask.ServiceBus/Tracking/AzureTableClient.cs +++ b/src/DurableTask.ServiceBus/Tracking/AzureTableClient.cs @@ -484,7 +484,7 @@ public async Task DeleteEntitesAsync(IEnumerable DeleteJumpStartEntitesAsync(IEnumerable entities) + public async Task DeleteJumpStartEntitiesAsync(IEnumerable entities) { try { @@ -497,7 +497,7 @@ public async Task DeleteJumpStartEntitesAsync(IEnumerable WriteJumpStartEntitesAsync(IEnumerable /// List of jump start events to delete - public Task DeleteJumpStartEntitesAsync(IEnumerable entities) + public Task DeleteJumpStartEntitiesAsync(IEnumerable entities) { var jumpStartEntities = entities.Select(e => new AzureTableOrchestrationJumpStartEntity(e)); - return this.tableClient.DeleteJumpStartEntitesAsync(jumpStartEntities); + return this.tableClient.DeleteJumpStartEntitiesAsync(jumpStartEntities); } /// diff --git a/src/DurableTask.ServiceBus/Tracking/BlobStorageClientHelper.cs b/src/DurableTask.ServiceBus/Tracking/BlobStorageClientHelper.cs index a605f0c27..a642054c6 100644 --- a/src/DurableTask.ServiceBus/Tracking/BlobStorageClientHelper.cs +++ b/src/DurableTask.ServiceBus/Tracking/BlobStorageClientHelper.cs @@ -152,6 +152,7 @@ public static bool IsContainerExpired(string containerName, DateTime thresholdDa { TraceHelper.Trace( TraceEventType.Warning, + "BlobStorageClientHelper-IsContainerExpired-ContainerIgnored", $"Container name {containerName} does not contain required 4 segments. Container {containerName} is ignored."); return false; @@ -170,6 +171,7 @@ public static bool IsContainerExpired(string containerName, DateTime thresholdDa { TraceHelper.Trace( TraceEventType.Warning, + "BlobStorageClientHelper-IsContainerExpired-InvalidDate", $"Cannot parse the the date string {dateString} in the format of yyyyMMdd. Container {containerName} is ignored."); return false; diff --git a/src/DurableTask.ServiceBus/Tracking/JumpStartManager.cs b/src/DurableTask.ServiceBus/Tracking/JumpStartManager.cs index 20c6ed76d..874d10985 100644 --- a/src/DurableTask.ServiceBus/Tracking/JumpStartManager.cs +++ b/src/DurableTask.ServiceBus/Tracking/JumpStartManager.cs @@ -48,11 +48,13 @@ public Task StartAsync() { if (Interlocked.CompareExchange(ref isStarted, 1, 0) != 0) { - throw TraceHelper.TraceException(TraceEventType.Error, + throw TraceHelper.TraceException( + TraceEventType.Error, + "JumpStartManager-AlreadyStarted", new InvalidOperationException("JumpStart has already started")); } - TraceHelper.Trace(TraceEventType.Information, "Jump start manager starting."); + TraceHelper.Trace(TraceEventType.Information, "JumpStartManager-Starting", "Jump start manager starting."); return Task.Factory.StartNew(() => JumpStartAsync()); } @@ -64,7 +66,7 @@ public Task StopAsync() return Task.FromResult(0); } - TraceHelper.Trace(TraceEventType.Information, "Jump start manager stopped."); + TraceHelper.Trace(TraceEventType.Information, "JumpStartManager-Stopped", "Jump start manager stopped."); return Task.FromResult(0); } @@ -76,11 +78,13 @@ public async Task JumpStartAsync() TimeSpan delay = this.interval; try { - TraceHelper.Trace(TraceEventType.Information, "Jump start starting fetch"); + TraceHelper.Trace(TraceEventType.Information, "JumpStartManager-Fetch-Begin", "Jump start starting fetch"); // TODO: Query in batchces and change timeframe only after curent range is finished IEnumerable entities = await this.service.InstanceStore.GetJumpStartEntitesAsync(1000); - TraceHelper.Trace(TraceEventType.Information, + TraceHelper.Trace( + TraceEventType.Information, + "JumpStartManager-Fetch-End", $"JumpStartManager: Fetched state entities count: {entities.Count()}"); var taskList = new List(); entities.ToList().ForEach(e => taskList.Add(this.JumpStartOrchestrationAsync(e))); @@ -92,7 +96,9 @@ public async Task JumpStartAsync() } catch (TaskCanceledException exception) { - TraceHelper.Trace(TraceEventType.Information, + TraceHelper.Trace( + TraceEventType.Information, + "JumpStartManager-Fetch-TaskCanceled", $"JumpStartManager: TaskCanceledException while fetching state entities, should be harmless: {exception.Message}"); delay = this.interval; } @@ -100,12 +106,17 @@ public async Task JumpStartAsync() { if (isStarted == 0) { - TraceHelper.Trace(TraceEventType.Information, + TraceHelper.Trace( + TraceEventType.Information, + "JumpStartManager-Fetch-HarmlessException", $"JumpStartManager: Harmless exception while fetching state entities after Stop(): {exception.Message}"); } else { - TraceHelper.TraceException(TraceEventType.Warning, exception, + TraceHelper.TraceException( + TraceEventType.Warning, + "JumpStartManager-Fetch-Exception", + exception, "JumpStartManager: Exception while fetching/processing state entities"); delay = this.interval; } @@ -122,7 +133,7 @@ protected async Task JumpStartOrchestrationAsync(OrchestrationJumpStartInstanceE if (stateEntity != null) { // It seems orchestration started, delete entity from JumpStart table - await this.service.InstanceStore.DeleteJumpStartEntitesAsync(new[] { jumpStartEntity }); + await this.service.InstanceStore.DeleteJumpStartEntitiesAsync(new[] { jumpStartEntity }); } else if (!jumpStartEntity.JumpStartTime.IsSet() && jumpStartEntity.State.CreatedTime + this.ignoreWindow < DateTime.UtcNow) @@ -143,14 +154,18 @@ protected async Task JumpStartOrchestrationAsync(OrchestrationJumpStartInstanceE }; await this.service.SendTaskOrchestrationMessageAsync(taskMessage); - TraceHelper.Trace(TraceEventType.Information, + TraceHelper.Trace( + TraceEventType.Information, + "JumpStartManager-SendTaskOrchestrationMessage", $"JumpStartManager: SendTaskOrchestrationMessageAsync({instance.InstanceId}, {instance.ExecutionId}) success!"); // Now update the JumpStart table jumpStartEntity.JumpStartTime = DateTime.UtcNow; await this.service.InstanceStore.WriteJumpStartEntitesAsync(new[] { jumpStartEntity }); - TraceHelper.Trace(TraceEventType.Information, + TraceHelper.Trace( + TraceEventType.Information, + "JumpStartManager-WriteJumpStartEntites", $"JumpStartManager: WriteJumpStartEntitesAsync({instance.InstanceId}, {instance.ExecutionId}) success!"); } } diff --git a/test/DurableTask.Core.Tests/CommonTests.cs b/test/DurableTask.Core.Tests/CommonTests.cs index 12b696101..e672768bc 100644 --- a/test/DurableTask.Core.Tests/CommonTests.cs +++ b/test/DurableTask.Core.Tests/CommonTests.cs @@ -14,8 +14,10 @@ namespace DurableTask.Core.Tests { using System; - using DurableTask.Core.Common; + using Microsoft.Practices.EnterpriseLibrary.SemanticLogging.Utility; using Microsoft.VisualStudio.TestTools.UnitTesting; + using DurableTask.Core.Common; + using DurableTask.Core.Tracing; [TestClass] public class CommonTests @@ -33,5 +35,11 @@ public void DateTimeExtensionsIsSetTest() Assert.IsFalse(DateTime.FromFileTimeUtc(0).IsSet()); } } + + [TestMethod] + public void ShouldValidateEventSource() + { + EventSourceAnalyzer.InspectAll(DefaultEventSource.Log); + } } } \ No newline at end of file diff --git a/test/DurableTask.Core.Tests/DurableTask.Core.Tests.csproj b/test/DurableTask.Core.Tests/DurableTask.Core.Tests.csproj index 25ffd6fda..6654ae3e2 100644 --- a/test/DurableTask.Core.Tests/DurableTask.Core.Tests.csproj +++ b/test/DurableTask.Core.Tests/DurableTask.Core.Tests.csproj @@ -6,7 +6,8 @@ - + + From 14b269d0229c749afec08193db1e488798cf46a8 Mon Sep 17 00:00:00 2001 From: siport Date: Fri, 30 Jun 2017 16:50:42 -0700 Subject: [PATCH 3/6] Fix typos --- src/DurableTask.Core/Common/Utils.cs | 2 +- src/DurableTask.Core/OrchestrationStateInstanceFilter.cs | 2 +- src/DurableTask.Core/OrchestrationStateNameVersionFilter.cs | 2 +- src/DurableTask.Core/OrchestrationStateTimeRangeFilter.cs | 2 +- src/DurableTask.Emulator/LocalOrchestrationService.cs | 1 - 5 files changed, 4 insertions(+), 5 deletions(-) diff --git a/src/DurableTask.Core/Common/Utils.cs b/src/DurableTask.Core/Common/Utils.cs index 86b413c33..71397f2ba 100644 --- a/src/DurableTask.Core/Common/Utils.cs +++ b/src/DurableTask.Core/Common/Utils.cs @@ -33,7 +33,7 @@ public static class Utils const int FullGzipHeaderLength = 10; /// - /// Gets a safe maximim datetime value that accounts for timezone + /// Gets a safe maximum datetime value that accounts for timezone /// public static readonly DateTime DateTimeSafeMaxValue = DateTime.MaxValue.Subtract(TimeSpan.FromDays(1)).ToUniversalTime(); diff --git a/src/DurableTask.Core/OrchestrationStateInstanceFilter.cs b/src/DurableTask.Core/OrchestrationStateInstanceFilter.cs index 4e28b079d..abca604ec 100644 --- a/src/DurableTask.Core/OrchestrationStateInstanceFilter.cs +++ b/src/DurableTask.Core/OrchestrationStateInstanceFilter.cs @@ -38,7 +38,7 @@ public OrchestrationStateInstanceFilter() public string ExecutionId { get; set; } /// - /// Gets or sets the match type of either statrts with or exact match for the filter + /// Gets or sets the match type of either starts with or exact match for the filter /// public bool StartsWith { get; set; } } diff --git a/src/DurableTask.Core/OrchestrationStateNameVersionFilter.cs b/src/DurableTask.Core/OrchestrationStateNameVersionFilter.cs index 4db4668db..a2e5a9208 100644 --- a/src/DurableTask.Core/OrchestrationStateNameVersionFilter.cs +++ b/src/DurableTask.Core/OrchestrationStateNameVersionFilter.cs @@ -14,7 +14,7 @@ namespace DurableTask.Core { /// - /// Filter for Orchestrationname and version + /// Filter for Orchestration Name and Version /// public class OrchestrationStateNameVersionFilter : OrchestrationStateQueryFilter { diff --git a/src/DurableTask.Core/OrchestrationStateTimeRangeFilter.cs b/src/DurableTask.Core/OrchestrationStateTimeRangeFilter.cs index 5a5a82e8c..16ad7b71a 100644 --- a/src/DurableTask.Core/OrchestrationStateTimeRangeFilter.cs +++ b/src/DurableTask.Core/OrchestrationStateTimeRangeFilter.cs @@ -16,7 +16,7 @@ namespace DurableTask.Core using System; /// - /// Filter for Orchestration time range on a timerange type + /// Filter for Orchestration State time range on a time range type /// public class OrchestrationStateTimeRangeFilter : OrchestrationStateQueryFilter { diff --git a/src/DurableTask.Emulator/LocalOrchestrationService.cs b/src/DurableTask.Emulator/LocalOrchestrationService.cs index 98a6f7b3b..7b75dc6b4 100644 --- a/src/DurableTask.Emulator/LocalOrchestrationService.cs +++ b/src/DurableTask.Emulator/LocalOrchestrationService.cs @@ -53,7 +53,6 @@ public class LocalOrchestrationService : IOrchestrationService, IOrchestrationSe /// /// Creates a new instance of the LocalOrchestrationService with default settings /// - public LocalOrchestrationService() { this.orchestratorQueue = new PeekLockSessionQueue(); From 8e06b0c9ac4cd39bd664e42af58703332d3a7fe2 Mon Sep 17 00:00:00 2001 From: siport Date: Fri, 30 Jun 2017 17:22:51 -0700 Subject: [PATCH 4/6] cr comments --- src/DurableTask.Core/Common/Utils.cs | 2 +- src/DurableTask.Core/OrchestrationStateInstanceFilter.cs | 8 ++++---- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/src/DurableTask.Core/Common/Utils.cs b/src/DurableTask.Core/Common/Utils.cs index 71397f2ba..25cd51ac0 100644 --- a/src/DurableTask.Core/Common/Utils.cs +++ b/src/DurableTask.Core/Common/Utils.cs @@ -70,7 +70,7 @@ public static void WriteObjectToStream(Stream objectStream, object obj) } /// - /// Writes the supplied string input to a MemoryStream, optionaly compressing the string + /// Writes the supplied string input to a MemoryStream, optionaly compressing the string, returns the stream /// public static Stream WriteStringToStream(string input, bool compress, out long originalStreamSize) { diff --git a/src/DurableTask.Core/OrchestrationStateInstanceFilter.cs b/src/DurableTask.Core/OrchestrationStateInstanceFilter.cs index abca604ec..6abc7fcb0 100644 --- a/src/DurableTask.Core/OrchestrationStateInstanceFilter.cs +++ b/src/DurableTask.Core/OrchestrationStateInstanceFilter.cs @@ -14,7 +14,7 @@ namespace DurableTask.Core { /// - /// Filter for Orchestration instance filter + /// Filter for Orchestration instance filter /// public class OrchestrationStateInstanceFilter : OrchestrationStateQueryFilter { @@ -28,17 +28,17 @@ public OrchestrationStateInstanceFilter() } /// - /// Gets or sets the InstanceId for the filter + /// Gets or sets the InstanceId for the filter /// public string InstanceId { get; set; } /// - /// Gets or sets the ExecutionId for the filter + /// Gets or sets the ExecutionId for the filter /// public string ExecutionId { get; set; } /// - /// Gets or sets the match type of either starts with or exact match for the filter + /// Gets or sets the match type of either starts with or exact match for the filter /// public bool StartsWith { get; set; } } From bc8dd5a413f3248d41431a650c08527cb2b2c386 Mon Sep 17 00:00:00 2001 From: siport Date: Mon, 3 Jul 2017 09:53:07 -0700 Subject: [PATCH 5/6] Fix the possible null ref when cancelling the orchestration --- .../ServiceBusOrchestrationService.cs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/DurableTask.ServiceBus/ServiceBusOrchestrationService.cs b/src/DurableTask.ServiceBus/ServiceBusOrchestrationService.cs index 75fe4c329..9bf627d9e 100644 --- a/src/DurableTask.ServiceBus/ServiceBusOrchestrationService.cs +++ b/src/DurableTask.ServiceBus/ServiceBusOrchestrationService.cs @@ -561,7 +561,7 @@ public async Task RenewTaskOrchestrationWorkItemLockAsync(TaskOrchestrationWorkI /// Complete an orchestation, this atomically sends any outbound messages and completes the session for all current messages /// /// The task orchestration to renew the lock on - /// New state of the orchestration to be persisted + /// New state of the orchestration to be persisted. Could be null if the orchestration is in completion. /// New work item messages to be processed /// New orchestration messages to be scheduled /// Delayed exection messages to be scheduled for the orchestration @@ -636,7 +636,7 @@ public async Task CompleteTaskOrchestrationWorkItemAsync( m, Settings.MessageCompressionSettings, Settings.MessageSettings, - newOrchestrationRuntimeState.OrchestrationInstance, + newOrchestrationRuntimeState?.OrchestrationInstance, "Timer Message", this.BlobStore, messageFireTime); @@ -677,7 +677,7 @@ public async Task CompleteTaskOrchestrationWorkItemAsync( continuedAsNewMessage, Settings.MessageCompressionSettings, Settings.MessageSettings, - newOrchestrationRuntimeState.OrchestrationInstance, + newOrchestrationRuntimeState?.OrchestrationInstance, "Continue as new", this.BlobStore, DateTimeUtils.MinDateTime); From ee28ab70eb406f5a8c3bf8b5e8d952bf69200c57 Mon Sep 17 00:00:00 2001 From: siport Date: Mon, 3 Jul 2017 13:58:09 -0700 Subject: [PATCH 6/6] Wholesale fix of spelling of Entities --- .../IOrchestrationServiceInstanceStore.cs | 10 ++++---- .../ServiceBusOrchestrationService.cs | 8 +++---- .../Tracking/AzureTableClient.cs | 8 +++---- .../Tracking/AzureTableInstanceStore.cs | 24 +++++++++---------- .../Tracking/JumpStartManager.cs | 10 ++++---- .../OrchestrationHubTableClientTests.cs | 4 ++-- 6 files changed, 32 insertions(+), 32 deletions(-) diff --git a/src/DurableTask.Core/IOrchestrationServiceInstanceStore.cs b/src/DurableTask.Core/IOrchestrationServiceInstanceStore.cs index 209048380..52c4dbf9b 100644 --- a/src/DurableTask.Core/IOrchestrationServiceInstanceStore.cs +++ b/src/DurableTask.Core/IOrchestrationServiceInstanceStore.cs @@ -44,7 +44,7 @@ public interface IOrchestrationServiceInstanceStore /// Writes a list of history events to instance store /// /// List of history events to write - Task WriteEntitesAsync(IEnumerable entities); + Task WriteEntitiesAsync(IEnumerable entities); /// /// Get a list of state events from instance store @@ -52,13 +52,13 @@ public interface IOrchestrationServiceInstanceStore /// The instance id to return state for /// The execution id to return state for /// The matching orchestation state or null if not found - Task> GetEntitesAsync(string instanceId, string executionId); + Task> GetEntitiesAsync(string instanceId, string executionId); /// /// Deletes a list of history events from instance store /// /// List of history events to delete - Task DeleteEntitesAsync(IEnumerable entities); + Task DeleteEntitiesAsync(IEnumerable entities); /// /// Gets a list of orchestration states for a given instance @@ -96,7 +96,7 @@ public interface IOrchestrationServiceInstanceStore /// Writes a list of jump start events to instance store /// /// List of jump start events to write - Task WriteJumpStartEntitesAsync(IEnumerable entities); + Task WriteJumpStartEntitiesAsync(IEnumerable entities); /// /// Deletes a list of jump start events from instance store @@ -108,6 +108,6 @@ public interface IOrchestrationServiceInstanceStore /// Get a list of jump start events from instance store /// /// List of jump start events - Task> GetJumpStartEntitesAsync(int top); + Task> GetJumpStartEntitiesAsync(int top); } } diff --git a/src/DurableTask.ServiceBus/ServiceBusOrchestrationService.cs b/src/DurableTask.ServiceBus/ServiceBusOrchestrationService.cs index 9bf627d9e..95472c7bc 100644 --- a/src/DurableTask.ServiceBus/ServiceBusOrchestrationService.cs +++ b/src/DurableTask.ServiceBus/ServiceBusOrchestrationService.cs @@ -514,7 +514,7 @@ Task UpdateInstanceStoreAsync(ExecutionStartedEvent executionStartedEvent, long SequenceNumber = sequenceNumber }; - return this.InstanceStore.WriteEntitesAsync(new[] { orchestrationStateEntity }); + return this.InstanceStore.WriteEntitiesAsync(new[] { orchestrationStateEntity }); } ServiceBusOrchestrationSession GetSessionInstanceForWorkItem(TaskOrchestrationWorkItem workItem) @@ -990,7 +990,7 @@ public async Task UpdateJumpStartStoreAsync(TaskMessage creationMessage) JumpStartTime = DateTimeUtils.MinDateTime }; - await this.InstanceStore.WriteJumpStartEntitesAsync(new[] { jumpStartEntity }); + await this.InstanceStore.WriteJumpStartEntitiesAsync(new[] { jumpStartEntity }); } /// @@ -1331,7 +1331,7 @@ async Task ProcessTrackingWorkItemAsync(TrackingWorkItem workItem) try { - await InstanceStore.WriteEntitesAsync(historyEntities); + await InstanceStore.WriteEntitiesAsync(historyEntities); } catch (Exception e) when (!Utils.IsFatal(e)) { @@ -1344,7 +1344,7 @@ async Task ProcessTrackingWorkItemAsync(TrackingWorkItem workItem) // TODO : send batch to instance store, it can write it as individual if it chooses foreach (OrchestrationStateInstanceEntity stateEntity in stateEntities) { - await InstanceStore.WriteEntitesAsync(new List { stateEntity }); + await InstanceStore.WriteEntitiesAsync(new List { stateEntity }); } } catch (Exception e) when (!Utils.IsFatal(e)) diff --git a/src/DurableTask.ServiceBus/Tracking/AzureTableClient.cs b/src/DurableTask.ServiceBus/Tracking/AzureTableClient.cs index 7a1950109..0a91c19a9 100644 --- a/src/DurableTask.ServiceBus/Tracking/AzureTableClient.cs +++ b/src/DurableTask.ServiceBus/Tracking/AzureTableClient.cs @@ -465,17 +465,17 @@ async Task ExecuteBatchOperationAsync(string operationTag, CloudTable table, Tab } } - public async Task WriteEntitesAsync(IEnumerable entities) + public async Task WriteEntitiesAsync(IEnumerable entities) { return await PerformBatchTableOperationAsync("Write Entities", this.historyTable, entities, (bo, te) => bo.InsertOrReplace(te)); } - public async Task WriteJumpStartEntitesAsync(IEnumerable entities) + public async Task WriteJumpStartEntitiesAsync(IEnumerable entities) { return await PerformBatchTableOperationAsync("Write Entities", this.jumpStartTable, entities, (bo, te) => bo.InsertOrReplace(te)); } - public async Task DeleteEntitesAsync(IEnumerable entities) + public async Task DeleteEntitiesAsync(IEnumerable entities) { return await PerformBatchTableOperationAsync("Delete Entities", this.historyTable, entities, (bo, te) => { @@ -497,7 +497,7 @@ public async Task DeleteJumpStartEntitiesAsync(IEnumerable /// List of history events to write - public async Task WriteEntitesAsync(IEnumerable entities) + public async Task WriteEntitiesAsync(IEnumerable entities) { - return await Utils.ExecuteWithRetries(() => this.tableClient.WriteEntitesAsync(entities.Select(HistoryEventToTableEntity)), + return await Utils.ExecuteWithRetries(() => this.tableClient.WriteEntitiesAsync(entities.Select(HistoryEventToTableEntity)), string.Empty, - "WriteEntitesAsync", + "WriteEntitiesAsync", MaxRetriesTableStore, IntervalBetweenRetriesSecs); } @@ -102,7 +102,7 @@ public async Task WriteEntitesAsync(IEnumerable enti /// The instance id to return state for /// The execution id to return state for /// The matching orchestation state or null if not found - public async Task> GetEntitesAsync(string instanceId, string executionId) + public async Task> GetEntitiesAsync(string instanceId, string executionId) { IEnumerable results = await this.tableClient.QueryOrchestrationStatesAsync( @@ -115,11 +115,11 @@ await this.tableClient.QueryOrchestrationStatesAsync( /// Deletes a list of history events from storage with retries for transient errors /// /// List of history events to delete - public async Task DeleteEntitesAsync(IEnumerable entities) + public async Task DeleteEntitiesAsync(IEnumerable entities) { - return await Utils.ExecuteWithRetries(() => this.tableClient.DeleteEntitesAsync(entities.Select(HistoryEventToTableEntity)), + return await Utils.ExecuteWithRetries(() => this.tableClient.DeleteEntitiesAsync(entities.Select(HistoryEventToTableEntity)), string.Empty, - "DeleteEntitesAsync", + "DeleteEntitiesAsync", MaxRetriesTableStore, IntervalBetweenRetriesSecs); } @@ -319,21 +319,21 @@ await Task.WhenAll(orchestrationStateEntitySegment.Results.Select( }))); List historyDeleteTasks = historyEntitiesToDelete.Select( - historyEventList => tableClient.DeleteEntitesAsync(historyEventList)).Cast().ToList(); + historyEventList => tableClient.DeleteEntitiesAsync(historyEventList)).Cast().ToList(); // need to serialize history deletes before the state deletes so we dont leave orphaned history events await Task.WhenAll(historyDeleteTasks).ConfigureAwait(false); - await Task.WhenAll(tableClient.DeleteEntitesAsync(stateEntitiesToDelete)).ConfigureAwait(false); + await Task.WhenAll(tableClient.DeleteEntitiesAsync(stateEntitiesToDelete)).ConfigureAwait(false); } /// /// Writes a list of jump start events to instance store /// /// List of jump start events to write - public Task WriteJumpStartEntitesAsync(IEnumerable entities) + public Task WriteJumpStartEntitiesAsync(IEnumerable entities) { var jumpStartEntities = entities.Select(e => new AzureTableOrchestrationJumpStartEntity(e)); - return this.tableClient.WriteJumpStartEntitesAsync(jumpStartEntities); + return this.tableClient.WriteJumpStartEntitiesAsync(jumpStartEntities); } /// @@ -350,7 +350,7 @@ public Task DeleteJumpStartEntitiesAsync(IEnumerable /// List of jump start events - public async Task> GetJumpStartEntitesAsync(int top) + public async Task> GetJumpStartEntitiesAsync(int top) { return (await this.tableClient.QueryJumpStartOrchestrationsAsync( DateTime.UtcNow.AddDays(-AzureTableClient.JumpStartTableScanIntervalInDays), diff --git a/src/DurableTask.ServiceBus/Tracking/JumpStartManager.cs b/src/DurableTask.ServiceBus/Tracking/JumpStartManager.cs index 874d10985..b1b9cf0ac 100644 --- a/src/DurableTask.ServiceBus/Tracking/JumpStartManager.cs +++ b/src/DurableTask.ServiceBus/Tracking/JumpStartManager.cs @@ -81,7 +81,7 @@ public async Task JumpStartAsync() TraceHelper.Trace(TraceEventType.Information, "JumpStartManager-Fetch-Begin", "Jump start starting fetch"); // TODO: Query in batchces and change timeframe only after curent range is finished - IEnumerable entities = await this.service.InstanceStore.GetJumpStartEntitesAsync(1000); + IEnumerable entities = await this.service.InstanceStore.GetJumpStartEntitiesAsync(1000); TraceHelper.Trace( TraceEventType.Information, "JumpStartManager-Fetch-End", @@ -129,7 +129,7 @@ public async Task JumpStartAsync() protected async Task JumpStartOrchestrationAsync(OrchestrationJumpStartInstanceEntity jumpStartEntity) { var instance = jumpStartEntity.State.OrchestrationInstance; - OrchestrationStateInstanceEntity stateEntity = (await this.service.InstanceStore.GetEntitesAsync(instance.InstanceId, instance.ExecutionId))?.FirstOrDefault(); + OrchestrationStateInstanceEntity stateEntity = (await this.service.InstanceStore.GetEntitiesAsync(instance.InstanceId, instance.ExecutionId))?.FirstOrDefault(); if (stateEntity != null) { // It seems orchestration started, delete entity from JumpStart table @@ -161,12 +161,12 @@ protected async Task JumpStartOrchestrationAsync(OrchestrationJumpStartInstanceE // Now update the JumpStart table jumpStartEntity.JumpStartTime = DateTime.UtcNow; - await this.service.InstanceStore.WriteJumpStartEntitesAsync(new[] { jumpStartEntity }); + await this.service.InstanceStore.WriteJumpStartEntitiesAsync(new[] { jumpStartEntity }); TraceHelper.Trace( TraceEventType.Information, - "JumpStartManager-WriteJumpStartEntites", - $"JumpStartManager: WriteJumpStartEntitesAsync({instance.InstanceId}, {instance.ExecutionId}) success!"); + "JumpStartManager-WriteJumpStartEntities", + $"JumpStartManager: WriteJumpStartEntitiesAsync({instance.InstanceId}, {instance.ExecutionId}) success!"); } } } diff --git a/test/DurableTask.ServiceBus.Tests/OrchestrationHubTableClientTests.cs b/test/DurableTask.ServiceBus.Tests/OrchestrationHubTableClientTests.cs index 816f13b85..fa8784b4e 100644 --- a/test/DurableTask.ServiceBus.Tests/OrchestrationHubTableClientTests.cs +++ b/test/DurableTask.ServiceBus.Tests/OrchestrationHubTableClientTests.cs @@ -303,7 +303,7 @@ IEnumerable CreateHistoryEntities(Azu historyEntities.Add(new AzureTableOrchestrationHistoryEventEntity(instanceId, genId, i, DateTime.Now, eeStartedEvent)); } - client.WriteEntitesAsync(historyEntities).Wait(); + client.WriteEntitiesAsync(historyEntities).Wait(); return historyEntities; } @@ -328,7 +328,7 @@ IEnumerable CreateStateEntities(AzureTableCl }; entities.Add(new AzureTableOrchestrationStateEntity(runtimeState)); - client.WriteEntitesAsync(entities).Wait(); + client.WriteEntitiesAsync(entities).Wait(); return entities; }