airbytehq / airbytehq/airbyte

[source-mssql] CDC Sync runs infinitely during heartbeat change events when the last heartbeat timestamp is null

オープン
#60,304 コメント 6 件 リアクション 0 件 担当者 0 名 GitHub で見る
area/connectors autoteam cdc community connectors/source/mssql team/db-dw-sources type/bug
主要言語
Python
スター
22.1k
フォーク
5.3k
PR マージ指標
PR 指標を取得中

説明

### Connector Name

source-mssql

### Connector Version

4.1.27

### What step the error happened?

During the sync

### Relevant information

We currently see an issue where CDC syncs run for an infinite amount of time after . This happens when there is a table that has no activity for days. These are the steps that you can try to reproduce. This is how we were able to reproduce on our customer's environment.

Steps to Reproduce:
1. Create a table in MSSQL in incremental mode and shove some good amount of random data into it.
2. Create a connection in airbyte with just that table and run the sync. The first sync will finish with a historical load and then add some more data but don't start the sync yet.
3. Now do not make any updates to the table for the next 20 or 30 days and you should be able to reproduce the issue
4. Make sure that the source has a initial wait time set to max i.e 1 hour and now run the sync and you will see that the connection goes in an idle state where debezium is reading mssql heartbeat (this heartbeat is different from your platform heartbeat) change events which means that the connector lsn heartbeat is not progressing

Generally if the initial wait time out is set to 1 hour, the sync should finish right after the 1 hour mark when the heartbeat messages are in an idle state due to the logic in DebeziumRecordIterator.kt which knows how to handle a situation when heartbeat is not progressing. The firstRecordWaitTime is the intial wait time out

```
private fun heartbeatPosNotChanging(): Boolean {
if (this.tsLastHeartbeat == null) {
return false
}

val timeElapsedSinceLastHeartbeatTs =
Duration.between(this.tsLastHeartbeat, LocalDateTime.now())
return timeElapsedSinceLastHeartbeatTs.compareTo(firstRecordWaitTime) > 0
}
```

Sometimes (as mentioned in steps for reproduction) what happens is that the loop that calls the above function, its stuck in an infinite state which is when the value of this.tsLastHeartbeat is null and i never see the value of this timestamp get updated.
In the below logs, you should see the timestamp where it starts emitting the heartbeat events and after a few spaces I am giving the output of the last time stamp that i saw the heartbeat event. Note that I had to create a custom connector to prove this, so the log messages might be different from what you see on your platform. The sync was running in an idle state for 4 hours even though we had a 1 hour initial wait time out set. I had to cancel the sync otherwise it would run for an indefinite amount of time

Solution:

The easiest way to solve this problem is to check wether this.tsLastHeartbeat has been null for a period of time. This could be set to the initial wait time but ideally this logic should be replaced with a special heartbeat time out since the initial wait time is for debezium to figure out the first record it can fetch in the initial wait time.

### Relevant log output

