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!

Duplicate Archivelog Record in 11gR2

Simon TannJun 13 2013 — edited Jun 24 2013

Hi Guys

Had an interesting error this morning in our production backup, a job that has run every day since January - it was missing an Archivelog. The interesting part is that there were two records for the same log sequence.

The first step in our backup is to perform a crosscheck:

sbvx10602 (fnc_rman) 14/06/2013 06:00:20: RMAN> crosscheck archivelog all;

sbvx10602 (fnc_rman) 14/06/2013 06:00:20: using target database control file instead of recovery catalog

sbvx10602 (fnc_rman) 14/06/2013 06:00:20: allocated channel: ORA_DISK_1

sbvx10602 (fnc_rman) 14/06/2013 06:00:20: channel ORA_DISK_1: SID=151 device type=DISK

sbvx10602 (fnc_rman) 14/06/2013 06:00:21: allocated channel: ORA_DISK_2

sbvx10602 (fnc_rman) 14/06/2013 06:00:21: channel ORA_DISK_2: SID=19 device type=DISK

...

sbvx10602 (fnc_rman) 14/06/2013 06:00:22: validation succeeded for archived log

sbvx10602 (fnc_rman) 14/06/2013 06:00:22: archived log file name=/opt/oracle/rman/spvx10599/TAPSPROD/archivelog/1_9325_799934039.arc RECID=9259 STAMP=817947899

sbvx10602 (fnc_rman) 14/06/2013 06:00:22: validation succeeded for archived log

sbvx10602 (fnc_rman) 14/06/2013 06:00:22: archived log file name=/opt/oracle/rman/spvx10599/TAPSPROD/archivelog/1_9326_799934039.arc RECID=9261 STAMP=817970481

sbvx10602 (fnc_rman) 14/06/2013 06:00:22: validation succeeded for archived log

sbvx10602 (fnc_rman) 14/06/2013 06:00:22: archived log file name=/opt/oracle/rman/spvx10599/TAPSPROD/archivelog/1_9326_799934039.arc RECID=9260 STAMP=817970479

sbvx10602 (fnc_rman) 14/06/2013 06:00:22: validation succeeded for archived log

sbvx10602 (fnc_rman) 14/06/2013 06:00:22: archived log file name=/opt/oracle/rman/spvx10599/TAPSPROD/archivelog/1_9327_799934039.arc RECID=9262 STAMP=817970562

...

Notice the two lines for the same file but with different record ids.

We then delete all archivelogs already backed up to disk (we like to keep 1 days worth of archivelogs on disk to speed up restorations and refreshes to development/qa databases):

sbvx10602 (fnc_rman) 14/06/2013 06:00:37: RMAN> delete noprompt archivelog all backed up 1 times to device type disk;

sbvx10602 (fnc_rman) 14/06/2013 06:00:37: using target database control file instead of recovery catalog

sbvx10602 (fnc_rman) 14/06/2013 06:00:38: allocated channel: ORA_DISK_1

sbvx10602 (fnc_rman) 14/06/2013 06:00:38: channel ORA_DISK_1: SID=151 device type=DISK

sbvx10602 (fnc_rman) 14/06/2013 06:00:38: allocated channel: ORA_DISK_2

sbvx10602 (fnc_rman) 14/06/2013 06:00:38: channel ORA_DISK_2: SID=19 device type=DISK

...

sbvx10602 (fnc_rman) 14/06/2013 06:00:39: List of Archived Log Copies for database with db_unique_name TAPSPROD

sbvx10602 (fnc_rman) 14/06/2013 06:00:39: =====================================================================

sbvx10602 (fnc_rman) 14/06/2013 06:00:39: Key Thrd Seq S Low Time

sbvx10602 (fnc_rman) 14/06/2013 06:00:39: ------- ---- ------- - ---------

...

sbvx10602 (fnc_rman) 14/06/2013 06:00:39: 9259 1 9325 A 12-JUN-13

