public override void ProcessSource(
ISourceDataProcessor <DmesgIsoLogParsedEntry, LogContext, LogParsedDataKey> dataProcessor,
ILogger logger, IProgress <int> progress, CancellationToken cancellationToken)
{
var contentDictionary = new Dictionary <string, IReadOnlyList <LogEntry> >();
string[] lineContent;
string[] firstSlice;
StringBuilder builder = new StringBuilder();
Timestamp oldestTimestamp = new Timestamp(long.MaxValue);
Timestamp newestTImestamp = new Timestamp(long.MinValue);
long startNanoSeconds = 0;
DateTime fileStartTime = default;
DateTime parsedTime = default;
var dateTimeCultureInfo = new CultureInfo("en-US");
foreach (var path in FilePaths)
{
ulong currentLineNumber = 1;
var file = new System.IO.StreamReader(path);
string line = string.Empty;
var entriesList = new List <LogEntry>();
LogEntry lastEntry = null;
while ((line = file.ReadLine()) != null)
{
//First, we check if the line is a new log entry by trying to parse its timestamp
if (line.Length >= 31 && DateTime.TryParseExact(line[..31], "yyyy-MM-ddTHH:mm:ss,ffffffK", dateTimeCultureInfo, DateTimeStyles.None, out parsedTime))
public override void ProcessSource(ISourceDataProcessor <QuicEvent, object, Guid> dataProcessor, ILogger logger, IProgress <int> progress, CancellationToken cancellationToken)
{
switch (sourceType)
{
case QuicEventSourceType.ETW:
ProcessEtwSource(dataProcessor, progress, cancellationToken);
break;
default:
throw new NotSupportedException("Source type not supported");
}
}
private void ProcessEtwSource(ISourceDataProcessor <QuicEvent, object, Guid> dataProcessor, IProgress <int> progress, CancellationToken cancellationToken)
{
using var source = new ETWTraceEventSource(filePaths);
long StartTime = 0;
source.AllEvents += (evt) =>
{
if (cancellationToken.IsCancellationRequested)
{
source.StopProcessing();
return;
}
if (info == null && evt.TimeStamp.Ticks != 0 && !IsKnownSynthEvent(evt))
{
StartTime = evt.TimeStamp.Ticks;
var firstEventNano = (evt.TimeStamp.Ticks - source.SessionStartTime.Ticks) * 100;
var lastEventNano = (source.SessionEndTime.Ticks - source.SessionStartTime.Ticks) * 100;
info = new DataSourceInfo(firstEventNano, lastEventNano, evt.TimeStamp.ToUniversalTime());
}
else if (evt.ProviderGuid == QuicEvent.ProviderGuid)
{
try
{
var quicEvent = QuicEtwEvent.TryCreate(evt, new Timestamp((evt.TimeStamp.Ticks - StartTime) * 100));
if (quicEvent != null)
{
dataProcessor.ProcessDataElement(quicEvent, this, cancellationToken);
}
}
catch (Exception ex)
{
Console.WriteLine(ex.ToString());
}
}
progress.Report((int)(evt.TimeStampRelativeMSec / source.SessionEndTimeRelativeMSec * 100));
};
source.Process();
if (info == null)
{
info = new DataSourceInfo(0, (source.SessionEndTime.Ticks - source.SessionStartTime.Ticks) * 100, source.SessionStartTime.ToUniversalTime());
}
}
private void ProcessEtwSource(ISourceDataProcessor <QuicEvent, object, Guid> dataProcessor, IProgress <int> progress, CancellationToken cancellationToken)
{
using var source = new ETWTraceEventSource(filePaths);
long StartTime = 0;
source.AllEvents += (evt) =>
{
bool isOriginalHeader = source.SessionStartTime == evt.TimeStamp;
if (info == null &&
!isOriginalHeader &&
!IsKnownSynthEvent(evt) &&
evt.TimeStamp.Ticks != 0)
{
var deltaBetweenStartAndFirstTicks = evt.TimeStamp.Ticks - source.SessionStartTime.Ticks;
var relativeNanoSeconds = deltaBetweenStartAndFirstTicks * 100;
StartTime = evt.TimeStamp.Ticks;
var lastnano = relativeNanoSeconds + ((source.SessionEndTime.Ticks - evt.TimeStamp.Ticks) * 100);
info = new DataSourceInfo(relativeNanoSeconds, lastnano, evt.TimeStamp.ToUniversalTime());
}
progress.Report((int)(evt.TimeStampRelativeMSec / source.SessionEndTimeRelativeMSec * 100));
};
source.AllEvents += (evt) =>
{
if (cancellationToken.IsCancellationRequested)
{
source.StopProcessing();
return;
}
if (evt.ProviderGuid == MsQuicEtwGuid)
{
var quicEvent = new QuicEtwEvent(evt, new Timestamp((evt.TimeStamp.Ticks - StartTime) * 100));
dataProcessor.ProcessDataElement(quicEvent, this, cancellationToken);
}
};
source.Process();
if (info == null)
{
info = new DataSourceInfo(0, (source.SessionEndTime.Ticks - source.SessionStartTime.Ticks) * 100, source.SessionStartTime.ToUniversalTime());
}
}
/// <inheritdoc />
public void ProcessSource(
ISourceDataProcessor <TestRecord, TestParserContext, int> dataProcessor,
ILogger logger,
IProgress <int> progress,
CancellationToken cancellationToken)
{
if (this.TestRecords == null)
{
return;
}
foreach (var testRecord in this.TestRecords)
{
dataProcessor.ProcessDataElement(testRecord, new TestParserContext(), cancellationToken);
}
progress.Report(100);
}
public override void ProcessSource(
ISourceDataProcessor <Source123DataObject, EngineTestContext, int> dataProcessor,
ILogger logger,
IProgress <int> progress, CancellationToken cancellationToken)
{
foreach (var line in this.filePaths
.SelectMany(x => File.ReadAllLines(x))
.Where(x => x.Length > 0 && x[0] != '#'))
{
var split = line.Split(',');
dataProcessor.ProcessDataElement(
new Source123DataObject
{
Id = int.Parse(split[0]),
Data = split[1],
},
new EngineTestContext(),
cancellationToken);
}
}
public override void ProcessSource(
ISourceDataProcessor <LTTngEvent, LTTngContext, string> dataProcessor,
ILogger logger,
IProgress <int> progress,
CancellationToken cancellationToken)
{
Progress <byte> progressReport = new Progress <byte>((percentComplete) => progress.Report(percentComplete));
void EventCallback(LTTngEvent lttngEvent, LTTngContext lttngContext)
{
if (this.EventCount == 0)
{
this.FirstEventTimestamp = lttngEvent.Timestamp;
this.FirstEventWallClock = lttngEvent.WallClockTime;
}
else
{
this.LastEventTimestamp = lttngEvent.Timestamp;
}
EventCount++;
dataProcessor.ProcessDataElement(lttngEvent, lttngContext, cancellationToken);
if (!this.TraceStats.TryGetValue(lttngEvent.Name, out var traceStats))
{
traceStats = new TraceStatsData();
this.TraceStats.Add(lttngEvent.Name, traceStats);
}
traceStats.EventCount++;
traceStats.PayloadBitCount += lttngEvent.PayloadBitCount;
}
{
var sw = new Stopwatch();
sw.Start();
var lttngCustomization = new LTTngPlaybackCustomization(this.ctfInput);
lttngCustomization.RegisterEventCallback(EventCallback);
var playback = new CtfPlayback.CtfPlayback(lttngCustomization, cancellationToken);
playback.Playback(this.ctfInput, new CtfPlaybackOptions {
ReadAhead = true
}, progressReport);
sw.Stop();
this.ProcessingTimeInMilliseconds = (ulong)sw.ElapsedMilliseconds;
}
{
// the playback object had a lot of memory associated with it. due to some garbage collection concerns
// (UI delays) and what I read about on msdn
// (https://docs.microsoft.com/en-us/dotnet/standard/garbage-collection/induced),
// i'm going to try inducing garbage collection here to see if it helps.
//
GC.Collect(2, GCCollectionMode.Default, true);
}
if (this.EventCount > 0)
{
this.dataSourceInfo = new DataSourceInfo(this.FirstEventTimestamp.ToNanoseconds, this.LastEventTimestamp.ToNanoseconds, this.FirstEventWallClock.ToUniversalTime());
}
else
{
throw new Exception("No events - failure processing .ctf");
}
}
public void ProcessSource(ISourceDataProcessor <PerfettoSqlEventKeyed, PerfettoSourceParser, string> dataProcessor,
ILogger logger,
IProgress <int> progress,
CancellationToken cancellationToken)
{
this.Progress = progress;
PerfettoTraceProcessor traceProc = new PerfettoTraceProcessor();
Timestamp firstSnapTime = Timestamp.MaxValue;
Timestamp lastSnapTime = Timestamp.MinValue;
Timestamp firstEventTime = Timestamp.MaxValue;
Timestamp lastEventTime = Timestamp.MinValue;
DateTime?traceStartDateTime = null;
try
{
// Start the progress counter to indicate something is happening because
// OpenTraceProcessor could take a few seconds
IncreaseProgress(1);
// Shell .exe should be located in same directory as this assembly.
var shellDir = Path.GetDirectoryName(Assembly.GetExecutingAssembly().Location);
var shellPath = Path.Combine(shellDir, PerfettoPluginConstants.TraceProcessorShellFileName);
// TraceProcessor seems to incorrectly output via stderr and not stdout (so we won't label stderr as Error)
DataReceivedEventHandler outputDataReceivedHandler = (sender, args) => logger.Verbose($"{PerfettoPluginConstants.TraceProcessorShellFileName}: {args.Data}");
DataReceivedEventHandler errorDataReceivedHandler = (sender, args) => logger.Verbose($"{PerfettoPluginConstants.TraceProcessorShellFileName}: {args.Data}");
// Start the Perfetto trace processor shell with the trace file
traceProc.OpenTraceProcessor(shellPath, filePath, outputDataReceivedHandler, errorDataReceivedHandler);
// Use this callback to receive events parsed and turn them in events with keys
// that get used by data cookers
void EventCallback(PerfettoSqlEvent ev)
{
var eventType = ev.GetType();
// Get all the timings we need from the snapshot events
if (eventType == typeof(PerfettoClockSnapshotEvent))
{
var clockSnapshot = (PerfettoClockSnapshotEvent)ev;
// Each "snapshot" is a collection of timings at a point of time in a trace. Each snapshot has a snapshot_ID
// that is incremented started from 0.
// SnapshotId of 0 indicates the first clock snapshot. This corresponds with the start of the trace
if (clockSnapshot.SnapshotId == 0 && clockSnapshot.ClockName == PerfettoClockSnapshotEvent.REALTIME)
{
// Convert from Unix time in nanoseconds to a DateTime
traceStartDateTime = new DateTime(1970, 1, 1, 0, 0, 0, 0, DateTimeKind.Utc);
traceStartDateTime = traceStartDateTime.Value.AddSeconds(clockSnapshot.ClockValue / 1000000000);
}
else if (clockSnapshot.SnapshotId == 0 && clockSnapshot.ClockName == PerfettoClockSnapshotEvent.BOOTTIME)
{
// Capture the initial BOOTTIME because all the events use BOOTTIME
firstSnapTime = new Timestamp(clockSnapshot.Timestamp);
}
if (clockSnapshot.ClockName == PerfettoClockSnapshotEvent.BOOTTIME)
{
// Events are ordered ASCENDING so keep overwriting and the last event is the actual end time
lastSnapTime = new Timestamp(clockSnapshot.Timestamp);
}
}
else if (eventType == typeof(PerfettoTraceBoundsEvent))
{
// The trace_bounds table stores a single row with the timestamps of the first and last events of the trace
var traceBounds = (PerfettoTraceBoundsEvent)ev;
firstEventTime = new Timestamp(traceBounds.StartTimestamp);
lastEventTime = new Timestamp(traceBounds.EndTimestamp);
}
else if (eventType == typeof(PerfettoMetadataEvent))
{
var metadata = (PerfettoMetadataEvent)ev;
if (!traceStartDateTime.HasValue && metadata.Name == "cr-trace-capture-datetime")
{
DateTime chromiumTraceCaptureDateTime;
if (DateTime.TryParse(metadata.StrValue, out chromiumTraceCaptureDateTime))
{
// Need to explicitly say time is in UTC, otherwise it will be interpreted as local
traceStartDateTime = DateTime.FromFileTimeUtc(chromiumTraceCaptureDateTime.ToFileTimeUtc());
}
}
}
PerfettoSqlEventKeyed newEvent = new PerfettoSqlEventKeyed(ev.GetEventKey(), ev);
// Store the event
var result = dataProcessor.ProcessDataElement(newEvent, this, cancellationToken);
}
// Perform the base queries for all the events we need
List <PerfettoSqlEvent> eventsToQuery = new List <PerfettoSqlEvent>
{
new PerfettoTraceBoundsEvent(),
new PerfettoClockSnapshotEvent(),
new PerfettoMetadataEvent(),
new PerfettoSliceEvent(),
new PerfettoArgEvent(),
new PerfettoThreadTrackEvent(),
new PerfettoThreadEvent(),
new PerfettoProcessRawEvent(),
new PerfettoSchedSliceEvent(),
new PerfettoAndroidLogEvent(),
new PerfettoRawEvent(),
new PerfettoCpuCounterTrackEvent(),
new PerfettoGpuCounterTrackEvent(),
new PerfettoCounterEvent(),
new PerfettoProcessCounterTrackEvent(),
new PerfettoCounterTrackEvent(),
new PerfettoProcessTrackEvent(),
new PerfettoPerfSampleEvent(),
new PerfettoStackProfileCallSiteEvent(),
new PerfettoStackProfileFrameEvent(),
new PerfettoStackProfileMappingEvent(),
new PerfettoStackProfileSymbolEvent(),
new PerfettoActualFrameEvent(),
new PerfettoExpectedFrameEvent()
};
// Increment progress for each table queried.
double queryProgressIncrease = 99.0 / eventsToQuery.Count;
// We need to run the first 3 queries (TraceBounds, ClockSnapshot, Metadata) in order to have all the information we need to
// gather the timing information. We want the timing information before we start to process the rest of the events,
// so that the source cookers can calculate relative timestamps
int cnt = 0;
int minQueriesForTimings = 3; // Need TraceBounds, ClockSnapshot, Metadata to have been processed
// Run all the queries
foreach (var query in eventsToQuery)
{
logger.Verbose($"Querying for {query.GetEventKey()} using SQL query: {query.GetSqlQuery()}");
// Run the query and process the events.
var dateTimeQueryStarted = DateTime.UtcNow;
var rowCount = traceProc.QueryTraceForEvents(query.GetSqlQuery(), query.GetEventKey(), EventCallback);
var dateTimeQueryFinished = DateTime.UtcNow;
logger.Verbose($"Query for {query.GetEventKey()} returning {rowCount} rows completed in {(dateTimeQueryFinished - dateTimeQueryStarted).TotalSeconds}s at {dateTimeQueryFinished.ToString("MM/dd/yyyy HH:mm:ss.fff")} UTC");
IncreaseProgress(queryProgressIncrease);
// If we have all the timing data we need, create the DataSourceInfo
if (++cnt == minQueriesForTimings)
{
if (firstEventTime != Timestamp.MaxValue && lastEventTime != Timestamp.MinValue)
{
if (!traceStartDateTime.HasValue)
{
logger.Warn($"Absolute trace start time can't be determined. Setting trace start time to now");
traceStartDateTime = DateTime.Now;
}
// Get the delta between the first event time and the first snapshot time
var startDelta = firstEventTime - firstSnapTime;
// Get the delta between the first and last event
var eventDelta = new Timestamp(lastEventTime.ToNanoseconds - firstEventTime.ToNanoseconds);
this.FirstEventTimestamp = firstEventTime;
this.LastEventTimestamp = lastEventTime;
// The starting UTC time is from the snapshot. We need to adjust it based on when the first event happened
// The highest precision DateTime has is ticks (a tick is a group of 100 nanoseconds)
DateTime adjustedTraceStartDateTime = traceStartDateTime.Value.AddTicks(startDelta.ToNanoseconds / 100);
logger.Verbose($"Perfetto trace UTC start: {adjustedTraceStartDateTime.ToUniversalTime().ToString()}");
this.dataSourceInfo = new DataSourceInfo(0, eventDelta.ToNanoseconds, adjustedTraceStartDateTime.ToUniversalTime());
}
else
{
throw new Exception("Start and end time were not able to be determined by the Perfetto trace");
}
}
}
// Done with the SQL trace processor
traceProc.CloseTraceConnection();
}
catch (Exception e)
{
logger.Error($"Error while processing Perfetto trace: {e.Message}");
traceProc.CloseTraceConnection();
}
}
/// <inheritdoc/>
public abstract void ProcessSource(
ISourceDataProcessor <T, TContext, TKey> dataProcessor,
ILogger logger,
IProgress <int> progress, CancellationToken cancellationToken);
public override void ProcessSource(
ISourceDataProcessor <CloudInitLogParsedEntry, LogContext, LogParsedDataKey> dataProcessor,
ILogger logger, IProgress <int> progress, CancellationToken cancellationToken)
{
if (FilePaths.Length == 0)
{
return;
}
Timestamp startTime = Timestamp.MaxValue;
Timestamp endTime = Timestamp.MinValue;
DateTime fileStartTime = default(DateTime);
long startNanoSeconds = 0;
foreach (var path in FilePaths)
{
ulong lineNumber = 0;
string line;
var file = new StreamReader(path);
var logEntries = new List <LogEntry>();
while ((line = file.ReadLine()) != null)
{
lineNumber++;
var cloudInitMatch = CloudInitRegex.Match(line);
if (cloudInitMatch.Success)
{
DateTime time;
if (!DateTime.TryParse(cloudInitMatch.Groups[1].Value.Replace(",", "."), out time))
{
throw new InvalidOperationException("Time cannot be parsed to DateTime format");
}
var utcTime = DateTime.FromFileTimeUtc(time.ToFileTimeUtc()); // Need to explicitly say log time is in UTC, otherwise it will be interpreted as local
var timeStamp = Timestamp.FromNanoseconds(utcTime.Ticks * 100);
if (timeStamp < startTime)
{
startTime = timeStamp;
fileStartTime = utcTime;
startNanoSeconds = startTime.ToNanoseconds;
}
if (timeStamp > endTime)
{
endTime = timeStamp;
}
var offsetEventTimestamp = new Timestamp(timeStamp.ToNanoseconds - startNanoSeconds);
LogEntry entry = new LogEntry(path, lineNumber, offsetEventTimestamp, cloudInitMatch.Groups[2].Value,
cloudInitMatch.Groups[3].Value, cloudInitMatch.Groups[4].Value);
dataProcessor.ProcessDataElement(entry, Context, cancellationToken);
}
else
{
Debugger.Break();
}
}
var offsetEndTimestamp = new Timestamp(endTime.ToNanoseconds - startNanoSeconds);
this.dataSourceInfo = new DataSourceInfo(0, offsetEndTimestamp.ToNanoseconds, fileStartTime);
Context.UpdateFileMetadata(path, new FileMetadata(lineNumber));
}
}
public override void ProcessSource(
ISourceDataProcessor <DmesgIsoLogParsedEntry, LogContext, LogParsedDataKey> dataProcessor,
ILogger logger, IProgress <int> progress, CancellationToken cancellationToken)
{
var contentDictionary = new Dictionary <string, IReadOnlyList <LogEntry> >();
string[] lineContent;
string[] firstSlice;
StringBuilder builder = new StringBuilder();
Timestamp oldestTimestamp = new Timestamp(long.MaxValue);
Timestamp newestTImestamp = new Timestamp(long.MinValue);
long startNanoSeconds = 0;
DateTime fileStartTime = default(DateTime);
DateTime parsedTime = default(DateTime);
var dateTimeCultureInfo = new CultureInfo("en-US");
foreach (var path in FilePaths)
{
ulong currentLineNumber = 1;
var file = new System.IO.StreamReader(path);
string line = string.Empty;
var entriesList = new List <LogEntry>();
LogEntry lastEntry = null;
while ((line = file.ReadLine()) != null)
{
//First, we check if the line is a new log entry by trying to parse its timestamp
if (line.Length >= 31 && DateTime.TryParseExact(line.Substring(0, 31), "yyyy-MM-ddTHH:mm:ss,ffffffK", dateTimeCultureInfo, DateTimeStyles.None, out parsedTime))
{
if (lastEntry != null)
{
dataProcessor.ProcessDataElement(lastEntry, Context, cancellationToken);
}
lastEntry = new LogEntry();
lastEntry.filePath = path;
lastEntry.lineNumber = currentLineNumber;
lastEntry.rawLog = line.Substring(32);
lineContent = lastEntry.rawLog.Split(':');
if (lineContent.Length == 1 || lineContent[0].Length > 20)
{
// Character ':' is not present in the beginning of the message, therefore there is no entity nor topic nor metadata
lastEntry.entity = string.Empty;
lastEntry.metadata = string.Empty;
lastEntry.topic = string.Empty;
lastEntry.message = lineContent[0];
}
else if (lineContent.Length == 2)
{
// Character ':' occurs once in the message and in the beginning, therefore there is entity but no topic nor metadata
lastEntry.entity = lineContent[0];
lastEntry.metadata = string.Empty;
lastEntry.topic = string.Empty;
lastEntry.message = lineContent[1];
}
else
{
// Character ':' occurs multiple times in the message, and at least once in the beginning
// We proceed to try to infer entity, metadata and topic
firstSlice = lineContent[0].Split(' ');
var lastSubstring = firstSlice[firstSlice.Length - 1];
int contentIndex = 2;
if (firstSlice.Length > 1 && this.IsNumberFormat(lastSubstring) && this.IsNumberFormat(lineContent[1]))
{
//There is metadata and entity
builder.Clear();
builder.Append(lastSubstring);
builder.Append(':');
builder.Append(lineContent[1]);
while (contentIndex < lineContent.Length && this.IsNumberFormat(lineContent[contentIndex]))
{
builder.Append(':');
builder.Append(lineContent[contentIndex]);
++contentIndex;
}
lastEntry.metadata = builder.ToString();
lastEntry.entity = lineContent[0].Substring(0, lineContent[0].Length - lastSubstring.Length - 1);
if ((contentIndex < lineContent.Length - 1) && !IsPCIinfo(lineContent[contentIndex]))
{
//We check for topic after the metadata
lastEntry.topic = lineContent[contentIndex];
++contentIndex;
}
}
else if (this.IsNumberFormat(lineContent[0]))
{
//There is metadata but no entity
builder.Clear();
builder.Append(lineContent[0]);
contentIndex = 1;
while (contentIndex < lineContent.Length && this.IsNumberFormat(lineContent[contentIndex]))
{
builder.Append(':');
builder.Append(lineContent[contentIndex]);
++contentIndex;
}
lastEntry.metadata = builder.ToString();
lastEntry.entity = string.Empty;
lastEntry.topic = string.Empty;
}
else
{
//There is entity but no metadata
if (lineContent[1].StartsWith(" type="))
{
//We check for topic after the entity
lastEntry.topic = string.Empty;
contentIndex = 1;
}
else
{
lastEntry.topic = lineContent[1];
}
lastEntry.entity = lineContent[0];
lastEntry.metadata = string.Empty;
}
builder.Clear();
//Remainder of the log is the message
if (contentIndex < lineContent.Length)
{
builder.Append(lineContent[contentIndex]);
++contentIndex;
}
while (contentIndex < lineContent.Length)
{
builder.Append(':');
builder.Append(lineContent[contentIndex]);
++contentIndex;
}
lastEntry.message = builder.ToString();
}
parsedTime = DateTime.FromFileTimeUtc(parsedTime.ToFileTimeUtc()); // Need to explicitly say log time is in UTC, otherwise it will be interpreted as local
var timeStamp = Timestamp.FromNanoseconds(parsedTime.Ticks * 100);
if (timeStamp < oldestTimestamp)
{
oldestTimestamp = timeStamp;
fileStartTime = parsedTime;
startNanoSeconds = oldestTimestamp.ToNanoseconds;
}
if (timeStamp > newestTImestamp)
{
newestTImestamp = timeStamp;
}
lastEntry.timestamp = new Timestamp(timeStamp.ToNanoseconds - startNanoSeconds);
entriesList.Add(lastEntry);
}
else if (entriesList.Count > 0)
{
if (lastEntry == null)
{
throw new InvalidOperationException("Can't parse the log.");
}
lastEntry.message = lastEntry.message + "\n" + line;
lastEntry.rawLog = lastEntry.rawLog + "\n" + line;
}
++currentLineNumber;
}
if (lastEntry != null)
{
dataProcessor.ProcessDataElement(lastEntry, Context, cancellationToken);
}
contentDictionary[path] = entriesList.AsReadOnly();
file.Close();
--currentLineNumber;
Context.UpdateFileMetadata(path, new FileMetadata(currentLineNumber));
}
var offsetEndTimestamp = new Timestamp(newestTImestamp.ToNanoseconds - startNanoSeconds);
dataSourceInfo = new DataSourceInfo(0, offsetEndTimestamp.ToNanoseconds, fileStartTime);
}
public override void ProcessSource(
ISourceDataProcessor <AndroidLogcatLogParsedEntry, LogContext, LogParsedDataKey> dataProcessor,
ILogger logger, IProgress <int> progress, CancellationToken cancellationToken)
{
var contentDictionary = new Dictionary <string, IReadOnlyList <LogEntry> >();
Timestamp oldestTimestamp = new Timestamp(long.MaxValue);
Timestamp newestTimestamp = new Timestamp(long.MinValue);
long startNanoSeconds = 0;
DateTime fileStartTime = default;
var dateTimeCultureInfo = new CultureInfo("en-US");
double? utcOffsetInHours = null;
var processingExceptions = new List <Exception>();
foreach (var path in FilePaths)
{
ulong currentLineNumber = 1;
string line = string.Empty;
try
{
var file = new System.IO.StreamReader(path);
var logEntries = new List <LogEntry>();
var durationLogEntries = new List <DurationLogEntry>();
string timeDateFormat = null;
var rootFolder = Path.GetDirectoryName(path);
var utcOffsetFilePath = Path.Combine(rootFolder, "utcoffset.txt");
if (File.Exists(utcOffsetFilePath))
{
var utcOffSetStr = File.ReadAllText(utcOffsetFilePath);
if (double.TryParse(utcOffSetStr, out double utcOffsetTmp))
{
utcOffsetInHours = utcOffsetTmp;
}
}
while ((line = file.ReadLine()) != null)
{
LogEntry logEntry = null;
// Optimization - don't save blank lines
if (line == String.Empty)
{
currentLineNumber++;
continue;
}
var androidLogCatMatch = AndroidLogCatRegex.Match(line);
if (androidLogCatMatch.Success && timeDateFormat == null)
{
const string monthDayFormat = "MM-dd HH:mm:ss.fff";
const string monthDayYearFormat = "MM-dd-yyyy HH:mm:ss.fff";
if (DateTime.TryParseExact(androidLogCatMatch.Groups[1].Value, monthDayFormat, dateTimeCultureInfo, DateTimeStyles.None, out _))
{
timeDateFormat = monthDayFormat;
}
else if (DateTime.TryParseExact(androidLogCatMatch.Groups[1].Value, monthDayYearFormat, dateTimeCultureInfo, DateTimeStyles.None, out _))
{
timeDateFormat = monthDayYearFormat;
}
else
{
throw new Exception($"Invalid date/time format: {androidLogCatMatch.Groups[1].Value}");
}
}
// First, we check if the line is a new log entry if it matched Regex and by trying to parse its timestamp
if (androidLogCatMatch.Success &&
androidLogCatMatch.Groups.Count >= 7 &&
DateTime.TryParseExact(androidLogCatMatch.Groups[1].Value, timeDateFormat, dateTimeCultureInfo, DateTimeStyles.None, out DateTime parsedTime))
{
var timeStamp = Timestamp.FromNanoseconds(parsedTime.Ticks * 100);
if (timeStamp < oldestTimestamp)
{
oldestTimestamp = timeStamp;
fileStartTime = parsedTime;
startNanoSeconds = oldestTimestamp.ToNanoseconds;
}
if (timeStamp > newestTimestamp)
{
newestTimestamp = timeStamp;
}
logEntry = new LogEntry
{
Timestamp = new Timestamp(timeStamp.ToNanoseconds), // We can't subtract startNanoSeconds here because logs are not necessarily time ordered
FilePath = path,
LineNumber = currentLineNumber,
PID = uint.Parse(androidLogCatMatch.Groups[2].Value),
TID = uint.Parse(androidLogCatMatch.Groups[3].Value),
Priority = Utilities.Common.StringIntern(androidLogCatMatch.Groups[4].Value),
Tag = Utilities.Common.StringIntern(androidLogCatMatch.Groups[5].Value.Trim()),
Message = androidLogCatMatch.Groups[6].Value,
};
// Specialized Duration parsing
DurationLogEntry durationLogEntry = null;
if (logEntry.Tag == "init" && logEntry.Message.Contains("took"))
{
var messageSplit = logEntry.Message.Split();
var firstSingleQuoteIdx = logEntry.Message.IndexOf('\'');
var secondSingleQuoteIdx = logEntry.Message.IndexOf('\'', firstSingleQuoteIdx + 1);
var name = logEntry.Message.Substring(firstSingleQuoteIdx + 1, secondSingleQuoteIdx - firstSingleQuoteIdx - 1);
// Command 'write /dev/cpuctl/cpu.rt_period_us 1000000' action=init (/system/etc/init/hw/init.rc:271) took 0ms and failed: ....
if (logEntry.Message.Contains("0ms"))
{
durationLogEntry = LogEntryFromDurationNs(0, logEntry, name);
}
// Service 'boringssl_self_test32_vendor' (pid 18) exited with status 0 waiting took 0.022000 seconds
if (messageSplit[^ 3] == "took" && messageSplit[^ 1] == "seconds")
public override void ProcessSource(
ISourceDataProcessor <WaLinuxAgentLogParsedEntry, LogContext, LogParsedDataKey> dataProcessor,
ILogger logger, IProgress <int> progress, CancellationToken cancellationToken)
{
if (FilePaths.Length == 0)
{
return;
}
Timestamp startTime = Timestamp.MaxValue;
Timestamp endTime = Timestamp.MinValue;
DateTime fileStartTime = default(DateTime);
long startNanoSeconds = 0;
foreach (var path in FilePaths)
{
ulong lineNumber = 0;
string line;
var file = new StreamReader(path);
var logEntries = new List <LogEntry>();
LogEntry lastLogEntry = null;
while ((line = file.ReadLine()) != null)
{
lineNumber++;
var WaLinuxAgentMatch = WaLinuxAgentRegex.Match(line);
if (!WaLinuxAgentMatch.Success)
{
// Continuation of the last line.
if (lastLogEntry == null)
{
throw new InvalidOperationException("Can't find the timestamp of the log.");
}
lastLogEntry.Log += '\n' + line;
continue;
}
// We successfully match the format of the log, which means the last log entry is completed.
if (lastLogEntry != null)
{
dataProcessor.ProcessDataElement(lastLogEntry, Context, cancellationToken);
}
DateTime time;
if (!DateTime.TryParse(WaLinuxAgentMatch.Groups[1].Value, out time))
{
throw new InvalidOperationException("Time cannot be parsed to DateTime format");
}
var utcTime = DateTime.FromFileTimeUtc(time.ToFileTimeUtc()); // Need to explicitly say log time is in UTC, otherwise it will be interpreted as local
var timeStamp = Timestamp.FromNanoseconds(utcTime.Ticks * 100);
if (timeStamp < startTime)
{
startTime = timeStamp;
fileStartTime = utcTime;
startNanoSeconds = startTime.ToNanoseconds;
}
if (timeStamp > endTime)
{
endTime = timeStamp;
}
var offsetEventTimestamp = new Timestamp(timeStamp.ToNanoseconds - startNanoSeconds);
lastLogEntry = new LogEntry(path, lineNumber, offsetEventTimestamp,
WaLinuxAgentMatch.Groups[2].Value, WaLinuxAgentMatch.Groups[3].Value);
}
if (lastLogEntry != null)
{
dataProcessor.ProcessDataElement(lastLogEntry, Context, cancellationToken);
}
Context.UpdateFileMetadata(path, new FileMetadata(lineNumber));
}
var offsetEndTimestamp = new Timestamp(endTime.ToNanoseconds - startNanoSeconds);
this.dataSourceInfo = new DataSourceInfo(0, offsetEndTimestamp.ToNanoseconds, fileStartTime);
}
