public object BeginEvent(string eventName, string functionName = null)
{
string key = MetricsEventManager.GetAggregateKey(eventName, functionName);
EventsBegan.Add(key);
return(key);
}
public async Task Scenario_Logging()
{
string testData = Guid.NewGuid().ToString();
JObject input = new JObject
{
{ "scenario", "logging" },
{ "input", testData },
};
Fixture.Host.ClearLogMessages();
Fixture.MetricsLogger.ClearCollections();
await Fixture.Host.BeginFunctionAsync("Scenarios", input);
string userCategory = LogCategories.CreateFunctionUserCategory("Scenarios");
IList <string> logs = null;
await TestHelpers.Await(() =>
{
logs = Fixture.Host.GetLogMessages(userCategory).Select(p => p.FormattedMessage).ToList();
return(logs.Count == 10);
}, userMessageCallback : Fixture.Host.GetLog);
// verify use of context.log to log complex objects
LogMessage scriptTrace = Fixture.Host.GetLogMessages(userCategory).Single(p => p.FormattedMessage != null && p.FormattedMessage.Contains(testData));
Assert.Equal(LogLevel.Information, scriptTrace.Level);
JObject logEntry = JObject.Parse(scriptTrace.FormattedMessage);
Assert.Equal("This is a test", logEntry["message"]);
Assert.Equal(testData, logEntry["input"]);
// verify log levels in traces
LogMessage[] traces = Fixture.Host.GetLogMessages(userCategory).Where(t => t.FormattedMessage != null && t.FormattedMessage.Contains("loglevel")).ToArray();
Assert.Equal(LogLevel.Information, traces[0].Level);
Assert.Equal("loglevel default", traces[0].FormattedMessage);
Assert.Equal(LogLevel.Information, traces[1].Level);
Assert.Equal("loglevel info", traces[1].FormattedMessage);
Assert.Equal(LogLevel.Trace, traces[2].Level);
Assert.Equal("loglevel verbose", traces[2].FormattedMessage);
Assert.Equal(LogLevel.Warning, traces[3].Level);
Assert.Equal("loglevel warn", traces[3].FormattedMessage);
Assert.Equal(LogLevel.Error, traces[4].Level);
Assert.Equal("loglevel error", traces[4].FormattedMessage);
// verify most of the logs look correct
Assert.EndsWith("Mathew Charles", logs[1]);
Assert.EndsWith("null", logs[2]);
Assert.EndsWith("1234", logs[3]);
Assert.EndsWith("true", logs[4]);
Assert.EndsWith("loglevel default", logs[5]);
Assert.EndsWith("loglevel info", logs[6]);
// We only expect 9 user log metrics to be counted, since
// verbose logs are filtered by default (the TestLogger explicitly
// allows all levels for testing purposes)
var key = MetricsEventManager.GetAggregateKey(MetricEventNames.FunctionUserLog, "Scenarios");
Assert.Equal(9, Fixture.MetricsLogger.LoggedEvents.Where(p => p == key).Count());
}
public async Task Validate_Manual()
{
string functionName = "Scenarios";
int invocationCount = 5;
List <string> functionTraces = new List <string>();
// We want to invoke this multiple times specifically to make sure Node invocationIds
// are correctly being set. Invoke them all first, then come back and validate all.
for (int i = 0; i < invocationCount; i++)
{
string functionTrace = $"Function trace: {Guid.NewGuid().ToString()}";
functionTraces.Add(functionTrace);
JObject input = new JObject()
{
{ "scenario", "appInsights" },
{ "container", "not-used" },
{ "value", functionTrace }
};
await _fixture.TestHost.BeginFunctionAsync(functionName, input);
}
// Now validate each function invocation.
foreach (string functionTrace in functionTraces)
{
await WaitForFunctionTrace(functionName, functionTrace);
string invocationId = await ValidateEndToEndTestAsync(functionName, functionTrace, true);
// TODO: Remove this check when metrics are supported in Node:
// https://github.com/Azure/azure-functions-host/issues/2189
if (this is ApplicationInsightsCSharpEndToEndTests)
{
// Do some additional metric validation
MetricTelemetry metric = _fixture.Channel.Telemetries
.OfType <MetricTelemetry>()
.Where(t => GetInvocationId(t) == invocationId)
.Single();
ValidateMetric(metric, invocationId, functionName);
}
}
// App Insights logs first, so wait until this metric appears
string metricKey = MetricsEventManager.GetAggregateKey(MetricEventNames.FunctionUserLog, functionName);
IEnumerable <string> GetMetrics() => _fixture.MetricsLogger.LoggedEvents.Where(p => p == metricKey);
// TODO: Remove this check when metrics are supported in Node:
// https://github.com/Azure/azure-functions-host/issues/2189
int expectedCount = this is ApplicationInsightsCSharpEndToEndTests ? 10 : 5;
await TestHelpers.Await(() => GetMetrics().Count() == expectedCount,
timeout : 15000, userMessageCallback : () => string.Join(Environment.NewLine, GetMetrics().Select(p => p.ToString())));
}
public void Log_WritesMetric_ForUserLogs_WithoutFunctionName()
{
var metrics = new TestMetricsLogger();
var logger = new UserLogMetricsLogger(_functionCategory, metrics, _scopeProvider);
// If for some reason the scope doesn't exist, we still want this to suceed, but
// without a function name.
logger.LogInformation("Message");
var expectedEvent = MetricsEventManager.GetAggregateKey(MetricEventNames.FunctionUserLog);
string eventName = metrics.LoggedEvents.Single();
Assert.Equal(expectedEvent, eventName);
}
public async Task FunctionLogging_Succeeds()
{
Fixture.Host.ClearLogMessages();
string functionName = "Scenarios";
string guid1 = Guid.NewGuid().ToString();
string guid2 = Guid.NewGuid().ToString();
var inputObject = new JObject
{
{ "Scenario", "logging" },
{ "Container", "scenarios-output" },
{ "Value", $"{guid1};{guid2}" }
};
await Fixture.Host.BeginFunctionAsync(functionName, inputObject);
IList <string> logs = null;
await TestHelpers.Await(() =>
{
logs = Fixture.Host.GetScriptHostLogMessages().Select(p => p.FormattedMessage).Where(p => p != null).ToArray();
return(logs.Any(p => p.Contains(guid2)));
});
logs.Single(p => p.EndsWith($"From TraceWriter: {guid1}"));
logs.Single(p => p.EndsWith($"From ILogger: {guid2}"));
// Make sure we get a metric logged from both ILogger and TraceWriter
var key = MetricsEventManager.GetAggregateKey(MetricEventNames.FunctionUserLog, "Scenarios");
Assert.Equal(2, Fixture.MetricsLogger.LoggedEvents.Where(p => p == key).Count());
// Make sure we've gotten a log from the aggregator
IEnumerable <LogMessage> getAggregatorLogs() => Fixture.Host.GetScriptHostLogMessages().Where(p => p.Category == LogCategories.Aggregator);
await TestHelpers.Await(() => getAggregatorLogs().Any());
var aggregatorLogs = getAggregatorLogs();
Assert.Equal(1, aggregatorLogs.Count());
// Make sure that no user logs made it to the EventGenerator (which the SystemLogger writes to)
IEnumerable <FunctionTraceEvent> allLogs = Fixture.EventGenerator.GetFunctionTraceEvents();
Assert.False(allLogs.Any(l => l.Summary.Contains("From ")));
Assert.False(allLogs.Any(l => l.Source.EndsWith(".User")));
Assert.False(allLogs.Any(l => l.Source == OutOfProcConstants.FunctionConsoleLogCategoryName));
Assert.NotEmpty(allLogs);
}
public void Log_WritesMetric_ForUserLogs()
{
var metrics = new TestMetricsLogger();
var logger = new UserLogMetricsLogger(_functionCategory, metrics, _scopeProvider);
// function executions will include this scope
using (CreateFunctionScope(logger))
{
logger.LogInformation("Message");
}
var expectedEvent = MetricsEventManager.GetAggregateKey(MetricEventNames.FunctionUserLog, _functionName);
string eventName = metrics.LoggedEvents.Single();
Assert.Equal(expectedEvent, eventName);
}
public void EndEvent_Function_AggregatesIntoExistingEvent()
{
SystemMetricEvent metricEvent;
for (int i = 0; i < 10; i++)
{
metricEvent = (SystemMetricEvent)_metricsLogger.BeginEvent("Event1", "Function1");
Thread.Sleep(50);
_metricsLogger.EndEvent(metricEvent);
}
for (int i = 0; i < 5; i++)
{
metricEvent = (SystemMetricEvent)_metricsLogger.BeginEvent("Event1", "Function2");
Thread.Sleep(50);
_metricsLogger.EndEvent(metricEvent);
}
for (int i = 0; i < 15; i++)
{
metricEvent = (SystemMetricEvent)_metricsLogger.BeginEvent("Event2");
Thread.Sleep(50);
_metricsLogger.EndEvent(metricEvent);
}
Assert.Equal(3, _metricsEventManager.QueuedEvents.Count);
string key = MetricsEventManager.GetAggregateKey("Event1", "Function1");
metricEvent = _metricsEventManager.QueuedEvents[key];
Assert.Equal(10, metricEvent.Count);
Assert.Equal("event1", metricEvent.EventName);
Assert.Equal("Function1", metricEvent.FunctionName);
key = MetricsEventManager.GetAggregateKey("Event1", "Function2");
metricEvent = _metricsEventManager.QueuedEvents[key];
Assert.Equal(5, metricEvent.Count);
Assert.Equal("event1", metricEvent.EventName);
Assert.Equal("Function2", metricEvent.FunctionName);
key = MetricsEventManager.GetAggregateKey("Event2");
metricEvent = _metricsEventManager.QueuedEvents[key];
Assert.Equal(15, metricEvent.Count);
Assert.Equal("event2", metricEvent.EventName);
Assert.Null(metricEvent.FunctionName);
}
public async Task FunctionLogging_Succeeds()
{
Fixture.Host.ClearLogMessages();
string functionName = "Scenarios";
string guid1 = Guid.NewGuid().ToString();
string guid2 = Guid.NewGuid().ToString();
var inputObject = new JObject
{
{ "Scenario", "logging" },
{ "Container", "scenarios-output" },
{ "Value", $"{guid1};{guid2}" }
};
await Fixture.Host.BeginFunctionAsync(functionName, inputObject);
IList <string> logs = null;
await TestHelpers.Await(() =>
{
logs = Fixture.Host.GetLogMessages().Select(p => p.FormattedMessage).Where(p => p != null).ToArray();
return(logs.Any(p => p.Contains(guid2)));
});
logs.Single(p => p.EndsWith($"From TraceWriter: {guid1}"));
logs.Single(p => p.EndsWith($"From ILogger: {guid2}"));
// TODO: Re-enable once we can override the IMetricsLogger
// Make sure we get a metric logged from both ILogger and TraceWriter
var key = MetricsEventManager.GetAggregateKey(MetricEventNames.FunctionUserLog, "Scenarios");
// Assert.Equal(2, Fixture.MetricsLogger.LoggedEvents.Where(p => p == key).Count());
// Make sure we've gotten a log from the aggregator
IEnumerable <LogMessage> getAggregatorLogs() => Fixture.Host.GetLogMessages().Where(p => p.Category == LogCategories.Aggregator);
await TestHelpers.Await(() => getAggregatorLogs().Any());
var aggregatorLogs = getAggregatorLogs();
Assert.Equal(1, aggregatorLogs.Count());
}
public void LogEvent_Function_AggregatesIntoExistingEvent()
{
Assert.Equal(0, _metricsEventManager.QueuedEvents.Count);
for (int i = 0; i < 10; i++)
{
_metricsLogger.LogEvent("Event1", "Function1");
}
for (int i = 0; i < 5; i++)
{
_metricsLogger.LogEvent("Event1", "Function2");
}
for (int i = 0; i < 15; i++)
{
_metricsLogger.LogEvent("Event3");
}
Assert.Equal(3, _metricsEventManager.QueuedEvents.Count);
string key = MetricsEventManager.GetAggregateKey("Event1", "Function1");
var metricEvent = _metricsEventManager.QueuedEvents[key];
Assert.Equal(10, metricEvent.Count);
Assert.Equal("event1", metricEvent.EventName);
Assert.Equal("Function1", metricEvent.FunctionName);
key = MetricsEventManager.GetAggregateKey("Event1", "Function2");
metricEvent = _metricsEventManager.QueuedEvents[key];
Assert.Equal(5, metricEvent.Count);
Assert.Equal("event1", metricEvent.EventName);
Assert.Equal("Function2", metricEvent.FunctionName);
key = MetricsEventManager.GetAggregateKey("Event3");
metricEvent = _metricsEventManager.QueuedEvents[key];
Assert.Equal(15, metricEvent.Count);
Assert.Equal("event3", metricEvent.EventName);
Assert.Null(metricEvent.FunctionName);
}
public void GetAggregateKey_ReturnsExpectedValue(string eventName, string functionName, string expected)
{
string result = MetricsEventManager.GetAggregateKey(eventName, functionName);
Assert.Equal(expected, result);
}
public void LogEvent(string eventName, string functionName = null)
{
LoggedEvents.Add(MetricsEventManager.GetAggregateKey(eventName, functionName));
}
public async Task Scenario_Logging()
{
string testData = Guid.NewGuid().ToString();
JObject input = new JObject
{
{ "scenario", "logging" },
{ "input", testData },
};
Fixture.Host.ClearLogMessages();
Fixture.MetricsLogger.ClearCollections();
await Fixture.Host.BeginFunctionAsync("Scenarios", input);
string userCategory = LogCategories.CreateFunctionUserCategory("Scenarios");
IList <string> userLogs = null;
string consoleLog = null;
await TestHelpers.Await(() =>
{
userLogs = Fixture.Host.GetScriptHostLogMessages(userCategory).Select(p => p.FormattedMessage).ToList();
consoleLog = Fixture.Host.GetScriptHostLogMessages(WorkerConstants.FunctionConsoleLogCategoryName).Select(p => p.FormattedMessage).SingleOrDefault();
return(userLogs.Count == 10 && consoleLog != null);
}, userMessageCallback : Fixture.Host.GetLog);
// verify use of context.log to log complex objects
LogMessage scriptTrace = Fixture.Host.GetScriptHostLogMessages(userCategory).Single(p => p.FormattedMessage != null && p.FormattedMessage.Contains(testData));
Assert.Equal(LogLevel.Information, scriptTrace.Level);
JObject logEntry = JObject.Parse(scriptTrace.FormattedMessage);
Assert.Equal("This is a test", logEntry["message"]);
Assert.Equal(testData, logEntry["input"]);
// verify log levels in traces
LogMessage[] traces = Fixture.Host.GetScriptHostLogMessages(userCategory).Where(t => t.FormattedMessage != null && t.FormattedMessage.Contains("loglevel")).ToArray();
Assert.Equal(LogLevel.Information, traces[0].Level);
Assert.Equal("loglevel default", traces[0].FormattedMessage);
Assert.Equal(LogLevel.Information, traces[1].Level);
Assert.Equal("loglevel info", traces[1].FormattedMessage);
Assert.Equal(LogLevel.Trace, traces[2].Level);
Assert.Equal("loglevel verbose", traces[2].FormattedMessage);
Assert.Equal(LogLevel.Warning, traces[3].Level);
Assert.Equal("loglevel warn", traces[3].FormattedMessage);
Assert.Equal(LogLevel.Error, traces[4].Level);
Assert.Equal("loglevel error", traces[4].FormattedMessage);
// verify most of the logs look correct
Assert.EndsWith("Mathew Charles", userLogs[1]);
Assert.EndsWith("null", userLogs[2]);
Assert.EndsWith("1234", userLogs[3]);
Assert.EndsWith("true", userLogs[4]);
Assert.EndsWith("loglevel default", userLogs[5]);
Assert.EndsWith("loglevel info", userLogs[6]);
// verify the console log
Assert.Equal("console log", consoleLog);
// We only expect 9 user log metrics to be counted, since
// verbose logs are filtered by default (the TestLogger explicitly
// allows all levels for testing purposes)
var key = MetricsEventManager.GetAggregateKey(MetricEventNames.FunctionUserLog, "Scenarios");
Assert.Equal(9, Fixture.MetricsLogger.LoggedEvents.Where(p => p == key).Count());
// Make sure that no user logs made it to the EventGenerator (which the SystemLogger writes to)
IEnumerable <FunctionTraceEvent> allLogs = Fixture.EventGenerator.GetFunctionTraceEvents();
Assert.False(allLogs.Any(l => l.Summary.Contains("loglevel")));
Assert.False(allLogs.Any(l => l.Summary.Contains("after done")));
Assert.False(allLogs.Any(l => l.Source.EndsWith(".User")));
Assert.False(allLogs.Any(l => l.Source == WorkerConstants.FunctionConsoleLogCategoryName));
Assert.NotEmpty(allLogs);
}