Beispiel #1
0
        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);
        }
Beispiel #2
0
        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++;
        }
Beispiel #4
0
        private void ProcessPendingEtwTraces()
        {
            while (this.pendingEtwEvents.EventList.Count > 0)
            {
                // Remove an event
                DecodedEventWrapper e = this.pendingEtwEvents.EventList.Dequeue();

                // Process the event
                this.ProcessTraceEvent(e);
            }
        }
Beispiel #5
0
        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);
        }
Beispiel #6
0
        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;
            }
        }
Beispiel #7
0
        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);
        }
Beispiel #8
0
        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);
                }
            }
        }
Beispiel #9
0
        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.");
            }
        }
Beispiel #11
0
 protected abstract void ProcessTraceEvent(DecodedEventWrapper eventWrapper);