From 2d27adb2f6dcbb36940d84c6d706b273ba1cf4d4 Mon Sep 17 00:00:00 2001 From: John Claus Date: Fri, 24 Apr 2026 17:08:37 -0600 Subject: [PATCH] fix: finalize PagingLogger disposal path --- src/Runner.Common/Logging.cs | 54 +++++- src/Runner.Worker/ExecutionContext.cs | 23 ++- src/Runner.Worker/JobRunner.cs | 7 +- src/Test/L0/PagingLoggerL0.cs | 211 +++++++++++++++++++++++ src/Test/L0/Worker/ExecutionContextL0.cs | 115 ++++++++++++ 5 files changed, 406 insertions(+), 4 deletions(-) diff --git a/src/Runner.Common/Logging.cs b/src/Runner.Common/Logging.cs index 9200ca5923c..d4d9d72a278 100644 --- a/src/Runner.Common/Logging.cs +++ b/src/Runner.Common/Logging.cs @@ -4,7 +4,7 @@ namespace GitHub.Runner.Common { [ServiceLocator(Default = typeof(PagingLogger))] - public interface IPagingLogger : IRunnerService + public interface IPagingLogger : IRunnerService, IDisposable { long TotalLines { get; } void Setup(Guid timelineId, Guid timelineRecordId); @@ -45,6 +45,8 @@ public class PagingLogger : RunnerService, IPagingLogger private int _blockByteCount; private int _blockCount; + private bool _disposed; + public long TotalLines => _totalLines; public override void Initialize(IHostContext hostContext) @@ -164,5 +166,55 @@ private void EndBlock(bool finalize) _jobServerQueue.QueueResultsUpload(_timelineRecordId, "ResultsLog", _resultsDataFileName, "Results.Core.Log", deleteSource: true, finalize, firstBlock: _resultsDataFileName.EndsWith(".1"), totalLines: _totalLines); } } + + // Best-effort cleanup for fault paths where End() was not reached. + public void Dispose() + { + Dispose(true); + GC.SuppressFinalize(this); + } + + protected virtual void Dispose(bool disposing) + { + if (_disposed) + { + return; + } + + if (disposing) + { + // Try normal flush+queue paths first. + try { EndPage(); } catch { } + + // Safety net for partially initialized page writer/stream. + if (_pageWriter != null) + { + try { _pageWriter.Dispose(); } catch { } + _pageWriter = null; + _pageData = null; + } + else if (_pageData != null) + { + try { _pageData.Dispose(); } catch { } + _pageData = null; + } + + try { EndBlock(finalize: true); } catch { } + + if (_resultsBlockWriter != null) + { + try { _resultsBlockWriter.Dispose(); } catch { } + _resultsBlockWriter = null; + _resultsBlockData = null; + } + else if (_resultsBlockData != null) + { + try { _resultsBlockData.Dispose(); } catch { } + _resultsBlockData = null; + } + } + + _disposed = true; + } } } diff --git a/src/Runner.Worker/ExecutionContext.cs b/src/Runner.Worker/ExecutionContext.cs index f072335b440..d9cf8bc710c 100644 --- a/src/Runner.Worker/ExecutionContext.cs +++ b/src/Runner.Worker/ExecutionContext.cs @@ -143,6 +143,7 @@ public sealed class ExecutionContext : RunnerService, IExecutionContext private IssueMatcherConfig[] _matchers; private IPagingLogger _logger; + private bool _ownsLogger; private IJobServerQueue _jobServerQueue; private Guid _mainTimelineId; @@ -411,6 +412,7 @@ public IExecutionContext CreateChild( else { child._logger = HostContext.CreateService(); + child._ownsLogger = true; child._logger.Setup(_mainTimelineId, recordId); } @@ -552,7 +554,14 @@ public TaskResult Complete(TaskResult? result = null, string currentOperation = _cancellationTokenSource?.Dispose(); } - _logger.End(); + try + { + _logger.End(); + } + finally + { + DisposeOwnedLogger(); + } UpdateGlobalStepsContext(); @@ -961,6 +970,7 @@ public void InitializeJob(Pipelines.AgentJobRequestMessage message, Cancellation // Logger (must be initialized before writing warnings). _logger = HostContext.CreateService(); + _ownsLogger = true; _logger.Setup(_mainTimelineId, _record.Id); // Initialize 'echo on action command success' property, default to false, unless Step_Debug is set @@ -1277,6 +1287,17 @@ private IExecutionContext CreatePostChild(string displayName, Dictionary variables, IDictionary contextData) { diff --git a/src/Runner.Worker/JobRunner.cs b/src/Runner.Worker/JobRunner.cs index 2ccad0c0ce2..7e5ba736e99 100644 --- a/src/Runner.Worker/JobRunner.cs +++ b/src/Runner.Worker/JobRunner.cs @@ -411,13 +411,16 @@ private async Task CompleteJobAsync(IRunServer runServer, IExecution private async Task CompleteJobAsync(IJobServer jobServer, IExecutionContext jobContext, Pipelines.AgentJobRequestMessage message, TaskResult? taskResult = null) { jobContext.Debug($"Finishing: {message.JobDisplayName}"); - TaskResult result = jobContext.Complete(taskResult); if (_runnerSettings.DisableUpdate == true) { - await WarningOutdatedRunnerAsync(jobContext, message, result); + // Emit warning before Complete() closes paging logger. + TaskResult warningResult = taskResult ?? jobContext.Result ?? TaskResult.Succeeded; + await WarningOutdatedRunnerAsync(jobContext, message, warningResult); } + TaskResult result = jobContext.Complete(taskResult); + try { var jobQueueTelemetry = await ShutdownQueue(throwOnFailure: true); diff --git a/src/Test/L0/PagingLoggerL0.cs b/src/Test/L0/PagingLoggerL0.cs index 7f8ba60d224..e3f9c23030a 100644 --- a/src/Test/L0/PagingLoggerL0.cs +++ b/src/Test/L0/PagingLoggerL0.cs @@ -1,6 +1,7 @@ using Moq; using System; using System.IO; +using System.Reflection; using Xunit; namespace GitHub.Runner.Common.Tests.Listener @@ -126,5 +127,215 @@ public void ShipEmptyLog() CleanLogFolder(); } } + + // Dispose without End() should flush/queue partial content. + [Fact] + [Trait("Level", "L0")] + [Trait("Category", "Common")] + public void Dispose_AfterPartialWrite_FlushesAndClosesFiles() + { + CleanLogFolder(); + + try + { + using (var hc = new TestHostContext(this)) + { + var pagingLogger = new PagingLogger(); + hc.SetSingleton(_jobServerQueue.Object); + pagingLogger.Initialize(hc); + Guid timeLineId = Guid.NewGuid(); + Guid timeLineRecordId = Guid.NewGuid(); + + string queuedPagePath = null; + _jobServerQueue + .Setup(x => x.QueueFileUpload(timeLineId, timeLineRecordId, It.IsAny(), It.IsAny(), It.IsAny(), true)) + .Callback((Guid _, Guid _, string _, string _, string path, bool _) => queuedPagePath = path); + + string queuedBlockPath = null; + _jobServerQueue + .Setup(x => x.QueueResultsUpload(timeLineRecordId, It.IsAny(), It.IsAny(), It.IsAny(), true, It.IsAny(), It.IsAny(), It.IsAny())) + .Callback((Guid _, string _, string path, string _, bool _, bool _, bool _, long _) => queuedBlockPath = path); + + // Act: write once, then dispose without End(). + pagingLogger.Setup(timeLineId, timeLineRecordId); + pagingLogger.Write(LogData); + pagingLogger.Dispose(); + + Assert.False(string.IsNullOrEmpty(queuedPagePath), "Dispose should have queued the partial page for upload."); + Assert.False(string.IsNullOrEmpty(queuedBlockPath), "Dispose should have queued the partial block for upload with finalize=true."); + + // Verify flushed content reached queued files. + Assert.Contains(LogData, File.ReadAllText(queuedPagePath)); + Assert.Contains(LogData, File.ReadAllText(queuedBlockPath)); + + // Cleanup files created outside the normal callback path. + File.Delete(queuedPagePath); + File.Delete(queuedBlockPath); + } + } + finally + { + CleanLogFolder(); + } + } + + // Dispose should be idempotent. + [Fact] + [Trait("Level", "L0")] + [Trait("Category", "Common")] + public void Dispose_IsIdempotent() + { + CleanLogFolder(); + + try + { + using (var hc = new TestHostContext(this)) + { + var pagingLogger = new PagingLogger(); + hc.SetSingleton(_jobServerQueue.Object); + pagingLogger.Initialize(hc); + Guid timeLineId = Guid.NewGuid(); + Guid timeLineRecordId = Guid.NewGuid(); + + int queueFileUploadCount = 0; + int queueResultsUploadCount = 0; + _jobServerQueue + .Setup(x => x.QueueFileUpload(timeLineId, timeLineRecordId, It.IsAny(), It.IsAny(), It.IsAny(), true)) + .Callback(() => queueFileUploadCount++); + _jobServerQueue + .Setup(x => x.QueueResultsUpload(timeLineRecordId, It.IsAny(), It.IsAny(), It.IsAny(), true, It.IsAny(), It.IsAny(), It.IsAny())) + .Callback(() => queueResultsUploadCount++); + + pagingLogger.Setup(timeLineId, timeLineRecordId); + pagingLogger.Write(LogData); + pagingLogger.Dispose(); + pagingLogger.Dispose(); + + Assert.Equal(1, queueFileUploadCount); + Assert.Equal(1, queueResultsUploadCount); + } + } + finally + { + CleanLogFolder(); + } + } + + // Dispose after End() should be a no-op. + [Fact] + [Trait("Level", "L0")] + [Trait("Category", "Common")] + public void Dispose_AfterEnd_IsNoOp() + { + CleanLogFolder(); + + try + { + using (var hc = new TestHostContext(this)) + { + var pagingLogger = new PagingLogger(); + hc.SetSingleton(_jobServerQueue.Object); + pagingLogger.Initialize(hc); + Guid timeLineId = Guid.NewGuid(); + Guid timeLineRecordId = Guid.NewGuid(); + + int queueCount = 0; + _jobServerQueue + .Setup(x => x.QueueFileUpload(timeLineId, timeLineRecordId, It.IsAny(), It.IsAny(), It.IsAny(), true)) + .Callback(() => queueCount++); + + pagingLogger.Setup(timeLineId, timeLineRecordId); + pagingLogger.Write(LogData); + pagingLogger.End(); + int afterEnd = queueCount; + + pagingLogger.Dispose(); + + Assert.Equal(afterEnd, queueCount); + } + } + finally + { + CleanLogFolder(); + } + } + + // Dispose before Write() should not queue uploads. + [Fact] + [Trait("Level", "L0")] + [Trait("Category", "Common")] + public void Dispose_BeforeAnyWrite_DoesNotThrow() + { + CleanLogFolder(); + + try + { + using (var hc = new TestHostContext(this)) + { + var pagingLogger = new PagingLogger(); + hc.SetSingleton(_jobServerQueue.Object); + pagingLogger.Initialize(hc); + + int queueCount = 0; + _jobServerQueue + .Setup(x => x.QueueFileUpload(It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny())) + .Callback(() => queueCount++); + + pagingLogger.Setup(Guid.NewGuid(), Guid.NewGuid()); + pagingLogger.Dispose(); + + Assert.Equal(0, queueCount); + } + } + finally + { + CleanLogFolder(); + } + } + + // Safety net: close orphaned _pageData when _pageWriter was never assigned. + [Fact] + [Trait("Level", "L0")] + [Trait("Category", "Common")] + public void Dispose_ReleasesOrphanedFileStream_WhenWriterWasNeverAssigned() + { + CleanLogFolder(); + + try + { + using (var hc = new TestHostContext(this)) + { + var pagingLogger = new PagingLogger(); + hc.SetSingleton(_jobServerQueue.Object); + pagingLogger.Initialize(hc); + pagingLogger.Setup(Guid.NewGuid(), Guid.NewGuid()); + + // Force partial-init state: _pageData set, _pageWriter null. + var pagesFolder = Path.Combine(hc.GetDirectory(WellKnownDirectory.Diag), PagingLogger.PagingFolder); + Directory.CreateDirectory(pagesFolder); + var orphanPath = Path.Combine(pagesFolder, $"orphan-{Guid.NewGuid():N}.log"); + var orphanStream = new FileStream(orphanPath, FileMode.Create, FileAccess.ReadWrite, FileShare.ReadWrite); + + typeof(PagingLogger) + .GetField("_pageData", BindingFlags.NonPublic | BindingFlags.Instance) + .SetValue(pagingLogger, orphanStream); + + pagingLogger.Dispose(); + + var closedStream = (FileStream)typeof(PagingLogger) + .GetField("_pageData", BindingFlags.NonPublic | BindingFlags.Instance) + .GetValue(pagingLogger); + Assert.Null(closedStream); + + Assert.True(orphanStream.SafeFileHandle.IsClosed, "Dispose should have closed the orphaned FileStream's handle."); + File.Delete(orphanPath); + } + } + finally + { + CleanLogFolder(); + } + } + } } diff --git a/src/Test/L0/Worker/ExecutionContextL0.cs b/src/Test/L0/Worker/ExecutionContextL0.cs index d35be3accb8..00eb261653b 100644 --- a/src/Test/L0/Worker/ExecutionContextL0.cs +++ b/src/Test/L0/Worker/ExecutionContextL0.cs @@ -1310,6 +1310,121 @@ public void InitializeJob_WorkflowIdentityNotSet_WhenServerSendsNoData() } } + [Fact] + [Trait("Level", "L0")] + [Trait("Category", "Worker")] + public void Complete_DisposesOwnedJobLogger() + { + using (TestHostContext hc = CreateTestContext()) + { + var jobRequest = CreateJobRequestMessage(); + var pagingLogger = new Mock(); + var jobServerQueue = new Mock(); + jobServerQueue.Setup(x => x.QueueTimelineRecordUpdate(It.IsAny(), It.IsAny())); + + hc.EnqueueInstance(pagingLogger.Object); + hc.SetSingleton(jobServerQueue.Object); + + var ec = new Runner.Worker.ExecutionContext(); + ec.Initialize(hc); + ec.InitializeJob(jobRequest, CancellationToken.None); + + ec.Complete(); + + pagingLogger.Verify(x => x.End(), Times.Once); + pagingLogger.Verify(x => x.Dispose(), Times.Once); + } + } + + [Fact] + [Trait("Level", "L0")] + [Trait("Category", "Worker")] + public void Complete_DisposesOwnedChildLogger() + { + using (TestHostContext hc = CreateTestContext()) + { + var jobRequest = CreateJobRequestMessage(); + var jobLogger = new Mock(); + var childLogger = new Mock(); + var jobServerQueue = new Mock(); + jobServerQueue.Setup(x => x.QueueTimelineRecordUpdate(It.IsAny(), It.IsAny())); + + hc.EnqueueInstance(jobLogger.Object); + hc.EnqueueInstance(childLogger.Object); + hc.SetSingleton(jobServerQueue.Object); + + var ec = new Runner.Worker.ExecutionContext(); + ec.Initialize(hc); + ec.InitializeJob(jobRequest, CancellationToken.None); + + var child = ec.CreateChild(Guid.NewGuid(), "step", "step", null, "step", ActionRunStage.Main); + child.Complete(); + + childLogger.Verify(x => x.End(), Times.Once); + childLogger.Verify(x => x.Dispose(), Times.Once); + jobLogger.Verify(x => x.Dispose(), Times.Never); + } + } + + [Fact] + [Trait("Level", "L0")] + [Trait("Category", "Worker")] + public void Complete_DoesNotDisposeSharedEmbeddedLogger() + { + using (TestHostContext hc = CreateTestContext()) + { + var jobRequest = CreateJobRequestMessage(); + var pagingLogger = new Mock(); + var jobServerQueue = new Mock(); + jobServerQueue.Setup(x => x.QueueTimelineRecordUpdate(It.IsAny(), It.IsAny())); + + hc.EnqueueInstance(pagingLogger.Object); + hc.SetSingleton(jobServerQueue.Object); + + var ec = new Runner.Worker.ExecutionContext(); + ec.Initialize(hc); + ec.InitializeJob(jobRequest, CancellationToken.None); + + var embedded = ec.CreateEmbeddedChild("scope", "__embedded", Guid.NewGuid(), ActionRunStage.Main); + embedded.Complete(); + + pagingLogger.Verify(x => x.End(), Times.Once); + pagingLogger.Verify(x => x.Dispose(), Times.Never); + } + } + + private Pipelines.AgentJobRequestMessage CreateJobRequestMessage() + { + var jobRequest = new Pipelines.AgentJobRequestMessage( + new TaskOrchestrationPlanReference(), + new TimelineReference(), + Guid.NewGuid(), + "some job name", + "some job name", + null, + null, + null, + new Dictionary(), + new List(), + new Pipelines.JobResources(), + new Pipelines.ContextData.DictionaryContextData(), + new Pipelines.WorkspaceOptions(), + new List(), + null, + null, + null, + null, + null); + jobRequest.Resources.Repositories.Add(new Pipelines.RepositoryResource() + { + Alias = Pipelines.PipelineConstants.SelfAlias, + Id = "github", + Version = "sha1" + }); + jobRequest.ContextData["github"] = new Pipelines.ContextData.DictionaryContextData(); + return jobRequest; + } + private bool ExpressionValuesAssertEqual(DictionaryContextData expect, DictionaryContextData actual) { foreach (var key in expect.Keys.ToList())