Supposing that you lose the Online Redo Logs of the Primary [after it has been SHUTDOWN NORMAL/IMMEDIATE] and you have to OPEN RESETLOGS, how do you handle the Standbys ?
This scenario demonstrated below works only if you did not have to issue a RESTORE DATABASE and RECOVER DATABASE at the Primary. In such a case you would have to FLASHBACK all the Standbys to a time/SCN earlier than the Recovery time OR you'd have to Rebuild the Standbys.
In my demonstration below, the RECOVER DATABASE was only from the ArchiveLogs that have already been shipped or applied to the Standby -- upto Sequence#505. You must verify that the last active Online Redo Log at the Primary has been Archived and Shipped (not necessarily applied) to the Standby[s] before you release your Primary for storage/server maintenance. If they were not Shipped automatically, you can manually copy them to the Standbys and use the ALTER DATABASE REGISTER LOGFILE command at the Standbys,
Let's assume that the Primary had been shutdown for storage/server maintenance (but the Standbys were yet running). The Standby's are *not* shutdown in my scenario.
Then, during the storage/server maintenance, the disk/filesystem for the Online Redo Logs was lost/corrupt. This necessitated an OPEN RESETLOGS.
The key thing is than an OPEN RESETLOGS creates a new Incarnation of the database. What happens at the Standbys subsequently ?
Let's assume that the Primary created a Controlfile Autobackup and then did SHUTDOWN IMMEDIATE before the storage/server maintenance.
Starting Control File and SPFILE Autobackup at 26-SEP-21
piece handle=/opt/oracle/FRA/ORCLCDB/ORCLCDB/autobackup/2021_09_26/o1_mf_s_1084311179_jo0xnh8o_.bkp comment=NONE
Finished Control File and SPFILE Autobackup at 26-SEP-21
RMAN>
RMAN> quit
Recovery Manager complete.
oracle19c>sqlplus '/ as sysdba'
SQL*Plus: Release 19.0.0.0.0 - Production on Sun Sep 26 21:34:25 2021
Version 19.12.0.0.0
Copyright (c) 1982, 2021, Oracle. All rights reserved.
Connected to:
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.12.0.0.0
SQL>
SQL> shutdown immediate;
Database closed.
Database dismounted.
ORACLE instance shut down.
SQL>
entries from the alert log show that SEQUENCE#505 was the last Online Redo Log that was active
and was also archived at shutdown (as is done in recent versions)
2021-09-26T21:33:34.741801+08:00
Thread 1 advanced to log sequence 505 (LGWR switch), current SCN: 15237281
Current log# 1 seq# 505 mem# 0: /opt/oracle/oradata/ORCLCDB/redo01.log
2021-09-26T21:33:35.533318+08:00
NET (PID:13253): Archived Log entry 1295 added for T-1.S-504 ID 0xa7521ccd LAD:1
2021-09-26T21:34:40.355271+08:00
Shutting down ORACLE instance (immediate) (OS id: 13897)
...
...
ALTER DATABASE CLOSE NORMAL
Stopping Emon pool
2021-09-26T21:34:54.826891+08:00
alter pluggable database all close immediate
Completed: alter pluggable database all close immediate
alter pluggable database all close immediate
Completed: alter pluggable database all close immediate
2021-09-26T21:34:55.811566+08:00
IM on ADG: Start of Empty Journal
IM on ADG: End of Empty Journal
Stopping Emon pool
Closing sequence subsystem (1373431005).
2021-09-26T21:34:56.082543+08:00
Stopping change tracking
2021-09-26T21:35:00.702496+08:00
TT04 (PID:4521): Shutdown in progress, stop CF update
2021-09-26T21:35:01.439450+08:00
Thread 1 advanced to log sequence 506 (thread close)
2021-09-26T21:35:01.537622+08:00
LGWR (PID:4387): Waiting for ORLs to be archived
2021-09-26T21:35:01.694980+08:00
ARC0 (PID:4457): Archived Log entry 1298 added for T-1.S-505 ID 0xa7521ccd LAD:1
2021-09-26T21:35:01.709616+08:00
LGWR (PID:4387): ORLs successfully archived
2021-09-26T21:35:02.711736+08:00
Shutting down archive processes
2021-09-26T21:35:02.712053+08:00
TT00 (PID:4453): Gap Manager exiting
2021-09-26T21:35:03.712018+08:00
Archiving is disabled
2021-09-26T21:35:03.712297+08:00
ARC3 (PID:4464): ARCH shutting down
However, it so happens that the Online Redo Logs are "lost" during server/storage maintenance. Maybe, even the Controlfiles are "lost". I decide to RESTORE CONTROLFILE and to OPEN RESETLOGS.
In the commands below, I deliberately use the SQL*Plus command line so that I can show the ArchiveLog Sequences#s that are applied before I can OPEN RESETLOGS (RMAN command line would hide the details) and I know that I can CANCEL and stop after Sequence#505
oracle19c>sqlplus '/ as sysdba'
SQL*Plus: Release 19.0.0.0.0 - Production on Sun Sep 26 21:39:59 2021
Version 19.12.0.0.0
Copyright (c) 1982, 2021, Oracle. All rights reserved.
Connected to an idle instance.
SQL> startup nomount;
ORACLE instance started.
Total System Global Area 1207955544 bytes
Fixed Size 9134168 bytes
Variable Size 872415232 bytes
Database Buffers 318767104 bytes
Redo Buffers 7639040 bytes
SQL> alter database mount;
alter database mount
*
ERROR at line 1:
ORA-00205: error in identifying control file, check alert log for more info
SQL>
SQL> quit
Disconnected from Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.12.0.0.0
oracle19c>rman target /
Recovery Manager: Release 19.0.0.0.0 - Production on Sun Sep 26 21:40:34 2021
Version 19.12.0.0.0
Copyright (c) 1982, 2019, Oracle and/or its affiliates. All rights reserved.
connected to target database: ORCLCDB (not mounted)
RMAN> restore controlfile from autobackup;
Starting restore at 26-SEP-21
using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=245 device type=DISK
recovery area destination: /opt/oracle/FRA/ORCLCDB
database name (or database unique name) used for search: ORCLCDB
channel ORA_DISK_1: AUTOBACKUP /opt/oracle/FRA/ORCLCDB/ORCLCDB/autobackup/2021_09_26/o1_mf_s_1084311179_jo0xnh8o_.bkp found in the recovery area
AUTOBACKUP search with format "%F" not attempted because DBID was not set
channel ORA_DISK_1: restoring control file from AUTOBACKUP /opt/oracle/FRA/ORCLCDB/ORCLCDB/autobackup/2021_09_26/o1_mf_s_1084311179_jo0xnh8o_.bkp
channel ORA_DISK_1: control file restore from AUTOBACKUP complete
output file name=/opt/oracle/oradata/ORCLCDB/control01.ctl
output file name=/opt/oracle/oradata/ORCLCDB/control02.ctl
Finished restore at 26-SEP-21
RMAN>
RMAN> alter database mount;
released channel: ORA_DISK_1
Statement processed
RMAN> alter database open;
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-03002: failure of sql statement command at 09/26/2021 21:41:17
ORA-01589: must use RESETLOGS or NORESETLOGS option for database open
RMAN>
RMAN> alter database open resetlogs;
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-03002: failure of sql statement command at 09/26/2021 21:41:35
ORA-01152: file 1 was not restored from a sufficiently old backup
ORA-01110: data file 1: '/opt/oracle/oradata/ORCLCDB/system01.dbf'
RMAN>
RMAN> quit
Recovery Manager complete.
oracle19c>
oracle19c>sqlplus '/ as sysdba'
SQL*Plus: Release 19.0.0.0.0 - Production on Sun Sep 26 21:54:27 2021
Version 19.12.0.0.0
Copyright (c) 1982, 2021, Oracle. All rights reserved.
Connected to:
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.12.0.0.0
SQL> recover database using backup controlfile until cancel;
ORA-00279: change 15237057 generated at 09/26/2021 21:28:26 needed for thread 1
ORA-00289: suggestion : /opt/oracle/archivelog/ORCLCDB/1_503_1036108814.dbf
ORA-00280: change 15237057 for thread 1 is in sequence #503
Specify log: {RET=suggested | filename | AUTO | CANCEL}
ORA-00279: change 15237253 generated at 09/26/2021 21:33:26 needed for thread 1
ORA-00289: suggestion : /opt/oracle/archivelog/ORCLCDB/1_504_1036108814.dbf
ORA-00280: change 15237253 for thread 1 is in sequence #504
ORA-00278: log file '/opt/oracle/archivelog/ORCLCDB/1_503_1036108814.dbf' no longer needed for this recovery
Specify log: {RET=suggested | filename | AUTO | CANCEL}
ORA-00279: change 15237281 generated at 09/26/2021 21:33:33 needed for thread 1
ORA-00289: suggestion : /opt/oracle/archivelog/ORCLCDB/1_505_1036108814.dbf
ORA-00280: change 15237281 for thread 1 is in sequence #505
ORA-00278: log file '/opt/oracle/archivelog/ORCLCDB/1_504_1036108814.dbf' no longer needed for this recovery
Specify log: {RET=suggested | filename | AUTO | CANCEL}
ORA-00279: change 15238147 generated at 09/26/2021 21:34:58 needed for thread 1
ORA-00289: suggestion : /opt/oracle/archivelog/ORCLCDB/1_506_1036108814.dbf
ORA-00280: change 15238147 for thread 1 is in sequence #506
ORA-00278: log file '/opt/oracle/archivelog/ORCLCDB/1_505_1036108814.dbf' no longer needed for this recovery
Specify log: {RET=suggested | filename | AUTO | CANCEL}
CANCEL
Media recovery cancelled.
SQL> alter database open resetlogs;
Database altered.
SQL> set pages60
SQL> set linesize132
SQL> alter session set nls_date_format='DD-MON-RR HH24:MI:SS';
Session altered.
SQL> select * from v$database_incarnation;
INCARNATION# RESETLOGS_CHANGE# RESETLOGS_TIME PRIOR_RESETLOGS_CHANGE# PRIOR_RESETLOGS_TI STATUS RESETLOGS_ID PRIOR_INCARNATION#
------------ ----------------- ------------------ ----------------------- ------------------ ------- ------------ ------------------
FLASHBACK_DATABASE_ALLOWED CON_ID
-------------------------- ----------
1 1 17-APR-19 00:55:59 0 PARENT 1005785759 0
NO 0
2 1920977 04-MAY-19 23:21:26 1 17-APR-19 00:55:59 PARENT 1007421686 1
NO 0
3 4797184 27-MAR-20 00:00:14 1920977 04-MAY-19 23:21:26 PARENT 1036108814 2
NO 0
4 15238148 26-SEP-21 22:00:48 4797184 27-MAR-20 00:00:14 CURRENT 1084312848 3
NO 0
SQL>
So, my Primary Database has now switched to
INCARNATION#4 with a RESETLOGS as of 26-Sep-21 22:00:48 with
RESETLOGS_ID "1084312848"
Let me check my Standby alert logs.
First, STDBYDB which shows that Sequence#505 was applied (ie. "Recovery of Onlin Redo Log ... Seq 505 .." message completed by showing the next message "Media Recovery Waiting for T-1.5-506"
2021-09-26T21:33:28.002521+08:00
rfs (PID:4667): Standby controlfile consistent with primary
2021-09-26T21:33:28.339263+08:00
rfs (PID:4667): Selected LNO:4 for T-1.S-504 dbid 2778483057 branch 1036108814
2021-09-26T21:33:28.667001+08:00
Recovery of Online Redo Log: Thread 1 Group 4 Seq 504 Reading mem 0
Mem# 0: /opt/oracle/oradata/STDBYDB/stdbredo01.log
2021-09-26T21:33:33.555294+08:00
ARC3 (PID:3201): Archived Log entry 108 added for T-1.S-504 ID 0xa7521ccd LAD:1
2021-09-26T21:33:33.827814+08:00
PR00 (PID:3847): Media Recovery Waiting for T-1.S-505
2021-09-26T21:33:33.991340+08:00
rfs (PID:4667): Standby controlfile consistent with primary
2021-09-26T21:33:34.547950+08:00
rfs (PID:4667): Selected LNO:4 for T-1.S-505 dbid 2778483057 branch 1036108814
2021-09-26T21:33:35.283450+08:00
Recovery of Online Redo Log: Thread 1 Group 4 Seq 505 Reading mem 0
Mem# 0: /opt/oracle/oradata/STDBYDB/stdbredo01.log
2021-09-26T21:35:00.057442+08:00
ARC1 (PID:3197): Archived Log entry 109 added for T-1.S-505 ID 0xa7521ccd LAD:1
2021-09-26T21:35:00.289539+08:00
PR00 (PID:3847): Media Recovery Waiting for T-1.S-506
2021-09-26T21:35:02.732262+08:00
rfs (PID:4502): Possible network disconnect with primary database
At this point, 21:35:02, it shows a "network disconnect with the primary database" which is when the Primary had fnished archiving Sequence#505 and was continuing the shutdown.
Subsequently, when the Primary goes through the OPEN RESETLOGS, the Standby shows
[note the "rfs (PID:20837): A new recovery destination branch has been registered" and " rfs (PID:20837): Standby in the future of new recovery destination branch(resetlogs_id) 1084312848" and "rfs (PID:20837): New Archival REDO Branch(resetlogs_id): 1084312848 Prior: 1036108814" messages" which match the RESETLOGS_ID information from the Primary's v$database_incarnation (listed above) :
2021-09-26T22:01:32.924024+08:00
rfs (PID:20634): krsr_rfs_atc: Identified database type as 'PHYSICAL STANDBY': Client is Foreground (PID:14755)
2021-09-26T22:01:44.591773+08:00
rfs (PID:20820): krsr_rfs_atc: Identified database type as 'PHYSICAL STANDBY': Client is SYNC (PID:14565)
rfs (PID:20820): New archival redo branch: 1084312848 current: 1036108814
rfs (PID:20820): Primary database is in MAXIMUM AVAILABILITY mode
rfs (PID:20820): Changing standby controlfile to RESYNCHRONIZATION level
rfs (PID:20820): Standby controlfile consistent with primary
rfs (PID:20820): No SRLs available for T-1
Clearing online log 5 of thread 1 sequence number 0
2021-09-26T22:01:49.532864+08:00
rfs (PID:20820): Selected LNO:5 for T-1.S-3 dbid 2778483057 branch 1084312848
2021-09-26T22:01:49.535634+08:00
Clearing online log 4 of thread 1 sequence number 0
2021-09-26T22:01:56.788073+08:00
rfs (PID:20837): krsr_rfs_atc: Identified database type as 'PHYSICAL STANDBY': Client is FAL (PID:14751)
2021-09-26T22:01:59.406342+08:00
rfs (PID:20837): Selected LNO:4 for T-1.S-2 dbid 2778483057 branch 1084312848
2021-09-26T22:02:00.964530+08:00
rfs (PID:20837): A new recovery destination branch has been registered
rfs (PID:20837): Standby in the future of new recovery destination branch(resetlogs_id) 1084312848
rfs (PID:20837): Incomplete Recovery SCN:0x0000000000e88403
rfs (PID:20837): Resetlogs SCN:0x0000000000e88404
rfs (PID:20837): SBPS:0x00000000004c4f04
rfs (PID:20837): New Archival REDO Branch(resetlogs_id): 1084312848 Prior: 1036108814
rfs (PID:20837): Archival Activation ID: 0xaa3191f1 Current: 0xa7521ccd
rfs (PID:20837): Effect of primary database OPEN RESETLOGS
rfs (PID:20837): Managed Standby Recovery process is active
2021-09-26T22:02:00.965240+08:00
Incarnation entry added for Branch(resetlogs_id): 1084312848 (STDBYDB)
2021-09-26T22:02:02.317070+08:00
Setting recovery target incarnation to 4
2021-09-26T22:02:02.421791+08:00
PR00 (PID:3847): MRP0: Incarnation has changed! Retry recovery...
2021-09-26T22:02:02.422333+08:00
Errors in file /opt/oracle/diag/rdbms/stdbydb/STDBYDB/trace/STDBYDB_pr00_3847.trc:
ORA-19906: recovery target incarnation changed during recovery
PR00 (PID:3847): Managed Standby Recovery not using Real Time Apply
Recovery interrupted!
Stopping change tracking
2021-09-26T22:02:02.735890+08:00
Errors in file /opt/oracle/diag/rdbms/stdbydb/STDBYDB/trace/STDBYDB_pr00_3847.trc:
ORA-19906: recovery target incarnation changed during recovery
2021-09-26T22:02:03.908863+08:00
Started logmerger process
2021-09-26T22:02:04.088714+08:00
PR00 (PID:20863): Managed Standby Recovery starting Real Time Apply
2021-09-26T22:02:05.658988+08:00
ARC1 (PID:3197): Archived Log entry 110 added for T-1.S-2 ID 0xaa3191f1 LAD:1
2021-09-26T22:02:06.477510+08:00
max_pdb is 5
2021-09-26T22:02:07.696019+08:00
Parallel Media Recovery started with 4 slaves
2021-09-26T22:02:08.510123+08:00
Stopping change tracking
2021-09-26T22:02:10.459429+08:00
PR00 (PID:20863): Media Recovery Waiting for T-1.S-1
PR00 (PID:20863): Fetching gap from T-1.S-1 to T-1.S-1
2021-09-26T22:02:10.779495+08:00
rfs (PID:20986): krsr_rfs_atc: Identified database type as 'PHYSICAL STANDBY': Client is FAL (PID:14753)
2021-09-26T22:02:12.270336+08:00
rfs (PID:20986): Opened log for T-1.S-1 dbid 2778483057 branch 1084312848
2021-09-26T22:02:12.385769+08:00
rfs (PID:20986): Archived Log entry 111 added for B-1084312848.T-1.S-1 ID 0xaa3191f1 LAD:2
2021-09-26T22:02:13.251841+08:00
PR00 (PID:20863): Media Recovery Log /opt/oracle/archivelog/STDBYDB/1_1_1084312848.dbf
2021-09-26T22:02:14.796992+08:00
PR00 (PID:20863): Media Recovery Log /opt/oracle/archivelog/STDBYDB/1_2_1084312848.dbf
2021-09-26T22:02:22.220965+08:00
PR00 (PID:20863): Media Recovery Waiting for T-1.S-3 (in transit)
2021-09-26T22:02:23.679612+08:00
Recovery of Online Redo Log: Thread 1 Group 5 Seq 3 Reading mem 0
Mem# 0: /opt/oracle/oradata/STDBYDB/stdbredo02.dbf
2021-09-26T22:02:33.322073+08:00
ARC2 (PID:3199): Archived Log entry 112 added for T-1.S-3 ID 0xaa3191f1 LAD:1
2021-09-26T22:02:34.236382+08:00
PR00 (PID:20863): Media Recovery Waiting for T-1.S-4
2021-09-26T22:02:34.559830+08:00
rfs (PID:20820): Changing standby controlfile to MAXIMUM AVAILABILITY level
2021-09-26T22:02:35.020783+08:00
rfs (PID:20820): Selected LNO:4 for T-1.S-4 dbid 2778483057 branch 1084312848
2021-09-26T22:02:35.329328+08:00
Recovery of Online Redo Log: Thread 1 Group 4 Seq 4 Reading mem 0
Mem# 0: /opt/oracle/oradata/STDBYDB/stdbredo01.log
2021-09-26T22:10:24.128439+08:00
PR00 (PID:20863): Media Recovery Waiting for T-1.S-5
2021-09-26T22:10:24.194710+08:00
ARC0 (PID:3193): Archived Log entry 113 added for T-1.S-4 ID 0xaa3191f1 LAD:1
2021-09-26T22:10:25.894496+08:00
rfs (PID:20820): Standby controlfile consistent with primary
2021-09-26T22:10:26.415829+08:00
rfs (PID:20820): Selected LNO:4 for T-1.S-5 dbid 2778483057 branch 1084312848
2021-09-26T22:10:32.885773+08:00
Recovery of Online Redo Log: Thread 1 Group 4 Seq 5 Reading mem 0
Mem# 0: /opt/oracle/oradata/STDBYDB/stdbredo01.log
2021-09-26T22:10:33.484509+08:00
ARC2 (PID:3199): Archived Log entry 114 added for T-1.S-5 ID 0xaa3191f1 LAD:1
2021-09-26T22:10:33.653161+08:00
PR00 (PID:20863): Media Recovery Waiting for T-1.S-6 (in transit)
2021-09-26T22:10:33.666695+08:00
rfs (PID:20820): Standby controlfile consistent with primary
2021-09-26T22:10:33.983459+08:00
rfs (PID:20820): Selected LNO:4 for T-1.S-6 dbid 2778483057 branch 1084312848
2021-09-26T22:10:34.715704+08:00
2021-09-26T22:10:34.715704+08:00
Recovery of Online Redo Log: Thread 1 Group 4 Seq 6 Reading mem 0
Mem# 0: /opt/oracle/oradata/STDBYDB/stdbredo01.log
The STDBYDB instance is already at Sequence#6 of the new Incarnation because the Primary database has been released for use and is already receiving new transactions and generating redo and ArchiveLogs which it is now shipping to all the Standbys.
The other current Standby STDB2 also shows that is now running with the new Incarnation and Sequence#6 :
2021-09-26T22:10:33.848217+08:00
PR00 (PID:20945): Media Recovery Waiting for T-1.S-6 (in transit)
2021-09-26T22:10:34.910903+08:00
Recovery of Online Redo Log: Thread 1 Group 5 Seq 6 Reading mem 0
Mem# 0: /opt/oracle/oradata/STDBNEW/stdbredo02.dbf
What about the Stanndy Database
STDB2 that I had set to lag by 1hour.
I present the alert log entries that shows it is aware of (Received and Archived, and in some cases, Applied, older Archives going back to the time before the Primary was shutdown).
2021-09-26T21:24:03.036631+08:00
ARC0 (PID:3517): Archive log for T-1.S-499 available in 59 minute(s)
2021-09-26T21:24:15.615120+08:00
rfs (PID:4480): Selected LNO:4 for T-1.S-501 dbid 2778483057 branch 1036108814
2021-09-26T21:24:16.085817+08:00
ARC1 (PID:3523): Archived Log entry 246 added for T-1.S-500 ID 0xa7521ccd LAD:1
2021-09-26T21:24:16.085881+08:00
ARC1 (PID:3523): Archive log for T-1.S-500 available in 60 minute(s)
2021-09-26T21:27:03.617096+08:00
db_recovery_file_dest_size of 10240 MB is 10.63% used. This is a
user-specified limit on the amount of space that will be used by this
database for recovery-related files, and does not reflect the amount of
space available in the underlying filesystem or ASM diskgroup.
2021-09-26T21:28:21.459249+08:00
rfs (PID:4480): Selected LNO:5 for T-1.S-502 dbid 2778483057 branch 1036108814
2021-09-26T21:28:25.263818+08:00
ARC2 (PID:3525): Archived Log entry 247 added for T-1.S-501 ID 0xa7521ccd LAD:1
2021-09-26T21:28:25.264142+08:00
ARC2 (PID:3525): Archive log for T-1.S-501 available in 60 minute(s)
2021-09-26T21:28:29.572537+08:00
rfs (PID:4480): Selected LNO:4 for T-1.S-503 dbid 2778483057 branch 1036108814
2021-09-26T21:28:29.580802+08:00
ARC3 (PID:3527): Archived Log entry 248 added for T-1.S-502 ID 0xa7521ccd LAD:1
2021-09-26T21:28:29.580964+08:00
ARC3 (PID:3527): Archive log for T-1.S-502 available in 59 minute(s)
2021-09-26T21:33:30.720113+08:00
rfs (PID:4480): Selected LNO:5 for T-1.S-504 dbid 2778483057 branch 1036108814
2021-09-26T21:33:30.737222+08:00
ARC0 (PID:3517): Archived Log entry 249 added for T-1.S-503 ID 0xa7521ccd LAD:1
2021-09-26T21:33:30.737298+08:00
ARC0 (PID:3517): Archive log for T-1.S-503 available in 60 minute(s)
2021-09-26T21:33:35.794308+08:00
rfs (PID:4480): Selected LNO:4 for T-1.S-505 dbid 2778483057 branch 1036108814
2021-09-26T21:33:35.825498+08:00
ARC1 (PID:3523): Archived Log entry 250 added for T-1.S-504 ID 0xa7521ccd LAD:1
2021-09-26T21:33:35.825563+08:00
ARC1 (PID:3523): Archive log for T-1.S-504 available in 60 minute(s)
2021-09-26T21:35:02.021214+08:00
rfs (PID:4493): Selected LNO:4 for T-1.S-505 dbid 2778483057 branch 1036108814
2021-09-26T21:35:02.225079+08:00
ARC2 (PID:3525): Archived Log entry 251 added for T-1.S-505 ID 0xa7521ccd LAD:1
2021-09-26T21:35:02.226252+08:00
ARC2 (PID:3525): Archive log for T-1.S-505 available in 59 minute(s)
2021-09-26T21:35:02.733024+08:00
rfs (PID:4488): Possible network disconnect with primary database
2021-09-26T22:01:13.848495+08:00
rfs (PID:20585): krsr_rfs_atc: Identified database type as 'PHYSICAL STANDBY': Client is ASYNC (PID:20568)
rfs (PID:20585): New archival redo branch: 1084312848 current: 1036108814
rfs (PID:20585): Primary database is in MAXIMUM PERFORMANCE mode
2021-09-26T22:01:13.995667+08:00
rfs (PID:20587): krsr_rfs_atc: Identified database type as 'PHYSICAL STANDBY': Client is ARCH (PID:14747)
rfs (PID:20587): New archival redo branch: 1084312848 current: 1036108814
2021-09-26T22:01:15.034084+08:00
rfs (PID:20585): No SRLs available for T-1
2021-09-26T22:01:15.317462+08:00
rfs (PID:20587): No SRLs available for T-1
Clearing online log 5 of thread 1 sequence number 0
2021-09-26T22:01:22.282624+08:00
rfs (PID:20587): Selected LNO:5 for T-1.S-1 dbid 2778483057 branch 1084312848
2021-09-26T22:01:22.283691+08:00
Clearing online log 4 of thread 1 sequence number 0
2021-09-26T22:01:22.380789+08:00
rfs (PID:20603): krsr_rfs_atc: Identified database type as 'PHYSICAL STANDBY': Client is Foreground (PID:14755)
2021-09-26T22:01:24.283184+08:00
rfs (PID:20587): A new recovery destination branch has been registered
rfs (PID:20587): Standby in the future of new recovery destination branch(resetlogs_id) 1084312848
rfs (PID:20587): Incomplete Recovery SCN:0x0000000000e6e7e1
rfs (PID:20587): Resetlogs SCN:0x0000000000e88404
rfs (PID:20587): SBPS:0x00000000004c4f04
rfs (PID:20587): New Archival REDO Branch(resetlogs_id): 1084312848 Prior: 1036108814
rfs (PID:20587): Archival Activation ID: 0xaa3191f1 Current: 0xa7521ccd
rfs (PID:20587): Effect of primary database OPEN RESETLOGS
rfs (PID:20587): Managed Standby Recovery process is active
2021-09-26T22:01:24.283999+08:00
Incarnation entry added for Branch(resetlogs_id): 1084312848 (STDB2)
2021-09-26T22:01:25.510452+08:00
Setting recovery target incarnation to 4
2021-09-26T22:01:27.818244+08:00
PR00 (PID:3913): MRP0: Incarnation has changed! Retry recovery...
2021-09-26T22:01:28.056186+08:00
Errors in file /opt/oracle/diag/rdbms/stdb2/STDB2/trace/STDB2_pr00_3913.trc:
ORA-19906: recovery target incarnation changed during recovery
Recovery interrupted!
2021-09-26T22:01:29.960402+08:00
Stopping change tracking
2021-09-26T22:01:29.962316+08:00
Errors in file /opt/oracle/diag/rdbms/stdb2/STDB2/trace/STDB2_pr00_3913.trc:
ORA-19906: recovery target incarnation changed during recovery
2021-09-26T22:01:30.588055+08:00
rfs (PID:20585): Selected LNO:4 for T-1.S-2 dbid 2778483057 branch 1084312848
2021-09-26T22:01:30.942431+08:00
Started logmerger process
2021-09-26T22:01:32.562040+08:00
PR00 (PID:20631): Managed Standby Recovery not using Real Time Apply
2021-09-26T22:01:34.537732+08:00
ARC2 (PID:3525): Archived Log entry 252 added for T-1.S-1 ID 0xaa3191f1 LAD:1
2021-09-26T22:01:34.537903+08:00
ARC2 (PID:3525): Archive log for T-1.S-1 available in 59 minute(s)
2021-09-26T22:01:34.915506+08:00
max_pdb is 5
2021-09-26T22:01:36.394057+08:00
Parallel Media Recovery started with 4 slaves
2021-09-26T22:01:38.128953+08:00
Media Recovery start incarnation depth : 1, target inc# : 4, irscn : 15238147
Stopping change tracking
2021-09-26T22:01:39.202866+08:00
PR00 (PID:20631): Media Recovery Waiting for B-1036108814.T-1.S-495
2021-09-26T22:01:55.182487+08:00
rfs (PID:20587): Opened log for T-1.S-495 dbid 2778483057 branch 1036108814
2021-09-26T22:01:57.676763+08:00
rfs (PID:20585): Selected LNO:5 for T-1.S-3 dbid 2778483057 branch 1084312848
2021-09-26T22:01:58.495693+08:00
ARC3 (PID:3527): Archived Log entry 253 added for T-1.S-2 ID 0xaa3191f1 LAD:1
2021-09-26T22:01:58.495890+08:00
ARC3 (PID:3527): Archive log for T-1.S-2 available in 59 minute(s)
2021-09-26T22:01:59.879131+08:00
rfs (PID:20587): Archived Log entry 254 added for B-1036108814.T-1.S-495 ID 0xa7521ccd LAD:3
2021-09-26T22:02:00.978032+08:00
PR00 (PID:20631): Media Recovery Delayed for 11 minute(s) T-1.S-495
2021-09-26T22:02:06.096910+08:00
rfs (PID:20950): krsr_rfs_atc: Identified database type as 'PHYSICAL STANDBY': Client is FAL (PID:14753)
2021-09-26T22:02:06.097083+08:00
rfs (PID:20948): krsr_rfs_atc: Identified database type as 'PHYSICAL STANDBY': Client is FAL (PID:14751)
2021-09-26T22:02:07.293676+08:00
rfs (PID:20587): Opened log for T-1.S-497 dbid 2778483057 branch 1036108814
2021-09-26T22:02:07.649778+08:00
rfs (PID:20950): Opened log for T-1.S-498 dbid 2778483057 branch 1036108814
2021-09-26T22:02:07.997282+08:00
rfs (PID:20948): Opened log for T-1.S-496 dbid 2778483057 branch 1036108814
2021-09-26T22:02:08.520189+08:00
rfs (PID:20587): Archived Log entry 255 added for B-1036108814.T-1.S-497 ID 0xa7521ccd LAD:3
2021-09-26T22:02:09.302061+08:00
rfs (PID:20950): Archived Log entry 256 added for B-1036108814.T-1.S-498 ID 0xa7521ccd LAD:3
2021-09-26T22:02:09.707710+08:00
rfs (PID:20948): Archived Log entry 257 added for B-1036108814.T-1.S-496 ID 0xa7521ccd LAD:3
2021-09-26T22:02:10.761235+08:00
rfs (PID:20587): Opened log for T-1.S-499 dbid 2778483057 branch 1036108814
2021-09-26T22:02:11.253039+08:00
rfs (PID:20587): Archived Log entry 258 added for B-1036108814.T-1.S-499 ID 0xa7521ccd LAD:3
2021-09-26T22:02:12.823920+08:00
rfs (PID:20948): Opened log for T-1.S-500 dbid 2778483057 branch 1036108814
2021-09-26T22:02:13.951243+08:00
rfs (PID:20948): Archived Log entry 259 added for B-1036108814.T-1.S-500 ID 0xa7521ccd LAD:3
2021-09-26T22:02:15.024761+08:00
rfs (PID:20587): Opened log for T-1.S-501 dbid 2778483057 branch 1036108814
2021-09-26T22:02:15.534976+08:00
rfs (PID:20950): Opened log for T-1.S-502 dbid 2778483057 branch 1036108814
2021-09-26T22:02:21.798580+08:00
rfs (PID:20950): Archived Log entry 260 added for B-1036108814.T-1.S-502 ID 0xa7521ccd LAD:3
2021-09-26T22:02:23.673255+08:00
rfs (PID:20587): Archived Log entry 261 added for B-1036108814.T-1.S-501 ID 0xa7521ccd LAD:3
2021-09-26T22:02:37.301066+08:00
rfs (PID:20585): Selected LNO:4 for T-1.S-4 dbid 2778483057 branch 1084312848
2021-09-26T22:02:37.452512+08:00
ARC0 (PID:3517): Archived Log entry 262 added for T-1.S-3 ID 0xaa3191f1 LAD:1
2021-09-26T22:02:37.452615+08:00
ARC0 (PID:3517): Archive log for T-1.S-3 available in 59 minute(s)
2021-09-26T22:10:31.699175+08:00
rfs (PID:20585): Selected LNO:5 for T-1.S-5 dbid 2778483057 branch 1084312848
2021-09-26T22:10:31.774120+08:00
ARC1 (PID:3523): Archived Log entry 263 added for T-1.S-4 ID 0xaa3191f1 LAD:1
2021-09-26T22:10:31.774245+08:00
ARC1 (PID:3523): Archive log for T-1.S-4 available in 59 minute(s)
2021-09-26T22:10:35.934765+08:00
rfs (PID:20585): Selected LNO:4 for T-1.S-6 dbid 2778483057 branch 1084312848
2021-09-26T22:10:35.938540+08:00
ARC2 (PID:3525): Archived Log entry 264 added for T-1.S-5 ID 0xaa3191f1 LAD:1
2021-09-26T22:10:35.938646+08:00
ARC2 (PID:3525): Archive log for T-1.S-5 available in 60 minute(s)
2021-09-26T22:12:59.695487+08:00
PR00 (PID:20631): Media Recovery Log /opt/oracle/archivelog/STDB2/1_495_1036108814.dbf
PR00 (PID:20631): Media Recovery Delayed for 19 minute(s) T-1.S-496
2021-09-26T22:21:12.441616+08:00
PR00 (PID:20631): Media Recovery Log /opt/oracle/archivelog/STDB2/1_496_1036108814.dbf
2021-09-26T22:21:15.172035+08:00
PR00 (PID:20631): Media Recovery Log /opt/oracle/archivelog/STDB2/1_497_1036108814.dbf
2021-09-26T22:21:16.215487+08:00
PR00 (PID:20631): Media Recovery Delayed for 20 minute(s) T-1.S-498
2021-09-26T22:22:10.156957+08:00
PR00 (PID:20631): Media Recovery Log /opt/oracle/archivelog/STDB2/1_498_1036108814.dbf
PR00 (PID:20631): Media Recovery Delayed for 21 minute(s) T-1.S-499
2021-09-26T22:23:15.521168+08:00
PR00 (PID:20631): Media Recovery Log /opt/oracle/archivelog/STDB2/1_499_1036108814.dbf
PR00 (PID:20631): Media Recovery Delayed for 22 minute(s) T-1.S-500
2021-09-26T22:24:17.854072+08:00
PR00 (PID:20631): Media Recovery Log /opt/oracle/archivelog/STDB2/1_500_1036108814.dbf
PR00 (PID:20631): Media Recovery Delayed for 26 minute(s) T-1.S-501
2021-09-26T22:28:31.972725+08:00
PR00 (PID:20631): Media Recovery Log /opt/oracle/archivelog/STDB2/1_502_1036108814.dbf
PR00 (PID:20631): Media Recovery Waiting for B-1036108814.T-1.S-503
2021-09-26T22:35:19.026115+08:00
rfs (PID:20585): Selected LNO:5 for T-1.S-7 dbid 2778483057 branch 1084312848
2021-09-26T22:35:19.052219+08:00
ARC3 (PID:3527): Archived Log entry 265 added for T-1.S-6 ID 0xaa3191f1 LAD:1
2021-09-26T22:35:19.052325+08:00
ARC3 (PID:3527): Archive log for T-1.S-6 available in 59 minute(s)
This has recognised the ResetLogs at 22:01 and has received the new Log Sequences (until Sequence#7) but still hasn't applied Sequence498 from the old Incarnation because that is not yet 1hour old [Sequence#497 has been applied to this Standby as at the time I view the alert log]. All the new Incarnation Log Sequences# 1 to 6 and onwards will be applied when each is 1hour old.
Since STDB2, seems to have stopped applying ArchiveLogs afer Sequence#502, I stopped and restarted delayed recovery and re-registered ArchiveLogs for Sequence#503 to #505 (that had actually already been Received and Archived between 21:33 and 21:36 earlier).
oracle19c>sqlplus
SQL*Plus: Release 19.0.0.0.0 - Production on Sun Sep 26 23:07:38 2021
Version 19.12.0.0.0
Copyright (c) 1982, 2021, Oracle. All rights reserved.
Enter user-name: / as sysdba
Connected to:
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.12.0.0.0
SQL> alter database recover managed standby database cancel;
Database altered.
SQL> alter database recover managed standby database using archived logfile disconnect from session;
Database altered.
SQL> qui
SP2-0042: unknown command "qui" - rest of line ignored.
SQL> quit
Disconnected from Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.12.0.0.0
oracle19c>
oracle19c>sqlplus '/ as sysdba'
SQL*Plus: Release 19.0.0.0.0 - Production on Sun Sep 26 23:11:34 2021
Version 19.12.0.0.0
Copyright (c) 1982, 2021, Oracle. All rights reserved.
Connected to:
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.12.0.0.0
SQL> alter database register logfile '/opt/oracle/archivelog/STDB2/1_503_1036108814.dbf';
Database altered.
SQL> alter database register logfile '/opt/oracle/archivelog/STDB2/1_504_1036108814.dbf';
Database altered.
SQL> alter database register logfile '/opt/oracle/archivelog/STDB2/1_505_1036108814.dbf';
Database altered.
SQL>
2021-09-26T23:07:57.810826+08:00
Managed Standby Recovery Canceled (STDB2)
Completed: alter database recover managed standby database cancel
2021-09-26T23:08:13.863811+08:00
alter database recover managed standby database using archived logfile disconnect from session
2021-09-26T23:08:13.865416+08:00
Attempt to start background Managed Standby Recovery process (STDB2)
Starting background process MRP0
2021-09-26T23:08:13.877996+08:00
MRP0 started with pid=36, OS id=14015
2021-09-26T23:08:13.879036+08:00
Background Managed Standby Recovery process started (STDB2)
2021-09-26T23:08:18.889440+08:00
Started logmerger process
2021-09-26T23:08:18.917894+08:00
PR00 (PID:14043): Managed Standby Recovery not using Real Time Apply
max_pdb is 5
2021-09-26T23:08:19.572566+08:00
Parallel Media Recovery started with 4 slaves
2021-09-26T23:08:19.748754+08:00
Media Recovery start incarnation depth : 1, target inc# : 4, irscn : 15238147
Stopping change tracking
2021-09-26T23:08:19.885274+08:00
Completed: alter database recover managed standby database using archived logfile disconnect from session
2021-09-26T23:08:19.969571+08:00
PR00 (PID:14043): Media Recovery Waiting for B-1036108814.T-1.S-503
2021-09-26T23:12:02.832089+08:00
alter database register logfile '/opt/oracle/archivelog/STDB2/1_503_1036108814.dbf'
2021-09-26T23:12:02.832185+08:00
There are 1 logfiles specified.
ALTER DATABASE REGISTER [PHYSICAL] LOGFILE
2021-09-26T23:12:04.988846+08:00
.... (PID:15189): Resynchronizing from T-1-S-10 to T-1.S-503
Completed: alter database register logfile '/opt/oracle/archivelog/STDB2/1_503_1036108814.dbf'
2021-09-26T23:12:13.842691+08:00
PR00 (PID:14043): Media Recovery Log /opt/oracle/archivelog/STDB2/1_503_1036108814.dbf
2021-09-26T23:12:15.812907+08:00
PR00 (PID:14043): Media Recovery Waiting for B-1036108814.T-1.S-504
2021-09-26T23:12:22.647534+08:00
alter database register logfile '/opt/oracle/archivelog/STDB2/1_504_1036108814.dbf'
2021-09-26T23:12:22.647609+08:00
There are 1 logfiles specified.
ALTER DATABASE REGISTER [PHYSICAL] LOGFILE
2021-09-26T23:12:24.805303+08:00
.... (PID:15189): Resynchronizing from T-1-S-503 to T-1.S-504
Completed: alter database register logfile '/opt/oracle/archivelog/STDB2/1_504_1036108814.dbf'
2021-09-26T23:12:30.299323+08:00
PR00 (PID:14043): Media Recovery Log /opt/oracle/archivelog/STDB2/1_504_1036108814.dbf
PR00 (PID:14043): Media Recovery Waiting for B-1036108814.T-1.S-505
2021-09-26T23:12:36.167593+08:00
alter database register logfile '/opt/oracle/archivelog/STDB2/1_505_1036108814.dbf'
2021-09-26T23:12:36.167671+08:00
There are 1 logfiles specified.
ALTER DATABASE REGISTER [PHYSICAL] LOGFILE
2021-09-26T23:12:38.271665+08:00
.... (PID:15189): Resynchronizing from T-1-S-504 to T-1.S-505
Completed: alter database register logfile '/opt/oracle/archivelog/STDB2/1_505_1036108814.dbf'
2021-09-26T23:12:41.883099+08:00
PR00 (PID:14043): Media Recovery Log /opt/oracle/archivelog/STDB2/1_505_1036108814.dbf
2021-09-26T23:12:43.883970+08:00
PR00 (PID:14043): Media Recovery Log /opt/oracle/archivelog/STDB2/1_1_1084312848.dbf
2021-09-26T23:12:44.047740+08:00
PR00 (PID:14043): Media Recovery Log /opt/oracle/archivelog/STDB2/1_2_1084312848.dbf
2021-09-26T23:12:44.473162+08:00
PR00 (PID:14043): Media Recovery Log /opt/oracle/archivelog/STDB2/1_3_1084312848.dbf
2021-09-26T23:12:44.701811+08:00
PR00 (PID:14043): Media Recovery Log /opt/oracle/archivelog/STDB2/1_4_1084312848.dbf
2021-09-26T23:12:52.961033+08:00
PR00 (PID:14043): Media Recovery Log /opt/oracle/archivelog/STDB2/1_5_1084312848.dbf
PR00 (PID:14043): Media Recovery Delayed for 59 minute(s) T-1.S-6
This is a bug I've noticed in the past. If a Standby has Received and Archived a logfile but hasn't applied it when it should have (
Sequence#503 to 505 should have been applied between 22:33 and 22:36 as they were received at 21:33 to 22:35-- you can see the earlier set of alert log entries that show that they were Received and Archived by this database instance), you might shutdown, startup and resume Recovery or simply stop and start Recovery. If that doesn't work, re-register the ArchiveLogs with the "ALTER DATABASE REGISTER LOGFILE" command again and re-attempt Recovery.
Now, all 3 of my Standby databases are in sync with the Primary (ie. STDBYDB and STDBNEW are current while STDB2 is lagging by 1hour, as designed).
Thus it is possible to do a RESETLOGS on a Primary as long as you ensure that
1. The Primary had Archived the last Online Redo Log before Shutdown
2. The Shutdown was Normal or Immediate
3. All the Standbys have, at least, Received all the ArchiveLogs (if there was a delay in shipping ArchiveLogs, you can manually copy them to the Standbys and use the ALTER DATABASE REGISTER LOGFILE command at the Standbys)
4. No actual recovery from Online Redo Logs {that were not shipped to the Standby} was required -- this is the case when the Shutdown is Normal or Immediate
