cancel
Showing results forΒ 
Search instead forΒ 
Did you mean:Β 

NetBackup VMWare Status 130

dwilson
Level 4

We are receiving the above 130 error on about 10 of our servers while trying to back them up. The servers are backed up via a VMWare policy type and have previously been backing up successfull in our environment and only recently started having the issue.Can someone help me out on some troubleshooting tips to get this resolved? Environment and Detailed Stauts below.

Environment:

Windows Server 2008R2 Master/Media Server (NetBackup 7.5.0.6)

NetBackup 5220 Appliance (Media Server 7.5.0.6 firmware 2.5.3)

IBM TS3200 Library

 

Detailed Status:

1/7/2014 5:38:48 AM - Info nbjm(pid=2060) starting backup job (jobid=470940) for client USXHQVMPGP, policy VMWare_HQ_1, schedule VMWare_HQ_1_Diff 
1/7/2014 5:38:48 AM - Info nbjm(pid=2060) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=470940, request id:{F963DE6A-C55C-4610-8F4A-B4593271CFCF}) 
1/7/2014 5:38:48 AM - requesting resource stu_disk_USXHQBCKSYM
1/7/2014 5:38:48 AM - requesting resource usxhqbck.NBU_CLIENT.MAXJOBS.USXHQVMPGP
1/7/2014 5:38:48 AM - requesting resource usxhqbck.NBU_POLICY.MAXJOBS.VMWare_HQ_1
1/7/2014 5:38:48 AM - requesting resource usxhqbck.VMware.Datastore.VM5-V7K-10K_02
1/7/2014 5:38:48 AM - granted resource usxhqbck.NBU_CLIENT.MAXJOBS.USXHQVMPGP
1/7/2014 5:38:48 AM - granted resource usxhqbck.NBU_POLICY.MAXJOBS.VMWare_HQ_1
1/7/2014 5:38:48 AM - granted resource usxhqbck.VMware.Datastore.VM5-V7K-10K_02
1/7/2014 5:38:48 AM - granted resource MediaID=@aaaak;DiskVolume=PureDiskVolume;DiskPool=dp_disk_usxhqbcksym;Path=PureDiskVolume;StorageSer...
1/7/2014 5:38:48 AM - granted resource stu_disk_USXHQBCKSYM
1/7/2014 5:38:48 AM - estimated 970650 Kbytes needed
1/7/2014 5:38:48 AM - begin Parent Job
1/7/2014 5:38:48 AM - begin Application Snapshot, Step By Condition
Status 0
1/7/2014 5:38:48 AM - end Application Snapshot, Step By Condition; elapsed time: 00:00:00
1/7/2014 5:38:48 AM - begin Application Snapshot, Read File List
Status 0
1/7/2014 5:38:48 AM - end Application Snapshot, Read File List; elapsed time: 00:00:00
1/7/2014 5:38:48 AM - begin Application Snapshot, Create Snapshot
1/7/2014 5:38:48 AM - started
1/7/2014 5:38:49 AM - started process bpbrm (10224)
1/7/2014 5:42:47 AM - Critical bpbrm(pid=10224) from client USXHQVMPGP: FTL - terminated by signal 11   
1/7/2014 5:42:47 AM - Warning bpbrm(pid=10224) from client USXHQVMPGP: WRN - ALL_LOCAL_DRIVES is not frozen   
1/7/2014 5:42:47 AM - Info bpfis(pid=10231) done. status: 130         
1/7/2014 5:42:47 AM - end Application Snapshot, Create Snapshot; elapsed time: 00:03:59
1/7/2014 5:42:47 AM - Info bpfis(pid=0) done. status: 130: system error occurred      
1/7/2014 5:42:47 AM - end writing
Status 130
1/7/2014 5:42:47 AM - end Parent Job; elapsed time: 00:03:59
1/7/2014 5:42:47 AM - begin Application Snapshot, Stop On Error
Status 0
1/7/2014 5:42:47 AM - end Application Snapshot, Stop On Error; elapsed time: 00:00:00
1/7/2014 5:42:47 AM - begin Application Snapshot, Resources For Cleanup
Status 4294957297
1/7/2014 5:42:47 AM - end Application Snapshot, Resources For Cleanup; elapsed time: 00:00:00
1/7/2014 5:42:47 AM - begin Application Snapshot, Delete Snapshot
1/7/2014 5:42:47 AM - started process bpbrm (10491)
1/7/2014 5:42:49 AM - Info bpbrm(pid=10491) Starting delete snapshot processing        
1/7/2014 5:42:49 AM - Info bpfis(pid=0) Snapshot will not be deleted       
1/7/2014 5:42:51 AM - Info bpfis(pid=10498) Backup started          
1/7/2014 5:42:51 AM - Critical bpbrm(pid=10491) from client USXHQVMPGP: FTL - cannot open /usr/openv/netbackup/online_util/fi_cntl/bpfis.fim.USXHQVMPGP_1389091128.1.0    
1/7/2014 5:42:55 AM - Info bpfis(pid=10498) done. status: 1542         
1/7/2014 5:42:55 AM - end Application Snapshot, Delete Snapshot; elapsed time: 00:00:08
1/7/2014 5:42:55 AM - Info bpfis(pid=0) done. status: 1542: An existing snapshot is no longer valid and cannot be mounted for subsequent operations
1/7/2014 5:42:55 AM - end writing
Status 1542
1/7/2014 5:42:55 AM - end operation
Status 130
1/7/2014 5:42:55 AM - end operation
system error occurred(130)

 

1 ACCEPTED SOLUTION

Accepted Solutions

dwilson
Level 4

Wanted to report back....after working with a VMWare engineer it was found that our issue was with the VMWare Tools installation and a known issue with using VMWare Snapshot Provider for snapshoting instead of Windows Volume Shadow Copy service. Although the VM Snapshot Provider will work in certain situation it will not. VMWare is aware of this and is working to resolve the issue. The work around for now is to disable or uninstall the feature in VMWare Tools and use Windows Shadow Copy.

View solution in original post

14 REPLIES 14

RamNagalla
Moderator
Moderator
Partner    VIP    Certified

what is the Version of Vcenter and VM hardware?

does the backup media server is the backup host?

if possible please post the bpfis and bpbrm log form the backup host.

dwilson
Level 4

vCenter 5.1

VMTools 9.0

the 5220 appliance is a media server and our master server is also a master/media server, in this instance the appliance is the media server being used.

I can provide the bpfis and bpbrm logs one or both

 

Will_Restore
Level 6

See this VMware KB, might apply to your situation

http://kb.vmware.com/selfservice/microsites/search.do?language=en_US&cmd=displayKC&externalId=2006849

 

RamNagalla
Moderator
Moderator
Partner    VIP    Certified

what is the backup host in this above failed job?

 you can find the backup host name in the Policy VMware tab 

and we require the logs form the backup host 

 

dwilson
Level 4

Our enviornment is set to "Backup Media Server" for that field instead of any static server. With that being said the Detailed Status for the failed job specifies that it used our appliance as the media server, so I assume the two logs you requested needs to come from there?

 

WR - I will take a look at the KB as well....Thanks.

dwilson
Level 4

No go on the KB article WR...the client in question is Win 2003 plus none of the listed event id's were found in the viewer.

SymTerry
Level 6
Employee Accredited

It would be nice to see the bpfis logs to get a better idea of what is going on. Also what errors are you getting in vcenter as well. the logs of that VM should say alot. It could be a VM quiescing error.

ejporter
Level 4

I have seen this a couple of times when the virtual machine is doing lots of IO and for VMWare can not create the snapshot.  The solution in our case was to simple change the backup window to a less busy time.

You might want to look at the VMWare logs and see if the snapshot is completing without issues.

rizwan84tx
Level 6
Certified

I echo words of ejporter. Are these 10 VMs are hosted in same Datastore or ESXi node? Try runing the backups when ESXi or datastore is less busy.

dwilson
Level 4

Thanks everyone I have staggered the start schedules as well as the policy priority levels. Will report back in the morning if this had any effect. I also attached the bpfis log from our appliance.

dwilson
Level 4

I also wanted to post a fresh detailed status for a job that ran earlier this morning for the bpfis I attached above. See below.

 

Detailed Status:

