Internal Metrics (#45)

* extend span recorder with metrics properties

* increment dropped span count when spans fail to send

* add max span per buffer option

Author: austinlparker

CHANGELOG.md

@@ -1,6 +1,12 @@
 # Changelog
 
 _vNext_
+- All value types are now properly handled in span serialization.
+- The platform version detection code has been improved and should be resilient to dynamic injection scenarios.
+- Logging now exists for many operations via the LibLog library. See the README for more details.
+- Error handling around dropped reports has been improved, and we now report dropped spans to LightStep.
+- The `LightStepHttpClient` now respects the `ReportTimeout` value. **Breaking Change**
+  - Previously, this value was not respected by the HTTP client and was using the default 100s timeout.
 - The `Options` class has been refactored to support a more fluent style of configuration. **Breaking Change**
   - By default, `SatelliteOptions` are now created when `Options` is created that points to the LightStep public satellite pool.
   - Please see the readme for more information on configuring the tracer.

README.md

@@ -42,6 +42,7 @@ There's several options that can be adjusted when instantiating a `LightStepTrac
 | WithSatellite(SatelliteOptions) | A SatelliteOptions object that specifies the host, port, and if we should use HTTPS |
 | WithHttp2(bool) | If this is true, we use HTTP/2 to communicate with the Satellite |
 | WithAutomaticReporting(bool) | If false, disables the automatic flushing of buffered spans. |
+| WithMaxBufferedSpans(int) | The maximum amount of spans to record in a single buffer. |
 
 ## `SatelliteOptions`
 | Property | Description |

examples/LightStep.CSharpDITestApp/LightStep.CSharpDITestApp.csproj

@@ -11,6 +11,7 @@
     <AssemblyName>LightStep.CSharpDITestApp</AssemblyName>
     <TargetFrameworkVersion>v4.7.1</TargetFrameworkVersion>
     <FileAlignment>512</FileAlignment>
+    <AutoGenerateBindingRedirects>true</AutoGenerateBindingRedirects>
   </PropertyGroup>
   <PropertyGroup Condition=" '$(Configuration)|$(Platform)' == 'Debug|AnyCPU' ">
     <PlatformTarget>AnyCPU</PlatformTarget>

src/LightStep/Collector/LightStepHttpClient.cs

@@ -8,6 +8,8 @@
 using System.Threading.Tasks;
 using Google.Protobuf;
 using LightStep.Logging;
+using Google.Protobuf.WellKnownTypes;
+using OpenTracing.Tag;
 
 namespace LightStep.Collector
 {
@@ -30,7 +32,7 @@ public LightStepHttpClient(string url, Options options)
         {
             _url = url;
             _options = options;
-            _client = new HttpClient();
+            _client = new HttpClient {Timeout = _options.ReportTimeout};
         }
 
         /// <summary>
@@ -42,7 +44,7 @@ public async Task<ReportResponse> SendReport(ReportRequest report)
         {
             // force net45 to attempt tls12 first and fallback appropriately
             ServicePointManager.SecurityProtocol = SecurityProtocolType.Tls12 | SecurityProtocolType.Tls11 | SecurityProtocolType.Tls;
-            
+
             _client.DefaultRequestHeaders.Accept.Add(
                 new MediaTypeWithQualityHeaderValue("application/octet-stream"));
             var reportsByteArray = report.ToByteArray();
@@ -54,9 +56,9 @@ public async Task<ReportResponse> SendReport(ReportRequest report)
             };
 
             request.Content.Headers.ContentType = new MediaTypeHeaderValue("application/octet-stream");
-            
-            ReportResponse responseValue = new ReportResponse();
-            
+
+            ReportResponse responseValue;
+
             try
             {
                 var response = await _client.SendAsync(request);
@@ -69,7 +71,13 @@ public async Task<ReportResponse> SendReport(ReportRequest report)
             {
                 _logger.WarnException("Exception caught while sending report, resetting HttpClient", ex);
                 _client.Dispose();
-                _client = new HttpClient();
+                _client = new HttpClient {Timeout = _options.ReportTimeout};
+                throw;
+            }
+            catch (Exception ex) when (ex is TaskCanceledException || ex is OperationCanceledException)
+            {
+                _logger.WarnException("Timed out sending report to satellite", ex);
+                throw;
             }
 
             return responseValue;
@@ -80,23 +88,30 @@ public async Task<ReportResponse> SendReport(ReportRequest report)
         /// </summary>
         /// <param name="spans">An enumerable of <see cref="SpanData" /></param>
         /// <returns>A <see cref="ReportRequest" /></returns>
-        public ReportRequest Translate(IEnumerable<SpanData> spans)
+        public ReportRequest Translate(ISpanRecorder spanBuffer)
         {
             _logger.Debug($"Serializing spans to proto.");
             var timer = new Stopwatch();
             timer.Start();
 
+            var metrics = new InternalMetrics
+            {
+                StartTimestamp = Timestamp.FromDateTime(spanBuffer.ReportStartTime.ToUniversalTime()),
+                DurationMicros = Convert.ToUInt64((spanBuffer.ReportEndTime - spanBuffer.ReportStartTime).Ticks / 10),
+                Counts = { new MetricsSample() { Name = "spans.dropped", IntValue = spanBuffer.DroppedSpanCount } }
+            };
+            
             var request = new ReportRequest
             {
                 Reporter = new Reporter
                 {
                     ReporterId = _options.TracerGuid
                 },
-                Auth = new Auth {AccessToken = _options.AccessToken}
+                Auth = new Auth {AccessToken = _options.AccessToken},
+                InternalMetrics = metrics
             };
             _options.Tags.ToList().ForEach(t => request.Reporter.Tags.Add(new KeyValue().MakeKeyValueFromKvp(t)));
-            spans.ToList().ForEach(span => request.Spans.Add(new Span().MakeSpanFromSpanData(span)));
-
+            spanBuffer.GetSpans().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/ISpanRecorder.cs

@@ -1,4 +1,5 @@
-using System.Collections.Generic;
+using System;
+using System.Collections.Generic;
 
 namespace LightStep
 {
@@ -8,20 +9,45 @@ namespace LightStep
     public interface ISpanRecorder
     {
         /// <summary>
-        ///     Saves a span.
+        /// The start (creation) time of the span buffer.
+        /// </summary>
+        DateTime ReportStartTime { get; }
+        /// <summary>
+        /// The finishing (flushing) time of the span buffer.
+        /// </summary>
+        DateTime ReportEndTime { get; set; }
+        /// <summary>
+        /// The count of dropped spans for this, or a prior, span buffer.
+        /// </summary>
+        int DroppedSpanCount { get; set; }
+        
+        /// <summary>
+        /// Saves a span.
         /// </summary>
         /// <param name="span"></param>
         void RecordSpan(SpanData span);
 
         /// <summary>
-        ///     Gets the current record of spans.
+        /// Returns this instance of the span buffer.
         /// </summary>
         /// <returns></returns>
-        List<SpanData> GetSpanBuffer();
+        ISpanRecorder GetSpanBuffer();
 
         /// <summary>
-        ///     Clears the span record.
+        /// Clears the span record.
         /// </summary>
         void ClearSpanBuffer();
+
+        /// <summary>
+        /// Increments the dropped span count.
+        /// </summary>
+        /// <param name="count"></param>
+        void RecordDroppedSpans(int count);
+
+        /// <summary>
+        /// Gets the spans stored in the buffer.
+        /// </summary>
+        /// <returns></returns>
+        IEnumerable<SpanData> GetSpans();
     }
 }

src/LightStep/LightStepSpanRecorder.cs

@@ -10,7 +10,16 @@ public sealed class LightStepSpanRecorder : ISpanRecorder
     {
         private List<SpanData> Spans { get; } = new List<SpanData>();
         private static readonly ILog _logger = LogProvider.GetCurrentClassLogger();
+        
+        /// <inheritdoc />
+        public DateTime ReportStartTime { get; } = DateTime.Now;
+
+        /// <inheritdoc />
+        public DateTime ReportEndTime { get; set; }
 
+        /// <inheritdoc />
+        public int DroppedSpanCount { get; set; }
+        
         /// <inheritdoc />
         public void RecordSpan(SpanData span)
         {
@@ -20,21 +29,16 @@ public void RecordSpan(SpanData span)
                 _logger.Trace($"Lock freed, adding new span: {span}");
                 Spans.Add(span);    
             }
-            
         }
 
         /// <inheritdoc />
-        public List<SpanData> GetSpanBuffer()
+        public ISpanRecorder 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;
+                ReportEndTime = DateTime.Now;
+                return this;
             }
-            
         }
 
         /// <inheritdoc />
@@ -46,7 +50,21 @@ public void ClearSpanBuffer()
                 _logger.Trace("Lock freed, clearing span buffer.");
                 Spans.Clear();    
             }
-            
+        }
+
+        /// <inheritdoc />
+        public void RecordDroppedSpans(int count)
+        {
+            DroppedSpanCount += count;
+        }
+
+        /// <inheritdoc />
+        public IEnumerable<SpanData> GetSpans()
+        {
+            lock (Spans)
+            {
+                return Spans.ToList();
+            }
         }
     }
 }

