Log failed request and expose timestamp as an optional parameter (#49)

* Add basic logging when failed to send telemetry

* Log error when async sender thread terminated abnormally

* Lower log level to warning if failed to send request to the server

* Add timestamp to the options of the track methods, which helps in the cases of high precision or delayed tracking calls.

* Add test cases for custom timestamp in track methods

* Add test logger for unit tests

* Expose timestamp as an optional parameter only at telemetry channel but not at the track methods

* Update Changelog.md

* Make the optional timestamp parameter either of String type or Time type.

Author: yantang-msft

CHANGELOG.md

@@ -3,6 +3,8 @@
 This file needs to be updated with every significant pull request. It is used to write down release notes.
 
 ## Version 0.5.5
+* Add some basic logging when failed to send telemetry to the server
+* Add timestamp as an optional parameter to the TelemetryChannel::write() method
 
 ## Version 0.5.4
 

lib/application_insights/channel/asynchronous_sender.rb

@@ -122,9 +122,10 @@ def run
               break
             end
           end
-        rescue
+        rescue Exception => e
           # Make sure work_thread sets to nil when it terminates abnormally
           @work_thread = nil
+          @logger.error('application_insights') { "Asynchronous sender work thread terminated abnormally: #{e.to_s}" }
         end
       end
     end

lib/application_insights/channel/sender_base.rb

@@ -3,6 +3,7 @@
 require 'openssl'
 require 'stringio'
 require 'zlib'
+require 'logger'
 
 module ApplicationInsights
   module Channel
@@ -20,6 +21,7 @@ def initialize(service_endpoint_uri)
         @service_endpoint_uri = service_endpoint_uri
         @queue = nil
         @send_buffer_size = 100
+        @logger = Logger.new(STDOUT)
       end
 
       # The service endpoint URI where this sender will send data to.
@@ -36,6 +38,9 @@ def initialize(service_endpoint_uri)
       # @return [Fixnum] the maximum number of items in a telemetry batch.
       attr_accessor :send_buffer_size
 
+      # The logger for the sender.
+      attr_accessor :logger
+
       # Immediately sends the data passed in to {#service_endpoint_uri}. If the
       # service request fails, the passed in items are pushed back to the {#queue}.
       # @param [Array<Contracts::Envelope>] data_to_send an array of
@@ -63,6 +68,10 @@ def send(data_to_send)
 
         response = http.request(request)
         http.finish if http.started?
+
+        if !response.kind_of? Net::HTTPSuccess
+          @logger.warn('application_insights') { "Failed to send data: #{response.message}" }
+        end
       end
 
       private

lib/application_insights/channel/telemetry_channel.rb

@@ -61,9 +61,20 @@ def flush
       #   an {Contracts::Envelope} before being enqueued to the {#queue}.
       # @param [TelemetryContext] context the override context to use when
       #   constructing the {Contracts::Envelope}.
-      def write(data, context=nil)
+      # @param [Time|String] time the timestamp of the telemetry used to construct the
+      #   {Contracts::Envelope}.
+      def write(data, context=nil, time=nil)
         local_context = context || @context
         raise ArgumentError, 'Context was required but not provided' unless local_context
+
+        if time && time.is_a?(String)
+          local_time = time
+        elsif time && time.is_a?(Time)
+          local_time = time.iso8601(7)
+        else
+          local_time = Time.now.iso8601(7)
+        end
+
         data_type = data.class.name.gsub(/^.*::/, '')
         set_properties data, local_context
         data_attributes = {
@@ -72,7 +83,7 @@ def write(data, context=nil)
         }
         envelope_attributes = {
           :name => 'Microsoft.ApplicationInsights.' + data_type[0..-5],
-          :time => Time.now.iso8601(7),
+          :time => local_time,
           :i_key => local_context.instrumentation_key,
           :tags => get_tags(local_context),
           :data => Contracts::Data.new(data_attributes)

lib/application_insights/telemetry_client.rb

@@ -217,7 +217,7 @@ def track_request(id, start_time, duration, response_code, success, options={})
         :measurements => options[:measurements] || {}
       )
 
-      self.channel.write(data, self.context)
+      self.channel.write(data, self.context, start_time)
     end
 
     # Flushes data in the queue. Data in the queue will be sent either immediately

test/application_insights/channel/test_sender_base.rb

@@ -1,5 +1,6 @@
 require_relative '../../../lib/application_insights/channel/queue_base'
 require_relative '../../../lib/application_insights/channel/sender_base'
+require_relative '../test_logger'
 require 'socket'
 require 'test/unit'
 require 'thread'
@@ -38,20 +39,26 @@ def test_send_buffer_size_works_as_expected
 
   def test_send_works_as_expected_with_400_code
     thread, port = execute_server '400 BadRequest'
+    test_logger = TestLogger.new
     sender = SenderBase.new 'http://localhost:' + port.to_s + '/track'
+    sender.logger = test_logger
     sender.queue = []
     sender.send([1, 2])
     thread.join
     assert_equal [], sender.queue
+    assert_true test_logger.messages.include?('BadRequest')
   end
 
   def test_send_works_as_expected_with_500_code
     thread, port = execute_server '500 InternalServerError'
+    test_logger = TestLogger.new
     sender = SenderBase.new 'http://localhost:' + port.to_s + '/track'
+    sender.logger = test_logger
     sender.queue = []
     sender.send([1, 2])
     thread.join
     assert_equal [], sender.queue
+    assert_true test_logger.messages.include?('InternalServerError')
   end
 
   def execute_server(code)

test/application_insights/channel/test_telemetry_channel.rb

@@ -3,6 +3,7 @@
 require_relative '../../../lib/application_insights/channel/synchronous_queue'
 require_relative '../../../lib/application_insights/channel/synchronous_sender'
 require 'test/unit'
+require 'time'
 
 include ApplicationInsights::Channel
 
@@ -72,6 +73,46 @@ def test_write_works_as_expected
     assert_same expected, actual.data.base_data
   end
 
+  def test_write_custom_timestamp
+    queue = MockTelemetryChannelQueue.new SynchronousSender.new
+    context = TelemetryContext.new
+    context.instrumentation_key = 'instrumentation key'
+    channel = TelemetryChannel.new context, queue
+    data = MockTelemetryItemData.new
+    timestamp = (Time.now - 5).iso8601(7)
+
+    channel.write data
+    actual = queue.queue[0]
+    assert_not_equal timestamp, actual.time
+
+    channel.write data, nil, timestamp
+    actual = queue.queue[1]
+    assert_equal timestamp, actual.time
+  end
+
+  def test_write_custom_timestamp_accept_string_time_type
+    queue = MockTelemetryChannelQueue.new SynchronousSender.new
+    context = TelemetryContext.new
+    context.instrumentation_key = 'instrumentation key'
+    channel = TelemetryChannel.new context, queue
+    data = MockTelemetryItemData.new
+
+    timestamp_string = (Time.now - 5).iso8601(7)
+    channel.write data, nil, timestamp_string
+    actual = queue.queue[0]
+    assert_equal timestamp_string, actual.time
+
+    timestamp_time = Time.now - 5
+    channel.write data, nil, timestamp_time
+    actual = queue.queue[1]
+    assert_equal timestamp_time.iso8601(7), actual.time
+  
+    timestamp_invalid = {:invalid => "invalid timestamp"}
+    channel.write data, nil, timestamp_invalid
+    actual = queue.queue[2]
+    assert_not_equal timestamp_invalid, actual.time
+  end
+
   def test_get_tags_works_as_expected
     queue = MockTelemetryChannelQueue.new SynchronousSender.new
     context = TelemetryContext.new

test/application_insights/test_logger.rb

@@ -0,0 +1,10 @@
+class TestLogger < Logger
+    def initialize
+      @strio = StringIO.new
+      super(@strio)
+    end
+  
+    def messages
+      @strio.string
+    end
+  end

test/application_insights/test_telemetry_client.rb

@@ -4,6 +4,7 @@
 require_relative '../../lib/application_insights/channel/telemetry_channel'
 require 'json'
 require 'test/unit'
+require 'time'
 
 include ApplicationInsights
 
@@ -60,7 +61,7 @@ def test_track_exception_works_as_expected
     assert_equal expected, actual
   end
 
-  def test_track_event_view_works_as_expected
+  def test_track_event_works_as_expected
     client, sender = self.create_client
     client.track_event 'test'
     client.flush
@@ -70,7 +71,7 @@ def test_track_event_view_works_as_expected
     assert_equal expected, actual
   end
 
-  def test_track_metric_view_works_as_expected
+  def test_track_metric_works_as_expected
     client, sender = self.create_client
     client.track_metric 'test', 42
     client.flush
@@ -90,22 +91,26 @@ def test_track_trace_view_works_as_expected
     assert_equal expected, actual
   end
 
-  def test_track_request_view_works_as_expected
+  def test_track_request_works_as_expected
+    start_time = Time.now.iso8601
     client, sender = self.create_client
-    client.track_request 'test', '2015-01-24T23:10:22.7411910-08:00', '0:00:00:02.0000000','200', true
+    client.track_request 'test', start_time, '0:00:00:02.0000000','200', true
     client.flush
-    expected = '[{"ver":1,"name":"Microsoft.ApplicationInsights.Request","time":"TIME_PLACEHOLDER","sampleRate":100.0,"tags":{"ai.internal.sdkVersion":"rb:__version__"},"data":{"baseType":"RequestData","baseData":{"ver":2,"id":"test","startTime":"2015-01-24T23:10:22.7411910-08:00","duration":"0:00:00:02.0000000","responseCode":"200","success":true}}}]'.gsub!(/__version__/, ApplicationInsights::VERSION)
-    sender.data_to_send[0].time = 'TIME_PLACEHOLDER'
+    expected = '[{"ver":1,"name":"Microsoft.ApplicationInsights.Request","time":"__time__","sampleRate":100.0,"tags":{"ai.internal.sdkVersion":"rb:__version__"},"data":{"baseType":"RequestData","baseData":{"ver":2,"id":"test","startTime":"__time__","duration":"0:00:00:02.0000000","responseCode":"200","success":true}}}]'
+      .gsub!(/__version__/, ApplicationInsights::VERSION)
+      .gsub!(/__time__/, start_time)
     actual = sender.data_to_send.to_json
     assert_equal expected, actual
   end
 
-  def test_track_request_view_works_as_expected_when_request_is_failed
+  def test_track_request_works_as_expected_when_request_is_failed
+    start_time = Time.now.iso8601
     client, sender = self.create_client
-    client.track_request 'test', '2015-01-24T23:10:22.7411910-08:00', '0:00:00:02.0000000','200', false
+    client.track_request 'test', start_time, '0:00:00:02.0000000','200', false
     client.flush
-    expected = '[{"ver":1,"name":"Microsoft.ApplicationInsights.Request","time":"TIME_PLACEHOLDER","sampleRate":100.0,"tags":{"ai.internal.sdkVersion":"rb:__version__"},"data":{"baseType":"RequestData","baseData":{"ver":2,"id":"test","startTime":"2015-01-24T23:10:22.7411910-08:00","duration":"0:00:00:02.0000000","responseCode":"200","success":false}}}]'.gsub!(/__version__/, ApplicationInsights::VERSION)
-    sender.data_to_send[0].time = 'TIME_PLACEHOLDER'
+    expected = '[{"ver":1,"name":"Microsoft.ApplicationInsights.Request","time":"__time__","sampleRate":100.0,"tags":{"ai.internal.sdkVersion":"rb:__version__"},"data":{"baseType":"RequestData","baseData":{"ver":2,"id":"test","startTime":"__time__","duration":"0:00:00:02.0000000","responseCode":"200","success":false}}}]'
+      .gsub!(/__version__/, ApplicationInsights::VERSION)
+      .gsub!(/__time__/, start_time)
     actual = sender.data_to_send.to_json
     assert_equal expected, actual
   end