Added basic OpenTelemetry tracing #23

onyx-ws · Dec 27, 2019 · cd16779 · cd16779
1 parent 43018c5
commit cd16779
Show file tree

Hide file tree

Showing 9 changed files with 129 additions and 68 deletions.
diff --git a/src/Ianvs/Common/IanvsContext.cs b/src/Ianvs/Common/IanvsContext.cs
@@ -6,6 +6,7 @@
 using Microsoft.AspNetCore.Http;
 using Onyx.Ianvs.Dispatch;
 using System.Security.Claims;
+using OpenTelemetry.Trace;
 
 namespace Onyx.Ianvs.Common
 {
@@ -16,7 +17,6 @@ public class IanvsContext
         public string Method { get; set; }
         public string Protocol { get; set; }
         public DateTimeOffset ReceivedAt { get; internal set; }
-
         public Ianvs::Endpoint MatchedEndpoint { get; internal set; }
         public Ianvs::Operation MatchedOperation { get; internal set; }
         public Ianvs::Server TargetServer { get; internal set; }
@@ -36,5 +36,7 @@ public class IanvsContext
         public List<SecurityRequirement> Security { get; set; }
         public SecurityRequirement SecurityRequirement { get; internal set; }
         public ClaimsPrincipal Principal { get; internal set; }
+        public ISpan TraceSpan { get; set; }
+        public Tracer Tracer { get; set; }
     }
 }
diff --git a/src/Ianvs/Dispatch/HttpDispatcher.cs b/src/Ianvs/Dispatch/HttpDispatcher.cs
@@ -1,9 +1,9 @@
 using Microsoft.Extensions.Logging;
 using Onyx.Ianvs.Common;
 using Onyx.Ianvs.Http;
+using OpenTelemetry.Trace;
 using System;
 using System.Collections.Generic;
-using System.IO;
 using System.Linq;
 using System.Net.Http;
 using System.Text;
@@ -58,7 +58,7 @@ public async Task<object> Dispatch(IanvsContext ianvsContext)
         /// </summary>
         /// <param name="ianvsContext">Ianvs processing context</param>
         /// <returns>The HTTP request message to send to the backend</returns>
-        public object PrepareRequest(IanvsContext ianvsContext)
+        public object PrepareRequest(IanvsContext ianvsContext, ISpan egressSpan)
         {
             string targetUrl = $"{ianvsContext.TargetUrl}?";
             foreach (var parameter in ianvsContext.MatchedOperation.Parameters)
@@ -92,6 +92,13 @@ public object PrepareRequest(IanvsContext ianvsContext)
                     ianvsContext.Variables.GetValueOrDefault("{request.header.content-Type}", "application/json")
                 );
             }
+            if (egressSpan.Context.IsValid)
+            {
+                ianvsContext.Tracer.TextFormat.Inject(
+                    egressSpan.Context,
+                    downstreamMsg.Headers,
+                    (headers, name, value) => headers.Add(name, value));
+            }
             return downstreamMsg;
         }
 

diff --git a/src/Ianvs/Dispatch/IDispatcher.cs b/src/Ianvs/Dispatch/IDispatcher.cs
@@ -1,4 +1,5 @@
 using Onyx.Ianvs.Common;
+using OpenTelemetry.Trace;
 using System;
 using System.Collections.Generic;
 using System.Linq;
@@ -9,7 +10,7 @@ namespace Onyx.Ianvs.Dispatch
     public interface IDispatcher
     {
         Task<object> Dispatch(IanvsContext ianvsContext);
-        object PrepareRequest(IanvsContext ianvsContext);
+        object PrepareRequest(IanvsContext ianvsContext, ISpan egressSpan);
         void ProcessResponse(IanvsContext ianvsContext);
     }
 }
diff --git a/src/Ianvs/Egress/EgressMiddleware.cs b/src/Ianvs/Egress/EgressMiddleware.cs
@@ -2,6 +2,7 @@
 using Microsoft.Extensions.Logging;
 using Onyx.Ianvs.Common;
 using Onyx.Ianvs.Dispatch;
+using OpenTelemetry.Trace;
 using System;
 using System.Diagnostics;
 using System.Threading.Tasks;
