Re: ORA-16040 error when working in Dataguard Environment

eAddict wrote:
> On my production system I performed a lot of log switches all at once:
>
> SQL> alter system switch logfile
> System altered.
>
> I did this about 8-10 times in a row. So why did I get the following
> error messages in the standby database? My parameters are set on the
> production system as:
>
> *.log_archive_dest_1='LOCATION=/oracle/SND/saparch'
> *.log_archive_dest_2='SERVICE=SSND reopen=60 LGWR'
> *.log_archive_dest_state_1='enable'
> *.log_archive_dest_state_2='enable'
>
>
> On the production database:
> ======================================================================
> Tue Oct 17 15:39:54 2006
> LGWR: Completed archiving log 14 thread 1 sequence 6688
> Creating archive destination LOG_ARCHIVE_DEST_2: 'SSND'
> LGWR: Beginning to archive log 11 thread 1 sequence 6689
> Beginning log switch checkpoint up to RBA [0x1a21.2.10], SCN:
> 0x0002.a9aabee8
> Tue Oct 17 15:39:54 2006
> ARC1: Evaluating archive log 14 thread 1 sequence 6688
> ARC1: Archive destination LOG_ARCHIVE_DEST_2: Previously completed
> ARC1: Beginning to archive log 14 thread 1 sequence 6688
> Creating archive destination LOG_ARCHIVE_DEST_1:
> '/oracle/SND/saparch/SNDarch1_6688.dbf'
> Tue Oct 17 15:39:54 2006
> Thread 1 advanced to log sequence 6689
> Current log# 11 seq# 6689 mem# 0: /oracle/SND/origlogA/log_g11m1.dbf
> Current log# 11 seq# 6689 mem# 1: /oracle/SND/mirrlogA/log_g11m2.dbf
> Tue Oct 17 15:39:54 2006
> ARC1: Completed archiving log 14 thread 1 sequence 6688
> Tue Oct 17 15:40:02 2006
> LGWR: Completed archiving log 11 thread 1 sequence 6689
> Creating archive destination LOG_ARCHIVE_DEST_2: 'SSND'
> LGWR: Beginning to archive log 12 thread 1 sequence 6690
> Beginning log switch checkpoint up to RBA [0x1a22.2.10], SCN:
> 0x0002.a9aabeec
> Tue Oct 17 15:40:02 2006
> ARC0: Evaluating archive log 11 thread 1 sequence 6689
> ARC0: Archive destination LOG_ARCHIVE_DEST_2: Previously completed
> ARC0: Beginning to archive log 11 thread 1 sequence 6689
> Creating archive destination LOG_ARCHIVE_DEST_1:
> '/oracle/SND/saparch/SNDarch1_6689.dbf'
> Tue Oct 17 15:40:02 2006
> Thread 1 advanced to log sequence 6690
> Current log# 12 seq# 6690 mem# 0: /oracle/SND/origlogB/log_g12m1.dbf
> Current log# 12 seq# 6690 mem# 1: /oracle/SND/mirrlogB/log_g12m2.dbf
> Tue Oct 17 15:40:02 2006
> Completed checkpoint up to RBA [0x1a22.2.10], SCN: 0x0002.a9aabeec
> Tue Oct 17 15:40:02 2006
> ARC0: Completed archiving log 11 thread 1 sequence 6689
> Tue Oct 17 15:40:03 2006
> LGWR: Completed archiving log 12 thread 1 sequence 6690
> Creating archive destination LOG_ARCHIVE_DEST_2: 'SSND'
> LGWR: Beginning to archive log 13 thread 1 sequence 6691
> Beginning log switch checkpoint up to RBA [0x1a23.2.10], SCN:
> 0x0002.a9aabeee
> Thread 1 advanced to log sequence 6691
> Current log# 13 seq# 6691 mem# 0: /oracle/SND/origlogA/log_g13m1.dbf
> Current log# 13 seq# 6691 mem# 1: /oracle/SND/mirrlogA/log_g13m2.dbf
> Tue Oct 17 15:40:03 2006
> Completed checkpoint up to RBA [0x1a23.2.10], SCN: 0x0002.a9aabeee
> Completed checkpoint up to RBA [0x1a21.2.10], SCN: 0x0002.a9aabee8
> Tue Oct 17 15:40:04 2006
> LGWR: Completed archiving log 13 thread 1 sequence 6691
> Creating archive destination LOG_ARCHIVE_DEST_2: 'SSND'
> LGWR: Beginning to archive log 14 thread 1 sequence 6692
> Tue Oct 17 15:40:04 2006
> ARC1: Evaluating archive log 12 thread 1 sequence 6690
> ARC1: Archive destination LOG_ARCHIVE_DEST_2: Previously completed
> ARC1: Beginning to archive log 12 thread 1 sequence 6690
> Creating archive destination LOG_ARCHIVE_DEST_1:
> '/oracle/SND/saparch/SNDarch1_6690.dbf'
> Tue Oct 17 15:40:04 2006
> Beginning log switch checkpoint up to RBA [0x1a24.2.10], SCN:
> 0x0002.a9aabef0
> Tue Oct 17 15:40:04 2006
> ARC0: Evaluating archive log 12 thread 1 sequence 6690
> ARC0: Unable to archive log 12 thread 1 sequence 6690
> Log actively being archived by another process
> ARC0: Evaluating archive log 13 thread 1 sequence 6691
> ARC0: Archive destination LOG_ARCHIVE_DEST_2: Previously completed
> ARC0: Beginning to archive log 13 thread 1 sequence 6691
> Creating archive destination LOG_ARCHIVE_DEST_1:
> '/oracle/SND/saparch/SNDarch1_6691.dbf'
> Tue Oct 17 15:40:04 2006
> Thread 1 advanced to log sequence 6692
> Current log# 14 seq# 6692 mem# 0: /oracle/SND/origlogB/log_g14m1.dbf
> Current log# 14 seq# 6692 mem# 1: /oracle/SND/mirrlogB/log_g14m2.dbf
> Tue Oct 17 15:40:04 2006
> ARC1: Completed archiving log 12 thread 1 sequence 6690
> Tue Oct 17 15:40:04 2006
> ARC0: Completed archiving log 13 thread 1 sequence 6691
> Tue Oct 17 15:40:04 2006
> LGWR: Completed archiving log 14 thread 1 sequence 6692
> Creating archive destination LOG_ARCHIVE_DEST_2: 'SSND'
> LGWR: Beginning to archive log 11 thread 1 sequence 6693
> Beginning log switch checkpoint up to RBA [0x1a25.2.10], SCN:
> 0x0002.a9aabef2
> Tue Oct 17 15:40:18 2006
> ARC1: Evaluating archive log 14 thread 1 sequence 6692
> ARC1: Archive destination LOG_ARCHIVE_DEST_2: Previously completed
> ARC1: Beginning to archive log 14 thread 1 sequence 6692
> Creating archive destination LOG_ARCHIVE_DEST_1:
> '/oracle/SND/saparch/SNDarch1_6692.dbf'
> Tue Oct 17 15:40:18 2006
> Thread 1 advanced to log sequence 6693
> Current log# 11 seq# 6693 mem# 0: /oracle/SND/origlogA/log_g11m1.dbf
> Current log# 11 seq# 6693 mem# 1: /oracle/SND/mirrlogA/log_g11m2.dbf
> Tue Oct 17 15:40:18 2006
> ARC1: Completed archiving log 14 thread 1 sequence 6692
> Tue Oct 17 15:40:19 2006
> Completed checkpoint up to RBA [0x1a25.2.10], SCN: 0x0002.a9aabef2
> Completed checkpoint up to RBA [0x1a24.2.10], SCN: 0x0002.a9aabef0
>
>
> On the standby database:
> ====================================================================
> Tue Oct 17 15:39:54 2006
> ARC0: Evaluating archive log 8 thread 1 sequence 6688
> ARC0: Beginning to archive log 8 thread 1 sequence 6688
> Creating archive destination LOG_ARCHIVE_DEST_2: 'SSND'
> Tue Oct 17 15:39:54 2006
> RFS: Successfully opened standby logfile 5:
> '/oracle/SND/stbylog/srl1.f'
> Tue Oct 17 15:40:02 2006
> ARC1: Evaluating archive log 8 thread 1 sequence 6688
> ARC1: Unable to archive log 8 thread 1 sequence 6688
> Log actively being archived by another process
> ARC1: Evaluating archive log 5 thread 1 sequence 6689
> ARC1: Beginning to archive log 5 thread 1 sequence 6689
> Creating archive destination LOG_ARCHIVE_DEST_2: 'SSND'
> Tue Oct 17 15:40:02 2006
> RFS: Successfully opened standby logfile 6:
> '/oracle/SND/stbylog/srl2.f'
> RFS: Successfully opened standby logfile 7:
> '/oracle/SND/stbylog/srl3.f'
> RFS: Successfully opened standby logfile 9:
> '/oracle/SND/stbylog/srl5.f'
> RFS: No standby redo logfiles of size 20480 blocks available
> RFS: Waiting for thread 1 sequence 6689 archival to complete
> Tue Oct 17 15:40:09 2006
> RFS: file locked log 8 thread 1 sequence 6688
> <============= THIS
> Tue Oct 17 15:40:09 2006
> ARC0: Error 16040 Creating archive log file to 'SSND'
> <============= THIS
> Tue Oct 17 15:40:09 2006
> Errors in file /oracle/SND/saptrace/background/snd_arc0_1223.trc:
> ORA-16040: standby destination archive log file is locked
> <============= THIS
> Creating archive destination LOG_ARCHIVE_DEST_1:
> '/oracle/SND/saparch/SNDarch1_6688.dbf'
> Tue Oct 17 15:40:09 2006
> RFS: Forced Shutdown due to RFS_ERROR state
> <============= THIS
> Tue Oct 17 15:40:09 2006
> ARC0: Completed archiving log 8 thread 1 sequence 6688
> ARC0: Evaluating archive log 5 thread 1 sequence 6689
> ARC0: Unable to archive log 5 thread 1 sequence 6689
> Log actively being archived by another process
> ARC0: Evaluating archive log 6 thread 1 sequence 6690
> ARC0: Beginning to archive log 6 thread 1 sequence 6690
> Creating archive destination LOG_ARCHIVE_DEST_1:
> '/oracle/SND/saparch/SNDarch1_6690.dbf'
> ARC0: Completed archiving log 6 thread 1 sequence 6690
> ARC0: Evaluating archive log 5 thread 1 sequence 6689
> ARC0: Unable to archive log 5 thread 1 sequence 6689
> Log actively being archived by another process
> ARC0: Evaluating archive log 7 thread 1 sequence 6691
> ARC0: Beginning to archive log 7 thread 1 sequence 6691
> Creating archive destination LOG_ARCHIVE_DEST_1:
> '/oracle/SND/saparch/SNDarch1_6691.dbf'
> ARC0: Completed archiving log 7 thread 1 sequence 6691
> ARC0: Evaluating archive log 5 thread 1 sequence 6689
> ARC0: Unable to archive log 5 thread 1 sequence 6689
> Log actively being archived by another process
> ARC0: Evaluating archive log 9 thread 1 sequence 6692
> ARC0: Beginning to archive log 9 thread 1 sequence 6692
> Creating archive destination LOG_ARCHIVE_DEST_2: 'SSND'
> Tue Oct 17 15:40:12 2006
> Media Recovery Log /oracle/SND/saparch/SNDarch1_6688.dbf
> Media Recovery Waiting for thread 1 seq# 6689 (in transit)
> Tue Oct 17 15:40:17 2006
> RFS: file locked log 5 thread 1 sequence 6689
> Tue Oct 17 15:40:17 2006
> ARC1: Error 16040 Creating archive log file to 'SSND'
> Tue Oct 17 15:40:17 2006
> Errors in file /oracle/SND/saptrace/background/snd_arc1_1225.trc:
> ORA-16040: standby destination archive log file is locked
> Creating archive destination LOG_ARCHIVE_DEST_1:
> '/oracle/SND/saparch/SNDarch1_6689.dbf'
> Tue Oct 17 15:40:17 2006
> RFS: Forced Shutdown due to RFS_ERROR state
> Tue Oct 17 15:40:17 2006
> ARC1: Completed archiving log 5 thread 1 sequence 6689
> ARC1: Evaluating archive log 9 thread 1 sequence 6692
> ARC1: Unable to archive log 9 thread 1 sequence 6692
> Log actively being archived by another process
> Tue Oct 17 15:40:18 2006
> RFS: Archival of thread 1 sequence 6689 complete
> RFS: Successfully opened standby logfile 5:
> '/oracle/SND/stbylog/srl1.f'
> Tue Oct 17 15:40:25 2006
> RFS: file locked log 9 thread 1 sequence 6692
> Tue Oct 17 15:40:25 2006
> ARC0: Error 16040 Creating archive log file to 'SSND'
> Tue Oct 17 15:40:25 2006
> Errors in file /oracle/SND/saptrace/background/snd_arc0_1223.trc:
> ORA-16040: standby destination archive log file is locked
> Creating archive destination LOG_ARCHIVE_DEST_1:
> '/oracle/SND/saparch/SNDarch1_6692.dbf'
> Tue Oct 17 15:40:25 2006
> RFS: Forced Shutdown due to RFS_ERROR state
> Tue Oct 17 15:40:25 2006
> ARC0: Completed archiving log 9 thread 1 sequence 6692
> Tue Oct 17 15:40:28 2006
> Media Recovery Log /oracle/SND/saparch/SNDarch1_6689.dbf
> Media Recovery Log /oracle/SND/saparch/SNDarch1_6690.dbf
> Media Recovery Log /oracle/SND/saparch/SNDarch1_6691.dbf
> Media Recovery Log /oracle/SND/saparch/SNDarch1_6692.dbf
> Media Recovery Waiting for thread 1 seq# 6693 (in transit)
> =========================================================
> Even after all the errors the standby database seemed to catch up OK.
> Is it my 2 destinations? One is local the other goes to the standby
> database.
>
> Thanks!
> Vince

This really is version dependent. We can see that on your version and configuration RFS is fairly compliant, it sees a locked file and tries again. On your production side, you can see Oracle has started up two archive processes. It's a good thing that the ARC0 process sees the ARC0 process has already archived 6690. Wait a minute - that's the same process!

ORA-16040 is supposed to mean you have duplicate definitions on the primary, leading to duplicate RFS processes on the standby. I don't see that in your definitions, but I'm wondering if perhaps an extra one was floating about from a previous shutdown? Have you done any switchovers? Anyways, since it fixed itself, you are ok. You may want to ask support anyways, there might be something else they know about.

Now, if you were using logical standby on RAC, you'd be running into a bug now and have to kill your RFS process.

Please remember to state versions and platforms and all relevant configuration information.

jg

-- 
@home.com is bogus.
http://www.springspotters.com/