private static LogValuesFormatter CreateLogValuesFormatter(string formatString, int expectedNamedParameterCount)
{
var logValuesFormatter = new LogValuesFormatter(formatString);
var actualCount = logValuesFormatter.ValueNames.Count;
if (actualCount != expectedNamedParameterCount)
{
throw new ArgumentException("UnexpectedNumberOfNamedParameters");
}
return(logValuesFormatter);
}
private static LogValuesFormatter CreateLogValuesFormatter(string formatString, int expectedNamedParameterCount)
{
var logValuesFormatter = new LogValuesFormatter(formatString);
var actualCount = logValuesFormatter.ValueNames.Length;
if (actualCount != expectedNamedParameterCount)
{
throw new ArgumentException($"The format string '{formatString}' does not have the expected number of named parameters. Expected {expectedNamedParameterCount} parameter(s) but found {actualCount} parameter(s).");
}
return(logValuesFormatter);
}
private static LogValuesFormatter CreateLogValuesFormatter(string formatString, int expectedNamedParameterCount)
{
var logValuesFormatter = new LogValuesFormatter(formatString);
var actualCount = logValuesFormatter.ValueNames.Count;
if (actualCount != expectedNamedParameterCount)
{
throw new ArgumentException($"Actual parameter count {actualCount} not equal to expected number {expectedNamedParameterCount}.");
}
return(logValuesFormatter);
}
public static FormattedLogValue Format(string msgTemplate, object?[]?values)
{
if (values == null || values.Length == 0)
{
return(new FormattedLogValue(msgTemplate, null));
}
var formatter = new LogValuesFormatter(msgTemplate);
var msg = formatter.FormatWithValues(values);
var dic = formatter.GetValues(values)
.ToDictionary(x => x.Key, x => x.Value);
return(new FormattedLogValue(msg, dic !));
}
public void SimpleStateTest()
{
object[] parameters = { "123" };
var logValuesFormatter = new LogValuesFormatter("MyLog {template}", parameters);
var state = logValuesFormatter.GetState(parameters);
state.Count.Should().Be(2);
state[0].Key.Should().Be("{OriginalFormat}");
state[0].Value.Should().Be("MyLog {template}");
state[1].Key.Should().Be("template");
state[1].Value.Should().Be("123");
}
public CustomLogEvent(string format, params object[] values)
{
if (values != null && values.Length != 0 && format != null)
{
_formatter = _formatters.GetOrAdd(format, f =>
{
return(new LogValuesFormatter(f));
});
}
else
{
_formatter = null;
}
_originalMessage = format ?? defaultValue;
_values = values;
}
public void MultipleParametersTest()
{
object[] parameters = { "123", "456" };
var logValuesFormatter = new LogValuesFormatter("MyLog {template1}, {template2}", parameters);
var state = logValuesFormatter.GetState(parameters);
state.Count.Should().Be(3);
state[0].Key.Should().Be("{OriginalFormat}");
state[0].Value.Should().Be("MyLog {template1}, {template2}");
state[1].Key.Should().Be("template1");
state[1].Value.Should().Be("123");
state[2].Key.Should().Be("template2");
state[2].Value.Should().Be("456");
}
private void AnalyzeFormatArgument(OperationAnalysisContext context, IOperation formatExpression, int paramsCount, bool argsIsArray, bool usingLoggerExtensionsTypes, IMethodSymbol methodSymbol)
{
var text = TryGetFormatText(formatExpression);
if (text == null)
{
if (usingLoggerExtensionsTypes)
{
context.ReportDiagnostic(formatExpression.CreateDiagnostic(CA2254Rule, methodSymbol.ToDisplayString(GetLanguageSpecificFormat(formatExpression))));
}
return;
}
LogValuesFormatter formatter;
try
{
formatter = new LogValuesFormatter(text);
}
#pragma warning disable CA1031 // Do not catch general exception types
catch (Exception)
#pragma warning restore CA1031 // Do not catch general exception types
{
return;
}
foreach (var valueName in formatter.ValueNames)
{
if (int.TryParse(valueName, out _))
{
context.ReportDiagnostic(formatExpression.CreateDiagnostic(CA2253Rule));
}
else if (!string.IsNullOrEmpty(valueName) && char.IsLower(valueName[0]))
{
context.ReportDiagnostic(formatExpression.CreateDiagnostic(CA1727Rule));
}
}
var argsPassedDirectly = argsIsArray && paramsCount == 1;
if (!argsPassedDirectly && paramsCount != formatter.ValueNames.Count)
{
context.ReportDiagnostic(formatExpression.CreateDiagnostic(CA2017Rule));
}
}
private void AnalyzeFormatArgument(SyntaxNodeAnalysisContext syntaxContext, ExpressionSyntax formatExpression, int paramsCount, bool argsIsArray)
{
var text = TryGetFormatText(formatExpression, syntaxContext.SemanticModel);
if (text == null)
{
syntaxContext.ReportDiagnostic(Diagnostic.Create(Descriptors.MEL0002ConcatenationInFormatString, formatExpression.GetLocation()));
return;
}
LogValuesFormatter formatter;
try
{
formatter = new LogValuesFormatter(text);
}
catch (Exception)
{
return;
}
foreach (var valueName in formatter.ValueNames)
{
if (int.TryParse(valueName, out _))
{
syntaxContext.ReportDiagnostic(Diagnostic.Create(Descriptors.MEL0001NumericsInFormatString, formatExpression.GetLocation()));
}
else if (char.IsLower(valueName[0]))
{
syntaxContext.ReportDiagnostic(Diagnostic.Create(Descriptors.MEL0005UsePascalCasedLogMessageTokens, formatExpression.GetLocation()));
}
}
var argsPassedDirectly = argsIsArray && paramsCount == 1;
if (!argsPassedDirectly && paramsCount != formatter.ValueNames.Count)
{
syntaxContext.ReportDiagnostic(Diagnostic.Create(Descriptors.MEL0003FormatParameterCountMismatch, formatExpression.GetLocation()));
}
}
public void ProcessEvents(string applicationName,
string serviceName,
int processId,
string replicaName,
ReplicaStatus replica,
CancellationToken cancellationToken)
{
var hasEventPipe = false;
for (int i = 0; i < 10; ++i)
{
if (DiagnosticsClient.GetPublishedProcesses().Contains(processId))
{
hasEventPipe = true;
break;
}
if (cancellationToken.IsCancellationRequested)
{
return;
}
Thread.Sleep(500);
}
if (!hasEventPipe)
{
_logger.LogInformation("Process id {PID}, does not support event pipe", processId);
return;
}
_logger.LogInformation("Listening for event pipe events for {ServiceName} on process id {PID}", replicaName, processId);
// Create the logger factory for this replica
using var loggerFactory = LoggerFactory.Create(builder => ConfigureLogging(serviceName, replicaName, builder));
var processor = new SimpleSpanProcessor(CreateSpanExporter(serviceName, replicaName));
var providers = new List <EventPipeProvider>()
{
// Runtime Metrics
new EventPipeProvider(
SystemRuntimeEventSourceName,
EventLevel.Informational,
(long)ClrTraceEventParser.Keywords.None,
new Dictionary <string, string>()
{
{ "EventCounterIntervalSec", "1" }
}
),
new EventPipeProvider(
MicrosoftAspNetCoreHostingEventSourceName,
EventLevel.Informational,
(long)ClrTraceEventParser.Keywords.None,
new Dictionary <string, string>()
{
{ "EventCounterIntervalSec", "1" }
}
),
new EventPipeProvider(
GrpcAspNetCoreServer,
EventLevel.Informational,
(long)ClrTraceEventParser.Keywords.None,
new Dictionary <string, string>()
{
{ "EventCounterIntervalSec", "1" }
}
),
// Application Metrics
new EventPipeProvider(
applicationName,
EventLevel.Informational,
(long)ClrTraceEventParser.Keywords.None,
new Dictionary <string, string>()
{
{ "EventCounterIntervalSec", "1" }
}
),
// Logging
new EventPipeProvider(
MicrosoftExtensionsLoggingProviderName,
EventLevel.LogAlways,
(long)(LoggingEventSource.Keywords.JsonMessage | LoggingEventSource.Keywords.FormattedMessage)
),
// Distributed Tracing
// Activity correlation
new EventPipeProvider(TplEventSource,
keywords: 0x80,
eventLevel: EventLevel.LogAlways),
// Diagnostic source events
new EventPipeProvider(DiagnosticSourceEventSource,
keywords: 0x1 | 0x2,
eventLevel: EventLevel.Verbose,
arguments: new Dictionary <string, string>
{
{ "FilterAndPayloadSpecs", DiagnosticFilterString }
})
};
while (!cancellationToken.IsCancellationRequested)
{
EventPipeSession session = null;
var client = new DiagnosticsClient(processId);
try
{
session = client.StartEventPipeSession(providers);
}
catch (EndOfStreamException)
{
break;
}
catch (Exception ex)
{
if (!cancellationToken.IsCancellationRequested)
{
_logger.LogDebug(0, ex, "Failed to start the event pipe session");
}
// We can't even start the session, wait until the process boots up again to start another metrics thread
break;
}
void StopSession()
{
try
{
session.Stop();
}
catch (EndOfStreamException)
{
// If the app we're monitoring exits abruptly, this may throw in which case we just swallow the exception and exit gracefully.
}
// We may time out if the process ended before we sent StopTracing command. We can just exit in that case.
catch (TimeoutException)
{
}
// On Unix platforms, we may actually get a PNSE since the pipe is gone with the process, and Runtime Client Library
// does not know how to distinguish a situation where there is no pipe to begin with, or where the process has exited
// before dotnet-counters and got rid of a pipe that once existed.
// Since we are catching this in StopMonitor() we know that the pipe once existed (otherwise the exception would've
// been thrown in StartMonitor directly)
catch (PlatformNotSupportedException)
{
}
}
using var _ = cancellationToken.Register(() => StopSession());
try
{
var source = new EventPipeEventSource(session.EventStream);
var activities = new Dictionary <string, ActivityItem>();
source.Dynamic.All += traceEvent =>
{
try
{
// Uncomment to debug the diagnostics source event source
//if (traceEvent.EventName == "Message")
//{
// _logger.LogTrace("[" + replicaName + "]:" + traceEvent.PayloadValue(0));
//}
//// Distributed tracing
// else
if (traceEvent.EventName == "Activity1Start/Start")
{
var listenerEventName = (string)traceEvent.PayloadByName("EventName");
if (traceEvent.PayloadByName("Arguments") is IDictionary <string, object>[] arguments)
{
string activityId = null;
string parentId = null;
string operationName = null;
string httpMethod = null;
string path = null;
string spanId = null;
string parentSpanId = null;
string traceId = null;
DateTime startTime = default;
ActivityIdFormat idFormat = default;
foreach (var arg in arguments)
{
var key = (string)arg["Key"];
var value = (string)arg["Value"];
if (key == "ActivityId")
{
activityId = value;
}
else if (key == "ActivityParentId")
{
parentId = value;
}
else if (key == "ActivityOperationName")
{
operationName = value;
}
else if (key == "ActivitySpanId")
{
spanId = value;
}
else if (key == "ActivityTraceId")
{
traceId = value;
}
else if (key == "ActivityParentSpanId")
{
parentSpanId = value;
}
else if (key == "Method")
{
httpMethod = value;
}
else if (key == "Path")
{
path = value;
}
else if (key == "ActivityStartTime")
{
startTime = new DateTime(long.Parse(value), DateTimeKind.Utc);
}
else if (key == "ActivityIdFormat")
{
idFormat = Enum.Parse <ActivityIdFormat>(value);
}
}
if (string.IsNullOrEmpty(activityId))
{
// Not a 3.1 application (we can detect this earlier)
return;
}
if (idFormat == ActivityIdFormat.Hierarchical)
{
// We need W3C to make it work
return;
}
// This is what open telemetry currently does
// https://github.com/open-telemetry/opentelemetry-dotnet/blob/4ba732af062ddc2759c02aebbc91335aaa3f7173/src/OpenTelemetry.Collector.AspNetCore/Implementation/HttpInListener.cs#L65-L92
var item = new ActivityItem()
{
Name = path,
SpanId = ActivitySpanId.CreateFromString(spanId),
TraceId = ActivityTraceId.CreateFromString(traceId),
ParentSpanId = parentSpanId == "0000000000000000" ? default : ActivitySpanId.CreateFromString(parentSpanId),
StartTime = startTime,
};
item.Attributes[SpanAttributeConstants.HttpMethodKey] = httpMethod;
item.Attributes[SpanAttributeConstants.HttpPathKey] = path;
activities[activityId] = item;
}
}
else if (traceEvent.EventName == "Activity1Stop/Stop")
{
var listenerEventName = (string)traceEvent.PayloadByName("EventName");
if (traceEvent.PayloadByName("Arguments") is IDictionary <string, object>[] arguments)
{
string activityId = null;
TimeSpan duration = default;
int statusCode = 0;
foreach (var arg in arguments)
{
var key = (string)arg["Key"];
var value = (string)arg["Value"];
if (key == "ActivityId")
{
activityId = value;
}
else if (key == "StatusCode")
{
statusCode = int.Parse(value);
}
else if (key == "ActivityDuration")
{
duration = new TimeSpan(long.Parse(value));
}
}
if (string.IsNullOrEmpty(activityId))
{
// Not a 3.1 application (we can detect this earlier)
return;
}
if (activities.TryGetValue(activityId, out var item))
{
item.Attributes[SpanAttributeConstants.HttpStatusCodeKey] = statusCode;
item.EndTime = item.StartTime + duration;
var spanData = new SpanData(item.Name,
new SpanContext(item.TraceId, item.SpanId, ActivityTraceFlags.Recorded),
item.ParentSpanId,
SpanKind.Server,
item.StartTime,
item.Attributes,
Enumerable.Empty <Event>(),
Enumerable.Empty <Link>(),
null,
Status.Ok,
item.EndTime);
processor.OnEnd(spanData);
activities.Remove(activityId);
}
}
}
else if (traceEvent.EventName == "Activity2Start/Start")
{
var listenerEventName = (string)traceEvent.PayloadByName("EventName");
_logger.LogDebug("[" + replicaName + "]: " + listenerEventName + " fired");
}
else if (traceEvent.EventName == "Activity2Stop/Stop")
{
var listenerEventName = (string)traceEvent.PayloadByName("EventName");
_logger.LogDebug("[" + replicaName + "]: " + listenerEventName + " fired");
}
// Metrics
else if (traceEvent.EventName.Equals("EventCounters"))
{
var payloadVal = (IDictionary <string, object>)traceEvent.PayloadValue(0);
var eventPayload = (IDictionary <string, object>)payloadVal["Payload"];
ICounterPayload payload = CounterPayload.FromPayload(eventPayload);
replica.Metrics[traceEvent.ProviderName + "/" + payload.Name] = payload.Value;
}
}
catch (Exception ex)
{
_logger.LogError(ex, "Error processing counter for {ProviderName}:{EventName}", traceEvent.ProviderName, traceEvent.EventName);
}
};
// Logging
string lastFormattedMessage = "";
var logActivities = new Dictionary <Guid, LogActivityItem>();
var stack = new Stack <Guid>();
source.Dynamic.AddCallbackForProviderEvent(MicrosoftExtensionsLoggingProviderName, "ActivityJsonStart/Start", (traceEvent) =>
{
var factoryId = (int)traceEvent.PayloadByName("FactoryID");
var categoryName = (string)traceEvent.PayloadByName("LoggerName");
var argsJson = (string)traceEvent.PayloadByName("ArgumentsJson");
// TODO: Store this information by logger factory id
var item = new LogActivityItem
{
ActivityID = traceEvent.ActivityID,
ScopedObject = new LogObject(JsonDocument.Parse(argsJson).RootElement),
};
if (stack.TryPeek(out var parentId) && logActivities.TryGetValue(parentId, out var parentItem))
{
item.Parent = parentItem;
}
stack.Push(traceEvent.ActivityID);
logActivities[traceEvent.ActivityID] = item;
});
source.Dynamic.AddCallbackForProviderEvent(MicrosoftExtensionsLoggingProviderName, "ActivityJsonStop/Stop", (traceEvent) =>
{
var factoryId = (int)traceEvent.PayloadByName("FactoryID");
var categoryName = (string)traceEvent.PayloadByName("LoggerName");
stack.Pop();
logActivities.Remove(traceEvent.ActivityID);
});
source.Dynamic.AddCallbackForProviderEvent(MicrosoftExtensionsLoggingProviderName, "MessageJson", (traceEvent) =>
{
// Level, FactoryID, LoggerName, EventID, EventName, ExceptionJson, ArgumentsJson
var logLevel = (LogLevel)traceEvent.PayloadByName("Level");
var factoryId = (int)traceEvent.PayloadByName("FactoryID");
var categoryName = (string)traceEvent.PayloadByName("LoggerName");
var eventId = (int)traceEvent.PayloadByName("EventId");
var eventName = (string)traceEvent.PayloadByName("EventName");
var exceptionJson = (string)traceEvent.PayloadByName("ExceptionJson");
var argsJson = (string)traceEvent.PayloadByName("ArgumentsJson");
// There's a bug that causes some of the columns to get mixed up
if (eventName.StartsWith("{"))
{
argsJson = exceptionJson;
exceptionJson = eventName;
eventName = null;
}
if (string.IsNullOrEmpty(argsJson))
{
return;
}
Exception exception = null;
var logger = loggerFactory.CreateLogger(categoryName);
var scopes = new List <IDisposable>();
if (logActivities.TryGetValue(traceEvent.ActivityID, out var logActivityItem))
{
// REVIEW: Does order matter here? We're combining everything anyways.
while (logActivityItem != null)
{
scopes.Add(logger.BeginScope(logActivityItem.ScopedObject));
logActivityItem = logActivityItem.Parent;
}
}
try
{
if (exceptionJson != "{}")
{
var exceptionMessage = JsonSerializer.Deserialize <JsonElement>(exceptionJson);
exception = new LoggerException(exceptionMessage);
}
var message = JsonSerializer.Deserialize <JsonElement>(argsJson);
if (message.TryGetProperty("{OriginalFormat}", out var formatElement))
{
var formatString = formatElement.GetString();
var formatter = new LogValuesFormatter(formatString);
object[] args = new object[formatter.ValueNames.Count];
for (int i = 0; i < args.Length; i++)
{
args[i] = message.GetProperty(formatter.ValueNames[i]).GetString();
}
logger.Log(logLevel, new EventId(eventId, eventName), exception, formatString, args);
}
else
{
var obj = new LogObject(message, lastFormattedMessage);
logger.Log(logLevel, new EventId(eventId, eventName), obj, exception, LogObject.Callback);
}
}
catch (Exception ex)
{
_logger.LogDebug(ex, "Error processing log entry for {ServiceName}", replicaName);
}
finally
{
scopes.ForEach(d => d.Dispose());
}
});
source.Dynamic.AddCallbackForProviderEvent(MicrosoftExtensionsLoggingProviderName, "FormattedMessage", (traceEvent) =>
{
// Level, FactoryID, LoggerName, EventID, EventName, FormattedMessage
var logLevel = (LogLevel)traceEvent.PayloadByName("Level");
var factoryId = (int)traceEvent.PayloadByName("FactoryID");
var categoryName = (string)traceEvent.PayloadByName("LoggerName");
var eventId = (int)traceEvent.PayloadByName("EventId");
var eventName = (string)traceEvent.PayloadByName("EventName");
var formattedMessage = (string)traceEvent.PayloadByName("FormattedMessage");
if (string.IsNullOrEmpty(formattedMessage))
{
formattedMessage = eventName;
eventName = "";
}
lastFormattedMessage = formattedMessage;
});
source.Process();
}
public LogValues(LogValuesFormatter formatter)
{
_formatter = formatter;
}
