internal void ProcessInactiveEtlFile(FileInfo etlFile, DateTime lastEndTime, CancellationToken cancellationToken)
{
this.currentTimestamp = DateTime.MinValue;
// Raise an event to indicate that we're starting on a new ETL file
this.OnEtlFileReadStart(etlFile.Name, false, lastEndTime);
// Read events from the ETL file
DateTime startTime = this.GetStartTime(lastEndTime);
DateTime endTime = this.processingWinFabEvents ? DateTime.MaxValue : Utility.ApplicationEtwTracesEndTime;
ITraceFileEventReader eventReader;
try
{
eventReader = this.traceFileEventReaderFactory.CreateTraceFileEventReader(etlFile.FullName);
}
catch (FileNotFoundException e)
{
// The file was not found, most likely because it was deleted by
// the our old logs deletion routine.
//
// NOTE: The method that processes the active ETL file does not handle
// this exception because we have logic to avoid deleting an active
// ETL file. We don't want to delete the active ETL file because ETW is
// still writing to it.
this.traceSource.WriteWarning(
this.logSourceId,
"Exception occurred while trying to process ETL file {0}. The file may have been deleted. Exception information: {1}",
etlFile.FullName,
e);
// Raise an event to indicate that we're done with this ETL file
this.OnEtlFileReadStop(etlFile.Name, false, lastEndTime, this.lastCompletedTimestamp, true);
return;
}
eventReader.EventRead += (sender, args) => this.OnEventFromEtl(sender, args, cancellationToken);
this.eventsReadFromCurrentEtl = false;
ReadEventsParameters readParam = new ReadEventsParameters()
{
EventReader = eventReader,
StartTime = startTime,
EndTime = endTime
};
try
{
var traceSessionMetadata = eventReader.ReadTraceSessionMetadata();
FabricEvents.Events.TraceSessionStats(
traceSessionMetadata.TraceSessionName,
traceSessionMetadata.EventsLostCount,
traceSessionMetadata.StartTime,
traceSessionMetadata.EndTime);
Utility.PerformWithRetries(
ReadEventsWorker,
readParam,
new RetriableOperationExceptionHandler(this.ReadEventsExceptionHandler));
}
catch (Exception e)
{
this.traceSource.WriteExceptionAsError(
this.logSourceId,
e,
"Failed to read some or all of the events from ETL file {0}.",
etlFile.FullName);
}
finally
{
eventReader.Dispose();
}
// Raise an event to indicate that we're done with this ETL file
this.OnEtlFileReadStop(etlFile.Name, false, lastEndTime, this.lastCompletedTimestamp, cancellationToken.IsCancellationRequested);
// We're done with this ETL file. Create a marker file for it.
if (!cancellationToken.IsCancellationRequested)
{
string etlFileMarker = Path.Combine(
this.markerFileDirectory,
etlFile.Name);
try
{
Utility.PerformIOWithRetries(
() =>
{
// Create file
using (FileStream fs = FabricFile.Create(etlFileMarker))
{
}
});
this.traceSource.WriteInfo(
this.logSourceId,
"Marker file {0} created.",
etlFileMarker);
}
catch (Exception e)
{
this.traceSource.WriteExceptionAsError(
this.logSourceId,
e,
"Failed to create marker file {0}.",
etlFileMarker);
}
}
else
{
// The producer is being stopped. It is possible that we didn't fully
// process this ETL file because we detected that the producer was
// being stopped. Therefore do not create a marker file for it in the
// archived traces directory yet. We should process it again when the
// producer is restarted.
this.traceSource.WriteInfo(
this.logSourceId,
"The producer is being stopped. Therefore, no marker file will be created for ETL file {0} in the archived traces directory.",
etlFile.FullName);
}
}
private static void ReadEventsWorker(ReadEventsParameters readParam)
{
readParam.EventReader.ReadEvents(readParam.StartTime, readParam.EndTime);
}
internal void ProcessActiveEtlFile(FileInfo etlFile, DateTime lastEndTime, out DateTime newEndTime, CancellationToken cancellationToken)
{
// When processing an active ETL file (i.e. an ETL file which ETW is
// still writing to), the following needs to be kept in mind:
//
// - We need to process this ETL file again in our next pass
// (because more events can be added to it after this pass). So
// the file should *not* be moved to the archived traces folder
// when we are done with it in this pass.
//
// - When we read the last event that is available from this ETL
// file in this pass, we *cannot* safely assume that more events
// with the exact same timestamp will not get added to this ETL
// file in the future. Therefore, the ending timestamp for this
// pass (which determines the starting timestamp for the next
// pass) should be computed such that we handle this corner case,
// i.e. if more events with the same timestamp do get added, we
// should be able to pick them up in our next pass.
this.lastCompletedTimestamp = lastEndTime;
this.currentTimestamp = DateTime.MinValue;
// Raise an event to indicate that we're starting on a new ETL file
this.OnEtlFileReadStart(etlFile.Name, true, lastEndTime);
// Read events from the ETL file
DateTime startTime = this.GetStartTime(lastEndTime);
// We read ETW events only up to the point where we are fairly sure they
// have been flushed to disk. To do this, we multiple the flush interval
// by a constant (to give us some extra cushion) and then subtract the
// result from current time.
const double EndTimeOffsetSeconds = -1 * EtlProducerConstants.DefaultTraceSessionFlushIntervalSeconds *
EtlProducerConstants.TraceSessionFlushIntervalMultiplier;
DateTime endTime = DateTime.UtcNow.AddSeconds(EndTimeOffsetSeconds);
if (false == this.processingWinFabEvents)
{
// If we're processing application traces but we do not have full
// knowledge of applications in the system up to the end time, then
// we push the end time further back to the time up to which we have
// full knowledge of applications in the system.
DateTime appEtwTracesEndTime = Utility.ApplicationEtwTracesEndTime;
if (endTime.CompareTo(appEtwTracesEndTime) > 0)
{
endTime = appEtwTracesEndTime;
}
}
var eventReader = this.traceFileEventReaderFactory.CreateTraceFileEventReader(etlFile.FullName);
eventReader.EventRead += (sender, args) => this.OnEventFromEtl(sender, args, cancellationToken);
this.eventsReadFromCurrentEtl = false;
ReadEventsParameters readParam = new ReadEventsParameters
{
EventReader = eventReader,
StartTime = startTime,
EndTime = endTime
};
try
{
Utility.PerformWithRetries(
ReadEventsWorker,
readParam,
new RetriableOperationExceptionHandler(this.ReadEventsExceptionHandler));
}
catch (Exception e)
{
this.traceSource.WriteExceptionAsError(
this.logSourceId,
e,
"Failed to read some or all of the events from ETL file {0}.",
etlFile.FullName);
}
finally
{
eventReader.Dispose();
}
// The end time for this pass is chosen as the latest timestamp for
// which we know for sure that we will not receive any more events.
//
// It is possible that we already read events with a later timestamp
// than the chosen end time for this pass. This happens when we
// cannot be sure that we won't receive any more events with that
// later timestamp after we complete this pass. By choosing an
// earlier end time, we enable ourselves to pick up additional
// events with that later timestamp in our next pass. However, this
// also means that some events that we already read in this pass may
// be read again in the next pass. This is okay because processing
// of events is designed to be idempotent.
newEndTime = this.lastCompletedTimestamp;
// We'll need to read from this ETL file again in the next pass.
// Don't move it to the archived traces folder yet.
// Raise an event to indicate that we're done with this ETL file
// (for this pass)
this.OnEtlFileReadStop(etlFile.Name, true, lastEndTime, this.lastCompletedTimestamp, cancellationToken.IsCancellationRequested);
}
