private static void ValidateTrace(TraceTelemetry telemetry, string expectedMessageStartsWith, string expectedCategory,
string expectedOperationName = null, string expectedInvocationId = null, string expectedOperationId = null,
string expectedParentId = null, bool hasCustomScope = false, LogLevel expectedLogLevel = LogLevel.Information)
{
Assert.StartsWith(expectedMessageStartsWith, telemetry.Message);
Assert.Equal(GetSeverityLevel(expectedLogLevel), telemetry.SeverityLevel);
Assert.Equal(expectedCategory, telemetry.Properties[LogConstants.CategoryNameKey]);
if (hasCustomScope)
{
ValidateCustomScopeProperty(telemetry);
}
if (expectedCategory == LogCategories.CreateFunctionCategory(expectedOperationName) ||
expectedCategory == LogCategories.CreateFunctionUserCategory(expectedOperationName))
{
// These should have associated operation information
Assert.Equal(expectedOperationName, telemetry.Context.Operation.Name);
Assert.Equal(expectedOperationId, telemetry.Context.Operation.Id);
Assert.Equal(expectedParentId, telemetry.Context.Operation.ParentId);
Assert.True(telemetry.Properties.TryGetValue(LogConstants.InvocationIdKey, out string id));
Assert.Equal(expectedInvocationId, id);
}
else
{
Assert.Null(telemetry.Context.Operation.Name);
Assert.Null(telemetry.Context.Operation.Id);
Assert.Null(telemetry.Context.Operation.ParentId);
Assert.False(telemetry.Properties.TryGetValue(LogConstants.InvocationIdKey, out string unused));
}
ValidateSdkVersion(telemetry);
}
public async Task LogFunctionStarted_CallsLogger()
{
FunctionStartedMessage message = new FunctionStartedMessage
{
Function = new FunctionDescriptor
{
ShortName = "Function.TestJob",
LogName = "TestJob"
},
ReasonDetails = "TestReason",
HostInstanceId = Guid.NewGuid(),
FunctionInstanceId = Guid.NewGuid()
};
await _instanceLogger.LogFunctionStartedAsync(message, CancellationToken.None);
string expectedCategory = LogCategories.CreateFunctionCategory("TestJob");
LogMessage logMessage = _provider.GetAllLogMessages().Single();
Assert.Equal(LogLevel.Information, logMessage.Level);
Assert.Equal(expectedCategory, logMessage.Category);
Assert.Null(logMessage.State);
Assert.Equal($"Executing 'Function.TestJob' (Reason='TestReason', Id={message.FunctionInstanceId})", logMessage.FormattedMessage);
}
private static void ValidateException(ExceptionTelemetry telemetry, string expectedCategory, string expectedOperationName)
{
Assert.Equal(expectedCategory, telemetry.Properties[LogConstants.CategoryNameKey]);
Assert.Equal(expectedOperationName, telemetry.Context.Operation.Name);
Assert.NotNull(telemetry.Context.Operation.Id);
if (expectedCategory == LogCategories.CreateFunctionUserCategory(expectedOperationName))
{
// It came directly from the user
Assert.IsType <Exception>(telemetry.Exception);
// Result logs do not include custom scopes.
ValidateCustomScopeProperty(telemetry);
}
else if (expectedCategory == LogCategories.CreateFunctionCategory(expectedOperationName))
{
// It came directly from the host, so wrapped in a FunctionInvocationException
Assert.IsType <FunctionInvocationException>(telemetry.Exception);
}
else if (expectedCategory == LogCategories.Results)
{
// Check that the Function details show up as 'prop__'. We may change this in the future as
// it may not be exceptionally useful.
Assert.Equal(expectedOperationName, telemetry.Properties[$"{LogConstants.CustomPropertyPrefix}{LogConstants.NameKey}"]);
Assert.Equal("This function was programmatically called via the host APIs.", telemetry.Properties[$"{LogConstants.CustomPropertyPrefix}{LogConstants.TriggerReasonKey}"]);
Assert.IsType <FunctionInvocationException>(telemetry.Exception);
Assert.IsType <Exception>(telemetry.Exception.InnerException);
}
ValidateSdkVersion(telemetry);
}
public async Task DoubleFailure()
{
var loggerProvider = new TestLoggerProvider();
// create a host with some global filters
var host = TestHelpers.NewJobHost <MyProg3>(
new MyInvocationFilterAttribute("global"), new MyExceptionFilterAttribute("global"), loggerProvider);
_throwAtPhase = "body;Post_m1";
await CallExpectFailureAsync(host);
var expected =
"[ctor][Pre-Instance][Pre_global][Pre_class][Pre_m1][Pre_m2]" +
"[body-Throw!]" +
"[Post_m2][Post_m1-Throw!][Post_class][Post_global][Post-Instance]" +
"[ExceptionFilter_Instance][ExceptionFilter_global][ExceptionFilter_class][ExceptionFilter_method]";
Assert.Equal(expected, TestLog.ToString());
var logger = loggerProvider.CreatedLoggers.Single(p => p.Category == LogCategories.CreateFunctionCategory(nameof(MyProg3.Method2)));
// strip out the 4 messages written by the executor ("Executing", FunctionStartedEvent, "Executed", FunctionCompletedEvent)
string logResult = string.Join("|", logger.GetLogMessages()
.Where(p => p.EventId.Id == 0 && !p.FormattedMessage.StartsWith("Execut"))
.Select(p => p.FormattedMessage));
Assert.Equal(
"Pre_global|Pre_class|Pre_m1|Pre_m2|" +
"Post_m2|Post_m1|Post_class|Post_global|" +
"ExceptionFilter_global|ExceptionFilter_class|ExceptionFilter_method", logResult);
}
public SystemLoggerTests()
{
_subscriptionId = "e3235165-1600-4819-85f0-2ab362e909e4";
_hostInstanceId = Guid.NewGuid().ToString();
_websiteName = "functionstest";
_environment = new TestEnvironment(new Dictionary <string, string>
{
{ EnvironmentSettingNames.AzureWebsiteOwnerName, $"{_subscriptionId}+westuswebspace" },
{ EnvironmentSettingNames.AzureWebsiteName, _websiteName },
{ EnvironmentSettingNames.AzureWebsiteRuntimeSiteName, _runtimeSiteName },
{ EnvironmentSettingNames.AzureWebsiteSlotName, _slotName }
});
_changeTokenSource = new TestChangeTokenSource <StandbyOptions>();
var host = new HostBuilder()
.ConfigureServices(s =>
{
s.AddSingleton <IEnvironment>(_environment);
s.ConfigureOptions <AppServiceOptionsSetup>();
s.AddSingleton <IOptionsChangeTokenSource <AppServiceOptions>, SpecializationChangeTokenSource <AppServiceOptions> >();
s.AddSingleton <IOptionsChangeTokenSource <StandbyOptions> >(_changeTokenSource);
})
.Build();
_appServiceOptions = host.Services.GetService <IOptionsMonitor <AppServiceOptions> >();
_mockEventGenerator = new Mock <IEventGenerator>(MockBehavior.Strict);
_inDiagnosticMode = false;
_category = LogCategories.CreateFunctionCategory(_functionName);
_debugStateProvider = new Mock <IDebugStateProvider>(MockBehavior.Strict);
_debugStateProvider.Setup(p => p.InDiagnosticMode).Returns(() => _inDiagnosticMode);
_logger = new SystemLogger(_hostInstanceId, _category, _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions);
}
private async Task <IActionResult> GetResultAsync(HttpContext context, IFunctionExecutionFeature functionExecution)
{
if (functionExecution.Descriptor == null)
{
return(new NotFoundResult());
}
if (context.Request.IsColdStart() && !context.Items.ContainsKey(ScriptConstants.AzureFunctionsColdStartKey))
{
// for cold start requests we want to measure the request
// pipeline dispatch time
// important that this stopwatch is started as early as possible
// in the pipeline (in this case, in our first middleware)
var sw = new Stopwatch();
sw.Start();
context.Items[ScriptConstants.AzureFunctionsColdStartKey] = sw;
}
PopulateRouteData(context);
bool authorized = await AuthenticateAndAuthorizeAsync(context, functionExecution.Descriptor);
if (!authorized)
{
return(new UnauthorizedResult());
}
// If the function is disabled, return 'NotFound', unless the request is being made with Admin credentials
if (functionExecution.Descriptor.Metadata.IsDisabled() &&
!AuthUtility.PrincipalHasAuthLevelClaim(context.User, AuthorizationLevel.Admin))
{
return(new NotFoundResult());
}
if (functionExecution.CanExecute)
{
// Add the request to the logging scope. This allows the App Insights logger to
// record details about the request.
ILoggerFactory loggerFactory = context.RequestServices.GetService <ILoggerFactory>();
ILogger logger = loggerFactory.CreateLogger(LogCategories.CreateFunctionCategory(functionExecution.Descriptor.Name));
var scopeState = new Dictionary <string, object>()
{
[ScriptConstants.LoggerHttpRequest] = context.Request,
};
using (logger.BeginScope(scopeState))
{
var applicationLifetime = context.RequestServices.GetService <IApplicationLifetime>();
CancellationToken cancellationToken = applicationLifetime != null ? applicationLifetime.ApplicationStopping : CancellationToken.None;
await functionExecution.ExecuteAsync(context.Request, cancellationToken);
}
}
if (context.Items.TryGetValue(ScriptConstants.AzureFunctionsHttpResponseKey, out object result) && result is IActionResult actionResult)
{
return(actionResult);
}
return(new OkResult());
}
public void CreateLogger_UsesSameFileWriter_ForSameFile()
{
var options = new ScriptJobHostOptions
{
RootLogPath = Path.GetTempPath()
};
var fileStatus = new Mock <IFileLoggingStatusManager>();
var primaryStatus = new Mock <IPrimaryHostStateProvider>();
using (var provider = new FunctionFileLoggerProvider(new OptionsWrapper <ScriptJobHostOptions>(options), fileStatus.Object, primaryStatus.Object))
{
provider.CreateLogger(LogCategories.CreateFunctionCategory("Test1"));
provider.CreateLogger(LogCategories.CreateFunctionUserCategory("Test1"));
provider.CreateLogger(LogCategories.CreateFunctionCategory("Test1"));
Assert.Single(provider.FileWriterCache);
// This creates a new entry.
provider.CreateLogger(LogCategories.CreateFunctionCategory("Test2"));
Assert.Equal(2, provider.FileWriterCache.Count);
Assert.NotSame(
provider.FileWriterCache[Path.Combine("Function", "Test1")],
provider.FileWriterCache[Path.Combine("Function", "Test2")]);
}
}
public DiagnosticLoggerTests()
{
_environment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsiteOwnerName, $"{_subscriptionId}+westuswebspace");
_environment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsiteHostName, _websiteHostName);
_environment.SetEnvironmentVariable(EnvironmentSettingNames.RegionName, _regionName);
_environment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsiteInstanceId, _roleInstance);
_mockEventGenerator = new Mock <IEventGenerator>(MockBehavior.Strict);
var appServiceOptions = new AppServiceOptions
{
AppName = "TestApp",
SlotName = "Production",
SubscriptionId = "abc123",
RuntimeSiteName = "TestApp_Runtime"
};
_appServiceOptionsWrapper = new TestOptionsMonitor <AppServiceOptions>(appServiceOptions);
_category = LogCategories.CreateFunctionCategory(_functionName);
var loggerProvider = new TestLoggerProvider();
var loggerFactory = new LoggerFactory();
loggerFactory.AddProvider(loggerProvider);
_hostNameProvider = new HostNameProvider(_environment);
_logger = new AzureMonitorDiagnosticLogger(_category, _hostInstanceId, _mockEventGenerator.Object, _environment, new LoggerExternalScopeProvider(), _hostNameProvider, _appServiceOptionsWrapper);
}
private string ValidateEndToEndTest(string functionName, string functionTrace, bool functionSuccess)
{
// Look for the trace that matches the GUID we passed in. That's how we'll find the
// function's invocation id.
TraceTelemetry trace = _fixture.Channel.Telemetries
.OfType <TraceTelemetry>()
.Where(t => t.Message.Contains(functionTrace))
.Single();
// functions need to log JSON that contains the invocationId and trace
JObject logPayload = JObject.Parse(trace.Message);
string logInvocationId = logPayload["invocationId"].ToString();
string invocationId = trace.Properties[LogConstants.InvocationIdKey];
// make sure they match
Assert.Equal(logInvocationId, invocationId);
// Find the Info traces.
TraceTelemetry[] traces = _fixture.Channel.Telemetries
.OfType <TraceTelemetry>()
.Where(t => GetInvocationId(t) == invocationId)
.Where(t => !t.Message.StartsWith("Exception")) // we'll verify the exception message separately
.Where(t => t.Properties[LogConstants.CategoryNameKey] == LogCategories.CreateFunctionCategory(functionName))
.OrderBy(t => t.Message)
.ToArray();
string expectedMessage = functionSuccess ? $"Executed 'Functions.{functionName}' (Succeeded, Id=" : $"Executed 'Functions.{functionName}' (Failed, Id=";
SeverityLevel expectedLevel = functionSuccess ? SeverityLevel.Information : SeverityLevel.Error;
ValidateTrace(traces[0], expectedMessage + invocationId, LogCategories.CreateFunctionCategory(functionName), functionName, invocationId, expectedLevel);
ValidateTrace(traces[1], $"Executing 'Functions.{functionName}' (Reason='This function was programmatically called via the host APIs.', Id=" + invocationId, LogCategories.CreateFunctionCategory(functionName), functionName, invocationId);
if (!functionSuccess)
{
TraceTelemetry errorTrace = _fixture.Channel.Telemetries
.OfType <TraceTelemetry>()
.Where(t => GetInvocationId(t) == invocationId)
.Where(t => t.Message.Contains("Exception while"))
.Single();
ValidateTrace(errorTrace, $"Exception while executing function: Functions.{functionName}.", LogCategories.CreateFunctionCategory(functionName), functionName, invocationId, SeverityLevel.Error);
ExceptionTelemetry exception = _fixture.Channel.Telemetries
.OfType <ExceptionTelemetry>()
.Single(t => GetInvocationId(t) == invocationId);
ValidateException(exception, invocationId, functionName, LogCategories.Results);
}
RequestTelemetry requestTelemetry = _fixture.Channel.Telemetries
.OfType <RequestTelemetry>()
.Where(t => GetInvocationId(t) == invocationId)
.Single();
ValidateRequest(requestTelemetry, invocationId, functionName, "req", functionSuccess);
return(invocationId);
}
protected async Task TableInputTest()
{
var input = new JObject
{
{ "Region", "West" },
{ "Status", 1 }
};
await Fixture.Host.BeginFunctionAsync("TableIn", input);
var result = await WaitForTraceAsync("TableIn", log =>
{
return(log.FormattedMessage.Contains("Result:"));
});
string message = result.FormattedMessage.Substring(result.FormattedMessage.IndexOf('{'));
// verify singleton binding
JObject resultObject = JObject.Parse(message);
JObject single = (JObject)resultObject["single"];
Assert.Equal("AAA", (string)single["PartitionKey"]);
Assert.Equal("001", (string)single["RowKey"]);
// verify partition binding
JArray partition = (JArray)resultObject["partition"];
Assert.Equal(3, partition.Count);
foreach (var entity in partition)
{
Assert.Equal("BBB", (string)entity["PartitionKey"]);
}
// verify query binding
JArray query = (JArray)resultObject["query"];
Assert.Equal(2, query.Count);
Assert.Equal("003", (string)query[0]["RowKey"]);
Assert.Equal("004", (string)query[1]["RowKey"]);
// verify input validation
input = new JObject
{
{ "Region", "West" },
{ "Status", "1 or Status neq 1" }
};
await Fixture.Host.BeginFunctionAsync("TableIn", input);
// Watch for the expected error.
var errorLog = await WaitForTraceAsync(log =>
{
return(log.Category == LogCategories.CreateFunctionCategory("TableIn") &&
log.Exception is FunctionInvocationException);
});
Assert.Equal("An invalid parameter value was specified for filter parameter 'Status'.", errorLog.Exception.InnerException.Message);
}
public void CreateLogger_ReturnsSystemLogger_ForNonUserCategories()
{
var provider = new SystemLoggerProvider(_options, null, ScriptSettingsManager.Instance);
Assert.IsType <SystemLogger>(provider.CreateLogger(LogCategories.CreateFunctionCategory("TestFunction")));
Assert.IsType <SystemLogger>(provider.CreateLogger(ScriptConstants.LogCategoryHostGeneral));
Assert.IsType <SystemLogger>(provider.CreateLogger("NotAFunction.TestFunction.User"));
}
public async Task ApplicationInsights_SuccessfulFunction()
{
string testName = nameof(TestApplicationInsightsInformation);
using (IHost host = ConfigureHost())
{
await host.StartAsync();
MethodInfo methodInfo = GetType().GetMethod(testName, BindingFlags.Public | BindingFlags.Static);
await host.GetJobHost().CallAsync(methodInfo, new { input = "function input" });
await host.StopAsync();
Assert.Equal(16, _channel.Telemetries.Count);
// Validate the request
RequestTelemetry request = _channel.Telemetries
.OfType <RequestTelemetry>()
.Single();
ValidateRequest(request, testName, true);
// invocation id is retrievable from the request
request.Properties.TryGetValue(LogConstants.InvocationIdKey, out string invocationId);
// Validate the traces. Order by message string as the requests may come in
// slightly out-of-order or on different threads
TraceTelemetry[] telemetries = _channel.Telemetries
.OfType <TraceTelemetry>()
.OrderBy(t => t.Message)
.ToArray();
string expectedFunctionCategory = LogCategories.CreateFunctionCategory(testName);
string expectedFunctionUserCategory = LogCategories.CreateFunctionUserCategory(testName);
string expectedOperationId = request.Context.Operation.Id;
ValidateTrace(telemetries[0], "ApplicationInsightsLoggerOptions", "Microsoft.Azure.WebJobs.Hosting.OptionsLoggingService");
ValidateTrace(telemetries[1], "Executed ", expectedFunctionCategory, testName, invocationId, expectedOperationId, request.Id);
ValidateTrace(telemetries[2], "Executing ", expectedFunctionCategory, testName, invocationId, expectedOperationId, request.Id);
ValidateTrace(telemetries[3], "Found the following functions:\r\n", LogCategories.Startup);
ValidateTrace(telemetries[4], "FunctionResultAggregatorOptions", "Microsoft.Azure.WebJobs.Hosting.OptionsLoggingService");
ValidateTrace(telemetries[5], "Job host started", LogCategories.Startup);
ValidateTrace(telemetries[6], "Job host stopped", LogCategories.Startup);
ValidateTrace(telemetries[7], "Logger", expectedFunctionUserCategory, testName, invocationId, expectedOperationId, request.Id, hasCustomScope: true);
ValidateTrace(telemetries[8], "LoggerFilterOptions", "Microsoft.Azure.WebJobs.Hosting.OptionsLoggingService");
ValidateTrace(telemetries[9], "LoggerFilterOptions", "Microsoft.Azure.WebJobs.Hosting.OptionsLoggingService");
ValidateTrace(telemetries[10], "SingletonOptions", "Microsoft.Azure.WebJobs.Hosting.OptionsLoggingService");
ValidateTrace(telemetries[11], "Starting JobHost", "Microsoft.Azure.WebJobs.Hosting.JobHostService");
ValidateTrace(telemetries[12], "Stopping JobHost", "Microsoft.Azure.WebJobs.Hosting.JobHostService");
ValidateTrace(telemetries[13], "Trace", expectedFunctionUserCategory, testName, invocationId, expectedOperationId, request.Id);
// We should have 1 custom metric.
MetricTelemetry metric = _channel.Telemetries
.OfType <MetricTelemetry>()
.Single();
ValidateMetric(metric, testName);
}
}
public async Task ApplicationInsights_FailedFunction()
{
string testName = nameof(TestApplicationInsightsFailure);
using (IHost host = ConfigureHost())
{
await host.StartAsync();
MethodInfo methodInfo = GetType().GetMethod(testName, BindingFlags.Public | BindingFlags.Static);
await Assert.ThrowsAsync <FunctionInvocationException>(() => host.GetJobHost().CallAsync(methodInfo, new { input = "function input" }));
await host.StopAsync();
Assert.Equal(14, _channel.Telemetries.Count);
// Validate the request
RequestTelemetry request = _channel.Telemetries
.OfType <RequestTelemetry>()
.Single();
ValidateRequest(request, testName, false);
// invocation id is retrievable from the request
request.Properties.TryGetValue(LogConstants.InvocationIdKey, out string invocationId);
// Validate the traces. Order by message string as the requests may come in
// slightly out-of-order or on different threads
TraceTelemetry[] telemetries = _channel.Telemetries
.OfType <TraceTelemetry>()
.OrderBy(t => t.Message)
.ToArray();
string expectedFunctionCategory = LogCategories.CreateFunctionCategory(testName);
string expectedFunctionUserCategory = LogCategories.CreateFunctionUserCategory(testName);
ValidateTrace(telemetries[0], "Error", expectedFunctionUserCategory, testName, invocationId, request.Context.Operation.Id, request.Id, expectedLogLevel: LogLevel.Error);
ValidateTrace(telemetries[1], "Executed", expectedFunctionCategory, testName, invocationId, expectedLogLevel: LogLevel.Error);
ValidateTrace(telemetries[2], "Executing", expectedFunctionCategory, testName, invocationId, request.Context.Operation.Id, request.Id);
ValidateTrace(telemetries[3], "Found the following functions:\r\n", LogCategories.Startup);
ValidateTrace(telemetries[4], "Job host started", LogCategories.Startup);
ValidateTrace(telemetries[5], "Job host stopped", LogCategories.Startup);
ValidateTrace(telemetries[6], "Logger", expectedFunctionUserCategory, testName, invocationId, request.Context.Operation.Id, request.Id, hasCustomScope: true);
ValidateTrace(telemetries[7], "Starting JobHost", "Microsoft.Azure.WebJobs.Hosting.JobHostService");
ValidateTrace(telemetries[8], "Stopping JobHost", "Microsoft.Azure.WebJobs.Hosting.JobHostService");
ValidateTrace(telemetries[9], "Trace", expectedFunctionUserCategory, testName, invocationId, request.Context.Operation.Id, request.Id);
// Validate the exception
ExceptionTelemetry[] exceptions = _channel.Telemetries
.OfType <ExceptionTelemetry>()
.OrderBy(t => t.Timestamp)
.ToArray();
Assert.Equal(3, exceptions.Length);
ValidateException(exceptions[0], expectedFunctionUserCategory, testName, request.Context.Operation.Id, request.Id);
ValidateException(exceptions[1], LogCategories.Results, testName, request.Context.Operation.Id, request.Id);
ValidateException(exceptions[2], expectedFunctionCategory, testName, null, null);
}
}
/// <summary>
/// Initialize the binding extension
/// </summary>
/// <param name="context">Context for the extension</param>
public void Initialize(ExtensionConfigContext context)
{
log = context.Config.LoggerFactory.CreateLogger(LogCategories.CreateFunctionCategory("SmartOffice"));
context.AddBindingRule <DataRepositoryAttribute>().BindToInput <object>(this);
context.AddBindingRule <PartnerServiceAttribute>().BindToInput <PartnerServiceClient>(this);
context.AddBindingRule <SecureScoreAttribute>().BindToInput <List <SecureScore> >(this);
context.AddBindingRule <SecurityAlertsAttribute>().BindToInput <List <Alert> >(this);
context.AddBindingRule <StorageServiceAttribute>().BindToInput <StorageService>(this);
}
public DiagnosticLoggerTests()
{
_environment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsiteOwnerName, $"{_subscriptionId}+westuswebspace");
_environment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsiteHostName, _websiteHostName);
_environment.SetEnvironmentVariable(EnvironmentSettingNames.RegionName, _regionName);
_mockEventGenerator = new Mock <IEventGenerator>(MockBehavior.Strict);
_category = LogCategories.CreateFunctionCategory(_functionName);
_logger = new AzureMonitorDiagnosticLogger(_category, _hostInstanceId, _mockEventGenerator.Object, _environment, new LoggerExternalScopeProvider());
}
public FileLoggerTests()
{
_logFilePath = Path.Combine(Path.GetTempPath(), "WebJobs.Script.Tests", "FileLoggerTests");
_category = LogCategories.CreateFunctionCategory("Test");
if (Directory.Exists(_logFilePath))
{
Directory.Delete(_logFilePath, recursive: true);
}
_fileWriter = new FileWriter(_logFilePath);
}
public SecretManagerTests()
{
_testEnvironment = new TestEnvironment();
_testEnvironment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsiteHostName, "test.azurewebsites.net");
_loggerProvider = new TestLoggerProvider();
var loggerFactory = new LoggerFactory();
loggerFactory.AddProvider(_loggerProvider);
_logger = _loggerProvider.CreateLogger(LogCategories.CreateFunctionCategory("test"));
_hostNameProvider = new HostNameProvider(_testEnvironment);
}
public async Task ServiceBusRequestWithoutParent()
{
var sender = new MessageSender(_connectionString, _queueName);
await sender.SendAsync(new Message { Body = Encoding.UTF8.GetBytes("message"), ContentType = "text/plain" });
using (var host = ConfigureHost())
{
await host.StartAsync();
_functionWaitHandle.WaitOne();
await Task.Delay(1000);
await host.StopAsync();
}
List <RequestTelemetry> requests = _channel.Telemetries.OfType <RequestTelemetry>().ToList();
List <DependencyTelemetry> dependencies = _channel.Telemetries.OfType <DependencyTelemetry>().ToList();
List <TraceTelemetry> traces = _channel.Telemetries.OfType <TraceTelemetry>().ToList();
Assert.Single(requests);
// The call to Complete the message registers as a dependency
Assert.Single(dependencies);
Assert.Single(dependencies, d => d.Name == "Complete");
var completeDependency = dependencies.Single(d => d.Name == "Complete");
var request = requests.Single();
Assert.NotNull(request.Context.Operation.Id);
ValidateServiceBusRequest(request, true, _endpoint, _queueName, nameof(ServiceBusTrigger), null, null);
ValidateServiceBusDependency(
completeDependency,
_endpoint,
_queueName,
"Complete",
nameof(ServiceBusTrigger),
request.Context.Operation.Id,
request.Id,
LogCategories.CreateFunctionCategory(nameof(ServiceBusTrigger)));
// Make sure that the trigger traces are correlated
traces = _channel.Telemetries.OfType <TraceTelemetry>().Where(t => t.Context.Operation.Id == request.Context.Operation.Id).ToList();
Assert.Equal(4, traces.Count());
foreach (var trace in traces)
{
Assert.Equal(request.Context.Operation.Id, trace.Context.Operation.Id);
Assert.Equal(request.Id, trace.Context.Operation.ParentId);
}
}
public void Log_WritesMetric_IgnoresOtherLogs()
{
var metrics = new TestMetricsLogger();
var logger = new UserLogMetricsLogger(LogCategories.CreateFunctionCategory(_functionName), metrics, _scopeProvider);
// function executions will include this scope
using (CreateFunctionScope(logger))
{
logger.LogInformation("Message");
}
Assert.Empty(metrics.LoggedEvents);
}
public async Task LogFunctionCompleted_CallsLogger()
{
FunctionDescriptor descriptor = new FunctionDescriptor
{
ShortName = "Function.TestJob",
LogName = "TestJob"
};
FunctionCompletedMessage successMessage = new FunctionCompletedMessage
{
Function = descriptor,
FunctionInstanceId = Guid.NewGuid(),
HostInstanceId = Guid.NewGuid()
};
Exception ex = new Exception("Kaboom!");
FunctionCompletedMessage failureMessage = new FunctionCompletedMessage
{
Function = descriptor,
Failure = new FunctionFailure {
Exception = ex
},
FunctionInstanceId = new Guid("8d71c9e3-e809-4cfb-bb78-48ae25c7d26d"),
HostInstanceId = Guid.NewGuid()
};
await _instanceLogger.LogFunctionCompletedAsync(successMessage, CancellationToken.None);
await _instanceLogger.LogFunctionCompletedAsync(failureMessage, CancellationToken.None);
LogMessage[] logMessages = _provider.GetAllLogMessages().ToArray();
Assert.Equal(2, logMessages.Length);
string expectedCategory = LogCategories.CreateFunctionCategory("TestJob");
LogMessage logMessage = logMessages[0];
Assert.Equal(LogLevel.Information, logMessage.Level);
Assert.Equal(expectedCategory, logMessage.Category);
Assert.Equal($"Executed 'Function.TestJob' (Succeeded, Id={successMessage.FunctionInstanceId})",
logMessage.FormattedMessage);
Assert.Null(logMessage.State);
logMessage = logMessages[1];
Assert.Equal(LogLevel.Error, logMessage.Level);
Assert.Equal(expectedCategory, logMessage.Category);
Assert.Equal($"Executed 'Function.TestJob' (Failed, Id={failureMessage.FunctionInstanceId})", logMessage.FormattedMessage);
Assert.Same(ex, logMessage.Exception);
Assert.Null(logMessage.State);
}
public async Task LogFunctionStarted_CallsLogger()
{
Dictionary <string, string> triggerDetails = new Dictionary <string, string>()
{
{ "MessageId", Guid.NewGuid().ToString() },
{ "DequeueCount", "1" },
{ "InsertionTime", DateTime.Now.ToString() }
};
FunctionStartedMessage message = new FunctionStartedMessage
{
Function = new FunctionDescriptor
{
ShortName = "Function.TestJob",
LogName = "TestJob"
},
ReasonDetails = "TestReason",
HostInstanceId = Guid.NewGuid(),
FunctionInstanceId = Guid.NewGuid(),
TriggerDetails = triggerDetails
};
string expectedMessage = $"MessageId: {triggerDetails["MessageId"]}, " +
$"DequeueCount: {triggerDetails["DequeueCount"]}, " +
$"InsertionTime: {triggerDetails["InsertionTime"]}";
await _instanceLogger.LogFunctionStartedAsync(message, CancellationToken.None);
string expectedCategory = LogCategories.CreateFunctionCategory("TestJob");
LogMessage[] logMessages = _provider.GetAllLogMessages().ToArray();
Assert.Equal(2, logMessages.Length);
LogMessage invocationLogMessage = logMessages[0];
Assert.Equal(LogLevel.Information, invocationLogMessage.Level);
Assert.Equal(expectedCategory, invocationLogMessage.Category);
Assert.Null(invocationLogMessage.State);
Assert.Equal($"Executing 'Function.TestJob' (Reason='TestReason', Id={message.FunctionInstanceId})",
invocationLogMessage.FormattedMessage);
LogMessage triggerDetailsLogMessage = logMessages[1];
Assert.Equal(LogLevel.Information, triggerDetailsLogMessage.Level);
Assert.Equal(expectedCategory, triggerDetailsLogMessage.Category);
Assert.NotNull(triggerDetailsLogMessage.State);
Assert.Equal($"Trigger Details: {expectedMessage}",
triggerDetailsLogMessage.FormattedMessage);
}
public SystemLoggerTests()
{
_settingsManager = ScriptSettingsManager.Instance;
_subscriptionId = "e3235165-1600-4819-85f0-2ab362e909e4";
_hostInstanceId = Guid.NewGuid().ToString();
_settingsManager.SetSetting(EnvironmentSettingNames.AzureWebsiteOwnerName, $"{_subscriptionId}+westuswebspace");
_websiteName = "functionstest";
_settingsManager.SetSetting(EnvironmentSettingNames.AzureWebsiteName, _websiteName);
_mockEventGenerator = new Mock <IEventGenerator>(MockBehavior.Strict);
_category = LogCategories.CreateFunctionCategory(_functionName);
_logger = new SystemLogger(_hostInstanceId, _category, _mockEventGenerator.Object, _settingsManager);
}
internal static void LogExceptionReceivedEvent(ExceptionReceivedEventArgs e, string functionName, ILoggerFactory loggerFactory)
{
try
{
var ctxt = e.ExceptionReceivedContext;
var logger = loggerFactory?.CreateLogger(LogCategories.CreateFunctionCategory(functionName));
string message = $"Message processing error (Action={ctxt.Action}, ClientId={ctxt.ClientId}, EntityPath={ctxt.EntityPath}, Endpoint={ctxt.Endpoint})";
var logLevel = GetLogLevel(e.Exception);
logger?.Log(logLevel, 0, message, e.Exception, (s, ex) => message);
}
catch
{
// best effort logging
}
}
public Fetch(
IRkiWebService rkiWebService,
IStorageService <List <DistrictResponseModel>, DistrictStorageServiceOptions> districtStorageService,
IStorageService <List <FederalStateResponseModel>, FederalStateStorageServiceOptions> federalStateStorageService,
IStorageService <List <StateConfig>, StateConfigStorageServiceOptions> statesConfigStorageService,
IStorageService <List <AreaConfig>, AreaConfigStorageServiceOptions> areasConfigStorageService,
IStorageService <LegendConfig, LegendConfigStorageServiceOptions> legendConfigStorageService,
ILoggerFactory loggerFactory)
{
_rkiWebService = rkiWebService;
_districtStorageService = districtStorageService;
_federalStateStorageService = federalStateStorageService;
_statesConfigStorageService = statesConfigStorageService;
_areasConfigStorageService = areasConfigStorageService;
_legendConfigStorageService = legendConfigStorageService;
_logger = loggerFactory?.CreateLogger(LogCategories.CreateFunctionCategory(nameof(Fetch)))
?? throw new Exception($"Failed to inject [{nameof(ILoggerFactory)}]");
}
public SystemLoggerTests()
{
_subscriptionId = "e3235165-1600-4819-85f0-2ab362e909e4";
_hostInstanceId = Guid.NewGuid().ToString();
_websiteName = "functionstest";
_mockEventGenerator = new Mock <IEventGenerator>(MockBehavior.Strict);
var environment = new TestEnvironment(new Dictionary <string, string>
{
{ EnvironmentSettingNames.AzureWebsiteOwnerName, $"{_subscriptionId}+westuswebspace" },
{ EnvironmentSettingNames.AzureWebsiteName, _websiteName },
});
_inDiagnosticMode = false;
_category = LogCategories.CreateFunctionCategory(_functionName);
_debugStateProvider = new Mock <IDebugStateProvider>(MockBehavior.Strict);
_debugStateProvider.Setup(p => p.InDiagnosticMode).Returns(() => _inDiagnosticMode);
_logger = new SystemLogger(_hostInstanceId, _category, _mockEventGenerator.Object, environment, _debugStateProvider.Object, null);
}
private static void CheckAndEnableAppInsights(JobHostConfiguration config)
{
// If AppInsights is enabled, build up a LoggerFactory
string instrumentationKey = Environment.GetEnvironmentVariable("APPINSIGHTS_INSTRUMENTATIONKEY");
if (!string.IsNullOrEmpty(instrumentationKey))
{
var filter = new LogCategoryFilter();
filter.DefaultLevel = LogLevel.Debug;
filter.CategoryLevels[LogCategories.Results] = LogLevel.Debug;
filter.CategoryLevels[LogCategories.Aggregator] = LogLevel.Debug;
// Adjust the LogLevel for a specific Function.
filter.CategoryLevels[LogCategories.CreateFunctionCategory(nameof(Functions.ProcessWorkItem))] = LogLevel.Debug;
config.LoggerFactory = new LoggerFactory()
.AddApplicationInsights(instrumentationKey, filter.Filter)
.AddConsole(filter.Filter);
}
}
public void CreateLogger_UsesSameFileWriter_ForSameFile()
{
var rootPath = Path.GetTempPath();
using (var provider = new FunctionFileLoggerProvider(Guid.NewGuid().ToString(), rootPath, () => true, () => true))
{
provider.CreateLogger(LogCategories.CreateFunctionCategory("Test1"));
provider.CreateLogger(LogCategories.CreateFunctionUserCategory("Test1"));
provider.CreateLogger(LogCategories.CreateFunctionCategory("Test1"));
Assert.Single(provider.FileWriterCache);
// This creates a new entry.
provider.CreateLogger(LogCategories.CreateFunctionCategory("Test2"));
Assert.Equal(2, provider.FileWriterCache.Count);
Assert.NotSame(
provider.FileWriterCache[Path.Combine("Function", "Test1")],
provider.FileWriterCache[Path.Combine("Function", "Test2")]);
}
}
public SystemLoggerTests()
{
_subscriptionId = "e3235165-1600-4819-85f0-2ab362e909e4";
_hostInstanceId = Guid.NewGuid().ToString();
_websiteName = "functionstest";
_mockEventGenerator = new Mock <IEventGenerator>(MockBehavior.Strict);
var configBuilder = ScriptSettingsManager.CreateDefaultConfigurationBuilder()
.AddInMemoryCollection(new Dictionary <string, string>
{
{ EnvironmentSettingNames.AzureWebsiteOwnerName, $"{_subscriptionId}+westuswebspace" },
{ EnvironmentSettingNames.AzureWebsiteName, _websiteName },
});
var config = configBuilder.Build();
_settingsManager = new ScriptSettingsManager(config);
_category = LogCategories.CreateFunctionCategory(_functionName);
_logger = new SystemLogger(_hostInstanceId, _category, _mockEventGenerator.Object, _settingsManager);
}
public async Task Invoke_ExceptionThrown_DetailsLogged()
{
var context = new DefaultHttpContext();
var request = context.Request;
request.Method = "GET";
request.Scheme = "http";
request.Host = new HostString("functions.com", 80);
request.Path = "/api/functions/function1";
request.QueryString = new QueryString("?action=throw");
var arguments = new Dictionary <string, object>()
{
{ "req", request }
};
var ex = await Assert.ThrowsAsync <FunctionInvocationException>(async() =>
{
await Fixture.JobHost.CallAsync("Function1", arguments);
});
var response = request.HttpContext.Items[ScriptConstants.AzureFunctionsHttpResponseKey];
var errorLogs = Fixture.LoggerProvider.GetAllLogMessages().Where(p => p.Level == LogLevel.Error).ToArray();
Assert.Equal(2, errorLogs.Length);
// first log is the result
Assert.Equal(LogCategories.Results, errorLogs[1].Category);
var error = errorLogs[0];
var invocationException = (FunctionInvocationException)error.Exception;
Assert.Equal("Exception while executing function: Function1", invocationException.Message);
Assert.Equal("TestFunctions.Functions.Run", invocationException.MethodName);
Assert.Equal("Function1", error.Scope[ScopeKeys.FunctionName]);
Assert.Equal(LogCategories.CreateFunctionCategory("Function1"), error.Category);
}
public FunctionDescriptor(
string name,
IFunctionInvoker invoker,
FunctionMetadata metadata,
Collection <ParameterDescriptor> parameters,
Collection <CustomAttributeBuilder> attributes,
Collection <FunctionBinding> inputBindings,
Collection <FunctionBinding> outputBindings)
{
Name = name;
Invoker = invoker;
Parameters = parameters;
CustomAttributes = attributes;
Metadata = metadata;
InputBindings = inputBindings;
OutputBindings = outputBindings;
TriggerParameter = Parameters?.FirstOrDefault(p => p.IsTrigger);
TriggerBinding = InputBindings?.SingleOrDefault(p => p.Metadata.IsTrigger);
HttpTriggerAttribute = GetTriggerAttributeOrNull <HttpTriggerAttribute>();
LogCategory = LogCategories.CreateFunctionCategory(Name);
}