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

Oracle connector restarts after ORA-01291

    XMLWordPrintable

Details

    Description

      What Debezium connector do you use and what version?

      1.9.1.Final

      What is the connector configuration?

      {
          "name": "src-ase1-22021",
          "config":
      {         "connector.class": "io.debezium.connector.oracle.OracleConnector",         "key.converter": "io.confluent.connect.avro.AvroConverter",         "key.converter.schema.registry.url": "XXX",         "value.converter": "io.confluent.connect.avro.AvroConverter",         "value.converter.schema.registry.url": "XXX",         "database.url": "jdbc:oracle:thin:@//XXX",         "database.user": "DSL_RO",         "database.password": "ENC[AES256_GCM,data:VNMcDAZCTFu+I668,iv:jLmCjqe3U0lLsgjJo9i94SsF4m4OXO8aXbCgJ86S1do=,tag:4hltjr9WgU0opb4lX3M8mg==,type:str]",         "database.dbname": "XXX",         "database.server.name": "ASE1",         "table.include.list": "ASEDBUSR.ABRDVRS,ASEDBUSR.ABRDVRSUNT,ASEDBUSR.ACTIVITY,ASEDBUSR.ADRESSE,ASEDBUSR.ADRESSEROLE,ASEDBUSR.ANTRFRAGENANTW,ASEDBUSR.ARBUN,ASEDBUSR.BANK,ASEDBUSR.BEZIEHUNG,ASEDBUSR.BILANZAUSGLEICH,ASEDBUSR.BUCHSTOFFV,ASEDBUSR.BUCHUNGSTOFF",         "snapshot.fetch.size": "10000",         "event.processing.failure.handling.mode": "fail",         "tombstones.on.delete": true,         "message.key.columns": "ASEDBUSR.ABRDVRS:PKEY;ASEDBUSR.ABRDVRSUNT:PKEY;ASEDBUSR.ACTIVITY:PKEY;ASEDBUSR.ADRESSE:PKEY;ASEDBUSR.ADRESSEROLE:PKEY;ASEDBUSR.ANTRFRAGENANTW:PKEY;ASEDBUSR.ARBUN:PKEY;ASEDBUSR.BANK:PKEY;ASEDBUSR.BEZIEHUNG:PKEY;ASEDBUSR.BILANZAUSGLEICH:PKEY;ASEDBUSR.BUCHSTOFFV:PKEY;ASEDBUSR.BUCHUNGSTOFF:PKEY",         "log.mining.strategy": "online_catalog",         "log.mining.archive.destination.name": "LOG_ARCHIVE_DEST_10",         "lob.enabled": true,         "time.precision.mode": "connect",         "tasks.max": "1",         "database.history.kafka.bootstrap.servers": "swwkafp01.suvanet.ch:9092",         "database.history.kafka.topic": "ase.schema-changes.asedbusr",         "database.history.consumer.security.protocol": "SASL_SSL",         "database.history.producer.security.protocol": "SASL_SSL",         "database.history.consumer.sasl.mechanism": "SCRAM-SHA-512",         "database.history.producer.sasl.mechanism": "SCRAM-SHA-512",         "database.history.consumer.sasl.jaas.config": "ENC[AES256_GCM,data:uK6nL+MtkuBv4JbkmGzOiqWqXWEdRzPTpz62KHcxqnAXrbVJAawiq5nyRb3U3Fj2jjgvzEjZT6scl2UkX8vCq+50R89Q3wsMDJge2/KbxodirWtukdROMOX3sn0S3Je9ZM+cMrEFqSelxEMBPrzel8UIeA==,iv:ITszOL5loaM3YtGtkxbG6/G+r0uh+uA//RRgy58fIrI=,tag:uoGE7++VUHRqG78WqBn1xg==,type:str]",         "database.history.producer.sasl.jaas.config": "ENC[AES256_GCM,data:Y8bglxC93enSj6NV0hCeDKzuW5rlCbjx2j6XAQFXefT4RUvhGxlUNMrMTdAipxgN7vj/fdxCHgDnX1sV1160qbTY3iYZGvV5KfRPH6hWgOuvElv2NEp8SDLm/bAFW6p+LPFsfX39MSzw4oRrk1ZBer2Gfw==,iv:15kpvdmln0VfxZ2QlF+A1IUBTzudnVTWA40fHhwHASg=,tag:tp43tzl2MDhw/aldbJNzDw==,type:str]",         "transforms": "unwrap",         "transforms.unwrap.type": "io.debezium.transforms.ExtractNewRecordState",         "transforms.unwrap.add.fields": "source.table:META_SRC_TABLENAME,source.ts_ms:META_SRC_TS,op:META_SRC_OP,source.scn:META_SRC_SCN,source.snapshot:META_SRC_SNAPSHOT",         "transforms.unwrap.delete.handling.mode": "rewrite",         "transforms.unwrap.drop.tombstones": false     }
      ,
          "sops": {
              "kms": null,
              "gcp_kms": null,
              "azure_kv": null,
              "hc_vault": null,
              "age": null,
              "lastmodified": "2022-01-31T15:45:42Z",
              "mac": "ENC[AES256_GCM,data:TdQ0XOrhkGlFVFIGWVYdA2vCn3UV5x39/1vZj5F3zQHgo+w3Am2OMPQ3V9nCYUqS144q0rnO21yYz+Tnp4pUGYFYFPjulrIw3NFQN+mEMM5JBYZIQIptI4OGXN2MiTBkXTyRZbRXzoc9GdHRS1lkRvpPNMR5e0zFu3AMVf5Zxsw=,iv:5clScQVFVRcXPk059q760vGIG9BQujJMt0wfWfD+t+M=,tag:FLoPP2zGqQREJFzFlQT+mg==,type:str]",
              "pgp": [
                 
      {                 "created_at": "2022-01-31T15:45:11Z",                 "enc": "-----BEGIN PGP MESSAGE-----\n\nhQEMA243CXYlIAr3AQf/WnSBFB9VC7uuE7M7iXSY0YsVmKMWWDXU8tvIjfsYzmEr\n66QWqUmTn5ux1RLkd/NrmAn8mx6Kc3PfCtmL1HyCAV+94P2uc4y63IxAggeWDBtA\nNZdr5BRCqlmZMIkVcO2EcV6/PZTxEBPOWzpeqQa63k1ihUwYhVhIslCo66haRL1A\nDKo/QaucLeqGpCFVgzTgCl5rCKSjScD8h0RV+I1uYR2afZxNy38rgFHd1/zhGa2W\nEngmVi481C1bW98MzndfOKg9P3dLHH1OwEEF0txZyKcp5ISWip44Nzr8WTfojp1n\nzNGGbGmbMARk48gicFr8oEy50ym49brw4J5l/SnHBtJeAWx4KUEj7wD/Vls+KFty\nXdd7ojEIDMIMyFKbNUPzGmZ0iXvEeAGFuFe9M8P+ExcDD7TcbGVpSwpFyyWeIuAe\ny4DGsmPgQBxrfA4kabyrRTYdAj4HejXsU47Gb4Ml9Q==\n=X1EW\n-----END PGP MESSAGE-----\n",                 "fp": "F7067DB106402AABEBEF13F8C6E64E19DC477D85"             }
              ],
              "encrypted_regex": "(database.password|database.history.consumer.sasl.jaas.config|database.history.producer.sasl.jaas.config)",
              "version": "3.7.1"
          }
      }
      

      What is the captured database version and mode of depoyment?

      Oracle 19c (non CDB)

      What behaviour do you see?

      At the time of the following warning /error there were several log switches going on (about 10). There were 3 errors and 1 warning for this connector at the time of the log switches.

      We can see entries like this in the logs:

       

      [2022-05-18 17:06:44,881] WARN [src-ase6-22024s1|task-0] WorkerSourceTask
      {id=src-ase6-22024s1-0}
      failed to poll records from SourceTask. Will retry operation. (org.apache.kafka.connect.runtime.WorkerSourceTask:306) org.apache.kafka.connect.errors.RetriableException: An exception occurred in the change event producer. This connector will be restarted. at io.debezium.pipeline.ErrorHandler.setProducerThrowable(ErrorHandler.java:46) at io.debezium.connector.oracle.logminer.LogMinerStreamingChangeEventSource.execute(LogMinerStreamingChangeEventSource.java:199) at io.debezium.connector.oracle.logminer.LogMinerStreamingChangeEventSource.execute(LogMinerStreamingChangeEventSource.java:59) at io.debezium.pipeline.ChangeEventSourceCoordinator.streamEvents(ChangeEventSourceCoordinator.java:174) at io.debezium.pipeline.ChangeEventSourceCoordinator.executeChangeEventSources(ChangeEventSourceCoordinator.java:141) at io.debezium.pipeline.ChangeEventSourceCoordinator.lambda$start$0(ChangeEventSourceCoordinator.java:109) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829) Caused by: java.sql.SQLException: ORA-01291: missing log file ORA-06512: at "SYS.DBMS_LOGMNR", line 72 ORA-06512: at line 1 at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:494) at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:446) at oracle.jdbc.driver.T4C8Oall.processError(T4C8Oall.java:1054) at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:623) at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:252) at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:612) at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:213) at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:37) at oracle.jdbc.driver.T4CStatement.executeForRows(T4CStatement.java:896) at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1119) at oracle.jdbc.driver.OracleStatement.executeInternal(OracleStatement.java:1737) at oracle.jdbc.driver.OracleStatement.execute(OracleStatement.java:1692) at oracle.jdbc.driver.OracleStatementWrapper.execute(OracleStatementWrapper.java:300) at io.debezium.jdbc.JdbcConnection.executeWithoutCommitting(JdbcConnection.java:1405) at io.debezium.connector.oracle.logminer.LogMinerStreamingChangeEventSource.startMiningSession(LogMinerStreamingChangeEventSource.java:532) at io.debezium.connector.oracle.logminer.LogMinerStreamingChangeEventSource.execute(LogMinerStreamingChangeEventSource.java:185) ... 9 more Caused by: Error : 1291, Position : 0, Sql = BEGIN sys.dbms_logmnr.start_logmnr(startScn => '289877889220', endScn => '289877892415', OPTIONS => DBMS_LOGMNR.DICT_FROM_ONLINE_CATALOG + DBMS_LOGMNR.NO_ROWID_IN_STMT);END;, OriginalSql = BEGIN sys.dbms_logmnr.start_logmnr(startScn => '289877889220', endScn => '289877892415', OPTIONS => DBMS_LOGMNR.DICT_FROM_ONLINE_CATALOG + DBMS_LOGMNR.NO_ROWID_IN_STMT);END;, Error Msg = ORA-01291: missing log file ORA-06512: at "SYS.DBMS_LOGMNR", line 72 ORA-06512: at line 1 at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:498) ... 24 more
      
      [2022-05-18 17:06:44,533] ERROR [src-ase6-22024s1|task-0] Producer failure (io.debezium.pipeline.ErrorHandler:35) java.sql.SQLException: ORA-01291: missing log file ORA-06512: at "SYS.DBMS_LOGMNR", line 72 ORA-06512: at line 1 at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:494) at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:446) at oracle.jdbc.driver.T4C8Oall.processError(T4C8Oall.java:1054) at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:623) at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:252) at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:612) at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:213) at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:37) at oracle.jdbc.driver.T4CStatement.executeForRows(T4CStatement.java:896) at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1119) at oracle.jdbc.driver.OracleStatement.executeInternal(OracleStatement.java:1737) at oracle.jdbc.driver.OracleStatement.execute(OracleStatement.java:1692) at oracle.jdbc.driver.OracleStatementWrapper.execute(OracleStatementWrapper.java:300) at io.debezium.jdbc.JdbcConnection.executeWithoutCommitting(JdbcConnection.java:1405) at io.debezium.connector.oracle.logminer.LogMinerStreamingChangeEventSource.startMiningSession(LogMinerStreamingChangeEventSource.java:532) at io.debezium.connector.oracle.logminer.LogMinerStreamingChangeEventSource.execute(LogMinerStreamingChangeEventSource.java:185) at io.debezium.connector.oracle.logminer.LogMinerStreamingChangeEventSource.execute(LogMinerStreamingChangeEventSource.java:59) at io.debezium.pipeline.ChangeEventSourceCoordinator.streamEvents(ChangeEventSourceCoordinator.java:174) at io.debezium.pipeline.ChangeEventSourceCoordinator.executeChangeEventSources(ChangeEventSourceCoordinator.java:141) at io.debezium.pipeline.ChangeEventSourceCoordinator.lambda$start$0(ChangeEventSourceCoordinator.java:109) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829) Caused by: Error : 1291, Position : 0, Sql = BEGIN sys.dbms_logmnr.start_logmnr(startScn => '289877889220', endScn => '289877892415', OPTIONS => DBMS_LOGMNR.DICT_FROM_ONLINE_CATALOG + DBMS_LOGMNR.NO_ROWID_IN_STMT);END;, OriginalSql = BEGIN sys.dbms_logmnr.start_logmnr(startScn => '289877889220', endScn => '289877892415', OPTIONS => DBMS_LOGMNR.DICT_FROM_ONLINE_CATALOG + DBMS_LOGMNR.NO_ROWID_IN_STMT);END;, Error Msg = ORA-01291: missing log file ORA-06512: at "SYS.DBMS_LOGMNR", line 72 ORA-06512: at line 1 at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:498) ... 24 more
      [2022-05-18 17:06:44,533] ERROR [src-ase6-22024s1|task-0] Mining session stopped due to the {} (io.debezium.connector.oracle.logminer.LogMinerHelper:117) java.sql.SQLException: ORA-01291: missing log file ORA-06512: at "SYS.DBMS_LOGMNR", line 72 ORA-06512: at line 1 at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:494) at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:446) at oracle.jdbc.driver.T4C8Oall.processError(T4C8Oall.java:1054) at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:623) at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:252) at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:612) at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:213) at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:37) at oracle.jdbc.driver.T4CStatement.executeForRows(T4CStatement.java:896) at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1119) at oracle.jdbc.driver.OracleStatement.executeInternal(OracleStatement.java:1737) at oracle.jdbc.driver.OracleStatement.execute(OracleStatement.java:1692) at oracle.jdbc.driver.OracleStatementWrapper.execute(OracleStatementWrapper.java:300) at io.debezium.jdbc.JdbcConnection.executeWithoutCommitting(JdbcConnection.java:1405) at io.debezium.connector.oracle.logminer.LogMinerStreamingChangeEventSource.startMiningSession(LogMinerStreamingChangeEventSource.java:532) at io.debezium.connector.oracle.logminer.LogMinerStreamingChangeEventSource.execute(LogMinerStreamingChangeEventSource.java:185) at io.debezium.connector.oracle.logminer.LogMinerStreamingChangeEventSource.execute(LogMinerStreamingChangeEventSource.java:59) at io.debezium.pipeline.ChangeEventSourceCoordinator.streamEvents(ChangeEventSourceCoordinator.java:174) at io.debezium.pipeline.ChangeEventSourceCoordinator.executeChangeEventSources(ChangeEventSourceCoordinator.java:141) at io.debezium.pipeline.ChangeEventSourceCoordinator.lambda$start$0(ChangeEventSourceCoordinator.java:109) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829) Caused by: Error : 1291, Position : 0, Sql = BEGIN sys.dbms_logmnr.start_logmnr(startScn => '289877889220', endScn => '289877892415', OPTIONS => DBMS_LOGMNR.DICT_FROM_ONLINE_CATALOG + DBMS_LOGMNR.NO_ROWID_IN_STMT);END;, OriginalSql = BEGIN sys.dbms_logmnr.start_logmnr(startScn => '289877889220', endScn => '289877892415', OPTIONS => DBMS_LOGMNR.DICT_FROM_ONLINE_CATALOG + DBMS_LOGMNR.NO_ROWID_IN_STMT);END;, Error Msg = ORA-01291: missing log file ORA-06512: at "SYS.DBMS_LOGMNR", line 72 ORA-06512: at line 1 at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:498) ... 24 more
      [2022-05-18 17:06:44,532] ERROR [src-ase6-22024s1|task-0] Got exception when starting mining session. (io.debezium.connector.oracle.logminer.LogMinerStreamingChangeEventSource:536) java.sql.SQLException: ORA-01291: missing log file ORA-06512: at "SYS.DBMS_LOGMNR", line 72 ORA-06512: at line 1 at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:494) at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:446) at oracle.jdbc.driver.T4C8Oall.processError(T4C8Oall.java:1054) at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:623) at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:252) at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:612) at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:213) at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:37) at oracle.jdbc.driver.T4CStatement.executeForRows(T4CStatement.java:896) at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1119) at oracle.jdbc.driver.OracleStatement.executeInternal(OracleStatement.java:1737) at oracle.jdbc.driver.OracleStatement.execute(OracleStatement.java:1692) at oracle.jdbc.driver.OracleStatementWrapper.execute(OracleStatementWrapper.java:300) at io.debezium.jdbc.JdbcConnection.executeWithoutCommitting(JdbcConnection.java:1405) at io.debezium.connector.oracle.logminer.LogMinerStreamingChangeEventSource.startMiningSession(LogMinerStreamingChangeEventSource.java:532) at io.debezium.connector.oracle.logminer.LogMinerStreamingChangeEventSource.execute(LogMinerStreamingChangeEventSource.java:185) at io.debezium.connector.oracle.logminer.LogMinerStreamingChangeEventSource.execute(LogMinerStreamingChangeEventSource.java:59) at io.debezium.pipeline.ChangeEventSourceCoordinator.streamEvents(ChangeEventSourceCoordinator.java:174) at io.debezium.pipeline.ChangeEventSourceCoordinator.executeChangeEventSources(ChangeEventSourceCoordinator.java:141) at io.debezium.pipeline.ChangeEventSourceCoordinator.lambda$start$0(ChangeEventSourceCoordinator.java:109) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829) Caused by: Error : 1291, Position : 0, Sql = BEGIN sys.dbms_logmnr.start_logmnr(startScn => '289877889220', endScn => '289877892415', OPTIONS => DBMS_LOGMNR.DICT_FROM_ONLINE_CATALOG + DBMS_LOGMNR.NO_ROWID_IN_STMT);END;, OriginalSql = BEGIN sys.dbms_logmnr.start_logmnr(startScn => '289877889220', endScn => '289877892415', OPTIONS => DBMS_LOGMNR.DICT_FROM_ONLINE_CATALOG + DBMS_LOGMNR.NO_ROWID_IN_STMT);END;, Error Msg = ORA-01291: missing log file ORA-06512: at "SYS.DBMS_LOGMNR", line 72 ORA-06512: at line 1 at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:498) ... 24 more

      Chris Cranford meant: The only way forward that I can see is to make ORA-01291 an exception that we capture & re-run the log mining step, likely with some type of flag that if the step fails after X attempts, we hard fail the connector to deal with situations where there is a critical problem where this error is raised.

      Attachments

        Activity

          People

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

            Dates

              Created:
              Updated:
              Resolved: