Video Screencast Help

RMAN Problems after Matster upgrade from 6.0 mp7 to 7.0

Created: 18 May 2010 | 7 comments

Hi,

we have an Oracle 10g RAC of two Windows x64 2003 Server, one of them is an Media-Server NB 6.0 mp5.
After Upgrade the Windows 2003 Master Server from NB 6.0 mp7 to 7.0 everything work well - Media Server, Lib., Exchange only the Oracle - RMAN Backup faild with Error 6.

==== started on 18.05.2010  14:59 ====
Script name: "C:\Program Files\VERITAS\NetBackup\DbExt\Oracle\s07win_arch.cmd"
#                                       
  RMAN  :  D:\oracle\ora102\bin\rman.exe                       
  NLS_LANG  :  american               
  ORACLE_HOME  :  D:\oracle\ora102         
  ORACLE_SID  :  dasp2           
  NLS_DATE_FORMAT  :  YYYY-MM-DD:hh24:mi:ss
  RMAN_LOG_FILE  :  "C:\Program Files\VERITAS\NetBackup\DbExt\Oracle\s07win_arch.05.1459.out"     
  NUMFILES_DASP    : 20     
  NB_ORA_SERV  :  s032backup                     
  NB_ORA_FULL  :  1                     
  NB_ORA_INCR  :  0                     
  NB_ORA_CINC  :  0                     
  NB_ORA_CLASS  :  s07win_ARCH                   
  RMAN_COMPRESSED_BACKUPSET  :  NO                  

Recovery Manager: Release 10.2.0.3.0 - Production on Tue May 18 14:59:31 2010

Copyright (c) 1982, 2005, Oracle.  All rights reserved.

connected to target database: DASP (DBID=2146408483)
connected to recovery catalog database

RMAN> 2> 3> 4> 5> 6> 7> 8> 9> 10>
allocated channel: ch00
channel ch00: sid=437 instance=dasp2 devtype=SBT_TAPE
channel ch00: VERITAS NetBackup for Oracle - Release 6.0 (2002111220)

sql statement: alter system archive log current

Starting backup at 2010-05-18:14:59:50
current log archived
channel ch00: starting archive log backupset
channel ch00: specifying archive log(s) in backup set
input archive log thread=1 sequence=21741 recid=39513 stamp=719316278
input archive log thread=1 sequence=21742 recid=39515 stamp=719319065
input archive log thread=1 sequence=21743 recid=39516 stamp=719323700
input archive log thread=1 sequence=21744 recid=39517 stamp=719327951
channel ch00: starting piece 1 at 2010-05-18:15:00:08
released channel: ch00
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-03009: failure of backup command on ch00 channel at 05/18/2010 15:16:03
ORA-19506: failed to create sequential file, name="arch-s12944-p1", parms=""
ORA-27028: skgfqcre: sbtbackup returned error
ORA-19511: Error received from media manager layer, error text:
   VxBSACreateObject: Failed with error:
   Server Status:  Communication with the server has not been iniatated or the server status has not been retrieved from the serve

RMAN>

Recovery Manager complete.
#   

>> bphdb log

:34.056 [54128.121272] <2> logparams: -sb -rdbms oracle -S s032backup -to 900 -c s07win_RMAN_ARCH -s daily_full -clnt s07win -FULL -kl 5 -b s07win_1274180472 -jobid 758880
:34.072 [54128.121272] <4> bphdb: INF - setenv NB_ORA_POLICY=s07win_RMAN_ARCH
:34.072 [54128.121272] <4> bphdb: INF - setenv NB_ORA_CLIENT=s07win
:34.072 [54128.121272] <4> bphdb: INF - setenv NB_ORA_MODE=B
:34.072 [54128.121272] <4> bphdb: INF - NB_ORA_POLICY=s07win_RMAN_ARCH
:34.072 [54128.121272] <4> bphdb: INF - NB_ORA_SCHED not defined.
:34.072 [54128.121272] <4> bphdb: INF - NB_ORA_PC_SCHED=daily_full
:34.072 [54128.121272] <4> bphdb: INF - NB_ORA_SERV=s032backup
:34.072 [54128.121272] <4> bphdb: INF - NB_ORA_PC_BTYPE not set
:34.072 [54128.121272] <4> bphdb: INF - setenv NB_ORA_FULL=1
:34.072 [54128.121272] <4> bphdb: INF - setenv NB_ORA_INCR=0
:34.072 [54128.121272] <4> bphdb: INF - setenv NB_ORA_CINC=0
:34.072 [54128.121272] <4> bphdb: INF - setenv NB_ORA_SCHEDULED=1
:34.072 [54128.121272] <4> bphdb: INF - BACKUP START
:34.150 [54128.121272] <4> bphdb: INF - CONTINUE BACKUP message received.
:34.150 [54128.121272] <4> bphdb: INF - Processing "C:\Program Files\VERITAS\NetBackup\DbExt\Oracle\s07win_arch.cmd"
:34.150 [54128.121272] <4> bphdb: INF - bphdb still working.
:34.150 [54128.121272] <4> bphdb: INF - bphdb still working.
:34.150 [54128.121272] <4> bphdb: INF - bphdb still working.
:34.150 [54128.121272] <4> bphdb: INF - bphdb still working.
:34.150 [54128.121272] <4> bphdb: INF - bphdb still working.
:34.150 [54128.121272] <4> bphdb: INF - bphdb still working.
:34.150 [54128.121272] <4> bphdb: INF - bphdb still working.
:34.150 [54128.121272] <4> bphdb: INF - bphdb still working.
:34.150 [54128.121272] <4> bphdb: INF - bphdb still working.
:34.150 [54128.121272] <4> bphdb: INF - bphdb still working.
:34.150 [54128.121272] <4> bphdb: INF - bphdb still working.
:34.150 [54128.121272] <4> bphdb: INF - bphdb still working.
:34.150 [54128.121272] <4> bphdb: INF - bphdb still working.
:34.150 [54128.121272] <4> bphdb: INF - bphdb still working.
:34.150 [54128.121272] <4> bphdb: INF - bphdb still working.
:34.150 [54128.121272] <4> bphdb: INF - bphdb still working.
:29.900 [54128.121272] <4> bphdb: INF - command successfully initiated
:29.900 [54128.121272] <16> bphdb: ERR - Script <"C:\Program Files\VERITAS\NetBackup\DbExt\Oracle\s07win_arch.cmd"> failed with status: <1>
:29.900 [54128.121272] <16> bphdb: ERR - for detail output information check file  <C:\Program Files\VERITAS\NetBackup\Logs\bphdb\oracle_stdout.0518110.130134.txt>
:29.900 [54128.121272] <16> bphdb: ERR - for detail error information check file  <C:\Program Files\VERITAS\NetBackup\Logs\bphdb\oracle_stderr.0518110.130134.txt>
:29.900 [54128.121272] <4> bphdb: file C:\Program Files\VERITAS\NetBackup\temp\obackup_class deleted.
:29.900 [54128.121272] <16> bphdb: ERR - bphdb exit status = 6: the backup failed to back up the requested files

:29.900 [54128.121272] <4> bphdb: INF - EXIT STATUS 6: the backup failed to back up the requested files

>>>dbclient Log

14:22:03.541 [4252.136476] <2> int_LogSystemInfo: INF -
VERITAS NetBackup for Oracle - Release 6.0 (2002111220)
        Platform:        Windows
        Computer:        s07win
        OS Release:        5.2
        Build number:    3790
        Misc Info:        Service Pack 2
        User:            SYSTEM
        Client Host:    s07win

14:22:03.541 [4252.136476] <2> int_GetMMInfo: INF - support for Proxy Copy enabled
14:23:56.119 [4252.136476] <2> vnet_vnetd_service_socket: ..\libvlibs\vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:23:56.119 [4252.136476] <2> vnet_vnetd_service_socket: ..\libvlibs\vnet_vnetd.c.2048: service: bprd
14:23:56.338 [4252.136476] <2> logconnections: BPRD CONNECT FROM 172.16.10.7.4340 TO 172.16.10.32.13724
14:23:56.728 [4252.136476] <2> xbsa_ProgressLogSetup: INF - No progress log: Job will proceed without progress logging
14:23:56.806 [4252.136476] <2> vnet_vnetd_service_socket: ..\libvlibs\vnet_vnetd.c.2034: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
14:23:56.806 [4252.136476] <2> vnet_vnetd_service_socket: ..\libvlibs\vnet_vnetd.c.2048: service: bprd
14:23:56.994 [4252.136476] <2> logconnections: BPRD CONNECT FROM 172.16.10.7.4341 TO 172.16.10.32.13724
14:24:27.010 [4252.136476] <2> nb_bind_on_port_addr: set socket option SO_EXCLUSIVEADDRUSE
14:35:29.494 [4272.64436] <16> readCommFile: ERR - timed out after 900 seconds while reading from C:\Program Files\VERITAS\NetBackup\Logs\user_ops\dbext\logs\64436.0.1274185189
14:35:29.494 [4272.64436] <32> serverResponse: ERR - could not read from comm file <C:\Program Files\VERITAS\NetBackup\Logs\user_ops\dbext\logs\64436.0.1274185189>
14:35:29.494 [4272.64436] <16> CreateNewImage: ERR - serverResponse() failed
14:35:29.494 [4272.64436] <16> VxBSACreateObject: ERR - Could not create new image with file /arch-s20007-p1-t719331587.
14:35:29.494 [4272.64436] <16> xbsa_CreateObject: ERR - VxBSACreateObject: Failed with error:
   Server Status:  Communication with the server has not been iniatated or the server status has not been retrieved from the serve
