How I Finished a Recovery From an Active Duplicate After Facing Errors ORA-19909 and ORA-01110

How I Finished a Recovery From an Active Duplicate After Facing Errors ORA-19909 and ORA-01110

The other day I was doing a database cloning in 11.2.0.4, from an active duplicate and got the following error ORA-19909: datafile 1 belongs to an orphan incarnation and ORA-01110: data file 1.

This is a blog post on how I solved these errors. It is worth mentioning that what I did here applies to  12c,18c and 19c databases as well.

I first verified that I had the password file from the target database, that I also had the corresponding TNS entries for it and as well I created a listener for this task only. The creation of the listener was a requirement from the client that I was working with, else I could have worked with the SCAN listener.

Next I verified that  I could connect to the target and auxiliary databases correctly and created the script below to use for this refresh.

##################################################################
## Connectivity Test
##################################################################
oracle $ ls $ORACLE_HOME/dbs/orapwSTG*
/u01/app/oracle/product/11.2.0.4/dbhome_3/dbs/orapwSTG1

oracle $ rman TARGET sys/********@PROD AUXILIARY sys/********@STG_STATIC
connected to target database: PROD (DBID=3874882083)
connected to auxiliary database: STG (not mounted)

##################################################################
## STG_STATIC TNS Entry
##################################################################

STG_STATIC =
  (DESCRIPTION =
    (ADDRESS_LIST =
      (ADDRESS = (PROTOCOL = TCP)(HOST = auxiliarydbadm01)(PORT = 1523))
    )
    (CONNECT_DATA =
      (SERVICE_NAME = STG1)
      (UR=A)
    )
  )

##################################################################
## PROD TNS Entry
##################################################################
PROD =
  (DESCRIPTION =
    (ADDRESS_LIST =
      (ADDRESS = (PROTOCOL = TCP)(HOST = prod_scan)(PORT = 1521))
    )
    (CONNECT_DATA =
      (SERVICE_NAME = PROD1)
    )
  )

##################################################################
## Listener used
##################################################################
LISTENER_REFRESH =
  (DESCRIPTION_LIST =
    (DESCRIPTION =
      (ADDRESS = (PROTOCOL = TCP)(HOST = auxiliarydbadm01)(PORT = 1523))
    )
  )

SID_LIST_LISTENER_REFRESH =
  (SID_LIST =
    (SID_DESC =
      (ORACLE_HOME = /u01/app/oracle/product/11.2.0.4/dbhome_3)
      (SID_NAME = QA1)
    )
    (SID_DESC =
      (ORACLE_HOME = /u01/app/oracle/product/11.2.0.4/dbhome_3)
      (SID_NAME = STG1)
    )
    (SID_DESC =
      (ORACLE_HOME = /u01/app/oracle/product/11.2.0.4/dbhome_3)
      (SID_NAME = RFSH1)
    )
  )

ADR_BASE_LISTENER = /u01/app/oracle

##################################################################
## recover_from_prod.sh
##################################################################

oracle $ cat recover_from_prod.sh
#!/bin/bash
export NLS_DATE_FORMAT='DD-MON-YYYY HH24:MI:SS'
export ORACLE_SID=STG1
export ORAENV_ASK=NO
. /usr/local/bin/oraenv
rman TARGET sys/********@PROD AUXILIARY sys/********@STG_STATIC <<endofrman
run {
allocate channel prmy1 type disk;
allocate channel prmy2 type disk;
allocate channel prmy3 type disk;
allocate channel prmy4 type disk;
allocate channel prmy5 type disk;
allocate channel prmy6 type disk;
allocate auxiliary channel aux1 type disk;
allocate auxiliary channel aux2 type disk;
allocate auxiliary channel aux3 type disk;
allocate auxiliary channel aux4 type disk;
allocate auxiliary channel aux5 type disk;
allocate auxiliary channel aux6 type disk;
DUPLICATE TARGET DATABASE TO 'STG' FROM ACTIVE DATABASE NOFILENAMECHECK;
}
endofrman

I knew that this duplicate was going to take a while as this was a 35 TB database. 

SQL> SELECT
  ( SELECT SUM(bytes)/power(1024,4) data_size FROM dba_data_files
  ) +
  ( SELECT NVL(SUM(bytes),0)/power(1024,4) temp_size FROM dba_temp_files
  ) +
  ( SELECT SUM(bytes)/power(1024,4) redo_size FROM sys.v_$log
  )                     +
  (SELECT SUM(BLOCK_SIZE*FILE_SIZE_BLKS)/power(1024,3) controlfile_size
  FROM v$controlfile
  ) "Database Size in TB"
FROM dual;

Database Size in TB
-------------------
         35.1021405

Even though it took a while, the restore for the duplicate database went ok, but when the recovery process started to happen, I got the following errors

oracle $ tail -100 recover_from_prod.log
...
Starting recover at 09-NOV-2020 08:27:59

starting media recovery
media recovery failed
Oracle instance started
...
RMAN-11003: failure during parse/execution of SQL statement: alter database recover if needed
 start until change 281698833114 using backup controlfile
ORA-00283: recovery session canceled due to errors
ORA-19909: datafile 1 belongs to an orphan incarnation
ORA-01110: data file 1: '+DATAC2/stg/datafile/system.636.1056008579'

These errors primarily happen because there are other files in the ASM diskgroup that have the same DBID as the auxiliary database that I was cloning.

As the way that RMAN works for an active duplicate is, if you are using ASM disk groups, is that it catalogs everything under the disk group that  db_recovery_file_dest parameter is set to if the log_archive_dest_1. parameter is not set.

This was true in my case as in the same cluster there is a standby running called proddr for the target database that I was cloning.

##################################################################
## db_recovery_file_dest and log_archive_dest_1 parameter values
##################################################################
oracle $ echo "
> show parameter log_archive_dest_1;
> " | sqlplus -s -L / as sysdba

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
log_archive_dest_1                   string
...

oracle $ echo "
> show parameter db_recovery_file_dest;
> " | sqlplus -s -L / as sysdba

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
db_recovery_file_dest                string      +RECOC2
db_recovery_file_dest_size           big integer 20000G


##################################################################
## From the recover_from_prod.log
##################################################################
...
 "+RECOC1/prod/archivelog/2020_11_09/thread_2_seq_535909.41715.1056009955" auxiliary format
 "+RECOC2"   ;
   catalog clone start with  "+RECOC2";
   switch clone datafile all;
}
...
List of Cataloged Files
=======================
File Name: +RECOC2/proddr/CONTROLFILE/current.7901.1022257521
File Name: +RECOC2/stg/archivelog/2020_11_09/thread_2_seq_535877.5618.1056010749
...
File Name: +RECOC2/proddr/archivelog/2020_11_07/thread_2_seq_535588.2240.1055891307
File Name: +RECOC2/proddr/archivelog/2020_11_07/thread_1_seq_567337.8034.1055892763
..
datafile 1 switched to datafile copy
input datafile copy RECID=67 STAMP=1056011218 file name=+DATAC2/stg/datafile/system.636.1056008579
...
datafile 133 switched to datafile copy
input datafile copy RECID=198 STAMP=1056011261 file name=+DATAC2/stg/datafile/aud_tbs.451.1056009851
datafile 134 switched to datafile copy
input datafile copy RECID=199 STAMP=1056011262 file name=+DATAC2/stg/datafile/revenue_ods2.622.1055987265

contents of Memory Script:
{
   set until scn  281698833114;
   recover
   clone database
    delete archivelog
   ;
}

So now that I have investigated the error, I proceeded to fix the error.

The first thing I did was try to open STG database in mount mode to see the contents of the control file, as from the log above I did see that the datafile copy had switched and updated the control file, and this will help me in doing a faster recovery of this process. 

SQL> startup mount;
ORACLE instance started.

Total System Global Area 2.5655E+10 bytes
Fixed Size		    2265224 bytes
Variable Size		 1.0402E+10 bytes
Database Buffers	 1.5099E+10 bytes
Redo Buffers		  151113728 bytes
*
ERROR at line 1:
ORA-01103: database name 'PROD' in control file is not 'STG'

From the error above, I see that the control file has the incorrect database name and what I have to do is to recreate the control file for this.

To avoid going to ASM or the recover log I have to gather all the datafiles and their location, I created instead a small parameter file that only includes the control file, the block size, the same compatible parameter and the name of the target database as database PROD  which is shown in the error ORA-01103 above.

Once I have the database PROD up, I just backup that database control file to trace.

oracle $ cat initprod.ora
DB_NAME=PROD
DB_UNIQUE_NAME=PROD
DB_BLOCK_SIZE=8192
*.control_files='/home/oracle/working/antunez/STG/control02.ctl'
*.compatible='11.2.0.4.0'

SQL> startup mount pfile='/home/oracle/working/antunez/initprod.ora';
ORACLE instance started.

Total System Global Area  513642496 bytes
Fixed Size                  2254624 bytes
Variable Size             402655456 bytes
Database Buffers          100663296 bytes
Redo Buffers                8069120 bytes
Database mounted.

SQL> alter database backup controlfile to trace as '/home/oracle/working/antunez/stg.sql';

Database altered.

SQL> shutdown abort
ORACLE instance shut down.

Now that I have the control file trace with the proper datafile location, I modify it to leave only the section of RESETLOGS and change the line of CREATE CONTROL FILE to use the SET command.

Once I have done that, I run the creation of the control file in STG database.

oracle $ cat /home/oracle/working/antunez/stg.sql
CREATE CONTROLFILE REUSE SET DATABASE "STG" RESETLOGS FORCE LOGGING ARCHIVELOG
    MAXLOGFILES 192
    MAXLOGMEMBERS 3
    MAXDATAFILES 1024
    MAXINSTANCES 32
    MAXLOGHISTORY 149504
LOGFILE
  GROUP 11 (
    '+DATAC2/stg/onlinelog/group_11.3162.914669717',
...
  '+DATAC2/stg/datafile/sysaux.454.1056009483',
  '+DATAC2/stg/datafile/users.448.1056009331',
  '+DATAC2/stg/datafile/users.455.1056009819'
CHARACTER SET AL32UTF8
;
oracle $ . oraenv <<< STG1
SQL> startup nomount;
ORACLE instance started.

Total System Global Area 2.5655E+10 bytes
Fixed Size		    2265224 bytes
Variable Size		 1.0402E+10 bytes
Database Buffers	 1.5099E+10 bytes
Redo Buffers		  151113728 bytes

SQL> @/home/oracle/working/antunez/stg.sql

Control file created.

SQL> select open_mode from v$database;
OPEN_MODE
--------------------
MOUNTED

What I needed now are the archived redo logs that were going to be used for the recovery, as some of the archivelogs were not copied.

RMAN thought that they were already in place for the recovery due to them being in the auxiliary host for the proddr standby database. So I did the below to find the range of archived redo logs that I was going to need.

If you remember the script that I used I set the NLS environment variable to this export NLS_DATE_FORMAT='DD-MON-YYYY HH24:MI:SS', this was so that in the log I would have the details of the times down to seconds from the RMAN output, and it came useful for this.

I extracted from the log  the until scn and the Starting Duplicate Db output. From this I obtained from the target database called PROD the range of archived redo log sequences that I was going to need.

oracle $ cat recover_from_prod.log | egrep "Starting Duplicate Db at | scn"
Starting Duplicate Db at 08-NOV-2020 17:07:35
   set until scn  281698833114;

oracle $ sqlplus sys/****@PROD as sysdba
...
SQL> select name from v$database;

NAME
---------
PROD

SQL> col scn format 999999999999999999999
SQL> select timestamp_to_scn(to_timestamp('08-11-2020 17:07:34','dd-mm-yyyy hh24:mi:ss')) scn from dual;

                   SCN
----------------------
          281674037748

SQL> select distinct thread#, sequence#, status, first_time, next_time, first_change#, next_change# from v$archived_log
where 281674037748 between first_change# and next_change# order by 1,2; 

   THREAD#  SEQUENCE# S FIRST_TIME          NEXT_TIME           FIRST_CHANGE# NEXT_CHANGE#
---------- ---------- - ------------------- ------------------- ------------- ------------
         1     567552 A 2020-11-08 17:04:19 2020-11-08 17:07:37    2.8167E+11   2.8167E+11
         2     535731 A 2020-11-08 17:05:00 2020-11-08 17:07:36    2.8167E+11   2.8167E+11

SQL> select distinct thread#, sequence#, status, first_time, next_time, first_change#, next_change# from v$archived_log
where 281698833114 between first_change# and next_change# order by 1,2; 

   THREAD#  SEQUENCE# S FIRST_TIME          NEXT_TIME           FIRST_CHANGE# NEXT_CHANGE#
---------- ---------- - ------------------- ------------------- ------------- ------------
         1     567681 A 2020-11-09 08:05:54 2020-11-09 08:06:09    2.8170E+11   2.8170E+11
         1     567682 A 2020-11-09 08:06:09 2020-11-09 08:10:27    2.8170E+11   2.8170E+11
         2     535910 A 2020-11-09 08:05:54 2020-11-09 08:06:09    2.8170E+11   2.8170E+11

With the data above, now I went and ran the following to backup copy command so that I could obtain the archived redo logs necessary for this recovery.

Do notice that I did it to a different location that the current db_recovery_file_dest and that I had to connect to both PROD and STG databases for this command.

oracle $ rman TARGET sys/********@PROD AUXILIARY sys/********@STG_STATIC
RMAN> run {
      backup as copy archivelog from sequence 567552 until sequence 567682 thread 1 auxiliary format '/u02/pythian/STG/%t_%s_%r.arc';
      backup as copy archivelog from sequence 535731 until sequence 535910 thread 2 auxiliary format '/u02/pythian/STG/%t_%s_%r.arc';
    }

Once the copy of the archived redo logs were restored, now I registered them to the control file of the STG database.

oracle $ . oraenv <<< STG1
oracle $ rman target /
connected to target database: STG (DBID=3874882083, not open)

RMAN> catalog start with '/u02/pythian/STG/;
cataloging files...
cataloging done

List of Cataloged Files
=======================
...
File Name: /u02/pythian/STG/1056028905_128319_904050853.arc
File Name: /u02/pythian/STG/1056030309_128439_904050853.arc

The last thing that I needed to do is to recover the STG database to the SCN found in the recover log. Making sure that I don’t connect to the target database called PROD, I am only connecting to the database called STG.

oracle $ . oraenv <<< STG1

oracle $ rman target /
connected to target database: STG (DBID=3874882083, not open)

RMAN> run {
   set until scn 281698833114;
   recover database;
}

executing command: SET until clause

Starting recover at 09-NOV-20
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=3142 device type=DISK

starting media recovery

archived log for thread 1 with sequence 567626 is already on disk as file /u02/pythian/STG/1056029933_128385_904050853.arc
archived log for thread 1 with sequence 567627 is already on disk as file /u02/pythian/STG/1056029940_128386_904050853.arc
archived log for thread 1 with sequence 567628 is already on disk as file /u02/pythian/STG/1056029941_128387_904050853.arc
archived log for thread 1 with sequence 567629 is already on disk as file /u02/pythian/STG/1056029942_128388_904050853.arc
archived log for thread 1 with sequence 567630 is already on disk as file /u02/pythian/STG/1056029943_128389_904050853.arc
archived log for thread 1 with sequence 567631 is already on disk as file /u02/pythian/STG/1056029945_128390_904050853.arc
archived log for thread 1 with sequence 567632 is already on disk as file /u02/pythian/STG/1056029952_128391_904050853.arc
...
archived log file name=/u02/pythian/STG/1056028890_128318_904050853.arc thread=2 sequence=535909
archived log file name=/u02/pythian/STG/1056030309_128439_904050853.arc thread=1 sequence=567680
archived log file name=/u02/pythian/STG/1056030310_128440_904050853.arc thread=1 sequence=567681
archived log file name=/u02/pythian/STG/1056028905_128319_904050853.arc thread=2 sequence=535910
media recovery complete, elapsed time: 00:06:35
Finished recover at 09-NOV-20

After this I just needed to open it as resetlogs, also what I wanted after this is for the cloned database to have a new DBID and at the end bring it up as a RAC database. Verifying as well the database and instance status using verify_data_dictionary_11g.sql

RMAN> alter database open resetlogs;

using target database control file instead of recovery catalog
database opened

RMAN> delete archivelog all;
...
Deleted 353 objects
RMAN> shutdown immediate

database shutdown

RMAN> STARTUP MOUNT

database mounted

RMAN> exit

oracle $ nid target=sys/*******

DBNEWID: Release 11.2.0.4.0 - Production on Mon Nov 9 14:34:22 2020

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.

Connected to database STG (DBID=3874882083)

Connected to server version 11.2.0

Control Files in database:
    +DATAC2/stg/controlfile/control01.ctl
    +RECOC2/stg/controlfile/control02.ctl

Change database ID of database STG? (Y/[N]) => Y

Proceeding with operation
Changing database ID from 3874882083 to 1490626863
    Control File +DATAC2/stg/controlfile/control01.ctl - modified
    Control File +RECOC2/stg/controlfile/control02.ctl - modified
    Datafile +DATAC2/stg/datafile/system.636.105600857 - dbid changed
    ...
    Datafile +DATAC2/stg/datafile/revenue_ods2.622.105598726 - dbid changed
    Control File +DATAC2/stg/controlfile/control01.ctl - dbid changed
    Control File +RECOC2/stg/controlfile/control02.ctl - dbid changed
    Instance shut down

Database ID for database STG changed to 1490626863.
All previous backups and archived redo logs for this database are unusable.
Database is not aware of previous backups and archived logs in Recovery Area.
Database has been shutdown, open database with RESETLOGS option.
Succesfully changed database ID.
DBNEWID - Completed succesfully.

oracle $ sqlplus / as sysdba
...
SQL> startup mount
ORACLE instance started.

Total System Global Area 1.6034E+11 bytes
Fixed Size                  2261848 bytes
Variable Size            2.5233E+10 bytes
Database Buffers         1.3475E+11 bytes
Redo Buffers              352444416 bytes
Database mounted.

SQL> ALTER DATABASE OPEN RESETLOGS;

Database altered.

SQL> ALTER SYSTEM SET cluster_database=TRUE SCOPE=spfile;
SQL> shutdown immediate
Database closed.
Database dismounted.
ORACLE instance shut down.

oracle $ srvctl start database -d STG
oracle $ srvctl status database -d STG
Instance STG1 is running on node auxiliarydbadm01
Instance STG2 is running on node auxiliarydbadm02

oracle $ sqlplus / as sysdba
SQL> @verify_data_dictionary_11g.sql
DATABASE NAME
=============
DBNAME
---------------
STG

================================================================================================
==   Oracle Instance Information
================================================================================================

--  IP Address   1**.***.***.30

   Cpu_Count                   24    |    Host_Name       auxiliarydbadm01
   Instance_Name             STG1    |    Database_Status           ACTIVE
   Status                    OPEN    |    Startup_Time    09-11-2020 14:43
   Version             11.2.0.4.0    |    Instance_Role   PRIMARY_INSTANCE

   Database log mode            ARCHIVELOG

   Background Dump Dest         /u01_diag/app/oracle/diag/diag/rdbms/stg/STG1/trace
   Spfile                       +DATAC2/stg/parameterfile/spfilestg.ora

   Redo size (Gb)            1.953125
   Redo size (Gb)           .09765625
-- Database Space (Gb)   35367.70    |    SGA (Gb)                149.3303 --
-- Nb. Datafiles              133    |    Nb. Tempfiles                 15 --


DBA_REGISTRY CONTENTS
================================================================

COMP_ID              COMP_NAME                                VERSION         Status
-------------------- ---------------------------------------- --------------- --------------------------------------------------
OWB                  OWB                                      11.2.0.4.0      VALID
APEX                 Oracle Application Express               3.2.1.00.12     VALID
EM                   Oracle Enterprise Manager                11.2.0.4.0      VALID
AMD                  OLAP Catalog                             11.2.0.4.0      VALID
SDO                  Spatial                                  11.2.0.4.0      VALID
ORDIM                Oracle Multimedia                        11.2.0.4.0      VALID
XDB                  Oracle XML Database                      11.2.0.4.0      VALID
CONTEXT              Oracle Text                              11.2.0.4.0      VALID
EXF                  Oracle Expression Filter                 11.2.0.4.0      VALID
RUL                  Oracle Rules Manager                     11.2.0.4.0      VALID
OWM                  Oracle Workspace Manager                 11.2.0.4.0      VALID
CATALOG              Oracle Database Catalog Views            11.2.0.4.0      VALID
CATPROC              Oracle Database Packages and Types       11.2.0.4.0      VALID
JAVAVM               JServer JAVA Virtual Machine             11.2.0.4.0      VALID
XML                  Oracle XDK                               11.2.0.4.0      VALID
CATJAVA              Oracle Database Java Packages            11.2.0.4.0      VALID
APS                  OLAP Analytic Workspace                  11.2.0.4.0      VALID
XOQ                  Oracle OLAP API                          11.2.0.4.0      VALID
RAC                  Oracle Real Application Clusters         11.2.0.4.0      VALID

19 rows selected.

LIST APPLIED PATCHES
=======================

ACTION_TIME                    ID         ACTION                         VERSION         BUNDLE                   COMMENTS
------------------------------ ---------- ------------------------------ --------------- ------------------------ --------------
24-AUG-13 12.03.45.119862 PM   0          APPLY                          11.2.0.4        PSU                      Patchset 11.2.0.2.0
17-FEB-16 01.17.34.459872 PM   0          jvmpsu.sql                     11.2.0.4                                 RAN jvmpsu.sql
17-FEB-16 01.18.26.518633 PM   20         APPLY                          11.2.0.4        EXA                      BP20
24-JUN-17 05.01.00.394556 AM   0          jvmpsu.sql                     11.2.0.4                                 RAN jvmpsu.sql
24-JUN-17 05.01.00.414355 AM   0          APPLY                          11.2.0.4                                 OJVM PSU post-instal
24-JUN-17 05.01.00.416012 AM   25434033   APPLY                                                                   Patch 25434033 appli
24-JUN-17 05.01.23.110902 AM   170418     APPLY                          11.2.0.4        EXA                      BP170418
24-JAN-19 07.48.56.741239 PM   180717     APPLY                          11.2.0.4        EXA                      BP180717
24-JAN-19 09.00.45.442572 PM   0          jvmpsu.sql                     11.2.0.4                                 RAN jvmpsu.sql
24-JAN-19 09.00.45.707068 PM   0          APPLY                          11.2.0.4                                 OJVM PSU post-instal
24-JAN-19 09.00.45.709711 PM   27923163   APPLY                                                                   Patch 27923163 appli

11 rows selected.

LIST APPLIED SQL PATCHES
=======================

COMMENTS                                                     ACTION                         ACTION_DATE          VERSION
------------------------------------------------------------ ------------------------------ -------------------- ---------------
RAN jvmpsu.sql                                               jvmpsu.sql                     17/02/16 13:17:34    11.2.0.4.5OJVMB
                                                                                                                 P

BP20                                                         APPLY                          17/02/16 13:18:26    11.2.0.4
BP180717                                                     APPLY                          24/01/19 19:48:56    11.2.0.4
RAN jvmpsu.sql                                               jvmpsu.sql                     24/01/19 21:00:45    11.2.0.4.180717
                                                                                                                 OJVMPSU

OJVM PSU post-install                                        APPLY                          24/01/19 21:00:45    11.2.0.4.180717
                                                                                                                 OJVMPSU

Patch 27923163 applied                                       APPLY                          24/01/19 21:00:45
OJVM PSU post-install                                        APPLY                          24/06/17 05:01:00    11.2.0.4.170418
                                                                                                                 OJVMPSU

RAN jvmpsu.sql                                               jvmpsu.sql                     24/06/17 05:01:00    11.2.0.4.170418
                                                                                                                 OJVMPSU

Patch 25434033 applied                                       APPLY                          24/06/17 05:01:00
BP170418                                                     APPLY                          24/06/17 05:01:23    11.2.0.4
Patchset 11.2.0.2.0                                          APPLY                          24/08/13 12:03:45    11.2.0.4

11 rows selected.

COUNT OF INVALID OBJECTS
========================

  COUNT(*)
----------
         0

1 row selected.

INVALID OBJECTS GROUPED BY OBJECT TYPE AND OWNER
================================================

no rows selected

LIST OF SYS INVALID OBJECTS
=======================

no rows selected

Hope this blog post helps you if you are ever facing the errors ORA-19909 and ORA-01110 as for me it took me a while to solve this and this would have come in handy in this situation.

Tags:
Rene Antunez
[email protected]
No Comments

Sorry, the comment form is closed at this time.