Skip to Main Content

Database Software

Announcement

For appeals, questions and feedback about Oracle Forums, please email oracle-forums-moderators_us@oracle.com. Technical questions should be asked in the appropriate category. Thank you!

Data Guard switchover with broker fails with ORA-16570 / ORA-16665

User_LKVFASep 10 2014 — edited Sep 10 2014

I'm using Data Guard 11g on Windows Server 2012 64 Bit. I recently configured the broker in order to handle switchovers more comfortable.

Unfortunately the switchover doesn't work. Broker confguration seems fine, since I can activate t and redo apply is working perfectly...

Now, the behaviour is the following.... Once I commit the switchover via broker it shows the following:

DGMGRL> switchover to smart_stb

Performing switchover NOW, please wait...

Error: ORA-16665: timeout waiting for the result from a database

Failed.

Unable to switchover, primary database is still "smart"

The switchover itself does happen, there is no restart of the primary database though!! Doesn't seem to be related to a buggy DGMGRL service entry. Actually the database won't even come down. The primary is supending every process while trying to do so. Broker is running in a timeout of course, but the primary remains in a supending state. The primary doesn't seem to be able to cominicate with the standby side or vice versa. Which is odd since redo log shipping and apply is workng fine as mentioned... so does a manual switchover. I have no idea what could cause this kind of behavour... Double checked everything. Once I restart both databases and bring them into the right state the switchover is completed. But no need to say that this isn't the intention of using the broker....

drc.log primary shows the following:

2014-09-10 09:13:01.378 02000000   746441090 DMON: SWITCHOVER TO smart_stb

2014-09-10 09:13:01.378 02000000   746441090 DMON: start task execution: SWITCHOVER

2014-09-10 09:13:01.378                      NSV1: Using RFIUPI_DGCI_CDESC

2014-09-10 09:13:01.409                      NSV1: Using RFIUPI_DGCI_CDESC

2014-09-10 09:13:01.409 02001000   746441090 Notifying Oracle Clusterware to teardown primary database for SWITCHOVER

2014-09-10 09:13:01.425                      CLSR: CRS not configured, config = 2

.

2014-09-10 09:13:01.425 02001000   746441090 DMON: posting primary instances for SWITCHOVER phase 1

2014-09-10 09:13:01.425 02001000   746441090 DMON: status from rfi_post_instances() for CTL_SWITCH = ORA-00000

2014-09-10 09:13:01.425                      INSV: Received message for inter-instance publication

2014-09-10 09:13:01.425 02001000   746441090 DMON: dispersing message to standbys for SWITCHOVER phase BEGIN

2014-09-10 09:13:01.425                            req ID 1.1.746441090, opcode CTL_SWITCH, phase BEGIN, flags 5

2014-09-10 09:13:01.425                      NSV1: Using RFIUPI_DB_INST_CDESC

2014-09-10 09:13:01.425 02001000   746441090 DMON: Entered rfmsoexinst() for phase BEGIN

2014-09-10 09:13:01.425                      INSV: Reply received for message with

2014-09-10 09:13:01.425                            req ID 1.1.746441090, opcode CTL_SWITCH, phase BEGIN

2014-09-10 09:13:01.425 02001000   746441090 DMON: posting primary instances for SWITCHOVER phase 2

2014-09-10 09:13:01.440 02001000   746441090 DMON: status from rfi_post_instances() for CTL_SWITCH = ORA-00000

2014-09-10 09:13:01.440                      INSV: Received message for inter-instance publication

2014-09-10 09:13:01.440 02001000   746441090 DMON: dispersing message to standbys for SWITCHOVER phase TEARDOWN

2014-09-10 09:13:01.440                            req ID 1.1.746441090, opcode CTL_SWITCH, phase TEARDOWN, flags 5

2014-09-10 09:13:01.440 02001000   746441090 DMON: Entered rfmsoexinst() for phase TEARDOWN

2014-09-10 09:13:01.440                      RSM0: Received Set State Request: rid=0x01041001, sid=0, phid=1, econd=2, sitehndl=0x02001000

2014-09-10 09:13:01.440                      Log Transport Resource: SetState OFFLINE, phase TEAR-DOWN, External Cond SWITCH-OVER-PHYS_STBY

2014-09-10 09:13:01.440                      RSM0: Received Set State Request: rid=0x01011001, sid=4, phid=1, econd=2, sitehndl=0x02001000

2014-09-10 09:13:01.440                      Database Resource[IAM=PRIMARY]: SetState PHYSICAL-APPLY-ON, phase TEAR-DOWN, External Cond SWITCH-OVER-PHYS_STBY, Target Site Handle 0x02001000

2014-09-10 09:13:01.440                      RSM0: Executing SQL [ALTER DATABASE COMMIT TO SWITCHOVER TO PHYSICAL STANDBY WITH SESSION SHUTDOWN]

2014-09-10 09:13:06.630                      SQL [ALTER DATABASE COMMIT TO SWITCHOVER TO PHYSICAL STANDBY WITH SESSION SHUTDOWN] Executed successfully

2014-09-10 09:13:06.630                      RSM: clearing IncarnationTable internal property of site 0x01010000

2014-09-10 09:13:06.630 02001000   746441090 DMON: Broker determines that instance restart is required:  Operation = SWITCHOVER  status = ORA-16570

2014-09-10 09:13:06.630 02001000   746441090     Resource: smart (01011001)  State: PHYSICAL-APPLY-ON

2014-09-10 09:13:06.630                      INSV: Reply received for message with

2014-09-10 09:13:06.630                            req ID 1.1.746441090, opcode CTL_SWITCH, phase TEARDOWN

2014-09-10 09:13:06.630 02001000   746441090 DMON: Instance "smart" (ID 1) returned ORA-16570

2014-09-10 09:13:06.630 02001000   746441090       for phase TEARDOWN of operation CTL_SWITCH

2014-09-10 09:13:06.646                      NSV1: Using RFIUPI_DGCI_CDESC

2014-09-10 09:13:06.646 02001000   746441090 DMON: posting primary instances for SWITCHOVER phase 2

2014-09-10 09:13:06.646                      INSV: Received message for inter-instance publication

2014-09-10 09:13:06.646 02001000   746441090 DMON: status from rfi_post_instances() for CTL_SWITCH = ORA-00000

2014-09-10 09:13:06.646                            req ID 1.1.746441090, opcode CTL_SWITCH, phase TEARDOWN, flags 5

2014-09-10 09:13:06.646 02001000   746441090 DMON: dispersing message to standbys for SWITCHOVER phase TEARDOWN

2014-09-10 09:13:06.646 02001000   746441090 DMON: Entered rfmsoexinst() for phase TEARDOWN

2014-09-10 09:13:06.646                      NSV1: Using RFIUPI_DB_INST_CDESC

2014-09-10 09:13:06.646                      INSV: Reply received for message with

2014-09-10 09:13:06.646                            req ID 1.1.746441090, opcode CTL_SWITCH, phase TEARDOWN

2014-09-10 09:13:06.646 02001000   746441090 DMON: Instance "smart" (ID 1) returned ORA-16570

2014-09-10 09:13:06.646 02001000   746441090       for phase TEARDOWN of operation CTL_SWITCH

2014-09-10 09:13:28.619                      NSV1: Using RFIUPI_DB_INST_CDESC

2014-09-10 09:13:28.619                      NSV1: Site smart_stb returned ORA-16665.

2014-09-10 09:13:43.620                      NSV1: Using RFIUPI_DB_INST_CDESC

2014-09-10 09:13:43.620                      NSV1: Site smart_stb returned ORA-16665.

2014-09-10 09:13:58.639                      NSV1: Using RFIUPI_DB_INST_CDESC

2014-09-10 09:13:58.639                      NSV1: Site smart_stb returned ORA-16665.

2014-09-10 09:14:13.657                      NSV1: Using RFIUPI_DB_INST_CDESC

2014-09-10 09:14:13.657                      NSV1: Site smart_stb returned ORA-16665.

2014-09-10 09:14:28.674                      NSV1: Using RFIUPI_DB_INST_CDESC

2014-09-10 09:14:28.674                      NSV1: Site smart_stb returned ORA-16665.

2014-09-10 09:14:43.676                      NSV1: Using RFIUPI_DB_INST_CDESC

2014-09-10 09:14:43.676                      NSV1: Site smart_stb returned ORA-16665.

2014-09-10 09:14:58.693                      NSV1: Using RFIUPI_DB_INST_CDESC

2014-09-10 09:14:58.693                      NSV1: Site smart_stb returned ORA-16665.

2014-09-10 09:15:13.695                      NSV1: Using RFIUPI_DB_INST_CDESC

2014-09-10 09:15:13.695                      NSV1: Site smart_stb returned ORA-16665.

2014-09-10 09:15:28.707                      NSV1: Using RFIUPI_DB_INST_CDESC

2014-09-10 09:15:28.707                      NSV1: Site smart_stb returned ORA-16665.

2014-09-10 09:15:43.724                      NSV1: Using RFIUPI_DB_INST_CDESC

2014-09-10 09:15:43.724                      NSV1: Site smart_stb returned ORA-16665.

2014-09-10 09:15:58.726                      NSV1: Using RFIUPI_DB_INST_CDESC

2014-09-10 09:15:58.726                      NSV1: Site smart_stb returned ORA-16665.

2014-09-10 09:16:13.727                      NSV1: Using RFIUPI_DB_INST_CDESC

2014-09-10 09:16:13.727                      NSV1: Site smart_stb returned ORA-16665.

2014-09-10 09:16:28.729 02001000   746441090 DMON: Database smart_stb returned ORA-16665

2014-09-10 09:16:28.729 02001000   746441090       for opcode = CTL_SWITCH, phase = TEARDOWN, req_id = 1.1.746441090

2014-09-10 09:16:28.729 02001000   746441090 Operation CTL_SWITCH canceled during phase 2, error = ORA-16665

2014-09-10 09:16:28.729 02001000   746441090 DMON: Switchover operation failed with status ORA-16665

2014-09-10 09:16:28.729                      NSV1: Using RFIUPI_DGCI_CDESC

2014-09-10 09:16:28.744 02001000   746441090 DMON: posting primary instances for SWITCHOVER phase 5

2014-09-10 09:16:28.744                      INSV: Received message for inter-instance publication

2014-09-10 09:16:28.744 02001000   746441090 DMON: status from rfi_post_instances() for CTL_SWITCH = ORA-00000

2014-09-10 09:16:28.744                            req ID 1.1.746441090, opcode CTL_SWITCH, phase END, flags 5

2014-09-10 09:16:28.744 02001000   746441090 DMON: Switchover Aborted due to errors

2014-09-10 09:16:28.744 02001000   746441090     Site named: smart is still primary

2014-09-10 09:16:28.744 02001000   746441090     error = ORA-16665

drc.log standby shows the following:

2014-09-10 09:13:01.352 02001000   746441090 Notifying Oracle Clusterware to teardown target standby database for SWITCHOVER

2014-09-10 09:13:01.367                      CLSR: CRS not configured, config = 2

.

2014-09-10 09:13:01.367 02001000   746441090 DMON: posting standby instances for SWITCHOVER phase 1