14:35:33.900 [4272.64436] <4> sbtend: INF - --- END of SESSION ---
14:35:33.900 [4272.64436] <8> close_image: Session being terminated abnormally, cleaning up
14:35:33.900 [4272.64436] <4> close_image: INF - backup FAILED
14:35:33.900 [4272.64436] <4> close_image: INF ---- end of Backup ---

14:35:33.900 [4272.64436] <16> VxBSAEndTxn: ERR - Transaction ended with active Backup/Restore.
14:35:33.900 [4272.64436] <16> xbsa_EndTransaction: ERR - VxBSAEndTxn: Failed with error:
   The transaction was aborted.
14:39:32.010 [4252.136476] <16> readCommFile: ERR - timed out after 900 seconds while reading from C:\Program Files\VERITAS\NetBackup\Logs\user_ops\dbext\logs\136476.0.1274185436
14:39:32.010 [4252.136476] <32> serverResponse: ERR - could not read from comm file <C:\Program Files\VERITAS\NetBackup\Logs\user_ops\dbext\logs\136476.0.1274185436>
14:39:32.010 [4252.136476] <16> CreateNewImage: ERR - serverResponse() failed
14:39:32.010 [4252.136476] <16> VxBSACreateObject: ERR - Could not create new image with file /arch-s12943-p1.
14:39:32.010 [4252.136476] <16> xbsa_CreateObject: ERR - VxBSACreateObject: Failed with error:
   Server Status:  Communication with the server has not been iniatated or the server status has not been retrieved from the serve
14:39:41.353 [4252.136476] <4> sbtend: INF - --- END of SESSION ---
14:39:41.353 [4252.136476] <8> close_image: Session being terminated abnormally, cleaning up
14:39:41.353 [4252.136476] <4> close_image: INF - backup FAILED
14:39:41.353 [4252.136476] <4> close_image: INF ---- end of Backup ---
 

Comments 7 CommentsJump to latest comment

Will Restore's picture

Did you only upgrade the Master Server?

Will Restore -- where there is a Will there is a way

Snapfish's picture

Yes, only the Master Server.

RMAN CMD
.......
@(
echo RUN {
echo ALLOCATE CHANNEL ch00 TYPE 'SBT_TAPE';
echo sql 'alter system archive log current';
echo # Backup all archive logs
echo BACKUP
echo       FILESPERSET 20
echo       FORMAT 'arch-s%%s-p%%p'
echo       ARCHIVELOG ALL DELETE ALL INPUT;
echo RELEASE CHANNEL ch00;
echo }
) | %RMAN% catalog rman*****/rman*****@rcrac target %TARGET_CONNECT_STR% msglog '%RMAN_LOG_FILE%' append

.....

Rolf Heitfeld's picture

We exactly have the same Problem!

After Upgrading the master only oracle backups fail with exaclty the same messages.

hopefully

regards

Dipl.-Ing. Rolf Heitfeld

Senior Technology Specialist

Marianne's picture

CreateNewImage: ERR - serverResponse() failed

Check bprd log on master to see if backup request from client is received.
Look for client's IP address and see if master can correctly resolve IP to client name and find policy.

Supporting Storage Foundation and VCS on Unix and Windows as well as NetBackup on Unix and Windows
Handy NBU Links

Will Restore's picture

It is important to understand how new components in NetBackup 6.x/7.x (such as nbemm, nbjm, nbpem, nbrb) communicate when troubleshooting network problems.

http://seer.entsupport.symantec.com/docs/293038.htm

Will Restore -- where there is a Will there is a way

Marianne's picture

Initial comms for database agents is the same as client-initiated backup/archive (Unix and windows).
Initial request goes straight to bprd on master. Since 6.0 this request to bprd is channeled via vnetd.

I have always been able to pick up client -> master comms problems by examining bprd.

This diagram can be found in Appendix A of NBU 7 Troubleshooting Guide:

Supporting Storage Foundation and VCS on Unix and Windows as well as NetBackup on Unix and Windows
Handy NBU Links

Rolf Heitfeld's picture

Hi - thanks for your answers:
It was a corrupt nblog.conf file on the server, that causes the problem. Symantec took 3 days to find that out... After solving I found this articel in the knowledge base - this seems to be the same..
http://seer.entsupport.symantec.com/docs/300751.htm

regards rolf

Dipl.-Ing. Rolf Heitfeld

Senior Technology Specialist