```shell
2025-05-01 12:26:10 source INFO main i.a.c.i.d.i.RecordWaitTimeUtil(getFirstRecordWaitTime):68 First record waiting time: 3600 seconds
2025-05-01 12:26:10 source INFO main i.a.i.s.m.i.MssqlInitialReadUtil(getCdcReadIterators):197 First record waiting time: 3600 seconds

2025-05-01 12:26:47 source INFO pool-5-thread-1 i.a.c.i.d.AirbyteDebeziumHandler$CapacityReportingBlockingQueue(reportQueueUtilization):48 CDC events queue stats: size=0, cap=10000, puts=3, polls=0
2025-05-01 12:26:47 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(computeNext):90 CDC events queue poll(): blocked for PT10.47050344S after 187 previous call(s) which were not logged.
2025-05-01 12:26:47 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(computeNext):143 GAURAV'S HEARTBEAT STOPPED EVENT: heartbeat position: 00019fda:001324bb:00b7, last heartbeat position: 00019fda:001324bb:00b7
2025-05-01 12:26:47 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(computeNext):147 CDC events queue poll(): returned a heartbeat event: no progress since last heartbeat.
2025-05-01 12:26:47 source INFO main i.a.i.s.m.MssqlCdcTargetPosition(reachedTargetPosition):117 Checking if target position is reached. Target LSN: 00019fdf:000605ba:0003, Position from heartbeat: 00019fda:001324bb:00b7
2025-05-01 12:26:47 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(heartbeatPosNotChanging):269 Checking if heartbeat position is not changing, last heartbeat: null
2025-05-01 12:26:57 source INFO pool-5-thread-1 i.d.c.c.BaseSourceTask(logStatistics):351 2 records sent during previous 00:00:20.548, last recorded offset of {server=FacetsReport, database=FacetsReport} partition is {event_serial_no=2, commit_lsn=00019fda:001324bb:00b7, change_lsn=00019fda:001322e1:012b}
2025-05-01 12:26:57 source INFO pool-5-thread-1 i.a.c.i.d.AirbyteDebeziumHandler$CapacityReportingBlockingQueue(reportQueueUtilization):48 CDC events queue stats: size=0, cap=10000, puts=4, polls=0
2025-05-01 12:26:57 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(computeNext):90 CDC events queue poll(): blocked for PT10.020363236S after its previous call which was also logged.
2025-05-01 12:26:57 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(computeNext):143 GAURAV'S HEARTBEAT STOPPED EVENT: heartbeat position: 00019fda:001324bb:00b7, last heartbeat position: 00019fda:001324bb:00b7
2025-05-01 12:26:57 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(computeNext):147 CDC events queue poll(): returned a heartbeat event: no progress since last heartbeat.
2025-05-01 12:26:57 source INFO main i.a.i.s.m.MssqlCdcTargetPosition(reachedTargetPosition):117 Checking if target position is reached. Target LSN: 00019fdf:000605ba:0003, Position from heartbeat: 00019fda:001324bb:00b7
2025-05-01 12:26:57 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(heartbeatPosNotChanging):269 Checking if heartbeat position is not changing, last heartbeat: null
2025-05-01 12:27:07 source INFO pool-5-thread-1 i.a.c.i.d.AirbyteDebeziumHandler$CapacityReportingBlockingQueue(reportQueueUtilization):48 CDC events queue stats: size=0, cap=10000, puts=5, polls=0
2025-05-01 12:27:07 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(computeNext):90 CDC events queue poll(): blocked for PT10.521561502S after its previous call which was also logged.
2025-05-01 12:27:07 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(computeNext):143 GAURAV'S HEARTBEAT STOPPED EVENT: heartbeat position: 00019fda:001324bb:00b7, last heartbeat position: 00019fda:001324bb:00b7
2025-05-01 12:27:07 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(computeNext):147 CDC events queue poll(): returned a heartbeat event: no progress since last heartbeat.
2025-05-01 12:27:07 source INFO main i.a.i.s.m.MssqlCdcTargetPosition(reachedTargetPosition):117 Checking if target position is reached. Target LSN: 00019fdf:000605ba:0003, Position from heartbeat: 00019fda:001324bb:00b7
2025-05-01 12:27:07 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(heartbeatPosNotChanging):269 Checking if heartbeat position is not changing, last heartbeat: null
2025-05-01 12:27:18 source INFO pool-5-thread-1 i.a.c.i.d.AirbyteDebeziumHandler$CapacityReportingBlockingQueue(reportQueueUtilization):48 CDC events queue stats: size=0, cap=10000, puts=6, polls=0
2025-05-01 12:27:18 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(computeNext):90 CDC events queue poll(): blocked for PT10.52164078S after its previous call which was also logged.
2025-05-01 12:27:18 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(computeNext):143 GAURAV'S HEARTBEAT STOPPED EVENT: heartbeat position: 00019fda:001324bb:00b7, last heartbeat position: 00019fda:001324bb:00b7
2025-05-01 12:27:18 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(computeNext):147 CDC events queue poll(): returned a heartbeat event: no progress since last heartbeat.
2025-05-01 12:27:18 source INFO main i.a.i.s.m.MssqlCdcTargetPosition(reachedTargetPosition):117 Checking if target position is reached. Target LSN: 00019fdf:000605ba:0003, Position from heartbeat: 00019fda:001324bb:00b7
2025-05-01 12:27:18 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(heartbeatPosNotChanging):269 Checking if heartbeat position is not changing, last heartbeat: null

2025-05-01 16:01:06 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(heartbeatPosNotChanging):269 Checking if heartbeat position is not changing, last heartbeat: null
2025-05-01 16:01:16 source INFO pool-5-thread-1 i.a.c.i.d.AirbyteDebeziumHandler$CapacityReportingBlockingQueue(reportQueueUtilization):48 CDC events queue stats: size=0, cap=10000, puts=1230, polls=0
2025-05-01 16:01:16 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(computeNext):90 CDC events queue poll(): blocked for PT10.019839935S after its previous call which was also logged.
2025-05-01 16:01:16 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(computeNext):143 GAURAV'S HEARTBEAT STOPPED EVENT: heartbeat position: 00019fda:001324bb:00b7, last heartbeat position: 00019fda:001324bb:00b7
2025-05-01 16:01:16 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(computeNext):147 CDC events queue poll(): returned a heartbeat event: no progress since last heartbeat.
2025-05-01 16:01:16 source INFO main i.a.i.s.m.MssqlCdcTargetPosition(reachedTargetPosition):117 Checking if target position is reached. Target LSN: 00019fdf:000605ba:0003, Position from heartbeat: 00019fda:001324bb:00b7
2025-05-01 16:01:16 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(heartbeatPosNotChanging):269 Checking if heartbeat position is not changing, last heartbeat: null
2025-05-01 16:01:26 source INFO pool-5-thread-1 i.a.c.i.d.AirbyteDebeziumHandler$CapacityReportingBlockingQueue(reportQueueUtilization):48 CDC events queue stats: size=0, cap=10000, puts=1231, polls=0
2025-05-01 16:01:26 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(computeNext):90 CDC events queue poll(): blocked for PT10.520768844S after its previous call which was also logged.
2025-05-01 16:01:26 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(computeNext):143 GAURAV'S HEARTBEAT STOPPED EVENT: heartbeat position: 00019fda:001324bb:00b7, last heartbeat position: 00019fda:001324bb:00b7
2025-05-01 16:01:26 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(computeNext):147 CDC events queue poll(): returned a heartbeat event: no progress since last heartbeat.
2025-05-01 16:01:26 source INFO main i.a.i.s.m.MssqlCdcTargetPosition(reachedTargetPosition):117 Checking if target position is reached. Target LSN: 00019fdf:000605ba:0003, Position from heartbeat: 00019fda:001324bb:00b7
2025-05-01 16:01:26 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(heartbeatPosNotChanging):269 Checking if heartbeat position is not changing, last heartbeat: null
2025-05-01 16:01:37 source INFO pool-5-thread-1 i.a.c.i.d.AirbyteDebeziumHandler$CapacityReportingBlockingQueue(reportQueueUtilization):48 CDC events queue stats: size=0, cap=10000, puts=1232, polls=0
2025-05-01 16:01:37 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(computeNext):90 CDC events queue poll(): blocked for PT10.520810749S after its previous call which was also logged.
2025-05-01 16:01:37 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(computeNext):143 GAURAV'S HEARTBEAT STOPPED EVENT: heartbeat position: 00019fda:001324bb:00b7, last heartbeat position: 00019fda:001324bb:00b7
2025-05-01 16:01:37 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(computeNext):147 CDC events queue poll(): returned a heartbeat event: no progress since last heartbeat.
2025-05-01 16:01:37 source INFO main i.a.i.s.m.MssqlCdcTargetPosition(reachedTargetPosition):117 Checking if target position is reached. Target LSN: 00019fdf:000605ba:0003, Position from heartbeat: 00019fda:001324bb:00b7
2025-05-01 16:01:37 source INFO main i.a.c.i.d.i.DebeziumRecordIterator(heartbeatPosNotChanging):269 Checking if heartbeat position is not changing, last heartbeat: null
```

### Contribute

- [x] Yes, I want to contribute

コントリビューションガイド

コントリビューションガイドを開く

評価

この issue はまだ評価されていません。

新しい issue をメールで受け取る

初心者向けの GitHub issue を短くまとめたダイジェスト。