diff --git a/apps/counterstrikesharp/src/FiveStack.Events/GameEnd.cs b/apps/counterstrikesharp/src/FiveStack.Events/GameEnd.cs index f7c5ef5..f8b48da 100644 --- a/apps/counterstrikesharp/src/FiveStack.Events/GameEnd.cs +++ b/apps/counterstrikesharp/src/FiveStack.Events/GameEnd.cs @@ -65,6 +65,14 @@ public HookResult OnGameEnd(EventCsWinPanelMatch @event, GameEventInfo info) Guid? winningLineupId = _matchEvents.GetWinningLineupId(); + _logger.LogInformation( + "OnGameEnd: dispatching end-of-map (use_playcast={UsePlaycast} tv_delay={TvDelay} onGameNode={OnGameNode} winningLineupId={WinningLineupId})", + matchData.options.use_playcast, + matchData.options.tv_delay, + _environmentService.isOnGameServerNode(), + winningLineupId + ); + // Move the map off Live immediately so it reflects WaitingForTV during the // tv_delay window (HandleEndOfMap may be deferred by use_playcast). This is // deduped in UpdateMapStatus, so HandleEndOfMap re-setting it is a no-op. @@ -72,10 +80,21 @@ public HookResult OnGameEnd(EventCsWinPanelMatch @event, GameEventInfo info) if (matchData.options.use_playcast) { + _logger.LogInformation( + "OnGameEnd: use_playcast enabled, deferring HandleEndOfMap by {TvDelay}s", + matchData.options.tv_delay + ); + + match.StartPlaycastWindowHeartbeat(matchData.options.tv_delay); + TimerUtility.AddTimer( matchData.options.tv_delay, () => { + _logger.LogInformation( + "OnGameEnd: playcast tv_delay elapsed, running HandleEndOfMap" + ); + match.StopPlaycastWindowHeartbeat(); HandleEndOfMap(winningLineupId); } ); diff --git a/apps/counterstrikesharp/src/FiveStack.Services/MatchManager.cs b/apps/counterstrikesharp/src/FiveStack.Services/MatchManager.cs index 8897e2d..d4664a6 100644 --- a/apps/counterstrikesharp/src/FiveStack.Services/MatchManager.cs +++ b/apps/counterstrikesharp/src/FiveStack.Services/MatchManager.cs @@ -24,6 +24,7 @@ public class MatchManager private eMapStatus _currentMapStatus = eMapStatus.Unknown; private Guid? _activeMapId; private Timer? _resumeMessageTimer; + private Timer? _playcastWindowTimer; public bool gameEnded = false; private readonly MatchEvents _matchEvents; @@ -617,6 +618,53 @@ public void SetupTeams() ); } + private const int PlaycastHeartbeatIntervalSeconds = 15; + + // The playcast window is the only stretch of a match where the plugin goes + // silent for minutes with the map's result still unwritten. Without a + // heartbeat, a timer that never fired and a process that was killed leave + // the exact same trace: nothing. + public void StartPlaycastWindowHeartbeat(int tvDelay) + { + StopPlaycastWindowHeartbeat(); + + // Anchored to a clock, not a tick count: CSS timers first fire after the + // interval and Swiftly's fire immediately, so counting down would report + // a different number on each runtime. + DateTime startedAt = DateTime.UtcNow; + + _playcastWindowTimer = TimerUtility.AddTimer( + PlaycastHeartbeatIntervalSeconds, + () => + { + int remaining = tvDelay - (int)(DateTime.UtcNow - startedAt).TotalSeconds; + + if (remaining <= 0) + { + StopPlaycastWindowHeartbeat(); + return; + } + + _logger.LogInformation( + "playcast window: {Remaining}s until HandleEndOfMap (match={MatchId} map={MapId} status={Status} gameEnded={GameEnded} players={Players})", + remaining, + _matchData?.id, + _activeMapId, + _currentMapStatus, + gameEnded, + MatchUtility.Players().Count + ); + }, + TimerFlags.REPEAT + ); + } + + public void StopPlaycastWindowHeartbeat() + { + _playcastWindowTimer?.Kill(); + _playcastWindowTimer = null; + } + public void delayChangeMap(int delay) { _remainingMapChangeDelay = delay; @@ -1151,6 +1199,7 @@ public void Reset() _logger.LogInformation("resetting match state"); _resumeMessageTimer?.Kill(); _mapChangeCountdownTimer?.Kill(); + StopPlaycastWindowHeartbeat(); _currentMapStatus = eMapStatus.Unknown; diff --git a/apps/swiftly/src/FiveStack.Events/GameEnd.cs b/apps/swiftly/src/FiveStack.Events/GameEnd.cs index 9912106..d02780e 100644 --- a/apps/swiftly/src/FiveStack.Events/GameEnd.cs +++ b/apps/swiftly/src/FiveStack.Events/GameEnd.cs @@ -62,9 +62,10 @@ public HookResult OnGameEnd(EventCsWinPanelMatch @event) Guid? winningLineupId = _matchEvents.GetWinningLineupId(); _logger.LogInformation( - "OnGameEnd: dispatching end-of-map (use_playcast={UsePlaycast} tv_delay={TvDelay} winningLineupId={WinningLineupId})", + "OnGameEnd: dispatching end-of-map (use_playcast={UsePlaycast} tv_delay={TvDelay} onGameNode={OnGameNode} winningLineupId={WinningLineupId})", matchData.options.use_playcast, matchData.options.tv_delay, + _environmentService.isOnGameServerNode(), winningLineupId ); @@ -79,6 +80,8 @@ public HookResult OnGameEnd(EventCsWinPanelMatch @event) "OnGameEnd: use_playcast enabled, deferring HandleEndOfMap by {TvDelay}s", matchData.options.tv_delay ); + match.StartPlaycastWindowHeartbeat(matchData.options.tv_delay); + TimerUtility.AddTimer( matchData.options.tv_delay, () => @@ -86,6 +89,7 @@ public HookResult OnGameEnd(EventCsWinPanelMatch @event) _logger.LogInformation( "OnGameEnd: playcast tv_delay elapsed, running HandleEndOfMap" ); + match.StopPlaycastWindowHeartbeat(); HandleEndOfMap(winningLineupId); } ); diff --git a/apps/swiftly/src/FiveStack.Services/MatchManager.cs b/apps/swiftly/src/FiveStack.Services/MatchManager.cs index c219726..e707b2c 100644 --- a/apps/swiftly/src/FiveStack.Services/MatchManager.cs +++ b/apps/swiftly/src/FiveStack.Services/MatchManager.cs @@ -22,6 +22,7 @@ public class MatchManager private eMapStatus _currentMapStatus = eMapStatus.Unknown; private Guid? _activeMapId; private CancellationTokenSource? _resumeMessageTimer; + private CancellationTokenSource? _playcastWindowTimer; public bool gameEnded = false; private readonly ISwiftlyCore _core; @@ -612,6 +613,52 @@ public void SetupTeams() ); } + private const int PlaycastHeartbeatIntervalSeconds = 15; + + // The playcast window is the only stretch of a match where the plugin goes + // silent for minutes with the map's result still unwritten. Without a + // heartbeat, a timer that never fired and a process that was killed leave + // the exact same trace: nothing. + public void StartPlaycastWindowHeartbeat(int tvDelay) + { + StopPlaycastWindowHeartbeat(); + + // Anchored to a clock, not a tick count: CSS timers first fire after the + // interval and Swiftly's fire immediately, so counting down would report + // a different number on each runtime. + DateTime startedAt = DateTime.UtcNow; + + _playcastWindowTimer = TimerUtility.Repeat( + PlaycastHeartbeatIntervalSeconds, + () => + { + int remaining = tvDelay - (int)(DateTime.UtcNow - startedAt).TotalSeconds; + + if (remaining <= 0) + { + StopPlaycastWindowHeartbeat(); + return; + } + + _logger.LogInformation( + "playcast window: {Remaining}s until HandleEndOfMap (match={MatchId} map={MapId} status={Status} gameEnded={GameEnded} players={Players})", + remaining, + _matchData?.id, + _activeMapId, + _currentMapStatus, + gameEnded, + MatchUtility.Players().Count + ); + } + ); + } + + public void StopPlaycastWindowHeartbeat() + { + TimerUtility.Kill(_playcastWindowTimer); + _playcastWindowTimer = null; + } + public void delayChangeMap(int delay) { _remainingMapChangeDelay = delay; @@ -1127,6 +1174,7 @@ public void Reset() _logger.LogInformation("resetting match state"); TimerUtility.Kill(_resumeMessageTimer); TimerUtility.Kill(_mapChangeCountdownTimer); + StopPlaycastWindowHeartbeat(); _currentMapStatus = eMapStatus.Unknown; diff --git a/scripts/tail.sh b/scripts/tail.sh index c4f350c..70da95b 100755 --- a/scripts/tail.sh +++ b/scripts/tail.sh @@ -32,6 +32,13 @@ fi # SwiftlyS2 bug: the game process stops emitting to stdout after the first # plugin hot reload, but its own log files keep flowing — so for swiftly, # merge the managed log file into the stream alongside container stdout. +# +# Both streams carry the same plugin lines while stdout is alive, so the file +# tail is gated on a liveness stamp the stdout side touches: its lines are only +# printed once stdout has been quiet for STDOUT_QUIET_SECONDS, i.e. once the +# reload bug has actually bitten. Otherwise every plugin line shows up twice. +STDOUT_QUIET_SECONDS=10 + if [ "$workload" = "dev-swiftly-game-server" ] && command -v kubectl >/dev/null 2>&1; then export KUBECONFIG="${KUBECONFIG:-$HOME/.kube/5stackgg}" pod=$(kubectl -n 5stack get pods -l app="$workload" \ @@ -39,14 +46,30 @@ if [ "$workload" = "dev-swiftly-game-server" ] && command -v kubectl >/dev/null --sort-by=.metadata.creationTimestamp \ -o jsonpath='{.items[-1].metadata.name}' 2>/dev/null || true) if [ -n "$pod" ]; then + stdout_stamp="$(mktemp -t tail-stdout-stamp)" + date +%s > "$stdout_stamp" + kubectl -n 5stack exec "$pod" -c "$workload" -- sh -c \ 'tail -n 5 -F /opt/instance/game/csgo/addons/swiftlys2/logs/managed/*.log 2>/dev/null' \ - | sed -u 's/^/[sw-log] /' & + | while IFS= read -r line; do + last="$(cat "$stdout_stamp" 2>/dev/null || echo 0)" + if [ "$(( $(date +%s) - last ))" -ge "$STDOUT_QUIET_SECONDS" ]; then + printf '[sw-log] %s\n' "$line" + fi + done & file_tail_pid=$! - trap 'kill "$file_tail_pid" 2>/dev/null' EXIT + trap 'kill "$file_tail_pid" 2>/dev/null; rm -f "$stdout_stamp"' EXIT fi fi # the container carries the same name as its workload # (no exec: the EXIT trap must fire to reap the background file tail) -codepier tail --deployment "$workload" --container "$workload" +if [ -n "${stdout_stamp:-}" ]; then + codepier tail --deployment "$workload" --container "$workload" \ + | while IFS= read -r line; do + date +%s > "$stdout_stamp" + printf '%s\n' "$line" + done +else + codepier tail --deployment "$workload" --container "$workload" +fi