2014-09-10 09:13:01.367                      INSV: Received message for inter-instance publication

2014-09-10 09:13:01.367                            req ID 1.1.746441090, opcode CTL_SWITCH, phase BEGIN, flags 5

2014-09-10 09:13:01.367 02001000   746441090 DMON: Entered rfmsoexinst() for phase BEGIN

2014-09-10 09:13:01.367                      INSV: Reply received for message with

2014-09-10 09:13:01.367                            req ID 1.1.746441090, opcode CTL_SWITCH, phase BEGIN

2014-09-10 09:13:01.367 02001000   746441090 DMON: Entered rfm_release_chief_lock() for CTL_SWITCH

2014-09-10 09:13:06.571 02001000   746441090 DMON: Entered rfm_get_chief_lock() for CTL_SWITCH, reason 0

2014-09-10 09:13:06.571 02001000   746441090 DMON: start task execution: SWITCHOVER

2014-09-10 09:13:06.586 02001000   746441090 DMON: posting standby instances for SWITCHOVER phase 2

2014-09-10 09:13:06.586                      INSV: Received message for inter-instance publication

2014-09-10 09:13:06.586                            req ID 1.1.746441090, opcode CTL_SWITCH, phase TEARDOWN, flags 5

2014-09-10 09:13:06.586 02001000   746441090 DMON: Entered rfmsoexinst() for phase TEARDOWN

2014-09-10 09:13:06.586                      RSM0: Received Set State Request: rid=0x02031001, sid=0, phid=1, econd=2, sitehndl=0x02001000

2014-09-10 09:13:06.586                      Redo Apply Resource: SetState OFFLINE, phase TEAR-DOWN, External Cond SWITCH-OVER-PHYS_STBY

2014-09-10 09:13:06.586                      RSM0: Received Set State Request: rid=0x02012001, sid=9, phid=1, econd=2, sitehndl=0x02001000

2014-09-10 09:13:06.586                      Database Resource[IAM=PHYSICAL]: SetState READ-WRITE-XPTON, phase TEAR-DOWN, External Cond SWITCH-OVER-PHYS_STBY, Target Site Handle 0x02001000

2014-09-10 09:13:06.586                      RSM0: Executing SQL [ALTER DATABASE RECOVER MANAGED STANDBY DATABASE CANCEL]

2014-09-10 09:13:07.602                      SQL [ALTER DATABASE RECOVER MANAGED STANDBY DATABASE CANCEL] Executed successfully

2014-09-10 09:13:07.711                      RSM0: Executing SQL [ALTER DATABASE RECOVER MANAGED STANDBY DATABASE THROUGH LAST SWITCHOVER NODELAY]

2014-09-10 09:13:09.509                      SQL [ALTER DATABASE RECOVER MANAGED STANDBY DATABASE THROUGH LAST SWITCHOVER NODELAY] Executed successfully

2014-09-10 09:13:09.509                      RSM0: Executing SQL [ALTER DATABASE COMMIT TO SWITCHOVER TO PRIMARY WAIT WITH SESSION SHUTDOWN]

2014-09-10 09:13:11.345                      SQL [ALTER DATABASE COMMIT TO SWITCHOVER TO PRIMARY WAIT WITH SESSION SHUTDOWN] Executed successfully

2014-09-10 09:13:11.345                      Database Resource SetState succeeded

2014-09-10 09:13:11.345                      INSV: Reply received for message with

2014-09-10 09:13:11.345                            req ID 1.1.746441090, opcode CTL_SWITCH, phase TEARDOWN

2014-09-10 09:13:11.345 02001000   746441090 DMON: Entered rfm_release_chief_lock() for CTL_SWITCH

2014-09-10 09:13:28.555                      drcx: Found task req_id=1.1.746441090 for PROBE, but the phase is done

2014-09-10 09:13:43.555                      drcx: Found task req_id=1.1.746441090 for PROBE, but the phase is done

2014-09-10 09:13:58.571                      drcx: Found task req_id=1.1.746441090 for PROBE, but the phase is done

2014-09-10 09:14:13.590                      drcx: Found task req_id=1.1.746441090 for PROBE, but the phase is done

2014-09-10 09:14:28.605                      drcx: Found task req_id=1.1.746441090 for PROBE, but the phase is done

2014-09-10 09:14:43.606                      drcx: Found task req_id=1.1.746441090 for PROBE, but the phase is done

2014-09-10 09:14:58.622                      drcx: Found task req_id=1.1.746441090 for PROBE, but the phase is done

2014-09-10 09:15:13.625                      drcx: Found task req_id=1.1.746441090 for PROBE, but the phase is done

2014-09-10 09:15:28.641                      drcx: Found task req_id=1.1.746441090 for PROBE, but the phase is done

2014-09-10 09:15:43.646                      drcx: Found task req_id=1.1.746441090 for PROBE, but the phase is done

2014-09-10 09:15:58.652                      drcx: Found task req_id=1.1.746441090 for PROBE, but the phase is done

2014-09-10 09:16:13.653                      drcx: Found task req_id=1.1.746441090 for PROBE, but the phase is done

2014-09-10 09:16:27.606 02001000   746441090 DMON: Data Guard Broker terminating NSV0, timed out waiting for a response from database smart

2014-09-10 09:16:27.825 02001000   746441090 DMON: Database smart returned ORA-16662

2014-09-10 09:16:27.825 02001000   746441090       for opcode = CTL_SWITCH, phase = RESYNCH, req_id = 1.1.746441090

2014-09-10 09:16:42.840 02001000   746441090 DMON: Data Guard Broker terminating NSV0, timed out waiting for a response from database smart

2014-09-10 09:16:42.840 02001000   746441090 DMON: Database smart returned ORA-16662

2014-09-10 09:16:42.840 02001000   746441090       for opcode = CTL_SWITCH, phase = RESYNCH, req_id = 1.1.746441090

2014-09-10 09:16:57.861 02001000   746441090 DMON: Data Guard Broker terminating NSV0, timed out waiting for a response from database smart

2014-09-10 09:16:57.861 02001000   746441090 DMON: Database smart returned ORA-16662

2014-09-10 09:16:57.861 02001000   746441090       for opcode = CTL_SWITCH, phase = RESYNCH, req_id = 1.1.746441090

2014-09-10 09:16:58.705 00001000   746441091 DMON: Entered rfm_get_chief_lock() for HEALTH_CHECK, reason 0

2014-09-10 09:16:58.705 00001000   746441091 DMON: Freeing orphaned task 1.1.746441090, opcode=CTL_SWITCH.

2014-09-10 09:16:58.705 00001000   746441091 DMON: start task execution: automatic healthcheck

2014-09-10 09:16:58.720 00001000   746441091 DMON: Start health check

2014-09-10 09:16:58.720                      INSV: Received message for inter-instance publication

2014-09-10 09:16:58.720 00001000   746441091 DMON: status from rfi_post_instances() = ORA-00000

2014-09-10 09:16:58.720                            req ID 1.1.746441091, opcode HEALTH_CHECK, phase BEGIN, flags 5

2014-09-10 09:16:58.720 00000000   746441091 DMON: Entered rfmhcexinst

2014-09-10 09:16:58.720 00000000   746441091 DMON: rfmhcexinst calling RSMs

2014-09-10 09:16:58.720                      RSM0: Received Get Status Request: rid=0x02012001, sid=4

2014-09-10 09:16:58.720                      RSM0: HEALTH CHECK ERROR: ORA-16816: incorrect database role

2014-09-10 09:16:58.720                      Warning: the given scn 281474976710655 with resetlogs_id = 851952614 is less than the resetlogs_change# 744657 of the same incarnation.

2014-09-10 09:16:58.736                      Current IncarnationTable value is:

2014-09-10 09:16:58.736                      2,744657,851952614,1,*1,1,851351631,0,#

2014-09-10 09:16:58.736                      RSM0: HEALTH CHECK ERROR: ORA-16700: the standby database has diverged from the primary database

2014-09-10 09:16:58.970 00000000   746441091 Operation HEALTH_CHECK canceled during phase 1, error = ORA-16810

2014-09-10 09:16:58.970                      RSM0: Received Get Status Request: rid=0x02031001, sid=1

2014-09-10 09:16:58.970 00000000   746441091 DMON: Standby Instance completed health check

2014-09-10 09:16:58.970                      INSV: Reply received for message with

2014-09-10 09:16:58.970                            req ID 1.1.746441091, opcode HEALTH_CHECK, phase BEGIN

2014-09-10 09:16:58.970                      DMON: HEALTH CHECK ERROR: ORA-16766: Redo Apply is stopped

2014-09-10 09:16:58.970                      DMON: After H/C aggregation, db 0x02001000 has severity=16501, status=16810

2014-09-10 09:16:58.970 00000000   746441091 Operation HEALTH_CHECK canceled during phase 1, error = ORA-16810

2014-09-10 09:16:58.970                      INSV: Received message for inter-instance publication

2014-09-10 09:16:58.970                            req ID 1.1.746441091, opcode HEALTH_CHECK, phase BEGIN, flags 20005

2014-09-10 09:16:58.970                      DMON: After H/C aggregation, db 0x02001000 has severity=16501, status=16810

2014-09-10 09:16:58.970                      INSV: Reply received for message with

2014-09-10 09:16:58.970                            req ID 1.1.746441091, opcode HEALTH_CHECK, phase BEGIN

2014-09-10 09:17:02.017 00000000   746441091 DMON: Entered rfm_release_chief_lock() for HEALTH_CHECK

2014-09-10 09:17:13.724                      drcx: could not find task req_id=1.1.746441091 for PROBE.

2014-09-10 09:17:28.730                      drcx: could not find task req_id=1.1.746441091 for PROBE.

alert.log primary shows the following:

LNS: Standby redo logfile selected for thread 1 sequence 12046 for destination LOG_ARCHIVE_DEST_2

Wed Sep 10 09:13:01 2014

ALTER DATABASE COMMIT TO SWITCHOVER TO PHYSICAL STANDBY WITH SESSION SHUTDOWN

Wed Sep 10 09:13:01 2014

Thread 1 advanced to log sequence 12047 (LGWR switch)

  Current log# 2 seq# 12047 mem# 0: X:\SMART\LOG1\SMART_21.LOG

  Current log# 2 seq# 12047 mem# 1: Y:\SMART\LOG2\SMART_22.LOG

Stopping background process QMNC

Wed Sep 10 09:13:01 2014

ARC1: Evaluating archive   log 1 thread 1 sequence 12046

CLOSE: killing server sessions.

Active process 15708 user 'SYSTEM' program 'ORACLE.EXE (W000)'

Active process 15708 user 'SYSTEM' program 'ORACLE.EXE (W000)'

Active process 13372 user 'SYSTEM' program 'ORACLE.EXE (W001)'

Active process 13372 user 'SYSTEM' program 'ORACLE.EXE (W001)'

Active process 15708 user 'SYSTEM' program 'ORACLE.EXE (W000)'

Active process 15708 user 'SYSTEM' program 'ORACLE.EXE (W000)'

Active process 13372 user 'SYSTEM' program 'ORACLE.EXE (W001)'

