备库alter日志出现大量Ora-16401: Archivelog Rejected By Rfs 报错

jiawang

In this Document

Symptoms

Changes

Cause

Solution

---

Applies to:  Oracle Database Backup Service - Version N/A and later
Oracle Database - Enterprise Edition - Version 10.2.0.4 to 11.1.0.7 [Release 10.2 to 11.1]
Oracle Database Cloud Schema Service - Version N/A and later
Oracle Database Exadata Cloud Machine - Version N/A and later
Oracle Cloud Infrastructure - Database Service - Version N/A and later
Information in this document applies to any platform.
SymptomsORA-16401: ARCHIVELOG REJECTED BY RFS error occurs when incorrect naming convention for fal_client parameter is set.
ChangesNOTE: In the images and/or the document content below, the user information and environment data used represents fictitious data from the Oracle sample schema(s), Public Documentation delivered with an Oracle database product or other training material. Any similarity to actual environments, actual persons, living or dead, is purely coincidental and not intended in any manner.
Primary database: p1ncm1
Standby database: p1ncm2
=============
***** Primary *****

log_archive_config DG_CONFIG=(p1ncm1,p1ncm2)
log_archive_dest_1 location=/<host>/p1ncm1/archive valid_for=(ALL_LOGFILES,ALL_ROLES) db_unique_name=p1ncm1
log_archive_dest_2 service=p1ncm2_<host> optional reopen=60 valid_for=(ONLINE_LOGFILES,PRIMARY_ROLE) db_unique_name=p1ncm2
fal_client p1ncm1_<host>
fal_server p1ncm2_<host>

--- 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: /<path>/p1ncm1/p1ncm1.redo.g02.m01.rdo
Current log# 2 seq# 4722 mem# 1: /<path>/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; <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: /<path>/p1ncm1/p1ncm1.redo.g04.m01.rdo
Current log# 4 seq# 4940 mem# 1: /<path>/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: '/<path>/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: '/<path>/p1ncm1/archive/p1ncm1.arch.4939.1.673712453.log'
(p1ncm1)
Wed Aug 11 00:00:58 2010
Committing creation of archivelog '/<path>/p1ncm1/archive/p1ncm1.arch.4939.1.673712453.log'
Invoking non-expedited destination LOG_ARCHIVE_DEST_2 thread 1 sequence 4939 host p1ncm2_<host>
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_<host>)
Wed Aug 11 00:00:58 2010
ARC1: Creating remote archive destination LOG_ARCHIVE_DEST_2: 'p1ncm2_<host>' (thread 1 sequence 4939)
(p1ncm1)
Wed Aug 11 00:01:19 2010
ARC1: Closing remote archive destination LOG_ARCHIVE_DEST_2: 'p1ncm2_<host>'
(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_<host>) <FAL[server, ARC1]: Begin FAL archive (dbid 0 branch 673712453 thread 1 sequence 4939 dest p1ncm2_<host>)
Wed Aug 11 00:01:20 2010
ARC1: Creating remote archive destination LOG_ARCHIVE_DEST_1: 'p1ncm2_<host>' (thread 1 sequence 4939) <<<(p1ncm1)
Wed Aug 11 00:01:20 2010
Errors in file /<path>/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_<host>)
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=/<path>/p1ncm2/archive valid_for=(ALL_LOGFILES,ALL_ROLES) db_unique_name=p1ncm2
log_archive_dest_2 service=p1ncm1_<host> optional reopen=60 valid_for=(ONLINE_LOGFILES,PRIMARY_ROLE) db_unique_name=p1ncm1
fal_client p1ncm2_<host>
fal_server p1ncm1_<host>

--- 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: '/<path>/p1ncm2/archive/p1ncm1.arch.4939.1.673712453.log'
Committing creation of archivelog '/<path>/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 /<path>/admin/p1ncm2/udump/p1ncm2_rfs_32487.trc:
ORA-16401: archivelog rejected by RFS
Wed Aug 11 00:01:53 2010
Media Recovery Log /<path>/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 destination pointed by log_archive_dest_2=p1ncm2_<host>
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_<host>

In effect p1ncm2_<host> and p1ncm1_<host> 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_<host> optional reopen=60 valid_for=(ONLINE_LOGFILES,PRIMARY_ROLE) db_unique_name=p1ncm2
alter system set fal_client=p1ncm1_<host> scope=both sid='*';

--- standby ---

Current Parameter Value:-

fal_client                     p1ncm2_<host>

Proposed Parameter Value:-

alter system set fal_client=p1ncm2_<host> scope=both sid='*'; ## same as primary's LAD_2