Merge pull request #97 from gas-buddy/eherot/preserve_millisecond_precision

Preserve millisecond precision and time zones.

Author: repeatedly

lib/fluent/plugin/in_sql.rb

@@ -60,13 +60,16 @@ class TableElement
       config_param :time_column, :string, default: nil
       config_param :primary_key, :string, default: nil
 
+      attr_reader :log
+
       def configure(conf)
         super
       end
 
-      def init(tag_prefix, base_model, router)
+      def init(tag_prefix, base_model, router, log)
         @router = router
         @tag = "#{tag_prefix}.#{@tag}" if tag_prefix
+        @log = log
 
         # creates a model for this table
         table_name = @table
@@ -108,6 +111,17 @@ def read_attribute_for_serialization(n)
         end
       end
 
+      # Make sure we always have a Fluent::EventTime object regardless of what comes in
+      def normalized_time(tv, now)
+        return Fluent::EventTime.from_time(tv) if tv.is_a?(Time)
+        begin
+          Fluent::EventTime.parse(tv.to_s)
+        rescue
+          log.warn "Message contains invalid timestamp, using current time instead (#{now.inspect})"
+          now
+        end
+      end
+
       # emits next records and returns the last record of emitted records
       def emit_next_records(last_record, limit)
         relation = @model
@@ -123,15 +137,13 @@ def emit_next_records(last_record, limit)
         relation.each do |obj|
           record = obj.serializable_hash rescue nil
           if record
-            if @time_column && tv = obj.read_attribute(@time_column)
-              if tv.is_a?(Time)
-                time = tv.to_i
+            time =
+              if @time_column && (tv = obj.read_attribute(@time_column))
+                normalized_time(tv, now)
               else
-                time = Time.parse(tv.to_s).to_i rescue now
+                now
               end
-            else
-              time = now
-            end
+
             me.add(time, record)
             last_record = record
           end
@@ -217,7 +229,7 @@ def start
       # ignore tables if TableElement#init failed
       @tables.reject! do |te|
         begin
-          te.init(@tag_prefix, @base_model, router)
+          te.init(@tag_prefix, @base_model, router, log)
           log.info "Selecting '#{te.table}' table"
           false
         rescue => e

test/fixtures/schema.rb

@@ -20,5 +20,12 @@
     t.datetime "created_at",  null: false
     t.datetime "updated_at",  null: false
   end
+
+  create_table "messages_custom_time", force: :cascade do |t|
+    t.string "message"
+    t.datetime "created_at",  null: false
+    t.datetime "updated_at",  null: false
+    t.string "custom_time"
+  end
 end
 

test/plugin/test_in_sql.rb

@@ -82,9 +82,9 @@ def test_message
       [d.events[2][1], "message 3"],
     ]
     actual = [
-      [Time.parse(d.events[0][2]["updated_at"]).to_i, d.events[0][2]["message"]],
-      [Time.parse(d.events[1][2]["updated_at"]).to_i, d.events[1][2]["message"]],
-      [Time.parse(d.events[2][2]["updated_at"]).to_i, d.events[2][2]["message"]],
+      [Fluent::EventTime.parse(d.events[0][2]["updated_at"]), d.events[0][2]["message"]],
+      [Fluent::EventTime.parse(d.events[1][2]["updated_at"]), d.events[1][2]["message"]],
+      [Fluent::EventTime.parse(d.events[2][2]["updated_at"]), d.events[2][2]["message"]],
     ]
     assert_equal(expected, actual)
   end

test/plugin/test_in_sql_with_custom_time.rb

@@ -0,0 +1,114 @@
+require "helper"
+require "fluent/test/driver/input"
+
+class SqlInputCustomTimeTest < Test::Unit::TestCase
+  def setup
+    Fluent::Test.setup
+  end
+
+  def teardown
+  end
+
+  CONFIG = %[
+    adapter postgresql
+    host localhost
+    port 5432
+    database fluentd_test
+
+    username fluentd
+    password fluentd
+
+    schema_search_path public
+
+    tag_prefix db
+
+    <table>
+      table messages_custom_time
+      tag logs
+      update_column updated_at
+      time_column custom_time
+    </table>
+  ]
+
+  def create_driver(conf = CONFIG)
+    Fluent::Test::Driver::Input.new(Fluent::Plugin::SQLInput).configure(conf)
+  end
+
+  def test_configure
+    d = create_driver
+    expected = {
+      host: "localhost",
+      port: 5432,
+      adapter: "postgresql",
+      database: "fluentd_test",
+      username: "fluentd",
+      password: "fluentd",
+      schema_search_path: "public",
+      tag_prefix: "db"
+    }
+    actual = {
+      host: d.instance.host,
+      port: d.instance.port,
+      adapter: d.instance.adapter,
+      database: d.instance.database,
+      username: d.instance.username,
+      password: d.instance.password,
+      schema_search_path: d.instance.schema_search_path,
+      tag_prefix: d.instance.tag_prefix
+    }
+    assert_equal(expected, actual)
+    tables = d.instance.instance_variable_get(:@tables)
+    assert_equal(1, tables.size)
+    messages_custom_time = tables.first
+    assert_equal("messages_custom_time", messages_custom_time.table)
+    assert_equal("logs", messages_custom_time.tag)
+  end
+
+  def test_message
+    d = create_driver(CONFIG + "select_interval 1")
+
+    start_time = Fluent::EventTime.now
+
+    # Create one message with a valid timestamp containing milliseconds and a time zone
+    Message.create!(message: "message 1", custom_time: '2020-08-27 15:00:16.100758000 -0400')
+
+    # Create one message without a timestamp so that we can test auto-creation
+    Message.create!(message: "message 2 (no timestamp)", custom_time: nil)
+
+    # Create one message with an unparseable timestamp so that we can check that a valid
+    # one is auto-generated.
+    Message.create!(message: "message 3 (bad timestamp)", custom_time: 'foo')
+
+    d.end_if do
+      d.record_count >= 3
+    end
+    d.run(timeout: 5)
+
+    assert_equal("db.logs", d.events[0][0])
+    expected = [
+      [d.events[0][1], "message 1"],
+      [d.events[1][1], "message 2 (no timestamp)"],
+      [d.events[2][1], "message 3 (bad timestamp)"],
+    ]
+
+    actual = [
+      [Fluent::EventTime.parse(d.events[0][2]["custom_time"]), d.events[0][2]["message"]],
+      d.events[1][2]["message"],
+      d.events[2][2]["message"],
+    ]
+
+    assert_equal(expected[0], actual[0])
+
+    # Messages 2 and 3 should have the same messages but (usually) a slightly later
+    # timestamps because they are generated by the input plugin instead of the test
+    # code
+    [1,2].each do |i|
+      assert_equal(expected[i][1], actual[i])
+      assert_operator(expected[i][0], :>=, start_time)
+    end
+  end
+
+  class Message < ActiveRecord::Base
+    self.table_name = "messages_custom_time"
+  end
+end