sbvx10602 (fnc_rman) 14/06/2013 06:00:39: Name: /opt/oracle/rman/spvx10599/TAPSPROD/archivelog/1_9325_799934039.arc

sbvx10602 (fnc_rman) 14/06/2013 06:00:39: 9261 1 9326 A 12-JUN-13

sbvx10602 (fnc_rman) 14/06/2013 06:00:39: Name: /opt/oracle/rman/spvx10599/TAPSPROD/archivelog/1_9326_799934039.arc

sbvx10602 (fnc_rman) 14/06/2013 06:00:39: 9260 1 9326 A 12-JUN-13

sbvx10602 (fnc_rman) 14/06/2013 06:00:39: Name: /opt/oracle/rman/spvx10599/TAPSPROD/archivelog/1_9326_799934039.arc

sbvx10602 (fnc_rman) 14/06/2013 06:00:39: 9262 1 9327 A 13-JUN-13

sbvx10602 (fnc_rman) 14/06/2013 06:00:39: Name: /opt/oracle/rman/spvx10599/TAPSPROD/archivelog/1_9327_799934039.arc

...

sbvx10602 (fnc_rman) 14/06/2013 06:00:45: deleted archived log

sbvx10602 (fnc_rman) 14/06/2013 06:00:45: archived log file name=/opt/oracle/rman/spvx10599/TAPSPROD/archivelog/1_9325_799934039.arc RECID=9259 STAMP=817947899

sbvx10602 (fnc_rman) 14/06/2013 06:00:45: deleted archived log

sbvx10602 (fnc_rman) 14/06/2013 06:00:45: archived log file name=/opt/oracle/rman/spvx10599/TAPSPROD/archivelog/1_9326_799934039.arc RECID=9261 STAMP=817970481

sbvx10602 (fnc_rman) 14/06/2013 06:00:45: deleted archived log

sbvx10602 (fnc_rman) 14/06/2013 06:00:45: archived log file name=/opt/oracle/rman/spvx10599/TAPSPROD/archivelog/1_9327_799934039.arc RECID=9262 STAMP=817970562

sbvx10602 (fnc_rman) 14/06/2013 06:00:45: Deleted 53 objects

sbvx10602 (fnc_rman) 14/06/2013 06:00:45: RMAN-06207: WARNING: 1 objects could not be deleted for DISK channel(s) due

sbvx10602 (fnc_rman) 14/06/2013 06:00:45: RMAN-06208: to mismatched status. Use CROSSCHECK command to fix status

sbvx10602 (fnc_rman) 14/06/2013 06:00:45: RMAN-06210: List of Mismatched objects

sbvx10602 (fnc_rman) 14/06/2013 06:00:45: RMAN-06211: ==========================

sbvx10602 (fnc_rman) 14/06/2013 06:00:45: RMAN-06212: Object Type Filename/Handle

sbvx10602 (fnc_rman) 14/06/2013 06:00:45: RMAN-06213: --------------- ---------------------------------------------------

sbvx10602 (fnc_rman) 14/06/2013 06:00:45: RMAN-06214: Archivelog /opt/oracle/rman/spvx10599/TAPSPROD/archivelog/1_9326_799934039.arc

Notice that our file was deleted for record id 9261 but the second delete (for record id 9260) failed.

We then attempt to back up all archivelogs:

sbvx10602 (fnc_rman) 14/06/2013 06:00:48: RMAN> backup as compressed backupset archivelog all

sbvx10602 (fnc_rman) 14/06/2013 06:00:48: 2> format '/opt/oracle/rman/spvx10599/TAPSPROD/backup/tapsprod_ARCH_%I_%t_%s_%p'

sbvx10602 (fnc_rman) 14/06/2013 06:00:48: 3> tag = '2013-06-14:ARCHLOG';

sbvx10602 (fnc_rman) 14/06/2013 06:00:48: Starting backup at 14-JUN-13

sbvx10602 (fnc_rman) 14/06/2013 06:00:52: current log archived

