17 October, 2021

My Posts on Standby Database[s] -- Data Guard

Although I have, in previous posts, covered Data Guard in 12c (and 12cR1 RAC), this is a list of recent Blog Posts on Data Guard. 





















My Posts on Database Flashback

 

My Blog Posts on Database Flashback

(The first 5 demonstrations are in 11gR2.  The last demonstration is in 19c)


(not in the series)



My Posts on Parallel Execution


My series of blog posts on Parallel Execution

(These demonstrations were against Oracle 11gR2.  19c may have new features / changes / improvements)













26 September, 2021

Resuming Standby Databases after a RESETLOGS (without Data Loss from Online Redo Logs !!) at the Primary

 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#505You 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

04 September, 2021

ADG and DML Redirection -- with Multiple Standbys

 Building on my previous blog post on Active Data Guard with DML Redirection, here are a few more tests.

First, on the Primary :



22:03:50 SQL> select name, db_unique_name, database_role from v$database;

NAME      DB_UNIQUE_NAME                 DATABASE_ROLE
--------- ------------------------------ ----------------
ORCLCDB   ORCLCDB                        PRIMARY

Elapsed: 00:00:00.02
22:04:08 SQL> alter pluggable database orclpdb1 open ;
alter pluggable database orclpdb1 open
*
ERROR at line 1:
ORA-65019: pluggable database ORCLPDB1 already open


Elapsed: 00:00:00.50
22:04:19 SQL>
22:05:02 SQL> alter session set container=ORCLPDB1;

Session altered.

Elapsed: 00:00:00.04
22:05:10 SQL> create table hemant.test_adg_dml as select * from dba_objects where 1=2;

Table created.

Elapsed: 00:00:01.16
22:05:31 SQL> insert into hemant.test_adg_dml select * from dba_objects;

73661 rows created.

Elapsed: 00:00:09.29
22:06:03 SQL> commit;

Commit complete.

Elapsed: 00:00:00.00
22:06:12 SQL>


Now, one the first Standby as Active Data Guard and with DML Redirection

22:02:08 SQL> select name, db_unique_name, database_role from v$database;

NAME      DB_UNIQUE_NAME                 DATABASE_ROLE
--------- ------------------------------ ----------------
ORCLCDB   STDBYDB                        PHYSICAL STANDBY

Elapsed: 00:00:00.00
22:07:24 SQL> alter database recover managed standby database cancel;

Database altered.

Elapsed: 00:00:01.01
22:07:34 SQL> alter database open read only;

Database altered.

Elapsed: 00:00:34.66
22:08:23 SQL> alter pluggable database orclpdb1 open read only;

Pluggable database altered.

Elapsed: 00:00:10.76
22:08:39 SQL> alter database recover managed standby database disconnect from session;

Database altered.

Elapsed: 00:00:07.04
22:08:48 SQL> connect hemant/hemant@stdbypdb1
Connected.
22:09:12 SQL> ALTER SESSION ENABLE ADG_REDIRECT_DML;

Session altered.

Elapsed: 00:00:00.00
22:09:28 SQL> select count(*) from hemant.test_adg_dml;

  COUNT(*)
----------
     73661

Elapsed: 00:00:01.60
22:09:48 SQL> insert into hemant.test_adg_dml select * from dba_objects;

73661 rows created.

Elapsed: 00:00:10.71
22:10:13 SQL> select count(*) from hemant.test_adg_dml;

  COUNT(*)
----------
    147322

Elapsed: 00:00:00.01
22:10:24 SQL> commit;

Commit complete.

Elapsed: 00:00:00.09
22:10:27 SQL>


Now, on another Standby with ADG and DML Redirection :

22:11:52 SQL> select name, db_unique_name, database_role from v$database;

NAME      DB_UNIQUE_NAME                 DATABASE_ROLE
--------- ------------------------------ ----------------
ORCLCDB   STDBNEW                        PHYSICAL STANDBY

Elapsed: 00:00:00.03
22:11:53 SQL> alter database recover managed standby database cancel;

Database altered.

Elapsed: 00:00:06.01
22:12:06 SQL> alter database open read only;

Database altered.

Elapsed: 00:00:32.27
22:12:42 SQL> alter pluggable database orclpdb1 open read only;

Pluggable database altered.

Elapsed: 00:00:14.89
22:12:59 SQL> alter database recover managed standby database disconnect from session;

Database altered.

Elapsed: 00:00:06.06
22:13:08 SQL>
22:20:58 SQL> connect hemant/hemant@stdbnewpdb1
Connected.
22:21:04 SQL> ALTER SESSION ENABLE ADG_REDIRECT_DML;

Session altered.

Elapsed: 00:00:00.01
22:21:18 SQL> select count(*) from hemant.test_adg_dml;

  COUNT(*)
----------
    147322

Elapsed: 00:00:00.02
22:21:27 SQL> insert into hemant.test_adg_dml select * from dba_objects;

73661 rows created.

Elapsed: 00:00:08.60
22:21:50 SQL> select count(*) from hemant.test_adg_dml;

  COUNT(*)
----------
    220983

Elapsed: 00:00:00.01
22:22:06 SQL> commit;

Commit complete.

Elapsed: 00:00:00.21
22:22:08 SQL>
22:22:43 SQL> select name, db_unique_name, database_role, open_mode from v$database;

NAME      DB_UNIQUE_NAME                 DATABASE_ROLE    OPEN_MODE
--------- ------------------------------ ---------------- --------------------
ORCLCDB   STDBNEW                        PHYSICAL STANDBY READ ONLY WITH APPLY

Elapsed: 00:00:00.01
22:22:44 SQL>


So, this proves that we can run ADG and DML Redirection concurrently from multiple Standbys.

Let me test Locking.

I run a DML from STDBYDB and then try a similar DML from the Primary.


22:24:35 SQL> select name, open_mode from v$pdbs;

NAME
--------------------------------------------------------------------------------------------------------------------------------
OPEN_MODE
----------
ORCLPDB1
READ ONLY


Elapsed: 00:00:00.00
22:24:40 SQL> show user
USER is "HEMANT"
22:24:45 SQL> delete hemant.test_adg_dml;

220983 rows deleted.

Elapsed: 00:00:17.20
22:25:16 SQL>
--- no COMMIT has been issued yet !


-- now this is on the Primary !
22:26:18 SQL> select name, db_unique_name, database_role, open_mode from v$database
22:26:25   2  /

NAME      DB_UNIQUE_NAME                 DATABASE_ROLE    OPEN_MODE
--------- ------------------------------ ---------------- --------------------
ORCLCDB   ORCLCDB                        PRIMARY          READ WRITE

Elapsed: 00:00:00.39
22:26:27 SQL> select name, open_mode from v$pdbs;

NAME
--------------------------------------------------------------------------------------------------------------------------------
OPEN_MODE
----------
ORCLPDB1
READ WRITE


Elapsed: 00:00:00.12
22:26:33 SQL> delete hemant.test_adg_dml;


This goes into an indefinite WAIT on the Primary
--- from another session, I use utllockt to identify the Blocker and Waiter at the Primary
WAITING_SESSION   LOCK_TYPE         MODE_REQUESTED MODE_HELD      LOCK_ID1          LOCK_ID2
----------------- ----------------- -------------- -------------- ----------------- -----------------
135               None
   391            Transaction       Exclusive      Exclusive      65541             5609

22:29:26 SQL> select s.sid, s.sql_id, sq.sql_text
22:30:47   2  from v$session s, v$sql sq
22:30:53   3  where s.sid in (135,391)
22:31:08   4  and s.sql_id=sq.sql_id
22:31:12   5  /

       SID SQL_ID
---------- -------------
SQL_TEXT
------------------------------------------------------------------------------------------------------------------------------------
       135 9utz9bdavk3bz