Active process 13372 user 'SYSTEM' program 'ORACLE.EXE (W001)'

Active process 15708 user 'SYSTEM' program 'ORACLE.EXE (W000)'

Active process 15708 user 'SYSTEM' program 'ORACLE.EXE (W000)'

Active process 13372 user 'SYSTEM' program 'ORACLE.EXE (W001)'

Active process 13372 user 'SYSTEM' program 'ORACLE.EXE (W001)'

Active process 15708 user 'SYSTEM' program 'ORACLE.EXE (W000)'

Active process 15708 user 'SYSTEM' program 'ORACLE.EXE (W000)'

Active process 13372 user 'SYSTEM' program 'ORACLE.EXE (W001)'

Active process 13372 user 'SYSTEM' program 'ORACLE.EXE (W001)'

Active process 15708 user 'SYSTEM' program 'ORACLE.EXE (W000)'

Active process 15708 user 'SYSTEM' program 'ORACLE.EXE (W000)'

Active process 13372 user 'SYSTEM' program 'ORACLE.EXE (W001)'

Active process 13372 user 'SYSTEM' program 'ORACLE.EXE (W001)'

Active process 15708 user 'SYSTEM' program 'ORACLE.EXE (W000)'

Active process 15708 user 'SYSTEM' program 'ORACLE.EXE (W000)'

Active process 13372 user 'SYSTEM' program 'ORACLE.EXE (W001)'

Active process 13372 user 'SYSTEM' program 'ORACLE.EXE (W001)'

CLOSE: all sessions shutdown successfully.

krss_find_arc: Selecting ARC2 to receive message as last resort

Waiting for all non-current ORLs to be archived...

Waiting for the ORL for thread 1 sequence 12046 to be archived...

Wed Sep 10 09:13:02 2014

ARC0: Evaluating archive   log 1 thread 1 sequence 12046

Wed Sep 10 09:13:02 2014

ARC2: Evaluating archive   log 1 thread 1 sequence 12046

ARC0: Unable to archive thread 1 sequence 12046

      Log actively being archived by another process

ARC2: Unable to archive thread 1 sequence 12046

      Log actively being archived by another process

Committing creation of archivelog 'W:\SMART\ARC\SMART_12046_1_851952614.ARC'

Archived Log entry 19372 added for thread 1 sequence 12046 ID 0xab72f94c dest 1:

ORL for thread 1 sequence 12046 has been archived...

All non-current ORLs have been archived.

Waiting for all FAL entries to be archived...

All FAL entries have been archived.

Waiting for dest_id 2 to become synchronized...

OCISessionBegin with PasswordVerifier succeeded

Client pid [12320] attached to RFS pid [3648] at remote instance number [1] at dest 'smart_dg_stb'

Active, synchronized Physical Standby switchover target has been identified

Switchover End-Of-Redo Log thread 1 sequence 12047 has been fixed

Switchover: Primary highest seen SCN set to 0x0.0x22345d2

ARCH: Noswitch archival of thread 1, sequence 12047

ARCH: End-Of-Redo Branch archival of thread 1 sequence 12047

ARCH: Evaluating archive   log 2 thread 1 sequence 12047

ARCH: LGWR is actively archiving destination LOG_ARCHIVE_DEST_2

ARCH: Transmitting activation ID 0xab72f94c

OCISessionBegin with PasswordVerifier succeeded

Client pid [12244] attached to RFS pid [9972] at remote instance number [1] at dest 'smart_dg_stb'

ARCH: Standby redo logfile selected for thread 1 sequence 12047 for destination LOG_ARCHIVE_DEST_2

Committing creation of archivelog 'W:\SMART\ARC\SMART_12047_1_851952614.ARC'

Archived Log entry 19373 added for thread 1 sequence 12047 ID 0xab72f94c dest 1:

Archived Log entry 19374 added for thread 1 sequence 12047 ID 0xab72f94c dest 2:

ARCH: Archiving is disabled due to current logfile archival

Primary will check for some target standby to have received alls redo

Final check for a synchronized target standby. Check will be made once.

ARCH: Transmitting activation ID 0xab72f94c

LOG_ARCHIVE_DEST_2 is a potential Physical Standby switchover target

Active, synchronized target has been identified

Target has also received all redo

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

|          Target Standby Status                           |

| LOG_ARCHIVE_DEST_1  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_2  : HAS RECEIVED ALL DATA          |

| LOG_ARCHIVE_DEST_3  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_4  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_5  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_6  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_7  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_8  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_9  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_10  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_11  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_12  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_13  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_14  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_15  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_16  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_17  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_18  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_19  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_20  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_21  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_22  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_23  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_24  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_25  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_26  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_27  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_28  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_29  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_30  : NOT ACTIVE                     |

| LOG_ARCHIVE_DEST_31  : NOT ACTIVE                     |

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

Backup controlfile written to trace file D:\ORACLE\ORA_DBA\SMART\TRACE\diag\rdbms\smart\smart\trace\smart_rsm0_12244.trc

Clearing standby activation ID 2876438860 (0xab72f94c)

The primary database controlfile was created using the

'MAXLOGFILES 255' clause.

There is space for up to 251 standby redo logfiles

Use the following SQL commands on the standby database to create

standby redo logfiles that match the primary database:

ALTER DATABASE ADD STANDBY LOGFILE 'srl1.f' SIZE 52428800;

ALTER DATABASE ADD STANDBY LOGFILE 'srl2.f' SIZE 52428800;

ALTER DATABASE ADD STANDBY LOGFILE 'srl3.f' SIZE 52428800;

ALTER DATABASE ADD STANDBY LOGFILE 'srl4.f' SIZE 52428800;

