Uploaded image for project: 'Debezium'
  1. Debezium
  2. DBZ-2759

long running transaction will be abandoned and ignored

    XMLWordPrintable

Details

    • Hide

      – Start connector:

      oc apply -f ./con_src_dad_cdc.yml

       – output in connect logs:

      2020-11-13 09:17:23,226 INFO The connector will wait for 1s before proceeding (io.debezium.pipeline.source.AbstractSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:23,226 INFO The connector will wait for 1s before proceeding (io.debezium.pipeline.source.AbstractSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:28,227 INFO Snapshot step 1 - Preparing (io.debezium.relational.RelationalSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:28,264 INFO Snapshot step 2 - Determining captured tables (io.debezium.relational.RelationalSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:28,454 INFO Snapshot step 3 - Locking captured tables [INFE01A.SUVANET.CH.DADENTW.KFK_SRC_CASE1] (io.debezium.relational.RelationalSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:28,455 INFO Snapshot step 4 - Determining snapshot offset (io.debezium.relational.RelationalSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:28,475 INFO Snapshot step 5 - Reading structure of captured tables (io.debezium.relational.RelationalSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:30,275 INFO Snapshot step 6 - Persisting schema history (io.debezium.relational.RelationalSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,685 INFO JdbcValueConverters returned 'org.apache.kafka.connect.data.SchemaBuilder' for column 'TITLE' (io.debezium.connector.oracle.OracleValueConverters) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,685 INFO JdbcValueConverters returned 'org.apache.kafka.connect.data.SchemaBuilder' for column 'ROW_COMMENT' (io.debezium.connector.oracle.OracleValueConverters) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,685 INFO JdbcValueConverters returned 'org.apache.kafka.connect.data.SchemaBuilder' for column 'CREATED' (io.debezium.connector.oracle.OracleValueConverters) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,686 INFO JdbcValueConverters returned 'org.apache.kafka.connect.data.SchemaBuilder' for column 'MODIFIED' (io.debezium.connector.oracle.OracleValueConverters) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,714 INFO Snapshot step 7 - Snapshotting data (io.debezium.relational.RelationalSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,714 INFO Exporting data from table 'INFE01A.SUVANET.CH.DADENTW.KFK_SRC_CASE1' (io.debezium.relational.RelationalSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,714 INFO For table 'INFE01A.SUVANET.CH.DADENTW.KFK_SRC_CASE1' using select statement: 'SELECT * FROM "DADENTW"."KFK_SRC_CASE1" AS OF SCN 202512281528' (io.debezium.relational.RelationalSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,724 INFO Finished exporting 3 records for table 'INFE01A.SUVANET.CH.DADENTW.KFK_SRC_CASE1'; total duration '00:00:00.01' (io.debezium.relational.RelationalSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,725 INFO Snapshot - Final stage (io.debezium.pipeline.source.AbstractSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,725 INFO Snapshot ended with SnapshotResult [status=COMPLETED, offset=OracleOffsetContext [scn=202512281528]] (io.debezium.pipeline.ChangeEventSourceCoordinator) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,725 INFO Connected metrics set to 'true' (io.debezium.pipeline.metrics.StreamingChangeEventSourceMetrics) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,727 INFO Starting streaming (io.debezium.pipeline.ChangeEventSourceCoordinator) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,727 INFO Requested thread factory for connector OracleConnector, id = infedad named = transactional-buffer (io.debezium.util.Threads) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,807 WARN [Producer clientId=connector-producer-my-src-cdc-dad-0] Error while fetching metadata with correlation id 4 : {infedad.DADENTW.KFK_SRC_CASE1=LEADER_NOT_AVAILABLE} (org.apache.kafka.clients.NetworkClient) [kafka-producer-network-thread | connector-producer-my-src-cdc-dad-0]2020-11-13 09:17:34,817 INFO AbstractConfig values:  (org.apache.kafka.common.config.AbstractConfig) [DistributedHerder-connect-1-1]2020-11-13 09:18:22,870 INFO WorkerSourceTask{id=my-src-cdc-dad-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask) [SourceTaskOffsetCommitter-1]2020-11-13 09:18:22,871 INFO WorkerSourceTask{id=my-src-cdc-dad-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask) [SourceTaskOffsetCommitter-1]2020-11-13 09:18:22,915 INFO WorkerSourceTask{id=my-src-cdc-dad-0} Finished commitOffsets successfully in 45 ms (org.apache.kafka.connect.runtime.WorkerSourceTask) [SourceTaskOffsetCommitter-1]2020-11-13 09:19:22,916 INFO WorkerSourceTask{id=my-src-cdc-dad-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask) [SourceTaskOffsetCommitter-1]2020-11-13 09:19:22,916 INFO WorkerSourceTask{id=my-src-cdc-dad-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask) [SourceTaskOffsetCommitter-1]2020-11-13 09:19:34,792 INFO AbstractConfig values:  (org.apache.kafka.common.config.AbstractConfig) [DistributedHerder-connect-1-1]

       – Update Statement in SQL Developer:

      UPDATE "DADENTW"."KFK_SRC_CASE1" SET "ROW_COMMENT" = 'update for id 3' WHERE id = 3; COMMIT;

       – forced log switch:

       exec SYS.do_logswitch;

       – output in connect log:

      2020-11-13 09:20:08,712 WARN All transactions with first SCN <= 202512306365 will be abandoned, offset: 202512303660 (io.debezium.connector.oracle.logminer.LogMinerHelper) [debezium-oracleconnector-infedad-change-event-source-coordinator]
      2020-11-13 09:20:08,713 WARN Following long running transaction 0F00030084860500 will be abandoned and ignored: Transaction{firstScn=202512303665, lastScn=202512303665, redoSqls=[[update "DADENTW"."KFK_SRC_CASE1" set "ROW_COMMENT" = 'update for id 3' where "ID" = '3' and "TITLE" = 'Testfall3' and "ROW_COMMENT" = 'COMMENT for row 3' and "CREATED" = TO_DATE('2020-11-10 21:18:51', 'YYYY-MM-DD HH24:MI:SS') and "MODIFIED" = TO_DATE('2020-11-10 21:18:51', 'YYYY-MM-DD HH24:MI:SS');]]} (io.debezium.connector.oracle.logminer.LogMinerHelper) [debezium-oracleconnector-infedad-change-event-source-coordinator]
      2020-11-13 09:20:22,917 INFO WorkerSourceTask{id=my-src-cdc-dad-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask) [SourceTaskOffsetCommitter-1]
      2020-11-13 09:20:22,917 INFO WorkerSourceTask{id=my-src-cdc-dad-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask) [SourceTaskOffsetCommitter-1]
      Show
      – Start connector: oc apply -f ./con_src_dad_cdc.yml  – output in connect logs: 2020-11-13 09:17:23,226 INFO The connector will wait for 1s before proceeding (io.debezium.pipeline.source.AbstractSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:23,226 INFO The connector will wait for 1s before proceeding (io.debezium.pipeline.source.AbstractSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:28,227 INFO Snapshot step 1 - Preparing (io.debezium.relational.RelationalSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:28,264 INFO Snapshot step 2 - Determining captured tables (io.debezium.relational.RelationalSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:28,454 INFO Snapshot step 3 - Locking captured tables [INFE01A.SUVANET.CH.DADENTW.KFK_SRC_CASE1] (io.debezium.relational.RelationalSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:28,455 INFO Snapshot step 4 - Determining snapshot offset (io.debezium.relational.RelationalSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:28,475 INFO Snapshot step 5 - Reading structure of captured tables (io.debezium.relational.RelationalSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:30,275 INFO Snapshot step 6 - Persisting schema history (io.debezium.relational.RelationalSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,685 INFO JdbcValueConverters returned 'org.apache.kafka.connect.data.SchemaBuilder' for column 'TITLE' (io.debezium.connector.oracle.OracleValueConverters) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,685 INFO JdbcValueConverters returned 'org.apache.kafka.connect.data.SchemaBuilder' for column 'ROW_COMMENT' (io.debezium.connector.oracle.OracleValueConverters) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,685 INFO JdbcValueConverters returned 'org.apache.kafka.connect.data.SchemaBuilder' for column 'CREATED' (io.debezium.connector.oracle.OracleValueConverters) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,686 INFO JdbcValueConverters returned 'org.apache.kafka.connect.data.SchemaBuilder' for column 'MODIFIED' (io.debezium.connector.oracle.OracleValueConverters) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,714 INFO Snapshot step 7 - Snapshotting data (io.debezium.relational.RelationalSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,714 INFO Exporting data from table 'INFE01A.SUVANET.CH.DADENTW.KFK_SRC_CASE1' (io.debezium.relational.RelationalSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,714 INFO For table 'INFE01A.SUVANET.CH.DADENTW.KFK_SRC_CASE1' using select statement: 'SELECT * FROM "DADENTW" . "KFK_SRC_CASE1" AS OF SCN 202512281528' (io.debezium.relational.RelationalSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,724 INFO Finished exporting 3 records for table 'INFE01A.SUVANET.CH.DADENTW.KFK_SRC_CASE1' ; total duration '00:00:00.01' (io.debezium.relational.RelationalSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,725 INFO Snapshot - Final stage (io.debezium.pipeline.source.AbstractSnapshotChangeEventSource) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,725 INFO Snapshot ended with SnapshotResult [status=COMPLETED, offset=OracleOffsetContext [scn=202512281528]] (io.debezium.pipeline.ChangeEventSourceCoordinator) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,725 INFO Connected metrics set to ' true ' (io.debezium.pipeline.metrics.StreamingChangeEventSourceMetrics) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,727 INFO Starting streaming (io.debezium.pipeline.ChangeEventSourceCoordinator) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,727 INFO Requested thread factory for connector OracleConnector, id = infedad named = transactional-buffer (io.debezium.util.Threads) [debezium-oracleconnector-infedad-change-event-source-coordinator]2020-11-13 09:17:32,807 WARN [Producer clientId=connector-producer-my-src-cdc-dad-0] Error while fetching metadata with correlation id 4 : {infedad.DADENTW.KFK_SRC_CASE1=LEADER_NOT_AVAILABLE} (org.apache.kafka.clients.NetworkClient) [kafka-producer-network-thread | connector-producer-my-src-cdc-dad-0]2020-11-13 09:17:34,817 INFO AbstractConfig values:  (org.apache.kafka.common.config.AbstractConfig) [DistributedHerder-connect-1-1]2020-11-13 09:18:22,870 INFO WorkerSourceTask{id=my-src-cdc-dad-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask) [SourceTaskOffsetCommitter-1]2020-11-13 09:18:22,871 INFO WorkerSourceTask{id=my-src-cdc-dad-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask) [SourceTaskOffsetCommitter-1]2020-11-13 09:18:22,915 INFO WorkerSourceTask{id=my-src-cdc-dad-0} Finished commitOffsets successfully in 45 ms (org.apache.kafka.connect.runtime.WorkerSourceTask) [SourceTaskOffsetCommitter-1]2020-11-13 09:19:22,916 INFO WorkerSourceTask{id=my-src-cdc-dad-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask) [SourceTaskOffsetCommitter-1]2020-11-13 09:19:22,916 INFO WorkerSourceTask{id=my-src-cdc-dad-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask) [SourceTaskOffsetCommitter-1]2020-11-13 09:19:34,792 INFO AbstractConfig values:  (org.apache.kafka.common.config.AbstractConfig) [DistributedHerder-connect-1-1]  – Update Statement in SQL Developer: UPDATE "DADENTW" . "KFK_SRC_CASE1" SET "ROW_COMMENT" = 'update for id 3' WHERE id = 3; COMMIT;  – forced log switch:  exec SYS.do_logswitch;  – output in connect log: 2020-11-13 09:20:08,712 WARN All transactions with first SCN <= 202512306365 will be abandoned, offset: 202512303660 (io.debezium.connector.oracle.logminer.LogMinerHelper) [debezium-oracleconnector-infedad-change-event-source-coordinator] 2020-11-13 09:20:08,713 WARN Following long running transaction 0F00030084860500 will be abandoned and ignored: Transaction{firstScn=202512303665, lastScn=202512303665, redoSqls=[[update "DADENTW" . "KFK_SRC_CASE1" set "ROW_COMMENT" = 'update for id 3' where "ID" = '3' and "TITLE" = 'Testfall3' and "ROW_COMMENT" = 'COMMENT for row 3' and "CREATED" = TO_DATE( '2020-11-10 21:18:51' , 'YYYY-MM-DD HH24:MI:SS' ) and "MODIFIED" = TO_DATE( '2020-11-10 21:18:51' , 'YYYY-MM-DD HH24:MI:SS' );]]} (io.debezium.connector.oracle.logminer.LogMinerHelper) [debezium-oracleconnector-infedad-change-event-source-coordinator] 2020-11-13 09:20:22,917 INFO WorkerSourceTask{id=my-src-cdc-dad-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask) [SourceTaskOffsetCommitter-1] 2020-11-13 09:20:22,917 INFO WorkerSourceTask{id=my-src-cdc-dad-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask) [SourceTaskOffsetCommitter-1]

    Description

      After successful start and snapshot, the connector starts with streaming but no changes are emitted to Kafka topics. If finally ends in ORA-1291: missing log file.

      Issues:

      • the connector only reacts on changes in the redo log after a log switch (forced or not forced). Changes in the active log aren't processed
      • after the log switch, the changes are ignored because changes' SCN is too old
      • after a few more log switches we end up in ORA-1291 like
      Caused by: Error : 1291, Position : 0, Sql = BEGIN sys.dbms_logmnr.start_logmnr(startScn => '202512024031', endScn => '202512024031', OPTIONS => DBMS_LOGMNR.DICT_FROM_REDO_LOGS + DBMS_LOGMNR.DDL_DICT_TRACKING + DBMS_LOGMNR.NO_ROWID_IN_STMT);END;, OriginalSql = BEGIN sys.dbms_logmnr.start_logmnr(startScn => '202512024031', endScn => '202512024031', OPTIONS => DBMS_LOGMNR.DICT_FROM_REDO_LOGS + DBMS_LOGMNR.DDL_DICT_TRACKING + DBMS_LOGMNR.NO_ROWID_IN_STMT);END;, Error Msg = ORA-01291: missing logfile
       ORA-06512: at "SYS.DBMS_LOGMNR", line 58
       ORA-06512: at line 1

       

       Our environment is a non CDB btw.

       

      Attachments

        Issue Links

          Activity

            People

              ccranfor@redhat.com Chris Cranford
              renerh René Rütter
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: