最近数据库重建DG,出现了一连串奇怪的问题,导致折腾了许久,泪奔中。详细场景如下:

T1主库不可访问,准备切换备库

T2 finish recover,switchover to primary,切换为主库

T3主库恢复,继续使用主库

T4重建dg从库

问题点:由于该重库之前重建过2次,第一次数据库名称为db1,第二次为当前的db2,新建的重库名称也为db2。采用duplicate复制的办法,有如下的问题:

 

 ……………………………………………………..

Starting restore at 2013-11-12 18:02:24
allocated channel: ORA_AUX_DISK_1
channel ORA_AUX_DISK_1: sid=4495 devtype=DISK

channel ORA_AUX_DISK_1: starting datafile backupset restore
channel ORA_AUX_DISK_1: specifying datafile(s) to restore from backup set
restoring datafile 00001 to /oracle/ora_data/YJFDB1STDBY/datafile/o1_mf_system_%u_.dbf
restoring datafile 00002 to /oracle/ora_data/YJFDB1STDBY/datafile/o1_mf_undotbs1_%u_.dbf
restoring datafile 00003 to /oracle/ora_data/YJFDB1STDBY/datafile/o1_mf_sysaux_%u_.dbf
restoring datafile 00004 to /oracle/ora_data/YJFDB1STDBY/datafile/o1_mf_users_%u_.dbf
restoring datafile 00005 to /oracle/ora_data/YJFDB1STDBY/datafile/o1_mf_ts_accou_%u_.dbf
restoring datafile 00006 to /oracle/ora_data/YJFDB1STDBY/datafile/o1_mf_ts_idx_a_%u_.dbf
restoring datafile 00007 to /oracle/ora_data/YJFDB1STDBY/datafile/o1_mf_ts_accou_%u_.dbf
restoring datafile 00008 to /oracle/ora_data/YJFDB1STDBY/datafile/o1_mf_ts_idx_a_%u_.dbf
restoring datafile 00009 to /oracle/ora_data/YJFDB1STDBY/datafile/o1_mf_ts_payco_%u_.dbf
restoring datafile 00010 to /oracle/ora_data/YJFDB1STDBY/datafile/o1_mf_ts_idx_p_%u_.dbf
restoring datafile 00011 to /oracle/ora_data/YJFDB1STDBY/datafile/o1_mf_perfstat_%u_.dbf
restoring datafile 00012 to /oracle/ora_data/YJFDB1STDBY/datafile/o1_mf_ts_accou_%u_.dbf
restoring datafile 00013 to /oracle/ora_data/YJFDB1STDBY/datafile/o1_mf_ts_accou_%u_.dbf
restoring datafile 00014 to /oracle/ora_data/YJFDB1STDBY/datafile/o1_mf_undotbs1_%u_.dbf
restoring datafile 00015 to /oracle/ora_data/YJFDB1STDBY/datafile/o1_mf_ts_accou_%u_.dbf
restoring datafile 00016 to /oracle/ora_data/YJFDB1STDBY/datafile/o1_mf_ts_accou_%u_.dbf
channel ORA_AUX_DISK_1: reading from backup piece /oracle/ora_exp/dg/g7oopmqr_1_1
channel ORA_AUX_DISK_1: restored backup piece 1
piece handle=/oracle/ora_exp/dg/g7oopmqr_1_1 tag=TAG20131112T164619
channel ORA_AUX_DISK_1: restore complete, elapsed time: 00:41:35
Finished restore at 2013-11-12 18:44:00

contents of Memory Script:
{
   switch clone datafile all;
}
executing Memory Script

看日志最后部分,正常的duplicate会执行该memory script,但是奇怪的这次没有自动执行下面的操作。

 

alter database recover managed standby database disconnect from session;

查看备库日志:

Tue Nov 12 18:32:24 2013
MRP0: Background Managed Standby Recovery process started (yjfdb1)
Managed Standby Recovery not using Real Time Apply
Tue Nov 12 18:32:31 2013
Errors in file /oracle/admin/yjfdb1/bdump/yjfdb1_dbw0_6714.trc:
ORA-01157: cannot identify/lock data file 1 – see DBWR trace file
ORA-01110: data file 1: ‘/oracle/ora_data/YJFDB1/datafile/o1_mf_system_90411s0n_.dbf’
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
Tue Nov 12 18:32:31 2013
Errors in file /oracle/admin/yjfdb1/bdump/yjfdb1_dbw0_6714.trc:
ORA-01157: cannot identify/lock data file 2 – see DBWR trace file
ORA-01110: data file 2: ‘/oracle/ora_data/YJFDB1/datafile/o1_mf_undotbs1_90411xs3_.dbf’
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
Tue Nov 12 18:32:31 2013
Errors in file /oracle/admin/yjfdb1/bdump/yjfdb1_dbw0_6714.trc:
ORA-01157: cannot identify/lock data file 3 – see DBWR trace file
ORA-01110: data file 3: ‘/oracle/ora_data/YJFDB1/datafile/o1_mf_sysaux_90413ghq_.dbf’
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory

发现没有找到恢复好的数据文件,分析后原因在于,没有执行duplicate最后脚本,该脚本负责处理duplicate后的数据库映射关系,同时更新standby的控制文件头,由于没有成功执行RMAN内部脚本,导致找不到路径,不知道这个算不算bug,那么问题就好解决了(目前已经完全恢复是前提),即进行数据库异常恢复:

手动进行路径映射恢复,值得注意的是:

1.一定要找好datafile#与没有更新的控制文件的对应关系;

2.不能重建备库的控制文件信息

 

至此,完成之后的日志:

Attempt to start background Managed Standby Recovery process (yjfdb1)
MRP0 started with pid=18, OS id=24694
Tue Nov 12 20:25:28 2013
MRP0: Background Managed Standby Recovery process started (yjfdb1)
Managed Standby Recovery not using Real Time Apply
 parallel recovery started with 7 processes
Tue Nov 12 20:25:34 2013
Waiting for all non-current ORLs to be archived…
Tue Nov 12 20:25:34 2013
Errors in file /oracle/admin/yjfdb1/bdump/yjfdb1_mrp0_24694.trc:
ORA-00313: open failed for members of log group 1 of thread 1
ORA-00312: online log 1 thread 1: ‘/oracle/ora_log/YJFDB1/onlinelog/redo1_2.log’
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
ORA-00312: online log 1 thread 1: ‘/oracle/ora_log/YJFDB1/onlinelog/redo1_1.log’
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
Tue Nov 12 20:25:34 2013
Errors in file /oracle/admin/yjfdb1/bdump/yjfdb1_mrp0_24694.trc:
ORA-00313: open failed for members of log group 1 of thread 1
ORA-00312: online log 1 thread 1: ‘/oracle/ora_log/YJFDB1/onlinelog/redo1_2.log’
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
ORA-00312: online log 1 thread 1: ‘/oracle/ora_log/YJFDB1/onlinelog/redo1_1.log’
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
Clearing online redo logfile 1 /oracle/ora_log/YJFDB1/onlinelog/redo1_1.log
Clearing online log 1 of thread 1 sequence number 2650
Tue Nov 12 20:25:34 2013
Errors in file /oracle/admin/yjfdb1/bdump/yjfdb1_mrp0_24694.trc:
ORA-00313: open failed for members of log group 1 of thread 1
ORA-00312: online log 1 thread 1: ‘/oracle/ora_log/YJFDB1/onlinelog/redo1_2.log’
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
ORA-00312: online log 1 thread 1: ‘/oracle/ora_log/YJFDB1/onlinelog/redo1_1.log’
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
Tue Nov 12 20:25:34 2013
Errors in file /oracle/admin/yjfdb1/bdump/yjfdb1_mrp0_24694.trc:
ORA-19527: physical standby redo log must be renamed
ORA-00312: online log 1 thread 1: ‘/oracle/ora_log/YJFDB1/onlinelog/redo1_1.log’
Clearing online redo logfile 1 complete
Media Recovery Log /oracle/ora_standby/1_2650_822846263.arc
Tue Nov 12 20:25:34 2013
Completed: alter database recover managed standby database disconnect from session
Tue Nov 12 20:25:47 2013
RFS[2]: Archived Log: ‘/oracle/ora_standby/1_2651_822846263.arc’
Primary database is in MAXIMUM PERFORMANCE mode
RFS[2]: Successfully opened standby log 10: ‘/oracle/ora_log/YJFDB1/standbylog/yjfdb1stdby101.log’
Tue Nov 12 20:27:54 2013
Media Recovery Log /oracle/ora_standby/1_2651_822846263.arc
Tue Nov 12 20:28:05 2013
Media Recovery Waiting for thread 1 sequence 2652 (in transit)
Tue Nov 12 20:38:37 2013
Primary database is in MAXIMUM PERFORMANCE mode
RFS[2]: Successfully opened standby log 11: ‘/oracle/ora_log/YJFDB1/standbylog/yjfdb1stdby111.log’
Tue Nov 12 20:38:40 2013
Media Recovery Log /oracle/ora_arc/1_2652_822846263.arc
Tue Nov 12 20:39:01 2013
Media Recovery Waiting for thread 1 sequence 2653 (in transit)
Tue Nov 12 22:05:56 2013
Primary database is in MAXIMUM PERFORMANCE mode
RFS[2]: Successfully opened standby log 10: ‘/oracle/ora_log/YJFDB1/standbylog/yjfdb1stdby101.log’
Tue Nov 12 22:06:03 2013
Media Recovery Log /oracle/ora_arc/1_2653_822846263.arc
Tue Nov 12 22:07:42 2013
Primary database is in MAXIMUM PERFORMANCE mode
RFS[2]: Successfully opened standby log 11: ‘/oracle/ora_log/YJFDB1/standbylog/yjfdb1stdby111.log’
Tue Nov 12 22:11:05 2013
Media Recovery Log /oracle/ora_arc/1_2654_822846263.arc
Tue Nov 12 22:12:48 2013
Media Recovery Waiting for thread 1 sequence 2655 (in transit)
Tue Nov 12 22:25:11 2013
Primary database is in MAXIMUM PERFORMANCE mode
RFS[2]: Successfully opened standby log 10: ‘/oracle/ora_log/YJFDB1/standbylog/yjfdb1stdby101.log’
Tue Nov 12 22:25:23 2013
Media Recovery Log /oracle/ora_arc/1_2655_822846263.arc
Tue Nov 12 22:27:31 2013
Media Recovery Waiting for thread 1 sequence 2656 (in transit)
Wed Nov 13 00:22:31 2013
Primary database is in MAXIMUM PERFORMANCE mode
RFS[2]: Successfully opened standby log 11: ‘/oracle/ora_log/YJFDB1/standbylog/yjfdb1stdby111.log’
Wed Nov 13 00:22:34 2013
Media Recovery Log /oracle/ora_arc/1_2656_822846263.arc
Wed Nov 13 00:26:52 2013
Media Recovery Waiting for thread 1 sequence 2657 (in transit)
Wed Nov 13 03:00:04 2013
Primary database is in MAXIMUM PERFORMANCE mode
RFS[2]: Successfully opened standby log 10: ‘/oracle/ora_log/YJFDB1/standbylog/yjfdb1stdby101.log’
Primary database is in MAXIMUM PERFORMANCE mode
RFS[2]: Successfully opened standby log 11: ‘/oracle/ora_log/YJFDB1/standbylog/yjfdb1stdby111.log’
Wed Nov 13 03:00:11 2013
Media Recovery Log /oracle/ora_arc/1_2657_822846263.arc
Wed Nov 13 03:00:53 2013
RFS[1]: Successfully opened standby log 10: ‘/oracle/ora_log/YJFDB1/standbylog/yjfdb1stdby101.log’
Wed Nov 13 03:01:45 2013
Media Recovery Log /oracle/ora_arc/1_2658_822846263.arc
Media Recovery Log /oracle/ora_arc/1_2659_822846263.arc
Media Recovery Waiting for thread 1 sequence 2660 (in transit)

PROCESS   CLIENT_P  SEQUENCE# STATUS                                                                                                                                                                                                                                                                        
——— ——– ———- ————                                                                                                                                                                                                                                                                  
ARCH      ARCH           2656 CLOSING                                                                                                                                                                                                                                                                       
ARCH      ARCH           2655 CLOSING                                                                                                                                                                                                                                                                       
RFS       UNKNOWN           0 IDLE                                                                                                                                                                                                                                                                          
MRP0      N/A            2657 WAIT_FOR_LOG                                                                                                                                                                                                                                                                  
RFS       LGWR           2657 IDLE      
 
 
至此,数据库重库恢复。值得感慨的是,幸好对数据库非常熟悉,要不我估计至少有50%的人会在这里翻船,因为这个场景相对比较特殊。