ALTER DATABASE ADD STANDBY LOGFILE 'srl5.f' SIZE 52428800;

Archivelog for thread 1 sequence 12047 required for standby recovery

Switchover: Primary controlfile converted to standby controlfile succesfully.

Switchover: Complete - Database shutdown required

Completed: ALTER DATABASE COMMIT TO SWITCHOVER TO PHYSICAL STANDBY WITH SESSION SHUTDOWN

Wed Sep 10 09:13:20 2014

Process (ospid 12320) is suspended due to switchover to physical standby operation.

Wed Sep 10 09:16:58 2014

Process (ospid 12244) is suspended due to switchover to physical standby operation.

Wed Sep 10 09:17:08 2014

Process (ospid 3080) is suspended due to switchover to physical standby operation.

Wed Sep 10 09:17:09 2014

Process (ospid 12636) is suspended due to switchover to physical standby operation.

Wed Sep 10 09:17:10 2014

Process (ospid 5292) is suspended due to switchover to physical standby operation.

Wed Sep 10 09:17:43 2014

Process RSM0, PID = 12244, will be killed

Wed Sep 10 09:17:44 2014

RSM0 started with pid=27, OS id=16280

Wed Sep 10 09:20:56 2014

minact-scn: got error during useg scan e:12751 usn:6

minact-scn: useg scan erroring out with error e:12751

Wed Sep 10 09:21:19 2014

Process (ospid 16280) is suspended due to switchover to physical standby operation.

Wed Sep 10 09:22:04 2014

Process RSM0, PID = 16280, will be killed

Wed Sep 10 09:22:05 2014

RSM0 started with pid=27, OS id=10528

Wed Sep 10 09:25:39 2014

Process (ospid 10528) is suspended due to switchover to physical standby operation.

Wed Sep 10 09:26:03 2014

minact-scn: got error during useg scan e:12751 usn:6

minact-scn: useg scan erroring out with error e:12751

Wed Sep 10 09:26:24 2014

Process RSM0, PID = 10528, will be killed

Wed Sep 10 09:26:25 2014

RSM0 started with pid=27, OS id=15752

Wed Sep 10 09:29:59 2014

Process (ospid 15752) is suspended due to switchover to physical standby operation.

Wed Sep 10 09:30:44 2014

Process RSM0, PID = 15752, will be killed

Wed Sep 10 09:30:45 2014

RSM0 started with pid=27, OS id=1972

Wed Sep 10 09:31:09 2014

minact-scn: got error during useg scan e:12751 usn:6

minact-scn: useg scan erroring out with error e:12751

Suspending MMON action 'Block Cleanout Optim, Undo Segment Scan' for 82800 seconds

Wed Sep 10 09:34:19 2014

Process (ospid 1972) is suspended due to switchover to physical standby operation.

alert-log standby shows the following:

Wed Sep 10 09:13:01 2014

ARC3: Evaluating archive   log 5 thread 1 sequence 12046

Committing creation of archivelog 'W:\SMART\ARC\SMART_12046_1_851952614.ARC'

Archived Log entry 5932 added for thread 1 sequence 12046 ID 0xab72f94c dest 1:

Wed Sep 10 09:13:01 2014

Media Recovery Waiting for thread 1 sequence 12047

Wed Sep 10 09:13:04 2014

Redo Shipping Client Connected as PUBLIC

-- Connected User is Valid

RFS[6]: Assigned to RFS process 3648

RFS[6]: Identified database type as 'physical standby': Client is ARCH pid 12320

Wed Sep 10 09:13:06 2014

Redo Shipping Client Connected as PUBLIC

-- Connected User is Valid

RFS[7]: Assigned to RFS process 9972

RFS[7]: Identified database type as 'physical standby': Client is Foreground pid 12244

RFS[7]: End-Of-Redo archival of thread 1 sequence 12047

RFS[7]: Successfully opened standby log 5: 'Y:\SMART\LOG2\SMART_S_5.LOG'

RFS[7]: Selected log 5 for thread 1 sequence 12047 dbid -1425016497 branch 851952614

Wed Sep 10 09:13:06 2014

ARC1: Evaluating archive   log 5 thread 1 sequence 12047

Committing creation of archivelog 'W:\SMART\ARC\SMART_12047_1_851952614.ARC'

Archived Log entry 5933 added for thread 1 sequence 12047 ID 0xab72f94c dest 1:

Wed Sep 10 09:13:06 2014

ALTER DATABASE RECOVER MANAGED STANDBY DATABASE CANCEL

MRP0: Background Media Recovery cancelled with status 16037

Errors in file D:\ORACLE\ORA_DBA\SMART\TRACE\diag\rdbms\smart_stb\smart\trace\smart_pr00_13804.trc:

ORA-16037: user requested cancel of managed recovery operation

Managed Standby Recovery not using Real Time Apply

Recovery interrupted!

Errors in file D:\ORACLE\ORA_DBA\SMART\TRACE\diag\rdbms\smart_stb\smart\trace\smart_pr00_13804.trc:

ORA-16037: user requested cancel of managed recovery operation

Wed Sep 10 09:13:07 2014

Errors in file D:\ORACLE\ORA_DBA\SMART\TRACE\diag\rdbms\smart_stb\smart\trace\smart_mrp0_11168.trc:

ORA-10877: error signaled in parallel recovery slave

Completed: ALTER DATABASE RECOVER MANAGED STANDBY DATABASE CANCEL

Database not available for switchover

  End-Of-REDO archived log file has not been recovered

  Incomplete recovery SCN:0:35846057 archive SCN:0:35866066

ALTER DATABASE RECOVER MANAGED STANDBY DATABASE THROUGH LAST SWITCHOVER NODELAY

started logmerger process

Wed Sep 10 09:13:07 2014

Managed Standby Recovery not using Real Time Apply

Parallel Media Recovery started with 8 slaves

Media Recovery Log W:\SMART\ARC\SMART_12047_1_851952614.ARC

Identified End-Of-Redo (switchover) for thread 1 sequence 12047 at SCN 0x0.22345d2

Resetting standby activation ID 2876438860 (0xab72f94c)

Media Recovery End-Of-Redo indicator encountered

Media Recovery Applied through change 35866066

Attempt to set limbo arscn 0:35866066 irscn 0:35866066

Completed: ALTER DATABASE RECOVER MANAGED STANDBY DATABASE THROUGH LAST SWITCHOVER NODELAY

ALTER DATABASE COMMIT TO SWITCHOVER TO PRIMARY WAIT WITH SESSION SHUTDOWN

Maximum wait for role transition is 15 minutes.

krsv_proc_kill: Killing 2 processes (all RFS)

Backup controlfile written to trace file D:\ORACLE\ORA_DBA\SMART\TRACE\diag\rdbms\smart_stb\smart\trace\smart_rsm0_14652.trc

SwitchOver after complete recovery through change 35866066

Online log X:\SMART\LOG1\SMART_11.LOG: Thread 1 Group 1 was previously cleared

Online log Y:\SMART\LOG2\SMART_12.LOG: Thread 1 Group 1 was previously cleared

Online log X:\SMART\LOG1\SMART_21.LOG: Thread 1 Group 2 was previously cleared

Online log Y:\SMART\LOG2\SMART_22.LOG: Thread 1 Group 2 was previously cleared

Online log X:\SMART\LOG1\SMART_31.LOG: Thread 1 Group 3 was previously cleared

Online log Y:\SMART\LOG2\SMART_32.LOG: Thread 1 Group 3 was previously cleared

Online log X:\SMART\LOG1\SMART_41.LOG: Thread 1 Group 4 was previously cleared

Online log Y:\SMART\LOG2\SMART_42.LOG: Thread 1 Group 4 was previously cleared

Standby became primary SCN: 35866064

Switchover: Complete - Database mounted as primary

Completed: ALTER DATABASE COMMIT TO SWITCHOVER TO PRIMARY WAIT WITH SESSION SHUTDOWN

Wed Sep 10 09:13:45 2014

ARC0: Becoming the 'no SRL' ARCH

Wed Sep 10 09:13:46 2014

ARC3: Becoming the 'no SRL' ARCH

Wed Sep 10 09:13:46 2014

ARC1: Becoming the 'no SRL' ARCH

Wed Sep 10 09:16:58 2014

NSV0 started with pid=26, OS id=15900

Wed Sep 10 09:21:20 2014

DMON: NSV0 network call timeout. Killing it now.

Setup is the following:

DGMGRL> show configuration;

Configuration - dg_smart

  Protection Mode: MaxPerformance

  Databases:

    smart     - Primary database

    smart_stb - Physical standby database

Fast-Start Failover: DISABLED

Configuration Status:

SUCCESS

DGMGRL> show database verbose smart

Database - smart

  Role:            PRIMARY

  Intended State:  TRANSPORT-ON

  Instance(s):

    smart

  Properties:

    DGConnectIdentifier             = 'smart_dg_prim'

    ObserverConnectIdentifier       = ''

    LogXptMode                      = 'ASYNC'

    DelayMins                       = '0'

    Binding                         = 'optional'

    MaxFailure                      = '0'

    MaxConnections                  = '1'

    ReopenSecs                      = '300'

    NetTimeout                      = '30'

    RedoCompression                 = 'DISABLE'

    LogShipping                     = 'ON'

    PreferredApplyInstance          = ''

    ApplyInstanceTimeout            = '0'

    ApplyParallel                   = 'AUTO'

    StandbyFileManagement           = 'AUTO'

    ArchiveLagTarget                = '300'

    LogArchiveMaxProcesses          = '4'

    LogArchiveMinSucceedDest        = '1'

    DbFileNameConvert               = ''

    LogFileNameConvert              = 'X:\SMART\LOG1, X:\SMART\LOG1, Y:\SMART\LOG2, Y:\SMART\LOG2'

    FastStartFailoverTarget         = ''

    InconsistentProperties          = '(monitor)'

    InconsistentLogXptProps         = '(monitor)'

    SendQEntries                    = '(monitor)'

    LogXptStatus                    = '(monitor)'

    RecvQEntries                    = '(monitor)'

    SidName                         = 'smart'

    StaticConnectIdentifier         = '(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=host02)(PORT=1599))(CONNECT_DATA=(SERVICE_NAME=smart_DGMGRL)(INSTANCE_NAME=smart)(SERVER=DEDICATED)))'

    StandbyArchiveLocation          = 'W:\SMART\arc\'

    AlternateLocation               = ''

    LogArchiveTrace                 = '8191'

    LogArchiveFormat                = 'smart_%s_%t_%r.arc'

    TopWaitEvents                   = '(monitor)'

Database Status:

SUCCESS

DGMGRL> show database verbose smart_stb

