Feature/fix tracing (#297)

* hacked together tracing fix by wrapping middleware delegate in another delegate

* #227 have re-implemented tracing, cleaned up trace names, probably still need some refactoring and tests as this was a bit of a hack job

* #227 bit of checking for when we dont want to use tracing, also removed a unit test for websockets that wasnt a unit test, i stuck it there because i wanted the code coverage and now im paying the price, will have to work out a better way to do it

* #227 a bit of refactoring to make this work better, still a bit hacky...would like to revisit the whole thing one day

* #227 dont need this

* #227 or this

* #227 small refactor

src/Ocelot/Configuration/Creator/HttpHandlerOptionsCreator.cs

@@ -1,13 +1,24 @@
-using Ocelot.Configuration.File;
+using Butterfly.Client.Tracing;
+using Ocelot.Configuration.File;
+using Ocelot.Requester;
 
 namespace Ocelot.Configuration.Creator
 {
     public class HttpHandlerOptionsCreator : IHttpHandlerOptionsCreator
     {
+        private IServiceTracer _tracer;
+
+        public HttpHandlerOptionsCreator(IServiceTracer tracer)
+        {
+            _tracer = tracer;
+        }
+
         public HttpHandlerOptions Create(FileReRoute fileReRoute)
         {
+            var useTracing = _tracer.GetType() != typeof(FakeServiceTracer) ? fileReRoute.HttpHandlerOptions.UseTracing : false;
+
             return new HttpHandlerOptions(fileReRoute.HttpHandlerOptions.AllowAutoRedirect,
-                fileReRoute.HttpHandlerOptions.UseCookieContainer, fileReRoute.HttpHandlerOptions.UseTracing);
+                fileReRoute.HttpHandlerOptions.UseCookieContainer, useTracing);
         }
     }
 }

src/Ocelot/Infrastructure/Extensions/StringValuesExtensions.cs

@@ -0,0 +1,17 @@
+using Microsoft.Extensions.Primitives;
+using System.Linq;
+
+namespace Ocelot.Infrastructure.Extensions
+{
+    internal static class StringValueExtensions
+    {
+        public static string GetValue(this StringValues stringValues)
+        {
+            if (stringValues.Count == 1)
+            {
+                return stringValues;
+            }
+            return stringValues.ToArray().LastOrDefault();
+        }
+    }
+}

src/Ocelot/Logging/IOcelotLogger.cs

@@ -0,0 +1,22 @@
+using System;
+
+namespace Ocelot.Logging
+{
+    /// <summary>
+    /// Thin wrapper around the DotNet core logging framework, used to allow the scopedDataRepository to be injected giving access to the Ocelot RequestId
+    /// </summary>
+    public interface IOcelotLogger
+    {
+        void LogTrace(string message, params object[] args);
+        void LogDebug(string message, params object[] args);
+        void LogInformation(string message, params object[] args);
+        void LogError(string message, Exception exception);
+        void LogError(string message, params object[] args);
+        void LogCritical(string message, Exception exception);
+
+        /// <summary>
+        /// The name of the type the logger has been built for.
+        /// </summary>
+        string Name { get; }
+    }
+}

src/Ocelot/Logging/IOcelotLoggerFactory.cs

@@ -1,27 +1,7 @@
-using System;
+namespace Ocelot.Logging
-
-namespace Ocelot.Logging
 {
     public interface IOcelotLoggerFactory
     {
         IOcelotLogger CreateLogger<T>();
     }
-
-    /// <summary>
-    /// Thin wrapper around the DotNet core logging framework, used to allow the scopedDataRepository to be injected giving access to the Ocelot RequestId
-    /// </summary>
-    public interface IOcelotLogger
-    {
-        void LogTrace(string message, params object[] args);
-        void LogDebug(string message, params object[] args);
-        void LogInformation(string message, params object[] args);
-        void LogError(string message, Exception exception);
-        void LogError(string message, params object[] args);
-        void LogCritical(string message, Exception exception);
-
-        /// <summary>
-        /// The name of the type the logger has been built for.
-        /// </summary>
-        string Name { get; }
-    }
 }

src/Ocelot/Logging/OcelotDiagnosticListener.cs

