public Task <IValueProvider> BindAsync(BindingContext context)
{
if (context == null)
{
throw new ArgumentNullException("context");
}
TraceWriter trace = context.Trace;
// If logger functionality is enabled, wrap an ILogger
if (_loggerFactory != null)
{
ILogger logger = _loggerFactory.CreateLogger(LogCategories.Function);
trace = new CompositeTraceWriter(new[] { trace, new LoggerTraceWriter(context.Trace.Level, logger) }, null, context.Trace.Level);
}
object tracer = null;
if (_parameter.ParameterType == typeof(TraceWriter))
{
tracer = trace;
}
else
{
// bind to an adapter
tracer = TextWriterTraceAdapter.Synchronized(trace);
}
return(BindAsync(tracer, context.ValueContext));
}
public void Flush_FlushesInternalWriters()
{
var traceWriter = new TestTraceWriter(TraceLevel.Error);
var compositeWriter = new CompositeTraceWriter(new[] { traceWriter });
string message = "Test trace";
compositeWriter.Error(message);
compositeWriter.Flush();
Assert.True(traceWriter.Flushed);
}
public void Flush_FlushesInternalWriters()
{
var traceWriter = new TestTraceWriter(TraceLevel.Error);
var compositeWriter = new CompositeTraceWriter(new[] { traceWriter });
string message = "Test trace";
compositeWriter.Error(message);
compositeWriter.Flush();
Assert.True(traceWriter.Flushed);
}
private object[] ProcessInputParameters(object[] parameters)
{
for (int i = 0; i < parameters.Length; i++)
{
TraceWriter writer = parameters[i] as TraceWriter;
if (writer != null)
{
parameters[i] = new CompositeTraceWriter(new[] { writer, TraceWriter });
}
}
return(parameters);
}
public void Trace_CallsInnerWriterTrace()
{
var traceWriter = new TestTraceWriter(TraceLevel.Verbose);
var compositeWriter = new CompositeTraceWriter(new[] { traceWriter });
string message = "Test trace";
compositeWriter.Verbose(message);
TraceEvent trace = traceWriter.Traces.FirstOrDefault();
Assert.NotNull(trace);
Assert.Equal(TraceLevel.Verbose, trace.Level);
Assert.Equal(message, trace.Message);
}
public void Trace_CallsInnerWriterTrace()
{
var traceWriter = new TestTraceWriter(TraceLevel.Verbose);
var compositeWriter = new CompositeTraceWriter(new[] { traceWriter });
string message = "Test trace";
compositeWriter.Verbose(message);
TraceEvent trace = traceWriter.Traces.FirstOrDefault();
Assert.NotNull(trace);
Assert.Equal(TraceLevel.Verbose, trace.Level);
Assert.Equal(message, trace.Message);
}
public void Trace_RespectsInnerWriterLevel()
{
var traceWriter = new TestTraceWriter(TraceLevel.Error);
var compositeWriter = new CompositeTraceWriter(new[] { traceWriter });
string message = "Test trace";
compositeWriter.Verbose(message);
compositeWriter.Error(message);
Assert.Equal(1, traceWriter.Traces.Count);
TraceEvent trace = traceWriter.Traces.First();
Assert.Equal(TraceLevel.Error, trace.Level);
Assert.Equal(message, trace.Message);
}
public void Dispose_Disposes_If_IDisposable()
{
var disposableTraceWriter1 = new DisposableTraceWriter();
var disposableTraceWriter2 = new DisposableTraceWriter();
var testTraceWriter = new TestTraceWriter(TraceLevel.Verbose);
Assert.IsNotType <IDisposable>(testTraceWriter);
var traceWriter = new CompositeTraceWriter(new TraceWriter[] { disposableTraceWriter1, testTraceWriter, disposableTraceWriter2 });
Assert.False(disposableTraceWriter1.IsDisposed);
Assert.False(disposableTraceWriter2.IsDisposed);
traceWriter.Dispose();
Assert.True(disposableTraceWriter1.IsDisposed);
Assert.True(disposableTraceWriter2.IsDisposed);
}
public void Trace_RespectsInnerWriterLevel()
{
var traceWriter = new TestTraceWriter(TraceLevel.Error);
var compositeWriter = new CompositeTraceWriter(new[] { traceWriter });
string message = "Test trace";
compositeWriter.Verbose(message);
compositeWriter.Error(message);
Assert.Equal(1, traceWriter.Traces.Count);
TraceEvent trace = traceWriter.Traces.First();
Assert.Equal(TraceLevel.Error, trace.Level);
Assert.Equal(message, trace.Message);
}
private async Task <string> ExecuteWithLoggingAsync(IFunctionInstance instance, FunctionStartedMessage message,
FunctionInstanceLogEntry fastItem,
IDictionary <string, ParameterLog> parameterLogCollector, TraceLevel functionTraceLevel, CancellationToken cancellationToken)
{
IFunctionOutputDefinition outputDefinition = null;
IFunctionOutput outputLog = null;
ITaskSeriesTimer updateOutputLogTimer = null;
TextWriter functionOutputTextWriter = null;
Func <Task> initializeOutputAsync = async() =>
{
outputDefinition = await _functionOutputLogger.CreateAsync(instance, cancellationToken);
outputLog = outputDefinition.CreateOutput();
functionOutputTextWriter = outputLog.Output;
updateOutputLogTimer = StartOutputTimer(outputLog.UpdateCommand, _exceptionHandler);
};
if (functionTraceLevel >= TraceLevel.Info)
{
await initializeOutputAsync();
}
try
{
// Create a linked token source that will allow us to signal function cancellation
// (e.g. Based on TimeoutAttribute, etc.)
CancellationTokenSource functionCancellationTokenSource = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken);
using (functionCancellationTokenSource)
{
// We create a new composite trace writer that will also forward
// output to the function output log (in addition to console, user TraceWriter, etc.).
TraceWriter traceWriter = new CompositeTraceWriter(_trace, functionOutputTextWriter, functionTraceLevel);
// Must bind before logging (bound invoke string is included in log message).
FunctionBindingContext functionContext = new FunctionBindingContext(instance.Id, functionCancellationTokenSource.Token, traceWriter);
var valueBindingContext = new ValueBindingContext(functionContext, cancellationToken);
var parameters = await instance.BindingSource.BindAsync(valueBindingContext);
Exception invocationException = null;
ExceptionDispatchInfo exceptionInfo = null;
string startedMessageId = null;
using (ValueProviderDisposable.Create(parameters))
{
if (functionTraceLevel >= TraceLevel.Info)
{
startedMessageId = await LogFunctionStartedAsync(message, outputDefinition, parameters, cancellationToken);
}
if (_fastLogger != null)
{
// Log started
fastItem.Arguments = message.Arguments;
await _fastLogger.AddAsync(fastItem);
}
try
{
await ExecuteWithLoggingAsync(instance, parameters, traceWriter, outputDefinition, parameterLogCollector, functionTraceLevel, functionCancellationTokenSource);
}
catch (Exception ex)
{
invocationException = ex;
}
}
if (invocationException != null)
{
if (outputDefinition == null)
{
// In error cases, even if logging is disabled for this function, we want to force
// log errors. So we must delay initialize logging here
await initializeOutputAsync();
startedMessageId = await LogFunctionStartedAsync(message, outputDefinition, parameters, cancellationToken);
}
// In the event of cancellation or timeout, we use the original exception without additional logging.
if (invocationException is OperationCanceledException || invocationException is FunctionTimeoutException)
{
exceptionInfo = ExceptionDispatchInfo.Capture(invocationException);
}
else
{
string errorMessage = string.Format("Exception while executing function: {0}", instance.FunctionDescriptor.ShortName);
FunctionInvocationException fex = new FunctionInvocationException(errorMessage, instance.Id, instance.FunctionDescriptor.FullName, invocationException);
traceWriter.Error(errorMessage, fex, TraceSource.Execution);
exceptionInfo = ExceptionDispatchInfo.Capture(fex);
}
}
if (exceptionInfo == null && updateOutputLogTimer != null)
{
await updateOutputLogTimer.StopAsync(cancellationToken);
}
// after all execution is complete, flush the TraceWriter
traceWriter.Flush();
// We save the exception info above rather than throwing to ensure we always write
// console output even if the function fails or was canceled.
if (outputLog != null)
{
await outputLog.SaveAndCloseAsync(fastItem, cancellationToken);
}
if (exceptionInfo != null)
{
// release any held singleton lock immediately
SingletonLock singleton = null;
if (TryGetSingletonLock(parameters, out singleton) && singleton.IsHeld)
{
await singleton.ReleaseAsync(cancellationToken);
}
exceptionInfo.Throw();
}
return(startedMessageId);
}
}
finally
{
if (outputLog != null)
{
((IDisposable)outputLog).Dispose();
}
if (updateOutputLogTimer != null)
{
((IDisposable)updateOutputLogTimer).Dispose();
}
}
}
protected virtual void Initialize()
{
string hostLogPath = Path.Combine(ScriptConfig.RootLogPath, "Host");
FileUtility.EnsureDirectoryExists(hostLogPath);
string debugSentinelFileName = Path.Combine(hostLogPath, ScriptConstants.DebugSentinelFileName);
this.LastDebugNotify = File.GetLastWriteTime(debugSentinelFileName);
IMetricsLogger metricsLogger = ScriptConfig.HostConfig.GetService<IMetricsLogger>();
if (metricsLogger == null)
{
metricsLogger = new MetricsLogger();
ScriptConfig.HostConfig.AddService<IMetricsLogger>(metricsLogger);
}
using (metricsLogger.LatencyEvent(MetricEventNames.HostStartupLatency))
{
// read host.json and apply to JobHostConfiguration
string hostConfigFilePath = Path.Combine(ScriptConfig.RootScriptPath, ScriptConstants.HostMetadataFileName);
// If it doesn't exist, create an empty JSON file
if (!File.Exists(hostConfigFilePath))
{
File.WriteAllText(hostConfigFilePath, "{}");
}
if (ScriptConfig.HostConfig.IsDevelopment || InDebugMode)
{
// If we're in debug/development mode, use optimal debug settings
ScriptConfig.HostConfig.UseDevelopmentSettings();
}
string json = File.ReadAllText(hostConfigFilePath);
JObject hostConfig;
try
{
hostConfig = JObject.Parse(json);
}
catch (JsonException ex)
{
throw new FormatException(string.Format("Unable to parse {0} file.", ScriptConstants.HostMetadataFileName), ex);
}
ApplyConfiguration(hostConfig, ScriptConfig);
// Set up a host level TraceMonitor that will receive notification
// of ALL errors that occur. This allows us to inspect/log errors.
var traceMonitor = new TraceMonitor()
.Filter(p => { return true; })
.Subscribe(HandleHostError);
ScriptConfig.HostConfig.Tracing.Tracers.Add(traceMonitor);
TraceLevel hostTraceLevel = ScriptConfig.HostConfig.Tracing.ConsoleLevel;
if (ScriptConfig.FileLoggingMode != FileLoggingMode.Never)
{
// Host file logging is only done conditionally
string hostLogFilePath = Path.Combine(ScriptConfig.RootLogPath, "Host");
TraceWriter fileTraceWriter = new FileTraceWriter(hostLogFilePath, hostTraceLevel).Conditional(p => FileLoggingEnabled);
if (TraceWriter != null)
{
// create a composite writer so our host logs are written to both
TraceWriter = new CompositeTraceWriter(new[] { TraceWriter, fileTraceWriter });
}
else
{
TraceWriter = fileTraceWriter;
}
}
if (TraceWriter != null)
{
ScriptConfig.HostConfig.Tracing.Tracers.Add(TraceWriter);
}
else
{
// if no TraceWriter has been configured, default it to Console
TraceWriter = new ConsoleTraceWriter(hostTraceLevel);
}
_debugModeFileWatcher = new AutoRecoveringFileSystemWatcher(hostLogPath, ScriptConstants.DebugSentinelFileName,
includeSubdirectories: false, changeTypes: WatcherChangeTypes.Created | WatcherChangeTypes.Changed);
_debugModeFileWatcher.Changed += OnDebugModeFileChanged;
var storageString = AmbientConnectionStringProvider.Instance.GetConnectionString(ConnectionStringNames.Storage);
Task<BlobLeaseManager> blobManagerCreation = null;
if (storageString == null)
{
// Disable core storage
ScriptConfig.HostConfig.StorageConnectionString = null;
blobManagerCreation = Task.FromResult<BlobLeaseManager>(null);
}
else
{
blobManagerCreation = BlobLeaseManager.CreateAsync(storageString, TimeSpan.FromSeconds(15), ScriptConfig.HostConfig.HostId, InstanceId, TraceWriter);
}
var bindingProviders = LoadBindingProviders(ScriptConfig, hostConfig, TraceWriter);
ScriptConfig.BindingProviders = bindingProviders;
TraceWriter.Info(string.Format(CultureInfo.InvariantCulture, "Reading host configuration file '{0}'", hostConfigFilePath));
if (ScriptConfig.FileWatchingEnabled)
{
_scriptFileWatcher = new AutoRecoveringFileSystemWatcher(ScriptConfig.RootScriptPath);
_scriptFileWatcher.Changed += OnFileChanged;
}
// If a file change should result in a restart, we debounce the event to
// ensure that only a single restart is triggered within a specific time window.
// This allows us to deal with a large set of file change events that might
// result from a bulk copy/unzip operation. In such cases, we only want to
// restart after ALL the operations are complete and there is a quiet period.
_restart = (e) =>
{
TraceWriter.Info(string.Format(CultureInfo.InvariantCulture, "File change of type '{0}' detected for '{1}'", e.ChangeType, e.FullPath));
TraceWriter.Info("Host configuration has changed. Signaling restart.");
RestartHost();
};
_restart = _restart.Debounce(500);
// take a snapshot so we can detect function additions/removals
_directoryCountSnapshot = Directory.EnumerateDirectories(ScriptConfig.RootScriptPath).Count();
List<FunctionDescriptorProvider> descriptionProviders = new List<FunctionDescriptorProvider>()
{
new ScriptFunctionDescriptorProvider(this, ScriptConfig),
new NodeFunctionDescriptorProvider(this, ScriptConfig),
new DotNetFunctionDescriptorProvider(this, ScriptConfig),
new PowerShellFunctionDescriptorProvider(this, ScriptConfig)
};
// Allow BindingProviders to initialize
foreach (var bindingProvider in ScriptConfig.BindingProviders)
{
try
{
bindingProvider.Initialize();
}
catch (Exception ex)
{
// If we're unable to initialize a binding provider for any reason, log the error
// and continue
TraceWriter.Error(string.Format("Error initializing binding provider '{0}'", bindingProvider.GetType().FullName), ex);
}
}
// Create the lease manager that will keep handle the primary host blob lease acquisition and renewal
// and subscribe for change notifications.
_blobLeaseManager = blobManagerCreation.GetAwaiter().GetResult();
if (_blobLeaseManager != null)
{
_blobLeaseManager.HasLeaseChanged += BlobLeaseManagerHasLeaseChanged;
}
// read all script functions and apply to JobHostConfiguration
Collection<FunctionDescriptor> functions = ReadFunctions(descriptionProviders);
Collection<CustomAttributeBuilder> typeAttributes = CreateTypeAttributes(ScriptConfig);
string defaultNamespace = "Host";
string typeName = string.Format(CultureInfo.InvariantCulture, "{0}.{1}", defaultNamespace, "Functions");
TraceWriter.Info(string.Format(CultureInfo.InvariantCulture, "Generating {0} job function(s)", functions.Count));
Type type = FunctionGenerator.Generate(HostAssemblyName, typeName, typeAttributes, functions);
List<Type> types = new List<Type>();
types.Add(type);
ScriptConfig.HostConfig.TypeLocator = new TypeLocator(types);
Functions = functions;
if (ScriptConfig.FileLoggingMode != FileLoggingMode.Never)
{
PurgeOldLogDirectories();
}
}
}
public CompositeTraceWriterTests()
{
_mockTextWriter = new Mock<TextWriter>(MockBehavior.Strict);
_mockTraceWriter = new Mock<TraceWriter>(MockBehavior.Strict, TraceLevel.Warning);
_traceWriter = new CompositeTraceWriter(_mockTraceWriter.Object, _mockTextWriter.Object);
}
public CompositeTraceWriterTests()
{
_mockTextWriter = new Mock <TextWriter>(MockBehavior.Strict);
_mockTraceWriter = new Mock <TraceWriter>(MockBehavior.Strict, TraceLevel.Warning);
_traceWriter = new CompositeTraceWriter(_mockTraceWriter.Object, _mockTextWriter.Object);
}
private async Task <string> ExecuteWithLogMessageAsync(IFunctionInstance instance, FunctionStartedMessage message,
IDictionary <string, ParameterLog> parameterLogCollector, CancellationToken cancellationToken)
{
string startedMessageId;
// Create the console output writer
IFunctionOutputDefinition outputDefinition = await _functionOutputLogger.CreateAsync(instance, cancellationToken);
// Create a linked token source that will allow us to signal function cancellation
// (e.g. Based on TimeoutAttribute, etc.)
CancellationTokenSource functionCancellationTokenSource = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken);
using (IFunctionOutput outputLog = await outputDefinition.CreateOutputAsync(cancellationToken))
using (ITaskSeriesTimer updateOutputLogTimer = StartOutputTimer(outputLog.UpdateCommand, _backgroundExceptionDispatcher))
using (functionCancellationTokenSource)
{
// We create a new composite trace writer that will also forward
// output to the function output log (in addition to console, user TraceWriter, etc.).
TraceWriter traceWriter = new CompositeTraceWriter(_trace, outputLog.Output);
FunctionBindingContext functionContext = new FunctionBindingContext(instance.Id, functionCancellationTokenSource.Token, traceWriter);
// Must bind before logging (bound invoke string is included in log message).
IReadOnlyDictionary <string, IValueProvider> parameters =
await instance.BindingSource.BindAsync(new ValueBindingContext(functionContext, cancellationToken));
ExceptionDispatchInfo exceptionInfo;
using (ValueProviderDisposable.Create(parameters))
{
startedMessageId = await LogFunctionStartedAsync(message, outputDefinition, parameters, cancellationToken);
try
{
await ExecuteWithOutputLogsAsync(instance, parameters, traceWriter, outputDefinition, parameterLogCollector, functionCancellationTokenSource);
exceptionInfo = null;
}
catch (OperationCanceledException exception)
{
exceptionInfo = ExceptionDispatchInfo.Capture(exception);
}
catch (Exception exception)
{
string errorMessage = string.Format("Exception while executing function: {0}", instance.FunctionDescriptor.ShortName);
FunctionInvocationException functionException = new FunctionInvocationException(errorMessage, instance.Id, instance.FunctionDescriptor.FullName, exception);
traceWriter.Error(errorMessage, functionException, TraceSource.Execution);
exceptionInfo = ExceptionDispatchInfo.Capture(functionException);
}
}
if (exceptionInfo == null && updateOutputLogTimer != null)
{
await updateOutputLogTimer.StopAsync(cancellationToken);
}
// after all execution is complete, flush the TraceWriter
traceWriter.Flush();
// We save the exception info rather than doing throw; above to ensure we always write console output,
// even if the function fails or was canceled.
await outputLog.SaveAndCloseAsync(cancellationToken);
if (exceptionInfo != null)
{
// release any held singleton lock immediately
SingletonLock singleton = null;
if (TryGetSingletonLock(parameters, out singleton) && singleton.IsHeld)
{
await singleton.ReleaseAsync(cancellationToken);
}
exceptionInfo.Throw();
}
return(startedMessageId);
}
}
