Data stopped coming after DST change (Logstash JDBC input)

Elastic Stack Logstash
1

Hi,

We had the DST change in Australia.
[ It ends at 2am (which is 3am Daylight Saving Time) on the first Sunday in April , when clocks are put back one hour.]

The data came in till 1:59 AM in night (April 3rd, 2022) and then stopped.

I am at loss as to what might have gone wrong. I am not even using the time of record creation as basis of pulling the new data.

Layout:
I am using the JDBC input plugin.

tracking_column => "resultnumber"
use_column_value => true
tracking_column_type => "numeric"
schedule => "*/5 * * * *"
jdbc_paging_enabled => "false"
jdbc_default_timezone => "Australia/Sydney"
jdbc_page_size => "500"
last_run_metadata_path => "logstash_jdbc_last_run_tracking"

As evident I am not using the time of record insertion for pulling the data. I am simply using the increasing resultnumber as the sql_last_value.

There are records which are available having values greater than the resultnumber stored in the tracking file logstash_jdbc_last_run_tracking.

Here is the redacted query string if it helps.

select resultnumber,resultstatus,createdon where resultnumber > :sql_last_value and createdon > '2021-01-01' order by resultnumber ASC

Any ideas?
I will update the question if I find something during my investigation.

2

Are any exceptions logged? Can you try removing any date/time fields from the select? For example, does

select resultnumber,resultstatus where resultnumber > :sql_last_value and createdon > '2021-01-01' order by resultnumber ASC

work? Date/time columns are automatically converted to Logstash timestamps. I wouldn't expect that to cause a problem when DST ends (times between 2 and 3 AM are ambiguous) rather when DST starts (times between 2 and 3 do not exist and attempts to parse them causes exceptions).

The fact that it worked until 1:59 (when times became ambiguous) rather than 2:59 (when time went backwards) probably tells us something, but I am not sure what.

3

I got some errors but not sure if this is related. Still investigating.

{  rufus-scheduler intercepted an error:
     job:
       Rufus::Scheduler::CronJob "*/5 * * * *" {}
     error:
       
       Sequel::InvalidValue
       TZInfo::AmbiguousTime: 2022-04-03 02:00:29 is an ambiguous local time.
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/tzinfo-2.0.4/lib/tzinfo/timezone.rb:525:in `period_for_local'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/sequel-5.51.0/lib/sequel/extensions/named_timezones.rb:115:in `convert_input_datetime_other'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/sequel-5.51.0/lib/sequel/timezones.rb:136:in `convert_input_datetime_no_offset'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/sequel-5.51.0/lib/sequel/timezones.rb:185:in `convert_input_timestamp'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/sequel-5.51.0/lib/sequel/timezones.rb:94:in `convert_timestamp'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/sequel-5.51.0/lib/sequel/database/misc.rb:312:in `to_application_timestamp'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/sequel-5.51.0/lib/sequel/adapters/jdbc.rb:715:in `timestamp_convert'
         org/jruby/RubyMethod.java:123:in `call'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/sequel-5.51.0/lib/sequel/adapters/jdbc.rb:825:in `process_result_set'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/sequel-5.51.0/lib/sequel/adapters/jdbc.rb:755:in `block in fetch_rows'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/sequel-5.51.0/lib/sequel/adapters/jdbc.rb:268:in `block in execute'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/sequel-5.51.0/lib/sequel/adapters/jdbc.rb:704:in `statement'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/sequel-5.51.0/lib/sequel/adapters/jdbc.rb:263:in `block in execute'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/sequel-5.51.0/lib/sequel/connection_pool/threaded.rb:92:in `hold'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/sequel-5.51.0/lib/sequel/database/connecting.rb:269:in `synchronize'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/sequel-5.51.0/lib/sequel/adapters/jdbc.rb:262:in `execute'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/sequel-5.51.0/lib/sequel/dataset/actions.rb:1093:in `execute'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/sequel-5.51.0/lib/sequel/adapters/jdbc.rb:755:in `fetch_rows'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/sequel-5.51.0/lib/sequel/dataset/actions.rb:152:in `each'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/logstash-integration-jdbc-5.1.8/lib/logstash/plugin_mixins/jdbc/statement_handler.rb:41:in `perform_query'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/logstash-integration-jdbc-5.1.8/lib/logstash/plugin_mixins/jdbc/jdbc.rb:214:in `execute_statement'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/logstash-integration-jdbc-5.1.8/lib/logstash/inputs/jdbc.rb:335:in `execute_query'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/logstash-integration-jdbc-5.1.8/lib/logstash/inputs/jdbc.rb:298:in `block in run'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/rufus-scheduler-3.0.9/lib/rufus/scheduler/jobs.rb:234:in `do_call'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/rufus-scheduler-3.0.9/lib/rufus/scheduler/jobs.rb:258:in `do_trigger'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/rufus-scheduler-3.0.9/lib/rufus/scheduler/jobs.rb:300:in `block in start_work_thread'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/rufus-scheduler-3.0.9/lib/rufus/scheduler/jobs.rb:299:in `block in start_work_thread'
         org/jruby/RubyKernel.java:1442:in `loop'
         /usr/share/logstash/vendor/bundle/jruby/2.5.0/gems/rufus-scheduler-3.0.9/lib/rufus/scheduler/jobs.rb:289:in `block in start_work_thread'
     tz:
       ENV['TZ']:
       Time.now: 2022-04-05 11:13:40 +1000
     scheduler:
       object_id: 2052
       opts:
         {:max_work_threads=>1}
         frequency: 0.3
         scheduler_lock: #<Rufus::Scheduler::NullLock:0x5de2e9d2>
         trigger_lock: #<Rufus::Scheduler::NullLock:0x231d5b7>
       uptime: 371.44675 (6m11s447)
       down?: false
       threads: 2
         thread: #<Thread:0x11f7ab3f>
         thread_key: rufus_scheduler_2052
         work_threads: 1
           active: 1
           vacant: 0
           max_work_threads: 1
         mutexes: {}
       jobs: 1
         at_jobs: 0
         in_jobs: 0
         every_jobs: 0
         interval_jobs: 0
         cron_jobs: 1
       running_jobs: 1
       work_queue: 0
}

Stackoverflow has a similar question.
And the linked issue looks uncomfortably familiar.

4

Absolutely it is related to that.

5

Skipping the records between the ambiguous time period of 1AM to 3 AM kind of fixes the issue. But I think there has to be a better way.

6

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.