src/LightStep/Options.cs

@@ -49,6 +49,11 @@ public class Options
         ///     Timeout for sending spans to a LightStep Satellite.
         /// </summary>
         public TimeSpan ReportTimeout { get; private set; }
+        
+        /// <summary>
+        ///     Maximum amount of spans to buffer in a single report. 
+        /// </summary>
+        public int ReportMaxSpans { get; private set;}
 
         /// <summary>
         ///     Tags that should be applied to each span generated by this tracer.
@@ -103,6 +108,13 @@ public Options WithAutomaticReporting(bool shouldRun)
             Run = shouldRun;
             return this;
         }
+
+        public Options WithMaxBufferedSpans(int count)
+        {
+            _logger.Debug($"Setting max spans per buffer to {count}");
+            ReportMaxSpans = count;
+            return this;
+        }
 
         /// <summary>
         ///     Creates a new set of options for the LightStep tracer.
@@ -120,6 +132,7 @@ public Options(string token)
             Satellite = new SatelliteOptions("collector.lightstep.com");
             UseHttp2 = false;
             Run = true;
+            ReportMaxSpans = int.MaxValue;
         }
 
         private IDictionary<string, object> MergeTags(IDictionary<string, object> input)

src/LightStep/Tracer.cs

@@ -1,6 +1,7 @@
 using System;
 using System.Collections.Generic;
 using System.Linq;
