Strange behavior from resetlogs.

cbruhn2's picture
articles: 

During a test of some backup setup with rman I ran into problem running the restore / recover command.

Setup:


database running in noarchivelog mode.
Had run some

recover database until cancel;
alter database open resetlogs;

Commands before running my backup database command from rman.
Here is a listing of what happened.

RMAN> list backup ;
 
RMAN> backup database ;
 
Starting backup at 12-JAN-07
allocated channel: ORA_DISK_1
channel ORA_DISK_1: sid=156 devtype=DISK
channel ORA_DISK_1: starting compressed full datafile backupset
channel ORA_DISK_1: specifying datafile(s) in backupset
input datafile fno=00001 name=/home/oracle/oracle/product/10.2.0/db_1/oradata/udd/system01.dbf
input datafile fno=00003 name=/home/oracle/oracle/product/10.2.0/db_1/oradata/udd/sysaux01.dbf
input datafile fno=00002 name=/home/oracle/oracle/product/10.2.0/db_1/oradata/udd/undotbs01.dbf
input datafile fno=00004 name=/home/oracle/oracle/product/10.2.0/db_1/oradata/udd/users01.dbf
channel ORA_DISK_1: starting piece 1 at 12-JAN-07
channel ORA_DISK_1: finished piece 1 at 12-JAN-07
piece handle=/home/oracle/oracle/product/10.2.0/db_1/flash_recovery_area/UDD/backupset/2007_01_12/o1_mf_nnndf_TAG20070112T140001_2th1ll09_.bkp tag=TAG20070112T140001 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:01:26
channel ORA_DISK_1: starting compressed full datafile backupset
channel ORA_DISK_1: specifying datafile(s) in backupset
including current control file in backupset
including current SPFILE in backupset
channel ORA_DISK_1: starting piece 1 at 12-JAN-07
channel ORA_DISK_1: finished piece 1 at 12-JAN-07
piece handle=/home/oracle/oracle/product/10.2.0/db_1/flash_recovery_area/UDD/backupset/2007_01_12/o1_mf_ncsnf_TAG20070112T140001_2th1o997_.bkp tag=TAG20070112T140001 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:03
Finished backup at 12-JAN-07

so far so good but now comes the strange and to me mysterious part ..........

RMAN> restore database validate ;
 
Starting restore at 12-JAN-07
using channel ORA_DISK_1
 
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-03002: failure of restore command at 01/12/2007 14:01:55
RMAN-06026: some targets not found - aborting restore
RMAN-06023: no backup or copy of datafile 4 found to restore
RMAN-06023: no backup or copy of datafile 3 found to restore
RMAN-06023: no backup or copy of datafile 2 found to restore
RMAN-06023: no backup or copy of datafile 1 found to restore

what's up doc? Who took my backup?
RMAN> crosscheck backup ;
 
using channel ORA_DISK_1
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=/home/oracle/oracle/product/10.2.0/db_1/flash_recovery_area/UDD/backupset/2007_01_12/o1_mf_nnndf_TAG20070112T140001_2th1ll09_.bkp recid=41 stamp=611676001
crosschecked backup piece: found to be 'AVAILABLE'
backup piece handle=/home/oracle/oracle/product/10.2.0/db_1/flash_recovery_area/UDD/backupset/2007_01_12/o1_mf_ncsnf_TAG20070112T140001_2th1o997_.bkp recid=42 stamp=611676089
Crosschecked 2 objects

RMAN> list backup ; 
 
List of Backup Sets
===================
 
BS Key  Type LV Size       Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
42      Full    1.06M      DISK        00:00:02     12-JAN-07
        BP Key: 42   Status: AVAILABLE  Compressed: YES  Tag: TAG20070112T140001        Piece Name: /home/oracle/oracle/product/10.2.0/db_1/flash_recovery_area/UDD/backupset/2007_01_12/o1_mf_ncsnf_TAG20070112T140001_2th1o997_.bkp
  Control File Included: Ckp SCN: 586006       Ckp time: 12-JAN-07
  SPFILE Included: Modification time: 12-JAN-07
 
