added diagnostic tracing to the service bus. Closes GH-913

DarthFubuMVC · Sep 1, 2015 · 196086d · 196086d
1 parent 22629a2
commit 196086d
Show file tree

Hide file tree

Showing 12 changed files with 203 additions and 12 deletions.
diff --git a/src/FubuMVC.Core/ServiceBus/Runtime/Envelope.cs b/src/FubuMVC.Core/ServiceBus/Runtime/Envelope.cs
@@ -1,6 +1,7 @@
 using System;
 using System.Collections.Generic;
 using FubuCore;
+using FubuMVC.Core.Diagnostics.Instrumentation;
 using FubuMVC.Core.Http;
 using FubuMVC.Core.ServiceBus.Runtime.Headers;
 using FubuMVC.Core.ServiceBus.Runtime.Invocation;
@@ -30,8 +31,11 @@ public class Envelope : HeaderWrapper
 
         [NonSerialized]
         private Lazy<object> _message;
-
-
+
+        /// <summary>
+        /// Used internally for logging
+        /// </summary>
+        [NonSerialized] internal ChainExecutionLog Log;
 
         public object Message
         {

diff --git a/src/FubuMVC.Core/ServiceBus/Runtime/Invocation/ChainInvoker.cs b/src/FubuMVC.Core/ServiceBus/Runtime/Invocation/ChainInvoker.cs
@@ -51,6 +51,12 @@ public virtual HandlerChain FindChain(Envelope envelope)
 
         public IInvocationContext ExecuteChain(Envelope envelope, HandlerChain chain)
         {
+            if (envelope.Log != null)
+            {
+                envelope.Log.RootChain = chain;
+                envelope.Log.StartSubject(chain);
+            }
+
             using (new ChainExecutionWatcher(_logger, chain, envelope))
             {
                 var context = new InvocationContext(envelope, chain);
@@ -63,6 +69,11 @@ public IInvocationContext ExecuteChain(Envelope envelope, HandlerChain chain)
                 finally
                 {
                     (behavior as IDisposable).CallIfNotNull(x => x.SafeDispose());
+
+                    if (envelope.Log != null)
+                    {
+                        envelope.Log.FinishSubject();
+                    }
                 }
 
                 return context;

diff --git a/src/FubuMVC.Core/ServiceBus/Runtime/Invocation/EnvelopeContext.cs b/src/FubuMVC.Core/ServiceBus/Runtime/Invocation/EnvelopeContext.cs
@@ -83,7 +83,7 @@ public virtual void Error(string correlationId, string message, Exception except
             _logger.Error(correlationId, message, exception);
         }
 
-        public virtual void Retry(Envelope envelope)
+        public void Retry(Envelope envelope)
         {
             _pipeline.Invoke(envelope, this);
         }

diff --git a/src/FubuMVC.Core/ServiceBus/Runtime/Invocation/EnvelopeLifecycle.cs b/src/FubuMVC.Core/ServiceBus/Runtime/Invocation/EnvelopeLifecycle.cs
@@ -13,9 +13,9 @@ public EnvelopeLifecycle(IContainer container)
             _container = container;
         }
 
-        public IEnvelopeContext StartNew(IHandlerPipeline pipeline)
+        public IEnvelopeContext StartNew(IHandlerPipeline pipeline, Envelope envelope)
         {
-            return _container.With(pipeline).GetInstance<T>();
+            return _container.With(pipeline).With(envelope).GetInstance<T>();
         }
     }
 }