+using System.Net.Http;
 using System.Threading;
 using System.Threading.Tasks;
 using LightStep.Collector;
@@ -19,9 +20,10 @@ public sealed class Tracer : ITracer
         private readonly Options _options;
         private readonly IPropagator _propagator;
         private readonly LightStepHttpClient _httpClient;
-        private readonly ISpanRecorder _spanRecorder;
+        private ISpanRecorder _spanRecorder;
         private readonly Timer _reportLoop;
         private static readonly ILog _logger = LogProvider.GetCurrentClassLogger();
+        private int currentDroppedSpanCount;
 
         /// <inheritdoc />
         public Tracer(Options options) : this(new AsyncLocalScopeManager(), Propagators.TextMap, options,
@@ -96,26 +98,67 @@ public async void Flush()
             if (_options.Run)
             {
                 // save current spans and clear the buffer
-                // TODO: add retry logic so as to not drop spans on unreachable satellite
-                _logger.Debug($"Flushing SpanData");
-                List<SpanData> currentSpans = new List<SpanData>();
+                ISpanRecorder currentBuffer;
                 lock (_lock)
                 {
-                    _logger.Debug($"Lock freed, getting current buffer.");
-                    currentSpans = _spanRecorder.GetSpanBuffer();
-                    _logger.Debug($"{currentSpans.Count} spans copied from buffer.");
+                    currentBuffer = _spanRecorder.GetSpanBuffer();
+                    _spanRecorder = new LightStepSpanRecorder();
+                    _logger.Debug($"{currentBuffer.GetSpans().Count()} spans in buffer.");
                 }
-                var data = _httpClient.Translate(currentSpans);
-                var resp = await _httpClient.SendReport(data);
-                if (resp.Errors.Count > 0) _logger.Warn($"Errors sending report to LightStep: {resp.Errors}");
+                
+                /**
+                 * there are two ways spans can be dropped:
+                 * 1. the buffer drops a span because it's too large, malformed, etc.
+                 * 2. the report failed to be sent to the satellite.
+                 * since flush is async and there can potentially be any number of buffers in flight to the satellite,
+                 * we need to set the current drop count on the tracer to be the amount of dropped spans from the buffer
+                 * plus the existing dropped spans, then mutate the current buffer to this new total value.
+                 */
+                currentDroppedSpanCount += currentBuffer.DroppedSpanCount;
+                currentBuffer.DroppedSpanCount = currentDroppedSpanCount;
+                var data = _httpClient.Translate(currentBuffer);
+
+                try
+                {
+                    var resp = await _httpClient.SendReport(data);
+                    if (resp.Errors.Count > 0)
+                    {
+                        _logger.Warn($"Errors in report: {resp.Errors}");
+                    }
+
+                    lock (_lock)
+                    {
+                        _logger.Debug($"Resetting tracer dropped span count as the last report was successful.");
+                        currentDroppedSpanCount = 0;  
+                    }
+                    
+                }
+                catch (Exception ex) when (ex is HttpRequestException || ex is TaskCanceledException || ex is OperationCanceledException)
+                {
+                    lock (_lock)
+                    {
+                        _logger.Warn($"Adding {currentBuffer.GetSpans().Count()} spans to dropped span count (current total: {currentDroppedSpanCount})");
+                        currentDroppedSpanCount += currentBuffer.GetSpans().Count();
+                    }
+                }
+                
+                
             }
         }
 
         internal void AppendFinishedSpan(SpanData span)
         {
             lock (_lock)
             {
-                _spanRecorder.RecordSpan(span);
+                if (_spanRecorder.GetSpans().Count() < _options.ReportMaxSpans )
+                {
+                    _spanRecorder.RecordSpan(span);
+                }
+                else
+                {
+                    _spanRecorder.RecordDroppedSpans(1);
+                    _logger.Warn($"Dropping span due to too many spans in buffer.");
+                }
             }
         }
     }