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

long running transaction will be abandoned and ignored

    XMLWordPrintable

Details

    • Bug
    • Resolution: Done
    • Major
    • 1.4.0.Beta1
    • 1.4.0.Alpha1
    • oracle-connector
    • None
    • False
    • False
    • Undefined
    • 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

          is related to

          Bug - A problem that impairs or prevents the functions of the product. DBZ-2754 Oracle Connector(Using Logminer) with Oracle RDS (v12) does not capture changes

          • Major - To be worked after higher priority work items are addressed. When the severity is high and the effort to change it is low to moderate, this term is chosen. Issues in this category likely have an existing workaround but implementation or execution may be non-trivial.
          • Closed

          Task - Represents a small unit of work that is not end-user facing. DBZ-2720 Check whether auto-commit DML operations trigger transaction buffer commits w/LogMiner

          • Major - To be worked after higher priority work items are addressed. When the severity is high and the effort to change it is low to moderate, this term is chosen. Issues in this category likely have an existing workaround but implementation or execution may be non-trivial.
          • Resolved

          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: