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);
}
public void Trace_DelegatesToInnerTraceWriterAndTextWriter()
{
_mockTraceWriter.Setup(p => p.Trace(It.Is <TraceEvent>(q => q.Level == TraceLevel.Warning && q.Source == "TestSource" && q.Message == "Test Warning" && q.Exception == null)));
_mockTraceWriter.Setup(p => p.Trace(It.Is <TraceEvent>(q => q.Level == TraceLevel.Error && q.Source == "TestSource" && q.Message == "Test Error" && q.Exception == null)));
Exception ex = new Exception("Kaboom!");
_mockTraceWriter.Setup(p => p.Trace(It.Is <TraceEvent>(q => q.Level == TraceLevel.Error && q.Source == "TestSource" && q.Message == "Test Error With Exception" && q.Exception == ex)));
_mockTextWriter.Setup(p => p.WriteLine("Test Information"));
_mockTextWriter.Setup(p => p.WriteLine("Test Warning"));
_mockTextWriter.Setup(p => p.WriteLine("Test Error"));
_mockTextWriter.Setup(p => p.WriteLine("Test Error With Exception"));
_mockTextWriter.Setup(p => p.WriteLine(ex.ToDetails()));
_traceWriter.Info("Test Information", source: "TestSource"); // don't expect this to be logged
_traceWriter.Warning("Test Warning", source: "TestSource");
_traceWriter.Error("Test Error", source: "TestSource");
_traceWriter.Error("Test Error With Exception", ex, source: "TestSource");
_mockTextWriter.VerifyAll();
_mockTraceWriter.VerifyAll();
}
public void Trace_DelegatesToInnerTraceWriterAndTextWriter()
{
_mockTraceWriter.Setup(p => p.Trace(TraceLevel.Warning, "TestSource", "Test Warning", null));
_mockTraceWriter.Setup(p => p.Trace(TraceLevel.Error, "TestSource", "Test Error", null));
Exception ex = new Exception("Kaboom!");
_mockTraceWriter.Setup(p => p.Trace(TraceLevel.Error, "TestSource", "Test Error With Exception", ex));
_mockTextWriter.Setup(p => p.WriteLine("Test Information"));
_mockTextWriter.Setup(p => p.WriteLine("Test Warning"));
_mockTextWriter.Setup(p => p.WriteLine("Test Error"));
_mockTextWriter.Setup(p => p.WriteLine("Test Error With Exception"));
_mockTextWriter.Setup(p => p.WriteLine(ex.ToDetails()));
_traceWriter.Info("Test Information", source: "TestSource"); // don't expect this to be logged
_traceWriter.Warning("Test Warning", source: "TestSource");
_traceWriter.Error("Test Error", source: "TestSource");
_traceWriter.Error("Test Error With Exception", ex, source: "TestSource");
_mockTextWriter.VerifyAll();
_mockTraceWriter.VerifyAll();
}
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 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();
}
}
}
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);
}
}