Wednesday, July 24, 2013


Replication Failure Due to Missing Archived Logs / 

Issue During Restore of Archived Logs




During replication from our Source DB to target DB failed with following error…
a) The SCN portion of the log position 8940427876.0.0.0.0.0 is invalid. b) The SCN associated with log position 8940427876.0.0.0.0.0 does not correspond to a current on-line redo log file and ARCHIVELOG mode is not enabled. c) The redo log file(s) corresponding to log position 8940427876.0.0.0.0.0 does not currently exist, exists but is inaccessible or exists and is corrupt. d) The control file contains invalid information
Initially it looked like the archivelog was deleted from disk post backup hence we decided to restore the archivelogs as per the timeline given by Apps team.
We used following script to restore the archived logs from  backup
run
{
ALLOCATE CHANNEL t1 TYPE 'SBT_TAPE';
ALLOCATE CHANNEL t2 TYPE 'SBT_TAPE';
ALLOCATE CHANNEL t3 TYPE 'SBT_TAPE';
ALLOCATE CHANNEL t4 TYPE 'SBT_TAPE';
restore archivelog
from time = "to_date('JUL 13 2013 00:00:00','MON DD YYYY HH24:MI:SS')"
until time = "to_date('JUL 16 2013 05:00:00','MON DD YYYY HH24:MI:SS')";
RELEASE CHANNEL t1;
RELEASE CHANNEL t2;
RELEASE CHANNEL t3;
RELEASE CHANNEL t4;
}

#select name, first_time, thread# from v$archived_log where 8583608519 between first_change# and next_change#

The logs were restored but when we execute we get following list blank name
NAME FIRST_TIM THREAD#
---------------------------------------- --------- -----------
              01-JUL-13      1
              01-JUL-13      2

The name column of the view v$archive_log will be blank after RMAN has deleted the archive log.

From the reference guide:

NAME VARCHAR2(513) Archived log file name. If set to NULL, either the log file was cleared before it was archived or an RMAN backup command with the "delete input" option was executed to back up archivelog all (RMAN> backup archivelog all delete input;).

We ran the following query to figure out the archive logs containing those changes…

set echo on feedback on time on timing on pagesize 100 linesize 80
alter session set nls_date_format = 'DD-MON-YYYY HH24:MI:SS';
select name, thread#, sequence#, status, first_time, next_time, first_change#, next_change#
from v$archived_log
where 8940427876 between first_change# and next_change#
order by first_change#;
NAME
--------------------------------------------------------------------------------
THREAD# SEQUENCE# S FIRST_TIM NEXT_TIME FIRST_CHANGE# NEXT_CHANGE#
---------- ---------- - --------- --------- ------------- ------------

1 16231 D 17-JUL-13 17-JUL-13 8939762971 8940683008


2 20020 D 17-JUL-13 17-JUL-13 8940108930 8940777999

Name was still blank, hence decided to check the backup pieces.
RMAN> list copy of archivelog sequence=16231 thread=1;
specification does not match any archived log in the repository

RMAN> list backup of archivelog sequence=16231 thread=1;
List of Backup Sets
===================
BS Key Size Device Type Elapsed Time Completion Time
------- ---------- ----------- ------------ --------------------
19997 1.49G SBT_TAPE 00:00:51 18-JUL-2013 00:36:57
BP Key: 19997 Status: AVAILABLE Compressed: NO Tag: HOT_ARCH_BK
Handle: XXXX_ARC_ifof0pnm_1_1_821061366 Media: @aaaaj

List of Archived Logs in backup set 19997
Thrd Seq Low SCN Low Time Next SCN Next Time
---- ------- ---------- -------------------- ---------- ---------
1 16231 8939762971 17-JUL-2013 15:28:53 8940683008 17-JUL-2013 18:05:31

RMAN> list copy of archivelog sequence=20020 thread=2;
specification does not match any archived log in the repository

RMAN> list backup of archivelog sequence=20020 thread=2;
List of Backup Sets
==================
BS Key Size Device Type Elapsed Time Completion Time
------- ---------- ----------- ------------ --------------------
19997 1.49G SBT_TAPE 00:00:51 18-JUL-2013 00:36:57
BP Key: 19997 Status: AVAILABLE Compressed: NO Tag: HOT_ARCH_BK
Handle: XXXX_ARC_ifof0pnm_1_1_821061366 Media: @aaaaj

List of Archived Logs in backup set 19997
Thrd Seq Low SCN Low Time Next SCN Next Time
---- ------- ---------- -------------------- ---------- ---------
2 20020 8940108930 17-JUL-2013 15:56:06 8940777999 17-JUL-2013 18:08:41

First, run the following SQL statement to determine the minimum and maximum sequence# for each thread/node that are still available on disk.
This will gives us the list of archive logs still on disk.

select thread#, min(sequence#), max(sequence#) from v$archived_log
where status = 'A'
group by thread#;
THREAD# MIN(SEQUENCE#) MAX(SEQUENCE#)
---------- -------------- --------------
1              16122                   16256
2              19734                    20063


