/// Constructor
public ExecutionLogFileReader(BinaryLogReader binaryLogReader, IExecutionLogTarget target)
{
Contract.Requires(binaryLogReader != null);
Contract.Requires(target != null);
m_target = target;
Reader = binaryLogReader;
RegisterHandlers(Reader);
}
private LogData ProcessLog(string resourceName, string cloneRoot, string userName, string repo, string hash, CheckRunConfiguration checkRunConfiguration = null)
{
var resourcePath = TestUtils.GetResourcePath(resourceName);
File.Exists(resourcePath).Should().BeTrue();
var binaryLogReader = new BinaryLogReader();
var logProcessor = new BinaryLogProcessor(binaryLogReader, TestLogger.Create <BinaryLogProcessor>(_testOutputHelper));
return(logProcessor.ProcessLog(resourcePath, cloneRoot, userName, repo, hash, checkRunConfiguration));
}
private void RegisterHandlers(BinaryLogReader logReader)
{
foreach (ExecutionLogEventMetadata meta in ExecutionLogMetadata.Events)
{
ExecutionLogEventMetadata thisMeta = meta;
logReader.RegisterHandler(
(uint)thisMeta.EventId,
(id, workerId, timestamp, eventReader) =>
{
if (m_target.CanHandleEvent(thisMeta.EventId, workerId, timestamp, eventReader.CurrentEventPayloadSize))
{
thisMeta.DeserializeAndLogToTarget(eventReader, m_target);
}
});
}
}
public static void Main(string[] args)
{
if (args.Length != 2)
{
PrintErrorMessage("Exactly two argument is required");
}
if (!File.Exists(args[0]))
{
PrintErrorMessage($"File not found: {args[0]}");
}
using var binaryLogReader = new BinaryLogReader(args[0]);
var events = binaryLogReader.ReadEvents();
var graphBuilder = new GraphBuilder();
var build = graphBuilder.HandleEvents(events.ToArray());
PrintProjectNodes(build);
PrintScanAndParseResults(args[1]);
}
public async Task LogExecutionBlobAsync(WorkerNotificationArgs notification)
{
Contract.Requires(notification.ExecutionLogData != null || notification.ExecutionLogData.Count != 0);
m_executionBlobQueue.Add(notification);
// After we put the executionBlob in a queue, we can unblock the caller and give an ACK to the worker.
await Task.Yield();
// Execution log events cannot be logged by multiple threads concurrently since they must be ordered
using (await m_logBlobMutex.AcquireAsync())
{
// We need to dequeue and process the blobs in order.
// Here, we do not necessarily process the blob that is just added to the queue above.
// There might be another thread that adds the next blob to the queue after the current thread,
// and that thread might acquire the lock earlier.
WorkerNotificationArgs executionBlobNotification = null;
Contract.Assert(m_executionBlobQueue.TryTake(out executionBlobNotification), "The executionBlob queue cannot be empty");
int blobSequenceNumber = executionBlobNotification.ExecutionLogBlobSequenceNumber;
ArraySegment <byte> executionLogBlob = executionBlobNotification.ExecutionLogData;
if (m_workerExecutionLogTarget == null)
{
return;
}
try
{
// Workers send execution log blobs one-at-a-time, waiting for a response from the master between each message.
// A sequence number higher than the last logged blob sequence number indicates a worker sent a subsequent blob without waiting for a response.
Contract.Assert(blobSequenceNumber <= m_lastBlobSeqNumber + 1, "Workers should not send a new execution log blob until receiving a response from the master for all previous blobs.");
// Due to network latency and retries, it's possible to receive a message multiple times.
// Ignore any low numbered blobs since they should have already been logged and ack'd at some point before
// the worker could send a higher numbered blob.
if (blobSequenceNumber != m_lastBlobSeqNumber + 1)
{
return;
}
if (m_executionLogBufferStream == null)
{
// Create the stream on demand, because we need to pass the BinaryLogReader stream with the header bytes in order
// to correctly deserialize events
m_executionLogBufferStream = new MemoryStream();
}
// Write the new execution log event content into buffer starting at beginning of buffer stream
m_executionLogBufferStream.SetLength(0);
m_executionLogBufferStream.Write(executionLogBlob.Array, executionLogBlob.Offset, executionLogBlob.Count);
// Reset the buffer stream to beginning and reset reader to ensure it reads events starting from beginning
m_executionLogBufferStream.Position = 0;
if (m_executionLogBinaryReader == null)
{
m_executionLogBinaryReader = new BinaryLogReader(m_executionLogBufferStream, m_masterService.Environment.Context);
m_executionLogReader = new ExecutionLogFileReader(m_executionLogBinaryReader, m_workerExecutionLogTarget);
}
m_executionLogBinaryReader.Reset();
// Read all events into worker execution log target
if (!m_executionLogReader.ReadAllEvents())
{
Logger.Log.DistributionCallMasterCodeException(m_appLoggingContext, nameof(LogExecutionBlobAsync), "Failed to read all worker events");
// Disable further processing of execution log since an error was encountered during processing
m_workerExecutionLogTarget = null;
}
else
{
m_lastBlobSeqNumber = blobSequenceNumber;
}
}
catch (Exception ex)
{
Logger.Log.DistributionCallMasterCodeException(m_appLoggingContext, nameof(LogExecutionBlobAsync), ex.ToStringDemystified() + Environment.NewLine
+ "Message sequence number: " + blobSequenceNumber
+ " Last sequence number logged: " + m_lastBlobSeqNumber);
// Disable further processing of execution log since an exception was encountered during processing
m_workerExecutionLogTarget = null;
}
}
if (m_executionBlobQueue.IsCompleted)
{
m_executionBlobCompletion.TrySetResult(true);
}
}
public void LogExecutionBlob(ArraySegment <byte> executionLogBlob, int blobSequenceNumber)
{
// Execution log events cannot be logged by multiple threads concurrently since they must be ordered
lock (m_logBlobLock)
{
if (m_workerExecutionLogTarget == null)
{
return;
}
try
{
// Workers send execution log blobs one-at-a-time, waiting for a response from the master between each message.
// A sequence number higher than the last logged blob sequence number indicates a worker sent a subsequent blob without waiting for a response.
Contract.Assert(blobSequenceNumber <= m_lastBlobSeqNumber + 1, "Workers should not send a new execution log blob until receiving a response from the master for all previous blobs.");
// Due to network latency and retries, it's possible to receive a message multiple times.
// Ignore any low numbered blobs since they should have already been logged and ack'd at some point before
// the worker could send a higher numbered blob.
if (blobSequenceNumber != m_lastBlobSeqNumber + 1)
{
return;
}
if (m_executionLogBufferStream == null)
{
// Create the stream on demand, because we need to pass the BinaryLogReader stream with the header bytes in order
// to correctly deserialize events
m_executionLogBufferStream = new MemoryStream();
}
// Write the new execution log event content into buffer starting at beginning of buffer stream
m_executionLogBufferStream.SetLength(0);
m_executionLogBufferStream.Write(executionLogBlob.Array, executionLogBlob.Offset, executionLogBlob.Count);
// Reset the buffer stream to beginning and reset reader to ensure it reads events starting from beginning
m_executionLogBufferStream.Position = 0;
if (m_executionLogBinaryReader == null)
{
m_executionLogBinaryReader = new BinaryLogReader(m_executionLogBufferStream, m_masterService.Environment.Context);
m_executionLogReader = new ExecutionLogFileReader(m_executionLogBinaryReader, m_workerExecutionLogTarget);
}
m_executionLogBinaryReader.Reset();
// Read all events into worker execution log target
if (!m_executionLogReader.ReadAllEvents())
{
Logger.Log.DistributionCallMasterCodeException(m_appLoggingContext, nameof(LogExecutionBlob), "Failed to read all worker events");
// Disable further processing of execution log since an error was encountered during processing
m_workerExecutionLogTarget = null;
}
else
{
m_lastBlobSeqNumber = blobSequenceNumber;
}
}
catch (Exception ex)
{
Logger.Log.DistributionCallMasterCodeException(m_appLoggingContext, nameof(LogExecutionBlob), ex.ToStringDemystified() + Environment.NewLine
+ "Message sequence number: " + blobSequenceNumber
+ " Last sequence number logged: " + m_lastBlobSeqNumber);
// Disable further processing of execution log since an exception was encountered during processing
m_workerExecutionLogTarget = null;
}
}
}
public void RoundTripLog()
{
BuildXLContext context = BuildXLContext.CreateInstanceForTesting();
var pt = context.PathTable;
string path1 = A("c", "a", "b", "c");
var ap1 = AbsolutePath.Create(pt, path1);
string path2 = A("c", "d", "c", "a");
var ap2 = AbsolutePath.Create(pt, path2);
string path3 = A("d", "a", "c", "a");
var ap3 = AbsolutePath.Create(pt, path3);
string path3Caps = A("D", "A", "c", "a");
var ap3Caps = AbsolutePath.Create(pt, path3Caps);
int lastTestCase0EventIteration = 0;
int testCase0EventIteration = 0;
int expectedReadCount = 0;
Guid logId = Guid.NewGuid();
using (MemoryStream ms = new MemoryStream())
{
using (BinaryLogger writer = new BinaryLogger(ms, context, logId, lastStaticAbsolutePathIndex: ap2.Value.Value, closeStreamOnDispose: false))
{
using (var eventScope = writer.StartEvent((uint)EventId.TestCase0, workerId: 0))
{
eventScope.Writer.Write(ap1);
eventScope.Writer.Write("test string");
eventScope.Writer.Write(ap3);
eventScope.Writer.Write(12345);
expectedReadCount++;
lastTestCase0EventIteration++;
}
using (var eventScope = writer.StartEvent((uint)EventId.TestCase0, workerId: 0))
{
eventScope.Writer.Write("test string 2");
eventScope.Writer.Write(true);
eventScope.Writer.Write(ap3);
expectedReadCount++;
lastTestCase0EventIteration++;
}
}
ms.Position = 0;
using (BinaryLogReader reader = new BinaryLogReader(ms, context))
{
XAssert.IsTrue(reader.LogId.HasValue);
XAssert.AreEqual(logId, reader.LogId.Value);
reader.RegisterHandler((uint)EventId.TestCase0, (eventId, workerId, timestamp, eventReader) =>
{
switch (testCase0EventIteration)
{
case 0:
XAssert.AreEqual(ap1, eventReader.ReadAbsolutePath());
XAssert.AreEqual("test string", eventReader.ReadString());
XAssert.AreEqual(ap3, eventReader.ReadAbsolutePath());
XAssert.AreEqual(12345, eventReader.ReadInt32());
break;
case 1:
XAssert.AreEqual("test string 2", eventReader.ReadString());
XAssert.AreEqual(true, eventReader.ReadBoolean());
XAssert.AreEqual(ap3, eventReader.ReadAbsolutePath());
break;
default:
XAssert.Fail("Event raised unexpected number of times.");
break;
}
testCase0EventIteration++;
});
reader.RegisterHandler((uint)EventId.UnusedEvent, (eventId, workerId, timestamp, eventReader) =>
{
XAssert.Fail("This event should never be called.");
});
int readCount = 0;
BinaryLogReader.EventReadResult?readResult;
while ((readResult = reader.ReadEvent()) == BinaryLogReader.EventReadResult.Success)
{
XAssert.IsTrue(readCount < expectedReadCount);
readCount++;
}
XAssert.AreEqual(expectedReadCount, readCount);
XAssert.AreEqual(lastTestCase0EventIteration, testCase0EventIteration);
XAssert.AreEqual(BinaryLogReader.EventReadResult.EndOfStream, readResult);
}
}
}
