/*
|| Oracle 11g DataGuard Listing 7
||
|| Illustrates the results of Fast-Start Failover (FSF) when controlled
|| by the Fast-Start Failover Observer (FSFO) in an Oracle Database 11g primary
|| and standby Data Guard environment.
||
|| Author: Jim Czuprynski
||
|| Usage Notes:
|| These examples are provided to demonstrate various Oracle 11gR1 Data Guard
|| features, and they should be carefully proofread before being executed
|| against any existing Oracle database to avoid potential damage!
*/

/* 
|| Listing 7.1:
|| Detecting a failover with FSFO
*/

>> Original standby database alert log entries:

. . .
Sun Aug 30 16:56:24 2009
Media Recovery Waiting for thread 1 sequence 19
Sun Aug 30 16:56:25 2009
Primary database is in MAXIMUM PERFORMANCE mode
kcrrvslf: active RFS archival for log 6 thread 1 sequence 18
RFS[1]: Successfully opened standby log 5: '/u01/app/oracle/oradata/stdby/srl02.log'
Recovery of Online Redo Log: Thread 1 Group 5 Seq 19 Reading mem 0
  Mem# 0: /u01/app/oracle/oradata/stdby/srl02.log
Sun Aug 30 17:03:21 2009
Attempting Fast-Start Failover because the threshold of 180 seconds has elapsed.
Sun Aug 30 17:03:42 2009
Initiated fast-start failover to database orcl_stdby1.
Sun Aug 30 17:03:42 2009
ALTER DATABASE RECOVER MANAGED STANDBY DATABASE FINISH FORCE
Terminal Recovery: Stopping real time apply
Sun Aug 30 17:03:42 2009
MRP0: Background Media Recovery cancelled with status 16037
Errors in file /u01/app/oracle/diag/rdbms/orcl_stdby1/orcl_stdby1/trace/orcl_stdby1_mrp0_5469.trc:
ORA-16037: user requested cancel of managed recovery operation
Managed Standby Recovery not using Real Time Apply
Shutting down recovery slaves due to error 16037
Recovery interrupted!
Recovered data files to a consistent state at change 5078856
Errors in file /u01/app/oracle/diag/rdbms/orcl_stdby1/orcl_stdby1/trace/orcl_stdby1_mrp0_5469.trc:
ORA-16037: user requested cancel of managed recovery operation
MRP0: Background Media Recovery process shutdown (orcl_stdby1)
Waiting for MRP0 pid 5469 to terminate
Terminal Recovery: Stopped real time apply
Attempt to do a Terminal Recovery (orcl_stdby1)
Media Recovery Start: Managed Standby Recovery (orcl_stdby1)
Fast Parallel Media Recovery enabled
Managed Standby Recovery not using Real Time Apply
Media Recovery Waiting for thread 1 sequence 19 (in transit)
tkcrrxms: Killing 4 processes (all RFS)
Terminal Recovery timestamp is '08/30/2009 17:03:46'
Terminal Recovery: applying standby redo logs.
Terminal Recovery: thread 1 seq# 19 redo required
Terminal Recovery: 
Recovery of Online Redo Log: Thread 1 Group 5 Seq 19 Reading mem 0
  Mem# 0: /u01/app/oracle/oradata/stdby/srl02.log
Identified End-Of-Redo for thread 1 sequence 19
Incomplete recovery applied all redo ever generated.
Recovery completed through change 5078858 time 08/30/2009 17:00:22
Media Recovery Complete (orcl_stdby1)
Terminal Recovery: successful completion
Resetting standby activation ID 1223590068 (0x48ee80b4)
Completed: ALTER DATABASE RECOVER MANAGED STANDBY DATABASE FINISH FORCE
ALTER DATABASE COMMIT TO SWITCHOVER TO PRIMARY WAIT WITH SESSION SHUTDOWN
ALTER DATABASE SWITCHOVER TO PRIMARY (orcl_stdby1)
Maximum wait for role transition is 15 minutes.
Sun Aug 30 17:03:47 2009
ARC2: Waiting for instance close to complete
All dispatchers and shared servers shutdown
Active process 12629 user 'oracle' program 'oracle@11gStdby'
Active process 12377 user 'oracle' program 'oracle@11gStdby'
Active process 11864 user 'oracle' program 'oracle@11gStdby (TNS V1-V3)'
Active process 8243 user 'oracle' program 'oracle@11gStdby'
Active process 11185 user 'oracle' program 'oracle@11gStdby (TNS V1-V3)'
Active process 5452 user 'oracle' program 'oracle@11gStdby (TNS V1-V3)'
CLOSE: waiting for server sessions to complete.
CLOSE: all sessions shutdown successfully.
Sun Aug 30 17:03:51 2009
SMON: disabling cache recovery
Backup controlfile written to trace file /u01/app/oracle/diag/rdbms/orcl_stdby1/orcl_stdby1/trace/orcl_stdby1_rsm0_5467.trc
ARC2: Wait for instance close completed
Standby terminal recovery start SCN: 5078856
RESETLOGS after complete recovery through change 5078858
Sun Aug 30 17:03:52 2009
idle dispatcher 'D000' terminated, pid = (16, 1)
Online log /u01/app/oracle/oradata/stdby/redo01.log: Thread 1 Group 1 was previously cleared
Online log /u01/app/oracle/oradata/stdby/redo02.log: Thread 1 Group 2 was previously cleared
Online log /u01/app/oracle/oradata/stdby/redo03.log: Thread 1 Group 3 was previously cleared
Standby became primary SCN: 5078855
Sun Aug 30 17:03:52 2009
Setting recovery target incarnation to 8
Converting standby mount to primary mount.
Switchover: Complete - Database mounted as primary (orcl_stdby1)
Completed: ALTER DATABASE COMMIT TO SWITCHOVER TO PRIMARY WAIT WITH SESSION SHUTDOWN
Sun Aug 30 17:03:52 2009
ARC3: STARTING ARCH PROCESSES
Sun Aug 30 17:03:53 2009
ALTER DATABASE OPEN
. . .
<< Edited for sake of brevity >>
. . .
Sun Aug 30 17:04:40 2009
Completed: ALTER DATABASE OPEN
Sun Aug 30 17:04:40 2009
Shutting down archive processes
ALTER SYSTEM SET log_archive_dest_1='location="/u01/app/oracle/flash_recovery_area/STDBY/"','valid_for=(ALL_LOGFILES,ALL_ROLES)' SCOPE=BOTH SID='orcl_stdby1';
ALTER SYSTEM SET log_archive_dest_state_1='ENABLE' SCOPE=BOTH SID='orcl_stdby1';
ALTER SYSTEM SET log_archive_trace=0 SCOPE=BOTH SID='orcl_stdby1';
ALTER SYSTEM SET log_archive_format='log_%s_%t_%r.arc' SCOPE=SPFILE SID='orcl_stdby1';
Sun Aug 30 17:04:45 2009
ARCH shutting down
ARC4: Archival stopped
ALTER SYSTEM SET standby_file_management='AUTO' SCOPE=BOTH SID='*';
ALTER SYSTEM SET archive_lag_target=0 SCOPE=BOTH SID='*';
ALTER SYSTEM SET log_archive_max_processes=4 SCOPE=BOTH SID='*';
ALTER SYSTEM SET log_archive_min_succeed_dest=1 SCOPE=BOTH SID='*';
ALTER SYSTEM SET log_file_name_convert='/u01/app/oracle/oradata/orcl/','/u01/app/oracle/oradata/stdby/' SCOPE=SPFILE;
Sun Aug 30 17:04:45 2009
Failover succeeded. Primary database is now orcl_stdby1.
. . .

