private static void ParseExtensionsLoggingEvent(TraceEvent data, int minRequestDurationMilliseconds, string eventArgs, Dictionary <string, AspNetCoreRequest> aspnetCoreRequests, Dictionary <AspNetCoreRequest, List <AspNetCoreTraceEvent> > failedRequests, Dictionary <AspNetCoreRequestId, List <AspNetCoreTraceEvent> > requestsFullTrace, AspNetCoreRequestEventType eventType) { var loggerName = data.PayloadByName("LoggerName").ToString(); string rawMessage = ""; if (!string.IsNullOrWhiteSpace(eventArgs)) { if (data.PayloadByName(eventArgs) != null) { rawMessage = data.PayloadByName(eventArgs).ToString(); if (rawMessage.ToLower().Contains("StructValue[]".ToLower())) { rawMessage = ""; try { var args = (IDictionary <string, object>[])data.PayloadByName(eventArgs); foreach (IDictionary <string, object> item in args.ToList()) { var dict = item.ToDictionary(x => x.Key, x => x.Value); rawMessage += $" {dict["Key"].ToString()}->[{dict["Value"].ToString()}]"; } } catch (Exception) { } } if (rawMessage.Length > 250) { rawMessage = rawMessage.Substring(0, 250) + "...[REMOVED_AS_MESSAGE_TOO_LARGE]"; } rawMessage = eventType.ToString() + ":" + rawMessage; } } else { rawMessage = eventType.ToString(); } var shortActivityId = StartStopActivityComputer.ActivityPathString(data.ActivityID); foreach (var key in requestsFullTrace.Keys.ToArray()) { if (shortActivityId.StartsWith(key.ShortActivityId)) { AddRawAspNetTraceToDictionary(key, shortActivityId, loggerName, rawMessage, data, requestsFullTrace); break; } } if (CheckAspNetLogger(loggerName) && eventType == AspNetCoreRequestEventType.Start) { if (data.ActivityID != Guid.Empty) { if (!aspnetCoreRequests.ContainsKey(shortActivityId)) { var coreRequest = new AspNetCoreRequest { ShortActivityId = shortActivityId, ProcessId = data.ProcessID, ActivityId = data.ActivityID, RelatedActivityId = StartStopActivityComputer.ActivityPathString(data.RelatedActivityID) }; var arguments = (IDictionary <string, object>[])data.PayloadByName("Arguments"); GetAspnetCoreRequestDetailsFromArgs(arguments.ToList(), out coreRequest.Path, out coreRequest.RequestId); coreRequest.StartTimeRelativeMSec = data.TimeStampRelativeMSec; if (!string.IsNullOrWhiteSpace(coreRequest.Path) && !string.IsNullOrWhiteSpace(coreRequest.RequestId)) { aspnetCoreRequests.Add(shortActivityId, coreRequest); } } AspNetCoreRequestId requestId = new AspNetCoreRequestId { ShortActivityId = shortActivityId, ActivityId = data.ActivityID }; AddRawAspNetTraceToDictionary(requestId, shortActivityId, loggerName, rawMessage, data, requestsFullTrace); } } if (CheckAspNetLogger(loggerName) && eventType == AspNetCoreRequestEventType.Stop) { if (data.ActivityID != Guid.Empty) { if (aspnetCoreRequests.TryGetValue(shortActivityId, out AspNetCoreRequest coreRequest)) { // // We are setting EndTime in 'Request finished' as well. Not // sure which is the correct one right now, so doing it both. // coreRequest.EndTimeRelativeMSec = data.TimeStampRelativeMSec; if ((coreRequest.EndTimeRelativeMSec - coreRequest.StartTimeRelativeMSec) < minRequestDurationMilliseconds) { var keyToRemove = requestsFullTrace.Keys.Where(x => x.ShortActivityId == coreRequest.ShortActivityId).FirstOrDefault(); if (keyToRemove != null) { requestsFullTrace.Remove(keyToRemove); } } } } } if (CheckAspNetLogger(loggerName) && eventType == AspNetCoreRequestEventType.Message) { string formattedMessage = string.Empty; if (data.PayloadByName("FormattedMessage") != null) { formattedMessage = data.PayloadByName("FormattedMessage").ToString(); } else if (data.PayloadByName("EventName") != null) { formattedMessage = data.PayloadByName("EventName").ToString(); } if (data.ActivityID != Guid.Empty) { if (formattedMessage.StartsWith("Request finished", StringComparison.OrdinalIgnoreCase)) { if (aspnetCoreRequests.TryGetValue(shortActivityId, out AspNetCoreRequest coreRequest)) { int statusCode = GetStatusCodeFromRequestFinishedMessage(formattedMessage); if (statusCode > 0) { coreRequest.StatusCode = statusCode; coreRequest.EndTimeRelativeMSec = data.TimeStampRelativeMSec; } if (statusCode >= 500) { AspNetCoreRequestId requestId = new AspNetCoreRequestId { ShortActivityId = shortActivityId, ActivityId = data.ActivityID }; var requestFullTraceFailedRequest = requestsFullTrace.Where(x => x.Key.ShortActivityId == coreRequest.ShortActivityId).FirstOrDefault(); if (requestFullTraceFailedRequest.Value != null && failedRequests.Count() < MAX_FAILED_REQUESTS_TO_TRACE) { failedRequests.Add(coreRequest.Clone(), requestFullTraceFailedRequest.Value.ToArray().ToList()); } } } } } } }
internal ETWEventRecord(ETWEventSource source, TraceEvent data, Dictionary <string, int> columnOrder, int nonRestFields, double durationMSec) : base(nonRestFields) { m_source = source; m_name = data.ProviderName + "/" + data.EventName; m_processName = data.ProcessName; if (!m_processName.StartsWith("(")) { m_processName += " (" + data.ProcessID + ")"; } m_timeStampRelativeMSec = data.TimeStampRelativeMSec; m_idx = data.EventIndex; // Compute the data column var restString = new StringBuilder(); // Deal with the special HasStack, ThreadID and ActivityID, DataLength fields; var hasStack = data.CallStackIndex() != CallStackIndex.Invalid; if (hasStack) { AddField("HasStack", hasStack.ToString(), columnOrder, restString); } var asCSwitch = data as CSwitchTraceData; if (asCSwitch != null) { AddField("HasBlockingStack", (asCSwitch.BlockingStack() != CallStackIndex.Invalid).ToString(), columnOrder, restString); } AddField("ThreadID", data.ThreadID.ToString("n0"), columnOrder, restString); AddField("ProcessorNumber", data.ProcessorNumber.ToString(), columnOrder, restString); if (0 < durationMSec) { AddField("DURATION_MSEC", durationMSec.ToString("n3"), columnOrder, restString); } var payloadNames = data.PayloadNames; if (payloadNames.Length == 0 && data.EventDataLength != 0) { // WPP events look classic and use the EventID as their discriminator if (data.IsClassicProvider && data.ID != 0) { AddField("EventID", ((int)data.ID).ToString(), columnOrder, restString); } AddField("DataLength", data.EventDataLength.ToString(), columnOrder, restString); } try { for (int i = 0; i < payloadNames.Length; i++) { AddField(payloadNames[i], data.PayloadString(i), columnOrder, restString); } } catch (Exception e) { AddField("ErrorParsingFields", e.Message, columnOrder, restString); } var message = data.FormattedMessage; if (message != null) { AddField("FormattedMessage", message, columnOrder, restString); } if (source.m_needsComputers) { TraceThread thread = data.Thread(); if (thread != null) { TraceActivity activity = source.m_activityComputer.GetCurrentActivity(thread); if (activity != null) { string id = activity.ID; if (Math.Abs(activity.StartTimeRelativeMSec - m_timeStampRelativeMSec) < .0005) { id = "^" + id; // Indicates it is at the start of the task. } AddField("ActivityInfo", id, columnOrder, restString); } var startStopActivity = source.m_startStopActivityComputer.GetCurrentStartStopActivity(thread, data); if (startStopActivity != null) { string name = startStopActivity.Name; string parentName = "$"; if (startStopActivity.Creator != null) { parentName = startStopActivity.Creator.Name; } AddField("StartStopActivity", name + "/P=" + parentName, columnOrder, restString); } } } // We pass 0 as the process ID for creating the activityID because we want uniform syntax. if (data.ActivityID != Guid.Empty) { AddField("ActivityID", StartStopActivityComputer.ActivityPathString(data.ActivityID), columnOrder, restString); } Guid relatedActivityID = data.RelatedActivityID; if (relatedActivityID != Guid.Empty) { AddField("RelatedActivityID", StartStopActivityComputer.ActivityPathString(data.RelatedActivityID), columnOrder, restString); } if (data.ContainerID != null) { AddField("ContainerID", data.ContainerID, columnOrder, restString); } m_asText = restString.ToString(); }