Applies to:
Oracle Server - Enterprise Edition - Version: 10.2.0.4 and later [Release: 10.2 and later ]Information in this document applies to any platform.
Symptoms
ORA-16401: ARCHIVELOG REJECTED BY RFS
Changes
***** Primary *****log_archive_config DG_CONFIG=(p1ncm1,p1ncm2)
log_archive_dest_1 location=/u99/ORACLE/p1ncm1/archive valid_for=(ALL_LOGFILES,ALL_ROLES) db_unique_name=p1ncm1
log_archive_dest_2 service=p1ncm2_dgfal.csm.fub.com optional reopen=60 valid_for=(ONLINE_LOGFILES,PRIMARY_ROLE) db_unique_name=p1ncm2
fal_client p1ncm1_fc.csm.fub.com
fal_server p1ncm2_fs.csm.fub.com
--- alert_p1ncm1.log ---
ARC0 started with pid=14, OS id=23650
Sat Jul 17 11:25:27 2010
ARC0: Archival started
ARC1: Archival started
LGWR: STARTING ARCH PROCESSES COMPLETE
ARC1 started with pid=15, OS id=23652
Sat Jul 17 11:25:27 2010
ARC0: Becoming the 'no FAL' ARCH
ARC0: Becoming the 'no SRL' ARCH
Sat Jul 17 11:25:27 2010
Thread 1 opened at log sequence 4722
Current log# 2 seq# 4722 mem# 0: /u02/ORACLE/p1ncm1/p1ncm1.redo.g02.m01.rdo
Current log# 2 seq# 4722 mem# 1: /u03/ORACLE/p1ncm1/p1ncm1.redo.g02.m02.rdo
Successful open of redo thread 1
Sat Jul 17 11:25:27 2010
ARC1: Becoming the heartbeat ARCH
.....skipping ....
Tue Aug 10 08:47:18 2010
ALTER SYSTEM SET log_archive_trace=1 SCOPE=BOTH; <<--------- Enabling Trace Here
Tue Aug 10 16:00:55 2010
ALTER SYSTEM ARCHIVE LOG
Tue Aug 10 16:00:55 2010
Thread 1 cannot allocate new log, sequence 4938
Private strand flush not complete
.....skipping ....
Tue Aug 10 22:40:48 2010
Thread 1 advanced to log sequence 4939 (LGWR switch)
Tue Aug 10 22:40:48 2010
ARC0: Evaluating archive log 2 thread 1 sequence 4938
.....skipping ....
ALTER SYSTEM ARCHIVE LOG
ARCH: Evaluating archive log 3 thread 1 sequence 4939
Wed Aug 11 00:00:55 2010
Thread 1 advanced to log sequence 4940 (LGWR switch)
Current log# 4 seq# 4940 mem# 0: /u04/ORACLE/p1ncm1/p1ncm1.redo.g04.m01.rdo
Current log# 4 seq# 4940 mem# 1: /u01/ORACLE/p1ncm1/p1ncm1.redo.g04.m02.rdo
Wed Aug 11 00:00:55 2010
ARCH: Destination LOG_ARCHIVE_DEST_2 archival not expedited
Wed Aug 11 00:00:55 2010
ARCH: Beginning to archive thread 1 sequence 4939 (7809558586167-7809568175169) (p1ncm1)
Wed Aug 11 00:00:55 2010
ARCH: Creating local archive destination LOG_ARCHIVE_DEST_1: '/u99/ORACLE/p1ncm1/archive/p1ncm1.arch.4939.1.673712453.log' (thread 1 sequence 4939)
(p1ncm1)
Wed Aug 11 00:00:55 2010
ARC0: Evaluating archive log 3 thread 1 sequence 4939
ARC0: Unable to archive thread 1 sequence 4939
Log actively being archived by another process
Wed Aug 11 00:00:58 2010
ARCH: Closing local archive destination LOG_ARCHIVE_DEST_1: '/u99/ORACLE/p1ncm1/archive/p1ncm1.arch.4939.1.673712453.log'
(p1ncm1)
Wed Aug 11 00:00:58 2010
Committing creation of archivelog '/u99/ORACLE/p1ncm1/archive/p1ncm1.arch.4939.1.673712453.log'
Invoking non-expedited destination LOG_ARCHIVE_DEST_2 thread 1 sequence 4939 host p1ncm2_dgfal.csm.fub.com
Wed Aug 11 00:00:58 2010
ARCH: Completed archiving thread 1 sequence 4939 (7809558586167-7809568175169) (p1ncm1)
Wed Aug 11 00:00:58 2010
Redo Shipping Client Connected as PUBLIC
-- Connected User is Valid
Wed Aug 11 00:00:58 2010
FAL[server, ARC1]: Begin FAL noexpedite archive (dbid 0 branch 673712453 thread 1 sequence 4939 dest p1ncm2_dgfal.csm.fub.com)
Wed Aug 11 00:00:58 2010
ARC1: Creating remote archive destination LOG_ARCHIVE_DEST_2: 'p1ncm2_dgfal.csm.fub.com' (thread 1 sequence 4939)
(p1ncm1)
Wed Aug 11 00:01:19 2010
ARC1: Closing remote archive destination LOG_ARCHIVE_DEST_2: 'p1ncm2_dgfal.csm.fub.com'
(p1ncm1)
Wed Aug 11 00:01:20 2010
FAL[server, ARC1]: Complete FAL noexpedite archive (dbid 0 branch 673712453 thread 1 sequence 4939 destination p1ncm2_dgfal.csm.fub.com) <<--- arc1 completed remote archival of seq# 4939 to destination "p1ncm2_dgfal.csm.fub.com"
FAL[server, ARC1]: Begin FAL archive (dbid 0 branch 673712453 thread 1 sequence 4939 dest p1ncm2_fc.csm.fub.com)
Wed Aug 11 00:01:20 2010
ARC1: Creating remote archive destination LOG_ARCHIVE_DEST_1: 'p1ncm2_fc.csm.fub.com' (thread 1 sequence 4939) <<<<------- arc1 again attempts to create same log seq# 4939 to destination "p1ncm2_fc.csm.fub.com" by means of FAL resolution
(p1ncm1)
Wed Aug 11 00:01:20 2010
Errors in file /u00/oracle/admin/p1ncm1/bdump/p1ncm1_arc1_23652.trc:
ORA-16401: archivelog rejected by RFS
FAL[server, ARC1]: Complete FAL archive (dbid 0 branch 673712453 thread 1 sequence 4939 destination p1ncm2_fc.csm.fub.com)
Wed Aug 11 01:00:01 2010
alter database backup controlfile to trace
Wed Aug 11 01:00:01 2010
Completed: alter database backup controlfile to trace
Wed Aug 11 01:00:14 2010
ALTER SYSTEM ARCHIVE LOG
Wed Aug 11 01:00:14 2010
Thread 1 cannot allocate new log, sequence 4941
Private strand flush not complete
********* Standby ********
log_archive_config DG_CONFIG=(p1ncm1,p1ncm2)
log_archive_dest_1 location=/u99/ORACLE/p1ncm2/archive valid_for=(ALL_LOGFILES,ALL_ROLES) db_unique_name=p1ncm2
log_archive_dest_2 service=p1ncm1_dgfal.csm.fub.com optional reopen=60 valid_for=(ONLINE_LOGFILES,PRIMARY_ROLE) db_unique_name=p1ncm1
fal_client p1ncm2_fc.csm.fub.com
fal_server p1ncm1_fs.csm.fub.com
--- alert_p1ncm2.log ---
Tue Aug 10 08:48:37 2010
ALTER SYSTEM SET log_archive_trace=1 SCOPE=BOTH;
Tue Aug 10 16:01:37 2010
Tue Aug 10 22:43:13 2010
Media Recovery Waiting for thread 1 sequence 4939
Wed Aug 11 00:01:23 2010
RFS[2]: Begin archive primary thread 1 sequence 4939 (p1ncm2)
Wed Aug 11 00:01:23 2010
RFS[2]: No standby redo logfiles created
Wed Aug 11 00:01:44 2010
RFS[2]: Completed archive primary log 0 thread 1 sequence 4939 (p1ncm2)
Wed Aug 11 00:01:44 2010
RFS[2]: Archived Log: '/u99/ORACLE/p1ncm2/archive/p1ncm1.arch.4939.1.673712453.log'
Committing creation of archivelog '/u99/ORACLE/p1ncm2/archive/p1ncm1.arch.4939.1.673712453.log'
Wed Aug 11 00:01:44 2010
Redo Shipping Client Connected as PUBLIC
-- Connected User is Valid
RFS[14]: Assigned to RFS process 32487
RFS[14]: Identified database type as 'physical standby'
Wed Aug 11 00:01:44 2010
RFS[14]: Begin archive primary thread 1 sequence 4939 (p1ncm2)
Wed Aug 11 00:01:44 2010
Errors in file /u00/oracle/admin/p1ncm2/udump/p1ncm2_rfs_32487.trc:
ORA-16401: archivelog rejected by RFS
Wed Aug 11 00:01:53 2010
Media Recovery Log /u99/ORACLE/p1ncm2/archive/p1ncm1.arch.4939.1.673712453.log
Wed Aug 11 00:02:43 2010
Cause
Incorrect naming convention for fal_client parameter
Primary shipped particular log seq# to a desntination pointed by log_archive_dest_2=p1ncm2_dgfal.csm.fub.com
The standby can do its own GAP analysis and can request logs from the FAL_SERVERS.
The FAL servers, in this case the primary, will try to honor that request.
when standby attempts to resolve a gap, primary gets a different fal_client=p1ncm1_fs.csm.fub.com
In effect p1ncm2_dgfal.csm.fub.com and p1ncm1_fs.csm.fub.com point the same standby
If we set up fal_client on standby with a different tns alias that we have set at primary's LADn,
then ORA-16401 is expected.
If the TNS alias had matched, then we would have been able to see that the FAL request from the standby was the same as the FAL request created by regular LADn redo shipping,
and we would not have created the second FRB (FAL Request Block)
Consequently no ORA-16401 would have been reported
In 11gR2 we explicitly say that FAL_CLIENT is optional and should not be used. In which case we use the DB_UNIQUE_NAME of the sender of the request to match up to a LADn. So there would not have been redundant request for the same log seq#.
Solution
Make sure primary's log_archive_dest_n remote desitnation and standby's fal_client share
the same tns alias.
---primary --
log_archive_dest_2 service=p1ncm2_dgfal.csm.fub.com optional reopen=60 valid_for=(ONLINE_LOGFILES,PRIMARY_ROLE) db_unique_name=p1ncm2
alter system set fal_client=p1ncm1_dgfal.csm.fub.com scope=both sid='*';
--- standby ---
Current Parameter Value:-
fal_client p1ncm2_fc.csm.fub.com
Proposed Parameter Value:-
alter system set fal_client=p1ncm2_dgfal.csm.fub.com scope=both sid='*'; ## same as primary's LAD_2
Niciun comentariu:
Trimiteți un comentariu