>> Original standby database Data Guard Broker Manager log entries:
. . .

DG 2009-08-30-17:03:21        0 2 0 Foreground: FSFO storing state flags=0x44021, version=302, obid=0x486f2408 (1215243272), threshold=180, laglim=30, obslim=30
DG 2009-08-30-17:03:41        0 2 0 DMON: Timeout posting message to site 1 after waited for 30 seconds. Killing NSV0 (pid=5454).
DG 2009-08-30-17:03:42  1012000 4 696266125 DMON: failed to forward op CTL_GET_STATUS to site orcl_primary with error ORA-16662
DG 2009-08-30-17:03:42        0 2 696266126 DMON: ENUM_DRC: success. (len = 777)
DG 2009-08-30-17:03:42        0 2 696266126 DMON: ENUM_DRC operation completed
DG 2009-08-30-17:03:42  1012000 4 696266125 DMON: Database orcl_stdby1 returned ORA-16662
DG 2009-08-30-17:03:42  1012000 4 696266125       for opcode = CTL_GET_STATUS, phase = NULL, req_id = 2.1.696266125
DG 2009-08-30-17:03:42  1012000 4 696266125 DMON: CTL_GET_STATUS operation completed
DG 2009-08-30-17:03:42  1000000 3 696266127 DMON: MON_PROPERTY operation completed
DG 2009-08-30-17:03:42  2000000 3 696266128 DMON: Entered rfm_get_chief_lock() for CTL_FAIL, reason 0
DG 2009-08-30-17:03:42  2000000 3 696266128 DMON: chief lock convert for failover
DG 2009-08-30-17:03:42  2001000 3 696266128 DMON: Beginning Failover to site orcl_stdby1
DG 2009-08-30-17:03:42  2001000 3 696266128 DMON: Notifying CRS to teardown database for FAILOVER
DG 2009-08-30-17:03:42        0 2 0 CLSR: clsr_dgb_teardown_database(): clsr_stop_dbservices() failed, rc = 184
.
DG 2009-08-30-17:03:42        0 2 0 CLSR: clsr_teardown_site(): clsr_dgb_teardown_database() failed, rc =  184
.
DG 2009-08-30-17:03:42        0 2 0 CLSR: clsr_teardown_site() failed, status = 184
.
DG 2009-08-30-17:03:42  2001000 3 696266128 CRS reports warning, continuing...
DG 2009-08-30-17:03:42  2001000 3 696266128 DMON: posting standby instances for FAILOVER phase 1
DG 2009-08-30-17:03:42  2001000 3 696266128 DMON: status from rfi_post_instances() for CTL_FAIL = ORA-00000
DG 2009-08-30-17:03:42  2001000 3 696266128 DMON: dispersing message to standbys for FAILOVER phase BEGIN
DG 2009-08-30-17:03:42        0 2 0 INSV: Received message for inter-instance publication
DG 2009-08-30-17:03:42        0 2 0       req ID 2.1.696266128, opcode CTL_FAIL, phase BEGIN, flags 5
DG 2009-08-30-17:03:42  2001000 3 696266128 DMON: Entered rfmfoexinst for phase 1
DG 2009-08-30-17:03:42        0 2 0 INSV: Reply received for message with
DG 2009-08-30-17:03:42        0 2 0       req ID 2.1.696266128, opcode CTL_FAIL, phase BEGIN
DG 2009-08-30-17:03:42  2001000 3 696266128 DMON: posting standby instances for FAILOVER phase 2
DG 2009-08-30-17:03:42  2001000 3 696266128 DMON: status from rfi_post_instances() for CTL_FAIL = ORA-00000
DG 2009-08-30-17:03:42  2001000 3 696266128 DMON: dispersing message to standbys for FAILOVER phase TEARDOWN
DG 2009-08-30-17:03:42        0 2 0 INSV: Received message for inter-instance publication
DG 2009-08-30-17:03:42        0 2 0       req ID 2.1.696266128, opcode CTL_FAIL, phase TEARDOWN, flags 5
DG 2009-08-30-17:03:42  2001000 3 696266128 DMON: Entered rfmfoexinst for phase 2
DG 2009-08-30-17:03:42        0 2 0 INSV: Reply received for message with
DG 2009-08-30-17:03:42        0 2 0       req ID 2.1.696266128, opcode CTL_FAIL, phase TEARDOWN
DG 2009-08-30-17:03:42  2001000 3 696266128 DMON: posting standby instances for FAILOVER phase 2
DG 2009-08-30-17:03:42  2001000 3 696266128 DMON: status from rfi_post_instances() for CTL_FAIL = ORA-00000
DG 2009-08-30-17:03:42  2001000 3 696266128 DMON: dispersing message to standbys for FAILOVER phase TEARDOWN
DG 2009-08-30-17:03:42        0 2 0 INSV: Received message for inter-instance publication
DG 2009-08-30-17:03:42        0 2 0       req ID 2.1.696266128, opcode CTL_FAIL, phase TEARDOWN, flags 5
DG 2009-08-30-17:03:42  2001000 3 696266128 DMON: Entered rfmfoexinst for phase 2
DG 2009-08-30-17:03:42        0 2 0 RSM 0 received SETSTATE request: rid=0x02031000, sid=0, phid=1, econd=6, sitehndl=0x02001000
DG 2009-08-30-17:03:42        0 2 0 Redo Apply Resource: SetState OFFLINE, phase TEAR-DOWN, External Cond GRACEFUL-FAIL-OVER-PHYS_STBY
DG 2009-08-30-17:03:42        0 2 0 RSM 0 received SETSTATE request: rid=0x02013000, sid=9, phid=1, econd=6, sitehndl=0x02001000
DG 2009-08-30-17:03:42        0 2 0 Database Resource[IAM=PHYSICAL]: SetState READ-WRITE-XPTON, phase TEAR-DOWN, External Cond GRACEFUL-FAIL-OVER-PHYS_STBY, Target Site Handle 0x02001000
DG 2009-08-30-17:03:42        0 2 0 Executing SQL [ALTER DATABASE RECOVER MANAGED STANDBY DATABASE FINISH FORCE]
DG 2009-08-30-17:03:43        0 2 696266131 DMON: MON_PROPERTY operation completed
DG 2009-08-30-17:03:43        0 2 696266132 DMON: GET_DRC: success. (len = 241)
DG 2009-08-30-17:03:43        0 2 696266132 DMON: GET_DRC operation completed
DG 2009-08-30-17:03:43  1000000 3 696266133 DMON: GET_SITE: success. (len = 343)
DG 2009-08-30-17:03:43  1000000 3 696266133 DMON: GET_SITE operation completed
DG 2009-08-30-17:03:43  2000000 3 696266134 DMON: GET_SITE: success. (len = 337)
DG 2009-08-30-17:03:43  2000000 3 696266134 DMON: GET_SITE operation completed
DG 2009-08-30-17:03:46        0 2 0 SQL [ALTER DATABASE RECOVER MANAGED STANDBY DATABASE FINISH FORCE] Executed successfully
DG 2009-08-30-17:03:46        0 2 0 Executing SQL [ALTER DATABASE COMMIT TO SWITCHOVER TO PRIMARY WAIT WITH SESSION SHUTDOWN]
DG 2009-08-30-17:03:51        0 2 0 Notify DMON of db close
DG 2009-08-30-17:03:52        0 2 0 SQL [ALTER DATABASE COMMIT TO SWITCHOVER TO PRIMARY WAIT WITH SESSION SHUTDOWN] Executed successfully
DG 2009-08-30-17:03:52        0 2 0 RSM: refreshing IncarnationTable internal property. New value is '8,5078859,696272632,7*7,5050220,695847608,5#6,5045967,694880645,5#5,4970489,693763762,2#4,4957899,692911765,2#3,4458754,692737822,2#2,522753,682541003,1#1,1,629600782,0#'
DG 2009-08-30-17:03:52        0 2 0 Database Resource SetState succeeded
DG 2009-08-30-17:03:52        0 2 0 INSV: Reply received for message with
DG 2009-08-30-17:03:52        0 2 0       req ID 2.1.696266128, opcode CTL_FAIL, phase TEARDOWN
DG 2009-08-30-17:03:52        0 2 0 Adding RC Block to site 0x01001000
DG 2009-08-30-17:03:52  2001000 3 696266128 DMON: Evaluating critical status of standbys in configuration
DG 2009-08-30-17:03:52  2001000 3 696266128 DMON: Evaluating critical status of 0x2010000
DG 2009-08-30-17:03:52  2001000 3 696266128         ChangeCritical value is FALSE
DG 2009-08-30-17:03:52  2001000 3 696266128         IsCritical value is FALSE
DG 2009-08-30-17:03:52        0 2 0 DMON: Failover - updated MIV to 103 (2.1.696266128), writing metadata to "/u01/app/oracle/product/11.1.0/db_1/dbs/dr1orcl_stdby1.dat"
DG 2009-08-30-17:03:53  2001000 3 696266128 DMON: posting primary instances for FAILOVER phase 3
DG 2009-08-30-17:03:53        0 2 0 INSV: Received message for inter-instance publication
DG 2009-08-30-17:03:53        0 2 0       req ID 2.1.696266128, opcode CTL_FAIL, phase RESYNCH, flags 5
DG 2009-08-30-17:03:53  2001000 3 696266128 DMON: status from rfi_post_instances() for CTL_FAIL = ORA-00000
DG 2009-08-30-17:03:53  2001000 3 696266128 DMON: dispersing message to standbys for FAILOVER phase RESYNCH
DG 2009-08-30-17:03:53        0 2 0 INSV: Reply received for message with
DG 2009-08-30-17:03:53        0 2 0       req ID 2.1.696266128, opcode CTL_FAIL, phase RESYNCH
DG 2009-08-30-17:03:53        0 2 0 DMON: FSFO configuration is lagging
DG 2009-08-30-17:03:53        0 2 0 DMON: FSFO storing state flags=0x46021, version=304, obid=0x486f2408 (1215243272), threshold=180, laglim=30, obslim=30
DG 2009-08-30-17:03:53        0 2 0 DMON: FSFO storing state flags=0x146021, version=304, obid=0x486f2408 (1215243272), threshold=180, laglim=30, obslim=30
DG 2009-08-30-17:03:53        0 2 0 Update Failover Conditions (CTL_FAIL)
DG 2009-08-30-17:03:53  2001000 3 696266128 DMON: posting primary instances for FAILOVER phase 4
DG 2009-08-30-17:03:53  2001000 3 696266128 DMON: status from rfi_post_instances() for CTL_FAIL = ORA-00000
DG 2009-08-30-17:03:53  2001000 3 696266128 DMON: dispersing message to standbys for FAILOVER phase BUILDUP
DG 2009-08-30-17:03:53        0 2 0 INSV: Received message for inter-instance publication
DG 2009-08-30-17:03:53        0 2 0       req ID 2.1.696266128, opcode CTL_FAIL, phase BUILDUP, flags 5
DG 2009-08-30-17:03:53  2001000 3 696266128 DMON: Entered rfmfoexinst for phase 4
DG 2009-08-30-17:03:53        0 2 0 RSM 0 received SETSTATE request: rid=0x02012000, sid=9, phid=2, econd=6, sitehndl=0x02001000
DG 2009-08-30-17:03:53        0 2 0 Database Resource[IAM=PRIMARY]: SetState READ-WRITE-XPTON, phase BUILD-UP, External Cond GRACEFUL-FAIL-OVER-PHYS_STBY, Target Site Handle 0x02001000
DG 2009-08-30-17:03:53        0 2 0 Set log transport destination: SetState ONLINE, phase BUILD-UP, External Cond GRACEFUL-FAIL-OVER-PHYS_STBY
DG 2009-08-30-17:03:53        0 2 0 Executing SQL [ALTER DATABASE OPEN]
DG 2009-08-30-17:03:57        0 2 0 DMON: Creating process FSFP
DG 2009-08-30-17:04:00        0 2 0 FSFP: Process started
DG 2009-08-30-17:04:00        0 2 0 DMON: FSFP successfully started
DG 2009-08-30-17:04:40        0 2 0 SQL [ALTER DATABASE OPEN] Executed successfully
DG 2009-08-30-17:04:40        0 2 0 RSM: DRC's protection mode is 'MaxPerformance'
DG 2009-08-30-17:04:40        0 2 0 RSM: protection mode set to MAXIMUM PERFORMANCE
DG 2009-08-30-17:04:40        0 2 0 Executing SQL [ALTER SYSTEM SET log_archive_dest_1='location="/u01/app/oracle/flash_recovery_area/STDBY/"', 'valid_for=(ALL_LOGFILES,ALL_ROLES)' scope=both sid='orcl_stdby1' ]
DG 2009-08-30-17:04:40        0 2 0 SQL [ALTER SYSTEM SET log_archive_dest_1='location="/u01/app/oracle/flash_recovery_area/STDBY/"', 'valid_for=(ALL_LOGFILES,ALL_ROLES)' scope=both sid='orcl_stdby1' ] Executed successfully
DG 2009-08-30-17:04:40        0 2 0 Executing SQL [ALTER SYSTEM SET log_archive_dest_state_1='ENABLE' SCOPE=BOTH sid='orcl_stdby1']
DG 2009-08-30-17:04:40        0 2 0 SQL [ALTER SYSTEM SET log_archive_dest_state_1='ENABLE' SCOPE=BOTH sid='orcl_stdby1'] Executed successfully
DG 2009-08-30-17:04:40        0 2 0 Setting init.ora parameter with SQL [ALTER SYSTEM SET log_archive_trace=0 SCOPE=BOTH sid='orcl_stdby1']
DG 2009-08-30-17:04:40        0 2 0 Executing SQL [ALTER SYSTEM SET log_archive_trace=0 SCOPE=BOTH sid='orcl_stdby1']
DG 2009-08-30-17:04:40        0 2 0 SQL [ALTER SYSTEM SET log_archive_trace=0 SCOPE=BOTH sid='orcl_stdby1'] Executed successfully
DG 2009-08-30-17:04:40        0 2 0 Setting init.ora parameter with SQL [ALTER SYSTEM SET log_archive_format='log_%s_%t_%r.arc' SCOPE=SPFILE sid='orcl_stdby1']
DG 2009-08-30-17:04:40        0 2 0 Executing SQL [ALTER SYSTEM SET log_archive_format='log_%s_%t_%r.arc' SCOPE=SPFILE sid='orcl_stdby1']
DG 2009-08-30-17:04:40        0 2 0 SQL [ALTER SYSTEM SET log_archive_format='log_%s_%t_%r.arc' SCOPE=SPFILE sid='orcl_stdby1'] Executed successfully
DG 2009-08-30-17:04:40        0 2 0 Setting init.ora parameter with SQL [ALTER SYSTEM SET standby_file_management='AUTO' SCOPE=BOTH sid='*']
DG 2009-08-30-17:04:40        0 2 0 Executing SQL [ALTER SYSTEM SET standby_file_management='AUTO' SCOPE=BOTH sid='*']
DG 2009-08-30-17:04:45        0 2 0 SQL [ALTER SYSTEM SET standby_file_management='AUTO' SCOPE=BOTH sid='*'] Executed successfully
DG 2009-08-30-17:04:45        0 2 0 Setting init.ora parameter with SQL [ALTER SYSTEM SET archive_lag_target=0 SCOPE=BOTH sid='*']
DG 2009-08-30-17:04:45        0 2 0 Executing SQL [ALTER SYSTEM SET archive_lag_target=0 SCOPE=BOTH sid='*']
DG 2009-08-30-17:04:45        0 2 0 SQL [ALTER SYSTEM SET archive_lag_target=0 SCOPE=BOTH sid='*'] Executed successfully
DG 2009-08-30-17:04:45        0 2 0 Setting init.ora parameter with SQL [ALTER SYSTEM SET log_archive_max_processes=4 SCOPE=BOTH sid='*']
DG 2009-08-30-17:04:45        0 2 0 Executing SQL [ALTER SYSTEM SET log_archive_max_processes=4 SCOPE=BOTH sid='*']
DG 2009-08-30-17:04:45        0 2 0 SQL [ALTER SYSTEM SET log_archive_max_processes=4 SCOPE=BOTH sid='*'] Executed successfully
DG 2009-08-30-17:04:45        0 2 0 Setting init.ora parameter with SQL [ALTER SYSTEM SET log_archive_min_succeed_dest=1 SCOPE=BOTH sid='*']
DG 2009-08-30-17:04:45        0 2 0 Executing SQL [ALTER SYSTEM SET log_archive_min_succeed_dest=1 SCOPE=BOTH sid='*']
DG 2009-08-30-17:04:45        0 2 0 SQL [ALTER SYSTEM SET log_archive_min_succeed_dest=1 SCOPE=BOTH sid='*'] Executed successfully
DG 2009-08-30-17:04:45        0 2 0 Setting init.ora parameter with SQL [ALTER SYSTEM SET log_file_name_convert="/u01/app/oracle/oradata/orcl/","/u01/app/oracle/oradata/stdby/" SCOPE=SPFILE]
DG 2009-08-30-17:04:45        0 2 0 Executing SQL [ALTER SYSTEM SET log_file_name_convert="/u01/app/oracle/oradata/orcl/","/u01/app/oracle/oradata/stdby/" SCOPE=SPFILE]
DG 2009-08-30-17:04:45        0 2 0 SQL [ALTER SYSTEM SET log_file_name_convert="/u01/app/oracle/oradata/orcl/","/u01/app/oracle/oradata/stdby/" SCOPE=SPFILE] Executed successfully
DG 2009-08-30-17:04:45        0 2 0 Database Resource SetState succeeded
DG 2009-08-30-17:04:45        0 2 0 RSM 0 received SETSTATE request: rid=0x02041000, sid=1, phid=2, econd=6, sitehndl=0x02001000
DG 2009-08-30-17:04:45        0 2 0 Log Transport Resource: SetState ONLINE, phase BUILD-UP, External Cond GRACEFUL-FAIL-OVER-PHYS_STBY
DG 2009-08-30-17:04:45        0 2 0 INSV: Reply received for message with
DG 2009-08-30-17:04:45        0 2 0       req ID 2.1.696266128, opcode CTL_FAIL, phase BUILDUP
DG 2009-08-30-17:04:45  2001000 3 696266128 DMON: Deferring associated archivelog destinations of
DG 2009-08-30-17:04:45  2001000 3 696266128       sites permanently disabled due to Failover
DG 2009-08-30-17:04:45        0 2 0 RSM: Site 01001000 archivelog destination deferred
DG 2009-08-30-17:04:45  2001000 3 696266128 DMON: Notifying CRS to buildup primary database after FAILOVER
DG 2009-08-30-17:04:45        0 2 0 CLSR: clsr_dbg_buildup_database(): prsr_init() failed, rc = 3
.
DG 2009-08-30-17:04:45        0 2 0 CLSR: clsr_dbg_buildup_database(): failed, rc = 184
.
DG 2009-08-30-17:04:45        0 2 0 CLSR: clsr_buildup_site(): clsr_dgb_buildup_database() failed, rc =  184
.
DG 2009-08-30-17:04:45        0 2 0 CLSR: clsr_buildup_site() failed, status = 184
.
DG 2009-08-30-17:04:45  2001000 3 696266128 DMON: CRS operation not successful. See related messages.
DG 2009-08-30-17:04:45  2001000 3 696266128 DMON: Posting DB_DOWN alert ...
DG 2009-08-30-17:04:45        0 2 0         ... with reason Data Guard Fast-Start Failover - Primary Disconnected
DG 2009-08-30-17:04:45  2001000 3 696266128 DMON: posting primary instances for FAILOVER phase 5
DG 2009-08-30-17:04:45  2001000 3 696266128 DMON: status from rfi_post_instances() for CTL_FAIL = ORA-00000
DG 2009-08-30-17:04:45        0 2 0 INSV: Received message for inter-instance publication
DG 2009-08-30-17:04:45        0 2 0       req ID 2.1.696266128, opcode CTL_FAIL, phase END, flags 5
DG 2009-08-30-17:04:45  2001000 3 696266128 DMON: FAILOVER Complete
DG 2009-08-30-17:04:45  2001000 3 696266128 New Primary Site is named: orcl_stdby1
DG 2009-08-30-17:04:45  2001000 3 696266128 DMON: dispersing message to standbys for FAILOVER phase END
. . .

