feat(log): ts before and after for each log entry and refactoring

Author: S1M0N38

src/lua/log.lua

@@ -5,16 +5,16 @@ LOG = {
   mod_path = nil,
   current_run_file = nil,
   pending_logs = {},
-  previous_game_state = nil,
+  game_state_before = {},
 }
 
 -- =============================================================================
 -- Utility Functions
 -- =============================================================================
 
 ---Writes a log entry to the JSONL file
----@param log_entry table The log entry to write
-local function write_log_entry(log_entry)
+---@param log_entry LogEntry The log entry to write
+function LOG.write(log_entry)
   if LOG.current_run_file then
     local log_line = json.encode(log_entry) .. "\n"
     local file = io.open(LOG.current_run_file, "a")
@@ -31,44 +31,36 @@ end
 function LOG.update()
   for key, pending_log in pairs(LOG.pending_logs) do
     if pending_log.condition() then
+      -- Update the log entry with after function call info
+      pending_log.log_entry["timestamp_ms_after"] = math.floor(socket.gettime() * 1000)
       pending_log.log_entry["game_state_after"] = utils.get_game_state()
-      write_log_entry(pending_log.log_entry)
-      LOG.previous_game_state = pending_log.log_entry.game_state_after
+      LOG.write(pending_log.log_entry)
+      -- Prepare for the next log entry
+      LOG.game_state_before = pending_log.log_entry.game_state_after
       LOG.pending_logs[key] = nil
     end
   end
 end
 
----Logs a function call to the JSONL file with completion waiting
----@param original_function function The original function being called
+--- Schedules a log entry to be written when the condition is met
 ---@param function_call FunctionCall The function call to log
-function LOG.write(original_function, function_call, ...)
+function LOG.schedule_write(function_call)
+  sendInfoMessage(function_call.name .. "(" .. json.encode(function_call.arguments) .. ")", "LOG")
+
   local log_entry = {
-    timestamp_ms = math.floor(socket.gettime() * 1000),
     ["function"] = function_call,
-    game_state_before = LOG.previous_game_state,
+    -- before function call
+    timestamp_ms_before = math.floor(socket.gettime() * 1000),
+    game_state_before = LOG.game_state_before,
+    -- after function call (will be filled in by LOG.write)
+    timestamp_ms_after = nil,
+    game_state_after = nil,
+  }
+  local pending_key = function_call.name .. "_" .. tostring(socket.gettime())
+  LOG.pending_logs[pending_key] = {
+    log_entry = log_entry,
+    condition = utils.COMPLETION_CONDITIONS[function_call.name],
   }
-
-  local result = original_function(...)
-  sendInfoMessage(function_call.name .. "(" .. json.encode(function_call.arguments) .. ")", "LOG")
-
-  -- Get completion condition by function name
-  local condition = utils.COMPLETION_CONDITIONS[function_call.name]
-  if condition then
-    -- Create a unique key for the pending log
-    local pending_key = function_call.name .. "_" .. tostring(socket.gettime())
-    LOG.pending_logs[pending_key] = {
-      log_entry = log_entry,
-      condition = condition,
-    }
-  else
-    -- Immediate logging if no condition found
-    log_entry["game_state_after"] = utils.get_game_state()
-    write_log_entry(log_entry)
-    LOG.previous_game_state = log_entry.game_state_after
-  end
-
-  return result
 end
 
 -- =============================================================================
@@ -87,7 +79,8 @@ function hook_go_to_menu()
       name = "go_to_menu",
       arguments = {},
     }
-    return LOG.write(original_function, function_call, ...)
+    LOG.schedule_write(function_call)
+    return original_function(...)
   end
   sendDebugMessage("Hooked into G.FUNCS.go_to_menu for logging", "LOG")
 end
@@ -124,7 +117,8 @@ function hook_start_run()
         challenge = args.challenge and args.challenge.name,
       },
     }
-    return LOG.write(original_function, function_call, game_state, args)
+    LOG.schedule_write(function_call)
+    return original_function(game_state, args)
   end
   sendDebugMessage("Hooked into G.FUNCS.start_run for logging", "LOG")
 end
@@ -138,7 +132,8 @@ function hook_select_blind()
   local original_function = G.FUNCS.select_blind
   G.FUNCS.select_blind = function(args)
     local function_call = { name = "skip_or_select_blind", arguments = { action = "select" } }
-    return LOG.write(original_function, function_call, args)
+    LOG.schedule_write(function_call)
+    return original_function(args)
   end
   sendDebugMessage("Hooked into G.FUNCS.select_blind for logging", "LOG")
 end
@@ -148,7 +143,8 @@ function hook_skip_blind()
   local original_function = G.FUNCS.skip_blind
   G.FUNCS.skip_blind = function(args)
     local function_call = { name = "skip_or_select_blind", arguments = { action = "skip" } }
-    return LOG.write(original_function, function_call, args)
+    LOG.schedule_write(function_call)
+    return original_function(args)
   end
   sendDebugMessage("Hooked into G.FUNCS.skip_blind for logging", "LOG")
 end
@@ -168,7 +164,8 @@ function hook_play_cards_from_highlighted()
       end
     end
     local function_call = { name = "play_hand_or_discard", arguments = { action = "play_hand", cards = cards } }
-    return LOG.write(original_function, function_call, ...)
+    LOG.schedule_write(function_call)
+    return original_function(...)
   end
   sendDebugMessage("Hooked into G.FUNCS.play_cards_from_highlighted for logging", "LOG")
 end
@@ -184,7 +181,8 @@ function hook_discard_cards_from_highlighted()
       end
     end
     local function_call = { name = "play_hand_or_discard", arguments = { action = "discard", cards = cards } }
-    return LOG.write(original_function, function_call, ...)
+    LOG.schedule_write(function_call)
+    return original_function(...)
   end
   sendDebugMessage("Hooked into G.FUNCS.discard_cards_from_highlighted for logging", "LOG")
 end
@@ -198,7 +196,8 @@ function hook_cash_out()
   local original_function = G.FUNCS.cash_out
   G.FUNCS.cash_out = function(...)
     local function_call = { name = "cash_out", arguments = {} }
-    return LOG.write(original_function, function_call, ...)
+    LOG.schedule_write(function_call)
+    return original_function(...)
   end
   sendDebugMessage("Hooked into G.FUNCS.cash_out for logging", "LOG")
 end
@@ -212,7 +211,8 @@ function hook_toggle_shop()
   local original_function = G.FUNCS.toggle_shop
   G.FUNCS.toggle_shop = function(...)
     local function_call = { name = "shop", arguments = { action = "next_round" } }
-    return LOG.write(original_function, function_call, ...)
+    LOG.schedule_write(function_call)
+    return original_function(...)
   end
   sendDebugMessage("Hooked into G.FUNCS.toggle_shop for logging", "LOG")
 end
@@ -273,34 +273,30 @@ function hook_hand_rearrange()
             arguments = { cards = cards },
           }
 
-          --- NOTE: we cannot use LOG.write because we do not have access to game_state_before. We need to recreate it.
-          --- The following lines corresponds to LOG.write
+          -- NOTE: we cannot schedule a log write because we don't have access to the
+          -- state before the function call. We need to recreate it.
+
+          -- HACK: we cannot compute the timestamp before in the right way the function
+          -- call because because this hook run with the game loop. So we use the
+          -- timestamp for after and before
+
+          local timestamp_ms = math.floor(socket.gettime() * 1000)
 
           local log_entry = {
-            timestamp_ms = math.floor(socket.gettime() * 1000),
             ["function"] = function_call,
-            game_state_before = previous_game_state,
+            timestamp_ms_before = timestamp_ms,
+            game_state_before = LOG.game_state_before,
+            timestamp_ms_after = timestamp_ms,
             game_state_after = utils.get_game_state(),
           }
-          LOG.previous_game_state = log_entry.game_state_after
 
           sendInfoMessage(function_call.name .. "(" .. json.encode(function_call.arguments) .. ")", "LOG")
-
-          if LOG.current_run_file then
-            local log_line = json.encode(log_entry) .. "\n"
-            local file = io.open(LOG.current_run_file, "a")
-            if file then
-              file:write(log_line)
-              file:close()
-            else
-              sendErrorMessage("Failed to open log file for writing: " .. LOG.current_run_file, "LOG")
-            end
-          end
+          LOG.write(log_entry)
+          LOG.game_state_before = log_entry.game_state_after
         end
       end
 
       previous_order = current_order
-      previous_game_state = utils.get_game_state()
       return result
     else
       -- For non-hand card areas, just call the original function