Improvements in trace output:

- Scheduled calls are traced with ---> or +++> prefixes... This is handy to find where scheduled calls were actually called in the code. Line number and function is shown correctly now. ---> is for one schedule, and +++> for repeated schedules.
- Fsm output is now also organized better. All Fsm calls are shown with :::> prefix. The onafter, onbefore, onenter or onleave method names are also shown, and also the state transition including the function call place is shown now.
-- Now for each trace line, the class name has 30 characters space.

Moose Development/Moose/Core/Base.lua

@@ -891,6 +891,26 @@ end
 -- Log a trace (only shown when trace is on)
 -- TODO: Make trace function using variable parameters.
 
+--- Set trace on.
+-- @param #BASE self
+-- @usage
+-- -- Switch the tracing On
+-- BASE:TraceOn()
+function BASE:TraceOn()
+  self:TraceOnOff( true )
+end
+
+--- Set trace off.
+-- @param #BASE self
+-- @usage
+-- -- Switch the tracing Off
+-- BASE:TraceOff()
+function BASE:TraceOff()
+  self:TraceOnOff( false )
+end
+
+
+
 --- Set trace on or off
 -- Note that when trace is off, no BASE.Debug statement is performed, increasing performance!
 -- When Moose is loaded statically, (as one file), tracing is switched off by default.
@@ -905,7 +925,7 @@ end
 -- -- Switch the tracing Off
 -- BASE:TraceOnOff( false )
 function BASE:TraceOnOff( TraceOnOff )
-  _TraceOnOff = TraceOnOff
+  _TraceOnOff = TraceOnOff or true
 end
 
 
@@ -925,8 +945,8 @@ end
 -- @param #BASE self
 -- @param #number Level
 function BASE:TraceLevel( Level )
-  _TraceLevel = Level
+  _TraceLevel = Level or 1
-  self:I( "Tracing level " .. Level )
+  self:I( "Tracing level " .. _TraceLevel )
 end
 
 --- Trace all methods in MOOSE
@@ -934,7 +954,7 @@ end
 -- @param #boolean TraceAll true = trace all methods in MOOSE.
 function BASE:TraceAll( TraceAll )
   
-  _TraceAll = TraceAll
+  _TraceAll = TraceAll or true
   
   if _TraceAll then
     self:I( "Tracing all methods in MOOSE " )
@@ -989,7 +1009,7 @@ function BASE:_F( Arguments, DebugInfoCurrentParam, DebugInfoFromParam )
       if DebugInfoFrom then
         LineFrom = DebugInfoFrom.currentline
       end
-      env.info( string.format( "%6d(%6d)/%1s:%25s%05d.%s(%s)" , LineCurrent, LineFrom, "F", self.ClassName, self.ClassID, Function, routines.utils.oneLineSerialize( Arguments ) ) )
+      env.info( string.format( "%6d(%6d)/%1s:%30s%05d.%s(%s)" , LineCurrent, LineFrom, "F", self.ClassName, self.ClassID, Function, routines.utils.oneLineSerialize( Arguments ) ) )
     end
   end
 end
@@ -1064,7 +1084,7 @@ function BASE:_T( Arguments, DebugInfoCurrentParam, DebugInfoFromParam )
   		if DebugInfoFrom then
   		  LineFrom = DebugInfoFrom.currentline
   	  end
-  		env.info( string.format( "%6d(%6d)/%1s:%25s%05d.%s" , LineCurrent, LineFrom, "T", self.ClassName, self.ClassID, routines.utils.oneLineSerialize( Arguments ) ) )
+  		env.info( string.format( "%6d(%6d)/%1s:%30s%05d.%s" , LineCurrent, LineFrom, "T", self.ClassName, self.ClassID, routines.utils.oneLineSerialize( Arguments ) ) )
     end
 	end
 end
@@ -1135,9 +1155,9 @@ function BASE:E( Arguments )
   	  LineFrom = DebugInfoFrom.currentline
   	end
   
-  	env.info( string.format( "%6d(%6d)/%1s:%25s%05d.%s(%s)" , LineCurrent, LineFrom, "E", self.ClassName, self.ClassID, Function, routines.utils.oneLineSerialize( Arguments ) ) )
+  	env.info( string.format( "%6d(%6d)/%1s:%30s%05d.%s(%s)" , LineCurrent, LineFrom, "E", self.ClassName, self.ClassID, Function, routines.utils.oneLineSerialize( Arguments ) ) )
   else