DELETE FROM "HEMANT"."TEST_ADG_DML" "A1"

       391 4kmzmr764b4k6
delete hemant.test_adg_dml


22:31:13 SQL>
--- SID=135 is the remote session from the STDBYDB instance


To reconfirm, this, I deliberately, change the SQL Text and try again

--- this from STDBYDB
22:33:19 SQL> rollback;

Rollback complete.

Elapsed: 00:00:52.76
22:34:27 SQL>
22:34:51 SQL> select name, db_unique_name, database_role, open_mode from v$database;

NAME      DB_UNIQUE_NAME                 DATABASE_ROLE    OPEN_MODE
--------- ------------------------------ ---------------- --------------------
ORCLCDB   STDBYDB                        PHYSICAL STANDBY READ ONLY WITH APPLY

Elapsed: 00:00:00.02
22:34:53 SQL> select name, open_mode from v$pdbs;

NAME
--------------------------------------------------------------------------------------------------------------------------------
OPEN_MODE
----------
ORCLPDB1
READ ONLY


Elapsed: 00:00:00.00
22:35:03 SQL>
22:35:50 SQL> delete /*+ Hint here from STDYBDB */ from hemant.test_adg_dml;

220983 rows deleted.

Elapsed: 00:00:06.78
22:36:27 SQL>

--- this from ORCLCDB
22:34:37 SQL> rollback;

Rollback complete.

Elapsed: 00:00:08.44
22:34:53 SQL>
22:36:41 SQL> select name, db_unique_name, database_role, open_mode from v$database;

NAME      DB_UNIQUE_NAME                 DATABASE_ROLE    OPEN_MODE
--------- ------------------------------ ---------------- --------------------
ORCLCDB   ORCLCDB                        PRIMARY          READ WRITE

Elapsed: 00:00:00.24
22:37:21 SQL> select name, open_mode from v$pdbs;

NAME
--------------------------------------------------------------------------------------------------------------------------------
OPEN_MODE
----------
ORCLPDB1
READ WRITE


Elapsed: 00:00:00.00
22:37:30 SQL> DELETE  /*+ I am the Primary */ hemant.test_adg_dml target_table;


Again goes into an Indefnite WAIT at the Primary
-- now check using utllockt at the Primary
WAITING_SESSION   LOCK_TYPE         MODE_REQUESTED MODE_HELD      LOCK_ID1          LOCK_ID2
----------------- ----------------- -------------- -------------- ----------------- -----------------
135               None
   391            Transaction       Exclusive      Exclusive      393247            7239


SQL> select s.sid, sq.sql_text
  2  from v$session s, v$sql sq
  3  where s.sid in (135, 391)
  4  and s.sql_id = sq.sql_id
  5  /

       SID
----------
SQL_TEXT
------------------------------------------------------------------------------------------------------------------------------------
       135
DELETE FROM "HEMANT"."TEST_ADG_DML" "A1"

       391
DELETE  /*+ I am the Primary */ hemant.test_adg_dml target_table


SQL>

---- apparently, when the Standby sends the SQL to the Primary it is rewritten as UPPER CASE
---- and the Invalid Hint that is a Comment is removed
---- nevertheless, this proves that SID=135 from the Standby is the Blocker and SID=391 on the Primary is the Waiter

So, this proves that DML Redirection from an ADG Standby does take locks and prevents concurrent DML against the same rows on the Primary (and, by extension, on any other ADG Standby)


Note :  According to Oracle's documentation the DML Redirect feature is for "read-mostly applications, which occasionally execute DMLs, on the standby database."    .  I wouldn't advise trying this for all sessions at the Instance ("alter system") level but only to be used occasionally at session level.


Update :  If the Primary goes down / shuts down, an ADG with DML Redirection will show
ORA-03150: end-of-file on communication channel for database link
ORA-02063: preceding line from ADGREDIRECT
at the next call 

29 August, 2021

Identifying Patches applied to an Oracle Installation and Database

"opatch" and "datapatch" are the methods to apply Oracle Patches in recent versions.

"opatch" applies updates to the library and binary files to the ORACLE_HOME at the OS level.

"datapatch" then applies the corresponding changes to the data dictionary in the database.  Note that if you have multiple databases running from the same ORACLE_HOME, you must run "datapatch" against each database.  Also, if you later create a new database [most of us use a template / script to do so], you must run "datapatch" against the new database as well.

The instructions for both "opatch" and "datapatch"  (including the pre-requisite checks) are included in the README file that accompanies each patch.   See Mike Dietrich's blog post on how to apply the July 2021 Release Update Patch


Here is a quick demo of the commands to identify patches that are applied.


oracle19c>$ORACLE_HOME/OPatch/opatch version
OPatch Version: 12.2.0.1.25

OPatch succeeded.
oracle19c>
oracle19c>$ORACLE_HOME/OPatch/opatch lspatches
32876380;OJVM RELEASE UPDATE: 19.12.0.0.210720 (32876380)
32904851;Database Release Update : 19.12.0.0.210720 (32904851)
29585399;OCW RELEASE UPDATE 19.3.0.0.0 (29585399)

OPatch succeeded.
oracle19c>
oracle19c>$ORACLE_HOME/OPatch/opatch lsinventory
Oracle Interim Patch Installer version 12.2.0.1.25
Copyright (c) 2021, Oracle Corporation.  All rights reserved.


Oracle Home       : /opt/oracle/product/19c/dbhome_1
Central Inventory : /opt/oracle/oraInventory
   from           : /opt/oracle/product/19c/dbhome_1/oraInst.loc
OPatch version    : 12.2.0.1.25
OUI version       : 12.2.0.7.0
Log file location : /opt/oracle/product/19c/dbhome_1/cfgtoollogs/opatch/opatch2021-08-29_21-20-33PM_1.log

Lsinventory Output file location : /opt/oracle/product/19c/dbhome_1/cfgtoollogs/opatch/lsinv/lsinventory2021-08-29_21-20-33PM.txt
--------------------------------------------------------------------------------
Local Machine Information::
Hostname: ora19cs1
ARU platform id: 226
ARU platform description:: Linux x86-64

Installed Top-level Products (1):

Oracle Database 19c                                                  19.0.0.0.0
There are 1 products installed in this Oracle Home.


Interim patches (3) :

Patch  32876380     : applied on Mon Aug 09 22:59:39 GMT+08:00 2021
Unique Patch ID:  24269510
Patch description:  "OJVM RELEASE UPDATE: 19.12.0.0.210720 (32876380)"
   Created on 5 Jul 2021, 04:53:50 hrs UTC
   Bugs fixed:
     29445548, 29254623, 29540327, 29774362, 30134746, 30160625, 30534662
     29512125, 29942275, 30855101, 31306261, 31359215, 30895577, 29224710
     26716835, 31668872, 32165759, 32069696, 32032733, 30889443, 30674373
     32167592, 32523206, 29415774, 28777073, 32124570, 31247838, 29540831
     32892883, 31776121

Patch  32904851     : applied on Mon Aug 09 21:44:24 GMT+08:00 2021
Unique Patch ID:  24343243
Patch description:  "Database Release Update : 19.12.0.0.210720 (32904851)"
   Created on 20 Jul 2021, 09:21:24 hrs UTC
   Bugs fixed:
     7391838, 8460502, 8476681, 14570574, 14735102, 15931756, 16662822
     16664572, 16750494, 17275499, 17395507, 17428816, 17468475, 17777718
     18534283, 18697534, 19080742, 19138896, 19697993, 20007421, 20083476
     20313356, 20319830, 20479545, 20867658, 20922160, 21119541, 21232786
     21245711, 21374587, 21528318, 21629064, 21639146, 21888352, 21965541
     22066547, 22252368, 22325312, 22387320, 22580355, 22725871, 22729345
     22748979, 23020668, 23094775, 23125587, 23294761, 23296836, 23311885
     23606241, 23645975, 23734075, 23763462, 24336782, 24356932, 24561942
     24596874, 24669730, 24687075, 24833686, 24957575, 24971456, 25030027
     25092651, 25093917, 25148135, 25404117, 25416731, 25560538, 25562258
     25607406, 25607716, 25756945, 25792962, 25804387, 25804908, 25806201
...
... cut short a VERY LONG LIST of Bug Numbers
...
     32677702, 32686850, 32697781, 32698569, 32700989, 32704765, 32711741
     32712220, 32716726, 32718316, 32720458, 32725484, 32728984, 32738356
     32739966, 32740503, 32754845, 32758096, 32765738, 32784393, 32784403
     32786309, 32795712, 32810668, 32811069, 32811131, 32816003, 32817950
     32818019, 32858446, 32874995, 32881853, 32889434, 32895105, 32900208
     32902635, 32936961, 32941509, 32996071, 33034103, 33048277, 33127032
     32490416

Patch  29585399     : applied on Thu Apr 18 15:21:33 GMT+08:00 2019
Unique Patch ID:  22840393
Patch description:  "OCW RELEASE UPDATE 19.3.0.0.0 (29585399)"
   Created on 9 Apr 2019, 19:12:47 hrs PST8PDT
   Bugs fixed:
     27222128, 27572040, 27604329, 27760043, 27877830, 28302580, 28470673
     28621543, 28642469, 28699321, 28710663, 28755846, 28772816, 28785321
     28800508, 28808652, 28815557, 28847541, 28847572, 28870496, 28871040
     28874416, 28877252, 28881191, 28881848, 28888083, 28911140, 28925250
     28925460, 28935956, 28940472, 3, 28942694, 28951332, 28963036, 28968779
     28980448, 28995287, 29003207, 29003617, 29016294, 29018680, 29024876
     29026154, 29027933, 29047127, 29052850, 29058476, 29111631, 29112455
     29117337, 29123444, 29125708, 29125786, 29129476, 29131772, 29132456
     29139727, 29146157, 29147849, 29149170, 29152603, 29152752, 29154631
     29154636, 29154829, 29159216, 29159661, 29160462, 29161923, 29169540
     29169739, 29170717, 29173618, 29181568, 29182920, 29183298, 29186091
     29191827, 29201143, 29201695, 29209545, 29210577, 29210610, 29210624
     29210683, 29213641, 29219627, 29224294, 29225861, 29229839, 29235934
     29242906, 29243749, 29244495, 29244766, 29244968, 29248723, 29249583
     29251564, 29255616, 29260224, 29261695, 29271019, 29273360, 29282090
     29282666, 29285453, 29285621, 29290235, 29292232, 29293806, 29294753
     29299830, 29307090, 29307109, 29311336, 29329675, 29330791, 29339299
     29357821, 29360467, 29360775, 29367971, 29368725, 29379299, 29379381
     29380527, 29381000, 29382296, 29391301, 29393649, 29402110, 29411931
     29413360, 29457319, 29465047



--------------------------------------------------------------------------------

OPatch succeeded.
oracle19c>


The first command "opatch version" shows the current version
The second command "opatch lspatches" provides a high level listing of the patches that have been applied.
The third command "opatch lsinventory" provides a detailed listing of the patches that includes the dates when they were applied by the DBA, the dates they were actually created and released by Oracle Development / Support and each individual Bug# numbers fixed in the patches.  
Release Updates in 12.2 and higher are cumulative.  Here, "19.12.0.0.210720" indicates that I have applied the 19.12 Release Update of July 2021 ("2107" from the patch identifier)


