My Oracle Support Banner

Replace Database from Existing Backup Failed With Errors KBHS-01300, ORA-27029 and KBHS-07502 (Doc ID 2405754.1)

Last updated on MAY 31, 2018

Applies to:

Oracle Database Cloud Service - Version N/A to N/A [Release 1.0]
Linux x86-64

Symptoms

Replace database from existing backup failed with errors in dbda.log

KBHS-01300: unable to read backup piece net3t9ov_1_1
RMAN-08615: channel ORA_SBT_TAPE_5: ORA-19870: error while restoring backup piece njt3t9pf_1_1
ORA-19507: failed to retrieve sequential file, handle="njt3t9pf_1_1", parms=""
ORA-27029: skgfrtrv: sbtrestore returned error
ORA-19511: non RMAN, but media manager or vendor specific failure, error text:
KBHS-07502: File not found

From activity log:

May 28, 2018 3:59:52 AM UTC Activity Submitted
May 28, 2018 3:59:52 AM UTC Activity Started
May 28, 2018 3:59:58 AM UTC Started prerequisite checks for replace database from existing backup.
May 28, 2018 3:59:58 AM UTC Starting prerequisite checks for replace database from existing backup.
May 28, 2018 4:02:03 AM UTC Prerequisite checks for replace database from existing backup successful.
May 28, 2018 4:02:07 AM UTC Starting begin operation for replace database from existing backup.
May 28, 2018 4:02:07 AM UTC Started begin operation replace database from existing backup.
May 28, 2018 4:11:17 AM UTC Begin operation for replace database from existing backup failed. Error [Non-zero return from ocde: dbda::INFO recover_database: Recovery Manager complete.\nERROR : ibkup begin has failed, please check logs. You might be able to restore the dbcs env and re-run ibkp begin\nERROR : Assistant dbda has failed, please check ocde logfile /var/opt/oracle/log/<sourceDB>/ocde/ocde_2018-05-28_12:05:33.log\nRunning tfactl start command\nStarting dbcsmon\ntfa.pm: INFO dbcsmon status is:\nStarting OSWatcher\ntfa.pm: INFO OSWatcher status is:\nINFO: Total time taken by ocde is 298 seconds \n\n#### Completed OCDE with errors, please check logs ####\n]
May 28, 2018 4:11:22 AM UTC Reverting to original state.
May 28, 2018 4:11:22 AM UTC Started reverting to original state.
May 28, 2018 4:17:32 AM UTC Reverted successfully to original state.
May 28, 2018 4:17:32 AM UTC The Service [TEST] is restarting...
May 28, 2018 4:17:32 AM UTC VM [TEST] of Database Cloud Service [TEST] is being stopped...
May 28, 2018 4:19:45 AM UTC VM [TEST] of Database Cloud Service [TEST] has been stopped.
May 28, 2018 4:19:45 AM UTC VM [TEST] of Database Cloud Service [TEST] is starting...
May 28, 2018 4:24:03 AM UTC SSH access to VM [DB_1/vm-1] succeeded...
May 28, 2018 4:24:05 AM UTC VM [TEST] of Database Cloud Service [TEST] has been started.
May 28, 2018 4:24:05 AM UTC The Service [TEST] has been restarted.
May 28, 2018 4:24:05 AM UTC Activity Ended

From From ocde log:

### Start: /var/opt/oracle/log/dbaas_lock/dbaas_lock_2018-05-28_09:29:00.log
>> BEGIN dbaas_lock log : dbaas_lock_2018-05-28_09:29:00.log

2018-05-28 09:29:00 - Lock dir is: /var/opt/oracle/ocde
2018-05-28 09:29:00 - Getting local lock: cstate
2018-05-28 09:29:00 - local lock parameters:
2018-05-28 09:29:00 -
............
2018-05-28 12:05:55 -
##Invoking assistant dbda
2018-05-28 12:05:55 - checking for pkg dbda/DbdaVars.pm
.............
2018-05-28 12:09:50 - Starting DBDA
..........
Config file is /var/opt/oracle/ocde/assistants/dbda/dbda.cfg
Enabling VNCR on this DB Node ... VNCR: enable_vncr() : VNCR for the listener : LISTENER was already enabled
Reloading listener after enable_vncr for LISTENER
listener reload DONE for LISTENER
DONE
INFO : Running dbca
INFO : Starting restore of backup
INFO : stopping the db
INFO: db stopped
INFO : deleting dbfiles
INFO : deleting oradata
INFO : restoring spfile
Configuring OSS
Running OPC installer...
INFO : libopc found at /u01/app/oracle/product/12.1.0/dbhome_1/lib. Move to /tmp directory.
Installing OPC installer local copy.
Running OPC installer.....
............
Skipping library download because option -libDir is not specified.
OPC installer completed successfully.
dbda::INFO Restoring SPFILE...
INFO : restoring controlfile
dbda::INFO Restoring CONTROLFILE...
dbda::INFO Disabling FRA temporarily.
INFO : restoring database
dbda::INFO Restore database started (May take a while) ...
INFO : recovering database
dbda::INFO Recovery of database started (May take a while) ...
dbda::INFO recover_database:
dbda::INFO recover_database: Recovery Manager: Release 12.1.0.2.0 - Production on Mon May 28 12:09:27 2018
dbda::INFO recover_database:
............
dbda::INFO recover_database: Recovery Manager complete.
ERROR : ibkup begin has failed, please check logs. You might be able to restore the dbcs env and re-run ibkp begin
2018-05-28 12:09:50 - cmd took 235 seconds
2018-05-28 12:09:50 - WARN : non-zero status returned
...............
Exit: 255
Excerpt:
Starting DBDA
..............
Config file is /var/opt/oracle/ocde/assistants/dbda/dbda.cfg
(...)
dbda::INFO recover_database:
dbda::INFO recover_database: Recovery Manager complete.
ERROR : ibkup begin has failed, please check logs. You might be able to restore the dbcs env and re-run ibkp begin
. . . . .
Successfully started TFA Process..
. . . . .
TFA Started and listening for commands
2018-05-28 12:10:04 - cmd took 13 seconds
2018-05-28 12:10:04 - Starting dbcsmon
2018-05-28 12:10:04 - Output from cmd /var/opt/oracle/tfa/bin/tfactl start dbcsmon run on localhost is:
2018-05-28 12:10:06 - dbcsmon is already running
2018-05-28 12:10:06 - cmd took 2 seconds
2018-05-28 12:10:06 - tfa.pm: INFO dbcsmon status is:
2018-05-28 12:10:06 - Output from cmd /var/opt/oracle/tfa/bin/tfactl toolstatus | grep dbcsmon | awk -F ' ' '{print $7}' run on localhost is:
2018-05-28 12:10:17 - RUNNING
2018-05-28 12:10:17 - cmd took 11 seconds
2018-05-28 12:10:17 - Starting OSWatcher
2018-05-28 12:10:17 - Output from cmd /var/opt/oracle/tfa/bin/tfactl start oswbb run on localhost is:
2018-05-28 12:10:18 - Starting OSWatcher
ERROR: Failed to start OSWatcher. Please review /var/opt/oracle/tfa/repository/suptools/test/oswbb/root/run_1527480618.log for details

2018-05-28 12:10:18 - cmd took 1 seconds
2018-05-28 12:10:18 - tfa.pm: INFO OSWatcher status is:
2018-05-28 12:10:18 - Output from cmd /var/opt/oracle/tfa/bin/tfactl toolstatus | grep oswbb | awk -F ' ' '{print $7}' run on localhost is:
2018-05-28 12:10:30 - NOT
2018-05-28 12:10:30 - cmd took 12 seconds
2018-05-28 12:10:30 - INFO: Total time taken by ocde is 298 seconds
2018-05-28 12:10:30 -
#### Completed OCDE with errors, please check logs ####
2018-05-28 12:10:30 - Output from cmd touch /var/opt/oracle/log/ocde/ocde.log run on localhost is:
2018-05-28 12:10:30 - cmd took 0 seconds

From dbda.log:

2018-05-28 12:05:56 - RPM: dbaastools-1.0-1+18.2.3.1.0_180523.0000.x86_64
2018-05-28 12:05:56 - Starting DBDA
............
2018-05-28 12:09:27 - dbda::INFO restore_database: RMAN-08089: channel ORA_SBT_TAPE_5: specifying datafile(s) to restore from backup set
2018-05-28 12:09:27 - dbda::INFO restore_database: RMAN-08610: channel ORA_SBT_TAPE_5: restoring datafile 00122 ....
2018-05-28 12:09:27 - dbda::INFO restore_database: RMAN-08003: channel ORA_SBT_TAPE_5: reading from backup piece o3t3tnbi_1_1
2018-05-28 12:09:27 - dbda::INFO restore_database: RMAN-08615: channel ORA_SBT_TAPE_1: ORA-19870: error while restoring backup piece o1t3tnbh_1_1
2018-05-28 12:09:27 - dbda::INFO restore_database: ORA-19507: failed to retrieve sequential file, handle="o1t3tnbh_1_1", parms=""
2018-05-28 12:09:27 - dbda::INFO restore_database: ORA-27029: skgfrtrv: sbtrestore returned error
2018-05-28 12:09:27 - dbda::INFO restore_database: ORA-19511: non RMAN, but media manager or vendor specific failure, error text:
2018-05-28 12:09:27 - dbda::INFO restore_database: KBHS-07502: File not found
................
2018-05-28 12:09:27 - dbda::INFO restore_database: KBHS-01404: See trace file /u01/app/oracle/product/12.1.0/dbhome_1/rdbms/log/sbtio_20825_139952098779776.log for details
2018-05-28 12:09:27 - dbda::INFO restore_database: KBHS-01300: unable to read backup piece net3t9ov_1_1
2018-05-28 12:09:27 - dbda::INFO restore_database: RMAN-08615: channel ORA_SBT_TAPE_5: ORA-19870: error while restoring backup piece njt3t9pf_1_1
2018-05-28 12:09:27 - dbda::INFO restore_database: ORA-19507: failed to retrieve sequential file, handle="njt3t9pf_1_1", parms=""
2018-05-28 12:09:27 - dbda::INFO restore_database: ORA-27029: skgfrtrv: sbtrestore returned error
2018-05-28 12:09:27 - dbda::INFO restore_database: ORA-19511: non RMAN, but media manager or vendor specific failure, error text:
2018-05-28 12:09:27 - dbda::INFO restore_database: KBHS-07502: File not found
2018-05-28 12:09:27 - dbda::INFO restore_database: KBHS-01404: See trace file /u01/app/oracle/product/12.1.0/dbhome_1/rdbms/log/sbtio_20826_140193145467520.log for details
2018-05-28 12:09:27 - dbda::INFO restore_database: KBHS-01300: unable to read backup piece njt3t9pf_1_1
2018-05-28 12:09:27 - dbda::INFO restore_database: RMAN-05016: failover to previous backup
2018-05-28 12:09:27 - dbda::INFO restore_database:
2018-05-28 12:09:27 - dbda::INFO restore_database: RMAN-00571: ===========================================================
2018-05-28 12:09:27 - dbda::INFO restore_database: RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
2018-05-28 12:09:27 - dbda::INFO restore_database: RMAN-00571: ===========================================================
2018-05-28 12:09:27 - dbda::INFO restore_database: RMAN-03002: failure of restore command at 05/28/2018 12:09:26
2018-05-28 12:09:27 - dbda::INFO restore_database: RMAN-06026: some targets not found - aborting restore
2018-05-28 12:09:27 - dbda::INFO restore_database: RMAN-06023: no backup or copy of datafile 7 found to restore
2018-05-28 12:09:27 - dbda::INFO restore_database: RMAN-06023: no backup or copy of datafile 5 found to restore
2018-05-28 12:09:27 - dbda::INFO restore_database:
2018-05-28 12:09:27 - dbda::INFO restore_database: RMAN>
2018-05-28 12:09:27 - dbda::INFO restore_database:
2018-05-28 12:09:27 - dbda::INFO restore_database: Recovery Manager complete.
2018-05-28 12:09:27 - INFO : recovering database
2018-05-28 12:09:27 - dbda::INFO Recovery of database started (May take a while) ...
2018-05-28 12:09:35 - dbda::INFO disk_archive_logs_purge: RMAN INPUT : CONFIGURE DEFAULT DEVICE TYPE TO DISK;
2018-05-28 12:09:35 - dbda::INFO disk_archive_logs_purge: RMAN INPUT : CROSSCHECK ARCHIVELOG ALL;
2018-05-28 12:09:35 - dbda::INFO disk_archive_logs_purge: RMAN INPUT : DELETE NOPROMPT EXPIRED ARCHIVELOG ALL;
2018-05-28 12:09:35 - dbda::INFO disk_archive_logs_purge: RMAN INPUT : CONFIGURE DEFAULT DEVICE TYPE TO SBT_TAPE;
2018-05-28 12:09:35 - dbda::INFO recover_database:
...............
2018-05-28 12:09:50 - dbda::ERROR ORA Error
2018-05-28 12:09:50 - dbda::ERROR Unknown DB Instance condition (ORA)
2018-05-28 12:09:50 - dbda::ERROR _manage_redo_logs: FAILED
2018-05-28 12:09:50 - dbda::ERROR ORA Error

at /var/opt/oracle/ocde/assistants/dbda/dbda line 1276
main::configure() called at /var/opt/oracle/ocde/assistants/dbda/dbda line 466
eval {...} called at /var/opt/oracle/ocde/assistants/dbda/dbda line 440
2018-05-28 12:09:50 - dbda::ERROR Unknown DB Instance condition (ORA)

at /var/opt/oracle/ocde/assistants/dbda/dbda line 1276
main::configure() called at /var/opt/oracle/ocde/assistants/dbda/dbda line 466
eval {...} called at /var/opt/oracle/ocde/assistants/dbda/dbda line 440
2018-05-28 12:09:50 - ERROR : ibkup begin has failed, please check logs. You might be able to restore the dbcs env and re-run ibkp begin
2018-05-28 12:09:50 - ERROR : ibkup begin has failed, please check logs. You might be able to restore the dbcs env and re-run ibkp begin
at /var/opt/oracle/ocde/assistants/dbda/dbda line 1277
main::configure() called at /var/opt/oracle/ocde/assistants/dbda/dbda line 466
eval {...} called at /var/opt/oracle/ocde/assistants/dbda/dbda line 440
2018-05-28 12:09:50 - ERROR: dbda failed

Changes

 

Cause

To view full details, sign in with your My Oracle Support account.

Don't have a My Oracle Support account? Click to get started!


My Oracle Support provides customers with access to over a million knowledge articles and a vibrant support community of peers and Oracle experts.