sbvx10602 (fnc_rman) 14/06/2013 06:00:52: using target database control file instead of recovery catalog

sbvx10602 (fnc_rman) 14/06/2013 06:00:53: allocated channel: ORA_DISK_1

sbvx10602 (fnc_rman) 14/06/2013 06:00:53: channel ORA_DISK_1: SID=149 device type=DISK

sbvx10602 (fnc_rman) 14/06/2013 06:00:53: allocated channel: ORA_DISK_2

sbvx10602 (fnc_rman) 14/06/2013 06:00:53: channel ORA_DISK_2: SID=225 device type=DISK

sbvx10602 (fnc_rman) 14/06/2013 06:00:54: RMAN-00571: ===========================================================

sbvx10602 (fnc_rman) 14/06/2013 06:00:54: RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============

sbvx10602 (fnc_rman) 14/06/2013 06:00:54: RMAN-00571: ===========================================================

sbvx10602 (fnc_rman) 14/06/2013 06:00:54: RMAN-03002: failure of backup command at 06/14/2013 06:00:53

sbvx10602 (fnc_rman) 14/06/2013 06:00:54: RMAN-06059: expected archived log not found, loss of archived log compromises recoverability

sbvx10602 (fnc_rman) 14/06/2013 06:00:54: ORA-19625: error identifying file /opt/oracle/rman/spvx10599/TAPSPROD/archivelog/1_9326_799934039.arc

sbvx10602 (fnc_rman) 14/06/2013 06:00:54: ORA-27037: unable to obtain file status

sbvx10602 (fnc_rman) 14/06/2013 06:00:54: Linux-x86_64 Error: 2: No such file or directory

sbvx10602 (fnc_rman) 14/06/2013 06:00:54: Additional information: 3

Checking v$archived_log:

recid

stamp

name

dest_id

thread#

sequence#

resetlogs_change#

resetlogs_time

resetlogs_id

first_change#

first_time

next_change#

next_time

blocks

block_size

creator

registrar

standby_dest

archived

applied

deleted

status

completion_time

dictionary_begin

dictionary_end

end_of_redo

backup_count

archival_thread#

activation#

is_recovery_dest_file

compressed

fal

end_of_redo_type

backed_by_vss

9258

817946761

9324

945184

21/11/2012 11:53:59 AM

799934039

5968108264691

12/06/2013 11:18:18 PM

5968108404334

12/06/2013 11:25:58 PM

445990

512

ARCH

YES

12/06/2013 11:26:01 PM

3820384721

9259

817947899

9325

945184

21/11/2012 11:53:59 AM

799934039

5968108404334

12/06/2013 11:25:58 PM

5968108491786

12/06/2013 11:44:56 PM

468326

512

ARCH

YES

12/06/2013 11:44:59 PM

3820384721

9260

817970479

9326

945184

21/11/2012 11:53:59 AM

799934039

5968108491786

12/06/2013 11:44:56 PM

5968108601796

13/06/2013 6:01:14 AM

451079

512

ARCH

YES

13/06/2013 6:01:19 AM

3820384721

9261

817970481

9326

945184

21/11/2012 11:53:59 AM

799934039

5968108491786

12/06/2013 11:44:56 PM

5968108601796

13/06/2013 6:01:14 AM

451079

512

RMAN

YES

13/06/2013 6:01:21 AM

9262

817970562

9327

945184

21/11/2012 11:53:59 AM

799934039

5968108601796

13/06/2013 6:01:14 AM

5968108603803

13/06/2013 6:02:41 AM

113367

512

FGRD

YES

13/06/2013 6:02:42 AM

3820384721

9263

817972979

/opt/oracle/rman/spvx10599/TAPSPROD/archivelog/1_9328_799934039.arc

9328

945184

21/11/2012 11:53:59 AM

799934039

5968108603803

13/06/2013 6:02:41 AM

5968108630444

13/06/2013 6:42:56 AM

488724

512

ARCH

YES

13/06/2013 6:42:59 AM

3820384721

9264

817976471

