Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
54 changes: 53 additions & 1 deletion src/Runner.Common/Logging.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -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;
}
}
}
23 changes: 22 additions & 1 deletion src/Runner.Worker/ExecutionContext.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -411,6 +412,7 @@ public IExecutionContext CreateChild(
else
{
child._logger = HostContext.CreateService<IPagingLogger>();
child._ownsLogger = true;
child._logger.Setup(_mainTimelineId, recordId);
}

Expand Down Expand Up @@ -552,7 +554,14 @@ public TaskResult Complete(TaskResult? result = null, string currentOperation =
_cancellationTokenSource?.Dispose();
}

_logger.End();
try
{
_logger.End();
}
finally
{
DisposeOwnedLogger();
}

UpdateGlobalStepsContext();

Expand Down Expand Up @@ -961,6 +970,7 @@ public void InitializeJob(Pipelines.AgentJobRequestMessage message, Cancellation

// Logger (must be initialized before writing warnings).
_logger = HostContext.CreateService<IPagingLogger>();
_ownsLogger = true;
_logger.Setup(_mainTimelineId, _record.Id);

// Initialize 'echo on action command success' property, default to false, unless Step_Debug is set
Expand Down Expand Up @@ -1277,6 +1287,17 @@ private IExecutionContext CreatePostChild(string displayName, Dictionary<string,
return CreateChild(newGuid, displayName, newGuid.ToString("N"), null, null, ActionRunStage.Post, intraActionState, _childTimelineRecordOrder - Root.PostJobSteps.Count, siblingScopeName: siblingScopeName);
}

private void DisposeOwnedLogger()
{
if (!_ownsLogger)
{
return;
}

_logger.Dispose();
_ownsLogger = false;
}

// Sets debug using vars context in case debug variables are not present.
private static void SetDebugUsingVars(IDictionary<string, VariableValue> variables, IDictionary<string, PipelineContextData> contextData)
{
Expand Down
7 changes: 5 additions & 2 deletions src/Runner.Worker/JobRunner.cs
Original file line number Diff line number Diff line change
Expand Up @@ -411,13 +411,16 @@ private async Task<TaskResult> CompleteJobAsync(IRunServer runServer, IExecution
private async Task<TaskResult> 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);
Expand Down
211 changes: 211 additions & 0 deletions src/Test/L0/PagingLoggerL0.cs
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
using Moq;
using System;
using System.IO;
using System.Reflection;
using Xunit;

namespace GitHub.Runner.Common.Tests.Listener
Expand Down Expand Up @@ -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<IJobServerQueue>(_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<string>(), It.IsAny<string>(), It.IsAny<string>(), true))
.Callback((Guid _, Guid _, string _, string _, string path, bool _) => queuedPagePath = path);

string queuedBlockPath = null;
_jobServerQueue
.Setup(x => x.QueueResultsUpload(timeLineRecordId, It.IsAny<string>(), It.IsAny<string>(), It.IsAny<string>(), true, It.IsAny<bool>(), It.IsAny<bool>(), It.IsAny<long>()))
.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<IJobServerQueue>(_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<string>(), It.IsAny<string>(), It.IsAny<string>(), true))
.Callback(() => queueFileUploadCount++);
_jobServerQueue
.Setup(x => x.QueueResultsUpload(timeLineRecordId, It.IsAny<string>(), It.IsAny<string>(), It.IsAny<string>(), true, It.IsAny<bool>(), It.IsAny<bool>(), It.IsAny<long>()))
.Callback(() => queueResultsUploadCount++);

pagingLogger.Setup(timeLineId, timeLineRecordId);
pagingLogger.Write(LogData);
pagingLogger.Dispose();
pagingLogger.Dispose();

Assert.Equal(1, queueFileUploadCount);
Assert.Equal(1, queueResultsUploadCount);
}
Comment thread
herbenderbler marked this conversation as resolved.
}
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<IJobServerQueue>(_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<string>(), It.IsAny<string>(), It.IsAny<string>(), 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<IJobServerQueue>(_jobServerQueue.Object);
pagingLogger.Initialize(hc);

int queueCount = 0;
_jobServerQueue
.Setup(x => x.QueueFileUpload(It.IsAny<Guid>(), It.IsAny<Guid>(), It.IsAny<string>(), It.IsAny<string>(), It.IsAny<string>(), It.IsAny<bool>()))
.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<IJobServerQueue>(_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();
}
}

}
}
Loading