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

ORA-01289 error encountered on Oracle RAC when multiple logs are mined with same sequence number

    XMLWordPrintable

Details

    • Bug
    • Resolution: Done
    • Major
    • 1.6.0.Beta2
    • 1.5.0.Beta1
    • oracle-connector
    • None

    Description

      After applied DBZ-3256, our connector has encountered this ORA-01289 (cannot add duplicate logfile) exception many times per hour. from our local build we have added ORA-01289 in the isRetriable list to avoid mining session stop. however it is causing big lag when restarting the connector.

      I noticed that the deDuplicate logic has been removed from the DBZ-3256. 
      so I added more detailed logs including SCN values  and here is what happened.

      scenario 1:  the duplicated online file redo12_1.log has the same SCN range with the archived log file thread_1_seq_29465.4537.1073541903

      - redo12_1.log with SCN range 17479872580113 to 17479872580858 (ACTIVE) 

      - thread_1_seq_29465.4537.1073541903 with SCN range 17479872580113 to 17479872580858 

      [2021-05-26 06:05:04,046] INFO Archive log +DG_FRA/IDBTSTX/ARCHIVELOG/2021_05_26/thread_1_seq_29462.2139.1073541889 with SCN range 17479872089805 to 17479872575086 to be added. (io.debezium.connector.oracle.logminer.LogMinerHelper:519)
[2021-05-26 06:05:04,047] INFO Archive log +DG_FRA/IDBTSTX/ARCHIVELOG/2021_05_26/thread_1_seq_29463.2123.1073541903 with SCN range 17479872575086 to 17479872580087 to be added. (io.debezium.connector.oracle.logminer.LogMinerHelper:519)
[2021-05-26 06:05:04,047] INFO Archive log +DG_FRA/IDBTSTX/ARCHIVELOG/2021_05_26/thread_1_seq_29464.490.1073541903 with SCN range 17479872580087 to 17479872580113 to be added. (io.debezium.connector.oracle.logminer.LogMinerHelper:519)
[2021-05-26 06:05:04,047] INFO Archive log +DG_FRA/IDBTSTX/ARCHIVELOG/2021_05_26/thread_1_seq_29465.4537.1073541903 with SCN range 17479872580113 to 17479872580858 to be added. (io.debezium.connector.oracle.logminer.LogMinerHelper:519)
[2021-05-26 06:05:04,047] INFO Online redo log +DG_REDO/idbtstx/redo12_1.log with SCN range 17479872580113 to 17479872580858 (ACTIVE) to be added. (io.debezium.connector.oracle.logminer.LogMinerHelper:526)
[2021-05-26 06:05:04,047] INFO Online redo log +DG_REDO/idbtstx/redo13_1.log with SCN range 17479872580858 to 9295429630892703743 (CURRENT) to be added. (io.debezium.connector.oracle.logminer.LogMinerHelper:526)
[2021-05-26 06:05:04,047] INFO Online redo log +DG_REDO/idbtstx/redo36_1.log with SCN range 17479872091396 to 17479872580687 (ACTIVE) to be added. (io.debezium.connector.oracle.logminer.LogMinerHelper:526)
[2021-05-26 06:05:04,047] INFO Online redo log +DG_REDO/idbtstx/redo15_1.log with SCN range 17479872580687 to 9295429630892703743 (CURRENT) to be added. (io.debezium.connector.oracle.logminer.LogMinerHelper:526)
[2021-05-26 06:05:04,047] INFO Adding log file +DG_FRA/IDBTSTX/ARCHIVELOG/2021_05_26/thread_1_seq_29462.2139.1073541889 to mining session (io.debezium.connector.oracle.logminer.LogMinerHelper:453)
[2021-05-26 06:05:04,055] INFO Adding log file +DG_FRA/IDBTSTX/ARCHIVELOG/2021_05_26/thread_1_seq_29463.2123.1073541903 to mining session (io.debezium.connector.oracle.logminer.LogMinerHelper:453)
[2021-05-26 06:05:04,061] INFO Adding log file +DG_FRA/IDBTSTX/ARCHIVELOG/2021_05_26/thread_1_seq_29464.490.1073541903 to mining session (io.debezium.connector.oracle.logminer.LogMinerHelper:453)
[2021-05-26 06:05:04,066] INFO Adding log file +DG_FRA/IDBTSTX/ARCHIVELOG/2021_05_26/thread_1_seq_29465.4537.1073541903 to mining session (io.debezium.connector.oracle.logminer.LogMinerHelper:453)
[2021-05-26 06:05:04,072] INFO Adding log file +DG_REDO/idbtstx/redo12_1.log to mining session (io.debezium.connector.oracle.logminer.LogMinerHelper:453)
[2021-05-26 06:05:04,081] ERROR Mining session stopped due to the {} (io.debezium.connector.oracle.logminer.LogMinerHelper:491)
java.sql.SQLException: ORA-01289: cannot add duplicate logfile +DG_REDO/idbtstx/redo12_1.log
ORA-06512: at "SYS.DBMS_LOGMNR", line 82
ORA-06512: at line 1

       

      scenario 2: the duplicated online file "redo18_1.log" has the overlapping scn range with archived log "thread_2_seq_30185.256.1073535067"

      - redo18_1.log with SCN range 17479867957964 to 9295429630892703743 (CURRENT)

      • thread_2_seq_30185.256.1073535067 with SCN range 17479867957964 to 17479867960887 
        [2021-05-26 04:11:06,421] INFO Archive log +DG_FRA/IDBTSTX/ARCHIVELOG/2021_05_26/thread_1_seq_29419.9446.1073535061 with SCN range 17479867625537 to 17479867956269 to be added. (io.debezium.connector.oracle.logminer.LogMinerHelper:519)