Database - smart_stb

  Role:            PHYSICAL STANDBY

  Intended State:  APPLY-ON

  Transport Lag:   0 seconds

  Apply Lag:       0 seconds

  Real Time Query: OFF

  Instance(s):

    smart

  Properties:

    DGConnectIdentifier             = 'smart_dg_stb'

    ObserverConnectIdentifier       = ''

    LogXptMode                      = 'ASYNC'

    DelayMins                       = '0'

    Binding                         = 'optional'

    MaxFailure                      = '0'

    MaxConnections                  = '1'

    ReopenSecs                      = '300'

    NetTimeout                      = '30'

    RedoCompression                 = 'DISABLE'

    LogShipping                     = 'ON'

    PreferredApplyInstance          = ''

    ApplyInstanceTimeout            = '0'

    ApplyParallel                   = 'AUTO'

    StandbyFileManagement           = 'AUTO'

    ArchiveLagTarget                = '300'

    LogArchiveMaxProcesses          = '4'

    LogArchiveMinSucceedDest        = '1'

    DbFileNameConvert               = ''

    LogFileNameConvert              = 'X:\SMART\LOG1, X:\SMART\LOG1, Y:\SMART\LOG2, Y:\SMART\LOG2'

    FastStartFailoverTarget         = ''

    InconsistentProperties          = '(monitor)'

    InconsistentLogXptProps         = '(monitor)'

    SendQEntries                    = '(monitor)'

    LogXptStatus                    = '(monitor)'

    RecvQEntries                    = '(monitor)'

    SidName                         = 'smart'

    StaticConnectIdentifier         = '(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=host01)(PORT=1599))(CONNECT_DATA=(SERVICE_NAME=smart_stb_DGMGRL)(INSTANCE_NAME=smart)(SERVER=DEDICATED)))'

    StandbyArchiveLocation          = 'W:\SMART\arc\'

    AlternateLocation               = ''

    LogArchiveTrace                 = '8191'

    LogArchiveFormat                = 'smart_%s_%t_%r.arc'

    TopWaitEvents                   = '(monitor)'

Database Status:

SUCCESS

tnsnames.ora:

smart_dg_stb=(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=host01)(PORT=1599))(CONNECT_DATA=(SERVER=DEDICATED)(SID=smart)))

smart_dg_prim=(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=host02)(PORT=1599))(CONNECT_DATA=(SERVER=DEDICATED)(SID=smart)))

Listner.ora primary:

LISTENER_REDO_SMART =

  (DESCRIPTION_LIST =

    (DESCRIPTION =

      (ADDRESS = (PROTOCOL = TCP)(HOST = host02)(PORT = 1599))

    )

  )

SID_LIST_LISTENER_REDO_SMART =

  (SID_LIST =

    (SID_DESC =

      (SID_NAME = CLRExtProc)

      (ORACLE_HOME = D:\oracle\11.2.0)

      (PROGRAM = extproc)

      (ENVS = "EXTPROC_DLLS=ONLY:D:\oracle\11.2.0\bin\oraclr11.dll")

    )

     (SID_DESC =

      (SID_NAME =smart)

    (ORACLE_HOME = D:\oracle\11.2.0)

    )

     (SID_DESC =

      (SID_NAME =smart)

    (GLOBAL_DBNAME=smart_DGMGRL)

    (ORACLE_HOME = D:\oracle\11.2.0)

    )

  )

Listener.ora standby

LISTENER_REDO_SMART =

  (DESCRIPTION_LIST =

    (DESCRIPTION =

      (ADDRESS = (PROTOCOL = TCP)(HOST = host01)(PORT = 1599))

    )

  )

SID_LIST_LISTENER_REDO_SMART =

  (SID_LIST =

    (SID_DESC =

      (SID_NAME = CLRExtProc)

      (ORACLE_HOME = D:\oracle\11.2.0)

      (PROGRAM = extproc)

      (ENVS = "EXTPROC_DLLS=ONLY:D:\oracle\11.2.0\bin\oraclr11.dll")

    )

     (SID_DESC =

      (SID_NAME = smart)

       (ORACLE_HOME = D:\oracle\11.2.0)

    )

     (SID_DESC =

      (SID_NAME = smart)

       (GLOBAL_DBNAME=smart_stb_DGMGRL)

    (ORACLE_HOME = D:\oracle\11.2.0)

    )

  )

LSNRCTL> status listener_redo_smart

Connecting to (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=host02)(PORT=1599)))

STATUS of the LISTENER

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

Alias                     LISTENER_REDO_SMART

Version                   TNSLSNR for 64-bit Windows: Version 11.2.0.3.0 - Production

Start Date                30-AUG-2014 20:46:12

Uptime                    10 days 13 hr. 11 min. 15 sec

Trace Level               off

Security                  ON: Local OS Authentication

SNMP                      OFF

Listener Parameter File   D:\oracle\11.2.0\network\admin\listener.ora

Listener Log File         D:\oracle\diag\tnslsnr\host02\listener_redo_smart\alert\log.xml

Listening Endpoints Summary...

  (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=host02)(PORT=1599)))

Services Summary...

Service "CLRExtProc" has 1 instance(s).

  Instance "CLRExtProc", status UNKNOWN, has 1 handler(s) for this service...

Service "HA_SMART" has 1 instance(s).

  Instance "smart", status READY, has 1 handler(s) for this service...

Service "smart" has 2 instance(s).

  Instance "smart", status UNKNOWN, has 1 handler(s) for this service...

  Instance "smart", status READY, has 1 handler(s) for this service...

Service "smart_DGB" has 1 instance(s).

  Instance "smart", status READY, has 1 handler(s) for this service...

Service "smart_DGMGRL" has 1 instance(s).

  Instance "smart", status UNKNOWN, has 1 handler(s) for this service...

The command completed successfully

I'd be more than grateful if anybody would have an idea how to solve it!!

Thanks in advance and kind regards....

This post has been answered by User_LKVFA on Sep 10 2014
Jump to Answer
Comments
Locked Post
New comments cannot be posted to this locked post.
Post Details
Locked on Oct 8 2014
Added on Sep 10 2014
1 comment
4,577 views