@@ -3,18 +3,48 @@ using Microsoft.AspNetCore.Http;
 using Microsoft.Extensions.DiagnosticAdapter;
 using Butterfly.Client.AspNetCore;
 using Butterfly.OpenTracing;
+using Ocelot.Middleware;
+using Butterfly.Client.Tracing;
+using System.Linq;
+using System.Collections.Generic;
+using Ocelot.Infrastructure.Extensions;
+using Microsoft.Extensions.Logging;
+using Ocelot.Requester;
 
 namespace Ocelot.Logging
 {
     public class OcelotDiagnosticListener
     {
+        private IServiceTracer _tracer;
         private IOcelotLogger _logger;
 
-        public OcelotDiagnosticListener(IOcelotLoggerFactory factory)
+        public OcelotDiagnosticListener(IOcelotLoggerFactory factory, IServiceTracer tracer)
         {
+            _tracer = tracer;
             _logger = factory.CreateLogger<OcelotDiagnosticListener>();
         }
 
+        [DiagnosticName("Ocelot.MiddlewareException")]
+        public virtual void OcelotMiddlewareException(Exception exception, DownstreamContext context, string name)
+        {
+            _logger.LogTrace($"Ocelot.MiddlewareException: {name}; {exception.Message}");
+            Event(context.HttpContext, $"Ocelot.MiddlewareStarted: {name}; {context.HttpContext.Request.Path}");
+        }
+
+        [DiagnosticName("Ocelot.MiddlewareStarted")]
+        public virtual void OcelotMiddlewareStarted(DownstreamContext context, string name)
+        {
+            _logger.LogTrace($"Ocelot.MiddlewareStarted: {name}; {context.HttpContext.Request.Path}");
+            Event(context.HttpContext, $"Ocelot.MiddlewareStarted: {name}; {context.HttpContext.Request.Path}");
+        }
+
+        [DiagnosticName("Ocelot.MiddlewareFinished")]
+        public virtual void OcelotMiddlewareFinished(DownstreamContext context, string name)
+        {
+            _logger.LogTrace($"OcelotMiddlewareFinished: {name}; {context.HttpContext.Request.Path}");
+            Event(context.HttpContext, $"OcelotMiddlewareFinished: {name}; {context.HttpContext.Request.Path}");
+        }
+
         [DiagnosticName("Microsoft.AspNetCore.MiddlewareAnalysis.MiddlewareStarting")]
         public virtual void OnMiddlewareStarting(HttpContext httpContext, string name)
         {
@@ -37,7 +67,27 @@ namespace Ocelot.Logging
 
         private void Event(HttpContext httpContext, string @event)
         {  
+            // Hack - if the user isnt using tracing the code gets here and will blow up on 
+            // _tracer.Tracer.TryExtract. We already use the fake tracer for another scenario
+            // so sticking it here as well..I guess we need a factory for this but no idea
+            // how to hook that into the diagnostic framework at the moment.
+            if(_tracer.GetType() == typeof(FakeServiceTracer))
+            {
+                return;
+            }
+
             var span = httpContext.GetSpan();
+            if(span == null)
+            {
+                var spanBuilder = new SpanBuilder($"server {httpContext.Request.Method} {httpContext.Request.Path}");
+                if (_tracer.Tracer.TryExtract(out var spanContext, httpContext.Request.Headers, (c, k) => c[k].GetValue(),
+                    c => c.Select(x => new KeyValuePair<string, string>(x.Key, x.Value.GetValue())).GetEnumerator()))
+                {
+                    spanBuilder.AsChildOf(spanContext);
+                };
+                span = _tracer.Start(spanBuilder);        
+                httpContext.SetSpan(span);   
+            }
             span?.Log(LogField.CreateNew().Event(@event));
         }
     }

src/Ocelot/Middleware/OcelotMiddlewareExtensions.cs

@@ -65,6 +65,8 @@
             rest of asp.net..
             */
 
+            builder.Properties["analysis.NextMiddlewareName"] = "TransitionToOcelotMiddleware";
+
             builder.Use(async (context, task) =>
             {
                 var downstreamContext = new DownstreamContext(context);

src/Ocelot/Middleware/Pipeline/OcelotPipelineBuilderExtensions.cs

@@ -3,6 +3,7 @@
 // Removed code and changed RequestDelete to OcelotRequestDelete, HttpContext to DownstreamContext, removed some exception handling messages
 
 using System;
+using System.Diagnostics;
 using System.Linq;
 using System.Linq.Expressions;
 using System.Reflection;
@@ -75,7 +76,28 @@ namespace Ocelot.Middleware.Pipeline
                 var instance = ActivatorUtilities.CreateInstance(app.ApplicationServices, middleware, ctorArgs);
                 if (parameters.Length == 1)
                 {
-                    return (OcelotRequestDelegate)methodinfo.CreateDelegate(typeof(OcelotRequestDelegate), instance);
+                    var ocelotDelegate = (OcelotRequestDelegate)methodinfo.CreateDelegate(typeof(OcelotRequestDelegate), instance);
+                    var diagnosticListener = (DiagnosticListener)app.ApplicationServices.GetService(typeof(DiagnosticListener));
+                    var middlewareName = ocelotDelegate.Target.GetType().Name;
+
+                    OcelotRequestDelegate wrapped = context => {
+                        try
+                        {
+                            Write(diagnosticListener, "Ocelot.MiddlewareStarted", middlewareName, context);
+                            return ocelotDelegate(context);
+                        }
+                        catch(Exception ex)
+                        {
+                            Write(diagnosticListener, "Ocelot.MiddlewareException", middlewareName, context);
+                            throw ex;
+                        }
+                        finally
+                        {
+                            Write(diagnosticListener, "Ocelot.MiddlewareFinished", middlewareName, context);
+                        }
+                    };
+
+                    return wrapped;
                 }
 
                 var factory = Compile<object>(methodinfo, parameters);
@@ -93,6 +115,14 @@ namespace Ocelot.Middleware.Pipeline
             });
         }
 
+        private static void Write(DiagnosticListener diagnosticListener, string message, string middlewareName, DownstreamContext context)
+        {
+            if(diagnosticListener != null)
+            {
+                diagnosticListener.Write(message, new { name = middlewareName, context = context });
+            }
+        }
+
         public static IOcelotPipelineBuilder MapWhen(this IOcelotPipelineBuilder app, Predicate predicate, Action<IOcelotPipelineBuilder> configuration)
         {
             if (app == null)

src/Ocelot/Requester/DelegatingHandlerHandlerFactory.cs

@@ -2,6 +2,7 @@ using System;
 using System.Collections.Generic;
 using System.Linq;
 using System.Net.Http;
+using Butterfly.Client.Tracing;
 using Microsoft.Extensions.DependencyInjection;
 using Ocelot.Configuration;
 using Ocelot.Logging;

src/Ocelot/Requester/FakeServiceTracer.cs

@@ -0,0 +1,17 @@
+using Butterfly.Client.Tracing;
+using Butterfly.OpenTracing;
+
+namespace Ocelot.Requester
+{
+    public class FakeServiceTracer : IServiceTracer
+    {
+        public ITracer Tracer { get; }
+        public string ServiceName { get; }
+        public string Environment { get; }
+        public string Identity { get; }
+        public ISpan Start(ISpanBuilder spanBuilder)
+        {
+            return null;
+        }
+    }
+}

src/Ocelot/Requester/TracingHandlerFactory.cs

@@ -1,5 +1,4 @@
 using Butterfly.Client.Tracing;
-using Butterfly.OpenTracing;
 using Ocelot.Infrastructure.RequestData;
 
 namespace Ocelot.Requester
@@ -22,16 +21,4 @@ namespace Ocelot.Requester
             return new OcelotHttpTracingHandler(_tracer, _repo);
         }
     }