[2021-05-26 04:11:06,422] INFO Archive log +DG_FRA/IDBTSTX/ARCHIVELOG/2021_05_26/thread_1_seq_29420.9963.1073535061 with SCN range 17479867956269 to 17479867956317 to be added. (io.debezium.connector.oracle.logminer.LogMinerHelper:519)
[2021-05-26 04:11:06,422] INFO Archive log +DG_FRA/IDBTSTX/ARCHIVELOG/2021_05_26/thread_1_seq_29421.9402.1073535063 with SCN range 17479867956317 to 17479867958317 to be added. (io.debezium.connector.oracle.logminer.LogMinerHelper:519)
[2021-05-26 04:11:06,422] INFO Archive log +DG_FRA/IDBTSTX/ARCHIVELOG/2021_05_26/thread_1_seq_29422.860.1073535063 with SCN range 17479867958317 to 17479867958663 to be added. (io.debezium.connector.oracle.logminer.LogMinerHelper:519)
[2021-05-26 04:11:06,422] INFO Online redo log +DG_REDO/idbtstx/redo14_1.log with SCN range 17479867958663 to 9295429630892703743 (CURRENT) to be added. (io.debezium.connector.oracle.logminer.LogMinerHelper:526)
[2021-05-26 04:11:06,424] INFO Archive log +DG_FRA/IDBTSTX/ARCHIVELOG/2021_05_26/thread_2_seq_30183.1788.1073535055 with SCN range 17479867234932 to 17479867950049 to be added. (io.debezium.connector.oracle.logminer.LogMinerHelper:519)
[2021-05-26 04:11:06,424] INFO Archive log +DG_FRA/IDBTSTX/ARCHIVELOG/2021_05_26/thread_2_seq_30184.2151.1073535063 with SCN range 17479867950049 to 17479867957964 to be added. (io.debezium.connector.oracle.logminer.LogMinerHelper:519)
[2021-05-26 04:11:06,424] INFO Archive log +DG_FRA/IDBTSTX/ARCHIVELOG/2021_05_26/thread_2_seq_30185.256.1073535067 with SCN range 17479867957964 to 17479867960887 to be added. (io.debezium.connector.oracle.logminer.LogMinerHelper:519)
[2021-05-26 04:11:06,424] INFO Online redo log +DG_REDO/idbtstx/redo18_1.log with SCN range 17479867957964 to 9295429630892703743 (CURRENT) to be added. (io.debezium.connector.oracle.logminer.LogMinerHelper:526)
[2021-05-26 04:11:06,424] INFO Adding log file +DG_FRA/IDBTSTX/ARCHIVELOG/2021_05_26/thread_1_seq_29419.9446.1073535061 to mining session (io.debezium.connector.oracle.logminer.LogMinerHelper:453)
[2021-05-26 04:11:06,434] INFO Adding log file +DG_FRA/IDBTSTX/ARCHIVELOG/2021_05_26/thread_1_seq_29420.9963.1073535061 to mining session (io.debezium.connector.oracle.logminer.LogMinerHelper:453)
[2021-05-26 04:11:06,439] INFO Adding log file +DG_FRA/IDBTSTX/ARCHIVELOG/2021_05_26/thread_1_seq_29421.9402.1073535063 to mining session (io.debezium.connector.oracle.logminer.LogMinerHelper:453)
[2021-05-26 04:11:06,443] INFO Adding log file +DG_FRA/IDBTSTX/ARCHIVELOG/2021_05_26/thread_1_seq_29422.860.1073535063 to mining session (io.debezium.connector.oracle.logminer.LogMinerHelper:453)
[2021-05-26 04:11:06,449] INFO Adding log file +DG_REDO/idbtstx/redo14_1.log to mining session (io.debezium.connector.oracle.logminer.LogMinerHelper:453)
[2021-05-26 04:11:06,455] INFO Adding log file +DG_FRA/IDBTSTX/ARCHIVELOG/2021_05_26/thread_2_seq_30183.1788.1073535055 to mining session (io.debezium.connector.oracle.logminer.LogMinerHelper:453)
[2021-05-26 04:11:06,460] INFO Adding log file +DG_FRA/IDBTSTX/ARCHIVELOG/2021_05_26/thread_2_seq_30184.2151.1073535063 to mining session (io.debezium.connector.oracle.logminer.LogMinerHelper:453)
[2021-05-26 04:11:06,467] INFO Adding log file +DG_FRA/IDBTSTX/ARCHIVELOG/2021_05_26/thread_2_seq_30185.256.1073535067 to mining session (io.debezium.connector.oracle.logminer.LogMinerHelper:453)
[2021-05-26 04:11:06,478] INFO Adding log file +DG_REDO/idbtstx/redo18_1.log to mining session (io.debezium.connector.oracle.logminer.LogMinerHelper:453)
[2021-05-26 04:11:06,488] ERROR Mining session stopped due to the {} (io.debezium.connector.oracle.logminer.LogMinerHelper:491)
java.sql.SQLException: ORA-01289: cannot add duplicate logfile +DG_REDO/idbtstx/redo18_1.log

         

      From the Oracle doc, ORA-01289 exception is caused by the same log sequence number

      LogMiner matches redo log files by the log sequence number. Thus, two redo log files with different names but with the same log sequence number will return the ORA-01289 exception. For instance, the online counterpart of an archived redo log file has a different name from the archived redo log file, but attempting to register it with LogMiner after registering the archived counterpart will result in the ORA-01289 exception being returned.

      I wonder if you guys want to add the de-duplicate logic back including SCN overlapping  
      or using the sequence number.

       

      Attachments

        1. archived-csv
          4.47 MB
        2. new-sql
          2 kB
        3. old-sql
          2 kB
        4. vlog-csv
          2 kB

        Activity

          People

            ccranfor@redhat.com Chris Cranford
            shiawu John Wu (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: