Veritas-bu

[Veritas-bu] RMAN backup fails nightly with same error codes, 6 & 13.

2003-04-25 14:17:52
Subject: [Veritas-bu] RMAN backup fails nightly with same error codes, 6 & 13.
From: mdd64 AT attbi DOT com (Mark Donaldson)
Date: Fri, 25 Apr 2003 12:17:52 -0600
RMAN backup fails nightly with same error codes, 6 & 13.Repost from my home
account to get it small enough...

----- Original Message -----

Every night we get two pairs of errors from our RMAN backups.  We'll get two
error code 6 & two error code 13.  It's nearly clockwork accurate every
night so I suspect some setup or RMAN scripting error.

It's a Oracle 9i RAC on Solaris 8 running against a Solaris SSO v4.5 NB
setup.  The DB is its own media server.

Here's a snip from the RMAN script output log - below that is a snip from
the .../logs/dbclient logfile:

channel ORA_SBT_TAPE_4: starting piece 1 at 25-APR-2003 03:41:45
channel ORA_SBT_TAPE_1: finished piece 1 at 25-APR-2003 03:42:00
channel ORA_SBT_TAPE_4: backup set complete, elapsed time: 00:24:13
channel ORA_SBT_TAPE_4: starting incremental level 1 datafile backupset
channel ORA_SBT_TAPE_4: specifying datafile(s) in backupset
input datafile fno=00138
name=/dbdata/u01/oradata/titan/OPL_J905134_D1_01.dbf
input datafile fno=00448 name=/dbdata/u17/oradata/titan/iv_tools2.dbf
channel ORA_SBT_TAPE_4: starting piece 1 at 25-APR-2003 03:41:45
channel ORA_SBT_TAPE_1: finished piece 1 at 25-APR-2003 03:42:00
piece handle=TITAN_17838_1_492232666 comment=API Version 2.0,MMS Version
4.0.0.0
channel ORA_SBT_TAPE_1: backup set complete, elapsed time: 00:24:14
channel ORA_SBT_TAPE_1: starting incremental level 1 datafile backupset
channel ORA_SBT_TAPE_1: specifying datafile(s) in backupset
input datafile fno=00139
name=/dbdata/u17/oradata/titan/OPL_J905134_D17_01.dbf
input datafile fno=00006 name=/dbdata/u01/oradata/titan/CC_D1_01.dbf
channel ORA_SBT_TAPE_1: starting piece 1 at 25-APR-2003 03:42:00
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-03002: failure of backup command at 04/25/2003 03:42:15
ORA-19506: failed to create sequential file, name="TITAN_17842_1_492234120",
par
ms=""
ORA-27028: skgfqcre: sbtbackup returned error
ORA-19511: Error received from media manager layer, error text:
   sbtbackup: Failed to open for backup.
RMAN>
Recovery Manager complete.
Script /export/home/oracle/cron/hot_database_backup.sh
==== ended in error on Fri Apr 25 03:42:27 CDT 2003 ====

#####################

Here's a relavant snip form the /usr/openv/netbackup/logs/dbclient logfile.
Note there's some errors here that look like files referenced weren't found:

03:40:57.660 [24976] <4> sbtinfo2: requesting image info for
<TITAN_17835_1_492232560>
03:40:57.660 [24976] <4> get_bfs_date_range: Start Time = 04/24/03 03:16:00
03:40:57.660 [24976] <4> get_bfs_date_range: End Time = 04/26/03 03:16:00
03:40:57.662 [24976] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35240 TO 10.240.232.60.13720
03:40:58.080 [24976] <4> sbtinfo2: Image Information for file
<TITAN_17835_1_492232560> :
03:40:58.080 [24976] <4> sbtinfo2:      Media Sharing Mode : <Single User>
03:40:58.080 [24976] <4> sbtinfo2:      File Ordering Mode : <Sequential
file access>
03:40:58.080 [24976] <4> sbtinfo2:      Media ID : <CG0065>
03:40:58.080 [24976] <4> sbtinfo2:      File Creation Date and Time :
<1051258565>
03:40:58.080 [24976] <4> sbtinfo2:      File Expiration Date and Time :
<1053936965>
03:40:58.080 [24976] <4> sbtinfo2:      Comment : <Backup ID :
saturn1_1051258565>
03:40:58.080 [24976] <4> sbtinfo2:      File Creation Method : <Stream>
03:41:05.290 [24976] <4> get_bfs_date_range: Start Time = 04/24/03 03:41:03
03:41:05.290 [24976] <4> get_bfs_date_range: End Time = 04/26/03 03:41:03
03:41:05.292 [24976] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35241 TO 10.240.232.60.13720
03:41:05.608 [24976] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35242 TO 10.240.232.60.13720
03:41:05.699 [24976] <4> find_backup_image: TITAN_17839_1_492234063 not
found
03:41:05.699 [24976] <4> do_backup_restore: Starting Backup Process:
                Server name:    europa
                Client name:    saturn1
                Policy name:    UNIX_Oracle
                Schedule name:  saturn1