@@ -27,38 +28,44 @@ public EgressMiddleware(RequestDelegate next, ILogger<EgressMiddleware> logger)
             _logger = logger;
         }
 
-        public async Task InvokeAsync(HttpContext httpContext, IanvsContext ianvsContext, DispatcherFactory dispatcherFactory)
+        public async Task InvokeAsync(HttpContext httpContext, IanvsContext ianvsContext, DispatcherFactory dispatcherFactory, Tracer tracer)
         {
+            var egressSpan = tracer.StartSpan("ianvs-egress");
+
             // TODO: Implement Protocol Translation - e.g. REST to gRPC
             // https://github.com/onyx-ws/ianvs/issues/11
 
             // Get the dispatcher matching for the backend
             ianvsContext.Dispatcher = dispatcherFactory.GetDispatcher(ianvsContext.MatchedEndpoint.Protocol);
+            egressSpan.AddEvent("Preparing Request");
             // Prepare backend request message
-            ianvsContext.BackendMessage.Message = ianvsContext.Dispatcher.PrepareRequest(ianvsContext);
+            ianvsContext.BackendMessage.Message = ianvsContext.Dispatcher.PrepareRequest(ianvsContext, egressSpan);
+            egressSpan.AddEvent("Request prepared");
 
             Stopwatch backendTimer = new Stopwatch();
             backendTimer.Start();
+
+            egressSpan.AddEvent("Sending backend request");
 
             _logger.LogInformation($"{Environment.MachineName} {ianvsContext.RequestId} Sending request to backend service {ianvsContext.MatchedOperation.OperationId} {ianvsContext.MatchedOperation.Method} {ianvsContext.MatchedEndpoint.Url} {ianvsContext.TargetServer.Url}");
             Task<object> backendResponse = ianvsContext.Dispatcher.Dispatch(ianvsContext);
 
             _logger.LogInformation($"{Environment.MachineName} {ianvsContext.RequestId} Waiting for backend service response");
             backendResponse.Wait();
-
             backendTimer.Stop();
+            egressSpan.AddEvent("Backend service response received");
 
             ianvsContext.BackendResponse = new BackendMessage()
             {
                 Message = backendResponse.Result
             };
 
             ianvsContext.Dispatcher.ProcessResponse(ianvsContext);
-
             _logger.LogInformation($"{Environment.MachineName} {ianvsContext.RequestId} Backend service response received in {backendTimer.ElapsedMilliseconds}ms {ianvsContext.StatusCode}");
 
+            egressSpan.End();
             // Egress middleware is the last in the Ianvs processing chain
-            // No call is made to _next
+            // No further calls made to _next
         }
     }
 }
diff --git a/src/Ianvs/IanvsBuilder.cs b/src/Ianvs/IanvsBuilder.cs
@@ -16,6 +16,11 @@
 using Onyx.Ianvs.Dispatch;
 using Onyx.Ianvs.Security;
 using Onyx.Ianvs.Security.Jwt;
+using OpenTelemetry.Hosting;
+using OpenTelemetry.Resources;
+using OpenTelemetry.Trace.Configuration;
+using OpenTelemetry.Trace.Samplers;
+using OpenTelemetry.Trace;
 
 namespace Onyx.Ianvs
 {
@@ -55,6 +60,8 @@ public static void AddIanvs(this IServiceCollection services)
             AddIanvsLoadBalancing(services);
             // Add Egress services
             AddIanvsEgress(services);
+            // Add Telemtry
+            AddTelemetry(services);
         }
 
         private static void AddIanvsCore(IServiceCollection services)
@@ -80,5 +87,26 @@ private static void AddIanvsLoadBalancing(IServiceCollection services)
             services.TryAddSingleton<LoadBalancerFactory>();
             services.TryAddSingleton<RandomLoadBalancer>();
         }
+
+        private static void AddTelemetry(IServiceCollection services)
+        {
+            services.AddOpenTelemetry(builder =>
+            {
+                builder
+                    .SetSampler(new AlwaysSampleSampler())
+                    // Once otelcol is out of alpha, switch to it and remove the Jaeger exporter
+                    // https://github.com/open-telemetry/opentelemetry-collector
+                    .UseJaeger(o =>
+                    {
+                        o.ServiceName = "ianvs-gateway";
+                        o.AgentHost = Environment.GetEnvironmentVariable("JAEGER_AGENT_HOST");
+                    })
+                    .AddRequestCollector()
+                    .SetResource(new Resource(new Dictionary<string, object>() { { "service.name", "ianvs-gateway" } }));
+            });
+
+            TracerFactory tracerFactory = services.BuildServiceProvider().GetService<TracerFactory>();
+            services.AddSingleton(tracerFactory.GetTracer("ianvs-gateway"));
+        }
     }
 }
