public virtual IEnumerable <ILoggerProvider> CreateLoggerProviders(string hostInstanceId, ScriptHostConfiguration scriptConfig, ScriptSettingsManager settingsManager,
Func <bool> isFileLoggingEnabled, Func <bool> isPrimary)
{
IList <ILoggerProvider> providers = new List <ILoggerProvider>();
IMetricsLogger metricsLogger = scriptConfig.HostConfig.GetService <IMetricsLogger>();
// Automatically register App Insights if the key is present
if (!string.IsNullOrEmpty(settingsManager?.ApplicationInsightsInstrumentationKey))
{
metricsLogger?.LogEvent(MetricEventNames.ApplicationInsightsEnabled);
ITelemetryClientFactory clientFactory = scriptConfig.HostConfig.GetService <ITelemetryClientFactory>() ??
new ScriptTelemetryClientFactory(settingsManager.ApplicationInsightsInstrumentationKey, scriptConfig.ApplicationInsightsSamplingSettings, scriptConfig.LogFilter.Filter);
providers.Add(new ApplicationInsightsLoggerProvider(clientFactory));
}
else
{
metricsLogger?.LogEvent(MetricEventNames.ApplicationInsightsDisabled);
}
providers.Add(new FunctionFileLoggerProvider(hostInstanceId, scriptConfig.RootLogPath, isFileLoggingEnabled, isPrimary));
providers.Add(new HostFileLoggerProvider(hostInstanceId, scriptConfig.RootLogPath, isFileLoggingEnabled));
if (settingsManager.Configuration.GetSection("host:logger:consoleLoggingMode").Value == "always")
{
providers.Add(new ConsoleLoggerProvider(scriptConfig.LogFilter.Filter, includeScopes: true));
}
return(providers);
}
/// <summary>
/// Performs all required initialization on the host.
/// Must be called before the host is started.
/// </summary>
public async Task InitializeAsync(CancellationToken cancellationToken = default)
{
_stopwatch = ValueStopwatch.StartNew();
using (_metricsLogger.LatencyEvent(MetricEventNames.HostStartupLatency))
{
PreInitialize();
HostInitializing?.Invoke(this, EventArgs.Empty);
_workerRuntime = _workerRuntime ?? _environment.GetEnvironmentVariable(EnvironmentSettingNames.FunctionWorkerRuntime);
// get worker config information and check to see if worker should index or not
var workerConfigs = _languageWorkerOptions.Value.WorkerConfigs;
bool workerIndexing = Utility.CanWorkerIndex(workerConfigs, _environment);
// Generate Functions
IEnumerable <FunctionMetadata> functionMetadataList = GetFunctionsMetadata(workerIndexing);
if (!_environment.IsPlaceholderModeEnabled())
{
string runtimeStack = _workerRuntime;
if (!string.IsNullOrEmpty(runtimeStack))
{
// Appending the runtime version is currently only enabled for linux consumption. This will be eventually enabled for
// Windows Consumption as well.
string runtimeVersion = _environment.GetEnvironmentVariable(RpcWorkerConstants.FunctionWorkerRuntimeVersionSettingName);
if (!string.IsNullOrEmpty(runtimeVersion))
{
runtimeStack = string.Concat(runtimeStack, "-", runtimeVersion);
}
}
_metricsLogger.LogEvent(string.Format(MetricEventNames.HostStartupRuntimeLanguage, Sanitizer.Sanitize(runtimeStack)));
Utility.LogAutorestGeneratedJsonIfExists(ScriptOptions.RootScriptPath, _logger);
}
IsFunctionDataCacheEnabled = GetIsFunctionDataCacheEnabled();
await InitializeFunctionDescriptorsAsync(functionMetadataList, cancellationToken);
if (!workerIndexing)
{
// Initialize worker function invocation dispatcher only for valid functions after creating function descriptors
// Dispatcher not needed for codeless function.
// Disptacher needed for non-dotnet codeless functions
var filteredFunctionMetadata = functionMetadataList.Where(m => !Utility.IsCodelessDotNetLanguageFunction(m));
await _functionDispatcher.InitializeAsync(Utility.GetValidFunctions(filteredFunctionMetadata, Functions), cancellationToken);
}
GenerateFunctions();
ScheduleFileSystemCleanup();
}
}
public void Decorator_LogEventWithMetricEvent_Called()
{
Guid invocationId = Guid.NewGuid();
FunctionMetadata meta = new FunctionMetadata();
FunctionStartedEvent evt = new FunctionStartedEvent(invocationId, meta);
_metricsLogger.Setup(a => a.LogEvent(evt));
_metricsLoggerDecorator.LogEvent(evt);
_metricsLogger.Verify(a => a.LogEvent(evt), Times.Once());
_metricsLogger.Reset();
}
internal static void LogInvocationMetrics(IMetricsLogger metrics, Collection <BindingMetadata> bindings)
{
metrics.LogEvent(MetricEventNames.FunctionInvoke);
// log events for each of the binding types used
foreach (var binding in bindings)
{
string eventName = binding.IsTrigger ?
string.Format(MetricEventNames.FunctionBindingTypeFormat, binding.Type) :
string.Format(MetricEventNames.FunctionBindingTypeDirectionFormat, binding.Type, binding.Direction);
metrics.LogEvent(eventName);
}
}
/// <summary>
/// Perform any early initialization operations.
/// </summary>
private void PreInitialize()
{
// Log whether App Insights is enabled
if (!string.IsNullOrEmpty(_settingsManager.ApplicationInsightsInstrumentationKey))
{
_metricsLogger.LogEvent(MetricEventNames.ApplicationInsightsEnabled);
}
else
{
_metricsLogger.LogEvent(MetricEventNames.ApplicationInsightsDisabled);
}
InitializeFileSystem();
}
/// <summary>
/// Performs all required initialization on the host.
/// Must be called before the host is started.
/// </summary>
public async Task InitializeAsync(CancellationToken cancellationToken = default)
{
_stopwatch.Start();
using (_metricsLogger.LatencyEvent(MetricEventNames.HostStartupLatency))
{
PreInitialize();
HostInitializing?.Invoke(this, EventArgs.Empty);
// Generate Functions
IEnumerable <FunctionMetadata> functionMetadataList = GetFunctionsMetadata();
_workerRuntime = _workerRuntime ?? Utility.GetWorkerRuntime(functionMetadataList);
if (!_environment.IsPlaceholderModeEnabled())
{
string runtimeStack = _workerRuntime;
if (!string.IsNullOrEmpty(runtimeStack))
{
// Appending the runtime version is currently only enabled for linux consumption. This will be eventually enabled for
// Windows Consumption as well.
string runtimeVersion = _environment.GetEnvironmentVariable(RpcWorkerConstants.FunctionWorkerRuntimeVersionSettingName);
if (!string.IsNullOrEmpty(runtimeVersion))
{
runtimeStack = string.Concat(runtimeStack, "-", runtimeVersion);
}
}
_metricsLogger.LogEvent(string.Format(MetricEventNames.HostStartupRuntimeLanguage, runtimeStack));
Utility.LogAutorestGeneratedJsonIfExists(ScriptOptions.RootScriptPath, _logger);
}
var directTypes = GetDirectTypes(functionMetadataList);
await InitializeFunctionDescriptorsAsync(functionMetadataList, cancellationToken);
// Initialize worker function invocation dispatcher only for valid functions after creating function descriptors
// Dispatcher not needed for non-proxy codeless function.
// Disptacher needed for non-dotnet codeless functions
var filteredFunctionMetadata = functionMetadataList.Where(m => m.IsProxy() || !Utility.IsCodelessDotNetLanguageFunction(m));
await _functionDispatcher.InitializeAsync(Utility.GetValidFunctions(filteredFunctionMetadata, Functions), cancellationToken);
GenerateFunctions(directTypes);
ScheduleFileSystemCleanup();
}
}
// Called on success and failure
public void End(bool success)
{
startedEvent.Success = success;
string eventName = success ? MetricEventNames.FunctionInvokeSucceeded : MetricEventNames.FunctionInvokeFailed;
dynamic data = new JObject();
data.Language = startedEvent.FunctionMetadata.Language;
data.FunctionName = _metadata != null ? _metadata.Name : string.Empty;
data.Success = success;
string jsonData = data.ToString();
startedEvent.Data = jsonData;
_metrics.LogEvent(eventName, startedEvent.FunctionName, jsonData);
_metrics.EndEvent(startedEvent);
if (invokeLatencyEvent != null)
{
MetricEvent metricEvent = invokeLatencyEvent as MetricEvent;
if (metricEvent != null)
{
metricEvent.Data = jsonData;
}
_metrics.EndEvent(invokeLatencyEvent);
}
}
private void EndFunction(FunctionInstanceLogEntry item)
{
item.Properties.TryGetValue(Key, out (FunctionStartedEvent, object)invocationTuple);
bool success = item.ErrorDetails == null;
var startedEvent = invocationTuple.Item1;
startedEvent.Success = success;
var function = startedEvent.FunctionMetadata;
string eventName = success ? MetricEventNames.FunctionInvokeSucceeded : MetricEventNames.FunctionInvokeFailed;
string functionName = function != null ? function.Name : string.Empty;
string data = string.Format(Microsoft.Azure.WebJobs.Script.Properties.Resources.FunctionInvocationMetricsData, startedEvent.FunctionMetadata.Language, functionName, success, Stopwatch.IsHighResolution);
_metrics.LogEvent(eventName, startedEvent.FunctionName, data);
startedEvent.Data = data;
_metrics.EndEvent(startedEvent);
var invokeLatencyEvent = invocationTuple.Item2;
if (invokeLatencyEvent is MetricEvent metricEvent)
{
metricEvent.Data = data;
}
_metrics.EndEvent(invokeLatencyEvent);
}
internal object LogInvocationMetrics(FunctionMetadata metadata)
{
// log events for each of the binding types used
foreach (var binding in metadata.Bindings)
{
string eventName = _bindingMetricEventNames.GetOrAdd(binding, (existing) =>
{
return(binding.IsTrigger ?
string.Format(MetricEventNames.FunctionBindingTypeFormat, binding.Type) :
string.Format(MetricEventNames.FunctionBindingTypeDirectionFormat, binding.Type, binding.Direction));
});
_metrics.LogEvent(eventName, metadata.Name);
}
return(_metrics.BeginEvent(MetricEventNames.FunctionInvokeLatency, metadata.Name));
}
// Called on success and failure
public void End(bool success)
{
_startedEvent.Success = success;
string eventName = success ? MetricEventNames.FunctionInvokeSucceeded : MetricEventNames.FunctionInvokeFailed;
var data = new JObject
{
["Language"] = _startedEvent.FunctionMetadata.Language,
["FunctionName"] = _metadata != null ? _metadata.Name : string.Empty,
["Success"] = success,
["IsStopwatchHighResolution"] = Stopwatch.IsHighResolution
};
string jsonData = data.ToString();
_startedEvent.Data = jsonData;
_metrics.LogEvent(eventName, _startedEvent.FunctionName, jsonData);
_metrics.EndEvent(_startedEvent);
if (_invokeLatencyEvent is MetricEvent metricEvent)
{
metricEvent.Data = jsonData;
}
_metrics.EndEvent(_invokeLatencyEvent);
}
private void RejectRequest(HttpContext httpContext, IMetricsLogger metricsLogger)
{
metricsLogger.LogEvent(MetricEventNames.FunctionInvokeThrottled);
httpContext.Response.StatusCode = 429;
httpContext.Response.Headers.Add(ScriptConstants.AntaresScaleOutHeaderName, "1");
}
public void Configure(HttpWorkerOptions options)
{
IConfigurationSection jobHostSection = _configuration.GetSection(ConfigurationSectionNames.JobHost);
var httpWorkerSection = jobHostSection.GetSection(ConfigurationSectionNames.HttpWorker);
var customHandlerSection = jobHostSection.GetSection(ConfigurationSectionNames.CustomHandler);
if (httpWorkerSection.Exists() && customHandlerSection.Exists())
{
_logger.LogWarning($"Both {ConfigurationSectionNames.HttpWorker} and {ConfigurationSectionNames.CustomHandler} sections are spefified in {ScriptConstants.HostMetadataFileName} file. {ConfigurationSectionNames.CustomHandler} takes precedence.");
}
if (customHandlerSection.Exists())
{
_metricsLogger.LogEvent(MetricEventNames.CustomHandlerConfiguration);
ConfigureWorkerDescription(options, customHandlerSection);
if (options.Type == CustomHandlerType.None)
{
// CustomHandlerType.None is only for maitaining backward compatibilty with httpWorker section.
_logger.LogWarning($"CustomHandlerType {CustomHandlerType.None} is not supported. Defaulting to {CustomHandlerType.Http}.");
options.Type = CustomHandlerType.Http;
}
return;
}
if (httpWorkerSection.Exists())
{
// TODO: Add aka.ms/link to new docs
_logger.LogWarning($"Section {ConfigurationSectionNames.HttpWorker} will be deprecated. Please use {ConfigurationSectionNames.CustomHandler} section.");
ConfigureWorkerDescription(options, httpWorkerSection);
// Explicity set this to None to differentiate between customHandler and httpWorker options.
options.Type = CustomHandlerType.None;
}
}
protected override HttpResponseMessage RejectRequest(HttpRequestMessage request)
{
var function = request.GetPropertyOrDefault <FunctionDescriptor>(ScriptConstants.AzureFunctionsHttpFunctionKey);
_metricsLogger.LogEvent(MetricEventNames.FunctionInvokeThrottled, function.Name);
return(base.RejectRequest(request));
}
/// <summary>
/// Adds additional <see cref="ILoggerProvider"/>s to the <see cref="ILoggerFactory"/>.
/// </summary>
/// <param name="factory">The <see cref="ILoggerFactory"/>.</param>
/// <param name="scriptConfig">The configuration.</param>
public virtual void AddLoggerProviders(ILoggerFactory factory, ScriptHostConfiguration scriptConfig, ScriptSettingsManager settingsManager)
{
IMetricsLogger metricsLogger = scriptConfig.HostConfig.GetService <IMetricsLogger>();
// Automatically register App Insights if the key is present
if (!string.IsNullOrEmpty(settingsManager?.ApplicationInsightsInstrumentationKey))
{
metricsLogger?.LogEvent(MetricEventNames.ApplicationInsightsEnabled);
ITelemetryClientFactory clientFactory = scriptConfig.HostConfig.GetService <ITelemetryClientFactory>() ??
new ScriptTelemetryClientFactory(settingsManager.ApplicationInsightsInstrumentationKey, scriptConfig.ApplicationInsightsSamplingSettings, scriptConfig.LogFilter.Filter);
scriptConfig.HostConfig.LoggerFactory.AddApplicationInsights(clientFactory);
}
else
{
metricsLogger?.LogEvent(MetricEventNames.ApplicationInsightsDisabled);
}
}
public virtual IEnumerable <ILoggerProvider> CreateLoggerProviders(string hostInstanceId, ScriptHostConfiguration scriptConfig, ScriptSettingsManager settingsManager,
Func <bool> isFileLoggingEnabled, Func <bool> isPrimary)
{
IList <ILoggerProvider> providers = new List <ILoggerProvider>();
IMetricsLogger metricsLogger = scriptConfig.HostConfig.GetService <IMetricsLogger>();
// Automatically register App Insights if the key is present
if (!string.IsNullOrEmpty(settingsManager?.ApplicationInsightsInstrumentationKey))
{
metricsLogger?.LogEvent(MetricEventNames.ApplicationInsightsEnabled);
ITelemetryClientFactory clientFactory = scriptConfig.HostConfig.GetService <ITelemetryClientFactory>() ??
new ScriptTelemetryClientFactory(settingsManager.ApplicationInsightsInstrumentationKey, scriptConfig.ApplicationInsightsSamplingSettings, scriptConfig.LogFilter.Filter);
providers.Add(new ApplicationInsightsLoggerProvider(clientFactory));
}
else
{
metricsLogger?.LogEvent(MetricEventNames.ApplicationInsightsDisabled);
}
providers.Add(new FunctionFileLoggerProvider(hostInstanceId, scriptConfig.RootLogPath, isFileLoggingEnabled, isPrimary));
providers.Add(new HostFileLoggerProvider(hostInstanceId, scriptConfig.RootLogPath, isFileLoggingEnabled));
// console logging defaults to false, except for self host
bool enableConsole = scriptConfig.IsSelfHost;
string configValue = settingsManager.Configuration.GetSection(ScriptConstants.ConsoleLoggingMode).Value;
if (!string.IsNullOrEmpty(configValue))
{
// if it has been explicitly configured that value overrides default
enableConsole = string.CompareOrdinal(configValue, "always") == 0 ? true : false;
}
if (ConsoleLoggingEnabled(scriptConfig, settingsManager))
{
providers.Add(new ConsoleLoggerProvider(scriptConfig.LogFilter.Filter, includeScopes: true));
}
return(providers);
}
/// <summary>
/// Performs all required initialization on the host.
/// Must be called before the host is started.
/// </summary>
public async Task InitializeAsync(CancellationToken cancellationToken = default)
{
_stopwatch.Start();
using (_metricsLogger.LatencyEvent(MetricEventNames.HostStartupLatency))
{
PreInitialize();
HostInitializing?.Invoke(this, EventArgs.Empty);
// Generate Functions
IEnumerable <FunctionMetadata> functionMetadataList = GetFunctionsMetadata();
_workerRuntime = _workerRuntime ?? Utility.GetWorkerRuntime(functionMetadataList);
if (!_environment.IsPlaceholderModeEnabled())
{
string runtimeStack = _workerRuntime;
// Appending the runtime version is currently only enabled for linux consumption. This will be eventually enabled for
// Windows Consumption as well.
string runtimeVersion = _environment.GetEnvironmentVariable(RpcWorkerConstants.FunctionWorkerRuntimeVersionSettingName);
if (!string.IsNullOrEmpty(runtimeVersion))
{
runtimeStack = string.Concat(runtimeStack, "-", runtimeVersion);
}
_metricsLogger.LogEvent(string.Format(MetricEventNames.HostStartupRuntimeLanguage, runtimeStack));
}
var directTypes = GetDirectTypes(functionMetadataList);
await InitializeFunctionDescriptorsAsync(functionMetadataList);
// Initialize worker function invocation dispatcher only for valid functions after creating function descriptors
await _functionDispatcher.InitializeAsync(Utility.GetValidFunctions(functionMetadataList, Functions), cancellationToken);
GenerateFunctions(directTypes);
CleanupFileSystem();
}
}
internal static object LogInvocationMetrics(IMetricsLogger metrics, FunctionMetadata metadata)
{
// log events for each of the binding types used
foreach (var binding in metadata.Bindings)
{
string eventName = binding.IsTrigger ?
string.Format(MetricEventNames.FunctionBindingTypeFormat, binding.Type) :
string.Format(MetricEventNames.FunctionBindingTypeDirectionFormat, binding.Type, binding.Direction);
metrics.LogEvent(eventName);
}
return(metrics.BeginEvent(MetricEventNames.FunctionInvokeLatency, metadata.Name));
}
public void Log <TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func <TState, Exception, string> formatter)
{
if (!IsEnabled(logLevel))
{
return;
}
var scope = _scopeProvider.GetScopeDictionary();
scope.TryGetValue(ScopeKeys.FunctionName, out string functionName);
_metricsLogger.LogEvent(MetricEventNames.FunctionUserLog, functionName);
}
// Called on success and failure
public void End(bool success)
{
startedEvent.Success = success;
string eventName = success ? MetricEventNames.FunctionInvokeSucceeded : MetricEventNames.FunctionInvokeFailed;
_metrics.LogEvent(eventName, startedEvent.FunctionName);
_metrics.EndEvent(startedEvent);
if (invokeLatencyEvent != null)
{
_metrics.EndEvent(invokeLatencyEvent);
}
}
// Called on success and failure
public void End(bool success)
{
_startedEvent.Success = success;
string eventName = success ? MetricEventNames.FunctionInvokeSucceeded : MetricEventNames.FunctionInvokeFailed;
string functionName = _metadata != null ? _metadata.Name : string.Empty;
string data = string.Format(Properties.Resources.FunctionInvocationMetricsData, _startedEvent.FunctionMetadata.Language, functionName, success, Stopwatch.IsHighResolution);
_metrics.LogEvent(eventName, _startedEvent.FunctionName, data);
_startedEvent.Data = data;
_metrics.EndEvent(_startedEvent);
if (_invokeLatencyEvent is MetricEvent metricEvent)
{
metricEvent.Data = data;
}
_metrics.EndEvent(_invokeLatencyEvent);
}
internal static void LogInvocationMetrics(IMetricsLogger metrics, Collection<BindingMetadata> bindings)
{
metrics.LogEvent(MetricEventNames.FunctionInvoke);
// log events for each of the binding types used
foreach (var binding in bindings)
{
string eventName = binding.IsTrigger ?
string.Format(MetricEventNames.FunctionBindingTypeFormat, binding.Type) :
string.Format(MetricEventNames.FunctionBindingTypeDirectionFormat, binding.Type, binding.Direction);
metrics.LogEvent(eventName);
}
}
public void LogEvent(MetricEvent metricEvent)
{
_metricsLogger.LogEvent(metricEvent);
}
