Experiments from the Field..Based on True Stories

An RMAN puzzle

  
In this article, we will look at a puzzling situation that happened at one of our environments, when we were carrying out an RMAN restoration. The RMAN backup was taken using a catalog (not using controlfile) and our mission was to restore PROD to UAT. Simple, right?

Wrong!

An Arrrgh! Moment..

We were using the following restoration script:

RMAN>
RMAN> run
2> {
3> set until time  "to_date('05/13/08 14:40:00','MM/DD/YY hh24:mi:ss')";
4> allocate auxiliary channel 'adisk_0' type DISK;
5> allocate auxiliary channel 'adisk_1' type DISK;
6> allocate auxiliary channel 'adisk_2' type DISK;
7> allocate auxiliary channel 'adisk_3' type DISK;
8> DUPLICATE TARGET DATABASE TO UAT;
9> }

The backup location was available and so were adequate backup channels, but we always ended up getting this laconic error:

...
...

Starting restore at 13-MAY-08

released channel: adisk_0
released channel: adisk_1
released channel: adisk_2
released channel: adisk_3
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-03002: failure of Duplicate Db command at 05/13/2008 15:25:38
RMAN-03015: error occurred in stored script Memory Script
RMAN-06026: some targets not found - aborting restore
RMAN-06100: no channel to restore a backup or copy of datafile 471
RMAN-06100: no channel to restore a backup or copy of datafile 466

RMAN>
RMAN> **end-of-file**

RMAN>

Recovery Manager complete.

No channel to restore?...

Huh? Well, as you can see, the channels were very well defined and even the rman log showed that the channels were being allocated. We even tried increasing the channels to 8 or 10, and also tried allocating auxiliary channels (was irrelevant), but to no avail.

Another option that was tried was plain and simple restoration using the RMAN> restore datafile 1; command. Although that failed since the paths of datafile 1 was not switched to UAT's convention, it did not prove anything.

My teammates, Dhandapani Perungulam   and Sandeep Rebba were trying out different options. Then someone had the bright idea of checking the timestamp of the completed backup. It was possible that we were trying to restore to a point in time before the backup had completed.

Verifying the rman backup completion time from catalog

First of all, we needed to set the NLS_DATE_FORMAT variable to include the HH24:MI format:

$  export NLS_DATE_FORMAT='dd-mon-rr hh24:mi'

Then we needed to connect to the target (source instance for replication in RMAN terminology) and RMAN catalog:

$  rman catalog rman@rman target sys@prd

Recovery Manager: Release 10.2.0.3.0 - Production on Fri May 23 14:34:02 2008

Copyright (c) 1982, 2005, Oracle.  All rights reserved.

rman database Password:

target database Password:

connected to target database: PRD (DBID=2530951715)
connected to recovery catalog database

RMAN>

This command will give us details of the backupsets and the time when the backup completed:

RMAN> list backup of database completed between '12-may-2008' and '14-may-2008;

...
...
...
BS Key  Type LV Size       Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
2794098 Incr 0  53.28G     SBT_TAPE    00:38:54     13-may-08 23:11
        BP Key: 2794121   Status: AVAILABLE  Compressed: NO  Tag: TAG20080513T203101
        Handle: racprod1_PRD<PRD_116563:654647578:1>.dbf   Media:
  List of Datafiles in backup set 2794098
  File LV Type Ckp SCN    Ckp Time        Name
  ---- -- ---- ---------- --------------- ----
  7    0  Incr 7247000051870 13-may-08 22:32 /u01/oracle/prdracdata/owad01.dbf
  295  0  Incr 7247000051870 13-may-08 22:32 /u01/oracle/prdracdata/system06.dbf
  379  0  Incr 7247000051870 13-may-08 22:32 /u01/oracle/prdracdata/rbs11.dbf
  459  0  Incr 7247000051870 13-may-08 22:32 /u01/oracle/prdracdata/apps_ts_interface01.dbf
  460  0  Incr 7247000051870 13-may-08 22:32 /u01/oracle/prdracdata/apps_ts_summary01.dbf
  481  0  Incr 7247000051870 13-may-08 22:32 /u01/oracle/prdracdata/apps_ts_tx_data12.dbf
  509  0  Incr 7247000051870 13-may-08 22:32 /u01/oracle/prdracdata/apps_ts_archive02.dbf

BS Key  Type LV Size       Device Type Elapsed Time Completion Time
------- ---- -- ---------- ----------- ------------ ---------------
2794099 Incr 0  55.62G     SBT_TAPE    00:39:54     13-may-08 23:12
        BP Key: 2794122   Status: AVAILABLE  Compressed: NO  Tag: TAG20080513T203101
        Handle: racprod1_PRD<PRD_116562:654647562:1>.dbf   Media:
  List of Datafiles in backup set 2794099
  File LV Type Ckp SCN    Ckp Time        Name
  ---- -- ---- ---------- --------------- ----
  5    0  Incr 7247000051797 13-may-08 22:32 /u01/oracle/prdracdata/system05.dbf
  17   0  Incr 7247000051797 13-may-08 22:32 /u01/oracle/prdracdata/rbs15.dbf
  18   0  Incr 7247000051797 13-may-08 22:32 /u01/oracle/prdracdata/apps_ts_interface03.dbf
  22   0  Incr 7247000051797 13-may-08 22:32 /u01/oracle/prdracdata/apps_ts_summary05.dbf
  398  0  Incr 7247000051797 13-may-08 22:32 /u01/oracle/prdracdata/discoverer01.dbf
  480  0  Incr 7247000051797 13-may-08 22:32 /u01/oracle/prdracdata/apps_ts_tx_data11.dbf
  508  0  Incr 7247000051797 13-may-08 22:32 /u01/oracle/prdracdata/apps_ts_nologging02.dbf

RMAN>

As we can see, 13-may-08 22:32 is the golden time. Anything after that in the until time statement will do.

Further progress..

So then, we tried with this script:

RMAN>
RMAN> run {
2> allocate auxiliary channel 'adisk_0' type DISK;
3> allocate auxiliary channel 'adisk_1' type DISK;
4> allocate auxiliary channel 'adisk_2' type DISK;
5> allocate auxiliary channel 'adisk_3' type DISK;
6> allocate auxiliary channel 'adisk_4' type DISK;
7>
8> set until time  "to_date('09/013/2008 22:40:00','DD/MM/YYYY HH24:MI:SS')";
9>
10> DUPLICATE TARGET DATABASE TO UAT;
11> }

Although, we got the following error for the archivelogs, we were able to open the database after manually supplying them and then doing an SQL> alter database open resetlogs; :

...
...

Starting recover at 13-MAY-08

starting media recovery

Oracle Error:
ORA-01547: warning: RECOVER succeeded but OPEN RESETLOGS would get error below
ORA-01194: file 1 needs more recovery to be consistent
ORA-01110: data file 1: '/u01/oracle/uatracdata/system01.dbf'

released channel: adisk_0
released channel: adisk_1
released channel: adisk_2
released channel: adisk_3
released channel: adisk_4
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-03002: failure of Duplicate Db command at 05/13/2008 22:47:51
RMAN-03015: error occurred in stored script Memory Script
RMAN-06053: unable to perform media recovery because of missing log
RMAN-06102: no channel to restore a backup or copy of log thread 2 seq 111965 lowscn 7246877796511
RMAN-06102: no channel to restore a backup or copy of log thread 1 seq 143643 lowscn 7246877796417

Conclusion

Some RMAN errors can be really hard to understand or debug. Especially, it seems that the no channel to restore a backup or copy seems to be a very generic error message in RMAN, which could really mean anything and can be very misleading.

For example, we can see that at the end, it gave the RMAN-06102: no channel to restore a backup or copy of log thread 2 seq 111965 lowscn 7246877796511 error, but that meant that it could not find the archive logs. After supplying the archive logs, the database opened up fine with the resetlogs option.