public void TimerFlush_CalledOnExpectedInterval()
{
int flushInterval = 10;
Mock <IEventGenerator> mockGenerator = new Mock <IEventGenerator>();
Mock <MetricsEventManager> mockEventManager = new Mock <MetricsEventManager>(_settingsManager, mockGenerator.Object, flushInterval, flushInterval)
{
CallBase = true
};
MetricsEventManager eventManager = mockEventManager.Object;
int numFlushes = 0;
mockEventManager.Protected().Setup("TimerFlush", ItExpr.IsAny <object>())
.Callback <object>((state) =>
{
numFlushes++;
});
Thread.Sleep(200);
// here we're just verifying that we're called
// multiple times
Assert.True(numFlushes >= 5, $"Expected numFlushes >= 5; Actual: {numFlushes}");
mockEventManager.VerifyAll();
}
public MetricsEventManagerTests()
{
_functionExecutionEventArguments = new List <FunctionExecutionEventArguments>();
var mockEventGenerator = new Mock <IEventGenerator>();
mockEventGenerator.Setup(e => e.LogFunctionExecutionEvent(
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <int>(),
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <long>(),
It.IsAny <bool>()))
.Callback((string executionId, string siteName, int concurrency, string functionName, string invocationId, string executionStage, long executionTimeSpan, bool success) =>
{
_functionExecutionEventArguments.Add(new FunctionExecutionEventArguments(executionId, siteName, concurrency, functionName, invocationId, executionStage, executionTimeSpan, success));
});
_events = new List <SystemMetricEvent>();
mockEventGenerator.Setup(p => p.LogFunctionMetricEvent(
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <long>(),
It.IsAny <long>(),
It.IsAny <long>(),
It.IsAny <long>(),
It.IsAny <DateTime>(),
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <string>()))
.Callback((string subscriptionId, string appName, string functionName, string eventName, long average, long min, long max, long count, DateTime eventTimestamp, string data, string runtimeSiteName, string slotName) =>
{
var evt = new SystemMetricEvent
{
FunctionName = functionName,
EventName = eventName,
Average = average,
Minimum = min,
Maximum = max,
Count = count,
Data = data,
RuntimeSiteName = runtimeSiteName,
SlotName = slotName
};
_events.Add(evt);
});
var mockMetricsPublisher = new Mock <IMetricsPublisher>();
var testAppServiceOptions = new Mock <IOptionsMonitor <AppServiceOptions> >();
testAppServiceOptions.Setup(a => a.CurrentValue).Returns(new AppServiceOptions {
AppName = "RandomAppName", SubscriptionId = Guid.NewGuid().ToString()
});
_metricsEventManager = new MetricsEventManager(testAppServiceOptions.Object, mockEventGenerator.Object, MinimumLongRunningDurationInMs / 1000, mockMetricsPublisher.Object);
_metricsLogger = new WebHostMetricsLogger(_metricsEventManager);
}
public async Task TimerFlush_CalledOnExpectedInterval()
{
int flushInterval = 10;
Mock <IEventGenerator> mockGenerator = new Mock <IEventGenerator>();
var testAppServiceOptions = new Mock <IOptionsMonitor <AppServiceOptions> >();
testAppServiceOptions.Setup(a => a.CurrentValue).Returns(new AppServiceOptions {
AppName = "RandomAppName", SubscriptionId = Guid.NewGuid().ToString()
});
Mock <MetricsEventManager> mockEventManager = new Mock <MetricsEventManager>(testAppServiceOptions.Object, mockGenerator.Object, flushInterval, null, null, NullLogger <MetricsEventManager> .Instance, flushInterval)
{
CallBase = true
};
MetricsEventManager eventManager = mockEventManager.Object;
int numFlushes = 0;
mockEventManager.Protected().Setup("TimerFlush", ItExpr.IsAny <object>())
.Callback <object>((state) =>
{
numFlushes++;
});
// here we're just verifying that we're called multiple times
await TestHelpers.Await(() => numFlushes >= 5, timeout : 2000, pollingInterval : 100, userMessageCallback : () => $"Expected numFlushes >= 5; Actual: {numFlushes}");
mockEventManager.VerifyAll();
}
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 MetricsEventManagerTests()
{
_functionExecutionEventArguments = new List <FunctionExecutionEventArguments>();
var mockEventGenerator = new Mock <IEventGenerator>();
mockEventGenerator.Setup(e => e.LogFunctionExecutionEvent(
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <int>(),
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <long>(),
It.IsAny <bool>()))
.Callback((string executionId, string siteName, int concurrency, string functionName, string invocationId, string executionStage, long executionTimeSpan, bool success) =>
{
_functionExecutionEventArguments.Add(new FunctionExecutionEventArguments(executionId, siteName, concurrency, functionName, invocationId, executionStage, executionTimeSpan, success));
});
_events = new List <SystemMetricEvent>();
mockEventGenerator.Setup(p => p.LogFunctionMetricEvent(
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <long>(),
It.IsAny <long>(),
It.IsAny <long>(),
It.IsAny <long>(),
It.IsAny <DateTime>(),
It.IsAny <string>(),
It.IsAny <string>()))
.Callback((string subscriptionId, string appName, string functionName, string eventName, long average, long min, long max, long count, DateTime eventTimestamp, string data, string runtimeSiteName) =>
{
var evt = new SystemMetricEvent
{
FunctionName = functionName,
EventName = eventName,
Average = average,
Minimum = min,
Maximum = max,
Count = count,
Data = data,
RuntimeSiteName = runtimeSiteName
};
_events.Add(evt);
});
var mockMetricsPublisher = new Mock <IMetricsPublisher>();
_metricsEventManager = new MetricsEventManager(new TestEnvironment(), mockEventGenerator.Object, MinimumLongRunningDurationInMs / 1000, mockMetricsPublisher.Object);
_metricsLogger = new WebHostMetricsLogger(_metricsEventManager);
}
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 MetricsEventManagerTests()
{
_settingsManager = ScriptSettingsManager.Instance;
_functionExecutionEventArguments = new List <FunctionExecutionEventArguments>();
var mockEventGenerator = new Mock <IEventGenerator>();
mockEventGenerator.Setup(e => e.LogFunctionExecutionEvent(
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <int>(),
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <long>(),
It.IsAny <bool>()))
.Callback((string executionId, string siteName, int concurrency, string functionName, string invocationId, string executionStage, long executionTimeSpan, bool success) =>
{
_functionExecutionEventArguments.Add(new FunctionExecutionEventArguments(executionId, siteName, concurrency, functionName, invocationId, executionStage, executionTimeSpan, success));
});
_events = new List <SystemMetricEvent>();
mockEventGenerator.Setup(p => p.LogFunctionMetricEvent(
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <long>(),
It.IsAny <long>(),
It.IsAny <long>(),
It.IsAny <long>()))
.Callback((string subscriptionId, string appName, string eventName, long average, long min, long max, long count) =>
{
var evt = new SystemMetricEvent
{
EventName = eventName,
Average = average,
Minimum = min,
Maximum = max,
Count = count
};
_events.Add(evt);
});
_metricsEventManager = new MetricsEventManager(_settingsManager, mockEventGenerator.Object, MinimumLongRunningDurationInMs / 1000);
_metricsLogger = new WebHostMetricsLogger(_metricsEventManager);
}
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 async Task TimerFlush_CalledOnExpectedInterval()
{
int flushInterval = 10;
Mock <IEventGenerator> mockGenerator = new Mock <IEventGenerator>();
Mock <MetricsEventManager> mockEventManager = new Mock <MetricsEventManager>(new TestEnvironment(), mockGenerator.Object, flushInterval, null, flushInterval)
{
CallBase = true
};
MetricsEventManager eventManager = mockEventManager.Object;
int numFlushes = 0;
mockEventManager.Protected().Setup("TimerFlush", ItExpr.IsAny <object>())
.Callback <object>((state) =>
{
numFlushes++;
});
// here we're just verifying that we're called multiple times
await TestHelpers.Await(() => numFlushes >= 5, timeout : 2000, pollingInterval : 100, userMessageCallback : () => $"Expected numFlushes >= 5; Actual: {numFlushes}");
mockEventManager.VerifyAll();
}
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);
}
public void GetAggregateKey_ReturnsExpectedValue(string eventName, string functionName, string expected)
{
string result = MetricsEventManager.GetAggregateKey(eventName, functionName);
Assert.Equal(expected, result);
}
public async Task MetricsEventManager_ActivityTimer_HandlesExceptions()
{
// create a local event manager for this test, so we can override the flush interval
var logger = _loggerFactory.CreateLogger <MetricsEventManager>();
var metricsEventManager = new MetricsEventManager(_mockAppServiceOptions.Object, _mockEventGenerator.Object, 1, _mockEventPublisher.Object, _linuxFunctionExecutionActivityPublisher.Object, logger);
var metricsLogger = new WebHostMetricsLogger(metricsEventManager);
// execute some functions
var taskList = new List <Task>();
for (int currentIndex = 0; currentIndex < 10; currentIndex++)
{
taskList.Add(ShortTestFunction(metricsLogger));
}
await Task.WhenAll(taskList);
// wait for a flush to occur
await Task.Delay(1000);
// verify events
Assert.Equal(10, _functionExecutionEventArguments.Count);
Assert.True(_functionExecutionEventArguments.All(p => p.ExecutionStage == ExecutionStage.Finished.ToString()));
// now force a logging error for an in progress function
// on the background timer
_throwOnExecutionEvent = true;
var id = Guid.NewGuid();
var functionMetadata = new FunctionMetadata
{
Name = "Test"
};
var functionEvent = new FunctionStartedEvent(id, functionMetadata);
metricsLogger.BeginEvent(functionEvent);
// wait for the error to be logged
LogMessage errorLog = null;
await TestHelpers.Await(() =>
{
errorLog = _testLoggerProvider.GetAllLogMessages().SingleOrDefault();
return(errorLog != null);
}, timeout : 5000);
// verify error was logged
Assert.Equal(LogLevel.Error, errorLog.Level);
Assert.Equal("Error occurred when logging function activity", errorLog.FormattedMessage);
// execute some more functions, verifying that the timer is
// still running
taskList = new List <Task>();
for (int currentIndex = 0; currentIndex < 10; currentIndex++)
{
taskList.Add(ShortTestFunction(metricsLogger));
}
await Task.WhenAll(taskList);
await Task.Delay(1000);
// verify events
Assert.Equal(20, _functionExecutionEventArguments.Count(p => p.ExecutionStage == ExecutionStage.Finished.ToString()));
int inProgressCount = _functionExecutionEventArguments.Count(p => p.InvocationId == id.ToString() && p.ExecutionStage == ExecutionStage.InProgress.ToString());
Assert.True(inProgressCount > 0);
}
public void LogEvent(string eventName, string functionName = null)
{
LoggedEvents.Add(MetricsEventManager.GetAggregateKey(eventName, functionName));
}
public MetricsEventManagerTests()
{
_loggerFactory = new LoggerFactory();
_testLoggerProvider = new TestLoggerProvider();
_loggerFactory.AddProvider(_testLoggerProvider);
_functionExecutionEventArguments = new List <FunctionExecutionEventArguments>();
_mockEventGenerator = new Mock <IEventGenerator>();
_mockEventGenerator.Setup(e => e.LogFunctionExecutionEvent(
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <int>(),
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <long>(),
It.IsAny <bool>()))
.Callback((string executionId, string siteName, int concurrency, string functionName, string invocationId, string executionStage, long executionTimeSpan, bool success) =>
{
if (_throwOnExecutionEvent && executionStage == ExecutionStage.InProgress.ToString())
{
_throwOnExecutionEvent = false;
throw new Exception("Kaboom!");
}
lock (_syncLock)
{
_functionExecutionEventArguments.Add(new FunctionExecutionEventArguments(executionId, siteName, concurrency, functionName, invocationId, executionStage, executionTimeSpan, success));
}
});
_events = new List <SystemMetricEvent>();
_mockEventGenerator.Setup(p => p.LogFunctionMetricEvent(
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <long>(),
It.IsAny <long>(),
It.IsAny <long>(),
It.IsAny <long>(),
It.IsAny <DateTime>(),
It.IsAny <string>(),
It.IsAny <string>(),
It.IsAny <string>()))
.Callback((string subscriptionId, string appName, string functionName, string eventName, long average, long min, long max, long count, DateTime eventTimestamp, string data, string runtimeSiteName, string slotName) =>
{
var evt = new SystemMetricEvent
{
FunctionName = functionName,
EventName = eventName,
Average = average,
Minimum = min,
Maximum = max,
Count = count,
Data = data,
RuntimeSiteName = runtimeSiteName,
SlotName = slotName
};
lock (_syncLock)
{
_events.Add(evt);
}
});
_mockEventPublisher = new Mock <IMetricsPublisher>();
_mockAppServiceOptions = new Mock <IOptionsMonitor <AppServiceOptions> >();
_mockAppServiceOptions.Setup(a => a.CurrentValue).Returns(new AppServiceOptions {
AppName = "RandomAppName", SubscriptionId = Guid.NewGuid().ToString()
});
_linuxFunctionExecutionActivityPublisher = new Mock <ILinuxContainerActivityPublisher>();
var logger = _loggerFactory.CreateLogger <MetricsEventManager>();
_metricsEventManager = new MetricsEventManager(_mockAppServiceOptions.Object, _mockEventGenerator.Object, MinimumLongRunningDurationInMs / 1000, _mockEventPublisher.Object, _linuxFunctionExecutionActivityPublisher.Object, logger);
_metricsLogger = new WebHostMetricsLogger(_metricsEventManager);
}
