Understand snapshot and offset behaviour in mssql source connector using CDC

[ritikanaidu-trakstar]

Hi,

I am using the Airbyte OSS version to ingest data from MSSQL server to Snowflake using CDC. The retention period is set to 10 days in SQL Server. Every 11th day, the job fails with this error -

2024-06-25 11:22:45 �[44msource�[0m > ERROR main i.a.c.i.b.s.SshWrappedSource(read):71 Exception occurred while getting the delegate read iterator, closing SSH tunnel io.airbyte.commons.exceptions.ConfigErrorException: Saved offset no longer present on the server. Please reset the connection, and then increase binlog retention and/or increase sync frequency.

To recover this, I have to reset the data and trigger a full refresh so that airbyte can get an initial snapshot again.

Looking at the events building up to this error, the lsn which the log reports missing from server - 0017bf25:0002d9d7:0004 is the lsn from the initial snapshot taken 10 days ago.

Logs from 10 days ago, snapshot offset shows that commit_lsn = 0017bf25:0002d9d7:0004

2024-06-14 12:24:17 ^[[44msource^[[0m > INFO main i.a.i.s.m.c.MssqlDebeziumStateUtil(format):185 Initial Debezium state offset constructed: {"[\"ZoomSTG\",{\"server\":\"ZoomSTG\",\"database\":\"ZoomSTG\"}]":"{\"commit_lsn\":\"0017bf25:0002d9d7:0004\",\"snapshot\":true,\"snapshot_completed\":true}"}

Latest logs where airbyte tries to locate the initial offset on the server, and fails because the lsn has been cleaned up by sql server after the retention period.

2024-06-25 11:22:45 �[44msource�[0m > INFO main i.d.c.CommonConnectorConfig(getSourceInfoStructMaker):1221 Loading the custom source info struct maker plugin: io.debezium.connector.sqlserver.SqlServerSourceInfoStructMaker
2024-06-25 11:22:45 �[44msource�[0m > INFO main i.a.i.s.m.c.MssqlDebeziumStateUtil(extractStateAttributes):240 Found previous partition offset SqlServerPartition [sourcePartition={server=ZoomSTG, database=ZoomSTG}]: {transaction_id=null, event_serial_no=0, commit_lsn=0017bf25:0002d9d7:0004, change_lsn=NULL}
2024-06-25 11:22:45 �[44msource�[0m > INFO main i.a.i.s.m.c.MssqlDebeziumStateUtil(parseSavedOffset):220 Closing offsetStorageReader and fileOffsetBackingStore
2024-06-25 11:22:45 �[44msource�[0m > INFO main o.a.k.c.s.FileOffsetBackingStore(stop):71 Stopped FileOffsetBackingStore
2024-06-25 11:22:45 �[43mdestination�[0m > 2024-06-25T11:22:45,111`�[32mINFO�[m`i.a.c.d.j.DefaultJdbcDatabase(lambda$unsafeQuery$1):132 - closing connection
2024-06-25 11:22:45 �[43mdestination�[0m > 2024-06-25T11:22:45,112`�[32mINFO�[m`i.a.i.d.s.t.SnowflakeV2TableMigrator(migrateIfNecessary):53 - Checking whether upcasing migration is necessary for tbl_bnf_suprvsr_link. Sync mode requires migration: true; existing case-sensitive table exists: false; existing uppercased table does not exist: false
2024-06-25 11:22:45 �[44msource�[0m > INFO main i.a.i.s.m.c.MssqlDebeziumStateUtil(lambda$savedOffsetStillPresentOnServer$3):268 0017bf25:0002d9d7:0004 lsn exists on server: [false]. (min server lsn: 0017bf3e:000132cc:0008 max server lsn: 0017c059:0004f2d5:0009)
2024-06-25 11:22:45 �[46mplatform�[0m > SOURCE analytics [airbyte/source-mssql:4.0.17] | Type: db-sources-cdc-cursor-invalid | Value: 1

My understanding of airbyte and debezium internals is limited. I would like to know if this is normal behaviour that airbyte tries to look for an lsn that will definitely run out its time in due course (retention period). Shouldn't it be looking for the incremental min_lsn on the server? Or should it be taking incremental (or blocking) snapshots periodically to build upon the initial snapshot taken during full refresh..? Appreciate any help in this regard, since this issue has been plaguing us for several weeks now. Thanks!