03:41:05.701 [24976] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35243 TO 10.240.232.60.13720
03:41:05.879 [24976] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35244 TO 10.240.232.60.13720
03:41:18.740 [24980] <4> sbtclose2: sbtclose2 exiting (0)
03:41:18.740 [24980] <4> sbtinfo2: requesting image info for
<TITAN_17836_1_492232575>
03:41:18.740 [24980] <4> get_bfs_date_range: Start Time = 04/24/03 03:16:15
03:41:18.740 [24980] <4> get_bfs_date_range: End Time = 04/26/03 03:16:15
03:41:18.742 [24980] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35257 TO 10.240.232.60.13720
03:41:19.190 [24980] <4> sbtinfo2: Image Information for file
<TITAN_17836_1_492232575> :
03:41:19.190 [24980] <4> sbtinfo2:      Media Sharing Mode : <Single User>
03:41:19.190 [24980] <4> sbtinfo2:      File Ordering Mode : <Sequential
file access>
03:41:19.190 [24980] <4> sbtinfo2:      Media ID : <CG0065>
03:41:19.190 [24980] <4> sbtinfo2:      File Creation Date and Time :
<1051258580>
03:41:19.190 [24980] <4> sbtinfo2:      File Expiration Date and Time :
<1053936980>
03:41:19.190 [24980] <4> sbtinfo2:      Comment : <Backup ID :
saturn1_1051258580>
03:41:19.190 [24980] <4> sbtinfo2:      File Creation Method : <Stream>
03:41:20.220 [24980] <4> get_bfs_date_range: Start Time = 04/24/03 03:41:19
03:41:20.220 [24980] <4> get_bfs_date_range: End Time = 04/26/03 03:41:19
03:41:20.221 [24980] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35258 TO 10.240.232.60.13720
03:41:20.526 [24980] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35260 TO 10.240.232.60.13720
03:41:20.628 [24980] <4> find_backup_image: TITAN_17840_1_492234079 not
found
03:41:20.628 [24980] <4> do_backup_restore: Starting Backup Process:
                Server name:    europa
                Client name:    saturn1
                Policy name:    UNIX_Oracle
                Schedule name:  saturn1
