diff --git a/src/FiveStack.Commands/Demo.cs b/src/FiveStack.Commands/Demo.cs index 8cbe1cf..a9502a0 100644 --- a/src/FiveStack.Commands/Demo.cs +++ b/src/FiveStack.Commands/Demo.cs @@ -19,7 +19,10 @@ public async void OnUploadDemo(CCSPlayerController? player, CommandInfo command) match.UpdateMapStatus(eMapStatus.UploadingDemo); - await _gameDemos.UploadDemos(); + using var cts = new System.Threading.CancellationTokenSource( + TimeSpan.FromSeconds(_environmentService.GetDemoUploadTimeLimitSeconds()) + ); + await _gameDemos.UploadDemos(cts.Token); } [ConsoleCommand("test_start_demo", "start demo recording")] diff --git a/src/FiveStack.Events/GameEnd.cs b/src/FiveStack.Events/GameEnd.cs index d2412d5..7133de8 100644 --- a/src/FiveStack.Events/GameEnd.cs +++ b/src/FiveStack.Events/GameEnd.cs @@ -197,19 +197,69 @@ private void HandleEndOfMap(Guid? winningLineupId) currentMap.id ); - try + // Only finish the map once the demo is confirmed uploaded, so + // the server stays reserved until it's safe. If the budget + // runs out, give up loudly and finish anyway (retried on next + // startup) so the match never gets stuck. + int uploadTimeLimit = + _environmentService.GetDemoUploadTimeLimitSeconds(); + using var uploadCts = new System.Threading.CancellationTokenSource( + TimeSpan.FromSeconds(uploadTimeLimit) + ); + + // Upload the specific map that just ended, not whatever the + // current match/map resolves to when the timer fires. + string uploadMatchId = expectedMatchId.ToString(); + string uploadMapId = currentMap.id.ToString(); + + bool uploaded = false; + int attempt = 0; + while (!uploadCts.IsCancellationRequested) { - await _gameDemos.UploadDemos(); - _logger.LogInformation( - "Demo upload finished (match={MatchId})", - expectedMatchId - ); + attempt++; + try + { + uploaded = await _gameDemos.UploadDemos( + uploadMatchId, + uploadMapId, + uploadCts.Token + ); + if (uploaded) + { + _logger.LogInformation( + "Demo upload finished (match={MatchId} attempts={Attempts})", + expectedMatchId, + attempt + ); + break; + } + } + catch (Exception ex) + { + _logger.LogError( + ex, + "UploadDemos failed (match={MatchId} attempt={Attempt})", + expectedMatchId, + attempt + ); + } + + try + { + await Task.Delay(TimeSpan.FromSeconds(10), uploadCts.Token); + } + catch (OperationCanceledException) + { + break; + } } - catch (Exception ex) + + if (!uploaded) { - _logger.LogError( - ex, - "UploadDemos failed after map end for match {MatchId}", + _logger.LogCritical( + "Demo upload did NOT complete within {Limit}s ({Attempts} attempt(s)) — this server may be too slow to upload demos. Finishing the map without a confirmed upload (match={MatchId}); the demo remains on disk and will be retried on next startup.", + uploadTimeLimit, + attempt, expectedMatchId ); } @@ -232,8 +282,9 @@ private void HandleEndOfMap(Guid? winningLineupId) bool isSurrenderedNow = wasSurrendered || next.isSurrendered(); _logger.LogInformation( - "Demo upload done — finishing map and switching (match={MatchId})", - expectedMatchId + "Finishing map and switching (match={MatchId} demoUploaded={Uploaded})", + expectedMatchId, + uploaded ); if (isSurrenderedNow) diff --git a/src/FiveStack.Services/EnvironmentService.cs b/src/FiveStack.Services/EnvironmentService.cs index 5ea45de..32a9deb 100644 --- a/src/FiveStack.Services/EnvironmentService.cs +++ b/src/FiveStack.Services/EnvironmentService.cs @@ -49,6 +49,18 @@ public bool AllowBots() return Environment.GetEnvironmentVariable("ALLOW_BOTS") == "true"; } + // Total budget for uploading a map's demos after it ends, across retries. + public int GetDemoUploadTimeLimitSeconds() + { + var raw = Environment.GetEnvironmentVariable("DEMO_UPLOAD_TIME_LIMIT_SECONDS"); + if (int.TryParse(raw, out int seconds) && seconds > 0) + { + return seconds; + } + + return 300; + } + public bool isOnGameServerNode() { return Environment.GetEnvironmentVariable("GAME_NODE_SERVER") == "true"; diff --git a/src/FiveStack.Services/GameDemos.cs b/src/FiveStack.Services/GameDemos.cs index bfcf367..d4d1d40 100644 --- a/src/FiveStack.Services/GameDemos.cs +++ b/src/FiveStack.Services/GameDemos.cs @@ -27,6 +27,22 @@ public class GameDemos private readonly IStringLocalizer _localizer; private string _rootDir = "/opt"; + // A finalized demo hasn't been written since tv_stoprecord; a file touched + // more recently than this may still be recording, so recovery skips it. + private const int RecordingFinalizeWindowSeconds = 60; + + // Shared to avoid socket churn; per-request auth is set on each message. + // Timeout is infinite by design — the caller's CancellationToken bounds it. + private static readonly HttpClient _httpClient = new HttpClient + { + Timeout = System.Threading.Timeout.InfiniteTimeSpan, + }; + + // Guards against two paths (GameEnd, orphan recovery, the console command) + // uploading/deleting the same demo at once. + private readonly HashSet _uploadsInProgress = new(); + private readonly object _uploadsLock = new(); + public GameDemos( ILogger logger, GameServer gameServer, @@ -54,12 +70,12 @@ public void Start() { MatchData? match = _matchService.GetCurrentMatch()?.GetMatchData(); - if (match == null) + if (match == null || match.current_match_map_id == null) { return; } - string lockFilePath = GetLockFilePath(match.id); + string lockFilePath = GetLockFilePath(match.current_match_map_id.Value); if (File.Exists(lockFilePath)) { _logger.LogInformation("Demo is already recording"); @@ -83,15 +99,17 @@ public void Stop() { MatchData? match = _matchService.GetCurrentMatch()?.GetMatchData(); - if (match == null) + if (match == null || match.current_match_map_id == null) { return; } string demoPath = GetMatchDemoPath(); - int demoCount = Directory.Exists(demoPath) ? Directory.GetFiles(demoPath, "*").Length : 0; + int demoCount = Directory.Exists(demoPath) + ? Directory.GetFiles(demoPath, "*.dem").Length + : 0; - File.Delete(GetLockFilePath(match.id)); + File.Delete(GetLockFilePath(match.current_match_map_id.Value)); Server.NextFrame(() => { _logger.LogInformation( @@ -111,170 +129,330 @@ public void StopTV() }); } - public async Task UploadDemos() + // Uploads the current match/map's demos. + public Task UploadDemos(System.Threading.CancellationToken cancellationToken = default) + { + return UploadDemosFromPath(GetMatchDemoPath(), cancellationToken); + } + + // Uploads a specific match/map's demos, independent of the current match + // state (which can change during the post-match upload window). + public Task UploadDemos( + string matchId, + string mapId, + System.Threading.CancellationToken cancellationToken = default + ) + { + return UploadDemosFromPath($"{_rootDir}/demos/{matchId}/{mapId}", cancellationToken); + } + + // Returns false if any demo still needs another attempt. + private async Task UploadDemosFromPath( + string demoPath, + System.Threading.CancellationToken cancellationToken + ) { - string demoPath = GetMatchDemoPath(); _logger.LogInformation($"Uploading demos from {demoPath}"); if (!Directory.Exists(demoPath)) { _logger.LogCritical($"Demo directory does not exist: {demoPath}"); - return; + return true; } - string[] files = Directory.GetFiles(demoPath, "*"); + string[] files = Directory.GetFiles(demoPath, "*.dem"); if (files.Length == 0) { _logger.LogWarning($"No demo files found in {demoPath}"); - return; + return true; } _logger.LogInformation($"Found {files.Length} demo file(s) in {demoPath}"); + bool allUploaded = true; foreach (string file in files) { - long size = new FileInfo(file).Length; - _logger.LogInformation($"Uploading demo {file} ({size} bytes)"); - await UploadDemo(file); + _logger.LogInformation($"Uploading demo {file}"); + if (!await UploadDemo(file, cancellationToken)) + { + allUploaded = false; + } + } + + if (allUploaded) + { + _logger.LogInformation("Uploaded all demos"); } - _logger.LogInformation("Uploaded all demos"); + + return allUploaded; } - public async Task UploadDemo(string filePath) + // Recording locks never survive a process restart, so any left on disk at + // startup are stale from a crash. Clear them so Start() doesn't refuse to + // record a resumed match. + public void ClearStaleRecordingLocks() { try { - if (_environmentService.IsOfflineMode()) + foreach (string lockFile in Directory.GetFiles(_rootDir, ".recording-demo-*")) { - return; + File.Delete(lockFile); + _logger.LogInformation($"Cleared stale recording lock {lockFile}"); } + } + catch (Exception ex) + { + _logger.LogError($"Failed to clear stale recording locks: {ex.Message}"); + } + } - MatchData? match = _matchService.GetCurrentMatch()?.GetMatchData(); + // Uploads .dem files left on disk by a crash/restart during the post-match + // upload window. Runs on startup to self-heal. + public async Task UploadOrphanedDemos( + System.Threading.CancellationToken cancellationToken = default + ) + { + if (_environmentService.IsOfflineMode()) + { + return; + } - string? serverId = _environmentService.GetServerId(); - string? apiPassword = _environmentService.GetServerApiPassword(); + string demosRoot = $"{_rootDir}/demos"; + if (!Directory.Exists(demosRoot)) + { + return; + } - if (serverId == null || apiPassword == null || match == null) + string[] files; + try + { + files = Directory.GetFiles(demosRoot, "*.dem", SearchOption.AllDirectories); + } + catch (Exception ex) + { + _logger.LogError($"Failed to scan for orphaned demos: {ex.Message}"); + return; + } + + if (files.Length == 0) + { + return; + } + + _logger.LogInformation( + $"Found {files.Length} demo(s) on disk, attempting to recover uploads" + ); + + // One overall budget for the whole pass so a backlog can't run for + // N × timeLimit; whatever isn't reached is retried on the next start. + using var cts = System.Threading.CancellationTokenSource.CreateLinkedTokenSource( + cancellationToken + ); + cts.CancelAfter(TimeSpan.FromSeconds(_environmentService.GetDemoUploadTimeLimitSeconds())); + + foreach (string file in files) + { + cts.Token.ThrowIfCancellationRequested(); + + // Skip anything still being recorded: an active recording holds a lock + // for its map, and a finalized demo hasn't been written since + // tv_stoprecord. The lock check covers the case where an active + // recording simply hasn't flushed within the freshness window. Keyed + // per-map so a finished map isn't skipped while a later map records. + string? mapId = Path.GetFileName(Path.GetDirectoryName(file)); + bool activelyRecording = + Guid.TryParse(mapId, out Guid parsedMapId) + && File.Exists(GetLockFilePath(parsedMapId)); + bool recentlyWritten = + File.GetLastWriteTimeUtc(file) + > DateTime.UtcNow.AddSeconds(-RecordingFinalizeWindowSeconds); + + if (activelyRecording || recentlyWritten) { - return; + _logger.LogInformation($"Skipping demo that may still be recording: {file}"); + continue; } - string demoName = Path.GetFileName(filePath); + _logger.LogInformation($"Recovering orphaned demo {file}"); + await UploadDemo(file, cts.Token); + } - string? presignedUrl = await GetPresignedUrl(filePath); - if (string.IsNullOrEmpty(presignedUrl)) + _logger.LogInformation("Finished recovering orphaned demos"); + } + + // Returns true when resolved (uploaded, or already-uploaded/map-gone); + // false on a retryable failure. + public async Task UploadDemo( + string filePath, + System.Threading.CancellationToken cancellationToken = default + ) + { + if (_environmentService.IsOfflineMode()) + { + return true; + } + + string? apiPassword = _environmentService.GetServerApiPassword(); + + if (apiPassword == null) + { + _logger.LogWarning("Cannot upload demo: server api password not configured"); + return false; + } + + // Derive ids from the path ({root}/demos/{matchId}/{mapId}/{demo}.dem) + // so this works for demos that aren't the current match. + string demoName = Path.GetFileName(filePath); + string? mapId = Path.GetFileName(Path.GetDirectoryName(filePath)); + string? matchId = Path.GetFileName(Path.GetDirectoryName(Path.GetDirectoryName(filePath))); + + if (!Guid.TryParse(matchId, out _) || !Guid.TryParse(mapId, out _)) + { + _logger.LogWarning( + $"Skipping demo with unexpected path (cannot derive match/map ids): {filePath}" + ); + return true; + } + + lock (_uploadsLock) + { + if (!_uploadsInProgress.Add(filePath)) { - _logger.LogCritical( - $"Failed to get presigned URL (match {match.id} map {match.current_match_map_id} demo {demoName})" - ); - return; + // Another path owns this upload; report not-done so the caller + // retries rather than treating it as a confirmed success. + _logger.LogInformation($"Demo already being uploaded, skipping: {demoName}"); + return false; } + } - using var httpClient = new HttpClient(); - httpClient.Timeout = System.Threading.Timeout.InfiniteTimeSpan; + try + { + var (presignedUrl, resolved) = await GetPresignedUrl( + matchId, + mapId, + filePath, + apiPassword, + cancellationToken + ); - var fileInfo = new FileInfo(filePath); - using (var fileStream = File.OpenRead(filePath)) + if (resolved) { - var request = new HttpRequestMessage(HttpMethod.Put, presignedUrl); - request.Content = new StreamContent(fileStream); - request.Content.Headers.ContentType = new MediaTypeHeaderValue( - "application/octet-stream" - ); - request.Content.Headers.ContentLength = fileInfo.Length; + return true; + } - _logger.LogInformation( - $"PUT demo {demoName} ({fileInfo.Length} bytes) for match {match.id}" - ); + if (string.IsNullOrEmpty(presignedUrl)) + { + // GetPresignedUrl already logged the specific reason (e.g. 409 + // "not finished yet", which is a normal retry, not an error). + return false; + } - var response = await httpClient.SendAsync(request); + var fileInfo = new FileInfo(filePath); + using var fileStream = File.OpenRead(filePath); - _logger.LogInformation( - $"demo PUT response {(int)response.StatusCode} {response.StatusCode} (match {match.id} demo {demoName})" - ); + var request = new HttpRequestMessage(HttpMethod.Put, presignedUrl); + request.Content = new StreamContent(fileStream); + request.Content.Headers.ContentType = new MediaTypeHeaderValue( + "application/octet-stream" + ); + request.Content.Headers.ContentLength = fileInfo.Length; + + _logger.LogInformation( + $"PUT demo {demoName} ({fileInfo.Length} bytes) for match {matchId}" + ); + + var response = await _httpClient.SendAsync(request, cancellationToken); + + _logger.LogInformation( + $"demo PUT response {(int)response.StatusCode} {response.StatusCode} (match {matchId} demo {demoName})" + ); + + if (!response.IsSuccessStatusCode) + { + _logger.LogCritical($"unable to upload demo {response.StatusCode}"); + return false; + } - if (response.IsSuccessStatusCode) - { - _logger.LogInformation($"demo uploaded (match {match.id} demo {demoName})"); + _logger.LogInformation($"demo uploaded (match {matchId} demo {demoName})"); - var notifyEndpoint = - $"{_environmentService.GetDemosUrl()}/demos/{match.id}/uploaded"; - var notifyRequest = new + var notifyRequest = new HttpRequestMessage( + HttpMethod.Post, + $"{_environmentService.GetDemosUrl()}/demos/{matchId}/uploaded" + ) + { + Content = JsonContent.Create( + new { demo = demoName, - mapId = match.current_match_map_id, + mapId = mapId, size = fileInfo.Length, - }; + } + ), + }; + notifyRequest.Headers.Authorization = new AuthenticationHeaderValue( + "Bearer", + apiPassword + ); - using var notifyClient = new HttpClient(); - notifyClient.DefaultRequestHeaders.Authorization = - new AuthenticationHeaderValue("Bearer", apiPassword); - var notifyResponse = await notifyClient.PostAsJsonAsync( - notifyEndpoint, - notifyRequest - ); + var notifyResponse = await _httpClient.SendAsync(notifyRequest, cancellationToken); - _logger.LogInformation( - $"demo uploaded notify response {(int)notifyResponse.StatusCode} {notifyResponse.StatusCode} (match {match.id} demo {demoName})" - ); + _logger.LogInformation( + $"demo uploaded notify response {(int)notifyResponse.StatusCode} {notifyResponse.StatusCode} (match {matchId} demo {demoName})" + ); - if (notifyResponse.IsSuccessStatusCode) - { - File.Delete(filePath); - } - else - { - _logger.LogCritical( - $"Failed to notify about demo upload: {notifyResponse.StatusCode}" - ); - } - } - else - { - _logger.LogCritical($"unable to upload demo {response.StatusCode}"); - } + if (!notifyResponse.IsSuccessStatusCode) + { + _logger.LogCritical( + $"Failed to notify about demo upload: {notifyResponse.StatusCode}" + ); + return false; } + + File.Delete(filePath); + return true; + } + catch (OperationCanceledException) + { + _logger.LogWarning($"Demo upload canceled (time budget reached): {filePath}"); + return false; } catch (Exception ex) { _logger.LogCritical($"An error occurred during file upload: {ex.Message}"); + return false; } - } - - private async Task GetPresignedUrl(string filePath) - { - MatchData? match = _matchService.GetCurrentMatch()?.GetMatchData(); - - if (match == null) + finally { - return null; - } - - string? apiPassword = _environmentService.GetServerApiPassword(); - if (apiPassword == null) - { - return null; + lock (_uploadsLock) + { + _uploadsInProgress.Remove(filePath); + } } + } - string endpoint = $"{_environmentService.GetDemosUrl()}/demos/{match.id}/pre-signed"; - - using var httpClient = new HttpClient(); - httpClient.DefaultRequestHeaders.Authorization = new AuthenticationHeaderValue( - "Bearer", - apiPassword - ); + // "resolved" = nothing left to upload (already uploaded / map gone); file cleaned up. + private async Task<(string? PresignedUrl, bool Resolved)> GetPresignedUrl( + string matchId, + string mapId, + string filePath, + string apiPassword, + System.Threading.CancellationToken cancellationToken = default + ) + { + string demoName = Path.GetFileName(filePath); + string endpoint = $"{_environmentService.GetDemosUrl()}/demos/{matchId}/pre-signed"; - var requestBody = new + var request = new HttpRequestMessage(HttpMethod.Post, endpoint) { - demo = Path.GetFileName(filePath), - mapId = _matchService.GetCurrentMatch()?.GetMatchData()?.current_match_map_id, + Content = JsonContent.Create(new { demo = demoName, mapId = mapId }), }; + request.Headers.Authorization = new AuthenticationHeaderValue("Bearer", apiPassword); - var response = await httpClient.PostAsJsonAsync(endpoint, requestBody); + var response = await _httpClient.SendAsync(request, cancellationToken); _logger.LogInformation( - $"presigned url response {(int)response.StatusCode} {response.StatusCode} (match {match.id} map {match.current_match_map_id} demo {Path.GetFileName(filePath)})" + $"presigned url response {(int)response.StatusCode} {response.StatusCode} (match {matchId} map {mapId} demo {demoName})" ); switch (response.StatusCode) @@ -285,22 +463,32 @@ public async Task UploadDemo(string filePath) case HttpStatusCode.NotAcceptable: _logger.LogInformation("demo is already uploaded"); File.Delete(filePath); - break; + return (null, true); case HttpStatusCode.Gone: _logger.LogInformation("match map not found"); File.Delete(filePath); - break; + return (null, true); } if (!response.IsSuccessStatusCode) { _logger.LogCritical($"unable to get presigned url: {response.StatusCode}"); - return null; + return (null, false); } - var responseContent = await response.Content.ReadFromJsonAsync(); + var responseContent = await response.Content.ReadFromJsonAsync( + cancellationToken + ); + + if (string.IsNullOrEmpty(responseContent?.PresignedUrl)) + { + _logger.LogCritical( + $"presigned url response had no url (match {matchId} map {mapId} demo {demoName})" + ); + return (null, false); + } - return responseContent?.PresignedUrl; + return (responseContent.PresignedUrl, false); } private string GetMatchDemoPath() @@ -314,8 +502,8 @@ private string GetMatchDemoPath() return $"{_rootDir}/demos/{match.id}/{match.current_match_map_id}"; } - private string GetLockFilePath(Guid matchId) + private string GetLockFilePath(Guid mapId) { - return $"{_rootDir}/.recording-demo-{matchId}"; + return $"{_rootDir}/.recording-demo-{mapId}"; } } diff --git a/src/FiveStackPlugin.cs b/src/FiveStackPlugin.cs index 619b603..66f4d3b 100644 --- a/src/FiveStackPlugin.cs +++ b/src/FiveStackPlugin.cs @@ -66,6 +66,7 @@ IStringLocalizer localizer } private Timer _pingTimer; + private readonly System.Threading.CancellationTokenSource _shutdownCts = new(); public override void Load(bool hotReload) { @@ -103,10 +104,36 @@ public override void Load(bool hotReload) { _matchService.GetMatchFromOffline(); } + + // On a fresh start (not a hot reload, where a recording may still be + // live) any recording lock left on disk is stale from a crash. + if (!hotReload) + { + _gameDemos.ClearStaleRecordingLocks(); + } + + // Recover demos left on disk by a previous crash/restart, once env/API have settled. + _ = Task.Run(async () => + { + try + { + await Task.Delay(TimeSpan.FromSeconds(15), _shutdownCts.Token); + await _gameDemos.UploadOrphanedDemos(_shutdownCts.Token); + } + catch (OperationCanceledException) + { + // plugin unloaded before/while recovering + } + catch (Exception ex) + { + _logger.LogError($"Failed to recover orphaned demos: {ex.Message}"); + } + }); } public override void Unload(bool hotReload) { + _shutdownCts.Cancel(); _pingTimer?.Dispose(); ConnectClientFunc.Unhook(ConnectClientHook, HookMode.Pre);