Another method, using sql is the DBMS_QOPATCH package which has been implemented and substantially improved in recent releases.  (Oracle Support Document "How to Find PSU/One-off Patches is Applied Using QOPatch(DBMS_QOPATCH) (Doc ID 2169610.1)" is a good starting point :


SQL> set pages50000
SQL> set long 100000
SQL> spool dbms_qopatch_lsinventory.TXT
SQL> select dbms_qopatch.get_opatch_lsinventory from dual;
...
...
SQL> spool off
SQL> quit
Disconnected from Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.12.0.0.0
oracle19c>ls -l dbms_qopatch_lsinventory.TXT
-rw-r--r--. 1 oracle oinstall 237880 Aug 29 21:50 dbms_qopatch_lsinventory.TXT
oracle19c>
oracle19c>wc -l dbms_qopatch_lsinventory.TXT
1792 dbms_qopatch_lsinventory.TXT

dbms_qopatch.get_opatch_lsinventory


Since my output file from the dbms_qopatch.get_opatch_lsinventory is very long (1792 lines, 237KBytes, I've presented a screenshot of some of the lines f rom the file).  In addition to showing Bug# numbers, it also shows the Bug Titles (i.e. Descriptions) which the command-line opatch lsinventory doe not provide.


DBMS_QOPATCH is very useful.  You can query to check if a certain Patch has been installed (Patch 32904851 is the July 2021 Release Update Patch 19.12 that I installed on 09-Aug-2021).


SQL> set pages5000
SQL> set pages50000
SQL> set long 1000000
SQL> set pages50000
SQL> set long 1000000
SQL> select xmltransform(dbms_qopatch.is_patch_installed('32904851'),dbms_qopatch.get_opatch_xslt) from dual;

XMLTRANSFORM(DBMS_QOPATCH.IS_PATCH_INSTALLED('32904851'),DBMS_QOPATCH.GET_OPATCH_XSLT)
------------------------------------------------------------------------------------------------------------------------------------

Patch Information:
         32904851:   applied on 2021-08-09T21:44:24+08:00


SQL>
SQL>


"opatch" only lists patches that are applied to the ORACLE_HOME.  However, you must also confirm if the database data dictionary has also been updated -- which would be so if "datapatch" has been executed.  (side note : "datapatch" also has a number of command-line arguments which you might want to explore)


This information is in the dba_registry and dba_registry_sqlpatch  views in the database


SQL> set linesize 132
SQL> select * from dba_registry_history order by action_time;

ACTION_TIME                                                                 ACTION
--------------------------------------------------------------------------- ------------------------------
NAMESPACE                      VERSION                                ID
------------------------------ ------------------------------ ----------
COMMENTS
------------------------------------------------------------------------------------------------------------------------------------
BUNDLE_SERIES
------------------------------
04-MAY-19 11.30.32.133846 PM                                                RU_APPLY
SERVER                         19.0.0.0.0
Patch applied on 19.3.0.0.0: Release_Update - 190410122720


09-AUG-21 10.13.42.105236 PM                                                RU_APPLY
SERVER                         19.0.0.0.0
Patch applied from 19.3.0.0.0 to 19.12.0.0.0: Release_Update - 210716141810


09-AUG-21 11.10.15.544636 PM                                                jvmpsu.sql
SERVER                         19.12.0.0.210720OJVMRU                  0
RAN jvmpsu.sql


09-AUG-21 11.10.15.722597 PM                                                APPLY
SERVER                         19.12.0.0.210720OJVMRU                  0
OJVM RU post-install


                                                                            BOOTSTRAP
DATAPATCH                      19
RDBMS_19.12.0.0.0DBRU_LINUX.X64_210715



SQL>
SQL> select * from dba_registry_sqlpatch order by action_time;

INSTALL_ID   PATCH_ID  PATCH_UID PATCH_TYPE ACTION          STATUS
---------- ---------- ---------- ---------- --------------- -------------------------
ACTION_TIME
---------------------------------------------------------------------------
DESCRIPTION
----------------------------------------------------------------------------------------------------
LOGFILE
------------------------------------------------------------------------------------------------------------------------------------
RU_LOGFILE
------------------------------------------------------------------------------------------------------------------------------------
FLAGS
----------
PATCH_DESCRIPTOR
------------------------------------------------------------------------------------------------------------------------------------
PATCH_DIRECTORY
------------------------------------------------------------------------------------------------------------------------------------
SOURCE_VERSION  SOURCE_BUILD_DESCRIPTION
--------------- --------------------------------------------------------------------------------
SOURCE_BUILD_TIMESTAMP                                                      TARGET_VERSION
--------------------------------------------------------------------------- ---------------
TARGET_BUILD_DESCRIPTION
--------------------------------------------------------------------------------
TARGET_BUILD_TIMESTAMP
---------------------------------------------------------------------------
         1   29517242   22862832 RU         APPLY           SUCCESS
04-MAY-19 11.31.01.355942 PM
Database Release Update : 19.3.0.0.190416 (29517242)
/opt/oracle/cfgtoollogs/sqlpatch/29517242/22862832/29517242_apply_ORCLCDB_CDBROOT_2019May04_23_23_03.log
/opt/oracle/cfgtoollogs/sqlpatch/29517242/22862832/29517242_ru_apply_ORCLCDB_CDBROOT_2019May04_23_22_59.log
N

sqlPatch ID="29517242" uniquePatchID=

19.1.0.0.0      Feature Release
                                                                            19.3.0.0.0
Release_Update
10-APR-19 12.27.20.000000 PM



         2   32904851   24343243 RU         APPLY           SUCCESS
09-AUG-21 10.35.37.696526 PM
Database Release Update : 19.12.0.0.210720 (32904851)
/opt/oracle/cfgtoollogs/sqlpatch/32904851/24343243/32904851_apply_ORCLCDB_CDBROOT_2021Aug09_22_04_05.log
/opt/oracle/cfgtoollogs/sqlpatch/32904851/24343243/32904851_ru_apply_ORCLCDB_CDBROOT_2021Aug09_22_03_59.log
N

sqlPatch ID="32904851" uniquePatchID=

19.3.0.0.0      Release_Update
10-APR-19 12.27.20.000000 PM                                                19.12.0.0.0
Release_Update
16-JUL-21 02.18.10.000000 PM



         3   32876380   24269510 INTERIM    APPLY           SUCCESS
09-AUG-21 11.12.07.815060 PM
OJVM RELEASE UPDATE: 19.12.0.0.210720 (32876380)
/opt/oracle/cfgtoollogs/sqlpatch/32876380/24269510/32876380_apply_ORCLCDB_CDBROOT_2021Aug09_23_06_42.log

NJ

sqlPatch ID="32876380" uniquePatchID=
504B03041400000008007A77E552F6AD657DF40100006C0400000C00000033323837363338302E786D6CB5534D73DA3014BCFB57BCEAD41EC01F044232B6339EE076
C804C81092999E3A8A2D374A6559
19.12.0.0.0     Release_Update
16-JUL-21 02.18.10.000000 PM                                                19.12.0.0.0
Release_Update
16-JUL-21 02.18.10.000000 PM


SQL>


The first query shows that "datapatch" was executed on 09-Aug-21 and the second query shows that it executed the changes for both Patches 32904851 (Database Release Update) and 32876380 (OJVM Release Update)


14 August, 2021

Restoring Standby Database after Failover

 In the previous post, I demonstrated how the Database Incarnation changed after a Failover was issued for a Standby Database.

Let's assume that Read-Write testing of the Standby has been done and now I need to restore and revert STDBYDB to the state of being a Standby for ORCLCDB


The Primary is still at Database Incarnation#=3  and is now at Sequence#=409



SQL> show parameter db_unique_name

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
db_unique_name                       string      ORCLCDB
SQL> select incarnation#
  2  from v$database_incarnation
  3  where status = 'CURRENT'
  4  /

INCARNATION#
------------
           3

SQL> archive log list;
Database log mode              Archive Mode
Automatic archival             Enabled
Archive destination            /opt/oracle/archivelog/ORCLCDB
Oldest online log sequence     407
Next log sequence to archive   409
Current log sequence           409
SQL>


The former Standby STDBYDB has already diverged and is at Incarnation#=4 and its current Sequence#=5


SQL> show parameter db_unique_name

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
db_unique_name                       string      STDBYDB
SQL> select incarnation#
  2  from v$database_incarnation
  3  where status = 'CURRENT'
  4  /

INCARNATION#
------------
           4

SQL> archive log list
Database log mode              Archive Mode
Automatic archival             Enabled
Archive destination            /opt/oracle/archivelog/STDBYDB
Oldest online log sequence     3
Next log sequence to archive   5
Current log sequence           5
SQL>


I now delete all the datafiles STDBYDB and restore the the backup that I made before I executed the Failover (see the previous blog post)


SQL> shutdown immediate;
Database closed.
Database dismounted.
ORACLE instance shut down.
SQL> quit
Disconnected from Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.12.0.0.0
oracle19c>cd
oracle19c>sh ./to_delete_STDBYDB.SH
oracle19c>
oracle19c>echo $ORACLE_SID
STDBYDB
oracle19c>rman target /

Recovery Manager: Release 19.0.0.0.0 - Production on Sat Aug 14 17:49:50 2021
Version 19.12.0.0.0

Copyright (c) 1982, 2019, Oracle and/or its affiliates.  All rights reserved.

connected to target database (not started)

RMAN> startup nomount;

Oracle instance started

Total System Global Area    1207955544 bytes

Fixed Size                     9134168 bytes
Variable Size                486539264 bytes
Database Buffers             704643072 bytes
Redo Buffers                   7639040 bytes

RMAN> restore controlfile from '/opt/oracle/FRA/STDBYDB/STDBYDB/autobackup/2021_08_13/o1_mf_s_1080515319_jkf2tzhp_.bkp';

Starting restore at 14-AUG-21
using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=245 device type=DISK

channel ORA_DISK_1: restoring control file
channel ORA_DISK_1: restore complete, elapsed time: 00:00:03
output file name=/opt/oracle/oradata/STDBYDB/control01.ctl
output file name=/opt/oracle/oradata/STDBYDB/control02.ctl
Finished restore at 14-AUG-21

RMAN> quit


Recovery Manager complete.
oracle19c>echo $ORACLE_SID
STDBYDB
oracle19c>sqlplus '/ as sysdba'

SQL*Plus: Release 19.0.0.0.0 - Production on Sat Aug 14 17:52: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 mount;

Database altered.

SQL>  show parameter db_unique_name

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
db_unique_name                       string      STDBYDB
SQL> select database_role, open_mode
  2  from v$database
  3  /

DATABASE_ROLE    OPEN_MODE
---------------- --------------------
PHYSICAL STANDBY MOUNTED

SQL> select incarnation#, resetlogs_change#, to_char(resetlogs_time,'DD-MON-RR HH24:MI') resetlogs_time,
  2  status, resetlogs_id
  3  from v$database_incarnation
  4  order by 1
  5  /

INCARNATION# RESETLOGS_CHANGE# RESETLOGS_TIME           STATUS  RESETLOGS_ID
------------ ----------------- ------------------------ ------- ------------
           1                 1 17-APR-19 00:55          PARENT    1005785759
           2           1920977 04-MAY-19 23:21          PARENT    1007421686
           3           4797184 27-MAR-20 00:00          CURRENT   1036108814

SQL>


So, this restored Controlfile confirms that I have a Standby Database that is now back at Incarnation#=3.
I can now proceed to restore the database and I assume that I can reapply all the ArchiveLogs from the Primary which is also at Incarnation#=3


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 Sat Aug 14 17:56:06 2021
Version 19.12.0.0.0

Copyright (c) 1982, 2019, Oracle and/or its affiliates.  All rights reserved.

connected to target database: ORCLCDB (DBID=2778483057, not open)

RMAN> restore database;

Starting restore at 14-AUG-21
using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=11 device type=DISK
allocated channel: ORA_DISK_2
channel ORA_DISK_2: SID=129 device type=DISK

channel ORA_DISK_1: starting datafile backup set restore
channel ORA_DISK_1: specifying datafile(s) to restore from backup set
channel ORA_DISK_1: restoring datafile 00003 to /opt/oracle/oradata/STDBYDB/sysaux01.dbf
channel ORA_DISK_1: restoring datafile 00007 to /opt/oracle/oradata/STDBYDB/users01.dbf
channel ORA_DISK_1: reading from backup piece /opt/oracle/FRA/STDBYDB/STDBYDB/backupset/2021_08_13/o1_mf_nnndf_TAG20210813T230720_jkf2ob5r_.bkp
channel ORA_DISK_2: starting datafile backup set restore
channel ORA_DISK_2: specifying datafile(s) to restore from backup set
channel ORA_DISK_2: restoring datafile 00001 to /opt/oracle/oradata/STDBYDB/system01.dbf
channel ORA_DISK_2: restoring datafile 00004 to /opt/oracle/oradata/STDBYDB/undotbs01.dbf
channel ORA_DISK_2: reading from backup piece /opt/oracle/FRA/STDBYDB/STDBYDB/backupset/2021_08_13/o1_mf_nnndf_TAG20210813T230720_jkf2o9j4_.bkp
....
....
....

channel ORA_DISK_2: restored backup piece 1
channel ORA_DISK_2: restore complete, elapsed time: 00:00:36
Finished restore at 14-AUG-21

RMAN> quit


Recovery Manager complete.
oracle19c>sqlplus '/ as sysdba'

SQL*Plus: Release 19.0.0.0.0 - Production on Sat Aug 14 18:01:50 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> show parameter db_unique_name

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
db_unique_name                       string      STDBYDB
SQL> select database_role, open_mode
  2  from v$database
  3  /

DATABASE_ROLE    OPEN_MODE
---------------- --------------------
PHYSICAL STANDBY MOUNTED

SQL> select incarnation#, resetlogs_change#, to_char(resetlogs_time,'DD-MON-RR HH24:MI') resetlogs_time,
  2  status, resetlogs_id
  3  from v$database_incarnation
  4  order by 1
  5  /

INCARNATION# RESETLOGS_CHANGE# RESETLOGS_TIME           STATUS  RESETLOGS_ID
------------ ----------------- ------------------------ ------- ------------
           1                 1 17-APR-19 00:55          PARENT    1005785759
           2           1920977 04-MAY-19 23:21          PARENT    1007421686
           3           4797184 27-MAR-20 00:00          CURRENT   1036108814

SQL>


Let my now try to Recover this Database as a Standby using ArchiveLogs from the PrimaryR (after " alter system set log_archive_dest_state_2='enable';" at the Primary)


SQL> select l.group#, l.bytes/1048576, l.status, f.member
  2  from v$standby_log l, v$logfile f
  3  where l.group#=f.group#
  4  order by 1
  5  /

    GROUP# L.BYTES/1048576 STATUS
---------- --------------- ----------
MEMBER
------------------------------------------------------------------------------------------------------------------------------------
         4             200 ACTIVE
/opt/oracle/oradata/STDBYDB/stdbredo01.log

         5             200 ACTIVE
/opt/oracle/oradata/STDBYDB/stdbredo02.dbf


SQL> alter database clear logfile group 4;

Database altered.

SQL> alter database clear logfile group 5;

Database altered.

SQL>
SQL>  select l.group#, l.bytes/1048576, l.status, f.member
  2  from v$standby_log l, v$logfile f
  3  where l.group#=f.group#
  4  order by 1
  5  /

    GROUP# L.BYTES/1048576 STATUS
---------- --------------- ----------
MEMBER
------------------------------------------------------------------------------------------------------------------------------------
         4             200 UNASSIGNED
/opt/oracle/oradata/STDBYDB/stdbredo01.log

         5             200 UNASSIGNED
/opt/oracle/oradata/STDBYDB/stdbredo02.dbf


SQL>
SQL> alter database recover managed standby database using current logfile disconnect from session;

Database altered.

SQL>


STDBYDB takes a few minutes to get all the ArchiveLogs from Sequence#402 onwards and apply them


2021-08-14T18:16:46.242533+08:00
 rfs (PID:24643): Selected LNO:5 for T-1.S-416 dbid 2778483057 branch 1036108814
2021-08-14T18:16:46.279518+08:00
ARC1 (PID:15987): Archived Log entry 19 added for T-1.S-415 ID 0xa7521ccd LAD:1
2021-08-14T18:16:46.408474+08:00
PR00 (PID:23234): Media Recovery Waiting for T-1.S-416 (in transit)
2021-08-14T18:16:46.420169+08:00
Recovery of Online Redo Log: Thread 1 Group 5 Seq 416 Reading mem 0
  Mem# 0: /opt/oracle/oradata/STDBYDB/stdbredo02.dbf


The Primary also now shows :


SQL> l
  1  select dest_id, db_unique_name, status, type, archived_seq#, applied_seq#, synchronized, gap_status
  2  from v$archive_dest_status
  3  where dest_id in (1,2,3)
  4* order by 1
SQL> /

   DEST_ID DB_UNIQUE_NAME                 STATUS    TYPE             ARCHIVED_SEQ# APPLIED_SEQ# SYN GAP_STATUS
---------- ------------------------------ --------- ---------------- ------------- ------------ --- ------------------------
         1 NONE                           VALID     LOCAL                      415            0 NO
         2 STDBYDB                        VALID     PHYSICAL                   415          414 YES NO GAP
         3 STDB2                          VALID     PHYSICAL                   415          405 NO  NO GAP

SQL>

I can also see the ArchiveLogs that were generated from STDBYDB :

oracle19c>pwd
/opt/oracle/archivelog/STDBYDB
oracle19c>ls -latr
total 196820
drwxr-xr-x. 6 oracle oinstall       63 Aug 11 14:25 ..
-rw-r-----. 1 oracle oinstall   269824 Aug 13 22:47 1_394_1036108814.dbf
-rw-r-----. 1 oracle oinstall  4147200 Aug 13 23:02 1_399_1036108814.dbf
-rw-r-----. 1 oracle oinstall     3584 Aug 13 23:02 1_400_1036108814.dbf
-rw-r-----. 1 oracle oinstall    24064 Aug 13 23:02 1_401_1036108814.dbf
-rw-r-----. 1 oracle oinstall     3072 Aug 13 23:03 1_402_1036108814.dbf
-rw-r-----. 1 oracle oinstall     1024 Aug 13 23:13 1_1_1080515513.dbf
-rw-r-----. 1 oracle oinstall 21302784 Aug 14 17:13 1_2_1080515513.dbf
-rw-r-----. 1 oracle oinstall 96683520 Aug 14 17:41 1_3_1080515513.dbf
-rw-r-----. 1 oracle oinstall    14848 Aug 14 17:42 1_4_1080515513.dbf
-rw-r-----. 1 oracle oinstall    45568 Aug 14 18:04 1_405_1036108814.dbf
-rw-r-----. 1 oracle oinstall   703488 Aug 14 18:04 1_404_1036108814.dbf
-rw-r-----. 1 oracle oinstall   486400 Aug 14 18:04 1_403_1036108814.dbf
-rw-r-----. 1 oracle oinstall 20830208 Aug 14 18:04 1_406_1036108814.dbf
-rw-r-----. 1 oracle oinstall  5378048 Aug 14 18:04 1_407_1036108814.dbf
-rw-r-----. 1 oracle oinstall   538112 Aug 14 18:04 1_408_1036108814.dbf
-rw-r-----. 1 oracle oinstall  4228096 Aug 14 18:04 1_409_1036108814.dbf
-rw-r-----. 1 oracle oinstall     4096 Aug 14 18:04 1_410_1036108814.dbf
-rw-r-----. 1 oracle oinstall   197120 Aug 14 18:07 1_411_1036108814.dbf
-rw-r-----. 1 oracle oinstall   176128 Aug 14 18:16 1_414_1036108814.dbf
-rw-r-----. 1 oracle oinstall   489984 Aug 14 18:16 1_412_1036108814.dbf
-rw-r-----. 1 oracle oinstall    91136 Aug 14 18:16 1_413_1036108814.dbf
-rw-r-----. 1 oracle oinstall     4096 Aug 14 18:16 1_415_1036108814.dbf
drwxr-xr-x. 2 oracle oinstall     4096 Aug 14 18:25 .
-rw-r-----. 1 oracle oinstall 45876224 Aug 14 18:25 1_416_1036108814.dbf
oracle19c>

Note how Sequence#1 to Sequence#4 were generated in the new Incarnation with Resetlogs ID 1080515513.  This was the Resetlogs ID assigned when STDBYDB was opened with Failover, thus a New Incarnation and effectively a Resetlogs. Sequence#403 onwards are from the Primary with Resetlogs ID 1036108814
(You can check the Resetlogs IDs shown in the previous blog post)

13 August, 2021

Failover and Database Incarnation

In previous blog posts, I have demonstrated : 

1.  Using Flashback Database for [destructive] testing at a Standby

2.  Using Snapshot Standby Database for [destructive] testing at a Standby



In this blog post, I will demonstrate the Database Incarnation feature when a Failover is executed.


This is the current status at the Primary :


SQL> show parameter db_unique_name

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
db_unique_name                       string      ORCLCDB
SQL> archive log list

SQL>
SQL> archive log list
Database log mode              Archive Mode
Automatic archival             Enabled
Archive destination            /opt/oracle/archivelog/ORCLCDB
Oldest online log sequence     401
Next log sequence to archive   403
Current log sequence           403
SQL>

SQL> select incarnation#, resetlogs_change#, to_char(resetlogs_time,'DD-MON-RR HH24:MI') resetlogs_time,
  2  status, resetlogs_id
  3  from v$database_incarnation
  4  order by 1
  5  /

INCARNATION# RESETLOGS_CHANGE# RESETLOGS_TIME           STATUS  RESETLOGS_ID
------------ ----------------- ------------------------ ------- ------------
           1                 1 17-APR-19 00:55          PARENT    1005785759
           2           1920977 04-MAY-19 23:21          PARENT    1007421686
           3           4797184 27-MAR-20 00:00          CURRENT   1036108814

SQL>
SQL> l
  1  select dest_id, db_unique_name, status, type, archived_seq#, applied_seq#, synchronized, gap_status
  2  from v$archive_dest_status
  3  where dest_id in (1,2,3)
  4* order by 1
SQL> /

   DEST_ID DB_UNIQUE_NAME STATUS    TYPE             ARCHIVED_SEQ# APPLIED_SEQ# SYN GAP_STATUS
---------- -------------- --------- ---------------- ------------- ------------ --- ------------------------
         1 NONE           VALID     LOCAL                      402            0 NO
         2 STDBYDB        VALID     PHYSICAL                   402          401 YES NO GAP
         3 STDB2          VALID     PHYSICAL                   402          384 NO  NO GAP

SQL>


And this is the current status at the first Standby (STDBYDB)


From the alert log :

2021-08-13T23:03:00.998407+08:00
Recovery of Online Redo Log: Thread 1 Group 4 Seq 403 Reading mem 0
  Mem# 0: /opt/oracle/oradata/STDBYDB/stdbredo01.log


SQL> show parameter db_unique_name

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
db_unique_name                       string      STDBYDB
SQL> select incarnation#, resetlogs_change#, to_char(resetlogs_time,'DD-MON-RR HH24:MI') resetlogs_time,
  2  status, resetlogs_id
  3  from v$database_incarnation
  4  order by 1
  5  /

INCARNATION# RESETLOGS_CHANGE# RESETLOGS_TIME           STATUS  RESETLOGS_ID
------------ ----------------- ------------------------ ------- ------------
           1                 1 17-APR-19 00:55          PARENT    1005785759
           2           1920977 04-MAY-19 23:21          PARENT    1007421686
           3           4797184 27-MAR-20 00:00          CURRENT   1036108814

SQL>


I now create a Backup of the Standby (STDBYDB) (for this test I will not be using Flashback Database or Snapshot Standby Database {see the first two blog posts listed at the beginning for demonstrations of both methods}) :


oracle19c>rman target /

Recovery Manager: Release 19.0.0.0.0 - Production on Fri Aug 13 23:07:04 2021
Version 19.12.0.0.0

Copyright (c) 1982, 2019, Oracle and/or its affiliates.  All rights reserved.

connected to target database: ORCLCDB (DBID=2778483057, not open)

RMAN> backup as compressed backupset database;

Starting backup at 13-AUG-21
Starting implicit crosscheck backup at 13-AUG-21
using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=128 device type=DISK
allocated channel: ORA_DISK_2
channel ORA_DISK_2: SID=252 device type=DISK
Crosschecked 10 objects
Crosschecked 11 objects
Finished implicit crosscheck backup at 13-AUG-21

Starting implicit crosscheck copy at 13-AUG-21
using channel ORA_DISK_1
using channel ORA_DISK_2
Finished implicit crosscheck copy at 13-AUG-21

searching for all files in the recovery area
cataloging files...
no files cataloged

using channel ORA_DISK_1
using channel ORA_DISK_2
channel ORA_DISK_1: starting compressed full datafile backup set
channel ORA_DISK_1: specifying datafile(s) in backup set
input datafile file number=00001 name=/opt/oracle/oradata/STDBYDB/system01.dbf
input datafile file number=00004 name=/opt/oracle/oradata/STDBYDB/undotbs01.dbf
channel ORA_DISK_1: starting piece 1 at 13-AUG-21
channel ORA_DISK_2: starting compressed full datafile backup set
channel ORA_DISK_2: specifying datafile(s) in backup set
input datafile file number=00003 name=/opt/oracle/oradata/STDBYDB/sysaux01.dbf
input datafile file number=00007 name=/opt/oracle/oradata/STDBYDB/users01.dbf
channel ORA_DISK_2: starting piece 1 at 13-AUG-21


....
....
....


Starting Control File and SPFILE Autobackup at 13-AUG-21
piece handle=/opt/oracle/FRA/STDBYDB/STDBYDB/autobackup/2021_08_13/o1_mf_s_1080515319_jkf2tzhp_.bkp comment=NONE
Finished Control File and SPFILE Autobackup at 13-AUG-21

RMAN>
RMAN> quit


Recovery Manager complete.
oracle19c>



I now execute a FAILOVER command at STDBYDB :


oracle19c>sqlplus '/ as sysdba'

SQL*Plus: Release 19.0.0.0.0 - Production on Fri Aug 13 23:11:08 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 recover managed standby database cancel;

Database altered.

SQL> show parameter db_unique_name

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
db_unique_name                       string      STDBYDB
SQL> alter database failover to STDBYDB;

Database altered.

SQL>
SQL> shutdown immediate;
ORA-01109: database not open


Database dismounted.
ORACLE instance shut down.
SQL> startup open;
ORACLE instance started.

Total System Global Area 1207955544 bytes
Fixed Size                  9134168 bytes
Variable Size             436207616 bytes
Database Buffers          754974720 bytes
Redo Buffers                7639040 bytes
Database mounted.
Database opened.
SQL> show parameter db_unique_name

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
db_unique_name                       string      STDBYDB
SQL>
SQL> select incarnation#, resetlogs_change#, to_char(resetlogs_time,'DD-MON-RR HH24:MI') resetlogs_time,
  2  status, resetlogs_id
  3  from v$database_incarnation
  4  order by 1
  5  /

INCARNATION# RESETLOGS_CHANGE# RESETLOGS_TIME           STATUS  RESETLOGS_ID
------------ ----------------- ------------------------ ------- ------------
           1                 1 17-APR-19 00:55          PARENT    1005785759
           2           1920977 04-MAY-19 23:21          PARENT    1007421686
           3           4797184 27-MAR-20 00:00          PARENT    1036108814
           4          14030903 13-AUG-21 23:11          CURRENT   1080515513

SQL>

>
The STDYDB alert log also shows :


2021-08-13T23:11:18.443497+08:00
alter database recover managed standby database cancel
2021-08-13T23:11:18.475672+08:00
PR00 (PID:354): MRP0: Background Media Recovery cancelled with status 16037
2021-08-13T23:11:18.475814+08:00
Errors in file /opt/oracle/diag/rdbms/stdbydb/STDBYDB/trace/STDBYDB_pr00_354.trc:
ORA-16037: user requested cancel of managed recovery operation
PR00 (PID:354): Managed Standby Recovery not using Real Time Apply
Recovery interrupted!
Recovered data files to a consistent state at change 14030850
Stopping change tracking
2021-08-13T23:11:18.858990+08:00
Errors in file /opt/oracle/diag/rdbms/stdbydb/STDBYDB/trace/STDBYDB_pr00_354.trc:
ORA-16037: user requested cancel of managed recovery operation
2021-08-13T23:11:19.004299+08:00
Background Media Recovery process shutdown (STDBYDB)
2021-08-13T23:11:19.477146+08:00
Managed Standby Recovery Canceled (STDBYDB)
Completed: alter database recover managed standby database cancel
2021-08-13T23:11:40.986985+08:00
alter database failover to STDBYDB

2021-08-13T23:11:40.987075+08:00
.... (PID:4479): The Time Management Interface (TMI) is being enabled for role transition
.... (PID:4479): information.  This will result in messages beingoutput to the alert log
.... (PID:4479): file with the prefix 'TMI: '.  This is being enabled to make the timing of
.... (PID:4479): the various stages of the role transition available for diagnostic purposes.
.... (PID:4479): This output will end when the role transition is complete.
TMI: dbsdrv failover to target BEGIN 2021-08-13 23:11:40.987474
Terminal Recovery requested in process 4479
TMI: adbdrv termRecovery BEGIN 2021-08-13 23:11:40.989180
2021-08-13T23:11:41.082414+08:00
Attempt to do a Terminal Recovery (STDBYDB)
TMI: adbdrv termRecovery END 2021-08-13 23:11:41.082472
2021-08-13T23:11:41.083019+08:00
Attempt to do a Terminal Recovery (STDBYDB)
TMI: adbdrv termRecovery END 2021-08-13 23:11:41.082472
2021-08-13T23:11:41.083019+08:00
Media Recovery Start: Managed Standby Recovery (STDBYDB)
 Started logmerger process
2021-08-13T23:11:41.141008+08:00
PR00 (PID:4636): Managed Standby Recovery not using Real Time Apply
2021-08-13T23:11:42.361339+08:00
max_pdb is 5
2021-08-13T23:11:43.009492+08:00
Parallel Media Recovery started with 4 slaves
2021-08-13T23:11:44.585417+08:00
Stopping change tracking
PR00 (PID:4636): Media Recovery Waiting for T-1.S-403 (in transit)
2021-08-13T23:11:45.982280+08:00
PR00 (PID:4636): Killing 3 processes (PIDS:375,391,394) (all RFS, wait for I/O) in order to disallow current and future RFS connections. Requested by OS process 4636
2021-08-13T23:11:45.982627+08:00
Process termination requested for pid 375 [source = rdbms], [info = 2] [request issued by pid: 4636, uid: 54321]
2021-08-13T23:11:45.983224+08:00
Process termination requested for pid 391 [source = rdbms], [info = 2] [request issued by pid: 4636, uid: 54321]
2021-08-13T23:11:45.983244+08:00
Process termination requested for pid 394 [source = rdbms], [info = 2] [request issued by pid: 4636, uid: 54321]
2021-08-13T23:11:47.984399+08:00
PR00 (PID:4636): Begin: SRL archival
PR00 (PID:4636): End: SRL archival
PR00 (PID:4636): Terminal Recovery timestamp is '08/13/2021 23:11:48'
2021-08-13T23:11:49.723810+08:00
PR00 (PID:4636): Terminal Recovery: applying standby redo logs.
PR00 (PID:4636): Terminal Recovery: thread 1 seq# 403 redo required
2021-08-13T23:11:49.887210+08:00
PR00 (PID:4636): Terminal Recovery:
2021-08-13T23:11:50.007728+08:00
Recovery of Online Redo Log: Thread 1 Group 4 Seq 403 Reading mem 0
  Mem# 0: /opt/oracle/oradata/STDBYDB/stdbredo01.log
2021-08-13T23:11:50.853550+08:00
Terminal Recovery finished with No-Data-Loss
2021-08-13T23:11:51.223461+08:00
Incomplete Recovery applied until change 14030902 time 08/13/2021 23:11:45
2021-08-13T23:11:51.329028+08:00
Media Recovery Complete (STDBYDB)
2021-08-13T23:11:52.416801+08:00
Terminal Recovery: successful completion

PR00 (PID:4636): Forcing ARSCN to IRSCN for TR SCN:0x0000000000d61836
PR00 (PID:4636): Attempt to set limbo arscn SCN:0x0000000000d61836 irscn SCN:0x0000000000d61836
PR00 (PID:4636): Resetting standby activation ID 2807176397 (0xa7521ccd)
Stopping change tracking
2021-08-13T23:11:52.625495+08:00
ALTER DATABASE SWITCHOVER TO PRIMARY (STDBYDB)
2021-08-13T23:11:52.626348+08:00
Maximum wait for role transition is 15 minutes.
TMI: kcv_commit_to_so_to_primary wait for MRP to finish BEGIN 2021-08-13 23:11:52.626362
TMI: kcv_commit_to_so_to_primary wait for MRP to finish END 2021-08-13 23:11:52.626450
TMI: kcv_commit_to_so_to_primary Switchover from physical BEGIN 2021-08-13 23:11:52.626957
Backup controlfile written to trace file /opt/oracle/diag/rdbms/stdbydb/STDBYDB/trace/STDBYDB_ora_4479.trc
Standby terminal recovery start SCN: 14030850
RESETLOGS after incomplete recovery UNTIL CHANGE 14030902 time 08/13/2021 23:11:45
NET  (PID:4479): ORL pre-clearing operation disabled by switchover
Online log /opt/oracle/oradata/STDBYDB/redo01.log: Thread 1 Group 1 was previously cleared
Online log /opt/oracle/oradata/STDBYDB/redo02.log: Thread 1 Group 2 was previously cleared
Online log /opt/oracle/oradata/STDBYDB/redo03.log: Thread 1 Group 3 was previously cleared
2021-08-13T23:11:53.667669+08:00
Standby became primary SCN: 14030849
2021-08-13T23:11:53.668267+08:00
Setting recovery target incarnation to 4
2021-08-13T23:11:53.715844+08:00

NET (PID:4479): RT: Role transition work is not done
NET (PID:4479): The Time Management Interface (TMI) is being enabled for role transition
NET (PID:4479): information. This will result in messages beingoutput to the alert log
NET (PID:4479): file with the prefix 'TMI: '. This is being enabled to make the timing of
NET (PID:4479): the various stages of the role transition available for diagnostic purposes.
NET (PID:4479): This output will end when the role transition is complete.
NET (PID:4479): Redo network throttle feature is disabled at mount time
2021-08-13T23:11:53.934288+08:00
NET (PID:4479): Database role cleared from PHYSICAL STANDBY [kcvs.c:1099]
Switchover: Complete - Database mounted as primary
TMI: kcv_commit_to_so_to_primary Switchover from physical END 2021-08-13 23:11:53.935283
TMI: dbsdrv failover to target END 2021-08-13 23:11:53.935372
Failover completed with No-Data-Loss.
Completed: alter database failover to STDBYDB

2021-08-13T23:12:16.059509+08:00
ARC1 (PID:32662): Becoming the 'no SRL' ARCH
2021-08-13T23:12:26.958308+08:00
Shutting down ORACLE instance (immediate) (OS id: 4479)
....
....
....
2021-08-13T23:12:45.501291+08:00
Instance shutdown complete (OS id: 4479)
....
....
....
2021-08-13T23:12:55.538734+08:00
Starting ORACLE instance (normal) (OS id: 5005)
....
....
....
2021-08-13T23:14:09.422553+08:00
CJQ0 started with pid=64, OS id=6101
Completed: ALTER DATABASE OPEN


Meanwhile, the Primary shows that it no longer communicates with STDBYDB


SQL> l
  1  select dest_id, db_unique_name, status, type, archived_seq#, applied_seq#, synchronized, gap_status
  2  from v$archive_dest_status
  3  where dest_id in (1,2,3)
  4* order by 1
SQL> /

   DEST_ID DB_UNIQUE_NAME STATUS    TYPE             ARCHIVED_SEQ# APPLIED_SEQ# SYN GAP_STATUS
---------- -------------- --------- ---------------- ------------- ------------ --- ------------------------
         1 NONE           VALID     LOCAL                      403            0 NO
         2 STDBYDB        ERROR     PHYSICAL                   401          401 NO  RESOLVABLE GAP
         3 STDB2          VALID     PHYSICAL                   403          386 NO  NO GAP

SQL>


from the alert log :
2021-08-13T23:02:58.137970+08:00
NET  (PID:32207): Archived Log entry 956 added for T-1.S-401 ID 0xa7521ccd LAD:1
2021-08-13T23:03:00.379365+08:00
ALTER SYSTEM ARCHIVE LOG
2021-08-13T23:03:01.008064+08:00
Thread 1 advanced to log sequence 403 (LGWR switch),  current SCN: 14029372
  Current log# 1 seq# 403 mem# 0: /opt/oracle/oradata/ORCLCDB/redo01.log
2021-08-13T23:03:01.143735+08:00
NET  (PID:32207): Archived Log entry 959 added for T-1.S-402 ID 0xa7521ccd LAD:1
2021-08-13T23:11:46.487983+08:00
LGWR (PID:3724): Attempting LAD:2 network reconnect (3113)
LGWR (PID:3724): LAD:2 network reconnect abandoned
2021-08-13T23:11:46.488223+08:00
Errors in file /opt/oracle/diag/rdbms/orclcdb/ORCLCDB/trace/ORCLCDB_lgwr_3724.trc:
ORA-03113: end-of-file on communication channel
LGWR (PID:3724): Error 3113 for LNO:1 to 'STDBYDB'
2021-08-13T23:11:46.532708+08:00
LGWR (PID:3724): LAD:2 is UNSYNCHRONIZED
2021-08-13T23:11:48.149800+08:00
LGWR (PID:3724): Failed to archive LNO:1 T-1.S-403, error=3113
LGWR (PID:3724): Error 1041 disconnecting from LAD:2 standby host 'STDBYDB'
2021-08-13T23:11:48.300060+08:00
Thread 1 advanced to log sequence 404 (LGWR switch),  current SCN: 14030909
  Current log# 2 seq# 404 mem# 0: /opt/oracle/oradata/ORCLCDB/redo02.log
2021-08-13T23:11:49.005544+08:00
ARC1 (PID:3853): Archived Log entry 961 added for T-1.S-403 ID 0xa7521ccd LAD:1
2021-08-13T23:13:23.840728+08:00
 rfs (PID:5505): krsr_rfs_atc: Identified database type as 'PRIMARY': Client is Foreground (PID:5166)
 rfs (PID:5505): Database mount ID mismatch [0xa9f74b79:0xa9f7dc16] (2851556217:2851593238)
 rfs (PID:5505): Not using real application clusters


So, now the STDBYDB database has diverged from the Primary at SCN#14030903 and no longer accepts Redo from the Primary.
The STDBYDB database is now at Incarnation#4


I can stop Redo Shipping from the Primary


SQL> show parameter db_unique_name

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
db_unique_name                       string      ORCLCDB
SQL> select incarnation#, resetlogs_change#, to_char(resetlogs_time,'DD-MON-RR HH24:MI') resetlogs_time,
  2  status, resetlogs_id
  3  from v$database_incarnation
  4  order by 1
  5  /

INCARNATION# RESETLOGS_CHANGE# RESETLOGS_TIME           STATUS  RESETLOGS_ID
------------ ----------------- ------------------------ ------- ------------
           1                 1 17-APR-19 00:55          PARENT    1005785759
           2           1920977 04-MAY-19 23:21          PARENT    1007421686
           3           4797184 27-MAR-20 00:00          CURRENT   1036108814

SQL>
SQL> l
  1  select dest_id, db_unique_name, status, type, archived_seq#, applied_seq#, synchronized, gap_status
  2  from v$archive_dest_status
  3  where dest_id in (1,2,3)
  4* order by 1
SQL> /

   DEST_ID DB_UNIQUE_NAME STATUS    TYPE             ARCHIVED_SEQ# APPLIED_SEQ# SYN GAP_STATUS
---------- -------------- --------- ---------------- ------------- ------------ --- ------------------------
         1 NONE           VALID     LOCAL                      403            0 NO
         2 STDBYDB        ERROR     PHYSICAL                   401          401 NO  RESOLVABLE GAP
         3 STDB2          VALID     PHYSICAL                   403          386 NO  NO GAP

SQL> 
SQL> show parameter log_archive_dest_state_2

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
log_archive_dest_state_2             string      enable
log_archive_dest_state_20            string      enable
log_archive_dest_state_21            string      enable
log_archive_dest_state_22            string      enable
log_archive_dest_state_23            string      enable
log_archive_dest_state_24            string      enable
log_archive_dest_state_25            string      enable
log_archive_dest_state_26            string      enable
log_archive_dest_state_27            string      enable
log_archive_dest_state_28            string      enable
log_archive_dest_state_29            string      enable
SQL> alter system set log_archive_dest_state_2='DEFER';

System altered.

SQL>

from the alert log
2021-08-13T23:21:58.120088+08:00
ALTER SYSTEM SET log_archive_dest_state_2='DEFER' SCOPE=BOTH;


Notice how v$archive_dest_status at the Primary now show that Sequence#401 is the last Archived and Applied at STDBYDB. Sequence#402 and subsequent ones are no longer relevant to STDBYDB.

You might note that the STDB2 which I have configured as a Lagging Standby (DEST_ID=3) is still receiving Redo from the Primary.  So, that Standby is still active.  (See here and here as to how I configured STDB2 as a second Standby that is lagging)


In the next Blog Post, I will show what happens if I attempt to restore the backup of STDBYDB and resync with the Primary after executing multiple changes (redo) in this database want to discard it, inspite of it now running at a different Incarnation# (Incarnation=4)