>> Original primary database alert log entries:

Thread 1 advanced to log sequence 19
  Current log# 3 seq# 19 mem# 0: /u01/app/oracle/oradata/orcl/redo03.log
Sun Aug 30 16:56:11 2009
LNS: Standby redo logfile selected for thread 1 sequence 19 for destination LOG_ARCHIVE_DEST_2
Sun Aug 30 17:00:56 2009
Fast-Start Failover reconfiguration in progress.
Sun Aug 30 17:01:15 2009
FSFP started with pid=47, OS id=32256 


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

Fatal NI connect error 12532, connecting to:
 (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=11gStdby)(PORT=1521))(CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=orcl_stdby1_DGB)(INSTANCE_NAME=orcl_stdby1)(CID=(PROGRAM=oracle)(HOST=11gPrimary)(USER=oracle))))

  VERSION INFORMATION:
	TNS for Linux: Version 11.1.0.6.0 - Production
	TCP/IP NT Protocol Adapter for Linux: Version 11.1.0.6.0 - Production
  Time: 30-AUG-2009 17:01:18
  Tracing not turned on.
  Tns error struct:
    ns main err code: 12532
    
TNS-12532: TNS:invalid argument
    ns secondary err code: 12560
    nt main err code: 502
    
TNS-00502: Invalid argument
    nt secondary err code: 113
    nt OS err code: 0


***********************************************************************
. . .
<< Several iterations of same error message have been removed for sake of brevity >>
. . .
Sun Aug 30 17:04:05 2009
Primary has heard from neither observer nor target standby within FastStartFailoverThreshold seconds.
It is likely an automatic failover has already occurred.Primary is shutting down.
Errors in file /u01/app/oracle/diag/rdbms/orcl_primary/orcl_primary/trace/orcl_primary_lgwr_8299.trc:
ORA-16830: primary isolated from fast-start failover partners longer than FastStartFailoverThreshold seconds: shutting down
LGWR (ospid: 8299): terminating the instance due to error 16830
Instance terminated by LGWR, pid = 8299


>> Original primary database Data Guard Broker Manager log entries:
. . .
DG 2009-08-30-17:00:50        0 2 0 LGWR: FSFO lagging by 31; pmy=08/30/2009 17:00:50 sby=08/30/2009 17:00:19
DG 2009-08-30-17:00:50        0 2 0 LGWR: FSFO SetState operation requires an ack
DG 2009-08-30-17:00:59        0 2 0 DMON: FSFP network call timeout.
DG 2009-08-30-17:00:59        0 2 0 DMON: Killing process FSFP.
DG 2009-08-30-17:01:14        0 2 0 DMON: Creating process FSFP
DG 2009-08-30-17:01:18        0 2 0 FSFP: Process started
DG 2009-08-30-17:01:18        0 2 0 FSFP: Failed to connect to remote database orcl_stdby1. Error is ORA-12532
DG 2009-08-30-17:01:19        0 2 0 DMON: FSFP successfully started
DG 2009-08-30-17:01:19        0 2 696266285 DMON: ORA-16662 network timeout in contacting database orcl_stdby1. Killing NSV1
DG 2009-08-30-17:01:20        0 2 696266285 DMON: Database orcl_stdby1 returned ORA-16662
DG 2009-08-30-17:01:20        0 2 696266285       for opcode = CTL_GET_STATUS, phase = BEGIN, req_id = 1.1.696266285
DG 2009-08-30-17:01:21        0 2 0 FSFP: Failed to connect to remote database orcl_stdby1. Error is ORA-12532
DG 2009-08-30-17:01:39        0 2 0 FSFP: Failed to connect to remote database orcl_stdby1. Error is ORA-12532
DG 2009-08-30-17:01:42        0 2 0 FSFP: Failed to connect to remote database orcl_stdby1. Error is ORA-12532
DG 2009-08-30-17:02:01        0 2 0 FSFP: Failed to connect to remote database orcl_stdby1. Error is ORA-12532
DG 2009-08-30-17:02:04        0 2 0 FSFP: Failed to connect to remote database orcl_stdby1. Error is ORA-12532
DG 2009-08-30-17:03:25        0 2 0 DMON: NSV1 network call timeout. Kill it.
DG 2009-08-30-17:03:26        0 2 0 FSFP: Failed to connect to remote database orcl_stdby1. Error is ORA-12532
DG 2009-08-30-17:03:29        0 2 0 FSFP: Failed to connect to remote database orcl_stdby1. Error is ORA-12532
DG 2009-08-30-17:03:30        0 2 0 RSM0: HEALTH CHECK WARNING: ORA-16829: fast-start failover configuration is lagging
DG 2009-08-30-17:03:30        0 2 0 RSM0: HEALTH CHECK ERROR: ORA-16820: fast-start failover observer is no longer observing this database
DG 2009-08-30-17:03:30        0 2 696266288 Operation CTL_GET_STATUS canceled during phase 2, error = ORA-16825
DG 2009-08-30-17:03:30        0 2 696266288 Operation CTL_GET_STATUS canceled during phase 2, error = ORA-16825
DG 2009-08-30-17:03:33        0 2 0 NSV1: Failed to connect to remote database orcl_stdby1. Error is ORA-12532
DG 2009-08-30-17:03:33        0 2 0 NSV1: Failed to send message to site orcl_stdby1. Error code is ORA-12532.
DG 2009-08-30-17:03:33        0 2 696266288 DMON: Database orcl_stdby1 returned ORA-12532
DG 2009-08-30-17:03:33        0 2 696266288       for opcode = CTL_GET_STATUS, phase = BEGIN, req_id = 1.1.696266288
DG 2009-08-30-17:03:35        0 2 696266291 DMON: MON_PROPERTY operation completed
DG 2009-08-30-17:03:35        0 2 696266292 DMON: GET_DRC: success. (len = 241)
DG 2009-08-30-17:03:35        0 2 696266292 DMON: GET_DRC operation completed
DG 2009-08-30-17:03:35  1000000 3 696266293 DMON: GET_SITE: success. (len = 343)
DG 2009-08-30-17:03:35  1000000 3 696266293 DMON: GET_SITE operation completed
DG 2009-08-30-17:03:35  2000000 3 696266294 DMON: GET_SITE: success. (len = 337)
DG 2009-08-30-17:03:35  2000000 3 696266294 DMON: GET_SITE operation completed
DG 2009-08-30-17:03:35  1000000 3 696266295 DMON: MON_PROPERTY operation completed
DG 2009-08-30-17:03:35  1012000 4 696266296 DMON: MON_PROPERTY operation completed
DG 2009-08-30-17:03:35  1012000 4 696266297 DMON: MON_PROPERTY operation completed
DG 2009-08-30-17:03:35  1012000 4 696266298 DMON: MON_PROPERTY operation completed
DG 2009-08-30-17:03:35  1012000 4 696266299 DMON: CTL_GET_STATUS operation completed
DG 2009-08-30-17:03:35  2000000 3 696266300 DMON: MON_PROPERTY operation completed
DG 2009-08-30-17:03:35  2013000 4 696266301 DMON: MON_PROPERTY operation completed
DG 2009-08-30-17:03:35  2013000 4 696266302 DMON: MON_PROPERTY operation completed
DG 2009-08-30-17:03:35  2013000 4 696266303 DMON: MON_PROPERTY operation completed
DG 2009-08-30-17:03:35  2013000 4 696266304 DMON: CTL_GET_STATUS operation completed
DG 2009-08-30-17:03:47        0 2 0 FSFP: Failed to connect to remote database orcl_stdby1. Error is ORA-12532
DG 2009-08-30-17:03:50        0 2 0 FSFP: Failed to connect to remote database orcl_stdby1. Error is ORA-12532
DG 2009-08-30-17:04:05        0 2 0 LGWR: Notifying CRS to disable services and monitoring for Primary Shutdown on Failover
DG 2009-08-30-17:04:05        0 2 0 LGWR: Notifying CRS to teardown database
. . .

