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

Sequence number not found Error despite the sequence being physically present

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Unresolved
    • Icon: Major Major
    • under-triaging
    • 3.1.1.Final
    • oracle-connector
    • None
    • True
    • Hide

      It stopped the application from flowing normally. Even a regular restart did not help because it still can't find the sequence. Had to clear the Kafka offset topic and then restart to start all the way from beginning

      Show
      It stopped the application from flowing normally. Even a regular restart did not help because it still can't find the sequence. Had to clear the Kafka offset topic and then restart to start all the way from beginning
    • False

      In order to make your issue reports as actionable as possible, please provide the following information, depending on the issue type.

      Bug report

      On August 27th early morning at around 1:32 AM Central time (6:32 AM GMT), our Oracle Debezium listener just stopped by complaining that Sequence 83875 does not exist and that it contains only log from sequence 83877 (DBA did confirm with logs which I am attaching to say that sequences upto 83876 id not get physically deleted at 7:30 AM Central time, but we do see some status = 'D' record in GV$ARCHIVED_LOG around 1:32 AM Central time (just around 7 seconds before our Debezium connector stopped with the error). Even a restart did not fix it as it can't find the right sequence/offset to start. Only after clearing Kafka offset topic, then it started working again fresh after capturing the structure of all the tables, all he way from the beginning.

      ERROR RECEIVED BY ORACLE JAVA CONTAINER WITH EMBEDDED DEBEZIUM ENGINE FLOW USING KAFKA BASED OFFSET MANAGEMENT AT 1:32 AM Central time

      {"@timestamp":"2025-08-27T06:32:13.069Z","ecs.version":"1.2.0","log.level":"ERROR","message":"Mining session stopped due to error.","process.thread.name":"debezium-oracleconnector-mydb-3735-change-event-source-coordinator","log.logger":"io.debezium.connector.oracle.logminer.LogMinerStreamingChangeEventSource","dbz.connectorContext":"streaming","dbz.connectorName":"my-3735","dbz.connectorType":"Oracle","dbz.databaseName":"MY3735","dbz.taskId":"0","error.type":"java.sql.SQLException","error.message":"ORA-00310: archived log contains sequence 83877; sequence 83875 required\nORA-00334: archived log: '+DATAC4/MYDB/ONLINELOG/group_1.302.1137059201'\n\nhttps://docs.oracle.com/error-help/db/ora-00310/","error.stack_trace":"java.sql.SQLException: ORA-00310: archived log contains sequence 83877; sequence 83875 required\nORA-00334: archived log: '+DATAC4/MYDB/ONLINELOG/group_1.302.1137059201'\n\nhttps://docs.oracle.com/error-help/db/ora-00310/\n\tat oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:709)\n\tat oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:609)\n\tat oracle.jdbc.driver.T4C8Oall.processError(T4C8Oall.java:1347)\n\tat oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:1100)\n\tat oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:408)\n\tat oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:499)\n\tat oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:274)\n\tat oracle.jdbc.driver.T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:1231)\n\tat

      OUR DATABASE ENTRIES  IN GV$ARCHIVED_LOG TABLE. 

      Note that our Completion times are in Central time zone. As we can see, just 7 seconds before we saw this error, we see an entry with status = 'D' and 'A' for sequence number 83876.

       

      But as per the RMAN STATUS, actual records get deleted only once in 4 hours and on 27th August, 2025, next deletion happened only at 3:30 AM Central time, followed by another deletion at 7:30 AM Central time. (DBA has also confirmed that actual deletion of 83876 happened only at 7:30 AM Central time). 
      DATA FROM V$RMAN_STATUS below

      Here are the logs our DBA Provided us for around 1:32 AM Central time when the problem happened

      2025-08-27T01:31:37.742561-05:00

      LOGMINER: Begin mining logfile for session -2146160639 thread 1 sequence 83874, +RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_1_seq_83874.816.1210210277

      2025-08-27T01:31:37.754345-05:00

      LOGMINER: Begin mining logfile for session -2146160639 thread 2 sequence 54578, +RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_2_seq_54578.4058.1210210277

      2025-08-27T01:31:38.191128-05:00

      Thread 1 advanced to log sequence 83876 (LGWR switch),  current SCN: 12801901024

        Current log# 2 seq# 83876 mem# 0: +DATAC4/MYDB/ONLINELOG/group_2.303.1137059201

        Current log# 2 seq# 83876 mem# 1: +RECOC4/MYDB/ONLINELOG/group_2.278.1137059201

      2025-08-27T01:31:39.783183-05:00

      ARC6 (PID:48587): Archived Log entry 171355 added for B-1137059200.T-1.S-83875 LOS:0x00000002fb0c2208 NXS:0x00000002fb0d8098 NAB:1918795 ID 0x40742365 LAD:1

      2025-08-27T01:31:56.471987-05:00

      LOGMINER: End   mining logfile for session -2146160639 thread 1 sequence 83874, +RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_1_seq_83874.816.1210210277

      2025-08-27T01:31:56.483203-05:00

      LOGMINER: Begin mining logfile for session -2146160639 thread 1 sequence 83875, +DATAC4/MYDB/ONLINELOG/group_1.302.1137059201

      2025-08-27T01:31:57.371944-05:00

      LOGMINER: End   mining logfile for session -2146160639 thread 2 sequence 54578, +RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_2_seq_54578.4058.1210210277

      2025-08-27T01:31:57.386898-05:00

      LOGMINER: Begin mining logfile for session -2146160639 thread 2 sequence 54579, +RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_2_seq_54579.3334.1210210295

      2025-08-27T01:32:05.240818-05:00

      Thread 1 advanced to log sequence 83877 (LGWR switch),  current SCN: 12802035991

        Current log# 1 seq# 83877 mem# 0: +DATAC4/MYDB/ONLINELOG/group_1.302.1137059201

        Current log# 1 seq# 83877 mem# 1: +RECOC4/MYDB/ONLINELOG/group_1.299.1137059201

      2025-08-27T01:32:06.677067-05:00

      ARC7 (PID:48591): Archived Log entry 171357 added for B-1137059200.T-1.S-83876 LOS:0x00000002fb0d8098 NXS:0x00000002fb0f90f9 NAB:1816599 ID 0x40742365 LAD:1

      2025-08-27T01:32:13.034362-05:00

      LOGMINER: Alternate logfile found.  Transition to mining archived logfile for session -2146160639 thread 1 sequence 83875, +DATAC4/MYDB/ONLINELOG/group_1.302.1137059201

      2025-08-27T01:32:38.275653-05:00

      Thread 1 advanced to log sequence 83878 (LGWR switch),  current SCN: 12802177506

        Current log# 2 seq# 83878 mem# 0: +DATAC4/MYDB/ONLINELOG/group_2.303.1137059201

        Current log# 2 seq# 83878 mem# 1: +RECOC4/MYDB/ONLINELOG/group_2.278.1137059201

      2025-08-27T01:32:39.949406-05:00

      ARC8 (PID:48605): Archived Log entry 171361 added for B-1137059200.T-1.S-83877 LOS:0x00000002fb0f90f9 NXS:0x00000002fb11b9b9 NAB:1947386 ID 0x40742365 LAD:1

      2025-08-27T02:00:00.192639-05:00

      Closing Resource Manager plan via scheduler window

      2025-08-27T02:02:53.391409-05:00

      Thread 1 advanced to log sequence 83879 (LGWR switch),  current SCN: 12802705026

        Current log# 1 seq# 83879 mem# 0: +DATAC4/MYDB/ONLINELOG/group_1.302.1137059201

        Current log# 1 seq# 83879 mem# 1: +RECOC4/MYDB/ONLINELOG/group_1.299.1137059201

      2025-08-27T02:02:54.781218-05:00

      ARC9 (PID:48611): Archived Log entry 171365 added for B-1137059200.T-1.S-83878 LOS:0x00000002fb11b9b9 NXS:0x00000002fb19c682 NAB:1797964 ID 0x40742365 LAD:1

      2025-08-27T02:05:57.935331-05:00

      This is the RMAN logs that DBA provided proving that actual deletion only happened at 7:30 AM Central

      Starting Control File and SPFILE Autobackup at Aug 27 2025 07:30:18

      piece handle=/zfssa/ed51/backup1/MYDB/CF_MYDB_c-1047488442-20250827-01 comment=NONE

      Finished Control File and SPFILE Autobackup at Aug 27 2025 07:30:20

       

      List of Archived Log Copies for database with db_unique_name MYDB

      =====================================================================

       

      Key     Thrd Seq     S Low Time

      ------- ---- ------- - --------------------

      171350  1    83874   A Aug 26 2025 23:30:08

              Name: +RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_1_seq_83874.816.1210210277

       

      171355  1    83875   A Aug 27 2025 01:31:17

              Name: +RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_1_seq_83875.671.1210210299

       

      171357  1    83876   A Aug 27 2025 01:31:38

              Name: +RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_1_seq_83876.696.1210210325

       

      171361  1    83877   A Aug 27 2025 01:32:05

              Name: +RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_1_seq_83877.3436.1210210359

       

      171365  1    83878   A Aug 27 2025 01:32:38

              Name: +RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_1_seq_83878.3123.1210212173

       

      171369  1    83879   A Aug 27 2025 02:02:53

              Name: +RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_1_seq_83879.704.1210215615

       

      171371  1    83880   A Aug 27 2025 03:00:14

              Name: +RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_1_seq_83880.3122.1210217229

       

      171375  1    83881   A Aug 27 2025 03:27:08

              Name: +RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_1_seq_83881.5134.1210217261

       

      171379  1    83882   A Aug 27 2025 03:27:41

              Name: +RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_1_seq_83882.1713.1210217411

       

      171347  2    54577   A Aug 26 2025 23:30:11

              Name: +RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_2_seq_54577.3893.1210210221

       

      171351  2    54578   A Aug 27 2025 01:30:20

              Name: +RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_2_seq_54578.4058.1210210277

       

      171353  2    54579   A Aug 27 2025 01:31:17

              Name: +RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_2_seq_54579.3334.1210210295

       

      171359  2    54580   A Aug 27 2025 01:31:35

              Name: +RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_2_seq_54580.5373.1210210329

       

      171363  2    54581   A Aug 27 2025 01:32:08

              Name: +RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_2_seq_54581.4740.1210210433

       

      171367  2    54582   A Aug 27 2025 01:33:53

              Name: +RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_2_seq_54582.5291.1210215603

       

      171374  2    54583   A Aug 27 2025 03:00:02

              Name: +RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_2_seq_54583.1431.1210217263

       

      171377  2    54584   A Aug 27 2025 03:27:42

              Name: +RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_2_seq_54584.4263.1210217409

       

      deleted archived log

      archived log file name=+RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_1_seq_83877.3436.1210210359 RECID=171361 STAMP=1210210359

      deleted archived log

      archived log file name=+RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_1_seq_83876.696.1210210325 RECID=171357 STAMP=1210210326

      deleted archived log

      archived log file name=+RECOC4/MYDB/ARCHIVELOG/2025_08_27/thread_1_seq_83875.671.1210210299 RECID=171355 STAMP=1210210299

      Here are the RMAN configs DBA provided (if that is important in this regard)

      show all;

      using target database control file instead of recovery catalog

      RMAN configuration parameters for database with db_unique_name MYDB are:

      CONFIGURE RETENTION POLICY TO RECOVERY WINDOW OF 21 DAYS;

      CONFIGURE BACKUP OPTIMIZATION OFF; # default

      CONFIGURE DEFAULT DEVICE TYPE TO DISK;

      CONFIGURE CONTROLFILE AUTOBACKUP ON;

      CONFIGURE CONTROLFILE AUTOBACKUP FORMAT FOR DEVICE TYPE DISK TO '/zfssa/ed51/backup1/MYDB/CF_%d_%F';

      CONFIGURE DEVICE TYPE DISK PARALLELISM 1 BACKUP TYPE TO BACKUPSET; # default

      CONFIGURE DATAFILE BACKUP COPIES FOR DEVICE TYPE DISK TO 1; # default

      CONFIGURE ARCHIVELOG BACKUP COPIES FOR DEVICE TYPE DISK TO 1; # default

      CONFIGURE MAXSETSIZE TO UNLIMITED; # default

      CONFIGURE ENCRYPTION FOR DATABASE OFF; # default

      CONFIGURE ENCRYPTION ALGORITHM 'AES128'; # default

      CONFIGURE COMPRESSION ALGORITHM 'BASIC' AS OF RELEASE 'DEFAULT' OPTIMIZE FOR LOAD TRUE ; # default

      CONFIGURE RMAN OUTPUT TO KEEP FOR 7 DAYS; # default

      CONFIGURE ARCHIVELOG DELETION POLICY TO NONE;

      CONFIGURE SNAPSHOT CONTROLFILE NAME TO '/zfssa/ed51/backup1/MYDB/snapcf_MYDB.f';

      What Debezium connector do you use and what version?

      implementation 'io.debezium:debezium-api:3.1.1.Final'

      implementation'io.debezium:debezium-embedded:3.1.1.Final'

      implementation 'org.apache.kafka:connect-runtime:3.8.0'

      implementation 'io.debezium:debezium-connector-oracle:3.1.1.Final' 

      implementation "com.oracle.database.jdbc:ojdbc11:23.5.0.24.07"

      implementation 'io.debezium:debezium-storage-kafka:3.1.1.Final'

      What is the connector configuration?

      decimalHandlingMode: string

      name: <<NAME>>

      class: io.debezium.connector.oracle.OracleConnector

      offsetTopic: <<OFFSETTOPICNAME>>

      offsetTopicNumberOfPartitions: 1

      offsetTopicReplicationFactor: 1

      heartbeatIntervalInMsecs: 100000

      heartbeatQuery: SELECT * FROM MYTABLE WHERE ROWNUM <= 1

      database.query.timeout.ms: 600000

      .with("name", connectorName)

      .with("connector.class", connectorClass)

      .with("offset.storage", "org.apache.kafka.connect.storage.KafkaOffsetBackingStore") .with("offset.storage.topic", debeziumConnectorOffsetTopic) .with(DistributedConfig.OFFSET_STORAGE_PARTITIONS_CONFIG, debeziumConnectorOffsetTopicPartitions) .with(DistributedConfig.OFFSET_STORAGE_REPLICATION_FACTOR_CONFIG, debeziumConnectorOffsetTopicReplicationFactor)

      .with("offset.flush.interval.ms", "60000")

      .with("database.hostname", wmsDbHost)

      .with("database.port", port)

      .with("database.user", username)

      .with("database.password", password)

      .with("database.dbname", dbName)

      .with("schema.include.list", schemaList)

      .with("table.include.list", tableList)

      .with("include.schema.changes", "false")

      .with("topic.prefix", topicPrefix)

      .with("database.server.name", dbserverName) .with("snapshot.mode", snapshotMode) // It is set as initial

      .with("converter.schemas.enable", "false")

      .with("decimal.handling.mode", decimalHandlingMode)

      .with("heartbeat.interval.ms", heartbeatInterval)

      .with("heartbeat.action.query", heartbeatActionQuery)

      .with("database.query.timeout", 600000) 

      .with("schema.history.internal.kafka.topic", schemaTopic) .with("schema.history.internal.kafka.bootstrap.servers", schemaBootstrapServers) .with("schema.history.internal.consumer.security.protocol", schemaSecurityProtocol) .with("schema.history.internal.consumer.ssl.keystore.type", schemaSslKeyStoreType) .with("schema.history.internal.consumer.ssl.keystore.location", schemaSslKeystoreLocation) .with("schema.history.internal.consumer.ssl.keystore.password", schemaSslKeystorePassword) .with("schema.history.internal.consumer.ssl.truststore.type", schemaSslTrustStoreType) .with("schema.history.internal.consumer.ssl.truststore.location", schemaSslTruststoreLocation) .with("schema.history.internal.consumer.ssl.truststore.password", schemaSslTruststorePassword) .with("schema.history.internal.consumer.ssl.endpoint.identification.algorithm", sslEndpointAlgorithm) .with("schema.history.internal.producer.security.protocol", schemaSecurityProtocol) .with("schema.history.internal.producer.ssl.keystore.type", schemaSslKeyStoreType) .with("schema.history.internal.producer.ssl.keystore.location", schemaSslKeystoreLocation) .with("schema.history.internal.producer.ssl.keystore.password", schemaSslKeystorePassword) .with("schema.history.internal.producer.ssl.truststore.type", schemaSslTrustStoreType) .with("schema.history.internal.producer.ssl.truststore.location", schemaSslTruststoreLocation) .with("schema.history.internal.producer.ssl.truststore.password", schemaSslTruststorePassword) .with("schema.history.internal.producer.ssl.endpoint.identification.algorithm", sslEndpointAlgorithm) .with("bootstrap.servers", schemaBootstrapServers) .with("security.protocol", schemaSecurityProtocol)

      .with("ssl.keystore.location", schemaSslKeystoreLocation)

      .with("ssl.keystore.password", schemaSslKeystorePassword)

      .with("ssl.truststore.location", schemaSslTruststoreLocation)

      .with("ssl.truststore.password", schemaSslTruststorePassword) .with("ssl.endpoint.identification.algorithm", sslEndpointAlgorithm)

      /** In case of Patching scenarios where one node is down and the other runs, need to give enough
      time for redo threads of the downed node to be archived and sync up the data with the surviving node. This is done based on suggestion from ccranfor@redhat.com 
      */
      .with(OracleConnectorConfig.LOG_MINING_LOG_QUERY_MAX_RETRIES.name(), logMiningLogQueryMaxRetries)
      .with(OracleConnectorConfig.LOG_MINING_LOG_BACKOFF_INITIAL_DELAY_MS.name(), logMiningBackOffInitialDelayInMs)
      .with(OracleConnectorConfig.LOG_MINING_LOG_BACKOFF_MAX_DELAY_MS.name(), logMiningBackOffMaxDelayInMs)

      .with(OracleConnectorConfig.ARCHIVE_DESTINATION_NAME, archiveDestinationName)
      .with(OracleConnectorConfig.LOG_MINING_QUERY_FILTER_MODE, OracleConnectorConfig.LogMiningQueryFilterMode.IN.name())
      .with(OracleConnectorConfig.LOG_MINING_STRATEGY, OracleConnectorConfig.LogMiningStrategy.ONLINE_CATALOG.name())
      .with(OracleConnectorConfig.LOG_MINING_BATCH_SIZE_DEFAULT, logMiningBatchSizeDefault)

      What is the captured database version and mode of deployment?

      (E.g. on-premises, with a specific cloud provider, etc.)

      Data base in running on a data center and is an Oracle database of version 19c.

      DB Server on Dev Database runs on a 2 node RAC. The Archived log files (which Log Miner reads from) are shared to both nodes in RAC as a shared path.

      What behavior do you expect?

      We expect that Sequence number should be found as it is not physically deleted from the database server archive logs.

      What behavior do you see?

      It somehow can't find the sequence number as described above.

      Do you see the same behaviour using the latest released Debezium version?

      Didn't try it with any version other than 3.1.1. This is happening only for the 2nd time in 2-3 months after moving to 3.1.1.Final version

      Do you have the connector logs, ideally from start till finish?

      Only INFO logs

      How to reproduce the issue using our tutorial deployment?

      N/A

      Feature request or enhancement

      For feature requests or enhancements, provide this information, please:

      Which use case/requirement will be addressed by the proposed feature?

      It will make sure that continuous flow of data is not disrupted.

      Implementation ideas (optional)

      First may need to identify why it happened. Hopefully DB logs will be helpful in this regard.

        1. image-2025-09-04-10-56-38-048.png
          1.07 MB
          Kenny Kuriakose
        2. image-2025-09-04-11-12-14-392.png
          1.17 MB
          Kenny Kuriakose
        3. image-2025-09-04-22-39-30-309.png
          441 kB
          Kenny Kuriakose
        4. image-2025-09-04-22-50-10-973.png
          1.65 MB
          Kenny Kuriakose
        5. image-2025-09-11-13-26-44-837.png
          432 kB
          Kenny Kuriakose
        6. image-2025-09-11-14-17-59-956.png
          1.18 MB
          Kenny Kuriakose

              Unassigned Unassigned
              kennyk2024 Kenny Kuriakose
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

                Created:
                Updated: