Fix dangling sessions and invalid players

Fixes dangling sessions that get more time than they should, and fixes error spam when players disconnect (prevents invalid players from having their time broadcast)

lua/autorun/sh_cfc_time_init.lua

@@ -3,8 +3,6 @@ require( "logger" )
 CFCTime = {}
 
 CFCTime.Logger = Logger( "CFCTime" )
-CFCTime.Logger:on( "error" ):call( ErrorNoHalt )
-CFCTime.Logger:on( "fatal" ):call( error )
 
 AddCSLuaFile( "cfc_time/shared/config.lua" )
 AddCSLuaFile( "cfc_time/shared/utime_compat.lua" )

lua/cfc_time/server/storage_options/mysql.lua

@@ -39,8 +39,7 @@ end
 
 function storage.database:onConnectionFailed( err )
     -- TODO: Test this
-    logger:error( "Failed to connect to database!" )
-    logger:fatal( err )
+    error( "CFCTime: Failed to connect to database! '" .. err .. "'" )
 end
 
 hook.Add( "PostGamemodeLoaded", "CFC_Time_DBInit", function()
@@ -50,13 +49,14 @@ end )
 
 --[ API Begins Here ]--
 
-function storage:UpdateBatch( batchData )
-    if not batchData then return end
-    if table.IsEmpty( batchData ) then return end
+function storage:UpdateBatch( batchData, callback )
+    if not batchData then return callback() end
+    if table.IsEmpty( batchData ) then return callback() end
+
+    local transaction = storage:InitTransaction()
+    transaction.onSuccess = callback
 
     for sessionID, data in pairs( batchData ) do
-        local transaction = storage:InitTransaction()
-
         local query = self:Prepare(
             "sessionUpdate",
             nil,
@@ -67,8 +67,9 @@ function storage:UpdateBatch( batchData )
         )
 
         transaction:addQuery( query )
-        transaction:start()
     end
+
+    transaction:start()
 end
 
 function storage:GetTotalTime( steamID, callback )

lua/cfc_time/server/storage_options/sqlite.lua

@@ -12,9 +12,9 @@ end )
 
 --[ API Begins Here ]--
 
-function storage:UpdateBatch( batchData )
-    if not batchData then return end
-    if table.IsEmpty( batchData ) then return end
+function storage:UpdateBatch( batchData, callback )
+    if not batchData then return callback() end
+    if table.IsEmpty( batchData ) then return callback() end
 
     sql.Begin()
 
@@ -24,6 +24,8 @@ function storage:UpdateBatch( batchData )
     end
 
     sql.Commit()
+
+    callback()
 end
 
 function storage:GetTotalTime( steamID, callback )

lua/cfc_time/server/storage_options/utils/mysql.lua

@@ -11,7 +11,7 @@ function storage:InitTransaction()
     local transaction = self.database:createTransaction()
 
     transaction.onError = function( _, err )
-        logger:error( err )
+        error( "Transaction error! '" .. err .. "'" )
     end
 
     return transaction
@@ -21,7 +21,7 @@ function storage:InitQuery( rawQuery )
     local query = self.database:query( rawQuery )
 
     query.onError = function( _, err, errQuery )
-        logger:error( err, errQuery )
+        error( "Query error! '" .. err .. "' - " .. errQuery )
     end
 
     return query
@@ -70,7 +70,7 @@ function storage:AddPreparedStatement( name, query )
     local statement = self.database:prepare( query )
 
     statement.onError = function( _, err, errQuery )
-        logger:error( "An error has occured in a prepared statement!", err, errQuery )
+        error( "An error has occured in a prepared statement! '" .. err .. "' - " .. errQuery )
     end
 
     statement.onSuccess = function()

lua/cfc_time/server/time_tracking.lua

@@ -1,7 +1,7 @@
 CFCTime.ctime = CFCTime.ctime or {}
 
 local ctime = CFCTime.ctime
-local logger = CFCTime.Logger
+local logger = CFCTime.Logger:scope( "Tracking" )
 local storage = CFCTime.Storage
 
 local getNow = os.time
@@ -19,7 +19,7 @@ ctime.sessionIDs = {}
 ctime.totalTimes = {}
 
 -- steamID64 = <player entity>
-local steamIDToPly = {}
+local steamID64ToPly = {}
 
 function ctime:broadcastPlayerTime( ply, totalTime, joined, duration )
     ply:SetNW2Float( "CFC_Time_TotalTime", totalTime )
@@ -30,10 +30,10 @@ function ctime:broadcastPlayerTime( ply, totalTime, joined, duration )
 end
 
 function ctime:broadcastTimes()
-    for steamID, totalTime in pairs( self.totalTimes ) do
-        local ply = steamIDToPly[steamID]
+    for steamID64, totalTime in pairs( self.totalTimes ) do
+        local ply = steamID64ToPly[steamID64]
 
-        local session = self.sessions[steamID]
+        local session = self.sessions[steamID64]
 
         local joined = session.joined
         local duration = session.duration
@@ -44,42 +44,44 @@ function ctime:broadcastTimes()
     end
 end
 
-function ctime:untrackPlayer( steamID )
-    self.sessions[steamID] = nil
-    self.sessionIDs[steamID] = nil
-    self.totalTimes[steamID] = nil
-    steamIDToPly[steamID] = nil
+function ctime:untrackPlayer( steamID64 )
+    logger:debug( "Untracking player ", steamID64 )
+
+    self.sessions[steamID64] = nil
+    self.sessionIDs[steamID64] = nil
+    self.totalTimes[steamID64] = nil
+    steamID64ToPly[steamID64] = nil
 end
 
 function ctime:updateTimes()
     local batch = {}
     local now = getNow()
+    local sessionIDToSteamID64 = {}
     local timeDelta = now - self.lastUpdate
 
-    for steamID, data in pairs( self.sessions ) do
-        local isValid = true
+    local sessionIDs = self.sessionIDs
+    local totalTimes = self.totalTimes
 
+    for steamID64, data in pairs( self.sessions ) do
         local joined = data.joined
         local departed = data.departed
 
-        if departed and departed < self.lastUpdate then
-            self:untrackPlayer( steamID )
-            isValid = false
-        end
-
         local sessionTime = ( departed or now ) - joined
-        if sessionTime <= 0 then
-            isValid = false
-        end
+        data.duration = sessionTime
 
-        if isValid then
-            data.duration = sessionTime
+        local sessionID = sessionIDs[steamID64]
+        batch[sessionID] = data
 
-            local sessionID = self.sessionIDs[steamID]
-            batch[sessionID] = data
+        local ply = steamID64ToPly[steamID64]
+        sessionIDToSteamID64[sessionID] = steamID64
 
-            local newTotal = self.totalTimes[steamID] + timeDelta
-            self.totalTimes[steamID] = newTotal
+        if IsValid( ply ) then
+            local newTotal = totalTimes[steamID64] + timeDelta
+            totalTimes[steamID64] = newTotal
+        else
+            logger:debug( "Player is invalid in updateTimes, setting departed", steamID64 )
+            totalTimes[steamID64] = nil
+            data.departed = departed or now
         end
     end
 
@@ -90,8 +92,16 @@ function ctime:updateTimes()
     logger:debug( "Updating " .. table.Count( batch ) .. " sessions:" )
     logger:debug( batch )
 
-    storage:UpdateBatch( batch )
-    self:broadcastTimes()
+    storage:UpdateBatch( batch, function()
+        for sessionID, data in pairs( batch ) do
+            if data.departed then
+                local steamID64 = sessionIDToSteamID64[sessionID]
+                self:untrackPlayer( steamID64 )
+            end
+        end
+
+        self:broadcastTimes()
+    end )
 end
 
 function ctime:startTimer()
@@ -112,12 +122,13 @@ function ctime:startTimer()
 end
 
 function ctime:stopTimer()
+    logger:debug( "Stopping timer" )
     timer.Remove( self.updateTimerName )
 end
 
 function ctime:initPlayer( ply )
     local now = getNow()
-    local steamID = ply:SteamID64()
+    local steamID64 = ply:SteamID64()
 
     local function setupPly( totalTime, isFirstVisit )
         local sessionTotalTime = totalTime + ( getNow() - now )
@@ -135,47 +146,45 @@ function ctime:initPlayer( ply )
         hook.Run( "CFC_Time_PlayerInitialTime", ply, isFirstVisit, initialTime )
         sessionTotalTime = sessionTotalTime + initialTime.seconds
 
-        ctime.totalTimes[steamID] = sessionTotalTime
-        ctime:broadcastPlayerTime( ply, sessionTotalTime, now, 0 )
+        ctime.totalTimes[steamID64] = sessionTotalTime
     end
 
     storage:PlayerInit( ply, now, function( data )
-        if not IsValid( ply ) then return end
+        logger:debug( "Player init data: ", ply, data )
 
         local isFirstVisit = data.isFirstVisit
         local sessionID = data.sessionID
 
-        steamIDToPly[steamID] = ply
-        ctime.sessionIDs[steamID] = sessionID
-        ctime.sessions[steamID] = { joined = now }
+        steamID64ToPly[steamID64] = ply
+        ctime.sessionIDs[steamID64] = sessionID
+        ctime.sessions[steamID64] = { joined = now }
 
         if isFirstVisit then return setupPly( 0, true ) end
 
-        storage:GetTotalTime( steamID, function( total )
-            if not IsValid( ply ) then return end
+        storage:GetTotalTime( steamID64, function( total )
+            logger:debug( "Got total time for ", ply, total )
             setupPly( total, false )
         end )
     end )
 end
 
 function ctime:cleanupPlayer( ply )
+    logger:debug( "Setting player departed after disconnect: ", ply )
     -- TODO: Verify bug report from the wiki: https://wiki.facepunch.com/gmod/GM:PlayerDisconnected
     local now = getNow()
-    local steamID = ply:SteamID64()
+    local steamID64 = ply:SteamID64()
 
-    if not steamID then
-        logger:error( "Player " .. ply:GetName() .. " did not have a steamID64 on disconnect" )
-        return
+    if not steamID64 then
+        error( "Player " .. ply:GetName() .. " did not have a steamID64 on disconnect" )
     end
 
-    logger:debug( "Player " .. ply:GetName() .. " ( " .. steamID .. " ) left at " .. now )
+    logger:debug( "Player " .. ply:GetName() .. " ( " .. steamID64 .. " ) left at " .. now )
 
-    if not self.sessions[steamID] then
-        logger:error( "No pending update for above player, did they leave before database returned?" )
-        return
+    if not self.sessions[steamID64] then
+        error( "No pending update for above player, did they leave before database returned?" )
     end
 
-    self.sessions[steamID].departed = now
+    self.sessions[steamID64].departed = now
 end
 
 hook.Add( "Think", "CFC_Time_Init", function()
@@ -184,9 +193,15 @@ hook.Add( "Think", "CFC_Time_Init", function()
 end )
 
 hook.Add( "PlayerFullLoad", "CFC_Time_PlayerInit", function( ply )
+    if ply:IsBot() then return end
+
+    logger:debug( "Player fully loaded: ", ply )
     ctime:initPlayer( ply )
 end )
 
 hook.Add( "PlayerDisconnected", "CFC_Time_PlayerCleanup", function( ply )
+    if ply:IsBot() then return end
+
+    logger:debug( "Player disconnected: ", ply )
     ctime:cleanupPlayer( ply )
 end )

lua/includes/modules/playerload.lua

@@ -0,0 +1,15 @@
+-- https://github.com/CFC-Servers/gm_playerload
+
+local loadQueue = {}
+
+hook.Add( "PlayerInitialSpawn", "GM_FullLoadSetup", function( ply )
+    loadQueue[ply] = true
+end )
+
+hook.Add( "SetupMove", "GM_FullLoadTrigger", function( ply, _, cmd )
+    if not loadQueue[ply] then return end
+    if cmd:IsForced() then return end
+
+    loadQueue[ply] = nil
+    hook.Run( "PlayerFullLoad", ply )
+end )