case 10227: Add far more logging to workflow actions

daszat · Dec 6, 2013 · e627395 · e627395
1 parent 553f3f8
commit e627395
Show file tree

Hide file tree

Showing 5 changed files with 25 additions and 0 deletions.
diff --git a/Zetbox.Workflow.Common/Workflow/ActionActions.cs b/Zetbox.Workflow.Common/Workflow/ActionActions.cs
@@ -9,6 +9,7 @@ namespace Zetbox.Basic.Workflow
     using Zetbox.API;
     using Zetbox.API.Common;
     using Zetbox.App.Base;
+    using Zetbox.API.Utils;
 
 
     /// <summary>
@@ -56,12 +57,16 @@ public static void Execute(Action obj, ParameterizedActionDefinition paramedActi
             if (current == null) throw new ArgumentException("current");
             var identity = _idResolver.GetCurrent();
 
+            Logging.Log.InfoFormat("Executing workflow action [{0}].{1}", current, obj.Name);
+
             // call invocation
             if (_invocationExec.HasValidInvocation(obj))
             {
+                Logging.Log.DebugFormat("  calling invocation [{0}].{1}", obj.ImplementorName, obj.MemberName);
                 var result = _invocationExec.CallInvocation<bool>(obj, typeof(ActionInvocationPrototype), obj, paramedAction, current, identity);
                 if (result == false)
                 {
+                    Logging.Log.Info("  -> returned false, exiting");
                     return;
                 }
             }

diff --git a/Zetbox.Workflow.Common/Workflow/StateActions.cs b/Zetbox.Workflow.Common/Workflow/StateActions.cs
@@ -4,6 +4,7 @@
 using System.Text;
 using Zetbox.API;
 using Zetbox.App.Base;
+using Zetbox.API.Utils;
 
 namespace Zetbox.Basic.Workflow
 {
@@ -12,6 +13,8 @@ public static class StateActions
     {
         internal static State CreateState(WFInstance instance, StateDefinition def)
         {
+            Logging.Log.InfoFormat("Creating WorkflowState [{0}].{1}", instance, def.Name);
+
             var ctx = instance.Context;
             var state = ctx.Create<State>();
             state.Instance = instance;
@@ -45,6 +48,7 @@ public static void postSet_LeftOn(State obj, PropertyPostSetterEventArgs<DateTim
         [Invocation]
         public static void ScheduleAction(State obj, DateTime invokeOn, Zetbox.Basic.Workflow.ParameterizedActionDefinition action)
         {
+            Logging.Log.InfoFormat("Scheduling workflow action [{0}].[{1}].{2}", obj.Instance, obj, action.Name);
             var ctx = obj.Context;
 
             // Avoid multiple entries for same action on same state

diff --git a/Zetbox.Workflow.Common/Workflow/StateChangeDefinitionActions.cs b/Zetbox.Workflow.Common/Workflow/StateChangeDefinitionActions.cs
@@ -8,6 +8,7 @@ namespace Zetbox.Basic.Workflow
     using Zetbox.API;
     using Zetbox.API.Common;
     using Zetbox.App.Base;
+    using Zetbox.API.Utils;
 
     /// <summary>
     /// An state change invocation prototype. If nothing changes, return StateChange.NextStates. If the state should end, return null or empty. If specific states should be entered, return them.
@@ -65,17 +66,23 @@ public static void Execute(StateChangeDefinition obj, Zetbox.Basic.Workflow.Stat
         {
             var identity = _idResolver.GetCurrent();
 
+            Logging.Log.InfoFormat("Executing workflow StateChange [{0}].{1}", current, obj.Name);
+
             var nextStates = obj.NextStates.ToList();
             // call invocation
             if (_invocationExec.HasValidInvocation(obj))
             {
+                Logging.Log.DebugFormat("  calling invocation [{0}].{1}", obj.ImplementorName, obj.MemberName);
                 nextStates = _invocationExec.CallInvocation<List<StateDefinition>>(obj, typeof(StateChangeInvocationPrototype), obj, current, identity);
             }
 
+            Logging.Log.InfoFormat("  nextStates.Count = {0}", nextStates.Count);
+
             var stateEnds = true;
             if (nextStates == null || nextStates.Count == 0)
             {
                 // workflow branch ends here
+                Logging.Log.Info("No next states, workflow will end");
             }
             else
             {
@@ -84,6 +91,7 @@ public static void Execute(StateChangeDefinition obj, Zetbox.Basic.Workflow.Stat
                 {
                     if (stateDef == current.StateDefinition)
                     {
+                        Logging.Log.Info("Staying in current state");
                         stateEnds = false;
                     }
                     else

diff --git a/Zetbox.Workflow.Common/Workflow/WFInstanceActions.cs b/Zetbox.Workflow.Common/Workflow/WFInstanceActions.cs
@@ -8,6 +8,7 @@ namespace Zetbox.Basic.Workflow
     using Zetbox.API;
     using Zetbox.API.Common;
     using Zetbox.App.Base;
+    using Zetbox.API.Utils;
 
     [Implementor]
     public class WFInstanceActions
@@ -42,6 +43,7 @@ public static void Start(WFInstance obj, Zetbox.Basic.Workflow.WFDefinition work
         {
             if (workflow != null)
             {
+                Logging.Log.InfoFormat("Starting workflow {0}", workflow.Name);
                 obj.Workflow = workflow;
                 foreach (var stateDef in workflow.StateDefinitions.Where(s => s.IsStartState))
                 {
@@ -85,6 +87,7 @@ public static void AddLogEntry(WFInstance obj, string formatString)
                     .Replace("{User}", (identity ?? (object)string.Empty).ToString())
                     .Replace("{Date}", DateTime.Today.ToShortDateString())
                     .Replace("{Time}", DateTime.Now.ToShortTimeString());
+                Logging.Log.InfoFormat("Adding WF-Logentry: {0}", msg);
                 var logEntry = ctx.Create<LogEntry>();
                 logEntry.Message = msg;
                 logEntry.Identity = identity;

diff --git a/Zetbox.Workflow.Server/SchedulerService.cs b/Zetbox.Workflow.Server/SchedulerService.cs
@@ -97,6 +97,7 @@ private void OnTimer(object state)
                                         .Take(MAX_ITEMS_PER_BATCH)
                                         .ToList();
                                 if (nextSchedulerEntries.Count == 0) break;
+                                Logging.Server.InfoFormat("Found {0} SchedulerEntries", nextSchedulerEntries.Count);
                                 foreach (var entry in nextSchedulerEntries)
                                 {
                                     lock (_lock)
@@ -116,6 +117,10 @@ private void OnTimer(object state)
                                                 .Where(ad => ad.IsRecurrent)
                                                 .Where(ad => ad.InvokeAction == localEntry.Action)
                                                 .ToList();
+                                            Logging.Server.InfoFormat("  processing wf instance.state '{0}.{1}', {2} actions", 
+                                                localEntry.State.Instance,
+                                                localEntry.State.ToString(),
+                                                scheduledActions.Count);
                                             foreach(var sAction in scheduledActions)
                                             {
                                                 sAction.Action.Execute(sAction, localEntry.State);