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); }