/* 
|| Listing 7.2:
|| Reinstating the original primary database after it has been successfully
|| failed over to the original physical standby database
*/

>> Original primary database alert log entries:

Sun Aug 30 17:21:20 2009
Starting ORACLE instance (normal)
LICENSE_MAX_SESSION = 0
LICENSE_SESSIONS_WARNING = 0
Picked latch-free SCN scheme 2
Autotune of undo retention is turned on. 
IMODE=BR
ILAT =18
LICENSE_MAX_USERS = 0
SYS auditing is disabled
Starting up ORACLE RDBMS Version: 11.1.0.6.0.
Using parameter settings in server-side spfile /u01/app/oracle/product/11.1.0/db_1/dbs/spfileorcl_primary.ora
System parameters with non-default values:
  processes                = 150
  sga_target               = 400M
  control_files            = "/u01/app/oracle/oradata/orcl/control01.ctl"
  control_files            = "/u01/app/oracle/oradata/orcl/control02.ctl"
  control_files            = "/u01/app/oracle/oradata/orcl/control03.ctl"
  db_block_size            = 8192
  compatible               = "11.1.0.0.0"
  log_archive_config       = "dg_config=(orcl_stdby1)"
  log_archive_dest_1       = "location="/u01/app/oracle/flash_recovery_area/ORCL/""
  log_archive_dest_1       = "valid_for=(ALL_LOGFILES,ALL_ROLES)"
  log_archive_dest_2       = "service="orcl_stdby1""
  log_archive_dest_2       = "   LGWR ASYNC NOAFFIRM delay=0 OPTIONAL compression=DISABLE max_failure=0 max_connections=1   reopen=300 db_unique_name="orcl_stdby1" net_timeout=30  valid_for=(online_logfile,primary_role)"
  log_archive_dest_state_1 = "ENABLE"
  log_archive_dest_state_2 = "ENABLE"
  log_archive_max_processes= 4
  log_archive_min_succeed_dest= 1
  log_archive_trace        = 0
  log_archive_format       = "log_%s_%t_%r.arc"
  fal_client               = "orcl_primary"
  fal_server               = "orcl_stdby1"
  archive_lag_target       = 0
  db_recovery_file_dest    = "/u01/app/oracle/flash_recovery_area"
  db_recovery_file_dest_size= 8G
  standby_file_management  = "AUTO"
  undo_tablespace          = "UNDOTBS1"
  sec_case_sensitive_logon = FALSE
  remote_login_passwordfile= "EXCLUSIVE"
  db_domain                = ""
  dispatchers              = "(PROTOCOL=TCP) (SERVICE=orclXDB)"
  audit_file_dest          = "/u01/app/oracle/admin/orcl/adump"
  audit_trail              = "DB"
  db_name                  = "orcl"
  db_unique_name           = "orcl_primary"
  open_cursors             = 300
  pga_aggregate_target     = 150M
  dg_broker_start          = TRUE
  dg_broker_config_file1   = "/u01/app/oracle/product/11.1.0/db_1/dbs/dr1orcl_primary.dat"
  dg_broker_config_file2   = "/u01/app/oracle/product/11.1.0/db_1/dbs/dr2orcl_primary.dat"
  diagnostic_dest          = "/u01/app/oracle"
