Video Screencast Help
Symantec to Separate Into Two Focused, Industry-Leading Technology Companies. Learn more.

Exchange Backup Failure

Created: 03 May 2013 | 1 comment

Hello,

all the sudden our exchange backups begin failing. Below is the Details from both the mbx02 and dag01 backups.

5/2/2013 5:59:15 PM - Info nbjm(pid=6568) starting backup job (jobid=322849) for client MBX02, policy Exchange, schedule Full 
5/2/2013 5:59:15 PM - Info nbjm(pid=6568) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=322849, request id:{C747D6AD-EE1D-4BEA-93E8-D63EE24F772F}) 
5/2/2013 5:59:15 PM - requesting resource Any
5/2/2013 5:59:15 PM - requesting resource horus.NBU_CLIENT.MAXJOBS.MBX02
5/2/2013 5:59:15 PM - requesting resource horus.NBU_POLICY.MAXJOBS.Exchange
5/2/2013 5:59:15 PM - granted resource horus.NBU_CLIENT.MAXJOBS.MBX02
5/2/2013 5:59:15 PM - granted resource horus.NBU_POLICY.MAXJOBS.Exchange
5/2/2013 5:59:15 PM - granted resource 093752
5/2/2013 5:59:15 PM - granted resource IBM.ULTRIUM-TD4.005
5/2/2013 5:59:15 PM - granted resource horus-hcart-robot-tld-1
5/2/2013 5:59:15 PM - estimated 248456322 Kbytes needed
5/2/2013 5:59:15 PM - begin Parent Job
5/2/2013 5:59:15 PM - begin Exchange 14 Snapshot, Step By Condition
Status 0
5/2/2013 5:59:15 PM - end Exchange 14 Snapshot, Step By Condition; elapsed time: 00:00:00
5/2/2013 5:59:15 PM - begin Exchange 14 Snapshot, Read File List
Status 0
5/2/2013 5:59:15 PM - end Exchange 14 Snapshot, Read File List; elapsed time: 00:00:00
5/2/2013 5:59:15 PM - begin Exchange 14 Snapshot, Create Snapshot
5/2/2013 5:59:15 PM - started process bpbrm (7168)
5/2/2013 5:59:15 PM - started
5/2/2013 5:59:20 PM - Info bpbrm(pid=7168) MBX02 is the host to backup data from    
5/2/2013 5:59:20 PM - Info bpbrm(pid=7168) reading file list from client       
5/2/2013 5:59:20 PM - Info bpbrm(pid=7168) start bpfis on client        
5/2/2013 5:59:20 PM - Info bpbrm(pid=7168) Starting create snapshot processing        
5/2/2013 5:59:22 PM - Info bpfis(pid=6428) Backup started          
5/2/2013 5:59:33 PM - Critical bpbrm(pid=7168) from client MBX02: FTL - snapshot creation failed - Error attempting to gather metadata., status 130
5/2/2013 5:59:33 PM - Info bpbrm(pid=7168) DB_BACKUP_STATUS is 156         
5/2/2013 5:59:33 PM - Warning bpbrm(pid=7168) from client MBX02: WRN - NEW_STREAM0 is not frozen   
5/2/2013 5:59:33 PM - Warning bpbrm(pid=7168) from client MBX02: WRN - Microsoft Information Store:\MDB02 is not frozen 
5/2/2013 5:59:33 PM - Info bpfis(pid=6428) done. status: 130         
5/2/2013 5:59:33 PM - end Exchange 14 Snapshot, Create Snapshot; elapsed time: 00:00:18
5/2/2013 5:59:33 PM - Info bpfis(pid=0) done. status: 130: system error occurred      
5/2/2013 5:59:33 PM - end writing
Status 130
5/2/2013 5:59:33 PM - end Parent Job; elapsed time: 00:00:18
5/2/2013 5:59:33 PM - begin Exchange 14 Snapshot, Stop On Error
Status 0
5/2/2013 5:59:33 PM - end Exchange 14 Snapshot, Stop On Error; elapsed time: 00:00:00
5/2/2013 5:59:33 PM - begin Exchange 14 Snapshot, Delete Snapshot
5/2/2013 5:59:34 PM - started process bpbrm (7664)
5/2/2013 5:59:39 PM - Info bpbrm(pid=7664) Starting delete snapshot processing        
5/2/2013 5:59:39 PM - Info bpfis(pid=0) Snapshot will not be deleted       
5/2/2013 5:59:42 PM - Info bpfis(pid=5384) Backup started          
5/2/2013 5:59:42 PM - Critical bpbrm(pid=7664) from client MBX02: cannot open C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.DAG01_1367531955.1.0     
5/2/2013 5:59:43 PM - Info bpfis(pid=5384) done. status: 1542         
5/2/2013 5:59:43 PM - end Exchange 14 Snapshot, Delete Snapshot; elapsed time: 00:00:10
5/2/2013 5:59:43 PM - Info bpfis(pid=0) done. status: 1542: An existing snapshot is no longer valid and cannot be mounted for subsequent operations
5/2/2013 5:59:43 PM - end writing
Status 1542
5/2/2013 5:59:43 PM - end operation
Status 130
5/2/2013 5:59:43 PM - end operation
system error occurred(130)

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

