diff --git a/src/Microsoft.Azure.WebJobs.Host/CompositeTraceWriter.cs b/src/Microsoft.Azure.WebJobs.Host/CompositeTraceWriter.cs index 94727a143..667b689d6 100644 --- a/src/Microsoft.Azure.WebJobs.Host/CompositeTraceWriter.cs +++ b/src/Microsoft.Azure.WebJobs.Host/CompositeTraceWriter.cs @@ -32,28 +32,29 @@ public CompositeTraceWriter(TraceWriter traceWriter, TextWriter textWriter) _innerTextWriter = textWriter; } - public override void Trace(TraceLevel level, string source, string message, Exception ex) + public override void Trace(TraceEvent traceEvent) { - InvokeTraceWriters(level, source, message, ex); - InvokeTextWriter(level, source, message, ex); + InvokeTraceWriters(traceEvent); + InvokeTextWriter(traceEvent); } - protected virtual void InvokeTraceWriters(TraceLevel level, string source, string message, Exception ex) + protected virtual void InvokeTraceWriters(TraceEvent traceEvent) { foreach (TraceWriter traceWriter in _innerTraceWriters) { // filter based on level before delegating - if (traceWriter.Level >= level) + if (traceWriter.Level >= traceEvent.Level) { - traceWriter.Trace(level, source, message, ex); + traceWriter.Trace(traceEvent); } } } - protected virtual void InvokeTextWriter(TraceLevel level, string source, string message, Exception ex) + protected virtual void InvokeTextWriter(TraceEvent traceEvent) { if (_innerTextWriter != null) { + string message = traceEvent.Message; if (!string.IsNullOrEmpty(message) && message.EndsWith("\r\n", StringComparison.OrdinalIgnoreCase)) { @@ -63,9 +64,9 @@ protected virtual void InvokeTextWriter(TraceLevel level, string source, string } _innerTextWriter.WriteLine(message); - if (ex != null) + if (traceEvent.Exception != null) { - _innerTextWriter.WriteLine(ex.ToDetails()); + _innerTextWriter.WriteLine(traceEvent.Exception.ToDetails()); } } } diff --git a/src/Microsoft.Azure.WebJobs.Host/ConsoleTraceWriter.cs b/src/Microsoft.Azure.WebJobs.Host/ConsoleTraceWriter.cs index 15666cb3c..eab83a0a7 100644 --- a/src/Microsoft.Azure.WebJobs.Host/ConsoleTraceWriter.cs +++ b/src/Microsoft.Azure.WebJobs.Host/ConsoleTraceWriter.cs @@ -21,15 +21,15 @@ public ConsoleTraceWriter(JobHostTraceConfiguration traceConfig, TextWriter cons _traceConfig = traceConfig; } - protected override void InvokeTextWriter(TraceLevel level, string source, string message, Exception ex) + protected override void InvokeTextWriter(TraceEvent traceEvent) { - if (MapTraceLevel(source, level) <= _traceConfig.ConsoleLevel) + if (MapTraceLevel(traceEvent.Source, traceEvent.Level) <= _traceConfig.ConsoleLevel) { // For Errors/Warnings we change the Console color // for visibility var holdColor = Console.ForegroundColor; bool changedColor = false; - switch (level) + switch (traceEvent.Level) { case TraceLevel.Error: Console.ForegroundColor = ConsoleColor.Red; @@ -41,7 +41,7 @@ protected override void InvokeTextWriter(TraceLevel level, string source, string break; } - base.InvokeTextWriter(level, source, message, ex); + base.InvokeTextWriter(traceEvent); if (changedColor) { diff --git a/src/Microsoft.Azure.WebJobs.Host/Executors/FunctionExecutor.cs b/src/Microsoft.Azure.WebJobs.Host/Executors/FunctionExecutor.cs index 57e4bc238..d652c13ae 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Executors/FunctionExecutor.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Executors/FunctionExecutor.cs @@ -108,8 +108,7 @@ public async Task TryExecuteAsync(IFunctionInstance instance, logCompletedCancellationToken = cancellationToken; } - await _functionInstanceLogger.LogFunctionCompletedAsync(completedMessage, - logCompletedCancellationToken); + await _functionInstanceLogger.LogFunctionCompletedAsync(completedMessage, logCompletedCancellationToken); if (loggedStartedEvent) { @@ -146,8 +145,7 @@ private async Task ExecuteWithLogMessageAsync(IFunctionInstance instance try { - await ExecuteWithOutputLogsAsync(instance, parameters, traceWriter, outputDefinition, - parameterLogCollector, cancellationToken); + await ExecuteWithOutputLogsAsync(instance, parameters, traceWriter, outputDefinition, parameterLogCollector, cancellationToken); exceptionInfo = null; } catch (OperationCanceledException exception) @@ -156,8 +154,10 @@ await ExecuteWithOutputLogsAsync(instance, parameters, traceWriter, outputDefini } catch (Exception exception) { - traceWriter.Error("Exception while executing:", exception, TraceSource.Execution); - exceptionInfo = ExceptionDispatchInfo.Capture(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); } } diff --git a/src/Microsoft.Azure.WebJobs.Host/FunctionInvocationException.cs b/src/Microsoft.Azure.WebJobs.Host/FunctionInvocationException.cs new file mode 100644 index 000000000..a07a741f8 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/FunctionInvocationException.cs @@ -0,0 +1,85 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the MIT License. See License.txt in the project root for license information. + +using System; +using System.Runtime.Serialization; + +namespace Microsoft.Azure.WebJobs.Host +{ + /// + /// Exception thrown when a job function invocation fails. + /// + [Serializable] + public class FunctionInvocationException : Exception + { + /// + public FunctionInvocationException() : base() + { + } + + /// + public FunctionInvocationException(string message) : base(message) + { + } + + /// + public FunctionInvocationException(string message, Exception innerException) : base(message, innerException) + { + } + + /// + /// Constructs a new instance. + /// + /// The . + /// The . + protected FunctionInvocationException(SerializationInfo info, StreamingContext context) : base(info, context) + { + if (info == null) + { + throw new ArgumentNullException("info"); + } + + InstanceId = Guid.Parse(info.GetString("InstanceId")); + MethodName = info.GetString("MethodName"); + } + + /// + /// Constructs a new instance. + /// + /// The exception message. + /// The function instance Id. + /// The fully qualified method name. + /// The exception that is the cause of the current exception (or null). + public FunctionInvocationException(string message, Guid instanceId, string methodName, Exception innerException) + : base(message, innerException) + { + InstanceId = instanceId; + MethodName = methodName; + } + + /// + /// Gets the instance Id of the failed invocation. This value can be correlated + /// to the Dashboard logs. + /// + public Guid InstanceId { get; set; } + + /// + /// Gets the fully qualified name of the function. + /// + public string MethodName { get; set; } + + /// + public override void GetObjectData(SerializationInfo info, StreamingContext context) + { + if (info == null) + { + throw new ArgumentNullException("info"); + } + + info.AddValue("InstanceId", this.InstanceId); + info.AddValue("MethodName", this.MethodName); + + base.GetObjectData(info, context); + } + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/Loggers/TraceWriterFunctionInstanceLogger.cs b/src/Microsoft.Azure.WebJobs.Host/Loggers/TraceWriterFunctionInstanceLogger.cs index 444970790..9d3899b59 100644 --- a/src/Microsoft.Azure.WebJobs.Host/Loggers/TraceWriterFunctionInstanceLogger.cs +++ b/src/Microsoft.Azure.WebJobs.Host/Loggers/TraceWriterFunctionInstanceLogger.cs @@ -41,7 +41,7 @@ public Task LogFunctionCompletedAsync(FunctionCompletedMessage message, Cancella // Also log the eror message using TraceSource.Host, to ensure // it gets written to Console _trace.Error(string.Format(CultureInfo.InvariantCulture, - " Function had errors. See Azure WebJobs SDK dashboard for details. Instance ID is '{0}'", message.FunctionInstanceId), source: TraceSource.Host); + " Function had errors. See Azure WebJobs SDK dashboard for details. Instance ID is '{0}'", message.FunctionInstanceId), message.Failure.Exception, TraceSource.Host); } return Task.FromResult(0); } diff --git a/src/Microsoft.Azure.WebJobs.Host/TraceEvent.cs b/src/Microsoft.Azure.WebJobs.Host/TraceEvent.cs new file mode 100644 index 000000000..af774c189 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/TraceEvent.cs @@ -0,0 +1,80 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the MIT License. See License.txt in the project root for license information. + +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Globalization; + +namespace Microsoft.Azure.WebJobs.Host +{ + /// + /// Defines a trace event that can be written to a . + /// + public class TraceEvent + { + private IDictionary _properties; + + /// + /// Constructs a new instance. + /// + /// The level of the trace. + /// The trace message. + /// The source of the trace (may be null). + /// The exception that caused the trace (may be null). + public TraceEvent(TraceLevel level, string message, string source = null, Exception exception = null) + { + Level = level; + Message = message; + Source = source; + Exception = exception; + Timestamp = DateTime.UtcNow; + } + + /// + /// The time the trace was recorded. + /// + public DateTime Timestamp { get; set; } + + /// + /// The level of the trace. + /// + public TraceLevel Level { get; set; } + + /// + /// The source of the trace. + /// + public string Source { get; set; } + + /// + /// The trace message. + /// + public string Message { get; set; } + + /// + /// The exception that caused the trace. + /// + public Exception Exception { get; set; } + + /// + /// Gets a set of properties for the . + /// + public IDictionary Properties + { + get + { + if (_properties == null) + { + _properties = new Dictionary(); + } + return _properties; + } + } + + /// + public override string ToString() + { + return string.Format(CultureInfo.InvariantCulture, "{0} {1} {2} {3} {4}", Timestamp, Level.ToString(), Message, Source, Exception); + } + } +} diff --git a/src/Microsoft.Azure.WebJobs.Host/TraceWriter.cs b/src/Microsoft.Azure.WebJobs.Host/TraceWriter.cs index e3f499de7..b472ae6f5 100644 --- a/src/Microsoft.Azure.WebJobs.Host/TraceWriter.cs +++ b/src/Microsoft.Azure.WebJobs.Host/TraceWriter.cs @@ -7,7 +7,7 @@ namespace Microsoft.Azure.WebJobs.Host { /// - /// Base class for trace writers used by . + /// Base class for trace writers used by the . /// See for details. /// public abstract class TraceWriter @@ -33,53 +33,50 @@ protected TraceWriter(TraceLevel level) public TraceLevel Level { get; set; } /// - /// Writes a trace entry. + /// Writes a trace event. /// - /// The for the trace entry - /// Optional source of the message. - /// The trace message. - /// Optional (if an error is being traced). - public abstract void Trace(TraceLevel level, string source, string message, Exception ex); + /// The to trace. + public abstract void Trace(TraceEvent traceEvent); /// - /// Writes a level trace entry. + /// Writes a level trace event. /// /// The trace message. /// The source of the message. public void Verbose(string message, string source = null) { - Trace(TraceLevel.Verbose, source, message, null); + Trace(new TraceEvent(TraceLevel.Verbose, message, source)); } /// - /// Writes a level trace entry. + /// Writes a level trace event. /// /// The trace message. /// The source of the message. public void Info(string message, string source = null) { - Trace(TraceLevel.Info, source, message, null); + Trace(new TraceEvent(TraceLevel.Info, message, source)); } /// - /// Writes a level trace entry. + /// Writes a level trace event. /// /// The trace message. /// The source of the message. public void Warning(string message, string source = null) { - Trace(TraceLevel.Warning, source, message, null); + Trace(new TraceEvent(TraceLevel.Warning, message, source)); } /// - /// Writes a level trace entry. + /// Writes a level trace event. /// /// The trace message. /// The optional for the error. /// The source of the message. public void Error(string message, Exception ex = null, string source = null) { - Trace(TraceLevel.Error, source, message, ex); + Trace(new TraceEvent(TraceLevel.Error, message, source, ex)); } /// diff --git a/src/Microsoft.Azure.WebJobs.Host/WebJobs.Host.csproj b/src/Microsoft.Azure.WebJobs.Host/WebJobs.Host.csproj index c50dcde85..e3c71225b 100644 --- a/src/Microsoft.Azure.WebJobs.Host/WebJobs.Host.csproj +++ b/src/Microsoft.Azure.WebJobs.Host/WebJobs.Host.csproj @@ -693,6 +693,7 @@ + @@ -860,6 +861,7 @@ + diff --git a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/AsyncChainEndToEndTests.cs b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/AsyncChainEndToEndTests.cs index 25ce6ebc1..e7d8eb4b8 100644 --- a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/AsyncChainEndToEndTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/AsyncChainEndToEndTests.cs @@ -6,6 +6,7 @@ using System.Diagnostics; using System.IO; using System.Linq; +using System.Reflection; using System.Text; using System.Threading; using System.Threading.Tasks; @@ -77,6 +78,7 @@ public async Task AsyncChainEndToEnd() "Microsoft.Azure.WebJobs.Host.EndToEndTests.AsyncChainEndToEndTests.WriteStartDataMessageToQueue", "Microsoft.Azure.WebJobs.Host.EndToEndTests.AsyncChainEndToEndTests.QueueToQueueAsync", "Microsoft.Azure.WebJobs.Host.EndToEndTests.AsyncChainEndToEndTests.QueueToBlobAsync", + "Microsoft.Azure.WebJobs.Host.EndToEndTests.AsyncChainEndToEndTests.AlwaysFails", "Microsoft.Azure.WebJobs.Host.EndToEndTests.AsyncChainEndToEndTests.BlobToBlobAsync", "Microsoft.Azure.WebJobs.Host.EndToEndTests.AsyncChainEndToEndTests.ReadResultBlob", "Job host started", @@ -157,16 +159,16 @@ public async Task TraceWriterLogging() await host.StopAsync(); - bool hasError = string.Join(Environment.NewLine, trace.Traces.Where(p => p.Contains("Error"))).Any(); + bool hasError = string.Join(Environment.NewLine, trace.Traces.Where(p => p.Message.Contains("Error"))).Any(); if (!hasError) { Assert.Equal(14, trace.Traces.Count); - Assert.NotNull(trace.Traces.SingleOrDefault(p => p.Contains("User TraceWriter log"))); - Assert.NotNull(trace.Traces.SingleOrDefault(p => p.Contains("User TextWriter log (TestParam)"))); - Assert.NotNull(trace.Traces.SingleOrDefault(p => p.Contains("Another User TextWriter log"))); + Assert.NotNull(trace.Traces.SingleOrDefault(p => p.Message.Contains("User TraceWriter log"))); + Assert.NotNull(trace.Traces.SingleOrDefault(p => p.Message.Contains("User TextWriter log (TestParam)"))); + Assert.NotNull(trace.Traces.SingleOrDefault(p => p.Message.Contains("Another User TextWriter log"))); string[] consoleOutputLines = consoleOutput.ToString().Trim().Split(new string[] { Environment.NewLine }, StringSplitOptions.None); - Assert.Equal(16, consoleOutputLines.Length); + Assert.Equal(17, consoleOutputLines.Length); Assert.Null(consoleOutputLines.SingleOrDefault(p => p.Contains("User TraceWriter log"))); Assert.Null(consoleOutputLines.SingleOrDefault(p => p.Contains("User TextWriter log (TestParam)"))); } @@ -175,6 +177,33 @@ public async Task TraceWriterLogging() Console.SetOut(hold); } + [Fact] + public void FunctionFailures_LogsExpectedTraceEvent() + { + TestTraceWriter trace = new TestTraceWriter(TraceLevel.Verbose); + _hostConfig.Tracing.Tracers.Add(trace); + JobHost host = new JobHost(_hostConfig); + + MethodInfo methodInfo = GetType().GetMethod("AlwaysFails"); + try + { + host.Call(methodInfo); + } + catch {} + + // We expect 3 error messages total + TraceEvent[] traceErrors = trace.Traces.Where(p => p.Level == TraceLevel.Error).ToArray(); + Assert.Equal(3, traceErrors.Length); + + // Ensure that all errors include the same exception, with function + // invocation details + FunctionInvocationException functionException = traceErrors.First().Exception as FunctionInvocationException; + Assert.NotNull(functionException); + Assert.NotEqual(Guid.Empty, functionException.InstanceId); + Assert.Equal(string.Format("{0}.{1}", methodInfo.DeclaringType.FullName, methodInfo.Name), functionException.MethodName); + Assert.True(traceErrors.All(p => functionException == p.Exception)); + } + [NoAutomaticTrigger] public static async Task WriteStartDataMessageToQueue( [Queue(Queue1Name)] ICollector queueMessages, @@ -187,6 +216,12 @@ public static async Task WriteStartDataMessageToQueue( await nonSdkBlob.WriteAsync(messageBytes, 0, messageBytes.Length); } + [NoAutomaticTrigger] + public static void AlwaysFails() + { + throw new Exception("Kaboom!"); + } + public static async Task QueueToQueueAsync( [QueueTrigger(Queue1Name)] string message, [Queue(Queue2Name)] IAsyncCollector output, diff --git a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/ServiceBusEndToEndTests.cs b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/ServiceBusEndToEndTests.cs index 6dc91c1a6..e508d8f2b 100644 --- a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/ServiceBusEndToEndTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/ServiceBusEndToEndTests.cs @@ -117,8 +117,8 @@ public async Task CustomMessageProcessorTest() // in addition to verifying that our custom processor was called, we're also // verifying here that extensions can log to the TraceWriter - Assert.Equal(4, trace.Traces.Count(p => p.Contains("Custom processor Begin called!"))); - Assert.Equal(4, trace.Traces.Count(p => p.Contains("Custom processor End called!"))); + Assert.Equal(4, trace.Traces.Count(p => p.Message.Contains("Custom processor Begin called!"))); + Assert.Equal(4, trace.Traces.Count(p => p.Message.Contains("Custom processor End called!"))); } finally { diff --git a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/SingletonEndToEndTests.cs b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/SingletonEndToEndTests.cs index d9c2bb94e..450e09090 100644 --- a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/SingletonEndToEndTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/SingletonEndToEndTests.cs @@ -196,7 +196,7 @@ public async Task SingletonFunction_Exception_LeaseReleasedImmediately() exception = ex; } - Assert.Equal("Kaboom!", exception.Message); + Assert.Equal("Exception while executing function: TestJobs.SingletonJob", exception.Message); VerifyLeaseState(method, null, LeaseState.Available, LeaseStatus.Unlocked); host.Stop(); diff --git a/test/Microsoft.Azure.WebJobs.Host.TestCommon/TestTraceWriter.cs b/test/Microsoft.Azure.WebJobs.Host.TestCommon/TestTraceWriter.cs index e61f29e40..435f36422 100644 --- a/test/Microsoft.Azure.WebJobs.Host.TestCommon/TestTraceWriter.cs +++ b/test/Microsoft.Azure.WebJobs.Host.TestCommon/TestTraceWriter.cs @@ -9,16 +9,15 @@ namespace Microsoft.Azure.WebJobs.Host.TestCommon { public class TestTraceWriter : TraceWriter { - public Collection Traces = new Collection(); + public Collection Traces = new Collection(); public TestTraceWriter(TraceLevel level) : base(level) { } - public override void Trace(TraceLevel level, string source, string message, Exception ex) + public override void Trace(TraceEvent traceEvent) { - string trace = string.Format("{0} {1} {2} {3}", level, source, message, ex); - Traces.Add(trace); + Traces.Add(traceEvent); } } } diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Bindings/TraceWriter/TextWriterTraceAdapterTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Bindings/TraceWriter/TextWriterTraceAdapterTests.cs index 15029ce35..589bbd69d 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Bindings/TraceWriter/TextWriterTraceAdapterTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Bindings/TraceWriter/TextWriterTraceAdapterTests.cs @@ -23,7 +23,7 @@ public TextWriterTraceAdapterTests() [Fact] public void Write_SingleCharacterWrites_BuffersUntilNewline() { - _mockTraceWriter.Setup(p => p.Trace(TraceLevel.Info, null, "Mathew\r\n", null)); + _mockTraceWriter.Setup(p => p.Trace(It.Is(q => q.Level == TraceLevel.Info && q.Message == "Mathew\r\n"))); _adapter.Write('M'); _adapter.Write('a'); @@ -39,10 +39,10 @@ public void Write_SingleCharacterWrites_BuffersUntilNewline() [Fact] public void Write_VariousWriteOverloads_BuffersUntilNewline() { - _mockTraceWriter.Setup(p => p.Trace(TraceLevel.Info, null, "=====================\r\n", null)); - _mockTraceWriter.Setup(p => p.Trace(TraceLevel.Info, null, "TestData123456True=====================\r\n", null)); - _mockTraceWriter.Setup(p => p.Trace(TraceLevel.Info, null, "This is a new line\r\n", null)); - _mockTraceWriter.Setup(p => p.Trace(TraceLevel.Info, null, "This is some more text", null)); + _mockTraceWriter.Setup(p => p.Trace(It.Is(q => q.Level == TraceLevel.Info && q.Message == "=====================\r\n"))); + _mockTraceWriter.Setup(p => p.Trace(It.Is(q => q.Level == TraceLevel.Info && q.Message == "TestData123456True=====================\r\n"))); + _mockTraceWriter.Setup(p => p.Trace(It.Is(q => q.Level == TraceLevel.Info && q.Message == "This is a new line\r\n"))); + _mockTraceWriter.Setup(p => p.Trace(It.Is(q => q.Level == TraceLevel.Info && q.Message == "This is some more text"))); _mockTraceWriter.Setup(p => p.Flush()); _adapter.Write("=====================\r\n"); @@ -59,7 +59,7 @@ public void Write_VariousWriteOverloads_BuffersUntilNewline() [Fact] public void Flush_FlushesRemainingBuffer() { - _mockTraceWriter.Setup(p => p.Trace(TraceLevel.Info, null, "This is a test", null)); + _mockTraceWriter.Setup(p => p.Trace(It.Is(q => q.Level == TraceLevel.Info && q.Message == "This is a test"))); _mockTraceWriter.Setup(p => p.Flush()); _adapter.Write("This"); diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/CompositeTraceWriterTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/CompositeTraceWriterTests.cs index 068ecf48a..311df995a 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/CompositeTraceWriterTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/CompositeTraceWriterTests.cs @@ -26,10 +26,10 @@ public CompositeTraceWriterTests() [Fact] 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)); + _mockTraceWriter.Setup(p => p.Trace(It.Is(q => q.Level == TraceLevel.Warning && q.Source == "TestSource" && q.Message == "Test Warning" && q.Exception == null))); + _mockTraceWriter.Setup(p => p.Trace(It.Is(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(TraceLevel.Error, "TestSource", "Test Error With Exception", ex)); + _mockTraceWriter.Setup(p => p.Trace(It.Is(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")); @@ -46,6 +46,29 @@ public void Trace_DelegatesToInnerTraceWriterAndTextWriter() _mockTraceWriter.VerifyAll(); } + [Fact] + public void Trace_CustomProperties() + { + TraceEvent capturedEvent = null; + _mockTraceWriter.Setup(p => p.Trace(It.IsAny())) + .Callback(p => + { + capturedEvent = p; + }); + _mockTextWriter.Setup(p => p.WriteLine("Test Warning")); + + TraceEvent traceEvent = new TraceEvent(TraceLevel.Warning, "Test Warning", "Test Source"); + traceEvent.Properties.Add("Test", "Test Property"); + + _traceWriter.Trace(traceEvent); + + _mockTraceWriter.VerifyAll(); + _mockTextWriter.VerifyAll(); + + Assert.Same(traceEvent, capturedEvent); + Assert.Equal("Test Property", capturedEvent.Properties["Test"]); + } + [Fact] public void Flush_FlushesInnerTraceWriterAndTextWriter() { diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/ConsoleTraceWriterTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/ConsoleTraceWriterTests.cs index 08b722ad9..2b394a889 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/ConsoleTraceWriterTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/ConsoleTraceWriterTests.cs @@ -36,15 +36,39 @@ public void Trace_FiltersBySourceAndLevel() { _mockTextWriter.Setup(p => p.WriteLine("Test Information")); - _mockTraceWriter.Setup(p => p.Trace(TraceLevel.Info, Host.TraceSource.Host, "Test Information", null)); - _mockTraceWriter.Setup(p => p.Trace(TraceLevel.Info, "TestSource", "Test Information With Source", null)); - _mockTraceWriter.Setup(p => p.Trace(TraceLevel.Info, null, "Test Information No Source", null)); - _mockTraceWriter.Setup(p => p.Trace(TraceLevel.Warning, null, "Test Warning", null)); - _mockTraceWriter.Setup(p => p.Trace(TraceLevel.Error, null, "Test Error", null)); - _mockTraceWriter2.Setup(p => p.Trace(TraceLevel.Error, null, "Test Error", null)); + _mockTraceWriter.Setup(p => p.Trace(It.Is( + q => q.Level == TraceLevel.Info && + q.Source == Host.TraceSource.Host && + q.Message == "Test Information"))); + _mockTraceWriter.Setup(p => p.Trace(It.Is( + q => q.Level == TraceLevel.Info && + q.Source == "TestSource" && + q.Message == "Test Information With Source"))); + _mockTraceWriter.Setup(p => p.Trace(It.Is( + q => q.Level == TraceLevel.Info && + q.Source == null && + q.Message == "Test Information No Source"))); + _mockTraceWriter.Setup(p => p.Trace(It.Is(q => + q.Level == TraceLevel.Warning && + q.Source == null && + q.Message == "Test Warning"))); + _mockTraceWriter.Setup(p => p.Trace(It.Is(q => + q.Level == TraceLevel.Error && + q.Source == null && + q.Message == "Test Error"))); + _mockTraceWriter2.Setup(p => p.Trace(It.Is(q => + q.Level == TraceLevel.Error && + q.Source == null && + q.Message == "Test Error"))); Exception ex = new Exception("Kaboom!"); - _mockTraceWriter.Setup(p => p.Trace(TraceLevel.Error, null, "Test Error With Exception", ex)); - _mockTraceWriter2.Setup(p => p.Trace(TraceLevel.Error, null, "Test Error With Exception", ex)); + _mockTraceWriter.Setup(p => p.Trace(It.Is(q => + q.Level == TraceLevel.Error && + q.Source == null && + q.Message == "Test Error With Exception"))); + _mockTraceWriter2.Setup(p => p.Trace(It.Is(q => + q.Level == TraceLevel.Error && + q.Source == null && + q.Message == "Test Error With Exception"))); // expect this to be logged to both tracer1 and textWriter _traceWriter.Info("Test Information", Host.TraceSource.Host); @@ -101,7 +125,10 @@ public void MapTraceLevel_PerformsCorrectMapping(string source, TraceLevel level public void ConsoleLevel_CanBeChangedWhileRunning() { _mockTextWriter.Setup(p => p.WriteLine("Test Information")); - _mockTraceWriter.Setup(p => p.Trace(TraceLevel.Info, null, "Test Information", null)); + _mockTraceWriter.Setup(p => p.Trace(It.Is(q => + q.Level == TraceLevel.Info && + q.Source == null && + q.Message == "Test Information"))); _traceWriter.Info("Test Information"); diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/TraceWriterFunctionInstanceLoggerTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/TraceWriterFunctionInstanceLoggerTests.cs index a47d1eec1..ff85028b2 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/TraceWriterFunctionInstanceLoggerTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/TraceWriterFunctionInstanceLoggerTests.cs @@ -7,20 +7,20 @@ using System.Threading.Tasks; using Microsoft.Azure.WebJobs.Host.Loggers; using Microsoft.Azure.WebJobs.Host.Protocols; -using Moq; +using Microsoft.Azure.WebJobs.Host.TestCommon; using Xunit; namespace Microsoft.Azure.WebJobs.Host.UnitTests.Loggers { public class TraceWriterFunctionInstanceLoggerTests { - private readonly Mock _mockTraceWriter; + private readonly TestTraceWriter _traceWriter; private readonly TraceWriterFunctionInstanceLogger _logger; public TraceWriterFunctionInstanceLoggerTests() { - _mockTraceWriter = new Mock(MockBehavior.Strict, TraceLevel.Warning); - _logger = new TraceWriterFunctionInstanceLogger(_mockTraceWriter.Object); + _traceWriter = new TestTraceWriter(TraceLevel.Verbose); + _logger = new TraceWriterFunctionInstanceLogger(_traceWriter); } [Fact] @@ -35,11 +35,13 @@ public async Task LogFunctionStartedAsync_CallsTraceWriter() ReasonDetails = "TestReason" }; - _mockTraceWriter.Setup(p => p.Trace(TraceLevel.Info, Host.TraceSource.Execution, "Executing: 'TestJob' - Reason: 'TestReason'", null)); - await _logger.LogFunctionStartedAsync(message, CancellationToken.None); - _mockTraceWriter.VerifyAll(); + Assert.Equal(1, _traceWriter.Traces.Count); + TraceEvent traceEvent = _traceWriter.Traces[0]; + Assert.Equal(TraceLevel.Info, traceEvent.Level); + Assert.Equal(Host.TraceSource.Execution, traceEvent.Source); + Assert.Equal("Executing: 'TestJob' - Reason: 'TestReason'", traceEvent.Message); } [Fact] @@ -47,11 +49,13 @@ public async Task LogFunctionCompletedAsync_CallsTraceWriter() { FunctionDescriptor descriptor = new FunctionDescriptor { - ShortName = "TestJob" + ShortName = "TestJob", + FullName = "TestNamespace.TestJob" }; FunctionCompletedMessage successMessage = new FunctionCompletedMessage { - Function = descriptor + Function = descriptor, + FunctionInstanceId = Guid.NewGuid() }; Exception ex = new Exception("Kaboom!"); @@ -62,14 +66,27 @@ public async Task LogFunctionCompletedAsync_CallsTraceWriter() FunctionInstanceId = new Guid("8d71c9e3-e809-4cfb-bb78-48ae25c7d26d") }; - _mockTraceWriter.Setup(p => p.Trace(TraceLevel.Info, Host.TraceSource.Execution, "Executed: 'TestJob' (Succeeded)", null)); - _mockTraceWriter.Setup(p => p.Trace(TraceLevel.Error, Host.TraceSource.Execution, "Executed: 'TestJob' (Failed)", ex)); - _mockTraceWriter.Setup(p => p.Trace(TraceLevel.Error, Host.TraceSource.Host, " Function had errors. See Azure WebJobs SDK dashboard for details. Instance ID is '8d71c9e3-e809-4cfb-bb78-48ae25c7d26d'", null)); - await _logger.LogFunctionCompletedAsync(successMessage, CancellationToken.None); await _logger.LogFunctionCompletedAsync(failureMessage, CancellationToken.None); - _mockTraceWriter.VerifyAll(); + Assert.Equal(3, _traceWriter.Traces.Count); + + TraceEvent traceEvent = _traceWriter.Traces[0]; + Assert.Equal(TraceLevel.Info, traceEvent.Level); + Assert.Equal(Host.TraceSource.Execution, traceEvent.Source); + Assert.Equal("Executed: 'TestJob' (Succeeded)", traceEvent.Message); + + traceEvent = _traceWriter.Traces[1]; + Assert.Equal(TraceLevel.Error, traceEvent.Level); + Assert.Equal(Host.TraceSource.Execution, traceEvent.Source); + Assert.Equal("Executed: 'TestJob' (Failed)", traceEvent.Message); + Assert.Same(ex, traceEvent.Exception); + + traceEvent = _traceWriter.Traces[2]; + Assert.Equal(TraceLevel.Error, traceEvent.Level); + Assert.Equal(Host.TraceSource.Host, traceEvent.Source); + Assert.Equal(" Function had errors. See Azure WebJobs SDK dashboard for details. Instance ID is '8d71c9e3-e809-4cfb-bb78-48ae25c7d26d'", traceEvent.Message); + Assert.Same(ex, traceEvent.Exception); } } } diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/PublicSurfaceTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/PublicSurfaceTests.cs index e0a9ab977..a16b77df3 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/PublicSurfaceTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/PublicSurfaceTests.cs @@ -126,7 +126,9 @@ public void WebJobsHostPublicSurface_LimitedToSpecificTypes() "StorageClientFactory", "StorageClientFactoryContext", "BindingDataProvider", - "IBindingDataProvider" + "IBindingDataProvider", + "FunctionInvocationException", + "TraceEvent" }; AssertPublicTypes(expected, assembly); diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Singleton/SingletonManagerTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Singleton/SingletonManagerTests.cs index c1f7a7e27..eeba39c12 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Singleton/SingletonManagerTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Singleton/SingletonManagerTests.cs @@ -94,10 +94,10 @@ public async Task TryLockAsync_CreatesBlobLease_WithAutoRenewal() await _singletonManager.ReleaseLockAsync(lockHandle, cancellationToken); // verify the traces - Assert.Equal(1, _trace.Traces.Count(p => p.Contains("Verbose WebJobs.Execution Waiting for Singleton lock (testid)"))); - Assert.Equal(1, _trace.Traces.Count(p => p.Contains("Verbose WebJobs.Execution Singleton lock acquired (testid)"))); - Assert.Equal(renewCount, _trace.Traces.Count(p => p.Contains("Renewing Singleton lock (testid)"))); - Assert.Equal(1, _trace.Traces.Count(p => p.Contains("Verbose WebJobs.Execution Singleton lock released (testid)"))); + Assert.Equal(1, _trace.Traces.Count(p => p.ToString().Contains("Verbose WebJobs.Execution Waiting for Singleton lock (testid)"))); + Assert.Equal(1, _trace.Traces.Count(p => p.ToString().Contains("Verbose WebJobs.Execution Singleton lock acquired (testid)"))); + Assert.Equal(renewCount, _trace.Traces.Count(p => p.ToString().Contains("Renewing Singleton lock (testid)"))); + Assert.Equal(1, _trace.Traces.Count(p => p.ToString().Contains("Verbose WebJobs.Execution Singleton lock released (testid)"))); renewCount = 0; await Task.Delay(1000);