diff --git a/src/Ianvs/Ingress/IngressMiddleware.cs b/src/Ianvs/Ingress/IngressMiddleware.cs
@@ -4,6 +4,8 @@
 using Microsoft.Extensions.Primitives;
 using Onyx.Ianvs.Common;
 using Onyx.Ianvs.Http;
+using OpenTelemetry.Trace;
+using OpenTelemetry.Trace.Configuration;
 using System;
 using System.Collections.Generic;
 using System.Diagnostics;
@@ -23,68 +25,75 @@ public IngressMiddleware(RequestDelegate next, ILogger<IngressMiddleware> logger
             _logger = logger;
         }
 
-        public async Task InvokeAsync(HttpContext httpContext, IanvsContext ianvsContext)
+        public async Task InvokeAsync(HttpContext httpContext, IanvsContext ianvsContext, Tracer tracer)
         {
-            try
+            using (tracer.StartActiveSpan("ianvs-ingress", SpanKind.Server, out ISpan ianvsSpan))
             {
-                // TODO: Implement Ingress operations
-                Stopwatch ianvsTimer = new Stopwatch();
-                ianvsTimer.Start();
+                ianvsContext.TraceSpan = ianvsSpan;
+                ianvsContext.Tracer = tracer;
 
-                ianvsContext.ReceivedAt = DateTimeOffset.UtcNow;
-                ianvsContext.RequestId = httpContext.TraceIdentifier;
-                ianvsContext.Url = httpContext.Request.GetDisplayUrl();
-                ianvsContext.Method = httpContext.Request.Method;
-                ianvsContext.Protocol = httpContext.Request.Protocol;
+                try
+                {
+                    // TODO: Implement Ingress operations
+                    Stopwatch ianvsTimer = new Stopwatch();
+                    ianvsTimer.Start();
 
-                _logger.LogInformation($"{Environment.MachineName} {ianvsContext.RequestId} Request starting {ianvsContext.Protocol} {ianvsContext.Method} {ianvsContext.Url}");
-                _logger.LogInformation($"{Environment.MachineName} {ianvsContext.RequestId} Request recieved at {ianvsContext.ReceivedAt}");
+                    ianvsContext.ReceivedAt = DateTimeOffset.UtcNow;
+                    ianvsContext.RequestId = httpContext.TraceIdentifier;
+                    ianvsContext.Url = httpContext.Request.GetDisplayUrl();
+                    ianvsContext.Method = httpContext.Request.Method;
+                    ianvsContext.Protocol = httpContext.Request.Protocol;
 
-                if (httpContext.Request.Headers.TryGetValue("x-ianvs-trackid", out StringValues trackId))
-                {
-                    ianvsContext.TrackId = trackId.ToString();
-                }
-                else
-                {
-                    ianvsContext.TrackId = Guid.NewGuid().ToString();
-                }
+                    _logger.LogInformation($"{Environment.MachineName} {ianvsContext.RequestId} Request starting {ianvsContext.Protocol} {ianvsContext.Method} {ianvsContext.Url}");
+                    _logger.LogInformation($"{Environment.MachineName} {ianvsContext.RequestId} Request recieved at {ianvsContext.ReceivedAt}");
+
+                    if (httpContext.Request.Headers.TryGetValue("x-ianvs-trackid", out StringValues trackId))
+                    {
+                        ianvsContext.TrackId = trackId.ToString();
+                    }
+                    else
+                    {
+                        ianvsContext.TrackId = Guid.NewGuid().ToString();
+                    }
+
+                    PromoteVariables(httpContext, ianvsContext);
+
+                    // When response is starting capture and log time Ianvs took to process
+                    httpContext.Response.OnStarting(async () =>
+                    {
+                        ianvsContext.ProcessingTime = ianvsTimer.ElapsedMilliseconds;
+                        ianvsContext.ResponseSentAt = DateTimeOffset.UtcNow;
+                        _logger.LogInformation($"{Environment.MachineName} {ianvsContext.RequestId} Response being sent at {ianvsContext.ResponseSentAt}.");
+                        _logger.LogInformation($"{Environment.MachineName} {ianvsContext.RequestId} Processing took {ianvsContext.ProcessingTime}ms");
+                    });
 
-                PromoteVariables(httpContext, ianvsContext);
+                    // When response is completed (i.e. Received by client) capture and log time it took
+                    httpContext.Response.OnCompleted(async () =>
+                    {
+                        ianvsTimer.Stop();
+                        ianvsContext.ProcessingCompletedAt = DateTimeOffset.UtcNow;
+                        _logger.LogInformation($"{Environment.MachineName} {ianvsContext.RequestId} Response received by client at {ianvsContext.ProcessingCompletedAt}");
+                        _logger.LogInformation($"{Environment.MachineName} {ianvsContext.RequestId} Request finished in {ianvsTimer.ElapsedMilliseconds}ms {httpContext.Response.StatusCode}");
+                    });
 
-                // When response is starting capture and log time Ianvs took to process
-                httpContext.Response.OnStarting(async () =>
+                    await _next(httpContext);
+
+                    httpContext.Response.StatusCode = ianvsContext.StatusCode;
+                    await httpContext.Response.WriteAsync(ianvsContext.Response);
+                }
+
+                catch (Exception e)
                 {
-                    ianvsContext.ProcessingTime = ianvsTimer.ElapsedMilliseconds;
+                    // Ok, something wrong happened - call the SWAT team
+                    _logger.LogError($"{Environment.MachineName} {ianvsContext.RequestId} Error occured processing request");
+                    _logger.LogError($"{Environment.MachineName} {ianvsContext.RequestId} Error: {e.ToString()}");
+
                     ianvsContext.ResponseSentAt = DateTimeOffset.UtcNow;
-                    _logger.LogInformation($"{Environment.MachineName} {ianvsContext.RequestId} Response being sent at {ianvsContext.ResponseSentAt}.");
-                    _logger.LogInformation($"{Environment.MachineName} {ianvsContext.RequestId} Processing took {ianvsContext.ProcessingTime}ms");
-                });
+                    ianvsContext.StatusCode = 500;
+                    httpContext.Response.StatusCode = ianvsContext.StatusCode;
 
-                // When response is completed (i.e. Received by client) capture and log time it took
-                httpContext.Response.OnCompleted(async () =>
-                {
-                    ianvsTimer.Stop();
-                    ianvsContext.ProcessingCompletedAt = DateTimeOffset.UtcNow;
-                    _logger.LogInformation($"{Environment.MachineName} {ianvsContext.RequestId} Response received by client at {ianvsContext.ProcessingCompletedAt}");
-                    _logger.LogInformation($"{Environment.MachineName} {ianvsContext.RequestId} Request finished in {ianvsTimer.ElapsedMilliseconds}ms {httpContext.Response.StatusCode}");
-                });
-
-                await _next(httpContext);
-
-                httpContext.Response.StatusCode = ianvsContext.StatusCode;
-                await httpContext.Response.WriteAsync(ianvsContext.Response);
-            }
-            catch(Exception e)
-            {
-                // Ok, something wrong happened - call the SWAT team
-                _logger.LogError($"{Environment.MachineName} {ianvsContext.RequestId} Error occured processing request");
-                _logger.LogError($"{Environment.MachineName} {ianvsContext.RequestId} Error: {e.ToString()}");
-
-                ianvsContext.ResponseSentAt = DateTimeOffset.UtcNow;
-                ianvsContext.StatusCode = 500;
-                httpContext.Response.StatusCode = ianvsContext.StatusCode;
-
-                await httpContext.Response.WriteAsync(string.Empty);
+                    await httpContext.Response.WriteAsync(string.Empty);
+                }
             }
         }
 

