public static void Log(LogCategories category, LogEventID id, TraceEventType type, string message)
{
LogEntry entry = new LogEntry();
entry.EventId = (int)id;
entry.Categories.Add(category.ToString());
entry.Message = message;
entry.Severity = type;
Logger.Write(entry);
}
private static void RegisterLogCategory( LogCategories name, bool enabled )
{
if( enabled )
{
LogCategories |= name;
}
else
{
LogCategories &= ~name;
}
}
public void LogToOperations(Exception ex, LogCategories category, EventSeverity severity, string message, params object[] args)
{
try
{
logger.LogToOperations(ex, String.Format(message, args), GetEventId(category),
severity, category.ToLoggerString());
}
catch
{
//don't want the app to fail because of failures in logging
}
}
static Logger()
{
Categories = (LogCategories)monodroid_get_log_categories();
}
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(19, _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);
string expectedOperationId = request.Context.Operation.Id;
ValidateTrace(telemetries[0], "ApplicationInsightsLoggerOptions", "Microsoft.Azure.WebJobs.Hosting.OptionsLoggingService");
ValidateTrace(telemetries[1], "Error", expectedFunctionUserCategory, testName, invocationId, expectedOperationId, request.Id, expectedLogLevel: LogLevel.Error);
ValidateTrace(telemetries[2], "Executed", expectedFunctionCategory, testName, invocationId, expectedOperationId, request.Id, expectedLogLevel: LogLevel.Error);
ValidateTrace(telemetries[3], "Executing", expectedFunctionCategory, testName, invocationId, expectedOperationId, request.Id);
ValidateTrace(telemetries[4], "Found the following functions:\r\n", LogCategories.Startup);
ValidateTrace(telemetries[5], "FunctionResultAggregatorOptions", "Microsoft.Azure.WebJobs.Hosting.OptionsLoggingService");
ValidateTrace(telemetries[6], "Job host started", LogCategories.Startup);
ValidateTrace(telemetries[7], "Job host stopped", LogCategories.Startup);
ValidateTrace(telemetries[8], "Logger", expectedFunctionUserCategory, testName, invocationId, expectedOperationId, request.Id, hasCustomScope: true);
ValidateTrace(telemetries[9], "LoggerFilterOptions", "Microsoft.Azure.WebJobs.Hosting.OptionsLoggingService");
ValidateTrace(telemetries[10], "LoggerFilterOptions", "Microsoft.Azure.WebJobs.Hosting.OptionsLoggingService");
ValidateTrace(telemetries[11], "SingletonOptions", "Microsoft.Azure.WebJobs.Hosting.OptionsLoggingService");
ValidateTrace(telemetries[12], "Starting JobHost", "Microsoft.Azure.WebJobs.Hosting.JobHostService");
ValidateTrace(telemetries[13], "Stopping JobHost", "Microsoft.Azure.WebJobs.Hosting.JobHostService");
ValidateTrace(telemetries[14], "Trace", expectedFunctionUserCategory, testName, invocationId, expectedOperationId, 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, expectedOperationId, request.Id);
ValidateException(exceptions[1], expectedFunctionCategory, testName, expectedOperationId, request.Id);
ValidateException(exceptions[2], LogCategories.Results, testName, expectedOperationId, request.Id);
}
}
private static void ValidateMetric(MetricTelemetry telemetry, string expectedInvocationId, string expectedOperationName)
{
ValidateTelemetry(telemetry, expectedInvocationId, expectedOperationName, LogCategories.CreateFunctionUserCategory(expectedOperationName), SeverityLevel.Information);
Assert.Equal("TestMetric", telemetry.Name);
Assert.Equal(1234, telemetry.Sum);
Assert.Equal(50, telemetry.Count);
Assert.Equal(10.4, telemetry.Min);
Assert.Equal(23, telemetry.Max);
Assert.Equal("100", telemetry.Properties[$"{LogConstants.CustomPropertyPrefix}MyCustomMetricProperty"]);
ValidateSdkVersion(telemetry, "af_");
}
private async Task WaitForFunctionTrace(string functionName, string functionTrace)
{
// watch for the specific user log, then make sure the request telemetry has flushed, which
// indicates all logging is done for this function invocation
await TestHelpers.Await(() =>
{
bool done = false;
TraceTelemetry logTrace = _fixture.Channel.Telemetries.OfType <TraceTelemetry>().SingleOrDefault(p => p.Message.Contains(functionTrace) && p.Properties[LogConstants.CategoryNameKey] == LogCategories.CreateFunctionUserCategory(functionName));
if (logTrace != null)
{
string invocationId = logTrace.Properties[LogConstants.InvocationIdKey];
RequestTelemetry request = _fixture.Channel.Telemetries.OfType <RequestTelemetry>().SingleOrDefault(p => GetInvocationId(p) == invocationId);
done = request != null;
}
return(done);
},
userMessageCallback : _fixture.TestHost.GetLog);
}
/// <summary>
/// Log a message. Actually perform the logging message to the
/// appender specifified in the configuration file.
/// </summary>
/// <param name="category">The category to which this log statement belongs.</param>
/// <param name="s">A <see cref="Severity"/> level which is used to determine if
/// the message should be logged or ignored.</param>
/// <param name="msg">A string value describing the message.</param>
/// <param name="e">An exception that has occurred. If no exception has occurred, use <code>null</code>.</param>
internal static void LogMessage( LogCategories category, Severity s, string msg, Exception e )
{
// string platform = System.Environment.OSVersion.Platform.ToString();
// if( platform.StartsWith( "Win" ) )
// LogMessage( category, GetExternalCaller( e ), GetLevel( s ), msg, e );
// else
LogMessage( category, typeof(Check), GetLevel( s ), msg, e );
}
/// <summary>
/// Call this method to determine whether the passed category (or combination
/// of categories) is enabled.
/// </summary>
/// <param name="category">The category or categories to process.</param>
/// <returns>True if all of the specified categories are enabled.</returns>
public static bool IsLogEnabled( LogCategories category )
{
return (LogCategories & category) != 0;
}
public async Task ServiceBusDependenciesAndRequestAreTracked(string message, bool success)
{
using (var host = ConfigureHost())
{
await host.StartAsync();
await host.GetJobHost()
.CallAsync(typeof(ServiceBusRequestAndDependencyCollectionTests).GetMethod(nameof(ServiceBusOut)), new { input = message });
_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.Equal(2, requests.Count);
// One dependency for the 'Send' from ServiceBusOut
// One dependency for the 'Complete' call in ServiceBusTrigger
Assert.Equal(2, dependencies.Count);
Assert.Single(dependencies, d => d.Name == "Complete");
Assert.Single(dependencies, d => d.Name == "Send");
var sbOutDependency = dependencies.Single(d => d.Name == "Send");
var completeDependency = dependencies.Single(d => d.Name == "Complete");
var sbTriggerRequest = requests.Single(r => r.Context.Operation.Name == nameof(ServiceBusTrigger));
var manualCallRequest = requests.Single(r => r.Context.Operation.Name == nameof(ServiceBusOut));
string manualOperationId = manualCallRequest.Context.Operation.Id;
string triggerOperationId = sbTriggerRequest.Context.Operation.Id;
// currently ApplicationInsights supports 2 parallel correlation schemes:
// legacy and W3C, they both appear in telemetry. UX handles all differences in operation Ids.
// This will be resolved in next .NET SDK on Activity level
string dependencyLegacyId = sbOutDependency.Properties.Single(p => p.Key == "ai_legacyRequestId").Value;
string triggerCallLegacyRootId = sbTriggerRequest.Properties.Single(p => p.Key == "ai_legacyRootId").Value;
string manualCallLegacyRootId = manualCallRequest.Properties.Single(p => p.Key == "ai_legacyRootId").Value;
Assert.Equal(sbTriggerRequest.Context.Operation.ParentId, dependencyLegacyId);
Assert.Equal(manualOperationId, sbOutDependency.Context.Operation.Id);
Assert.Equal(manualCallLegacyRootId, triggerCallLegacyRootId);
ValidateServiceBusRequest(sbTriggerRequest, success, _endpoint, _queueName, nameof(ServiceBusTrigger), triggerOperationId, dependencyLegacyId);
ValidateServiceBusDependency(
sbOutDependency,
_endpoint,
_queueName,
"Send",
nameof(ServiceBusOut),
manualOperationId,
manualCallRequest.Id,
LogCategories.Bindings);
ValidateServiceBusDependency(
completeDependency,
_endpoint,
_queueName,
"Complete",
nameof(ServiceBusTrigger),
sbTriggerRequest.Context.Operation.Id,
sbTriggerRequest.Id,
LogCategories.CreateFunctionCategory(nameof(ServiceBusTrigger)));
var functionTraces = traces.Where(t => t.Context.Operation.Id == sbTriggerRequest.Context.Operation.Id).ToList();
Assert.Equal(success ? 4 : 6, functionTraces.Count);
foreach (var trace in functionTraces)
{
Assert.Equal(sbTriggerRequest.Context.Operation.Id, trace.Context.Operation.Id);
Assert.Equal(sbTriggerRequest.Id, trace.Context.Operation.ParentId);
}
}
private bool IsUserLogCategory(string categoryName)
{
return(LogCategories.IsFunctionUserCategory(categoryName) || categoryName.Equals(OutOfProcConstants.FunctionConsoleLogCategoryName, StringComparison.OrdinalIgnoreCase));
}
public SomeClass(ILoggerFactory loggerFactory) // Note that we inject ILoggerFactory
{
this._log = loggerFactory.CreateLogger(
LogCategories.CreateFunctionUserCategory(this.GetType().FullName)); // Must use CreateFunctionUserCategory to create the log category name otherwise the log gets filtered out.
}
public ApplicationInsightsLogger(TelemetryClient client, string categoryName)
{
_telemetryClient = client;
_categoryName = categoryName ?? DefaultCategoryName;
_isUserFunction = LogCategories.IsFunctionUserCategory(categoryName);
}
/// <summary>
/// A log method that adds the log information to <see cref="LogMessages"/>.
/// </summary>
/// <param name="category">The category of the log entry.</param>
/// <param name="level">The log level.</param>
/// <param name="scope">The logging scope that renders the log entry.</param>
/// <param name="message">The log message.</param>
protected void LogMethod(LogCategories category, LogLevel level, LogScope scope, string message)
{
scope.MustNotBeNull(nameof(scope));
this.LogMessages.Add($"{category}, {level}, {scope.Id}, {message}");
}
private int GetEventId(LogCategories category)
{
return 5000 + (int)category;
}
private void Log(LogCategories category, string kind, string name, Exception exception = null,
List <KeyValuePair <string, string> > payload = null, Severities severity = Severities.Normal)
{
if (string.IsNullOrEmpty(kind))
{
throw new ArgumentNullException(nameof(kind));
}
if (string.IsNullOrEmpty(name))
{
throw new ArgumentNullException(nameof(name));
}
try
{
using (LogContext.PushProperty("ApplicationId", _application.Id))
using (LogContext.PushProperty("ApplicationName", _application.Name))
using (LogContext.PushProperty("ApplicationType", _application.Type))
using (LogContext.PushProperty("ApplicationVersion", _application.Version))
using (LogContext.PushProperty("ActionId", _application.Id))
using (LogContext.PushProperty("ActionCategory", category))
using (LogContext.PushProperty("ActionKind", kind))
using (LogContext.PushProperty("ActionName", name))
using (LogContext.PushProperty("ActionSeverity", (int)severity))
using (LogContext.PushProperty("ActionPayload", payload))
{
switch (category)
{
case LogCategories.Information:
_logger.Information(name);
break;
case LogCategories.Debug:
_logger.Debug(name);
break;
case LogCategories.Notice:
_logger.Verbose(name);
break;
case LogCategories.Warning:
_logger.Warning(name);
break;
case LogCategories.Error:
_logger.Error(exception, name);
break;
case LogCategories.Fetal:
_logger.Fatal(name);
break;
case LogCategories.Audit:
_logger.Verbose(name);
break;
default:
throw new ArgumentOutOfRangeException();
}
}
}
catch
{
// ignored
}
}
/// <summary>
/// Reset all counters to 0.
/// </summary>
public static void Reset( LogCategories category )
{
lock( statsLock )
{
if( (category & LogCategories.Cache) != 0 )
{
cacheHits = 0;
cacheMisses = 0;
skippedQueries = 0;
uniqingCount = 0;
}
}
}
public async Task GetHostSecrets_WhenTooManyBackups_ThrowsException()
{
using (var directory = new TempDirectory())
{
string functionName = "testfunction";
string expectedTraceMessage = string.Format(Resources.ErrorTooManySecretBackups, ScriptConstants.MaximumSecretBackupCount, functionName,
string.Format(Resources.ErrorSameSecrets, "test0,test1"));
string functionSecretsJson =
@"{
'keys': [
{
'name': 'Key1',
'value': 'FunctionValue1',
'encrypted': true
},
{
'name': 'Key2',
'value': 'FunctionValue2',
'encrypted': false
}
]
}";
ILoggerFactory loggerFactory = new LoggerFactory();
TestLoggerProvider loggerProvider = new TestLoggerProvider();
loggerFactory.AddProvider(loggerProvider);
var logger = loggerFactory.CreateLogger(LogCategories.CreateFunctionCategory("Test1"));
IDictionary <string, string> functionSecrets;
ISecretsRepository repository = new FileSystemSecretsRepository(directory.Path);
using (var secretManager = new SecretManager(repository, logger, new TestMetricsLogger()))
{
InvalidOperationException ioe = null;
try
{
for (int i = 0; i < ScriptConstants.MaximumSecretBackupCount + 20; i++)
{
File.WriteAllText(Path.Combine(directory.Path, functionName + ".json"), functionSecretsJson);
// If we haven't hit the exception yet, pause to ensure the file contents are being flushed.
if (i >= ScriptConstants.MaximumSecretBackupCount)
{
await Task.Delay(500);
}
string hostName = "test" + (i % 2).ToString();
using (new TestScopedEnvironmentVariable(EnvironmentSettingNames.AzureWebsiteHostName, hostName))
{
functionSecrets = await secretManager.GetFunctionSecretsAsync(functionName);
}
}
}
catch (InvalidOperationException ex)
{
ioe = ex;
}
}
Assert.True(Directory.GetFiles(directory.Path, $"{functionName}.{ScriptConstants.Snapshot}*").Length >= ScriptConstants.MaximumSecretBackupCount);
Assert.True(loggerProvider.GetAllLogMessages().Any(
t => t.Level == LogLevel.Debug && t.FormattedMessage.IndexOf(expectedTraceMessage, StringComparison.OrdinalIgnoreCase) > -1),
"Expected Trace message not found");
}
}
/// <summary>
/// Log a message. The specified <see cref="Severity"/> level is compared against
/// the current logging levels to determine if the message is logged or ignored.
/// </summary>
/// <param name="category">The category to which this log statement belongs.</param>
/// <param name="s">The severity level of the logging message.</param>
/// <param name="msg">The message to log.</param>
public static void Log( LogCategories category, Severity s, string msg )
{
LogMessage( category, s, msg, null );
}
async Task Process()
{
var logger = loggerFactory.CreateLogger(LogCategories.CreateTriggerCategory("BatchedQueue"));
var ct = tokenSource.Token;
while (tokenSource.IsCancellationRequested == false)
{
try
{
IEnumerable <CloudQueueMessage>[] results = null;
try
{
for (var i = 0; i < gets.Length; i++)
{
gets[i] = queue.GetMessagesAsync(CloudQueueMessage.MaxNumberOfMessagesToPeek,
VisibilityTimeout, null, null, ct);
}
results = await Task.WhenAll(gets).ConfigureAwait(false);
}
catch (StorageException ex)
{
if (ex.IsNotFoundQueueNotFound() || ex.IsConflictQueueBeingDeletedOrDisabled() || ex.IsServerSideError())
{
await Delay(false, ct).ConfigureAwait(false);
continue;
}
throw;
}
var messages = results.SelectMany(msgs => msgs).ToArray();
if (messages.Length > 0)
{
var batch = new MessageBatch(messages);
var data = new TriggeredFunctionData {
TriggerValue = batch
};
var result = await executor.TryExecuteAsync(data, ct).ConfigureAwait(false);
if (result.Succeeded)
{
await batch.Complete(queue, poisonQueue, maxRetries, visibilityTimeout, ct);
await Delay(true, ct).ConfigureAwait(false);
}
else
{
await batch.RetryAll(queue, poisonQueue, maxRetries, visibilityTimeout, ct);
await Delay(false, ct).ConfigureAwait(false);
}
}
else
{
logger.LogDebug("No messages received");
await Delay(false, ct).ConfigureAwait(false);
}
}
catch (TaskCanceledException)
{
}
}
}
/// <summary>
/// Log an error message. Include the exception that has occurred
/// in the text of the error message.
/// </summary>
/// <param name="category">The category to which this log statement belongs.</param>
/// <param name="e">The exception to be logged.</param>
public static void LogError( LogCategories category, Exception e )
{
Log( category, Severity.Error, "", e );
}
public void ILogger_Succeeds()
{
string functionName = nameof(ILoggerFunctions.ILogger);
using (JobHost host = new JobHost(CreateConfig()))
{
var method = typeof(ILoggerFunctions).GetMethod(functionName);
host.Call(method);
}
// Six loggers are the startup, singleton, results, function and function.user
Assert.Equal(5, _loggerProvider.CreatedLoggers.Count);
var functionLogger = _loggerProvider.CreatedLoggers.Where(l => l.Category == LogCategories.CreateFunctionUserCategory(functionName)).Single();
var resultsLogger = _loggerProvider.CreatedLoggers.Where(l => l.Category == LogCategories.Results).Single();
Assert.Equal(2, functionLogger.LogMessages.Count);
var infoMessage = functionLogger.LogMessages[0];
var errorMessage = functionLogger.LogMessages[1];
// These get the {OriginalFormat} property as well as the 2 from structured log properties
Assert.Equal(3, infoMessage.State.Count());
Assert.Equal(3, errorMessage.State.Count());
Assert.Equal(1, resultsLogger.LogMessages.Count);
// TODO: beef these verifications up
}
public static bool IsLoggingEnabled( LogCategories categories, bool matchAll )
{
if( matchAll )
{
return (enabledLogCategories & categories) == categories;
}
else
{
return (enabledLogCategories & categories) != 0;
}
}
public void TraceWriter_ForwardsTo_ILogger()
{
string functionName = nameof(ILoggerFunctions.TraceWriterWithILoggerFactory);
using (JobHost host = new JobHost(CreateConfig()))
{
var method = typeof(ILoggerFunctions).GetMethod(functionName);
host.Call(method);
}
// Five loggers are the startup, singleton, results, function and function.user
Assert.Equal(5, _loggerProvider.CreatedLoggers.Count);
var functionLogger = _loggerProvider.CreatedLoggers.Where(l => l.Category == LogCategories.CreateFunctionUserCategory(functionName)).Single();
Assert.Equal(2, functionLogger.LogMessages.Count);
var infoMessage = functionLogger.LogMessages[0];
var errorMessage = functionLogger.LogMessages[1];
// These get the {OriginalFormat} only
Assert.Single(infoMessage.State);
Assert.Single(errorMessage.State);
//TODO: beef these verifications up
}
public void Validate_BeginScope()
{
var hostBuilder = new HostBuilder()
.ConfigureAppConfiguration(c =>
{
c.AddInMemoryCollection(new Dictionary <string, string>
{
{ "APPINSIGHTS_INSTRUMENTATIONKEY", "some_key" },
});
})
.ConfigureDefaultTestWebScriptHost(b =>
{
b.Services.AddSingleton <ITelemetryChannel>(_fixture.Channel);
});
using (var host = hostBuilder.Build())
{
ILoggerFactory loggerFactory = host.Services.GetService <ILoggerFactory>();
// Create a logger and try out the configured factory. We need to pretend that it is coming from a
// function, so set the function name and the category appropriately.
ILogger logger = loggerFactory.CreateLogger(LogCategories.CreateFunctionCategory("Test"));
string customGuid = Guid.NewGuid().ToString();
using (logger.BeginScope(new Dictionary <string, object>
{
[ScriptConstants.LogPropertyFunctionNameKey] = "Test",
["parentId"] = customGuid // use a parent id so we can pull all our traces out
}))
{
// Now log as if from within a function.
// Test that both dictionaries and structured logs work as state
// and that nesting works as expected.
using (logger.BeginScope("{customKey1}", "customValue1"))
{
logger.LogInformation("1");
using (logger.BeginScope(new Dictionary <string, object>
{
["customKey2"] = "customValue2"
}))
{
logger.LogInformation("2");
}
logger.LogInformation("3");
}
using (logger.BeginScope("should not throw"))
{
logger.LogInformation("4");
}
}
TraceTelemetry[] traces = _fixture.Channel.Telemetries.OfType <TraceTelemetry>()
.Where(t => t.Properties.TryGetValue("prop__parentId", out string value) && value == customGuid)
.OrderBy(t => t.Message).ToArray();
Assert.Equal(4, traces.Length);
// Every telemetry will have {originalFormat}, Category, Level, but we validate those elsewhere.
// We're only interested in the custom properties.
Assert.Equal("1", traces[0].Message);
Assert.Equal(7, traces[0].Properties.Count);
Assert.Equal("customValue1", traces[0].Properties["prop__customKey1"]);
Assert.Equal("2", traces[1].Message);
Assert.Equal(8, traces[1].Properties.Count);
Assert.Equal("customValue1", traces[1].Properties["prop__customKey1"]);
Assert.Equal("customValue2", traces[1].Properties["prop__customKey2"]);
Assert.Equal("3", traces[2].Message);
Assert.Equal(7, traces[2].Properties.Count);
Assert.Equal("customValue1", traces[2].Properties["prop__customKey1"]);
Assert.Equal("4", traces[3].Message);
Assert.Equal(6, traces[3].Properties.Count);
}
}
/// <summary>
/// Initializes a new instance of the <see cref="MqttTriggerAttribute"/>.
/// </summary>
/// <param name="connectionFactory">the connection factory.</param>
/// <param name="loggerFactory">The loggerFactory.</param>
internal MqttTriggerAttributeBindingProvider(IMqttConnectionFactory connectionFactory, ILoggerFactory loggerFactory)
{
_connectionFactory = connectionFactory;
_logger = loggerFactory.CreateLogger(LogCategories.CreateTriggerCategory("Mqtt"));
}
public void TimerTrigger()
{
var logs = Fixture.Host.GetLogMessages(LogCategories.CreateFunctionUserCategory("TimerTrigger"));
Assert.Contains(logs, log => log.FormattedMessage.Contains("Timer function ran!"));
}
private void AddLogging(IServiceCollection services)
{
services.AddLogging();
services.AddScoped <ILogger>(provider =>
provider.GetService <ILoggerFactory>().CreateLogger(LogCategories.CreateFunctionUserCategory("EntitySquasher")));
services.AddScoped <IHttpSpiExecutionContextManager, HttpSpiExecutionContextManager>();
services.AddScoped <ISpiExecutionContextManager>((provider) =>
(ISpiExecutionContextManager)provider.GetService(typeof(IHttpSpiExecutionContextManager)));
services.AddScoped <ILoggerWrapper, LoggerWrapper>();
}
internal FunctionInvokerBase(ScriptHost host, FunctionMetadata functionMetadata, ILoggerFactory loggerFactory, string logDirName = null)
{
Host = host;
Metadata = functionMetadata;
FunctionLogger = loggerFactory.CreateLogger(LogCategories.CreateFunctionCategory(functionMetadata.Name));
}
private async Task <IActionResult> GetResultAsync(HttpContext context, IFunctionExecutionFeature functionExecution)
{
if (functionExecution.Descriptor == null)
{
return(new NotFoundResult());
}
if (context.Request.IsColdStart())
{
// 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.Request.HttpContext.Items.Add(ScriptConstants.AzureFunctionsColdStartKey, sw);
}
// Add route data to request info
// TODO: Keeping this here for now as other code depend on this property, but this can be done in the HTTP binding.
var routingFeature = context.Features.Get <IRoutingFeature>();
context.Items.Add(HttpExtensionConstants.AzureWebJobsHttpRouteDataKey, new Dictionary <string, object>(routingFeature.RouteData.Values));
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))
{
// TODO: Flow cancellation token from caller
await functionExecution.ExecuteAsync(context.Request, CancellationToken.None);
}
}
if (context.Items.TryGetValue(ScriptConstants.AzureFunctionsHttpResponseKey, out object result) && result is IActionResult actionResult)
{
return(actionResult);
}
return(new OkResult());
}
static public void Process(string s1, string s2, LogLevel ll, LogCategories lc)
{
NinjaTrader.Cbi.Log.Process(typeof(NinjaTrader.Custom.Resource), "Zweistein", new object[] { s1, s2 }, ll, lc);
}
public void CreateLogger_ReturnsSystemLogger_ForNonUserCategories()
{
Assert.IsType <SystemLogger>(_provider.CreateLogger(LogCategories.CreateFunctionCategory("TestFunction")));
Assert.IsType <SystemLogger>(_provider.CreateLogger(ScriptConstants.LogCategoryHostGeneral));
Assert.IsType <SystemLogger>(_provider.CreateLogger("NotAFunction.TestFunction.User"));
}
private void AddLogging(IServiceCollection services)
{
services.AddLogging();
services.AddScoped <ILogger>(provider =>
provider.GetService <ILoggerFactory>().CreateLogger(LogCategories.CreateFunctionUserCategory("GiasAdapter")));
services.AddScoped <ILoggerWrapper, LoggerWrapper>();
}
public void CreateLogger_ReturnsNullLogger_ForUserCategory()
{
Assert.IsType <NullLogger>(_provider.CreateLogger(LogCategories.CreateFunctionUserCategory("TestFunction")));
}
/// <summary>
/// Emit current statistics for the specified categories.
/// </summary>
/// <param name="category">The categories to emit statistics for.</param>
public static void LogStatistics( LogCategories category )
{
if( Check.IsLogEnabled( LogCategories.Cache ) )
{
lock( statsLock )
{
long accessCount = cacheHits + cacheMisses;
double hitRatio = accessCount > 0 ? (double) cacheHits / accessCount : 0;
// format output using the current culture (if possible; cannot use neutral cultures)
string ratio;
if( ! CultureInfo.CurrentCulture.IsNeutralCulture )
{
NumberFormatInfo nfi = CultureInfo.CurrentCulture.NumberFormat;
ratio = String.Format( nfi, "{0:p}", hitRatio );
}
else
{
ratio = String.Format( "{0:p}", hitRatio );
}
Check.LogInfo( LogCategories.Cache, "Cache size/hits/misses: {0}/{1}/{2} ({3} hit ratio)",
CacheSize, cacheHits, cacheMisses, ratio );
Check.LogInfo( LogCategories.Cache, "Cache (objects uniqued): {0}", uniqingCount );
Check.LogInfo( LogCategories.Cache, "Cache (queries skipped): {0}", skippedQueries );
}
}
}
public async Task HttpTrigger_CSharp_CustomRoute_ReturnsExpectedResponse()
{
string functionName = "HttpTrigger-CSharp-CustomRoute";
string functionKey = await _fixture.Host.GetFunctionSecretAsync(functionName);
string uri = $"api/csharp/products/electronics/123?code={functionKey}";
HttpRequestMessage request = new HttpRequestMessage(HttpMethod.Get, uri);
HttpResponseMessage response = await _fixture.Host.HttpClient.SendAsync(request);
Assert.Equal(HttpStatusCode.OK, response.StatusCode);
string json = await response.Content.ReadAsStringAsync();
var product = JObject.Parse(json);
Assert.Equal("electronics", (string)product["category"]);
Assert.Equal(123, (int?)product["id"]);
// test optional id parameter
uri = $"api/csharp/products/electronics?code={functionKey}";
request = new HttpRequestMessage(HttpMethod.Get, uri);
response = await _fixture.Host.HttpClient.SendAsync(request);
Assert.Equal(HttpStatusCode.OK, response.StatusCode);
json = await response.Content.ReadAsStringAsync();
product = JObject.Parse(json);
Assert.Equal("electronics", (string)product["category"]);
Assert.Null((int?)product["id"]);
// test optional category parameter
uri = $"api/csharp/products?code={functionKey}";
request = new HttpRequestMessage(HttpMethod.Get, uri);
response = await _fixture.Host.HttpClient.SendAsync(request);
Assert.Equal(HttpStatusCode.OK, response.StatusCode);
json = await response.Content.ReadAsStringAsync();
product = JObject.Parse(json);
Assert.Null((string)product["category"]);
Assert.Null((int?)product["id"]);
// test a constraint violation (invalid id)
uri = $"api/csharp/products/electronics/1x3?code={functionKey}";
request = new HttpRequestMessage(HttpMethod.Get, uri);
response = await _fixture.Host.HttpClient.SendAsync(request);
Assert.Equal(HttpStatusCode.NotFound, response.StatusCode);
// test a constraint violation (invalid category)
uri = $"api/csharp/products/999/123?code={functionKey}";
request = new HttpRequestMessage(HttpMethod.Get, uri);
response = await _fixture.Host.HttpClient.SendAsync(request);
Assert.Equal(HttpStatusCode.NotFound, response.StatusCode);
// verify route parameters were part of binding data
var logs = _fixture.Host.GetLogMessages(LogCategories.CreateFunctionUserCategory(functionName));
Assert.True(logs.Any(p => p.FormattedMessage.Contains("Parameters: category=electronics id=123")));
Assert.True(logs.Any(p => p.FormattedMessage.Contains("ProductInfo: Category=electronics Id=123")));
}
/// <summary>
/// Log a message. The current logging level is used to determine
/// if the message is appended to the configured appender
/// or if it is ignored.
/// </summary>
/// <param name="category">The category to which this log statement belongs.</param>
/// <param name="s">The severity of the logging message.</param>
/// <param name="errorMsg">A concise description of the problem encountered.</param>
/// <param name="args">Variable values that are to be captured with the logging statement.</param>
public static void Log( LogCategories category, Severity s, string errorMsg, params object[] args )
{
if( args != null && args.Length > 0 )
{
LogMessage( category, s, Format( s + ": " + errorMsg, args ), null );
}
else
{
LogMessage( category, s, errorMsg, null );
}
}
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);
}
/// <summary>
/// Log a message. The specified <see cref="Severity"/> level is compared against
/// the current logging levels to determine if the message is logged or ignored.
/// </summary>
/// <param name="category">The category to which this log statement belongs.</param>
/// <param name="s">The severity level of the logging message.</param>
/// <param name="msg">The message to log.</param>
/// <param name="e">An exception to associate with the error being logged.</param>
public static void Log( LogCategories category, Severity s, string msg, Exception e )
{
LogMessage( category, s, msg, e );
}
public MqttConnectionFactory(ILoggerFactory loggerFactory, IManagedMqttClientFactory mqttFactory, INameResolver nameResolver)
{
_mqttFactory = mqttFactory;
_nameResolver = nameResolver;
_logger = loggerFactory.CreateLogger(LogCategories.CreateTriggerCategory("Mqtt"));
}
/// <summary>
/// Log an error message. The error message is delegated to the log4net
/// appender(s) in the app config file.
/// </summary>
/// <param name="category">The category to which this log statement belongs.</param>
/// <param name="errorMsg">A description of what has occurred.</param>
/// <param name="args">Variable values that were present at
/// the time the error occurred.</param>
public static void LogError( LogCategories category, string errorMsg, params object[] args )
{
Log( category, Severity.Error, errorMsg, args );
}
public async Task HttpTrigger_CustomRoute_Get_ReturnsExpectedResponse()
{
var id = "4e2796ae-b865-4071-8a20-2a15cbaf856c";
string functionKey = await _fixture.Host.GetFunctionSecretAsync("HttpTrigger-CustomRoute-Get");
string uri = $"api/node/products/electronics/{id}?code={functionKey}";
HttpRequestMessage request = new HttpRequestMessage(HttpMethod.Get, uri);
request.Headers.Accept.Add(new MediaTypeWithQualityHeaderValue("text/plain"));
HttpResponseMessage response = await _fixture.Host.HttpClient.SendAsync(request);
Assert.Equal(HttpStatusCode.OK, response.StatusCode);
string json = await response.Content.ReadAsStringAsync();
JArray products = JArray.Parse(json);
Assert.Equal(1, products.Count);
var product = products[0];
Assert.Equal("electronics", (string)product["category"]);
Assert.Equal(id, (string)product["id"]);
// test optional route param (id)
uri = $"api/node/products/electronics?code={functionKey}";
request = new HttpRequestMessage(HttpMethod.Get, uri);
request.Headers.Accept.Add(new MediaTypeWithQualityHeaderValue("text/plain"));
response = await _fixture.Host.HttpClient.SendAsync(request);
Assert.Equal(HttpStatusCode.OK, response.StatusCode);
json = await response.Content.ReadAsStringAsync();
products = JArray.Parse(json);
Assert.Equal(2, products.Count);
var logs = _fixture.Host.GetScriptHostLogMessages(LogCategories.CreateFunctionUserCategory("HttpTrigger-CustomRoute-Get"));
var log = logs.Single(p => p.FormattedMessage.Contains($"category: electronics id: <empty>"));
_fixture.Host.ClearLogMessages();
// test optional route param (category)
uri = $"api/node/products?code={functionKey}";
request = new HttpRequestMessage(HttpMethod.Get, uri);
request.Headers.Accept.Add(new MediaTypeWithQualityHeaderValue("text/plain"));
response = await _fixture.Host.HttpClient.SendAsync(request);
Assert.Equal(HttpStatusCode.OK, response.StatusCode);
json = await response.Content.ReadAsStringAsync();
products = JArray.Parse(json);
Assert.Equal(3, products.Count);
logs = _fixture.Host.GetScriptHostLogMessages(LogCategories.CreateFunctionUserCategory("HttpTrigger-CustomRoute-Get"));
log = logs.Single(p => p.FormattedMessage.Contains($"category: <empty> id: <empty>"));
// test a constraint violation (invalid id)
uri = $"api/node/products/electronics/notaguid?code={functionKey}";
request = new HttpRequestMessage(HttpMethod.Get, uri);
request.Headers.Accept.Add(new MediaTypeWithQualityHeaderValue("text/plain"));
response = await _fixture.Host.HttpClient.SendAsync(request);
Assert.Equal(HttpStatusCode.NotFound, response.StatusCode);
// test a constraint violation (invalid category)
uri = $"api/node/products/999/{id}?code={functionKey}";
request = new HttpRequestMessage(HttpMethod.Get, uri);
request.Headers.Accept.Add(new MediaTypeWithQualityHeaderValue("text/plain"));
response = await _fixture.Host.HttpClient.SendAsync(request);
Assert.Equal(HttpStatusCode.NotFound, response.StatusCode);
}
private static void LogMessage( LogCategories category, Type originator, Level level, string msg, Exception e )
{
if( IsLogEnabled( category ) )
{
// If the standard .NET configuration file has syntax errors, or contains
// unmatched section declarations and corresponding XML block, .NET throws an
// error when log4net first accesses the file. These errors are handled by
// log4net but are visible inside a debugger (you may ignore them).
ILog log = GetLogger( originator );
if( log != null )
{
log.Logger.Log( originator, level, msg, e );
}
}
}
public ServiceProviderHolder(IContainer rootAutofacContainer, IOptions <ExecutionContextOptions> executionContextOptions, ILoggerFactory loggerFactory)
{
_rootAutofacContainer = rootAutofacContainer;
_executionContextOptions = executionContextOptions;
_logger = loggerFactory.CreateLogger(LogCategories.CreateFunctionUserCategory("Startup"));
}
private async Task <string> ValidateEndToEndTestAsync(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)
{
// We see two exceptions:
// - 1 with the RequestTelemetry
// - 1 with the TraceTelemetry that "Function Executed (Failure...")
ExceptionTelemetry[] exceptions = _fixture.Channel.Telemetries
.OfType <ExceptionTelemetry>()
.Where(t => GetInvocationId(t) == invocationId)
.OrderBy(t => t.Properties[LogConstants.CategoryNameKey])
.ToArray();
Assert.Equal(2, exceptions.Length);
ValidateException(exceptions[0], invocationId, functionName, LogCategories.CreateFunctionCategory(functionName));
ValidateException(exceptions[1], invocationId, functionName, LogCategories.Results);
}
// The Request is written separately by App Insights so we need to wait for it
RequestTelemetry requestTelemetry = null;
await TestHelpers.Await(() =>
{
requestTelemetry = _fixture.Channel.Telemetries
.OfType <RequestTelemetry>()
.Where(t => GetInvocationId(t) == invocationId)
.SingleOrDefault();
return(requestTelemetry != null);
});
ValidateRequest(requestTelemetry, invocationId, functionName, "req", functionSuccess);
// Make sure all the operationIds match
var operationId = requestTelemetry.Context.Operation.Id;
Assert.Equal(operationId, traces[0].Context.Operation.Id);
Assert.Equal(operationId, traces[1].Context.Operation.Id);
return(invocationId);
}
public static void SetLogStatus( LogCategories name, bool enabled )
{
if( enabled )
{
enabledLogCategories |= name;
}
else
{
enabledLogCategories &= ~name;
}
}