Sun Aug 30 17:21:22 2009
PMON started with pid=2, OS id=3460 
Sun Aug 30 17:21:22 2009
VKTM started with pid=3, OS id=3462 at elevated priority
VKTM running at (20)ms precision
Sun Aug 30 17:21:23 2009
PSP0 started with pid=6, OS id=3470 
Sun Aug 30 17:21:23 2009
DIAG started with pid=4, OS id=3466 
Sun Aug 30 17:21:23 2009
DBRM started with pid=5, OS id=3468 
Sun Aug 30 17:21:24 2009
DSKM started with pid=7, OS id=3472 
Sun Aug 30 17:21:24 2009
DIA0 started with pid=8, OS id=3474 
Sun Aug 30 17:21:24 2009
MMAN started with pid=7, OS id=3476 
Sun Aug 30 17:21:24 2009
DBW0 started with pid=9, OS id=3478 
Sun Aug 30 17:21:25 2009
LGWR started with pid=10, OS id=3480 
Sun Aug 30 17:21:25 2009
CKPT started with pid=11, OS id=3482 
Sun Aug 30 17:21:25 2009
SMON started with pid=12, OS id=3484 
Sun Aug 30 17:21:25 2009
RECO started with pid=13, OS id=3486 
starting up 1 dispatcher(s) for network address '(ADDRESS=(PARTIAL=YES)(PROTOCOL=TCP))'...
Sun Aug 30 17:21:26 2009
MMNL started with pid=15, OS id=3491 
Sun Aug 30 17:21:26 2009
MMON started with pid=14, OS id=3489 
starting up 1 shared server(s) ...
ORACLE_BASE from environment = /u01/app/oracle
Sun Aug 30 17:21:26 2009
ALTER DATABASE   MOUNT
Sun Aug 30 17:21:27 2009
DMON started with pid=18, OS id=3498 
Setting recovery target incarnation to 4
Successful mount of redo thread 1, with mount id 1224091033
Allocated 3981204 bytes in shared pool for flashback generation buffer
Starting background process RVWR
Sun Aug 30 17:21:34 2009
RVWR started with pid=20, OS id=3505 
Database mounted in Exclusive Mode
Lost write protection disabled
Completed: ALTER DATABASE   MOUNT
Starting Data Guard Broker (DMON)
Sun Aug 30 17:21:35 2009
FSFP started with pid=21, OS id=3508 
Sun Aug 30 17:21:39 2009
NSV1 started with pid=24, OS id=3518 
Sun Aug 30 17:21:43 2009
INSV started with pid=23, OS id=3578 
Sun Aug 30 17:21:47 2009
ALTER SYSTEM SET log_archive_dest_state_2='RESET' SCOPE=BOTH;
Sun Aug 30 17:22:10 2009
Using STANDBY_ARCHIVE_DEST parameter default value as /u01/app/oracle/flash_recovery_area/ORCL/
Redo Shipping Client Connected as PUBLIC
-- Connected User is Valid
RFS[1]: Assigned to RFS process 3639
RFS[1]: Database mount ID mismatch [0x48f61941:0x48f62599] (1224087873:1224091033)
RFS[1]: Not using real application clusters
Errors in file /u01/app/oracle/diag/rdbms/orcl_primary/orcl_primary/trace/orcl_primary_rfs_3639.trc:
ORA-16009: remote archive log destination must be a STANDBY database
Sun Aug 30 17:22:37 2009
NSV1 started with pid=25, OS id=3756 
Sun Aug 30 17:22:42 2009
RSM0 started with pid=27, OS id=3771 
FLASHBACK DATABASE TO SCN 5078855
Flashback Restore Start
Flashback Restore Complete
Flashback Media Recovery Start
Fast Parallel Media Recovery NOT enabled
Recovery of Online Redo Log: Thread 1 Group 2 Seq 18 Reading mem 0
  Mem# 0: /u01/app/oracle/oradata/orcl/redo02.log