1/8/2014 6:06:37 AM - Info nbjm(pid=2060) starting backup job (jobid=471363) for client USXHQVMCOGNOS1, policy VMWare_HQ_1, schedule VMWare_HQ_1_Diff 
1/8/2014 6:06:37 AM - Info nbjm(pid=2060) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=471363, request id:{3025A789-C545-4A1C-9EA8-76C53222D73B}) 
1/8/2014 6:06:37 AM - requesting resource stu_disk_USXHQBCKSYM
1/8/2014 6:06:37 AM - requesting resource usxhqbck.NBU_CLIENT.MAXJOBS.USXHQVMCOGNOS1
1/8/2014 6:06:37 AM - requesting resource usxhqbck.NBU_POLICY.MAXJOBS.VMWare_HQ_1
1/8/2014 6:06:37 AM - requesting resource usxhqbck.VMware.Datastore.VM5-V7K-10K_07
1/8/2014 6:06:37 AM - granted resource usxhqbck.NBU_CLIENT.MAXJOBS.USXHQVMCOGNOS1
1/8/2014 6:06:37 AM - granted resource usxhqbck.NBU_POLICY.MAXJOBS.VMWare_HQ_1
1/8/2014 6:06:37 AM - granted resource usxhqbck.VMware.Datastore.VM5-V7K-10K_07
1/8/2014 6:06:37 AM - granted resource MediaID=@aaaak;DiskVolume=PureDiskVolume;DiskPool=dp_disk_usxhqbcksym;Path=PureDiskVolume;StorageSer...
1/8/2014 6:06:37 AM - granted resource stu_disk_USXHQBCKSYM
1/8/2014 6:06:37 AM - estimated 3844131 Kbytes needed
1/8/2014 6:06:37 AM - begin Parent Job
1/8/2014 6:06:37 AM - begin Application Snapshot, Step By Condition
Status 0
1/8/2014 6:06:37 AM - end Application Snapshot, Step By Condition; elapsed time: 00:00:00
1/8/2014 6:06:37 AM - begin Application Snapshot, Read File List
Status 0
1/8/2014 6:06:37 AM - end Application Snapshot, Read File List; elapsed time: 00:00:00
1/8/2014 6:06:37 AM - begin Application Snapshot, Create Snapshot
1/8/2014 6:06:37 AM - started
1/8/2014 6:06:38 AM - started process bpbrm (3947)
1/8/2014 6:06:39 AM - Info bpbrm(pid=3947) USXHQVMCOGNOS1 is the host to backup data from    
1/8/2014 6:06:39 AM - Info bpbrm(pid=3947) reading file list from client       
1/8/2014 6:06:39 AM - Info bpbrm(pid=3947) start bpfis on client        
1/8/2014 6:06:39 AM - Info bpbrm(pid=3947) Starting create snapshot processing        
1/8/2014 6:06:39 AM - Info bpfis(pid=3978) Backup started          
1/8/2014 6:06:40 AM - snapshot backup of client USXHQVMCOGNOS1 using method VMware_v2
1/8/2014 6:08:43 AM - Critical bpbrm(pid=3947) from client USXHQVMCOGNOS1: FTL - terminated by signal 11   
1/8/2014 6:08:43 AM - Warning bpbrm(pid=3947) from client USXHQVMCOGNOS1: WRN - ALL_LOCAL_DRIVES is not frozen   
1/8/2014 6:08:43 AM - Info bpfis(pid=3978) done. status: 130         
1/8/2014 6:08:43 AM - end Application Snapshot, Create Snapshot; elapsed time: 00:02:06
1/8/2014 6:08:43 AM - Info bpfis(pid=0) done. status: 130: system error occurred      
1/8/2014 6:08:43 AM - end writing
Status 130
1/8/2014 6:08:43 AM - end Parent Job; elapsed time: 00:02:06
1/8/2014 6:08:43 AM - begin Application Snapshot, Stop On Error
Status 0
1/8/2014 6:08:43 AM - end Application Snapshot, Stop On Error; elapsed time: 00:00:00
1/8/2014 6:08:43 AM - begin Application Snapshot, Resources For Cleanup
Status 4294957297
1/8/2014 6:08:43 AM - end Application Snapshot, Resources For Cleanup; elapsed time: 00:00:00
1/8/2014 6:08:43 AM - begin Application Snapshot, Delete Snapshot
1/8/2014 6:08:44 AM - started process bpbrm (4061)
1/8/2014 6:08:46 AM - Info bpbrm(pid=4061) Starting delete snapshot processing        
1/8/2014 6:08:46 AM - Info bpfis(pid=0) Snapshot will not be deleted       
1/8/2014 6:08:47 AM - Info bpfis(pid=4076) Backup started          
1/8/2014 6:08:47 AM - Critical bpbrm(pid=4061) from client USXHQVMCOGNOS1: FTL - cannot open /usr/openv/netbackup/online_util/fi_cntl/bpfis.fim.USXHQVMCOGNOS1_1389179197.1.0    
1/8/2014 6:08:51 AM - Info bpfis(pid=4076) done. status: 1542         
1/8/2014 6:08:51 AM - end Application Snapshot, Delete Snapshot; elapsed time: 00:00:08
1/8/2014 6:08:51 AM - Info bpfis(pid=0) done. status: 1542: An existing snapshot is no longer valid and cannot be mounted for subsequent operations
1/8/2014 6:08:51 AM - end writing
Status 1542
1/8/2014 6:08:51 AM - end operation
Status 130
1/8/2014 6:08:51 AM - end operation
system error occurred(130)

RamNagalla
Moderator
Moderator
Partner    VIP    Certified

does the bpfis log with  VERBOSE level 5?

does the VMs have any existing snaphots?

dwilson
Level 4

After looking into our VM logging it looks that we are receiving errors quiescing the drives to these servers. I have opened a ticket with our VMWare support and will report back on our findings.

dwilson
Level 4

Wanted to report back....after working with a VMWare engineer it was found that our issue was with the VMWare Tools installation and a known issue with using VMWare Snapshot Provider for snapshoting instead of Windows Volume Shadow Copy service. Although the VM Snapshot Provider will work in certain situation it will not. VMWare is aware of this and is working to resolve the issue. The work around for now is to disable or uninstall the feature in VMWare Tools and use Windows Shadow Copy.