protected void QueueEtwTrace(DecodedEventWrapper e)
{
// Events are always processed in batches where each batch contains
// events that have the same timestamp. The reason is as follows.
//
// The last batch of events from an active ETL file (i.e. an ETL
// file that ETW is still writing to) might be read more than once.
// This is because we don't know whether more events will get
// written to that ETL file with the exact same timestamp after the
// current pass. Therefore, we make note of that timestamp and
// retrieve events from that timestamp in the next pass too. As a
// result, some of those events might get read more than once.
// Because of this, special handling is required for the last batch
// of events in an active ETL file. Therefore, we process ETW events
// in batches, where a batch is defined as a set of events bearing
// the same timestamp.
// Check if we should process the ETW events that we have batched up
// so far.
if (this.ShouldProcessPendingEtwTraces(e.Timestamp))
{
this.ProcessPendingEtwTraces();
}
// Add new ETW event to queue
this.AddToPendingEtwTraces(e);
}
private Closeness ComputeCloseness(FilterElement filterElement, DecodedEventWrapper etwEvent)
{
if (null == filterElement.TaskName)
{
// If the task name for this filter is a wildcard, the event name
// should also be a wildcard because we don't support filters of
// the format '*.<eventType>'. This means we have a wildcard match.
System.Fabric.Interop.Utility.ReleaseAssert(null == filterElement.EventType, StringResources.DCAError_EventNameNotAWildcard);
return(Closeness.TaskWildcardEventWildcardMatch);
}
if (false == filterElement.TaskName.Equals(etwEvent.TaskName))
{
// If the task name for this filter does not match the event's
// task name, then we have no match.
return(Closeness.NoMatch);
}
if (null == filterElement.EventType)
{
// If the event name for this filter is a wildcard, we have a
// task name, event wildcard match.
return(Closeness.TaskNameEventWildcardMatch);
}
if (false == filterElement.EventType.Equals(etwEvent.EventType))
{
// If the event name for this filter does not match the event's
// event name, then we have no match.
return(Closeness.NoMatch);
}
// If we get here, it means that both task name and event name match
return(Closeness.TaskNameEventTypeMatch);
}
protected override void ProcessTraceEvent(DecodedEventWrapper eventWrapper)
{
System.Fabric.Interop.Utility.ReleaseAssert(this.bookmark != null, StringResources.DCAError_ProcessTraceEventCalledUnexpectedly);
this.perfHelper.EtwEventProcessed();
// If it is a Windows Fabric event, then check the filters to see if
// the event should be included in the ETW traces.
if (this.FiltersAllowEventInclusion(eventWrapper))
{
// According to the filters, the event should be included.
// Compute the row key for this event.
//
// The row key is in the following format:
// <etlFileBookmark>_<eventSequenceNumberInEtlFile>
//
// By choosing the row key in this manner, we ensure the following:
// - The row key for an event is unique within the partition.
// Recall that the partition in this case is the deployment
// ID of the role instance.
// - If an event happens to get processed multiple times (for
// example because the previous pass was interrupted), it
// gets the same row key each time. Thus event processing is
// idempotent.
//
// Uniqueness and idempotence are ensured because the event
// sequence number for an ETL file starts at 0 on every pass and
// increases for each event in the pass. If the same ETL file is
// read in multiple passes, bookmark for that ETL file is
// different for every pass, unless a pass is interrupted. If a
// pass is interrupted, the next pass has the same bookmark, but
// it also starts reading events from the same point within the
// ETL file. Thus, the comination of bookmark and event sequence
// number for an event is always unique within a role instance
// and always the same if that event is processed multiple times.
string nodesUniqueEventId = string.Concat(
this.bookmark,
"_",
this.eventSequenceNumber.ToString(CultureInfo.InvariantCulture));
// Write the event to the cache
this.WriteTraceEvent(eventWrapper, nodesUniqueEventId);
this.perfHelper.EventWrittenToLocalBuffer();
}
// Increment the event sequence number. This needs to be done
// regardless of whether the event was included or not. This way, if
// an event is processed in multiple passes (for example because a
// previous pass was interrupted) and the filtering criteria changes
// in between passes, all events still have the same sequence numbers.
// Thus, the sequence numbers are kept independent of the results of
// filtering.
this.eventSequenceNumber++;
}
private void ProcessPendingEtwTraces()
{
while (this.pendingEtwEvents.EventList.Count > 0)
{
// Remove an event
DecodedEventWrapper e = this.pendingEtwEvents.EventList.Dequeue();
// Process the event
this.ProcessTraceEvent(e);
}
}
private void AddToPendingEtwTraces(DecodedEventWrapper e)
{
this.pendingEtwEvents.Timestamp = e.Timestamp;
// Assign a timestamp differentiator to the event in order to distinguish
// it from other events in the same ETL file that also bear the same
// timestamp. Timestamp differentiator values start at 0 for each
// timestamp and are incremented by 1 for each event bearing that
// timestamp.
e.TimestampDifferentiator = this.pendingEtwEvents.EventList.Count;
this.pendingEtwEvents.EventList.Enqueue(e);
}
private void MatchEventWithFilter(FilterElement filterElement, DecodedEventWrapper etwEvent, out Closeness closeness, out bool includeEvent)
{
includeEvent = false;
// Figure out if we have a match and if so how close is the match
closeness = this.ComputeCloseness(filterElement, etwEvent);
// If we have a match, figure out whether the event should be
// included or not
if (closeness > Closeness.NoMatch)
{
includeEvent = filterElement.Level >= etwEvent.Level;
}
}
internal bool ShouldIncludeEvent(DecodedEventWrapper etwEvent)
{
// If there are no filters, then we should include the event
if (null == this.filters)
{
return(true);
}
// If we have filters, then don't include the event unless the
// filters effectively ask for it to be included.
bool includeEvent = false;
Closeness closeness = Closeness.NoMatch;
// Go through each filter and compare ...
foreach (FilterElement filterElement in this.filters)
{
// Check if the event matches the current filter. If it matches,
// check whether the filter asks for the event to be included or
// excluded.
bool tempIncludeEvent;
Closeness tempCloseness;
this.MatchEventWithFilter(
filterElement,
etwEvent,
out tempCloseness,
out tempIncludeEvent);
// If this filter is a closer match than previously encountered
// filters, then update our decision to include or exclude the
// event.
// If this filter is not a closer match than previously
// encountered filters, then we do not update our decision.
if (tempCloseness > closeness)
{
System.Fabric.Interop.Utility.ReleaseAssert(tempCloseness != Closeness.NoMatch, string.Empty);
includeEvent = tempIncludeEvent;
closeness = tempCloseness;
if (Closeness.MaxCloseness == closeness)
{
// We already found the closest possible match. We can't
// find a closer match than this. So break out of the loop.
break;
}
}
}
return(includeEvent);
}
protected override void ProcessTraceEvent(DecodedEventWrapper eventWrapper)
{
#if !DotNetCoreClr
this.perfHelper.EtwEventProcessed();
#endif
if (null == this.fileSink)
{
// An error occurred during the creation of the temporary file
// sink. So just return immediately without doing anything.
return;
}
// Record the index of this event
this.lastEventIndex.Set(eventWrapper.Timestamp, eventWrapper.TimestampDifferentiator);
// 1. Check if the event has already been processed in a previous pass.
// This check would effectively drop out of order timestamp events.
// 2. If we are using compression, then we don't filter the logs. Just
// include everything.
// 3. If we're not using compression and it is a Windows Fabric event,
// then check the filters to see if the event should be included in
// the ETW traces.
if ((this.lastEventIndex.CompareTo(this.maxIndexAlreadyProcessed) > 0) &&
(this.compressCsvFiles || this.FiltersAllowEventInclusion(eventWrapper)))
{
// According to the filters, the event should be included.
// Write the event to the ETW CSV file.
try
{
this.fileSink.WriteEvent(eventWrapper.StringRepresentation.Replace("\r\n", "\r\t").Replace("\n", "\t"));
#if !DotNetCoreClr
this.perfHelper.EventWrittenToCsv();
#endif
}
catch (Exception e)
{
// Log an error and move on
this.TraceSource.WriteExceptionAsError(
this.LogSourceId,
e,
"Failed to write filtered event {0} to trace file {1}.",
eventWrapper.StringRepresentation,
this.fileSink.TempFileName);
}
}
}
protected bool FiltersAllowEventInclusion(DecodedEventWrapper e)
{
lock (this.FilterLock)
{
if (null == this.Filter)
{
// If the filter object is null, then the event gets included.
return(true);
}
if (this.Filter.IsWindowsFabricEventFilter)
{
if (this.IsProcessingWindowsFabricEtlFiles)
{
return(this.Filter.ShouldIncludeEvent(e));
}
return(true);
}
return(this.Filter.ShouldIncludeEvent(e));
}
}
private void WriteTraceEvent(DecodedEventWrapper eventWrapper, string nodesUniqueEventId)
{
if (null == this.streamWriter)
{
// An error occurred during the creation of the buffered event
// file. So just return immediately without doing anything.
return;
}
// NOTE: The order in which the information is written must match
// the order of the EventLineParts enumeration defined in this class.
string eventInfo = string.Format(
CultureInfo.InvariantCulture,
"{0},{1},{2},{3},{4},{5},{6},{7},{8},{9},{10},{11},{12},{13},{14},{15}",
eventWrapper.InternalEvent.EventRecord.EventHeader.ProviderId,
eventWrapper.InternalEvent.EventRecord.EventHeader.EventDescriptor.Id,
eventWrapper.InternalEvent.EventRecord.EventHeader.EventDescriptor.Version,
eventWrapper.InternalEvent.EventRecord.EventHeader.EventDescriptor.Channel,
eventWrapper.InternalEvent.EventRecord.EventHeader.EventDescriptor.Opcode,
eventWrapper.InternalEvent.EventRecord.EventHeader.EventDescriptor.Task,
eventWrapper.InternalEvent.EventRecord.EventHeader.EventDescriptor.Keyword,
nodesUniqueEventId,
eventWrapper.Timestamp.ToBinary(),
eventWrapper.Timestamp, // We write the human-readable form for easier debugging
eventWrapper.Level,
eventWrapper.ThreadId,
eventWrapper.ProcessId,
eventWrapper.TaskName,
eventWrapper.EventType,
eventWrapper.EventText);
eventInfo = eventInfo.Replace("\r\n", "\t").Replace("\n", "\t").Replace("\r", "\t");
try
{
Utility.PerformIOWithRetries(
ctx =>
{
string eventString = ctx;
try
{
this.streamWriter.WriteLine(eventString);
}
catch (System.Text.EncoderFallbackException ex)
{
// This can happen if the manifest file does not match the binary.
// Write an error message and move on.
this.TraceSource.WriteError(
this.LogSourceId,
"Exception occurred while writing filtered ETW event to buffered event file. Exception information: {0}",
ex);
}
},
eventInfo);
}
catch (Exception e)
{
// Log an error and move on
this.TraceSource.WriteExceptionAsError(
this.LogSourceId,
e,
"Failed to write ETW event to buffered event file.");
}
}
protected abstract void ProcessTraceEvent(DecodedEventWrapper eventWrapper);