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

No recovery after repeated retry attempts for ORA-01343 error: LogMiner encountered corruption in the logstream\n","error.stack_trace":"java.sql.SQLException: ORA-01343: LogMiner encountered corruption in the logstream

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Not a Bug
    • Icon: Major Major
    • None
    • None
    • oracle-connector
    • None
    • False
    • Hide

      None

      Show
      None
    • False

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

      Bug report

      We got ORA-01343 and never recovered after that

      1) We got ORA-01343: LogMiner encountered corruption in the logstream\n","error.stack_trace":"java.sql.SQLException: ORA-01343: LogMiner encountered corruption in the logstream\n\n\tat oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:630)\n\tat 

      2) This stopped the application

      3) Even after multiple retry attempts on its own, it keeps failing giving the same error again and again 

      4) Only way we recovered the application was to stop the Server, then clean up the offset topic, schema/history topics and then start the server again, so that it started with a full snapshot from start.

       

      This happened at 

      {"@timestamp":"2025-04-03T07:57:57.557Z","ecs.version":"1.2.0","log.level":"ERROR","message":"Mining session stopped due to error.","process.thread.name":"debezium-oracleconnector-db51-scan3-81-change-event-source-coordinator","log.logger":"io.debezium.connector.oracle.logminer.LogMinerStreamingChangeEventSource","dbz.connectorContext":"streaming","dbz.connectorName":"db51-scan3-81","dbz.connectorType":"Oracle","dbz.databaseName":"D81","dbz.taskId":"0","error.type":"java.sql.SQLException","error.message":"ORA-01343: LogMiner encountered corruption in the logstream\n","error.stack_trace":"java.sql.SQLException: ORA-01343: LogMiner encountered corruption in the logstream\n\n\tat oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:630)\n\tat oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:564)\n\tat oracle.jdbc.driver.T4C8Oall.processError(T4C8Oall.java:1151)\n\tat oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:771)\n\tat oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:299)\n\tat oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:498)\n\tat 
      
      oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:152)\n\tat oracle.jdbc.driver.T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:937)\n\tat oracle.jdbc.driver.OracleStatement.prepareDefineBufferAndExecute(OracleStatement.java:1172)\n\tat oracle.jdbc.driver.OracleStatement.executeMaybeDescribe(OracleStatement.java:1101)\n\tat oracle.jdbc.driver.OracleStatement.executeSQLSelect(OracleStatement.java:1426)\n\tat oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1309)\n\tat oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3746)\n\tat oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:3855)\n\tat oracle.jdbc.driver.OraclePreparedStatementWrapper.executeQuery(OraclePreparedStatementWrapper.java:1098)\n\tat io.debezium.connector.oracle.logminer.processor.AbstractLogMinerEventProcessor.process(AbstractLogMinerEventProcessor.java:237)\n\tat io.debezium.connector.oracle.logminer.LogMinerStreamingChangeEventSource.execute(LogMinerStreamingChangeEventSource.java:243)\n\tat io.debezium.connector.oracle.logminer.LogMinerStreamingChangeEventSource.execute(LogMinerStreamingChangeEventSource.java:62)\n\tat io.debezium.pipeline.ChangeEventSourceCoordinator.streamEvents(ChangeEventSourceCoordinator.java:313)\n\tat io.debezium.pipeline.ChangeEventSourceCoordinator.executeChangeEventSources(ChangeEventSourceCoordinator.java:203)\n\tat io.debezium.pipeline.ChangeEventSourceCoordinator.lambda$start$0(ChangeEventSourceCoordinator.java:143)\n\tat java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)\n\tat java.base/java.util.concurrent.FutureTask.run(Unknown Source)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)\n\tat java.base/java.lang.Thread.run(Unknown Source)\nCaused by: Error : 1343, Position : 0, Sql = SELECT SCN, SQL_REDO, OPERATION_CODE, TIMESTAMP, XID, CSF, TABLE_NAME, SEG_OWNER, OPERATION, USERNAME, ROW_ID, ROLLBACK, RS_ID, STATUS, INFO, SSN, THREAD#, DATA_OBJ#, DATA_OBJV#, DATA_OBJD# FROM V$LOGMNR_CONTENTS WHERE SCN > :1  AND SCN <= :2  AND (((OPERATION_CODE IN (1,2,3,7,34,36,255)) AND (SEG_OWNER IS NULL OR SEG_OWNER NOT IN ('APPQOSSYS','AUDSYS','CTXSYS','DVSYS','DBSFWUSER','DBSNMP','GGSHAREDCAP','GSMADMIN_INTERNAL','LBACSYS','MDSYS','OJVMSYS','OLAPSYS','ORDDATA','ORDSYS','OUTLN','SYS','SYSTEM','VECSYS','WMSYS','XDB'))) OR (OPERATION_CODE = 5 AND INFO NOT LIKE 'INTERNAL DDL%')), OriginalSql = SELECT SCN, SQL_REDO, OPERATION_CODE, TIMESTAMP, XID, CSF, TABLE_NAME, SEG_OWNER, OPERATION, USERNAME, ROW_ID, ROLLBACK, RS_ID, STATUS, INFO, SSN, THREAD#, DATA_OBJ#, DATA_OBJV#, DATA_OBJD# FROM V$LOGMNR_CONTENTS WHERE SCN > ? AND SCN <= ? AND (((OPERATION_CODE IN (1,2,3,7,34,36,255)) AND (SEG_OWNER IS NULL OR SEG_OWNER NOT IN ('APPQOSSYS','AUDSYS','CTXSYS','DVSYS','DBSFWUSER','DBSNMP','GGSHAREDCAP','GSMADMIN_INTERNAL','LBACSYS','MDSYS','OJVMSYS','OLAPSYS','ORDDATA','ORDSYS','OUTLN','SYS','SYSTEM','VECSYS','WMSYS','XDB'))) OR (OPERATION_CODE = 5 AND INFO NOT LIKE 'INTERNAL DDL%')), Error Msg = ORA-01343: LogMiner encountered corruption in the logstream\n\n\tat oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:637)\n\t... 25 more\n"}
      
      {"@timestamp":"2025-04-03T07:57:57.575Z","ecs.version":"1.2.0","log.level":"INFO","message":"Streaming metrics dump: LogMinerStreamingChangeEventSourceMetrics\{connectorConfig=io.debezium.connector.oracle.OracleConnectorConfig@74d2808, startTime=2025-03-19T21:17:57.040806881Z, clock=SystemClock[Z], currentScn=18658017047, offsetScn=18657649372, commitScn=18657678371, oldestScn=-1, oldestScnTime=null, currentLogFileNames=[+DATAC3/DB51P0302_TTC/ONLINELOG/group_1.313.1102332859, +RECOC3/DB51P0302_TTC/ONLINELOG/group_1.262.1102332861, +DATAC3/DB51P0302_TTC/ONLINELOG/group_3.315.1102332861, +RECOC3/DB51P0302_TTC/ONLINELOG/group_3.263.1102332863], redoLogStatuses=[+DATAC3/DB51P0302_TTC/ONLINELOG/group_4.316.1102332863 | ACTIVE, +DATAC3/DB51P0302_TTC/ONLINELOG/group_2.314.1102332861 | ACTIVE, +RECOC3/DB51P0302_TTC/ONLINELOG/group_2.258.1102332861 | ACTIVE, +RECOC3/DB51P0302_TTC/ONLINELOG/group_4.282.1102332863 | ACTIVE, +RECOC3/DB51P0302_TTC/ONLINELOG/group_3.263.1102332863 | CURRENT, +DATAC3/DB51P0302_TTC/ONLINELOG/group_3.315.1102332861 | CURRENT, +DATAC3/DB51P0302_TTC/ONLINELOG/group_1.313.1102332859 | CURRENT, +RECOC3/DB51P0302_TTC/ONLINELOG/group_1.262.1102332861 | CURRENT], databaseZoneOffset=-05:00, batchSize=31000, logSwitchCount=56, logMinerQueryCount=309154, sleepTime=600, minimumLogsMined=4, maximumLogsMined=4, maxBatchProcessingThroughput=10758, timeDifference=2, processedRowsCount=354722383, activeTransactionCount=0, rolledBackTransactionCount=168809, oversizedTransactionCount=0, changesCount=65555921, scnFreezeCount=0, batchProcessingDuration={min=PT0.13385633S,max=PT2M54.147170588S,total=PT97H44M33.447567676S}, fetchQueryDuration=\{min=PT0.103069613S,max=PT15.284849404S,total=PT84H33M27.407131501S}, commitDuration=\{min=PT0.000001476S,max=PT56.568803291S,total=PT2H56M52.311411218S}, lagFromSourceDuration=\{min=PT0.180891901S,max=PT23M26.918024454S,total=PT1289998H17M56.926823424S}, miningSessionStartupDuration=\{min=PT0.006469534S,max=PT41.732280717S,total=PT3H15M34.525768636S}, parseTimeDuration=\{min=PT0.000020198S,max=PT0.081612355S,total=PT41M2.255830504S}, resultSetNextDuration=\{min=PT0.000000093S,max=PT12.279902059S,total=PT1H28M58.386074729S}, userGlobalAreaMemory=\{value=57266504,max=79809880}, processGlobalAreaMemory=\{value=203069960,max=539204104}, abandonedTransactionIds=[], rolledBackTransactionIds=[3d001300ca6f1500, 5400000092f00c00, 58000f00a78f0500, 41000d00338b3100, 41001600818c3100, 2800020017350d00, 41001f00988f3100, 5e001d0080750200, 5a0020000eb10a00, 2f001c00a3801a00]} ","process.thread.name":"debezium-oracleconnector-ed51-scan3-81-change-event-source-coordinator","log.logger":"io.debezium.connector.oracle.logminer.LogMinerStreamingChangeEventSource","dbz.connectorContext":"streaming","dbz.connectorName":"ed51-scan3-81","dbz.connectorType":"Oracle","dbz.databaseName":"D81","dbz.taskId":"0"}
      
      {"@timestamp":"2025-04-03T07:57:57.575Z","ecs.version":"1.2.0","log.level":"INFO","message":"Offsets: OracleOffsetContext [scn=18657678371, commit_scn=[\"18657678371:1:05000900ff410900\",\"18657678281:2:50001a006d260600\"], lcr_position=null]","process.thread.name":"debezium-oracleconnector-ed51-scan3-81-change-event-source-coordinator","log.logger":"io.debezium.connector.oracle.logminer.LogMinerStreamingChangeEventSource","dbz.connectorContext":"streaming","dbz.connectorName":"ed51-scan3-81","dbz.connectorType":"Oracle","dbz.databaseName":"D81","dbz.taskId":"0"}
      
      {"@timestamp":"2025-04-03T07:57:57.575Z","ecs.version":"1.2.0","log.level":"INFO","message":"Finished streaming","process.thread.name":"debezium-oracleconnector-ed51-scan3-81-change-event-source-coordinator","log.logger":"io.debezium.pipeline.ChangeEventSourceCoordinator","dbz.connectorContext":"streaming","dbz.connectorName":"ed51-scan3-81","dbz.connectorType":"Oracle","dbz.databaseName":"D81","dbz.taskId":"0"}
      
      {"@timestamp":"2025-04-03T07:57:57.575Z","ecs.version":"1.2.0","log.level":"INFO","message":"Connected metrics set to 'false'","process.thread.name":"debezium-oracleconnector-ed51-scan3-81-change-event-source-coordinator","log.logger":"io.debezium.pipeline.ChangeEventSourceCoordinator","dbz.connectorContext":"streaming","dbz.connectorName":"ed51-scan3-81","dbz.connectorType":"Oracle","dbz.databaseName":"D81","dbz.taskId":"0"}
      
      {"@timestamp":"2025-04-03T07:57:57.631Z","ecs.version":"1.2.0","log.level":"WARN","message":"Going to restart connector after 10 sec. after a retriable exception","process.thread.name":"pool-6-thread-1","log.logger":"io.debezium.connector.common.BaseSourceTask"}
      
      {"@timestamp":"2025-04-03T07:57:57.636Z","ecs.version":"1.2.0","log.level":"INFO","message":"SignalProcessor stopped","process.thread.name":"pool-6-thread-1","log.logger":"io.debezium.pipeline.signal.SignalProcessor"}
      
      {"@timestamp":"2025-04-03T07:57:57.640Z","ecs.version":"1.2.0","log.level":"INFO","message":"Connection gracefully closed","process.thread.name":"pool-8-thread-1","log.logger":"io.debezium.jdbc.JdbcConnection"}
      

       
       

      What Debezium connector do you use and what version?

      It is 2.7.3, but here are helpful additional library information we use in our Java Springboot application.

      implementation 'io.debezium:debezium-api:2.7.3.Final'
      implementation'io.debezium:debezium-embedded:2.7.3.Final'
      implementation 'org.apache.kafka:connect-runtime:3.6.1'
      implementation 'io.debezium:debezium-connector-oracle:2.7.3.Final'
      implementation 'com.oracle.database.jdbc:ojdbc8:21.6.0.0'
      implementation 'io.debezium:debezium-storage-kafka:2.7.3.Final'
      

      What is the connector configuration?

      connector:

      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", wmsDbzConnectorName)
      .with("connector.class", wmsDbzConnectorClass)
      .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("database.history.kafka.topic", dbAndSchemaHistoryTopic)
      .with("database.history.consumer.group.id", dbAndSchemaHistoryTopicConsumerGroupId)
      .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)
      

      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?

      Was hoping that this error should either not happen or even if it happens, it should be able to recover. Any reason why it never recovered even after all the umlimited retry attempts we see. We had to clean up offset topics and schema/history topics and restart server to get this working, meaning full snapshot was required

      What behavior do you see?

      1) We got ORA-01343: LogMiner encountered corruption in the logstream\n","error.stack_trace":"java.sql.SQLException: ORA-01343: LogMiner encountered corruption in the logstream\n\n\tat oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:630)\n\tat 

      2) This stopped the application

      3) Even after multiple retry attempts on its own, it keeps failing giving the same error again and again 

      4) Only way we recovered the application was to stop the Server, then clean up the offset topic, schema/history topics and then start the server again, so that it started with a full snapshot from start.

       

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

      Didn't try anything beyond 2.7.3 yet

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

      I shared it above. But don't have TRACE

      How to reproduce the issue using our tutorial deployment?

      It is a kind of one time issue and hard to reproduce.

      Feature request or enhancement

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

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

      <Your answer>

      Implementation ideas (optional)

      Is there any setting to force a full snapshot if retry won't work even after 5 attempts ? Also would like to know the cause of this.

        1. alert_debezium_apr3.log
          32.10 MB
          Kenny Kuriakose
        2. alert_debezium_apr3-1.log
          32.10 MB
          Kenny Kuriakose

              ccranfor@redhat.com Chris Cranford
              kennyk2024 Kenny Kuriakose
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

                Created:
                Updated:
                Resolved: