Why is Splunk DB Connect incorrectly tailing my rising column and duplicating events?

[RJ_Grayson]

I'm trying to tail a database using a rising column labelled "ID". Splunk DB Connect is working in the sense that it can search the database and return results but it appears to be updating the checkpoint sporadically and out of order which is causing duplicate events to be indexed.

The database is MS SQL.

inputs.conf:
[mi_input://my_querytable]
connection = My_Database
enable_query_wrapping = 1
index = my_index
input_timestamp_column_fullname = (003) my_querytable.Time.datetime
input_timestamp_column_name = Insert_Time
interval = 120
max_rows = 100000
mode = advanced
output_timestamp_format = yyyy-MM-dd HH:mm:ss
query = SELECT ID,Time,Field2,Field2,Field3,Field4,Field5,Field56,Field7 FROM "my_table"."dbo"."my_querytable" WHERE ID > ?
sourcetype = my_sourcetype
tail_rising_column_checkpoint_value = 1675918831
tail_rising_column_fullname = (001) my_querytable.ID.bigint
tail_rising_column_name = ID
ui_query_catalog = my_catalog
ui_query_mode = advanced
ui_query_schema = dbo
ui_query_table = my_querytable
disabled = 0
fetch_size = 20000

Here are what the logs look like when the query runs every 2 minutes and returns 100000 records via 20000 row pulls.

2017-02-26T16:42:43+0000 [INFO] [mi_input.py], line 193: action=start_executing_dbinput dbinput="mi_input://my_querytable"
2017-02-26T16:43:01+0000 [INFO] [modular_input_event_writer.py], line 93 : action=print_csv_from_jdbc_to_event_stream dbinput="mi_input://my_querytable" input_mode=advanced events=20000
2017-02-26T16:43:01+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1401390595
2017-02-26T16:43:16+0000 [INFO] [modular_input_event_writer.py], line 93 : action=print_csv_from_jdbc_to_event_stream dbinput="mi_input://my_querytable" input_mode=advanced events=20000
2017-02-26T16:43:17+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1413595646
2017-02-26T16:43:19+0000 [INFO] [modular_input_event_writer.py], line 93 : action=print_csv_from_jdbc_to_event_stream dbinput="mi_input://my_querytable" input_mode=advanced events=20000
2017-02-26T16:43:20+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1399518391
2017-02-26T16:43:22+0000 [INFO] [modular_input_event_writer.py], line 93 : action=print_csv_from_jdbc_to_event_stream dbinput="mi_input://my_querytable" input_mode=advanced events=20000
2017-02-26T16:43:23+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1399707472
2017-02-26T16:43:25+0000 [INFO] [modular_input_event_writer.py], line 93 : action=print_csv_from_jdbc_to_event_stream dbinput="mi_input://my_querytable" input_mode=advanced events=20000
2017-02-26T16:43:26+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1524449693
2017-02-26T16:43:26+0000 [INFO] [modular_input_event_writer.py], line 93 : action=print_csv_from_jdbc_to_event_stream dbinput="mi_input://my_querytable" input_mode=advanced events=0
2017-02-26T16:43:26+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1524449693
2017-02-26T16:43:26+0000 [INFO] [mi_input.py], line 211: action=complete_dbinput dbinput="mi_input://my_querytable"
2017-02-26T16:44:43+0000 [INFO] [mi_input.py], line 193: action=start_executing_dbinput dbinput="mi_input://my_querytable"
2017-02-26T16:45:30+0000 [INFO] [modular_input_event_writer.py], line 93 : action=print_csv_from_jdbc_to_event_stream dbinput="mi_input://my_querytable" input_mode=advanced events=20000
2017-02-26T16:45:31+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1533335128
2017-02-26T16:45:33+0000 [INFO] [modular_input_event_writer.py], line 93 : action=print_csv_from_jdbc_to_event_stream dbinput="mi_input://my_querytable" input_mode=advanced events=20000
2017-02-26T16:45:34+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1533500333
2017-02-26T16:45:36+0000 [INFO] [modular_input_event_writer.py], line 93 : action=print_csv_from_jdbc_to_event_stream dbinput="mi_input://my_querytable" input_mode=advanced events=20000
2017-02-26T16:45:37+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1528798868
2017-02-26T16:45:39+0000 [INFO] [modular_input_event_writer.py], line 93 : action=print_csv_from_jdbc_to_event_stream dbinput="mi_input://my_querytable" input_mode=advanced events=20000
2017-02-26T16:45:40+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1680663600
2017-02-26T16:45:42+0000 [INFO] [modular_input_event_writer.py], line 93 : action=print_csv_from_jdbc_to_event_stream dbinput="mi_input://my_querytable" input_mode=advanced events=20000
2017-02-26T16:45:43+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1675416914
2017-02-26T16:45:43+0000 [INFO] [modular_input_event_writer.py], line 93 : action=print_csv_from_jdbc_to_event_stream dbinput="mi_input://my_querytable" input_mode=advanced events=0
2017-02-26T16:45:43+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1675416914
2017-02-26T16:45:43+0000 [INFO] [mi_input.py], line 211: action=complete_dbinput dbinput="mi_input://my_querytable"

Here is the chronological order of just the checkpoint being updated. Notice how it jumps back and forth in the rising column:

2017-02-26T16:43:01+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1401390595
2017-02-26T16:43:17+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1413595646
2017-02-26T16:43:20+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1399518391
2017-02-26T16:43:23+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1399707472
2017-02-26T16:43:26+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1524449693
2017-02-26T16:43:26+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1524449693
2017-02-26T16:45:31+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1533335128
2017-02-26T16:45:34+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1533500333
2017-02-26T16:45:37+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1528798868
2017-02-26T16:45:40+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1680663600
2017-02-26T16:45:43+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1675416914
2017-02-26T16:45:43+0000 [INFO] [mi_input.py], line 109: action=rising_column_checkpoint_updated dbinput="mi_input://my_querytable" checkpoint=1675416914

I've tried changing the query to something like this but the query constantly times out even when only trying to return 100 rows.

SELECT ID,Time,Field2,Field2,Field3,Field4,Field5,Field56,Field7 FROM "my_table"."dbo"."my_querytable" WHERE ID > ? ORDER BY ID

I also tried changing the max row pull to 1000/1000 every two minutes so it was forced to only grab 1000 rows every two minutes and update the checkpoint value only once every two minutes. The checkpoint value still kept bouncing around and was not in a linear progression.

Anyone have any idea why I'm seeing this kind of behavior and if there is anything I can do about it?

[RJ_Grayson · Accepted solution]

Adding the ORDER BY clause fixed this issue. Even though the database was being written with a rising column the data wasn't ordered in the database. Each time DBConnect queried the database without the ORDER BY clause it caused the checkpoint value to be updated with whatever value was at the end of the column (which may or may not have been in rising order). Forcing the query to ORDER BY did the trick, though there appears to be some limitations. When I tried to backfill from 1 year ago the query continued to time out. I was only successful in getting it to run with the ORDER BY clause by querying less than 1 days worth of data from the table.

[patelmc]

I am using ORDER BY clause for time_period column but I am using DESC instead of ASC and It causes duplicates in indexes all the time and my index count went up to 2 million rows but mu DB only has total 9k rows and I am checking this every 30 sec. So, does DESC causing this duplicate rows?

[jaivijay_rio]

but why db connect v3 ignores the records in rising column.

ID value
2 xyz
3 XXX
4 ABC
5 etc

When the rising column is set to increment from id = 2, the checkpoint changes to 5 and i am only getting one row retrieved. - 4 (rest of the rows are ignored ) WHY 😞

[woodcock]

A general deployment concern: You should be running DBConnect on a Heavy Forwarder and sending events to the Indexer Tiers. DO NOT use a regular search head and ESPECIALLY do not use a Universal Forwarder or a Light Forwarder. Strange things can happen if you do the latter.

[muebel]

My first guess is something weird with the ID column. I'm guessing its a unique auto-incrementing primary key for the table?

If it was mixed up and non-unique, that would explain the bouncing around and duplicate event indexing.

[jcoates_splunk]

Try adding an ORDER BY.

[RJ_Grayson]

The ID column is definitely unique. Interestingly enough I tried changing the query this morning to include "ORDER BY ID" and it worked, the query didn't time out this time (my checkpoint value was only from data an hour ago, my previous attempt was with a checkpoint value of data from a year ago). So far since I made this change I haven't seen any duplicate events. It almost sounds like the database table I'm querying doesn't have it's ID column ordered correctly (if that's a thing, I'm not a DBA by any stretch) and is causing some weirdness with the checkpoint value when it attempts to query the DB table. I'm going to check with the DBA who maintains this today to see if my suspicions are correct.

[felipecerda]

I was having the same problem until I read your comment here. I originally had "order by ID desc" at the end of my query but I removed "desc" and only left "order by ID" like you did, and I got the same result, so far I haven't seen duplicate events.

[jtacy]

You're right: the sort order for a query is nondeterministic without an ORDER BY clause. Here's a little discussion about it for SQL Server but it likely applies to most databases (the SQL spec doesn't specify an implicit sort order):
http://dba.stackexchange.com/questions/5774/why-is-ssms-inserting-new-rows-at-the-top-of-a-table-not...

The documentation for DB Connect also states that sorting on the rising column is required:
http://docs.splunk.com/Documentation/DBX/3.0.0/DeployDBX/Createandmanagedatabaseinputs#Rising_Column