5/2/2013 5:58:55 PM - Info nbjm(pid=6568) starting backup job (jobid=322848) for client DAG01, policy Exchange, schedule Full 
5/2/2013 5:58:55 PM - Info nbjm(pid=6568) requesting MEDIA_SERVER_ONLY resources from RB for backup job (jobid=322848, request id:{98DDDC82-222F-4C52-8948-AD0512454131}) 
5/2/2013 5:58:55 PM - requesting resource Any
5/2/2013 5:58:55 PM - requesting resource horus.NBU_CLIENT.MAXJOBS.DAG01
5/2/2013 5:58:55 PM - requesting resource horus.NBU_POLICY.MAXJOBS.Exchange
5/2/2013 5:58:55 PM - requesting resource EXCHANGE_RESOLVER.horus.Exchange.DAG01
5/2/2013 5:58:55 PM - granted resource horus.NBU_CLIENT.MAXJOBS.DAG01
5/2/2013 5:58:55 PM - granted resource horus.NBU_POLICY.MAXJOBS.Exchange
5/2/2013 5:58:55 PM - granted resource EXCHANGE_RESOLVER.horus.Exchange.DAG01
5/2/2013 5:58:56 PM - estimated 0 Kbytes needed
5/2/2013 5:58:56 PM - begin Parent Job
5/2/2013 5:58:56 PM - begin Exchange 14 Resolver, Start Notify Script
5/2/2013 5:58:56 PM - Info RUNCMD(pid=8328) started           
5/2/2013 5:58:56 PM - Info RUNCMD(pid=8328) exiting with status: 0        
Status 0
5/2/2013 5:58:56 PM - end Exchange 14 Resolver, Start Notify Script; elapsed time: 00:00:00
5/2/2013 5:58:56 PM - begin Exchange 14 Resolver, Step By Condition
Status 0
5/2/2013 5:58:56 PM - end Exchange 14 Resolver, Step By Condition; elapsed time: 00:00:00
5/2/2013 5:58:56 PM - begin Exchange 14 Resolver, Read File List
Status 0
5/2/2013 5:58:56 PM - end Exchange 14 Resolver, Read File List; elapsed time: 00:00:00
5/2/2013 5:58:56 PM - begin Exchange 14 Resolver, Resolver Discovery
5/2/2013 5:58:57 PM - started process bpbrm (2644)
5/2/2013 5:58:58 PM - Info bpbrm(pid=2644) DAG01 is the host to restore to     
5/2/2013 5:58:58 PM - Info bpbrm(pid=2644) reading file list from client       
5/2/2013 5:59:07 PM - Info bpbrm(pid=2644) client_pid=8680           
5/2/2013 5:59:07 PM - Info bpbrm(pid=2644) from client DAG01: TRV - BPRESOLVER has executed on server (MBX02) 
5/2/2013 5:59:13 PM - Info bpresolver(pid=8680) done.  status: 0        
5/2/2013 5:59:13 PM - Info bpresolver(pid=8680) done. status: 0: the requested operation was successfully completed   
Status 0
5/2/2013 5:59:13 PM - end Exchange 14 Resolver, Resolver Discovery; elapsed time: 00:00:17
5/2/2013 5:59:13 PM - begin Exchange 14 Resolver, Persist Discovery
Status 0
5/2/2013 5:59:13 PM - end Exchange 14 Resolver, Persist Discovery; elapsed time: 00:00:00
5/2/2013 5:59:13 PM - begin Exchange 14 Resolver, Policy Execution Manager Preprocessed
Status 130
5/2/2013 5:59:43 PM - end Exchange 14 Resolver, Policy Execution Manager Preprocessed; elapsed time: 00:00:30
5/2/2013 5:59:43 PM - begin Exchange 14 Resolver, Stop On Error
Status 0
5/2/2013 5:59:43 PM - end Exchange 14 Resolver, Stop On Error; elapsed time: 00:00:00
5/2/2013 5:59:43 PM - begin Exchange 14 Resolver, End Notify Script
5/2/2013 5:59:44 PM - Info RUNCMD(pid=9396) started           
5/2/2013 5:59:44 PM - Info RUNCMD(pid=9396) exiting with status: 0        
Status 0
5/2/2013 5:59:44 PM - end Exchange 14 Resolver, End Notify Script; elapsed time: 00:00:01
Status 130
5/2/2013 5:59:44 PM - end Parent Job; elapsed time: 00:00:48
system error occurred(130)

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

thanks

Operating Systems:

Comments 1 CommentJump to latest comment

Mark_Solutions's picture

Usually this happens after a snapshot has failed or replication is out of sync

Run vssadmin list writers to see what state they are in and if any failed either re-start the exchange replication service or reboot

You could also run bpfis query to see if any snapshots have been left behind that need to be deleted

Authorised Symantec Consultant

Don't forget to "Mark as Solution" if someones advice has solved your issue - and please bring back the Thumbs Up!!.