-    env.info( string.format( "%1s:%25s%05d(%s)" , "E", self.ClassName, self.ClassID, routines.utils.oneLineSerialize( Arguments ) ) )
+    env.info( string.format( "%1s:%30s%05d(%s)" , "E", self.ClassName, self.ClassID, routines.utils.oneLineSerialize( Arguments ) ) )
   end
   
 end
@@ -1163,9 +1183,9 @@ function BASE:I( Arguments )
       LineFrom = DebugInfoFrom.currentline
     end
   
-    env.info( string.format( "%6d(%6d)/%1s:%25s%05d.%s(%s)" , LineCurrent, LineFrom, "I", self.ClassName, self.ClassID, Function, routines.utils.oneLineSerialize( Arguments ) ) )
+    env.info( string.format( "%6d(%6d)/%1s:%30s%05d.%s(%s)" , LineCurrent, LineFrom, "I", self.ClassName, self.ClassID, Function, routines.utils.oneLineSerialize( Arguments ) ) )
   else
-    env.info( string.format( "%1s:%25s%05d(%s)" , "I", self.ClassName, self.ClassID, routines.utils.oneLineSerialize( Arguments ) ) )
+    env.info( string.format( "%1s:%30s%05d(%s)" , "I", self.ClassName, self.ClassID, routines.utils.oneLineSerialize( Arguments ) ) )
   end
   
 end

Moose Development/Moose/Core/Fsm.lua

@@ -594,7 +594,17 @@ do -- FSM
       return errmsg
     end
     if self[handler] then
-      self:T( "*** FSM ***    " .. step .. " *** " .. params[1] .. " --> " .. params[2] .. " --> " .. params[3] )
+      if step == "onafter" or step == "OnAfter" then
+        self:T( ":::>" .. step .. params[2] .. " : " .. params[1] .. " >> " .. params[2] .. ">" .. step .. params[2] .. "()" .. " >> " .. params[3] )
+      elseif step == "onbefore" or step == "OnBefore" then
+        self:T( ":::>" .. step .. params[2] .. " : " .. params[1] .. " >> " .. step .. params[2] .. "()" .. ">" .. params[2] .. " >> " .. params[3] )
+      elseif step == "onenter" or step == "OnEnter" then
+        self:T( ":::>" .. step .. params[3] .. " : " .. params[1] .. " >> " .. params[2] .. " >> "  .. step .. params[3] .. "()" .. ">" .. params[3] )
+      elseif step == "onleave" or step == "OnLeave" then
+        self:T( ":::>" .. step .. params[1] .. " : " .. params[1] .. ">" .. step .. params[1] .. "()" .. " >> " .. params[2] .. " >> " .. params[3] )
+      else
+        self:T( ":::>" .. step .. " : " .. params[1] .. " >> " .. params[2] .. " >> " .. params[3] )
+      end      
       self._EventSchedules[EventName] = nil
       local Result, Value = xpcall( function() return self[handler]( self, unpack( params ) ) end, ErrorHandler )
       return Value
@@ -718,13 +728,13 @@ do -- FSM
         if DelaySeconds < 0 then -- Only call the event ONCE!
           DelaySeconds = math.abs( DelaySeconds )
           if not self._EventSchedules[EventName] then
-            CallID = self.CallScheduler:Schedule( self, self._handler, { EventName, ... }, DelaySeconds or 1, nil, nil, nil, 4 )
+            CallID = self.CallScheduler:Schedule( self, self._handler, { EventName, ... }, DelaySeconds or 1, nil, nil, nil, 4, true )
             self._EventSchedules[EventName] = CallID
           else
             -- reschedule
           end
         else
-          CallID = self.CallScheduler:Schedule( self, self._handler, { EventName, ... }, DelaySeconds or 1, nil, nil, nil, 4 )
+          CallID = self.CallScheduler:Schedule( self, self._handler, { EventName, ... }, DelaySeconds or 1, nil, nil, nil, 4, true )
         end
       else
         error( "FSM: An asynchronous event trigger requires a DelaySeconds parameter!!! This can be positive or negative! Sorry, but will not process this." )