To determine their FIRST_CHANGE# and FIRST_TIME, please run the following SQL statement, as shown here.

set echo on feedback on time on timing on pagesize 100 linesize 80
alter session set nls_date_format = 'DD-MON-YYYY HH24:MI:SS';
select name, thread#, sequence#, status, first_time, next_time, first_change#, next_change#
from v$archived_log
where
(thread# = 1 and sequence# = 16122) or
(thread# = 2 and sequence# = 19734)
order by first_change#;
NAME
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
THREAD# SEQUENCE# S FIRST_TIME NEXT_TIME FIRST_CHANGE# NEXT_CHANGE#
---------- ---------- - -------------------- -------------------- ------------- ------------

2 19734 D 15-JUL-2013 23:46:55 16-JUL-2013 00:10:58 8899005572 8899582829  
ç Original entry , deleted post RMAN backup

+PSFT_HR_PROD_DATA/XXXX/archivelog/2013_07_18/thread_2_seq_19734.1649.821074773
2 19734 A 15-JUL-2013 23:46:55 16-JUL-2013 00:10:58 8899005572 8899582829 
ç restored archivelog backup

+PSFT_HR_PROD_DATA/XXXX/archivelog/2013_07_18/thread_1_seq_16122.1646.821074773
1 16122 A 15-JUL-2013 23:47:18 16-JUL-2013 00:00:19 8899012060 8899374054
ç restored archivelog backup


1 16122 D 15-JUL-2013 23:47:18 16-JUL-2013 00:00:19 8899012060 8899374054
ç Original entry , deleted post RMAN backup

I suggest to run the following RMAN script.

run
{
ALLOCATE CHANNEL t1 TYPE 'SBT_TAPE';
ALLOCATE CHANNEL t2 TYPE 'SBT_TAPE';
ALLOCATE CHANNEL t3 TYPE 'SBT_TAPE';
ALLOCATE CHANNEL t4 TYPE 'SBT_TAPE';
restore archivelog from time = "to_date('JUL 14 2013 00:00:00','MON DD YYYY HH24:MI:SS')"
until time = "to_date('JUL 16 2013 00:10:58','MON DD YYYY HH24:MI:SS')";
RELEASE CHANNEL t1;
RELEASE CHANNEL t2;
RELEASE CHANNEL t3;
RELEASE CHANNEL t4;
}

archived log for thread 1 with sequence 16122 is already on disk as file +PSFT_HR_PROD_DATA/XXXX/archivelog/2013_07_18/thread_1_seq_16122.1646.821074773
archived log for thread 1 with sequence 16123 is already on disk as file +PSFT_HR_PROD_DATA/XXXX/archivelog/2013_07_18/thread_1_seq_16123.1644.821074773
archived log for thread 1 with sequence 16124 is already on disk as file +PSFT_HR_PROD_DATA/XXXX/archivelog/2013_07_18/thread_1_seq_16124.1648.821074773
archived log for thread 2 with sequence 19734 is already on disk as file +PSFT_HR_PROD_DATA/XXXX/archivelog/2013_07_18/thread_2_seq_19734.1649.821074773
archived log for thread 2 with sequence 19735 is already on disk as file +PSFT_HR_PROD_DATA/XXXX/archivelog/2013_07_18/thread_2_seq_19735.1650.821074773
released channel: t1
released channel: t2
released channel: t3
released channel: t4
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-03002: failure of restore command at 07/18/2013 20:45:45
RMAN-06026: some targets not found - aborting restore
RMAN-06025: no backup of archived log for thread 2 with sequence 19733 and starting SCN of 8897710936 found to restore

So if you see, the sequence its showing for thread 2 is the one before what is available on disk. So now we have to check the backup piece containing this particular log sequence.
RMAN archive log backup shows following…
BS Key  Size       Device Type Elapsed Time Completion Time    
------- ---------- ----------- ------------ --------------------
19842   1.30G      SBT_TAPE    00:00:35     16-JUL-2013 04:58:32
       BP Key: 19842   Status: EXPIRED  Compressed: NO  Tag: HOT_ARCH_BK
       Handle: XXXX_ARC_dioes0al_1_1_820904277   Media: @aaaaj

 List of Archived Logs in backup set 19842
 Thrd Seq     Low SCN    Low Time             Next SCN   Next Time
 ---- ------- ---------- -------------------- ---------- ---------
 1    16120   8898316623 15-JUL-2013 23:16:07 8898774568 15-JUL-2013 23:31:54
 1    16121   8898774568 15-JUL-2013 23:31:54 8899012060 15-JUL-2013 23:47:18
 2    19733   8897710936 15-JUL-2013 22:58:36 8899005572 15-JUL-2013 23:46:55   
ç thread 2 with sequence 19733 and starting SCN of 8897710936
 2    19734   8899005572 15-JUL-2013 23:46:55 8899582829 16-JUL-2013 00:10:58

According to the output, the RMAN backup piece 'XXXX_ARC_dioes0al_1_1_820904277' contain the archivelog sequence# 19733 of thread# 2, but the RMAN backup status is EXPIRED. That explains why you are getting the following error, as shown here, because the RMAN backup is EXPIRED, which contains the archivelog sequence# 19733 of thread# 2

RMAN-06025: no backup of archived log for thread 2 with sequence 19733 and starting SCN of 8897710936 found to restore

To change the status from EXPIRED to AVAILABLE, run the following RMAN script.

spool log to rman_archivelog_crosscheck01.log
set echo on
run
{
ALLOCATE CHANNEL t1 TYPE 'SBT_TAPE';
ALLOCATE CHANNEL t2 TYPE 'SBT_TAPE';
ALLOCATE CHANNEL t3 TYPE 'SBT_TAPE';
ALLOCATE CHANNEL t4 TYPE 'SBT_TAPE';
crosscheck backup;
RELEASE CHANNEL t1;
RELEASE CHANNEL t2;
RELEASE CHANNEL t3;
RELEASE CHANNEL t4;
}
spool log off

Afterward, run the following RMAN restore script

spool log to rman_archivelog_restore02.log
set echo on
run
{
ALLOCATE CHANNEL t1 TYPE 'SBT_TAPE';
ALLOCATE CHANNEL t2 TYPE 'SBT_TAPE';
ALLOCATE CHANNEL t3 TYPE 'SBT_TAPE';
ALLOCATE CHANNEL t4 TYPE 'SBT_TAPE';
restore archivelog from time = "to_date('JUL 14 2013 00:00:00','MON DD YYYY HH24:MI:SS')"
until time = "to_date('JUL 16 2013 00:10:58','MON DD YYYY HH24:MI:SS')";
RELEASE CHANNEL t1;
RELEASE CHANNEL t2;
RELEASE CHANNEL t3;
RELEASE CHANNEL t4;
}
spool log off

set echo on feedback on time on timing on pagesize 100 linesize 80
select name, thread#, sequence#, status, first_time, next_time, first_change#, next_change#
from v$archived_log
where 8940427876 between first_change# and next_change#
order by first_change#;
NAME
--------------------------------------------------------------------------------
THREAD# SEQUENCE# S FIRST_TIM NEXT_TIME FIRST_CHANGE# NEXT_CHANGE#
---------- ---------- - --------- --------- ------------- ------------

1 16231 D 17-JUL-13 17-JUL-13 8939762971 8940683008


2 20020 D 17-JUL-13 17-JUL-13 8940108930 8940777999

Thrd Seq Low SCN Low Time Next SCN Next Time
---- ------- ---------- -------------------- ---------- ---------
1 15955 8848106302 13-JUL-2013 20:08:40 8848165443 13-JUL-2013 20:09:05
1 15956 8848165443 13-JUL-2013 20:09:05 8849372833 13-JUL-2013 22:00:25
2 19508 8849012683 13-JUL-2013 20:38:13 8849372813 13-JUL-2013 22:00:24
2 19509 8849372813 13-JUL-2013 22:00:24 8849672629 14-JUL-2013 00:26:26


List of Archived Logs in backup set 19842
Thrd Seq Low SCN Low Time Next SCN Next Time
---- ------- ---------- -------------------- ---------- ---------
1 16120 8898316623 15-JUL-2013 23:16:07 8898774568 15-JUL-2013 23:31:54
1 16121 8898774568 15-JUL-2013 23:31:54 8899012060 15-JUL-2013 23:47:18
2 19733 8897710936 15-JUL-2013 22:58:36 8899005572 15-JUL-2013 23:46:55
2 19734 8899005572 15-JUL-2013 23:46:55 8899582829 16-JUL-2013 00:10:58

List of Archived Logs in backup set 19595
Thrd Seq Low SCN Low Time Next SCN Next Time
---- ------- ---------- -------------------- ---------- ---------
1 15957 8849372833 13-JUL-2013 22:00:25 8849499795 13-JUL-2013 23:19:50
1 15958 8849499795 13-JUL-2013 23:19:50 8850111952 14-JUL-2013 01:15:30
2 19510 8849672629 14-JUL-2013 00:26:26 8849927816 14-JUL-2013 01:13:23
2 19511 8849927816 14-JUL-2013 01:13:23 8850109483 14-JUL-2013 01:15:29

List of Archived Logs in backup set 19843
Thrd Seq Low SCN Low Time Next SCN Next Time
---- ------- ---------- -------------------- ---------- ---------
1 16122 8899012060 15-JUL-2013 23:47:18 8899374054 16-JUL-2013 00:00:19
1 16123 8899374054 16-JUL-2013 00:00:19 8899582716 16-JUL-2013 00:10:56
1 16124 8899582716 16-JUL-2013 00:10:56 8899757027 16-JUL-2013 00:24:31
2 19735 8899582829 16-JUL-2013 00:10:58 8900326154 16-JUL-2013 01:10:19
So given the time frame from Jul 14, 00:00 to Jul 16, 00:00 following are the sequence numbers for corresponding threads.
run
{
restore archive from sequence 19509 thread 2 until sequence 19735 thread 2;
restore archive from sequence 15958 thread 1 until sequence 16124 thread 1;
}

Once restored, the CDC started successfully and issue was resolved.