diff --git a/src/Ianvs/Onyx.Ianvs.csproj b/src/Ianvs/Onyx.Ianvs.csproj
@@ -10,6 +10,9 @@
   <ItemGroup>
     <PackageReference Include="Microsoft.IdentityModel.Protocols.OpenIdConnect" Version="5.6.0" />
     <PackageReference Include="Microsoft.VisualStudio.Azure.Containers.Tools.Targets" Version="1.9.5" />
+    <PackageReference Include="OpenTelemetry.Collector.AspNetCore" Version="0.2.0-alpha.147" />
+    <PackageReference Include="OpenTelemetry.Exporter.Jaeger" Version="0.2.0-alpha.147" />
+    <PackageReference Include="OpenTelemetry.Hosting" Version="0.2.0-alpha.147" />
   </ItemGroup>
 
 </Project>
diff --git a/src/Ianvs/Routing/RoutingMiddleware.cs b/src/Ianvs/Routing/RoutingMiddleware.cs
@@ -7,6 +7,7 @@
 using System.Threading.Tasks;
 using Onyx.Ianvs.Configuration.Store;
 using Microsoft.Extensions.Logging;
+using OpenTelemetry.Trace;
 
 namespace Onyx.Ianvs.Routing
 {
@@ -25,13 +26,15 @@ public RoutingMiddleware(RequestDelegate next, ILogger<RoutingMiddleware> logger
         }
 
         public async Task InvokeAsync(HttpContext httpContext, Ianvs::IanvsContext ianvsContext,
-            IIanvsConfigurationStore ianvsConfiguration)
+            IIanvsConfigurationStore ianvsConfiguration, Tracer tracer)
         {
             // TODO: Implement Routing
             // WIP - https://github.com/onyx-ws/ianvs/issues/1
             // TODO: Handle endpoints with templates
             // https://github.com/onyx-ws/ianvs/issues/2
 
+            var routingSpan = tracer.StartSpan("ianvs-routing");
+
             // Find a matching Path
             string requestPath = httpContext.Request.Path;
             _logger.LogInformation($"{Environment.MachineName} {ianvsContext.RequestId} Looking for a configured route");
@@ -43,6 +46,7 @@ public async Task InvokeAsync(HttpContext httpContext, Ianvs::IanvsContext ianvs
             {
                 // Path not found
                 // Return 404 - Not Found (https://tools.ietf.org/html/rfc7231#section-6.5.4)
+                routingSpan.AddEvent("Route not matched");
                 _logger.LogWarning($"{Environment.MachineName} {ianvsContext.RequestId} No configured route found");
                 ianvsContext.StatusCode = 404;
                 ianvsContext.Response = "";
@@ -51,7 +55,7 @@ public async Task InvokeAsync(HttpContext httpContext, Ianvs::IanvsContext ianvs
             {
                 ianvsContext.MatchedEndpoint = matchedEndpoint;
                 _logger.LogInformation($"{Environment.MachineName} {ianvsContext.RequestId} Possible matching route found at {ianvsContext.MatchedEndpoint.Url}");
-                
+
                 // Path found - Match Operation
                 string requestMethod = httpContext.Request.Method;
                 Ianvs::Operation matchedOperation = matchedEndpoint.Operations.FirstOrDefault(
@@ -62,6 +66,7 @@ public async Task InvokeAsync(HttpContext httpContext, Ianvs::IanvsContext ianvs
                 {
                     // Operation not found
                     // Return 405 - Method Not Allowed (https://tools.ietf.org/html/rfc7231#section-6.5.5)
+                    routingSpan.AddEvent("Method not matched");
                     _logger.LogWarning($"{Environment.MachineName} {ianvsContext.RequestId} No configured operation found");
                     ianvsContext.StatusCode = 405;
                     ianvsContext.Response = "";
@@ -70,12 +75,16 @@ public async Task InvokeAsync(HttpContext httpContext, Ianvs::IanvsContext ianvs
                 {
                     // Operation found
                     // Simulate operation
+                    routingSpan.AddEvent("Route found");
+
                     ianvsContext.MatchedOperation = matchedOperation;
                     _logger.LogInformation($"{Environment.MachineName} {ianvsContext.RequestId} Matched route at {ianvsContext.MatchedOperation.OperationId} {ianvsContext.MatchedOperation.Method} {ianvsContext.MatchedEndpoint.Url}");
 
                     await _next(httpContext);
                 }
             }
+
+            routingSpan.End();
         }
     }
 }