#110 periodically call unserviced TCD callbacks

coordinator/startup.lua

@@ -16,7 +16,7 @@ local config       = require("coordinator.config")
 local coordinator  = require("coordinator.coordinator")
 local renderer     = require("coordinator.renderer")
 
-local COORDINATOR_VERSION = "alpha-v0.5.7"
+local COORDINATOR_VERSION = "alpha-v0.5.9"
 
 local print = util.print
 local println = util.println
@@ -181,8 +181,7 @@ if ui_ok then
     log_sys("system started successfully")
 end
 
--- event loop
--- ui_ok will never change in this loop, same as while true or exit if UI start failed
+-- main event loop
 while ui_ok do
     local event, param1, param2, param3, param4, param5 = util.pull_event()
 
@@ -299,6 +298,9 @@ while ui_ok do
         renderer.handle_touch(core.events.touch(param1, param2, param3))
     end
 
+    -- call unserviced TCD callbacks
+    tcallbackdsp.call_unserviced()
+
     -- check for termination request
     if event == "terminate" or ppm.should_terminate() then
         println_ts("terminate requested, closing connections...")

scada-common/tcallbackdsp.lua

@@ -9,6 +9,8 @@ local tcallbackdsp = {}
 
 local registry = {}
 
+local UNSERVICED_CALL_DELAY = util.TICK_TIME_S
+
 -- request a function to be called after the specified time
 ---@param time number seconds
 ---@param f function callback function
@@ -20,7 +22,7 @@ function tcallbackdsp.dispatch(time, f)
         expiry = time + util.time_s()
     }
 
-    log.debug("queued callback for " .. util.strval(f) .. " timer #" .. timer)
+    -- log.debug(util.c("TCD: queued callback for ", f, " [timer: ", timer, "]"))
 end
 
 -- request a function to be called after the specified time, aborting any registered instances of that function reference
@@ -31,7 +33,7 @@ function tcallbackdsp.dispatch_unique(time, f)
     for timer, entry in pairs(registry) do
         if entry.callback == f then
             -- found an instance of this function reference, abort it
-            log.debug(util.c("TCD: aborting duplicate timer callback (timer: ", timer, ", ", f, ")"))
+            log.debug(util.c("TCD: aborting duplicate timer callback [timer: ", timer, ", ", f, "]"))
 
             -- cancel event and remove from registry (even if it fires it won't call)
             util.cancel_timer(timer)
@@ -46,7 +48,7 @@ function tcallbackdsp.dispatch_unique(time, f)
         expiry = time + util.time_s()
     }
 
-    log.debug("queued callback for " .. util.strval(f) .. " timer #" .. timer)
+    -- log.debug(util.c("TCD: queued callback for ", f, " [timer: ", timer, "]"))
 end
 
 -- lookup a timer event and execute the callback if found
@@ -60,14 +62,44 @@ function tcallbackdsp.handle(event)
     end
 end
 
+-- execute any callbacks that are overdo their time and have not been serviced
+--
+-- this can be called periodically to prevent loss of any callbacks do to timer events that are lost (see github issue #110)
+function tcallbackdsp.call_unserviced()
+    local found_unserviced = true
+
+    while found_unserviced do
+        found_unserviced = false
+
+        -- go through registry, restart if unserviced entries were found due to mutating registry table
+        for timer, entry in pairs(registry) do
+            found_unserviced = util.time_s() > (entry.expiry + UNSERVICED_CALL_DELAY)
+            if found_unserviced then
+                local overtime = util.time_s() - entry.expiry
+                local callback = entry.callback
+
+                log.warning(util.c("TCD: executing unserviced callback ", entry.callback, " (", overtime, "s late) [timer: ", timer, "]"))
+
+                -- clear first so that dispatch_unique call from inside callback won't see it as a conflict
+                registry[timer] = nil
+                callback()
+                break
+            end
+        end
+    end
+end
+
 -- identify any overdo callbacks
 --
 -- prints to log debug output
 function tcallbackdsp.diagnostics()
     for timer, entry in pairs(registry) do
-        if entry.expiry >= util.time_s() then
+        if entry.expiry < util.time_s() then
             local overtime = util.time_s() - entry.expiry
             log.debug(util.c("TCD: unserviced timer ", timer, " for callback ", entry.callback, " is at least ", overtime, "s late"))
+        else
+            local time = entry.expiry - util.time_s()
+            log.debug(util.c("TCD: pending timer ", timer, " for callback ", entry.callback, " (call after ", entry.duration, "s, expires ", time, ")"))
         end
     end
 end

scada-common/util.lua

@@ -5,6 +5,11 @@
 ---@class util
 local util = {}
 
+-- ENVIRONMENT CONSTANTS --
+
+util.TICK_TIME_S = 0.05
+util.TICK_TIME_MS = 50
+
 -- OPERATORS --
 
 -- trinary operator