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

Oracle duplicates on connector restart

    XMLWordPrintable

Details

    Description

      SQL update on oracle happened at 2022-04-01 04:27:05

      first pod:

      [2022-04-01 04:26:54,378] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:27:04,378] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:27:07,317] INFO 3 records sent during previous 00:02:15.609, last recorded offset: {commit_scn=521946806622, transaction_id=null, snapshot_pending_tx=24001300c14b2800:521942243012, snapshot_scn=521942243764, scn=521946805424} (io.debezium.connector.common.BaseSourceTask)
      [2022-04-01 04:27:10,756] WARN Event for transaction 1500010085173900 has already been processed, skipped. (io.debezium.connector.oracle.logminer.processor.memory.MemoryLogMinerEventProcessor)
      [2022-04-01 04:27:14,047] WARN Event for transaction 1500010085173900 has already been processed, skipped. (io.debezium.connector.oracle.logminer.processor.memory.MemoryLogMinerEventProcessor)
      [2022-04-01 04:27:14,378] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:27:24,382] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:27:34,382] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:27:44,382] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:27:54,383] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:28:04,383] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:28:14,383] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:28:24,384] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:28:34,384] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:28:44,384] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:28:54,384] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:29:04,385] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:29:14,385] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:29:24,385] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:29:34,386] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:29:44,386] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:29:54,386] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:30:04,386] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:30:14,387] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:30:24,387] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:30:26,893] INFO Successfully processed removal of connector 'kafka-connect-src-01' (org.apache.kafka.connect.storage.KafkaConfigBackingStore)
      [2022-04-01 04:30:26,893] INFO [Worker clientId=connect-1, groupId=cp-kafka-connect-src] Connector kafka-connect-src-01 config removed (org.apache.kafka.connect.runtime.distributed.DistributedHerder)
      [2022-04-01 04:30:29,683] INFO [Worker clientId=connect-1, groupId=cp-kafka-connect-src] Handling connector-only config update by stopping connector kafka-connect-src-01 (org.apache.kafka.connect.runtime.distributed.DistributedHerder)
      [2022-04-01 04:30:29,683] INFO Stopping connector kafka-connect-src-01 (org.apache.kafka.connect.runtime.Worker)
      [2022-04-01 04:30:29,683] INFO Scheduled shutdown for WorkerConnector{id=kafka-connect-src-01} (org.apache.kafka.connect.runtime.WorkerConnector)
      [2022-04-01 04:30:29,684] INFO Completed shutdown for WorkerConnector{id=kafka-connect-src-01} (org.apache.kafka.connect.runtime.WorkerConnector)
      [2022-04-01 04:30:29,685] INFO [Worker clientId=connect-1, groupId=cp-kafka-connect-src] Rebalance started (org.apache.kafka.connect.runtime.distributed.WorkerCoordinator)
      [2022-04-01 04:30:29,685] INFO [Worker clientId=connect-1, groupId=cp-kafka-connect-src] (Re-)joining group (org.apache.kafka.clients.consumer.internals.AbstractCoordinator)
      [2022-04-01 04:30:29,690] INFO [Worker clientId=connect-1, groupId=cp-kafka-connect-src] Successfully joined group with generation Generation{generationId=25, memberId='redact', protocol='sessioned'} (org.apache.kafka.clients.consumer.internals.AbstractCoordinator)
      [2022-04-01 04:30:29,740] INFO [Worker clientId=connect-1, groupId=cp-kafka-connect-src] Successfully synced group in generation Generation{generationId=25, memberId='redact', protocol='sessioned'} (org.apache.kafka.clients.consumer.internals.AbstractCoordinator)
      [2022-04-01 04:30:29,741] INFO Stopping connector kafka-connect-src-01 (org.apache.kafka.connect.runtime.Worker)
      [2022-04-01 04:30:29,741] WARN Ignoring stop request for unowned connector kafka-connect-src-01 (org.apache.kafka.connect.runtime.Worker)
      [2022-04-01 04:30:29,741] INFO Stopping task kafka-connect-src-01-0 (org.apache.kafka.connect.runtime.Worker)
      [2022-04-01 04:30:29,741] WARN Ignoring await stop request for non-present connector kafka-connect-src-01 (org.apache.kafka.connect.runtime.Worker)
      [2022-04-01 04:30:30,228] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:30:30,228] INFO Stopping down connector (io.debezium.connector.common.BaseSourceTask)
      [2022-04-01 04:30:31,807] INFO startScn=521946816124, endScn=521946816941 (io.debezium.connector.oracle.logminer.LogMinerStreamingChangeEventSource)
      [2022-04-01 04:30:31,807] INFO Streaming metrics dump: OracleStreamingChangeEventSourceMetrics{currentScn=521946816941, oldestScn=521946816125, committedScn=521946816852, offsetScn=521946816124, logMinerQueryCount=107, totalProcessedRows=24380, totalCapturedDmlCount=5, totalDurationOfFetchingQuery=PT42.623021S, lastCapturedDmlCount=0, lastDurationOfFetchingQuery=PT0.426255S, maxCapturedDmlCount=1, maxDurationOfFetchingQuery=PT0.632614S, totalBatchProcessingDuration=PT46.398845S, lastBatchProcessingDuration=PT0.471523S, maxBatchProcessingThroughput=2, currentLogFileName=[/app/data2/redact/redact/onlinelog/o1_mf_3_jnltk3gt_.log, /app/fra2/redact/redact/onlinelog/o1_mf_3_jnltk34t_.log], minLogFilesMined=2, maxLogFilesMined=2, redoLogStatus=[/app/fra2/redact/redact/onlinelog/o1_mf_3_jnltk34t_.log | CURRENT, /app/data2/redact/redact/onlinelog/o1_mf_3_jnltk3gt_.log | CURRENT, /app/fra2/redact/redact/onlinelog/o1_mf_1_jnltk32q_.log | INACTIVE, /app/data2/redact/redact/onlinelog/o1_mf_2_jnltk3gf_.log | INACTIVE, /app/data2/redact/redact/onlinelog/o1_mf_1_jnltk3cl_.log | INACTIVE, /app/fra2/redact/redact/onlinelog/o1_mf_2_jnltk341_.log | INACTIVE], switchCounter=0, batchSize=20000, millisecondToSleepBetweenMiningQuery=3000, hoursToKeepTransaction=0, networkConnectionProblemsCounter0, batchSizeDefault=20000, batchSizeMin=1000, batchSizeMax=100000, sleepTimeDefault=1000, sleepTimeMin=0, sleepTimeMax=3000, sleepTimeIncrement=200, totalParseTime=PT0.001519S, totalStartLogMiningSessionDuration=PT0.81828S, lastStartLogMiningSessionDuration=PT0.008S, maxStartLogMiningSessionDuration=PT0.012142S, totalProcessTime=PT46.398845S, minBatchProcessTime=PT0.38491S, maxBatchProcessTime=PT0.853923S, totalResultSetNextTime=PT0.005149S, lagFromTheSource=DurationPT3.785887S, maxLagFromTheSourceDuration=PT13M44.666385S, minLagFromTheSourceDuration=PT0.648581S, lastCommitDuration=PT0.000009S, maxCommitDuration=PT0.015242S, activeTransactions=1, rolledBackTransactions=28, committedTransactions=5727, abandonedTransactionIds=[], rolledbackTransactionIds=[06001c002afa0400, 0600090012fa0400, 08001600c9fa0400, 030003009bf80400, 090011008cfc0400, 0900090096fc0400, 0600020022fa0400, 0a000c002eec0900, 02000200fe210400, 0600060032fa0400, 0a00090043ec0900, 07001000fef80400, 07001b001df90400, 04001d009ff80400, 070021001ff90400, 070012000df90400, 04001e0093f80400, 0c0003000eb00100, 0a001a004dec0900, 0a001f0039ec0900, 0900210090fc0400, 0700170006f90400, 06000f0032fa0400, 02001000f0210400, 05000c0000f90400, 0a0003005aec0900, 0a001b005aec0900, 0a0020004cec0900], registeredDmlCount=5, committedDmlCount=2, errorCount=0, warningCount=0, scnFreezeCount=0, unparsableDdlCount=0, miningSessionUserGlobalAreaMemory=7137488, miningSessionUserGlobalAreaMaxMemory=7374384, miningSessionProcessGlobalAreaMemory=11450824, miningSessionProcessGlobalAreaMaxMemory=11450824} (io.debezium.connector.oracle.logminer.LogMinerStreamingChangeEventSource)
      [2022-04-01 04:30:31,807] INFO Offsets: OracleOffsetContext [scn=521946816124] (io.debezium.connector.oracle.logminer.LogMinerStreamingChangeEventSource)
      [2022-04-01 04:30:31,807] INFO Finished streaming (io.debezium.pipeline.ChangeEventSourceCoordinator)
      [2022-04-01 04:30:31,807] INFO Connected metrics set to 'false' (io.debezium.pipeline.ChangeEventSourceCoordinator)
      [2022-04-01 04:30:31,815] INFO Connection gracefully closed (io.debezium.jdbc.JdbcConnection)
      [2022-04-01 04:30:31,816] INFO [Producer clientId=my-topicoracle-dbhistory] Closing the Kafka producer with timeoutMillis = 30000 ms. (org.apache.kafka.clients.producer.KafkaProducer)
      [2022-04-01 04:30:31,817] INFO Metrics scheduler closed (org.apache.kafka.common.metrics.Metrics)
      [2022-04-01 04:30:31,817] INFO Closing reporter org.apache.kafka.common.metrics.JmxReporter (org.apache.kafka.common.metrics.Metrics)
      [2022-04-01 04:30:31,817] INFO Metrics reporters closed (org.apache.kafka.common.metrics.Metrics)
      [2022-04-01 04:30:31,817] INFO App info kafka.producer for my-topicoracle-dbhistory unregistered (org.apache.kafka.common.utils.AppInfoParser)
      [2022-04-01 04:30:31,817] INFO [Producer clientId=connector-producer-kafka-connect-src-01-0] Closing the Kafka producer with timeoutMillis = 30000 ms. (org.apache.kafka.clients.producer.KafkaProducer)
      [2022-04-01 04:30:31,819] INFO Metrics scheduler closed (org.apache.kafka.common.metrics.Metrics)
      [2022-04-01 04:30:31,819] INFO Closing reporter org.apache.kafka.common.metrics.JmxReporter (org.apache.kafka.common.metrics.Metrics)
      [2022-04-01 04:30:31,819] INFO Metrics reporters closed (org.apache.kafka.common.metrics.Metrics)
      [2022-04-01 04:30:31,819] INFO App info kafka.producer for connector-producer-kafka-connect-src-01-0 unregistered (org.apache.kafka.common.utils.AppInfoParser)
      [2022-04-01 04:30:31,820] INFO App info kafka.admin.client for connector-adminclient-kafka-connect-src-01-0 unregistered (org.apache.kafka.common.utils.AppInfoParser)
      [2022-04-01 04:30:31,820] INFO Metrics scheduler closed (org.apache.kafka.common.metrics.Metrics)
      [2022-04-01 04:30:31,820] INFO Closing reporter org.apache.kafka.common.metrics.JmxReporter (org.apache.kafka.common.metrics.Metrics)
      [2022-04-01 04:30:31,820] INFO Metrics reporters closed (org.apache.kafka.common.metrics.Metrics)
      [2022-04-01 04:30:31,823] INFO [Worker clientId=connect-1, groupId=cp-kafka-connect-src] Finished stopping tasks in preparation for rebalance (org.apache.kafka.connect.runtime.distributed.DistributedHerder)
      [2022-04-01 04:30:31,827] INFO [Worker clientId=connect-1, groupId=cp-kafka-connect-src] Finished flushing status backing store in preparation for rebalance (org.apache.kafka.connect.runtime.distributed.DistributedHerder)
      [2022-04-01 04:30:31,827] INFO [Worker clientId=connect-1, groupId=cp-kafka-connect-src] Joined group at generation 25 with protocol version 2 and got assignment: Assignment{error=0, leader='redact', leaderUrl='http://redact:8083/', offset=51, connectorIds=[], taskIds=[], revokedConnectorIds=[kafka-connect-src-01], revokedTaskIds=[kafka-connect-src-01-0], delay=0} with rebalance delay: 0 (org.apache.kafka.connect.runtime.distributed.DistributedHerder)
      [2022-04-01 04:30:31,828] INFO [Worker clientId=connect-1, groupId=cp-kafka-connect-src] Starting connectors and tasks using config offset 51 (org.apache.kafka.connect.runtime.distributed.DistributedHerder)
      [2022-04-01 04:30:31,828] INFO [Worker clientId=connect-1, groupId=cp-kafka-connect-src] Finished starting connectors and tasks (org.apache.kafka.connect.runtime.distributed.DistributedHerder)
      [2022-04-01 04:30:31,828] INFO [Worker clientId=connect-1, groupId=cp-kafka-connect-src] Rebalance started (org.apache.kafka.connect.runtime.distributed.WorkerCoordinator)
      [2022-04-01 04:30:31,828] INFO [Worker clientId=connect-1, groupId=cp-kafka-connect-src] (Re-)joining group (org.apache.kafka.clients.consumer.internals.AbstractCoordinator)
      [2022-04-01 04:30:31,829] INFO [Worker clientId=connect-1, groupId=cp-kafka-connect-src] Successfully joined group with generation Generation{generationId=26, memberId='redact', protocol='sessioned'} (org.apache.kafka.clients.consumer.internals.AbstractCoordinator)
      [2022-04-01 04:30:31,833] INFO [Worker clientId=connect-1, groupId=cp-kafka-connect-src] Successfully synced group in generation Generation{generationId=26, memberId='redact', protocol='sessioned'} (org.apache.kafka.clients.consumer.internals.AbstractCoordinator)
      [2022-04-01 04:30:31,833] INFO [Worker clientId=connect-1, groupId=cp-kafka-connect-src] Joined group at generation 26 with protocol version 2 and got assignment: Assignment{error=0, leader='redact', leaderUrl='http://redact:8083/', offset=51, connectorIds=[], taskIds=[], revokedConnectorIds=[], revokedTaskIds=[], delay=0} with rebalance delay: 0 (org.apache.kafka.connect.runtime.distributed.DistributedHerder)
      [2022-04-01 04:30:31,834] INFO [Worker clientId=connect-1, groupId=cp-kafka-connect-src] Starting connectors and tasks using config offset 51 (org.apache.kafka.connect.runtime.distributed.DistributedHerder)
      [2022-04-01 04:30:31,834] INFO [Worker clientId=connect-1, groupId=cp-kafka-connect-src] Finished starting connectors and tasks (org.apache.kafka.connect.runtime.distributed.DistributedHerder) 

      kubectl delete pod happened at 2022-04-01 04:30:25

      second pod:

      [2022-04-01 04:32:44,917] INFO Requested thread factory for connector OracleConnector, id = my-topicoracle named = change-event-source-coordinator (io.debezium.util.Threads)
      [2022-04-01 04:32:44,918] INFO Creating thread debezium-oracleconnector-my-topicoracle-change-event-source-coordinator (io.debezium.util.Threads)
      [2022-04-01 04:32:44,919] INFO WorkerSourceTask{id=kafka-connect-src-01-0} Source task finished initialization and start (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:32:44,920] INFO WorkerSourceTask{id=kafka-connect-src-01-0} Executing source task (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:32:44,922] INFO Metrics registered (io.debezium.pipeline.ChangeEventSourceCoordinator)
      [2022-04-01 04:32:44,923] INFO Context created (io.debezium.pipeline.ChangeEventSourceCoordinator)
      [2022-04-01 04:32:44,930] INFO The previous offset has been found. (io.debezium.connector.oracle.OracleSnapshotChangeEventSource)
      [2022-04-01 04:32:44,931] INFO Snapshot ended with SnapshotResult [status=SKIPPED, offset=OracleOffsetContext [scn=521946805424]] (io.debezium.pipeline.ChangeEventSourceCoordinator)
      [2022-04-01 04:32:44,936] INFO Connected metrics set to 'true' (io.debezium.pipeline.ChangeEventSourceCoordinator)
      [2022-04-01 04:32:45,030] INFO Database Version: Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
      Version 19.13.0.0.0 (io.debezium.connector.oracle.OracleConnection)
      [2022-04-01 04:32:45,031] INFO No incremental snapshot in progress, no action needed on start (io.debezium.pipeline.source.snapshot.incremental.AbstractIncrementalSnapshotChangeEventSource)
      [2022-04-01 04:32:45,039] INFO Connection gracefully closed (io.debezium.jdbc.JdbcConnection)
      [2022-04-01 04:32:45,039] INFO Starting streaming (io.debezium.pipeline.ChangeEventSourceCoordinator)
      [2022-04-01 04:32:47,426] INFO 3 records sent during previous 00:00:19.565, last recorded offset: {commit_scn=521946806622, transaction_id=null, snapshot_pending_tx=24001300c14b2800:521942243012, snapshot_scn=521942243764, scn=521946805424} (io.debezium.connector.common.BaseSourceTask)
      [2022-04-01 04:32:47,540] INFO The task will send records to topic 'my-topicoracle.redact' for the first time. Checking whether topic exists (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:32:47,640] INFO Topic 'my-topicoracle.redact' already exists. (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:32:47,994] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:32:58,144] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask)
      [2022-04-01 04:33:08,144] INFO WorkerSourceTask{id=kafka-connect-src-01-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask) 

      "[2022-04-01 04:32:47,426] INFO 3 records sent" should not have happened because that single oracle update was processed before at "[2022-04-01 04:27:07,317]"

       

      cc ccranfor@redhat.com 

      Attachments

        1. act1.zip
          2.51 MB
        2. act2.zip
          1.23 MB

        Issue Links

          Activity

            People

              ccranfor@redhat.com Chris Cranford
              tooptoop toop toop (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: