真实案例:Oracle数据库恢复ORA-01861问题

Oracle 数据库WEBDB 在新的服务器环境进行备份的异地恢复测试，在执行到还原数据文件时出现“ORA-01861: literal does not match format string ”的错误。

该错误不是NLS_DATE_FORMAT 参数设置不正确导致的，而是一个Oracle bug 导致的。在该错误的解决过程中，我们没有采用官方推荐的重建控制文件的解决方法，而是使用自己的解决方法，将老备份集完全删除再注册进新备份集。

生产数据库是10.2.0.3  ，RAC 集群，ASM 存储，测试数据库为单实例，文件系统存储。

这个bug 不会影响到生产库的正常的备份和恢复操作。

 

(miki西游 @mikixiyou 原文链接: http://mikixiyou.iteye.com/blog/1569963 )

 

1.  问题

在还原数据文件时，出现ORA-01861 错误，文件无法还原，导致备份恢复工作停止。

整个还原过程操作如下：

1 、在sqlplus 中启动实例到nomount 状态；

2 、在rman 中还原控制文件；

restore controlfile from ‘/backup/ctl.xxx’;

3 、启动实例到mounted 状态

sql ‘alter database mount’;

4 、注册备份集

catalog start with ‘/backup/’;

因为生产库的备份集所在目录和测试库的备份集所在目录不一样，所以使用catalog 将新位置注册进控制文件中。

5 、还原所有数据文件，并重命名。

这里测试还原第一个数据文件，文件位置从ASM 修改文件系统目录。

run
{
allocate channel ch01 type disk;
set until time "to_date('2012-06-25 23:00:00','yyyy-mm-dd hh24:mi:ss')";

set newname for datafile 1 to '/stor2T/app/oracle/oradata/WEBDB/system01.dbf';
restore datafile 1;
switch datafile all;
release channel ch01;
}

在这一步操作时，出现如下错误：

RMAN-03002: failure of restore command at 06/27/2012 16:09:51

ORA-01861: literal does not match format string

 

备份恢复测试工作因此而中止。

从错误信息看，这个应该是NLS_DATE_FORMAT 的格式设置的不对，set until time 的格式有问题。

于是，我们换成set until scn 进行数据文件的还原，还原操作的脚步如下是这样。

run
{
allocate channel ch01 type disk;
set until scn 3054150330;

set newname for datafile 1 to '/stor2T/app/oracle/oradata/WEBDB/system01.dbf';
restore datafile 1;
switch datafile all;
release channel ch01;
}

 

但是，还是报ORA-01861 错误。

甚至执行列出所有备份集时都出现这个错误。

RMAN> list backupset summary;

 

using target database control file instead of recovery catalog

RMAN-00571: ===========================================================

RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============

RMAN-00571: ===========================================================

RMAN-03002: failure of list command at 06/27/2012 16:29:18

ORA-01861: literal does not match format string

从这个现象看，这个问题已经不是一个参数设置不正确那么简单了。

2.  分析

Oracle 有一个BUG ，为 Bug 8513905 : ORA-1861 DURING RMAN RECOVERY 。

它分析这个bug 是因为控制文件的备份片含有无效的日期数据。

这里的控制文件是从备份集中restore 过来的。使用还原方法是”restore controlfile from ‘/backup/ctl.ccc’” 。

使用下列SQL 查询v$backup_piece 视图，找出无效日期数据。

alter session set nls_date_format='yyyy-mm-dd hh24:mi:ss';

 

select recid, status, device_type, handle, completion_time from v$backup_piece where completion_time > '2012-06-25 23:00:00';

查询操作很快报错，错误信息就是ORA-01861 。

 

使用这个SQL 将控制文件信息dump 出来，分析备份集在控制文件中是如何存储的。

alter session set events 'immediate trace name controlf level 20';

得到的信息如下：

 

***************************************************************************

BACKUP PIECE RECORDS

***************************************************************************

(size = 736, compat size = 736, section max = 4401, section in-use = 4401,

   last-recid= 313177, old-recno = 4338, last-recno = 4337)

 (extent = 1, blkno = 1326, numrecs = 4401)

Earliest record:

 RECID #308777 Recno 4338 Record timestamp   01/13/12 23:22:35 piece #1   copy #1 pool 0

   Backup set key: stamp=772500152, count=310443

   V$RMAN_STATUS: recid=18446744071562033872, stamp=18446744071562033864

   Flags: <deleted> <concurrent access>

   Device: DISK

   Handle:

   Media-Handle:

   Comment:

   Tag: TAG20120113T222641

   Completion time   01/13/12 23:36:12

Latest record:

 RECID #313177 Recno 4337 Record timestamp   06/27/12 16:50:43 piece #1   copy #2 pool 0

   Backup set key: stamp=784411507, count=313801

   V$RMAN_STATUS: recid=18446744071562033872, stamp=18446744071562033864

   Flags: <concurrent access>

   Device: DISK

   Handle: /WEBDBbackup/WEBDB_db_e9nc2arj_1_1.20120527

   Media-Handle:

   Comment:

   Tag: BAK_FULL

   Completion time   06/31/12 08:00:44

 

 RECID #313171 Recno 4331 Record timestamp   06/27/12 16:50:42 piece #1   copy #2 pool 0

   Backup set key: stamp=787003506, count=314306

   V$RMAN_STATUS: recid=18446744071562033872, stamp=18446744071562033864

   Flags: <concurrent access>

   Device: DISK

   Handle: /WEBDBbackup/WEBDB_db_u2nehe3i_1_1.20120626

   Media-Handle:

   Comment:

   Tag: BAK_FULL

   Completion time   06/31/12 08:09:08

 

 

在控制文件中，备份片除掉最早的2012 年1 月13 日的结束时间是正常的，其他都是不正确的，结束时间为2012 年6 月31 日。

这个时间格式是不正确的，因为2012 年6 月根本就没有31 日。

问题可以确认了，所有的备份片的结束时间都是不正确的，所以只要校验到该时间，就会出错。

 

3.  解决

3.1          重建控制文件解决法

问题出在控制文件中备份片的完成时间上，因此可以使用重建控制文件的方法来解决这个问题。

使用alter database backup controlfile to trace 生成创建控制文件的脚步到trc 文件中。

执行创建文件时，出现下列错误：

CREATE CONTROLFILE REUSE DATABASE "WEBDB" NORESETLOGS FORCE LOGGING ARCHIVELOG

*

ERROR at line 1:

ORA-01503: CREATE CONTROLFILE failed

ORA-01565: error in identifying file '+WEBDBDG/system01.dbf'

ORA-17503: ksfdopn:2 Failed to open file +WEBDBDG/system01.dbf

ORA-15001: diskgroup "WEBDBDG" does not exist or is not mounted

ORA-15077: could not locate ASM instance serving a required diskgroup

ORA-29701: unable to connect to Cluster Manager

 

因为数据文件不存在，所以控制文件不能重建。但数据文件要存在，则需要控制文件先正常，再从备份集中还原出来。

这里陷入死锁状态。

3.2          清理控制文件备份集解决法

我们再想一下，是控制文件中的备份集有错误的日期数据，所以不能还原数据文件。

我们重建控制文件的解决方法就是为了完全清理掉这些备份集，再重新注册备份集进来。

但控制文件不能重建，故我们需要手工去清理掉这些备份集，再注册新备份集进来，也可达到清理错误日期数据的目的。

首先，删除掉所有的备份集。

delete backupset ;

这个操作不需要校验备份集的完成日期，因此可用。

再次，重新注册备份集。

catalog start with ‘/backup/’ ;

最后，还原数据文件。

此时，数据文件可以正常还原了。

我们再dump 一下控制文件中的信息，发现所有的备份集的结束时间已经处于正确的值。

***************************************************************************

BACKUP PIECE RECORDS

***************************************************************************

 (size = 736, compat size = 736, section max = 4401, section in-use = 4401,

   last-recid= 313178, old-recno = 4339, last-recno = 4338)

 (extent = 1, blkno = 1326, numrecs = 4401)

Earliest record:

 RECID #308778 Recno 4339 Record timestamp   01/13/12 23:22:34 piece #1   copy #1 pool 0

   Backup set key: stamp=772500152, count=310442

   V$RMAN_STATUS: recid=18446744071562033792, stamp=18446744071562033784

   Flags: <deleted> <concurrent access>

   Device: DISK

   Handle:

   Media-Handle:

   Comment:

   Tag: TAG20120113T222641

   Completion time   01/13/12 23:36:12

Latest record:

 RECID #313178 Recno 4338 Record timestamp   06/28/12 10:32:42 piece #1   copy #2 pool 0

   Backup set key: stamp=787003506, count=314306

   V$RMAN_STATUS: recid=18446744071562033792, stamp=18446744071562033784

  Flags: <concurrent access>

   Device: DISK

   Handle: /WEBDBbackup/WEBDB_db_u2nehe3i_1_1.20120626

   Media-Handle:

   Comment:

   Tag: BAK_FULL

   Completion time   07/01/12 01:51:08

 

在trc 文件中，最后的备份集记录的结束时间不再是2012 年6 月31 日。

 

4.  该bug 是如何生成的

首先，我回到生产库时，查询v$backup_pieces 视图，并没有发现completion_time 的值有2012 年6 月31 日的记录。这就是说，bug 不是在主库中，主库的备份和恢复不会有问题。

接着，我们重新审视一下测试库的恢复操作过程。

1 、在sqlplus 中启动实例到nomount 状态；

2 、在rman 中还原控制文件；

restore controlfile from ‘/backup/ctl.xxx’;

3 、启动实例到mounted 状态

sql ‘alter database mount’;

4 、注册备份集

catalog start with ‘/backup/’;

 

在第三步将数据库实例启动到mounted 状态后，我们就可以查询一下控制文件中的备份集状况了。

如果这时测试库服务器上的备份集文件和主库上的备份集文件一致的话，则不用执行catalog ，将新备份集注册进控制文件中。

在第四步之前，我们检查一下备份集。

alter session set nls_date_format='yyyy-mm-dd hh24:mi:ss';

 

select recid, status, device_type, handle, completion_time from v$backup_piece where completion_time > '2012-06-25 23:00:00';

这时，并没有报错，没有出现异常的日期数据。

再执行了第四步之后，我们再执行查询v$backup_piece 的操作时，就出错了。

因此，我们可以判断bug 再使用catalog 注册新备份集时出错的。（注：至于为什么会出错，这需要oracle 的工程师去分析其软件产品。）

这里，我怀疑是控制文件中已经有的备份集和新注册的备份集冲突，所以导致备份集完成时间出现错误。

5.  总结

在注册进新的备份集到控制文件之前，需要将老的所有的备份集删除掉，这样确保不出现ORA-01861 错误。

Oracle 官方文档RMAN Recovery Session Fails with ORA-1861 [ID 852723.1] 中记录该bug 的生成原因和解决方法。但它提供的解决方法在我们这种情况下并不适用。

我们使用delete backupset 方法将所有备份集删除掉，再注册进新备份集的方法更加简洁有效。

再新注册备份集之后，我又对控制文件做了一次dump 操作，得出trc 文件中关于备份片记录的情况。

***************************************************************************

BACKUP PIECE RECORDS

***************************************************************************

 (size = 736, compat size = 736, section max = 4401, section in-use = 4401,

   last-recid= 313178, old-recno = 4339, last-recno = 4338)

 (extent = 1, blkno = 1326, numrecs = 4401)

Earliest record:

 RECID #308778 Recno 4339 Record timestamp   01/13/12 23:22:34 piece #1   copy #1 pool 0

   Backup set key: stamp=772500152, count=310442

   V$RMAN_STATUS: recid=18446744071562033792, stamp=18446744071562033784

   Flags: <deleted> <concurrent access>

   Device: DISK

   Handle:

   Media-Handle:

   Comment:

   Tag: TAG20120113T222641

   Completion time   01/13/12 23:36:12

Latest record:

 RECID #313178 Recno 4338 Record timestamp   06/28/12 10:32:42 piece #1   copy #2 pool 0

   Backup set key: stamp=787003506, count=314306

   V$RMAN_STATUS: recid=18446744071562033792, stamp=18446744071562033784

   Flags: <concurrent access>

   Device: DISK

   Handle: /WEBDBbackup/WEBDB_db_u2nehe3i_1_1.20120626

   Media-Handle:

   Comment:

   Tag: BAK_FULL

   Completion time   07/01/12 01:51:08

从结果中可以看到备份集的完成时间已经恢复正常。

因此，我们的异地恢复测试操作步骤需要做一点修改。在第四步注册备份集操作时，需要加上删除所有老的备份集操作。