Recovery of Online Redo Log: Thread 1 Group 3 Seq 19 Reading mem 0
  Mem# 0: /u01/app/oracle/oradata/orcl/redo03.log
Incomplete Recovery applied until change 5078856 time 08/30/2009 17:00:21
Flashback Media Recovery Complete
Completed: FLASHBACK DATABASE TO SCN 5078855
alter database convert to physical standby
ALTER DATABASE CONVERT TO PHYSICAL STANDBY (orcl_primary)
Clearing standby activation ID 1223590068 (0x48ee80b4)
The primary database controlfile was created using the
'MAXLOGFILES 16' clause.
There is space for up to 13 standby redo logfiles
Use the following SQL commands on the standby database to create
standby redo logfiles that match the primary database:
ALTER DATABASE ADD STANDBY LOGFILE 'srl1.f' SIZE 52428800;
ALTER DATABASE ADD STANDBY LOGFILE 'srl2.f' SIZE 52428800;
ALTER DATABASE ADD STANDBY LOGFILE 'srl3.f' SIZE 52428800;
ALTER DATABASE ADD STANDBY LOGFILE 'srl4.f' SIZE 52428800;
Completed: alter database convert to physical standby
Sun Aug 30 17:22:52 2009
Shutting down instance: further logons disabled
Stopping background process MMNL
Stopping background process MMON
Shutting down instance (immediate)
License high water mark = 6
Waiting for dispatcher 'D000' to shutdown
Waiting for shared server 'S000' to die
Sun Aug 30 17:22:54 2009
ORA-1089 : opidrv aborting process unknown ospid (3882_3086882496)
All dispatchers and shared servers shutdown
alter database CLOSE NORMAL
ORA-1109 signalled during: alter database CLOSE NORMAL...
alter database DISMOUNT
Completed: alter database DISMOUNT
ARCH: Archival disabled due to shutdown: 1089
Shutting down archive processes
Archiving is disabled
Archive process shutdown avoided: 0 active
Shutting down Data Guard Broker processes
Sun Aug 30 17:22:58 2009
Completed: Data Guard Broker shutdown
ARCH: Archival disabled due to shutdown: 1089
Shutting down archive processes
Archiving is disabled
Sun Aug 30 17:22:59 2009
Stopping background process VKTM: 
Archive process shutdown avoided: 0 active
Sun Aug 30 17:23:02 2009
Instance shutdown complete
Sun Aug 30 17:23:20 2009
Starting ORACLE instance (normal)
LICENSE_MAX_SESSION = 0
LICENSE_SESSIONS_WARNING = 0
Picked latch-free SCN scheme 2
Autotune of undo retention is turned on. 
IMODE=BR
ILAT =18
LICENSE_MAX_USERS = 0
SYS auditing is disabled
Starting up ORACLE RDBMS Version: 11.1.0.6.0.
Using parameter settings in server-side spfile /u01/app/oracle/product/11.1.0/db_1/dbs/spfileorcl_primary.ora
System parameters with non-default values:
  processes                = 150
  sga_target               = 400M
  control_files            = "/u01/app/oracle/oradata/orcl/control01.ctl"
  control_files            = "/u01/app/oracle/oradata/orcl/control02.ctl"
  control_files            = "/u01/app/oracle/oradata/orcl/control03.ctl"
  db_block_size            = 8192
  compatible               = "11.1.0.0.0"
  log_archive_config       = "dg_config=(orcl_stdby1)"
  log_archive_dest_1       = "location="/u01/app/oracle/flash_recovery_area/ORCL/""
  log_archive_dest_1       = "valid_for=(ALL_LOGFILES,ALL_ROLES)"
  log_archive_dest_2       = "service="orcl_stdby1""
  log_archive_dest_2       = "   LGWR ASYNC NOAFFIRM delay=0 OPTIONAL compression=DISABLE max_failure=0 max_connections=1   reopen=300 db_unique_name="orcl_stdby1" net_timeout=30  valid_for=(online_logfile,primary_role)"
  log_archive_dest_state_1 = "ENABLE"
  log_archive_dest_state_2 = "RESET"
  log_archive_max_processes= 4
  log_archive_min_succeed_dest= 1
  log_archive_trace        = 0
  log_archive_format       = "log_%s_%t_%r.arc"
  fal_client               = "orcl_primary"
  fal_server               = "orcl_stdby1"
  archive_lag_target       = 0
  db_recovery_file_dest    = "/u01/app/oracle/flash_recovery_area"
  db_recovery_file_dest_size= 8G
  standby_file_management  = "AUTO"
  undo_tablespace          = "UNDOTBS1"
  sec_case_sensitive_logon = FALSE
  remote_login_passwordfile= "EXCLUSIVE"
  db_domain                = ""
  dispatchers              = "(PROTOCOL=TCP) (SERVICE=orclXDB)"
  audit_file_dest          = "/u01/app/oracle/admin/orcl/adump"
  audit_trail              = "DB"
  db_name                  = "orcl"
  db_unique_name           = "orcl_primary"
  open_cursors             = 300
  pga_aggregate_target     = 150M
  dg_broker_start          = TRUE
  dg_broker_config_file1   = "/u01/app/oracle/product/11.1.0/db_1/dbs/dr1orcl_primary.dat"
  dg_broker_config_file2   = "/u01/app/oracle/product/11.1.0/db_1/dbs/dr2orcl_primary.dat"
  diagnostic_dest          = "/u01/app/oracle"