-
-    public class FakeServiceTracer : IServiceTracer
-    {
-        public ITracer Tracer { get; }
-        public string ServiceName { get; }
-        public string Environment { get; }
-        public string Identity { get; }
-        public ISpan Start(ISpanBuilder spanBuilder)
-        {
-            throw new System.NotImplementedException();
-        }
-    }
 }

test/Ocelot.ManualTest/appsettings.json

@@ -2,7 +2,7 @@
   "Logging": {
     "IncludeScopes": false,
     "LogLevel": {
-      "Default": "Debug",
+      "Default": "Error",
       "System": "Error",
       "Microsoft": "Error"
     }

test/Ocelot.ManualTest/configuration.json

@@ -99,7 +99,7 @@
       "HttpHandlerOptions": {
         "AllowAutoRedirect": true,
         "UseCookieContainer": true,
-        "UseTracing": false
+        "UseTracing": true
       },
       "QoSOptions": {
         "ExceptionsAllowedBeforeBreaking": 3,

test/Ocelot.UnitTests/Configuration/HttpHandlerOptionsCreatorTests.cs

@@ -1,6 +1,10 @@
-using Ocelot.Configuration;
+using System;
+using Butterfly.Client.Tracing;
+using Butterfly.OpenTracing;
+using Ocelot.Configuration;
 using Ocelot.Configuration.Creator;
 using Ocelot.Configuration.File;
+using Ocelot.Requester;
 using Shouldly;
 using TestStack.BDDfy;
 using Xunit;
@@ -9,13 +13,54 @@ namespace Ocelot.UnitTests.Configuration
 {
     public class HttpHandlerOptionsCreatorTests
     {
-        private readonly IHttpHandlerOptionsCreator _httpHandlerOptionsCreator;
+        private IHttpHandlerOptionsCreator _httpHandlerOptionsCreator;
         private FileReRoute _fileReRoute;
         private HttpHandlerOptions _httpHandlerOptions;
+        private IServiceTracer _serviceTracer;
 
         public HttpHandlerOptionsCreatorTests()
         {
-            _httpHandlerOptionsCreator = new HttpHandlerOptionsCreator();
+            _serviceTracer = new FakeServiceTracer();
+            _httpHandlerOptionsCreator = new HttpHandlerOptionsCreator(_serviceTracer);
+        }
+
+        [Fact]
+        public void should_not_use_tracing_if_fake_tracer_registered()
+        {
+            var fileReRoute = new FileReRoute 
+            {
+                HttpHandlerOptions = new FileHttpHandlerOptions
+                {
+                    UseTracing = true
+                }
+            };
+
+            var expectedOptions = new HttpHandlerOptions(false, false, false);
+
+            this.Given(x => GivenTheFollowing(fileReRoute))
+                .When(x => WhenICreateHttpHandlerOptions())
+                .Then(x => ThenTheFollowingOptionsReturned(expectedOptions))
+                .BDDfy();
+        }
+
+        [Fact]
+        public void should_use_tracing_if_real_tracer_registered()
+        {
+            var fileReRoute = new FileReRoute 
+            {
+                HttpHandlerOptions = new FileHttpHandlerOptions
+                {
+                    UseTracing = true
+                }
+            };
+
+            var expectedOptions = new HttpHandlerOptions(false, false, true);
+
+            this.Given(x => GivenTheFollowing(fileReRoute))
+                .And(x => GivenARealTracer())
+                .When(x => WhenICreateHttpHandlerOptions())
+                .Then(x => ThenTheFollowingOptionsReturned(expectedOptions))
+                .BDDfy();
         }
 
         [Fact]
@@ -68,5 +113,27 @@ namespace Ocelot.UnitTests.Configuration
             _httpHandlerOptions.UseCookieContainer.ShouldBe(expected.UseCookieContainer);
             _httpHandlerOptions.UseTracing.ShouldBe(expected.UseTracing);
         }
+
+        private void GivenARealTracer()
+        {
+            var tracer = new RealTracer();
+            _httpHandlerOptionsCreator = new HttpHandlerOptionsCreator(tracer);
+        }
+
+        class RealTracer : IServiceTracer
+        {
+            public ITracer Tracer => throw new NotImplementedException();
+
+            public string ServiceName => throw new NotImplementedException();
+
+            public string Environment => throw new NotImplementedException();
+
+            public string Identity => throw new NotImplementedException();
+
+            public ISpan Start(ISpanBuilder spanBuilder)
+            {
+                throw new NotImplementedException();
+            }
+        }
     }
 }

test/Ocelot.UnitTests/WebSockets/WebSocketsProxyMiddlewareTests.cs

@@ -1,239 +0,0 @@
-using System;
-using System.Collections.Generic;
-using System.IO;
-using System.Net.WebSockets;
-using System.Text;
-using System.Threading;
-using System.Threading.Tasks;
-using Consul;
-using Microsoft.AspNetCore.Builder;
-using Microsoft.AspNetCore.Hosting;
-using Microsoft.Extensions.Configuration;
-using Microsoft.Extensions.DependencyInjection;
-using Microsoft.Extensions.Logging;
-using Newtonsoft.Json;
-using Ocelot.Configuration.File;
-using Ocelot.DependencyInjection;
-using Ocelot.Middleware;
-using Shouldly;
-using TestStack.BDDfy;
-using Xunit;
-
-namespace Ocelot.UnitTests.Websockets
-{
-    public class WebSocketsProxyMiddlewareTests : IDisposable
-    {
-        private IWebHost _firstDownstreamHost;
-        private readonly List<string> _firstRecieved;
-        private WebHostBuilder _ocelotBuilder;
-        private IWebHost _ocelotHost;
-
-        public WebSocketsProxyMiddlewareTests()
-        {
-            _firstRecieved = new List<string>();
-        }
-
-        [Fact]
-        public async Task should_proxy_websocket_input_to_downstream_service()
-        {
-            var downstreamPort = 5001;
-            var downstreamHost = "localhost";
-
-            var config = new FileConfiguration
-            {
-                ReRoutes = new List<FileReRoute>
-                {
-                    new FileReRoute
-                    {
-                        UpstreamPathTemplate = "/",
-                        DownstreamPathTemplate = "/ws",
-                        DownstreamScheme = "ws",
-                        DownstreamHostAndPorts = new List<FileHostAndPort>
-                        {
-                            new FileHostAndPort
-                            {
-                                Host = downstreamHost,
-                                Port = downstreamPort
-                            }
-                        }
-                    }
-                }
-            };
-
-            this.Given(_ => GivenThereIsAConfiguration(config))
-                .And(_ => StartFakeOcelotWithWebSockets())
-                .And(_ => StartFakeDownstreamService($"http://{downstreamHost}:{downstreamPort}", "/ws"))
-                .When(_ => StartClient("ws://localhost:5000/"))
-                .Then(_ => _firstRecieved.Count.ShouldBe(10))
-                .BDDfy();
-        }
-
-        public void Dispose()
-        {
-            _firstDownstreamHost?.Dispose();
-        }
-
-        public async Task StartFakeOcelotWithWebSockets()
-        {
-            _ocelotBuilder = new WebHostBuilder();
-            _ocelotBuilder.ConfigureServices(s =>
-            {
-                s.AddSingleton(_ocelotBuilder);
-                s.AddOcelot();
-            });
-            _ocelotBuilder.UseKestrel()
-                .UseUrls("http://localhost:5000")
-                .UseContentRoot(Directory.GetCurrentDirectory())
-                .ConfigureAppConfiguration((hostingContext, config) =>
-                {
-                    config.SetBasePath(hostingContext.HostingEnvironment.ContentRootPath);
-                    var env = hostingContext.HostingEnvironment;
-                    config.AddJsonFile("appsettings.json", optional: true, reloadOnChange: true)
-                        .AddJsonFile($"appsettings.{env.EnvironmentName}.json", optional: true, reloadOnChange: true);
-                    config.AddJsonFile("configuration.json");
-                    config.AddEnvironmentVariables();
-                })
-                .ConfigureLogging((hostingContext, logging) =>
-                {
-                    logging.AddConfiguration(hostingContext.Configuration.GetSection("Logging"));
-                    logging.AddConsole();
-                })
-                .Configure(app =>
-                {
-                    app.UseWebSockets();
-                    app.UseOcelot().Wait();
-                })
-                .UseIISIntegration();
-            _ocelotHost = _ocelotBuilder.Build();
-            await _ocelotHost.StartAsync();
-        }
-
-        public void GivenThereIsAConfiguration(FileConfiguration fileConfiguration)
-        {
-            var configurationPath = Path.Combine(AppContext.BaseDirectory, "configuration.json");
-
-            var jsonConfiguration = JsonConvert.SerializeObject(fileConfiguration);
-
-            if (File.Exists(configurationPath))
-            {
-                File.Delete(configurationPath);
-            }
-
-            File.WriteAllText(configurationPath, jsonConfiguration);
-        }
-
-        private async Task StartFakeDownstreamService(string url, string path)
-        {
-            _firstDownstreamHost = new WebHostBuilder()
-                .ConfigureServices(s => { }).UseKestrel()
-                .UseUrls(url)
-                .UseContentRoot(Directory.GetCurrentDirectory())
-                .ConfigureAppConfiguration((hostingContext, config) =>
-                {
-                    config.SetBasePath(hostingContext.HostingEnvironment.ContentRootPath);
-                    var env = hostingContext.HostingEnvironment;
-                    config.AddJsonFile("appsettings.json", optional: true, reloadOnChange: true)
-                        .AddJsonFile($"appsettings.{env.EnvironmentName}.json", optional: true, reloadOnChange: true);
-                    config.AddEnvironmentVariables();
-                })
-                .ConfigureLogging((hostingContext, logging) =>
-                {
-                    logging.AddConfiguration(hostingContext.Configuration.GetSection("Logging"));
-                    logging.AddConsole();
-                })
-                .Configure(app =>
-                {
-                    app.UseWebSockets();
-                    app.Use(async (context, next) =>
-                    {
-                        if (context.Request.Path == path)
-                        {
-                            if (context.WebSockets.IsWebSocketRequest)
-                            {
-                                WebSocket webSocket = await context.WebSockets.AcceptWebSocketAsync();
-                                await Echo(webSocket);
-                            }
-                            else
-                            {
-                                context.Response.StatusCode = 400;
-                            }
-                        }
-                        else
-                        {
-                            await next();
-                        }
-                    });
-                })
-                .UseIISIntegration().Build();
-            await _firstDownstreamHost.StartAsync();
-        }
-
-        private async Task StartClient(string url)
-        {
-            var client = new ClientWebSocket();
-
-            await client.ConnectAsync(new Uri(url), CancellationToken.None);
-
-            var sending = Task.Run(async () =>
-            {
-                string line = "test";
-                for (int i = 0; i < 10; i++)
-                {
-                    var bytes = Encoding.UTF8.GetBytes(line);
-
-                    await client.SendAsync(new ArraySegment<byte>(bytes), WebSocketMessageType.Text, true,
-                        CancellationToken.None);
-                    await Task.Delay(10);
-                }
-
-                await client.CloseOutputAsync(WebSocketCloseStatus.NormalClosure, "", CancellationToken.None);
-            });
-
-            var receiving = Task.Run(async () =>
-            {
-                var buffer = new byte[1024 * 4];
-
-                while (true)
-                {
-                    var result = await client.ReceiveAsync(new ArraySegment<byte>(buffer), CancellationToken.None);
-
-                    if (result.MessageType == WebSocketMessageType.Text)
-                    {
-                        _firstRecieved.Add(Encoding.UTF8.GetString(buffer, 0, result.Count));
-                    }
-
-                    else if (result.MessageType == WebSocketMessageType.Close)
-                    {
-                        await client.CloseAsync(WebSocketCloseStatus.NormalClosure, "", CancellationToken.None);
-                        break;
-                    }
-                }
-            });
-
-            await Task.WhenAll(sending, receiving);
-        }
-
-        private async Task Echo(WebSocket webSocket)
-        {
-            try
-            {
-                var buffer = new byte[1024 * 4];
-
-                var result = await webSocket.ReceiveAsync(new ArraySegment<byte>(buffer), CancellationToken.None);
-
-                while (!result.CloseStatus.HasValue)
-                {
-                    await webSocket.SendAsync(new ArraySegment<byte>(buffer, 0, result.Count), result.MessageType, result.EndOfMessage, CancellationToken.None);
-
-                    result = await webSocket.ReceiveAsync(new ArraySegment<byte>(buffer), CancellationToken.None);
-                }
-
-                await webSocket.CloseAsync(result.CloseStatus.Value, result.CloseStatusDescription, CancellationToken.None);
-            }
-            catch (Exception e)
-            {
-                Console.WriteLine(e);
-            }
-        }
-    }
-}