/opt/oracle/rman/spvx10599/TAPSPROD/archivelog/1_9329_799934039.arc

9329

945184

21/11/2012 11:53:59 AM

799934039

5968108630444

13/06/2013 6:42:56 AM

5968108679108

13/06/2013 7:41:08 AM

449350

512

ARCH

YES

13/06/2013 7:41:11 AM

3820384721

and v$loghist:

thread#	sequence#	first_change#	first_time	switch_change#
1	9325	5968108404334	12/06/2013 11:25:58 PM	5968108491786
1	9326	5968108491786	12/06/2013 11:44:56 PM	5968108601796
1	9327	5968108601796	13/06/2013 6:01:14 AM	5968108603803

Alert log:

Wed Jun 12 23:44:53 2013

Thread 1 cannot allocate new log, sequence 9326

Private strand flush not complete

Current log# 3 seq# 9325 mem# 0: /opt/oracle/admin/TAPSPROD/redologs/1/a_log3.redo

Current log# 3 seq# 9325 mem# 1: /opt/oracle/admin/TAPSPROD/redologs/2/b_log3.redo

Thread 1 advanced to log sequence 9326 (LGWR switch)

Current log# 1 seq# 9326 mem# 0: /opt/oracle/admin/TAPSPROD/redologs/1/a_log1.redo

Current log# 1 seq# 9326 mem# 1: /opt/oracle/admin/TAPSPROD/redologs/2/b_log1.redo

Wed Jun 12 23:44:59 2013

Archived Log entry 9259 added for thread 1 sequence 9325 ID 0xe3b671d1 dest 1:

Thu Jun 13 02:01:55 2013

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

NI cryptographic checksum mismatch error: 12599.

VERSION INFORMATION:

TNS for Linux: Version 11.2.0.3.0 - Production

Oracle Bequeath NT Protocol Adapter for Linux: Version 11.2.0.3.0 - Production

TCP/IP NT Protocol Adapter for Linux: Version 11.2.0.3.0 - Production

Time: 13-JUN-2013 02:01:55

Tracing not turned on.

Tns error struct:

ns main err code: 12599

TNS-12599: TNS:cryptographic checksum mismatch

ns secondary err code: 2526

nt main err code: 0

nt secondary err code: 0

nt OS err code: 0

Thu Jun 13 02:05:48 2013

DBMS_STATS: GATHER_STATS_JOB encountered errors. Check the trace file.

Errors in file /opt/oracle/diag/diag/rdbms/tapsprod/TAPSPROD/trace/TAPSPROD_j001_10698.trc:

ORA-20011: Approximate NDV failed: ORA-29913: error in executing ODCIEXTTABLEOPEN callout

KUP-11024: This external table can only be accessed from within a Data Pump job.

Thu Jun 13 06:01:08 2013

Thread 1 cannot allocate new log, sequence 9327

Private strand flush not complete

Current log# 1 seq# 9326 mem# 0: /opt/oracle/admin/TAPSPROD/redologs/1/a_log1.redo

Current log# 1 seq# 9326 mem# 1: /opt/oracle/admin/TAPSPROD/redologs/2/b_log1.redo

Thread 1 advanced to log sequence 9327 (LGWR switch)

Current log# 2 seq# 9327 mem# 0: /opt/oracle/admin/TAPSPROD/redologs/3/a_log2.redo

Current log# 2 seq# 9327 mem# 1: /opt/oracle/admin/TAPSPROD/redologs/4/b_log2.redo

Thu Jun 13 06:01:19 2013

Archived Log entry 9260 added for thread 1 sequence 9326 ID 0xe3b671d1 dest 1:

Can anyone help me understand what has happened here?

In the meantime I have taken a full backup which completed successfully.

Thanks

Simon

Locked Post

New comments cannot be posted to this locked post.

Locked on Jul 22 2013

Added on Jun 13 2013

#11gr2, #backup, #database, #error, #oracle, #performance-availability, #recovery-manager-rman, #rman

21 comments

3,076 views