Sun Aug 30 17:23:23 2009
PMON started with pid=2, OS id=4075 
Sun Aug 30 17:23:23 2009
VKTM started with pid=3, OS id=4077 at elevated priority
VKTM running at (20)ms precision
Sun Aug 30 17:23:23 2009
DIAG started with pid=4, OS id=4081 
Sun Aug 30 17:23:23 2009
DBRM started with pid=5, OS id=4083 
Sun Aug 30 17:23:24 2009
PSP0 started with pid=6, OS id=4085 
Sun Aug 30 17:23:24 2009
DSKM started with pid=7, OS id=4087 
Sun Aug 30 17:23:24 2009
DIA0 started with pid=8, OS id=4089 
Sun Aug 30 17:23:24 2009
MMAN started with pid=7, OS id=4091 
Sun Aug 30 17:23:25 2009
DBW0 started with pid=9, OS id=4093 
Sun Aug 30 17:23:25 2009
LGWR started with pid=10, OS id=4095 
Sun Aug 30 17:23:25 2009
CKPT started with pid=11, OS id=4097 
Sun Aug 30 17:23:26 2009
SMON started with pid=12, OS id=4099 
Sun Aug 30 17:23:26 2009
RECO started with pid=13, OS id=4101 
starting up 1 dispatcher(s) for network address '(ADDRESS=(PARTIAL=YES)(PROTOCOL=TCP))'...
Sun Aug 30 17:23:26 2009
MMNL started with pid=15, OS id=4105 
Sun Aug 30 17:23:26 2009
MMON started with pid=14, OS id=4103 
starting up 1 shared server(s) ...
ORACLE_BASE from environment = /u01/app/oracle
Sun Aug 30 17:23:27 2009
DMON started with pid=18, OS id=4111 
Sun Aug 30 17:23:27 2009
ALTER DATABASE   MOUNT
Setting recovery target incarnation to 4
ARCH: STARTING ARCH PROCESSES
Sun Aug 30 17:23:34 2009
ARC0 started with pid=20, OS id=4120 
Sun Aug 30 17:23:34 2009
ARC1 started with pid=21, OS id=4122 
Sun Aug 30 17:23:34 2009
ARC2 started with pid=22, OS id=4124 
ARC0: Archival started
ARC1: Archival started
ARC2: Archival started
ARC3: Archival started
ARCH: STARTING ARCH PROCESSES COMPLETE
ARC1: Becoming the 'no FAL' ARCH
ARC1: Becoming the 'no SRL' ARCH
ARC0: Becoming the heartbeat ARCH
ARC1: Thread not mounted
ARC2: Thread not mounted
Sun Aug 30 17:23:34 2009
ARC3 started with pid=23, OS id=4126 
ARC3: Thread not mounted
ARC0: Thread not mounted
Successful mount of redo thread 1, with mount id 1224046609
Allocated 3981204 bytes in shared pool for flashback generation buffer
Starting background process RVWR
Sun Aug 30 17:23:34 2009
RVWR started with pid=24, OS id=4129 
Physical Standby Database mounted.
Lost write protection disabled
Completed: ALTER DATABASE   MOUNT
Starting Data Guard Broker (DMON)
Sun Aug 30 17:23:35 2009
INSV started with pid=25, OS id=4132 
Sun Aug 30 17:24:03 2009
NSV1 started with pid=28, OS id=4251 
Sun Aug 30 17:24:08 2009
RSM0 started with pid=29, OS id=4262 
Using STANDBY_ARCHIVE_DEST parameter default value as /u01/app/oracle/flash_recovery_area/ORCL/
ALTER SYSTEM SET log_archive_dest_1='location="/u01/app/oracle/flash_recovery_area/ORCL/"','valid_for=(ALL_LOGFILES,ALL_ROLES)' SCOPE=BOTH SID='orcl_primary';
ALTER SYSTEM SET log_archive_dest_state_1='ENABLE' SCOPE=BOTH SID='orcl_primary';
ALTER SYSTEM SET log_archive_trace=0 SCOPE=BOTH SID='orcl_primary';
ALTER SYSTEM SET log_archive_format='log_%s_%t_%r.arc' SCOPE=SPFILE SID='orcl_primary';
ALTER SYSTEM SET standby_file_management='AUTO' SCOPE=BOTH SID='*';
ALTER SYSTEM SET archive_lag_target=0 SCOPE=BOTH SID='*';
ALTER SYSTEM SET log_archive_max_processes=4 SCOPE=BOTH SID='*';
ALTER SYSTEM SET log_archive_min_succeed_dest=1 SCOPE=BOTH SID='*';
ALTER SYSTEM SET fal_server='orcl_stdby1' SCOPE=BOTH;
ALTER SYSTEM SET fal_client='orcl_primary' SCOPE=BOTH;
ALTER DATABASE RECOVER MANAGED STANDBY DATABASE  THROUGH ALL SWITCHOVER DISCONNECT  USING CURRENT LOGFILE
Attempt to start background Managed Standby Recovery process (orcl_primary)
Sun Aug 30 17:24:14 2009
MRP0 started with pid=31, OS id=4271 
MRP0: Background Managed Standby Recovery process started (orcl_primary)
Fast Parallel Media Recovery enabled
Managed Standby Recovery starting Real Time Apply
 parallel recovery started with 2 processes
Waiting for all non-current ORLs to be archived...
Clearing online redo logfile 1 /u01/app/oracle/oradata/orcl/redo01.log
Clearing online log 1 of thread 1 sequence number 17
Sun Aug 30 17:24:21 2009
Completed: ALTER DATABASE RECOVER MANAGED STANDBY DATABASE  THROUGH ALL SWITCHOVER DISCONNECT  USING CURRENT LOGFILE
Clearing online redo logfile 1 complete
Clearing online redo logfile 2 /u01/app/oracle/oradata/orcl/redo02.log
Clearing online log 2 of thread 1 sequence number 18
Sun Aug 30 17:24:26 2009
Clearing online redo logfile 2 complete
Clearing online redo logfile 3 /u01/app/oracle/oradata/orcl/redo03.log
Clearing online log 3 of thread 1 sequence number 19
Sun Aug 30 17:24:27 2009
Redo Shipping Client Connected as PUBLIC
-- Connected User is Valid
RFS[1]: Assigned to RFS process 4390
RFS[1]: Identified database type as 'physical standby'
Primary database is in MAXIMUM PERFORMANCE mode
Sun Aug 30 17:24:27 2009
Redo Shipping Client Connected as PUBLIC
-- Connected User is Valid
RFS[2]: Assigned to RFS process 4392
RFS[2]: Identified database type as 'physical standby'
RFS LogMiner: Client disabled from further notification
Sun Aug 30 17:24:29 2009
Redo Shipping Client Connected as PUBLIC
-- Connected User is Valid
RFS[3]: Assigned to RFS process 4398
RFS[3]: Identified database type as 'physical standby'
Primary database is in MAXIMUM PERFORMANCE mode
Clearing online redo logfile 3 complete
RFS[1]: Successfully opened standby log 5: '/u01/app/oracle/oradata/orcl/srl02.log'
kcrrvslf: active RFS archival for log 5 thread 1 sequence 2
RFS[2]: Successfully opened standby log 4: '/u01/app/oracle/oradata/orcl/srl01.log'
Media Recovery Waiting for thread 1 sequence 19
RFS[2]: Detected missing archivals for Branch(resetlogs_id): 695847608
RFS[2]: Last archived SCN: 0:5078349  Last change SCN: 0:5078858
RFS[2]: New Archival REDO Branch(resetlogs_id): 696272632  Prior: 695847608
RFS[2]: Archival Activation ID: 0x48f61941 Current: 0x0
RFS[2]: Effect of primary database OPEN RESETLOGS
RFS[2]: Managed Standby Recovery process is active
Setting recovery target incarnation to 5
RFS[2]: Incarnation entry added for Branch(resetlogs_id): 696272632 (orcl_primary)
Sun Aug 30 17:24:36 2009
Setting recovery target incarnation to 5
Sun Aug 30 17:24:38 2009
Redo Shipping Client Connected as PUBLIC
-- Connected User is Valid
RFS[4]: Assigned to RFS process 4406
RFS[4]: Identified database type as 'physical standby'