BS Key  Type LV Size       Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
43      Full    96.16M     DISK        00:00:00     12-JAN-07
        BP Key: 43   Status: AVAILABLE  Compressed: YES  Tag: TAG20070112T140001        Piece Name: /home/oracle/oracle/product/10.2.0/db_1/flash_recovery_area/UDD/backupset/2007_01_12/o1_mf_nnndf_TAG20070112T140001_2th1ll09_.bkp
  List of Datafiles in backup set 43
  File LV Type Ckp SCN    Ckp Time  Name
  ---- -- ---- ---------- --------- ----
  1       Full 586006     12-JAN-07 /home/oracle/oracle/product/10.2.0/db_1/oradata/udd/system01.dbf
  2       Full 586006     12-JAN-07 /home/oracle/oracle/product/10.2.0/db_1/oradata/udd/undotbs01.dbf
  3       Full 586006     12-JAN-07 /home/oracle/oracle/product/10.2.0/db_1/oradata/udd/sysaux01.dbf
  4       Full 586006     12-JAN-07 /home/oracle/oracle/product/10.2.0/db_1/oradata/udd/users01.dbf

seems backup are available so why not use them.
 
RMAN> list recoverable backup ;
 
 
List of Backup Sets
===================
 
BS Key  Type LV Size       Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
42      Full    1.06M      DISK        00:00:02     12-JAN-07
        BP Key: 42   Status: AVAILABLE  Compressed: YES  Tag: TAG20070112T140001        Piece Name: /home/oracle/oracle/product/10.2.0/db_1/flash_recovery_area/UDD/backupset/2007_01_12/o1_mf_ncsnf_TAG20070112T140001_2th1o997_.bkp
  Control File Included: Ckp SCN: 586006       Ckp time: 12-JAN-07
  SPFILE Included: Modification time: 12-JAN-07

Interesting, as there is only 1 backup piece that is able to be recovered from..
Probably a better way to check your backup status than just list backup.

I then ran

RMAN> list incarnation ;
 
 
List of Database Incarnations
DB Key  Inc Key DB Name  DB ID            STATUS  Reset SCN  Reset Time
------- ------- -------- ---------------- --- ---------- ----------
1       1       UDD      2338364670       PARENT  1          30-JUN-05
2       2       UDD      2338364670       PARENT  446075     10-JAN-07
3       3       UDD      2338364670       PARENT  455314     10-JAN-07
4       4       UDD      2338364670       PARENT  459128     10-JAN-07
5       5       UDD      2338364670       PARENT  459129     10-JAN-07
6       6       UDD      2338364670       CURRENT 459129     10-JAN-07
 
RMAN>

This was very interesting as it seems that 2 incarnations got the same SCN number. How this could happen I have not verified, or any idea about. It seems that Oracle got an "Bug 3698501 Reconfiguration may reuse an old incarnation number" related to RAC environment (which I'm not using) and fixed in 10.2.0.1 (my version).
I know why I got new incarnations (alter database open resetlogs) but how i got the same SCN for different incarnations I don't know.

The Fix:


Ran another recover until cancel ; alter database open resetlogs ; command, and now got
RMAN> list incarnation ;
 
List of Database Incarnations
DB Key  Inc Key DB Name  DB ID            STATUS  Reset SCN  Reset Time
------- ------- -------- ---------------- --- ---------- ----------
1       1       UDD      2338364670       PARENT  1          30-JUN-05
2       2       UDD      2338364670       PARENT  446075     10-JAN-07
3       3       UDD      2338364670       PARENT  455314     10-JAN-07
4       4       UDD      2338364670       PARENT  459128     10-JAN-07
5       5       UDD      2338364670       PARENT  459129     10-JAN-07
6       6       UDD      2338364670       PARENT  459129     10-JAN-07
7       7       UDD      2338364670       CURRENT 586007     12-JAN-07
 
RMAN>

And now all my backup functions worked on the new incarnation as expected. I didn't care about the other incarnations as I was only interested in the CURRENT.