03:41:20.630 [24980] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35261 TO 10.240.232.60.13720
03:41:20.763 [24980] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35262 TO 10.240.232.60.13720
03:41:20.911 [24976] <4> do_backup_restore: sbtbackup took 15 secs. Start
transfering data ...
03:41:22.020 [24976] <4> sbtwrite2: writing buffer # 1 of size 262144.
03:41:30.785 [24980] <4> do_backup_restore: sbtbackup took 10 secs. Start
transfering data ...
03:41:31.422 [24980] <4> sbtwrite2: writing buffer # 1 of size 262144.
03:41:37.010 [24984] <4> sbtclose2: sbtclose2 exiting (0)
03:41:37.010 [24984] <4> sbtinfo2: requesting image info for
<TITAN_17837_1_492232651>
03:41:37.010 [24984] <4> get_bfs_date_range: Start Time = 04/24/03 03:17:31
03:41:37.011 [24984] <4> get_bfs_date_range: End Time = 04/26/03 03:17:31
03:41:37.013 [24984] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35275 TO 10.240.232.60.13720
03:41:37.450 [24984] <4> sbtinfo2: Image Information for file
<TITAN_17837_1_492232651> :
03:41:37.450 [24984] <4> sbtinfo2:      Media Sharing Mode : <Single User>
03:41:37.450 [24984] <4> sbtinfo2:      File Ordering Mode : <Sequential
file access>
03:41:37.451 [24984] <4> sbtinfo2:      Media ID : <CG0080>
03:41:37.451 [24984] <4> sbtinfo2:      File Creation Date and Time :
<1051258654>
03:41:37.451 [24984] <4> sbtinfo2:      File Expiration Date and Time :
<1053937054>
03:41:37.451 [24984] <4> sbtinfo2:      Comment : <Backup ID :
saturn1_1051258654>
03:41:37.451 [24984] <4> sbtinfo2:      File Creation Method : <Stream>
03:41:45.690 [24984] <4> get_bfs_date_range: Start Time = 04/24/03 03:41:44
03:41:45.690 [24984] <4> get_bfs_date_range: End Time = 04/26/03 03:41:44
03:41:45.692 [24984] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35317 TO 10.240.232.60.13720
03:41:46.015 [24984] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35322 TO 10.240.232.60.13720
03:41:46.110 [24984] <4> find_backup_image: TITAN_17841_1_492234104 not
found
03:41:46.110 [24984] <4> do_backup_restore: Starting Backup Process:
                Server name:    europa
                Client name:    saturn1
                Policy name:    UNIX_Oracle
                Schedule name:  saturn1
03:41:46.112 [24984] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35327 TO 10.240.232.60.13720
03:41:46.272 [24984] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35330 TO 10.240.232.60.13720
03:41:54.010 [24965] <4> sbtclose2: sbtclose2 exiting (0)
03:41:54.011 [24965] <4> sbtinfo2: requesting image info for
<TITAN_17838_1_492232666>
03:41:54.011 [24965] <4> get_bfs_date_range: Start Time = 04/24/03 03:17:46
03:41:54.011 [24965] <4> get_bfs_date_range: End Time = 04/26/03 03:17:46
03:41:54.013 [24965] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35374 TO 10.240.232.60.13720
03:41:54.521 [24965] <4> sbtinfo2: Image Information for file
<TITAN_17838_1_492232666> :
03:41:54.521 [24965] <4> sbtinfo2:      Media Sharing Mode : <Single User>
03:41:54.521 [24965] <4> sbtinfo2:      File Ordering Mode : <Sequential
file access>
03:41:54.521 [24965] <4> sbtinfo2:      Media ID : <CG0080>
03:41:54.521 [24965] <4> sbtinfo2:      File Creation Date and Time :
<1051258670>
03:41:54.521 [24965] <4> sbtinfo2:      File Expiration Date and Time :
<1053937070>
03:41:54.521 [24965] <4> sbtinfo2:      Comment : <Backup ID :
saturn1_1051258670>
03:41:54.521 [24965] <4> sbtinfo2:      File Creation Method : <Stream>
03:41:56.292 [24984] <4> do_backup_restore: sbtbackup took 10 secs. Start
transfering data ...
03:42:01.340 [24984] <4> sbtwrite2: writing buffer # 1 of size 262144.
03:42:02.760 [24965] <4> get_bfs_date_range: Start Time = 04/24/03 03:42:00
03:42:02.761 [24965] <4> get_bfs_date_range: End Time = 04/26/03 03:42:00
03:42:02.763 [24965] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35376 TO 10.240.232.60.13720
03:42:03.075 [24965] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35377 TO 10.240.232.60.13720
03:42:03.162 [24965] <4> find_backup_image: TITAN_17842_1_492234120 not
found
03:42:03.162 [24965] <4> do_backup_restore: Starting Backup Process:
                Server name:    europa
                Client name:    saturn1
                Policy name:    UNIX_Oracle
                Schedule name:  saturn1
