private void Reader_TraceRead(object sender, EventRecordEventArgs e)
{
if (this.token.IsCancellationRequested)
{
// If cancellation has been request, let the reader know that it's time to stop.
e.Cancel = true;
// Call completed.
this.OnCompleted();
return;
}
if (e.Record.EventHeader.EventDescriptor.Version < MinimumVersionSupported)
{
return;
}
var traceRecord = this.Lookup(new TraceIdentity(e.Record.EventHeader.EventDescriptor.Id, (TaskName)e.Record.EventHeader.EventDescriptor.Task));
if (traceRecord?.Target == null)
{
return;
}
traceRecord.Level = (TraceLevel)e.Record.EventHeader.EventDescriptor.Level;
traceRecord.TracingProcessId = e.Record.EventHeader.ProcessId;
traceRecord.ThreadId = e.Record.EventHeader.ThreadId;
traceRecord.TimeStamp = DateTime.FromFileTimeUtc(e.Record.EventHeader.TimeStamp);
traceRecord.Version = e.Record.EventHeader.EventDescriptor.Version;
traceRecord.PropertyValueReader = ValueReaderCreator.CreateRawByteValueReader(traceRecord.GetType(), traceRecord.Version, e.Record.UserData, e.Record.UserDataLength);
this.DispatchAsync(traceRecord, CancellationToken.None).GetAwaiter().GetResult();
}
private void OnEventRead(object sender, EventRecordEventArgs e)
{
string[] formattedEvent = ManifestCache.FormatEvent(e.Record)?.Split(new char[] { ',' }, EtlInputFields.Count());
Log.Trivial($"formattedEvent", formattedEvent);
if (formattedEvent == null)
{
EventReadErrors++;
Log.Warning("null etl event. enable logdebug 5 and review log");
EventDefinition eventDefinition = ManifestCache.GetEventDefinition(e.Record);
Log.Debug($"null etl event: e:", e);
Log.Debug($"null etl event: eventDefinition", eventDefinition);
return;
}
_traceDispatcher(new T()
{
Timestamp = DateTime.FromFileTimeUtc(e.Record.EventHeader.TimeStamp),
Level = formattedEvent[EtlInputFields.Level],
TID = (int)e.Record.EventHeader.ThreadId,
PID = (int)e.Record.EventHeader.ProcessId,
Type = formattedEvent[EtlInputFields.Type],
Text = formattedEvent[EtlInputFields.Text]
});
}
private void OnEventFromEtl(object sender, EventRecordEventArgs e, CancellationToken cancellationToken)
{
if (cancellationToken.IsCancellationRequested)
{
// We are in the process of stopping. Don't start any new work.
return;
}
// At least one event has been read from the current ETL file
this.eventsReadFromCurrentEtl = true;
// Get the event's timestamp
EventRecord eventRecord = e.Record;
long eventTimestampFileTime = eventRecord.EventHeader.TimeStamp;
DateTime eventTimestamp = DateTime.FromFileTimeUtc(eventTimestampFileTime);
if (this.currentTimestamp == DateTime.MinValue)
{
// Current timestamp is not yet initialized. Initialize it now.
this.currentTimestamp = eventTimestamp;
}
else
{
int timeComparisonResult = DateTime.Compare(
this.currentTimestamp,
eventTimestamp);
if (0 > timeComparisonResult)
{
// Event timestamp is different from that of the last event
// we received. So we shouldn't be receiving any more events
// with the same timestamp as that of the previous event,
// i.e. we've moved forward to a new timestamp.
this.lastCompletedTimestamp = this.lastCompletedTimestamp > this.currentTimestamp
? this.lastCompletedTimestamp : this.currentTimestamp;
this.currentTimestamp = eventTimestamp;
}
else if (0 < timeComparisonResult)
{
// The event timestamp shouldn't be older than that of the
// previous event, i.e. we don't expect to move back in time.
// modifying the time of the latest event to be same as last known good event which was in order
eventRecord.EventHeader.TimeStamp = this.currentTimestamp.ToFileTimeUtc();
this.perfHelper.EtlUnorderedEventRecieved();
}
// If eventTimestamp is same as currentTimestamp then we should process the events
// we keep LastCompletedTimestamp as is
}
// Process the event
this.OnEtwTraceAvailable(eventRecord);
}
protected void OnEtwEventReceived(object sender, EventRecordEventArgs e)
{
if (this.Stopping)
{
// DCA is stopping. Don't process any more events.
return;
}
DateTime eventDateTime = DateTime.FromFileTimeUtc(e.Record.EventHeader.TimeStamp);
EtwEventTimestamp eventTimestamp = new EtwEventTimestamp();
eventTimestamp.Timestamp = eventDateTime;
if (eventDateTime.Equals(this.MostRecentEtwEventTimestamp.Timestamp))
{
// This event has the same timestamp as the previous one. Increment the
// differentiator so that we can keep track of how far we've read.
eventTimestamp.Differentiator = this.MostRecentEtwEventTimestamp.Differentiator + 1;
}
else
{
// This event has a later timestamp than the previous one. Initialize
// the differentiator to 0.
Debug.Assert(
eventDateTime.CompareTo(
this.MostRecentEtwEventTimestamp.Timestamp) > 0,
"Event timestamps should only move forward in time.");
eventTimestamp.Differentiator = 0;
}
Utility.TraceSource.WriteInfo(
TraceType,
"ETW event received. Timestamp: {0} ({1}, {2}).",
eventTimestamp.Timestamp,
eventTimestamp.Timestamp.Ticks,
eventTimestamp.Differentiator);
if (eventTimestamp.CompareTo(this.LatestProcessedEtwEventTimestamp) > 0)
{
// This event occurred after our last processed event. So we need to
// process it.
this.ProcessEtwEvent(e.Record, eventTimestamp);
// Update our latest processed event
this.LatestProcessedEtwEventTimestamp = eventTimestamp;
Utility.TraceSource.WriteInfo(
TraceType,
"The latest timestamp upto which we have processed ETW events is {0} ({1}, {2}).",
this.LatestProcessedEtwEventTimestamp.Timestamp,
this.LatestProcessedEtwEventTimestamp.Timestamp.Ticks,
this.LatestProcessedEtwEventTimestamp.Differentiator);
}
else
{
Utility.TraceSource.WriteInfo(
TraceType,
"Ignoring an ETW event because its timestamp {0} ({1}, {2}) is older than the latest timestamp {3} ({4}, {5}) that we have already processed. Ignored event ID: {6}.",
eventTimestamp.Timestamp,
eventTimestamp.Timestamp.Ticks,
eventTimestamp.Differentiator,
this.LatestProcessedEtwEventTimestamp.Timestamp,
this.LatestProcessedEtwEventTimestamp.Timestamp.Ticks,
this.LatestProcessedEtwEventTimestamp.Differentiator,
e.Record.EventHeader.EventDescriptor.Id);
}
this.MostRecentEtwEventTimestamp = eventTimestamp;
}
public void TestableOnEtwEventReceived(object sender, EventRecordEventArgs e)
{
this.OnEtwEventReceived(sender, e);
}
// TODO - Uncomment code below when totally transitioned to structured traces
//ref EventRecord eventRecord, StringBuilder unstructuredTextString, bool isUnstructured)
private void DeliverEventToSinks(object sender, EventRecordEventArgs eventRecordEventArgs)
{
var decodedEvent = new DecodedEtwEvent();
var decodingAttempted = false;
var decodingFailed = false;
this.numEventsRead++;
this.lastEventReadTimestampFileTime = eventRecordEventArgs.Record.EventHeader.TimeStamp;
EventRecord eventRecord = eventRecordEventArgs.Record;
StringBuilder unstructuredTextString = new StringBuilder(eventRecordEventArgs.UnstructuredRecord);
bool isUnstructured = eventRecordEventArgs.IsUnstructured;
List <EventRecord> rawEventList = null;
List <DecodedEtwEvent> decodedEventList = null;
foreach (var sink in this.sinksIEtlFile)
{
if (sink.NeedsDecodedEvent)
{
// This consumer needs the decoded event
if (false == decodingAttempted)
{
// We haven't yet attempted to decode the event. Attempt
// it now.
// For handling Linux legacy unstructured traces only
if (isUnstructured == true)
{
decodedEvent.StringRepresentation = unstructuredTextString.ToString();
decodingFailed = false;
decodingAttempted = true;
}
else
{
try
{
string unusedOriginalEventName;
if (false == this.DecodeEvent(ref eventRecord, out decodedEvent, out unusedOriginalEventName))
{
// Our attempt to decode the event failed
decodingFailed = true;
}
}
catch (Exception e)
{
this.traceSource.WriteError(
this.logSourceId,
"Exception encountered while decoding Ltt event. The event will be skipped. Event ID: {0}, Task: {1}, Level: {2}. Exception information: {3}",
eventRecord.EventHeader.EventDescriptor.Id,
eventRecord.EventHeader.EventDescriptor.Task,
eventRecord.EventHeader.EventDescriptor.Level,
e);
decodingFailed = true;
}
}
if (false == decodingFailed)
{
// Our attempt to decode the event succeeded. Put it
// in the event list.
Debug.Assert(null == decodedEventList, "Decoded event list should not be initialized previously.");
decodedEventList = new List <DecodedEtwEvent> {
decodedEvent
};
}
decodingAttempted = true;
}
if (false == decodingFailed)
{
sink.OnEtwEventsAvailable(decodedEventList);
}
}
else
{
if (isUnstructured == false)
{
// This consumer needs the raw event
if (null == rawEventList)
{
// Put the event in the event list
rawEventList = new List <EventRecord> {
eventRecord
};
}
if (sink is IEtlFileSink)
{
IEtlFileSink sinkEtl = sink as IEtlFileSink;
sinkEtl.OnEtwEventsAvailable(rawEventList);
}
}
}
}
}
// TODO This eventually needs to be moved to its own Consumer so event is not decoded more than once.
// EventRecord eventRecord, string lttUnstructuredTextEventString, string taskNameEventNameFromUnstructured, bool isUnstructuredLtt, StreamWriter fileStreamDtr, StreamWriter fileStreamTable)
private void WriteEventToCsvAndTableFiles(object sender, EventRecordEventArgs eventRecordEventArgs)
{
EventRecord eventRecord = eventRecordEventArgs.Record;
string lttUnstructuredTextEventString = eventRecordEventArgs.UnstructuredRecord;
string taskNameEventNameFromUnstructured = eventRecordEventArgs.TaskNameEventName;
bool isUnstructuredLtt = eventRecordEventArgs.IsUnstructured;
DecodedEtwEvent decodedEvent;
string taskNameEventName = taskNameEventNameFromUnstructured;
decodedEvent.StringRepresentation = null;
bool decodingFailed = false;
// Test whether event needs to be decoded.
if (!isUnstructuredLtt)
{
try
{
string originalEventName;
if (false == this.DecodeEvent(ref eventRecord, out decodedEvent, out originalEventName))
{
// Our attempt to decode the event failed
decodingFailed = true;
}
// TODO - to be removed after transitioning for structured traces in Linux
taskNameEventName = $"{decodedEvent.TaskName}.{originalEventName}";
}
catch (Exception e)
{
this.traceSource.WriteError(
this.logSourceId,
"Exception encountered while decoding ETW event. The event will be skipped. Event ID: {0}, Task: {1}, Level: {2}. Exception information: {3}",
eventRecord.EventHeader.EventDescriptor.Id,
eventRecord.EventHeader.EventDescriptor.Task,
eventRecord.EventHeader.EventDescriptor.Level,
e);
decodingFailed = true;
}
}
else
{
// legacy Service Fabric traces which consisted only of Unstructured traces.
decodedEvent = new DecodedEtwEvent()
{
StringRepresentation = lttUnstructuredTextEventString
};
}
if (false == decodingFailed)
{
// Our attempt to decode the event succeeded. Put it
// writing to dtr file
string replacedLFStringRepresentation = decodedEvent.StringRepresentation.Replace("\r\n", "\r\t").Replace("\n", "\t");
try
{
this.fileStreamDtr.Write(replacedLFStringRepresentation);
this.fileStreamDtr.Write("\r\n");
if (this.fileStreamTable != null && this.tableEventsWhiteList.Contains(taskNameEventName))
{
this.fileStreamTable.Write(replacedLFStringRepresentation);
this.fileStreamTable.Write("\r\n");
}
}
catch (System.Text.EncoderFallbackException)
{
this.dataCorruptionStatistics++;
}
}
}
