Add Logging via LibLog (#44)

* add logging via liblog

* update example app w/serilog to demonstrate logging levels

Author: austinlparker

README.md

@@ -65,4 +65,8 @@ var overrideTags = new Dictionary<string, object>
 };
 var tracerOptions = new Options("TEST_TOKEN").WithSatellite(satelliteOptions).WithTags(overrideTags);
 var tracer = new Tracer(tracerOptions);
-```
+```
+
+## Logging
+This tracer uses [LibLog](https://github.com/damianh/LibLog), a transparent logging abstraction that provides built-in support for NLog, Log4Net, Serilog, and Loupe.
+If you use a logging provider that isn't identified by LibLog, see [this gist](https://gist.github.com/damianh/fa529b8346a83f7f49a9) on how to implement a custom logging provider.

examples/LightStep.CSharpAspectTestApp/Program.cs

@@ -17,7 +17,7 @@ static void Main(string[] args)
             // create your tracer options, initialize it, assign it to the GlobalTracer
             var lsKey = Environment.GetEnvironmentVariable("LS_KEY");
             var lsSettings = new SatelliteOptions("collector.lightstep.com");
-            var lsOptions = new Options(lsKey).WithStatellite(lsSettings);
+            var lsOptions = new Options(lsKey).WithSatellite(lsSettings);
             var tracer = new Tracer(lsOptions);
 
             GlobalTracer.Register(tracer);

examples/LightStep.CSharpDITestApp/Program.cs

@@ -12,7 +12,7 @@ internal class Program
         public static void Main(string[] args)
         {
             // replace these options with your satellite and api key
-            var tracerOptions = new Options("TEST_TOKEN").WithStatellite(new SatelliteOptions("localhost", 9996, true));
+            var tracerOptions = new Options("TEST_TOKEN").WithSatellite(new SatelliteOptions("localhost", 9996, true));
             var container = new WindsorContainer();
             // during registration, pass your options to the concrete LightStep Tracer implementation
             container.Register(Component.For<ITracer>().ImplementedBy<Tracer>().DependsOn(Dependency.OnValue("options", tracerOptions)));            

examples/LightStep.CSharpTestApp/LightStep.CSharpTestApp.csproj

@@ -7,6 +7,8 @@
   </PropertyGroup>
   <ItemGroup>
     <PackageReference Include="OpenTracing" Version="0.12.0" />
+    <PackageReference Include="Serilog" Version="2.7.1" />
+    <PackageReference Include="Serilog.Sinks.Console" Version="3.1.1" />
   </ItemGroup>
   <ItemGroup>
     <ProjectReference Include="..\..\src\LightStep\LightStep.csproj" />

examples/LightStep.CSharpTestApp/Program.cs

@@ -3,16 +3,24 @@
 using System.Threading;
 using Google.Protobuf.WellKnownTypes;
 using OpenTracing.Util;
+using global::Serilog;
+using Serilog.Events;
+using Serilog.Sinks.SystemConsole;
 
 namespace LightStep.CSharpTestApp
 {
     internal class Program
     {
         private static void Main(string[] args)
         {
+            Log.Logger = new LoggerConfiguration()
+                .MinimumLevel.Debug()
+                .WriteTo.Console()
+                .CreateLogger();
+
             // substitute your own LS API Key here
             var lightStepSatellite = new SatelliteOptions("localhost", 9996, true);
-            var lightStepOptions = new Options("TEST_TOKEN").WithStatellite(lightStepSatellite);
+            var lightStepOptions = new Options("TEST_TOKEN").WithSatellite(lightStepSatellite);
             var tracer = new Tracer(lightStepOptions);
             GlobalTracer.Register(tracer);
 
@@ -21,16 +29,17 @@ private static void Main(string[] args)
                 {
                     scope.Span.Log("test");
                     tracer.ActiveSpan.Log($"iteration {i}");
-                    Console.WriteLine("sleeping for a bit");
+                    
                     Thread.Sleep(new Random().Next(5, 10));
                     var innerSpan = tracer.BuildSpan("childSpan").Start();
                     innerSpan.SetTag("innerTestTag", "true");
-                    Console.WriteLine("sleeping more...");
+                    
                     Thread.Sleep(new Random().Next(10, 20));
                     innerSpan.Finish();
                 }
 
             tracer.Flush();
+            Console.ReadKey();
         }
 
     }

src/LightStep/Collector/LightStepHttpClient.cs

@@ -1,12 +1,13 @@
 using System;
 using System.Collections.Generic;
-using System.IO;
+using System.Diagnostics;
 using System.Linq;
 using System.Net;
 using System.Net.Http;
 using System.Net.Http.Headers;
 using System.Threading.Tasks;
 using Google.Protobuf;
+using LightStep.Logging;
 
 namespace LightStep.Collector
 {
@@ -18,6 +19,7 @@ public class LightStepHttpClient
         private readonly Options _options;
         private HttpClient _client;
         private readonly string _url;
+        private static readonly ILog _logger = LogProvider.GetCurrentClassLogger();
 
         /// <summary>
         ///     Create a new client.
@@ -61,15 +63,15 @@ public async Task<ReportResponse> SendReport(ReportRequest report)
                 response.EnsureSuccessStatusCode();
                 var responseData = await response.Content.ReadAsStreamAsync();
                 responseValue = ReportResponse.Parser.ParseFrom(responseData);
+                _logger.Debug($"Report HTTP Response {response.StatusCode}");
             }
             catch (HttpRequestException ex)
             {
-                Console.WriteLine(ex);
-                Console.WriteLine("resetting httpclient");
+                _logger.WarnException("Exception caught while sending report, resetting HttpClient", ex);
                 _client.Dispose();
                 _client = new HttpClient();
             }
-
+            
             return responseValue;
         }
 
@@ -80,6 +82,10 @@ public async Task<ReportResponse> SendReport(ReportRequest report)
         /// <returns>A <see cref="ReportRequest" /></returns>
         public ReportRequest Translate(IEnumerable<SpanData> spans)
         {
+            _logger.Debug($"Serializing spans to proto.");
+            var timer = new Stopwatch();
+            timer.Start();
+
             var request = new ReportRequest
             {
                 Reporter = new Reporter
@@ -90,6 +96,9 @@ public ReportRequest Translate(IEnumerable<SpanData> spans)
             };
             _options.Tags.ToList().ForEach(t => request.Reporter.Tags.Add(new KeyValue().MakeKeyValueFromKvp(t)));
             spans.ToList().ForEach(span => request.Spans.Add(new Span().MakeSpanFromSpanData(span)));
+
+            timer.Stop();
+            _logger.Debug($"Serialization complete in {timer.ElapsedMilliseconds}ms. Request size: {request.CalculateSize()}b.");
             return request;
         }
     }

src/LightStep/LightStep.csproj

@@ -8,6 +8,11 @@
   <ItemGroup>
     <PackageReference Include="Google.Api.CommonProtos" Version="1.3.0" />
     <PackageReference Include="Google.Protobuf" Version="3.6.1" />
+    <PackageReference Include="LibLog" Version="5.0.3">
+      <PrivateAssets>all</PrivateAssets>
+      <IncludeAssets>runtime; build; native; contentfiles; analyzers</IncludeAssets>
+    </PackageReference>
+    <PackageReference Include="Microsoft.CSharp" Version="4.5.0" />
     <PackageReference Include="OpenTracing" Version="0.12.0" />
     <PackageReference Include="System.Json" Version="4.5.0" />
   </ItemGroup>

src/LightStep/LightStepSpanRecorder.cs

@@ -1,19 +1,23 @@
 using System;
 using System.Collections.Generic;
 using System.Linq;
+using LightStep.Logging;
 
 namespace LightStep
 {
     /// <inheritdoc />
     public sealed class LightStepSpanRecorder : ISpanRecorder
     {
         private List<SpanData> Spans { get; } = new List<SpanData>();
+        private static readonly ILog _logger = LogProvider.GetCurrentClassLogger();
 
         /// <inheritdoc />
         public void RecordSpan(SpanData span)
         {
+            _logger.Trace($"Waiting for lock in SpanRecorder.");
             lock (Spans)
             {
+                _logger.Trace($"Lock freed, adding new span: {span}");
                 Spans.Add(span);    
             }
 
@@ -22,8 +26,10 @@ public void RecordSpan(SpanData span)
         /// <inheritdoc />
         public List<SpanData> GetSpanBuffer()
         {
+            _logger.Trace("Waiting for lock in SpanRecorder");
             lock (Spans)
             {
+                _logger.Trace("Lock freed, getting span buffer.");
                 var currentSpans = Spans.ToList();
                 Spans.Clear();
                 return currentSpans;
@@ -34,8 +40,10 @@ public List<SpanData> GetSpanBuffer()
         /// <inheritdoc />
         public void ClearSpanBuffer()
         {
+            _logger.Trace("Waiting for lock in SpanRecorder.");
             lock (Spans)
             {
+                _logger.Trace("Lock freed, clearing span buffer.");
                 Spans.Clear();    
             }
 

src/LightStep/Options.cs

@@ -4,6 +4,7 @@
 using System.Linq;
 using System.Reflection;
 using System.Runtime.Versioning;
+using LightStep.Logging;
 
 namespace LightStep
 {
@@ -12,6 +13,8 @@ namespace LightStep
     /// </summary>
     public class Options
     {
+        private static readonly ILog _logger = LogProvider.GetCurrentClassLogger();
+
         /// <summary>
         ///     An identifier for the Tracer.
         /// </summary>
@@ -54,42 +57,49 @@ public class Options
 
         public Options WithToken(string token)
         {
+            _logger.Debug($"Setting access token to {token}");
             AccessToken = token;
             return this;
         }
 
         public Options WithHttp2()
         {
+            _logger.Debug("Enabling HTTP/2 support.");
             UseHttp2 = true;
             return this;
         }
 
-        public Options WithStatellite(SatelliteOptions options)
+        public Options WithSatellite(SatelliteOptions options)
         {
+            _logger.Debug($"Setting satellite to {options}");
             Satellite = options;
             return this;
         }
 
         public Options WithReportPeriod(TimeSpan period)
         {
+            _logger.Debug($"Setting reporting period to {period}");
             ReportPeriod = period;
             return this;
         }
 
         public Options WithReportTimeout(TimeSpan timeout)
         {
+            _logger.Debug($"Setting report timeout to {timeout}");
             ReportTimeout = timeout;
             return this;
         }
 
         public Options WithTags(IDictionary<string, object> tags)
         {
+            _logger.Debug($"Setting default tags to: {tags.Select(kvp => $"{kvp.Key}:{kvp.Value},")}");
             Tags = MergeTags(tags);
             return this;
         }
 
         public Options WithAutomaticReporting(bool shouldRun)
         {
+            _logger.Debug($"Setting automatic reporting to {shouldRun}");
             Run = shouldRun;
             return this;
         }
@@ -119,7 +129,7 @@ private IDictionary<string, object> MergeTags(IDictionary<string, object> input)
             foreach (var item in attributes)
             {
                 if (!mergedAttributes.ContainsKey(item.Key))
-                {
+                {                    
                     mergedAttributes.Add(item.Key, item.Value);
                 }
             }

src/LightStep/Propagation/PropagatorStack.cs

@@ -1,17 +1,20 @@
 using System;
 using System.Collections.Generic;
+using LightStep.Logging;
 using OpenTracing.Propagation;
 
 namespace LightStep.Propagation
 {
     /// <inheritdoc />
     public class PropagatorStack : IPropagator
     {
+        private static readonly ILog _logger = LogProvider.GetCurrentClassLogger();
+
         /// <inheritdoc />
         public PropagatorStack(IFormat<ITextMap> format)
         {
             if (format == null) throw new ArgumentNullException(nameof(format));
-
+            _logger.Trace($"Creating new PropagatorStack with format {format}");
             Format = format;
             Propagators = new List<IPropagator>();
         }
@@ -30,7 +33,10 @@ public PropagatorStack(IFormat<ITextMap> format)
         public void Inject<TCarrier>(SpanContext context, IFormat<TCarrier> format, TCarrier carrier)
         {
             Propagators.ForEach(propagator =>
-                propagator.Inject(context, format, carrier)
+                {
+                    _logger.Debug($"Injecting context to {propagator.GetType()}");
+                    propagator.Inject(context, format, carrier);
+                }
             );
         }
 
@@ -39,6 +45,7 @@ public SpanContext Extract<TCarrier>(IFormat<TCarrier> format, TCarrier carrier)
         {
             for (var i = Propagators.Count - 1; i >= 0; i--)
             {
+                _logger.Debug($"Trying to extract from {Propagators[i].GetType()}");
                 var context = Propagators[i].Extract(format, carrier);
                 if (context != null) return context;
             }
@@ -55,7 +62,7 @@ public SpanContext Extract<TCarrier>(IFormat<TCarrier> format, TCarrier carrier)
         public PropagatorStack AddPropagator(IPropagator propagator)
         {
             if (propagator == null) throw new ArgumentNullException(nameof(propagator));
-
+            _logger.Trace($"Adding {propagator.GetType()} to PropagatorStack.");
             Propagators.Add(propagator);
             return this;
         }