03:42:03.164 [24965] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35378 TO 10.240.232.60.13720
03:42:03.304 [24965] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35379 TO 10.240.232.60.13720
03:42:08.310 [24965] <16> serverResponse: ERR - server exited with status
11: system call failed
03:42:08.311 [24965] <16> CreateNewImage: ERR - serverResponse() failed
03:42:08.311 [24965] <16> do_backup_restore: Failed to open.
03:42:08.311 [24965] <16> sbtbackup: Failed to open for backup.
03:42:09.545 [24984] <16> writeToServer: ERR - send() to server on socket %d
failed: Broken pipe (32)
03:42:09.545 [24984] <16> dbc_put: ERR - failed sending data to server
03:42:09.546 [24984] <16> sbtwrite2: sbtwrite2() failed.
03:42:13.751 [24984] <16> dbc_put: ERR - invalid handle received from the
application
03:42:13.751 [24984] <16> sbtwrite2: sbtwrite2() failed.
03:42:14.780 [24984] <8> close_image: Session being terminated abnormally,
cleaning up
03:42:14.780 [24984] <4> close_image: INF - backup FAILED
03:42:14.780 [24984] <4> close_image: INF ---- end of Backup ---
03:42:14.780 [24984] <16> sbtclose2: ERROR. Failed to process:
<TITAN_17841_1_492234104>
03:42:14.781 [24984] <4> sbtclose2: sbtclose2 exiting (-1)
03:42:14.781 [24984] <16> sbtclose2: Failed to process backup file.
03:42:16.930 [24976] <8> close_image: Session being terminated abnormally,
cleaning up
03:42:16.931 [24976] <4> close_image: INF - backup FAILED
03:42:16.931 [24976] <4> close_image: INF ---- end of Backup ---
03:42:16.931 [24976] <16> sbtclose2: ERROR. Failed to process:
<TITAN_17839_1_492234063>
03:42:16.932 [24976] <4> sbtclose2: sbtclose2 exiting (-1)
03:42:16.932 [24976] <16> sbtclose2: Failed to process backup file.
03:42:18.990 [24980] <8> close_image: Session being terminated abnormally,
cleaning up
03:42:18.991 [24980] <4> close_image: INF - backup FAILED
03:42:18.991 [24980] <4> close_image: INF ---- end of Backup ---
03:42:18.991 [24980] <16> sbtclose2: ERROR. Failed to process:
<TITAN_17840_1_492234079>
03:42:18.992 [24980] <4> sbtclose2: sbtclose2 exiting (-1)
03:42:18.992 [24980] <16> sbtclose2: Failed to process backup file.
03:42:21.061 [24976] <4> get_bfs_date_range: Start Time = 04/24/03 03:41:03
03:42:21.061 [24976] <4> get_bfs_date_range: End Time = 04/26/03 03:41:03
03:42:21.063 [24976] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35386 TO 10.240.232.60.13720
03:42:21.384 [24976] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35387 TO 10.240.232.60.13720
03:42:22.091 [24980] <4> get_bfs_date_range: Start Time = 04/24/03 03:41:19
03:42:22.091 [24980] <4> get_bfs_date_range: End Time = 04/26/03 03:41:19
03:42:22.093 [24980] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35388 TO 10.240.232.60.13720
03:42:22.414 [24980] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35389 TO 10.240.232.60.13720
03:42:23.021 [24984] <4> get_bfs_date_range: Start Time = 04/24/03 03:41:44
03:42:23.021 [24984] <4> get_bfs_date_range: End Time = 04/26/03 03:41:44
03:42:23.023 [24984] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35391 TO 10.240.232.60.13720
03:42:23.344 [24984] <2> logconnections: BPRD CONNECT FROM
10.240.232.13.35392 TO 10.240.232.60.13720
03:42:23.771 [24965] <4> sbtend: --- END of SESSION ---
03:42:24.561 [24976] <4> sbtend: --- END of SESSION ---
03:42:25.601 [24980] <4> sbtend: --- END of SESSION ---
03:42:26.520 [24984] <4> sbtend: --- END of SESSION ---

Any ideas?
-M


<Prev in Thread] Current Thread [Next in Thread>