diff --git a/src/FubuMVC.Core/ServiceBus/Runtime/Invocation/HandlerPipeline.cs b/src/FubuMVC.Core/ServiceBus/Runtime/Invocation/HandlerPipeline.cs
@@ -76,7 +76,7 @@ public virtual void Invoke(Envelope envelope, IEnvelopeContext context)
         public void Receive(Envelope envelope)
         {
             envelope.UseSerializer(_serializer);
-            using (var context = _lifecycle.StartNew(this))
+            using (var context = _lifecycle.StartNew(this, envelope))
             {
                 context.InfoMessage(() => new EnvelopeReceived { Envelope = envelope.ToToken() });
                 Invoke(envelope, context);
@@ -87,7 +87,7 @@ public void Receive(Envelope envelope)
 
         public void InvokeNow(Envelope envelope)
         {
-            using (var context = _lifecycle.StartNew(this))
+            using (var context = _lifecycle.StartNew(this, envelope))
             {
                 Invoke(envelope, context);
             }

diff --git a/src/FubuMVC.Core/ServiceBus/Runtime/Invocation/IEnvelopeLifecycle.cs b/src/FubuMVC.Core/ServiceBus/Runtime/Invocation/IEnvelopeLifecycle.cs
@@ -2,6 +2,6 @@ namespace FubuMVC.Core.ServiceBus.Runtime.Invocation
 {
     public interface IEnvelopeLifecycle
     {
-        IEnvelopeContext StartNew(IHandlerPipeline pipeline);
+        IEnvelopeContext StartNew(IHandlerPipeline pipeline, Envelope envelope);
     }
 }
diff --git a/src/FubuMVC.Core/ServiceBus/Runtime/Invocation/InvocationContext.cs b/src/FubuMVC.Core/ServiceBus/Runtime/Invocation/InvocationContext.cs
@@ -1,6 +1,7 @@
 using System;
 using System.Collections.Generic;
 using FubuCore.Binding;
+using FubuMVC.Core.Diagnostics.Instrumentation;
 using FubuMVC.Core.Http;
 using FubuMVC.Core.Runtime;
 using FubuMVC.Core.ServiceBus.Configuration;
@@ -18,6 +19,11 @@ public InvocationContext(Envelope envelope, HandlerChain chain)
         {
             if (envelope == null) throw new ArgumentNullException("envelope");
 
+            if (envelope.Log != null)
+            {
+                Set(typeof(IChainExecutionLog), envelope.Log);
+            }
+
             var currentChain = new CurrentChain(chain, _emptyDictionary);
             Set(typeof(ICurrentChain), currentChain);
 

diff --git a/src/FubuMVC.Core/ServiceBus/Runtime/Invocation/ProductionDiagnosticEnvelopeContext.cs b/src/FubuMVC.Core/ServiceBus/Runtime/Invocation/ProductionDiagnosticEnvelopeContext.cs
@@ -1,13 +1,36 @@
+using System;
 using FubuCore.Dates;
 using FubuCore.Logging;
+using FubuMVC.Core.Diagnostics.Instrumentation;
 using FubuMVC.Core.ServiceBus.Runtime.Cascading;
 
 namespace FubuMVC.Core.ServiceBus.Runtime.Invocation
 {
     public class ProductionDiagnosticEnvelopeContext : EnvelopeContext
     {
-        public ProductionDiagnosticEnvelopeContext(ILogger logger, ISystemTime systemTime, IChainInvoker invoker, IOutgoingSender outgoing, IHandlerPipeline pipeline) : base(logger, systemTime, invoker, outgoing, pipeline)
+        private readonly Envelope _envelope;
+        private readonly IExecutionLogger _executionLogger;
+        protected readonly ChainExecutionLog _log;
+
+        public ProductionDiagnosticEnvelopeContext(ILogger logger, ISystemTime systemTime, IChainInvoker invoker, IOutgoingSender outgoing, IHandlerPipeline pipeline, Envelope envelope, IExecutionLogger executionLogger) : base(logger, systemTime, invoker, outgoing, pipeline)
+        {
+            _envelope = envelope;
+            _executionLogger = executionLogger;
+            _log = new ChainExecutionLog();
+
+            _envelope.Log = _log;
+        }
+
+        public sealed override void Dispose()
+        {
+            _log.MarkFinished();
+            _executionLogger.Record(_log, _envelope);
+        }
+
+        public sealed override void Error(string correlationId, string message, Exception exception)
         {
+            _log.LogException(exception);
+            base.Error(correlationId, message, exception);
         }
     }
 }
diff --git a/src/FubuMVC.Core/ServiceBus/Runtime/Invocation/VerboseDiagnosticEnvelopeContext.cs b/src/FubuMVC.Core/ServiceBus/Runtime/Invocation/VerboseDiagnosticEnvelopeContext.cs
@@ -1,13 +1,35 @@
+using System;
 using FubuCore.Dates;
 using FubuCore.Logging;
+using FubuMVC.Core.Diagnostics.Instrumentation;
 using FubuMVC.Core.ServiceBus.Runtime.Cascading;
 
 namespace FubuMVC.Core.ServiceBus.Runtime.Invocation
 {
-    public class VerboseDiagnosticEnvelopeContext : EnvelopeContext
+    public class VerboseDiagnosticEnvelopeContext : ProductionDiagnosticEnvelopeContext
     {
-        public VerboseDiagnosticEnvelopeContext(ILogger logger, ISystemTime systemTime, IChainInvoker invoker, IOutgoingSender outgoing, IHandlerPipeline pipeline) : base(logger, systemTime, invoker, outgoing, pipeline)
+        public VerboseDiagnosticEnvelopeContext(ILogger logger, ISystemTime systemTime, IChainInvoker invoker, IOutgoingSender outgoing, IHandlerPipeline pipeline, Envelope envelope, IExecutionLogger executionLogger) : base(logger, systemTime, invoker, outgoing, pipeline, envelope, executionLogger)
         {
         }
+
+        public override void InfoMessage<T>(Func<T> func)
+        {
+            var message = func();
+            _log.Log(message);
+            logger.InfoMessage(message);
+        }
+
+        public override void DebugMessage<T>(Func<T> func)
+        {
+            var message = func();
+            _log.Log(message);
+            logger.DebugMessage(message);
+        }
+
+        public override void InfoMessage<T>(T message)
+        {
+            _log.Log(message);
+            base.InfoMessage(message);
+        }
     }
 }
diff --git a/src/FubuMVC.IntegrationTesting/FubuMVC.IntegrationTesting.csproj b/src/FubuMVC.IntegrationTesting/FubuMVC.IntegrationTesting.csproj
@@ -209,6 +209,7 @@
     <Compile Include="Serenity\BrowserType_selection_tester.cs" />
     <Compile Include="Serenity\SerenitySystemTester.cs" />
     <Compile Include="Serenity\WaitTester.cs" />
+    <Compile Include="ServiceBus\end_to_end_diagnostics_specs.cs" />
     <Compile Include="ServiceBus\Publishing\PublishingConfigurationIntegrationTester.cs" />
     <Compile Include="StaticFiles\reading_static_file_content_with_katana.cs" />
     <Compile Include="Routing\end_to_end_route_alias_tester.cs" />

diff --git a/src/FubuMVC.IntegrationTesting/ServiceBus/end_to_end_diagnostics_specs.cs b/src/FubuMVC.IntegrationTesting/ServiceBus/end_to_end_diagnostics_specs.cs
@@ -0,0 +1,124 @@
+using System;
+using System.Collections.Generic;
+using System.Collections.Specialized;
+using System.Diagnostics;
+using System.Linq;
+using System.Threading;
+using FubuCore;
+using FubuCore.Logging;
+using FubuMVC.Core;
+using FubuMVC.Core.Diagnostics.Instrumentation;
+using FubuMVC.Core.ServiceBus;
+using FubuMVC.Core.ServiceBus.Configuration;
+using NUnit.Framework;
+using Shouldly;
+using TraceLevel = FubuMVC.Core.TraceLevel;
+
+namespace FubuMVC.IntegrationTesting.ServiceBus
+{
+    [TestFixture]
+    public class end_to_end_diagnostics_specs
+    {
+        [Test]
+        public void see_tracing_logs_in_production_mode_happy_path()
+        {
+            var registry = new FubuRegistry();
+            registry.ServiceBus.Enable(true);
+            registry.Features.Diagnostics.Enable(TraceLevel.Production);
+            registry.ServiceBus.EnableInMemoryTransport();
+
+            using (var runtime = registry.ToRuntime())
+            {
+                var bus = runtime.Get<IServiceBus>();
+
+                bus.Consume(new TracedInput());
+
+                var history = runtime.Get<IChainExecutionHistory>();
+
+                var log = history.RecentReports().Single(x => x.RootChain != null && x.RootChain.InputType() == typeof(TracedInput));
+
+                log.Activity.AllSteps().Any(x => x.Log is StringMessage).ShouldBeFalse();
+
+                var headers = log.Request["Headers"].ShouldBeOfType<NameValueCollection>();
+                headers.AllKeys.Each(x => Debug.WriteLine("{0} = {1}", x, headers[x]));
+            }
+        }
+
+        [Test]
+        public void get_error_messages_in_production_mode()
+        {
+            var registry = new FubuRegistry();
+            registry.ServiceBus.Enable(true);
+            registry.Features.Diagnostics.Enable(TraceLevel.Production);
+            registry.ServiceBus.EnableInMemoryTransport();
+
+            using (var runtime = registry.ToRuntime())
+            {
+                var bus = runtime.Get<IServiceBus>();
+
+                bus.Consume(new TracedInput { Fail = true });
+
+
+                var history = runtime.Get<IChainExecutionHistory>();
+
+                var log = history.RecentReports().Single(x => x.RootChain != null && x.RootChain.InputType() == typeof(TracedInput));
+
+                log.Activity.AllSteps().Any(x => x.Log is ExceptionReport).ShouldBeTrue();
+                log.HadException.ShouldBeTrue();
+            }
+        }
+
+        [Test]
+        public void see_tracing_logs_in_verbose_mode_happy_path()
+        {
+            var registry = new FubuRegistry();
+            registry.ServiceBus.Enable(true);
+            registry.Features.Diagnostics.Enable(TraceLevel.Verbose);
+            registry.ServiceBus.EnableInMemoryTransport();
+
+            using (var runtime = registry.ToRuntime())
+            {
+                var bus = runtime.Get<IServiceBus>();
+
+                bus.Consume(new TracedInput());
+
+                var history = runtime.Get<IChainExecutionHistory>();
+
+                var log = history.RecentReports().Single(x => x.RootChain != null && x.RootChain.InputType() == typeof(TracedInput));
+
+                log.Request["Headers"].ShouldBeOfType<NameValueCollection>();
+
+                log.Activity.AllSteps().Any().ShouldBeTrue();
+                log.Activity.AllSteps().Any(x => x.Log is StringMessage).ShouldBeTrue();
+
+                log.Activity.AllSteps().Each(x => Debug.WriteLine(x));
+            }
+        }
+    }
+
+    public class TracedInput
+    {
+        public bool Fail { get; set; }
+    }
+
+    public class TracedInputConsumer
+    {
+        private readonly ILogger _logger;
+
+        public TracedInputConsumer(ILogger logger)
+        {
+            _logger = logger;
+        }
+
+        public void Consume(TracedInput input)
+        {
+            _logger.Info("I got into TracedInputConsumer");
+
+            Thread.Sleep(1.Seconds());
+            if (input.Fail)
+            {
+                throw new DivideByZeroException("You shall not pass!");
+            }
+        }
+    }
+}
diff --git a/src/FubuMVC.Tests/ServiceBus/Runtime/Invocation/HandlerPipelineTester.cs b/src/FubuMVC.Tests/ServiceBus/Runtime/Invocation/HandlerPipelineTester.cs
@@ -103,7 +103,7 @@ protected override void beforeEach()
             ClassUnderTest.Expect(x => x.FindContinuation(theEnvelope, theContext))
                           .Return(theContinuation);
 
-            MockFor<IEnvelopeLifecycle>().Stub(x => x.StartNew(ClassUnderTest))
+            MockFor<IEnvelopeLifecycle>().Stub(x => x.StartNew(ClassUnderTest, theEnvelope))
                 .Return(theContext);
 
             ClassUnderTest.Receive(theEnvelope);