Moose Development/Moose/Core/ScheduleDispatcher.lua

@@ -52,7 +52,7 @@ end
 -- Nothing of this code should be modified without testing it thoroughly.
 -- @param #SCHEDULEDISPATCHER self
 -- @param Core.Scheduler#SCHEDULER Scheduler
-function SCHEDULEDISPATCHER:AddSchedule( Scheduler, ScheduleFunction, ScheduleArguments, Start, Repeat, Randomize, Stop, TraceLevel )
+function SCHEDULEDISPATCHER:AddSchedule( Scheduler, ScheduleFunction, ScheduleArguments, Start, Repeat, Randomize, Stop, TraceLevel, Fsm )
   self:F2( { Scheduler, ScheduleFunction, ScheduleArguments, Start, Repeat, Randomize, Stop, TraceLevel } )
 
   self.CallID = self.CallID + 1
@@ -85,13 +85,40 @@ function SCHEDULEDISPATCHER:AddSchedule( Scheduler, ScheduleFunction, ScheduleAr
   self.Schedule[Scheduler][CallID].Randomize = Randomize or 0
   self.Schedule[Scheduler][CallID].Stop = Stop
   
-  local Source = ""
+  
-  local Line = ""
+  -- This section handles the tracing of the scheduled calls.
+  -- Because these calls will be executed with a delay, we inspect the place where these scheduled calls are initiated.
+  -- The Info structure contains the output of the debug.getinfo() calls, which inspects the call stack for the function name, line number and source name.
+  -- The call stack has many levels, and the correct semantical function call depends on where in the code AddSchedule was "used".
+  --   - Using SCHEDULER:New()
+  --   - Using Schedule:AddSchedule()
+  --   - Using Fsm:__Func()
+  --   - Using Class:ScheduleOnce()
+  --   - Using Class:ScheduleRepeat()
+  --   - ...
+  -- So for each of these scheduled call variations, AddSchedule is the workhorse which will schedule the call.
+  -- But the correct level with the correct semantical function location will differ depending on the above scheduled call invocation forms.
+  -- That's where the field TraceLevel contains optionally the level in the call stack where the call information is obtained.
+  -- The TraceLevel field indicates the correct level where the semantical scheduled call was invoked within the source, ensuring that function name, line number and source name are correct.
+  -- There is one quick ...
+  -- The FSM class models scheduled calls using the __Func syntax. However, these functions are "tailed".
+  -- There aren't defined anywhere within the source code, but rather implemented as triggers within the FSM logic, 
+  -- and using the onbefore, onafter, onenter, onleave prefixes. (See the FSM for details).
+  -- Therefore, in the call stack, at the TraceLevel these functions are mentioned as "tail calls", and the Info.name field will be nil as a result.
+  -- To obtain the correct function name for FSM object calls, the function is mentioned in the call stack at a higher stack level.
+  -- So when function name stored in Info.name is nil, then I inspect the function name within the call stack one level higher.
+  -- So this little piece of code does its magic wonderfully, preformance overhead is neglectible, as scheduled calls don't happen that often.
+
+  local Info = {}
   
   if debug then
     TraceLevel = TraceLevel or 2
-    Source = debug.getinfo( TraceLevel, "S" ).source
+    Info = debug.getinfo( TraceLevel, "nlS" )
-    Line = debug.getinfo( TraceLevel, "nl" ).currentline
+    local name_fsm = debug.getinfo( TraceLevel - 1, "n" ).name -- #string
+    if name_fsm then
+      Info.name = name_fsm
+    end
+    --env.info( debug.traceback() )
   end
 
   self:T3( self.Schedule[Scheduler][CallID] )
@@ -99,8 +126,10 @@ function SCHEDULEDISPATCHER:AddSchedule( Scheduler, ScheduleFunction, ScheduleAr
   self.Schedule[Scheduler][CallID].CallHandler = function( Params )
     
     local CallID = Params.CallID
-    local Source = Params.Source
+    local Info = Params.Info
-    local Line = Params.Line
+    local Source = Info.source
+    local Line = Info.currentline
+    local Name = Info.name or "?"
 
     local ErrorHandler = function( errmsg )
       env.info( "Error in timer function: " .. errmsg )
@@ -134,19 +163,19 @@ function SCHEDULEDISPATCHER:AddSchedule( Scheduler, ScheduleFunction, ScheduleAr
       local Stop = Schedule.Stop or 0
       local ScheduleID = Schedule.ScheduleID
       
-      local Prefix = ( Repeat == 0 ) and " ---> " or " +++> "
+      local Prefix = ( Repeat == 0 ) and "--->" or "+++>"
       
       local Status, Result
       --self:E( { SchedulerObject = SchedulerObject } )
       if SchedulerObject then
         local function Timer()
-          SchedulerObject:T( Prefix .. ( Source or "-" ) .. ": " .. ( Line or "-" ) )
+          SchedulerObject:T( Prefix .. Name .. ":" .. Line .. " (" .. Source .. ")" )
           return ScheduleFunction( SchedulerObject, unpack( ScheduleArguments ) ) 
         end
         Status, Result = xpcall( Timer, ErrorHandler )
       else
         local function Timer()
-          self:T( Prefix .. ( Source or "-" ) .. ": " .. ( Line or "-" ) )
+          self:T( Prefix .. Name .. ":" .. Line .. " (" .. Source .. ")" )
           return ScheduleFunction( unpack( ScheduleArguments ) ) 
         end
         Status, Result = xpcall( Timer, ErrorHandler )
@@ -177,13 +206,13 @@ function SCHEDULEDISPATCHER:AddSchedule( Scheduler, ScheduleFunction, ScheduleAr
         self:Stop( Scheduler, CallID )
       end
     else
-      self:I( " <<<> " .. ( Source or "-" ) .. ": " .. ( Line or "-" ) )
+      self:I( "<<<>" .. Name .. ":" .. Line .. " (" .. Source .. ")" )
     end
     
     return nil
   end
   
-  self:Start( Scheduler, CallID, Source, Line )
+  self:Start( Scheduler, CallID, Info )
   
   return CallID
 end
@@ -197,7 +226,7 @@ function SCHEDULEDISPATCHER:RemoveSchedule( Scheduler, CallID )
   end
 end
 
-function SCHEDULEDISPATCHER:Start( Scheduler, CallID, Source, Line )
+function SCHEDULEDISPATCHER:Start( Scheduler, CallID, Info )
   self:F2( { Start = CallID, Scheduler = Scheduler } )
 
   if CallID then
@@ -208,13 +237,13 @@ function SCHEDULEDISPATCHER:Start( Scheduler, CallID, Source, Line )
       Schedule[CallID].StartTime = timer.getTime()  -- Set the StartTime field to indicate when the scheduler started.
       Schedule[CallID].ScheduleID = timer.scheduleFunction( 
         Schedule[CallID].CallHandler, 
-        { CallID = CallID, Source = Source, Line = Line }, 
+        { CallID = CallID, Info = Info }, 
         timer.getTime() + Schedule[CallID].Start 
       )
     end
   else
     for CallID, Schedule in pairs( self.Schedule[Scheduler] or {} ) do
-      self:Start( Scheduler, CallID, Source, Line ) -- Recursive
+      self:Start( Scheduler, CallID, Info ) -- Recursive
     end
   end
 end

Moose Development/Moose/Core/Scheduler.lua

@@ -238,7 +238,7 @@ end
 -- @param #number RandomizeFactor Specifies a randomization factor between 0 and 1 to randomize the Repeat.
 -- @param #number Stop Specifies the amount of seconds when the scheduler will be stopped.
 -- @return #number The ScheduleID of the planned schedule.
-function SCHEDULER:Schedule( SchedulerObject, SchedulerFunction, SchedulerArguments, Start, Repeat, RandomizeFactor, Stop, TraceLevel )
+function SCHEDULER:Schedule( SchedulerObject, SchedulerFunction, SchedulerArguments, Start, Repeat, RandomizeFactor, Stop, TraceLevel, Fsm )
   self:F2( { Start, Repeat, RandomizeFactor, Stop } )
   self:T3( { SchedulerArguments } )
 
@@ -257,7 +257,8 @@ function SCHEDULER:Schedule( SchedulerObject, SchedulerFunction, SchedulerArgume
     Repeat,
     RandomizeFactor,
     Stop,
-    TraceLevel or 3
+    TraceLevel or 3,
+    Fsm
   )
   
   self.Schedules[#self.Schedules+1] = ScheduleID