Netbackup 7.1 - Exchange 2010 - issue when backuping passive node

[Louis_Rioux]

Hi

We are in a process to migrate from Netbackup 6.5.4 and Exchange 2007 to Netbackup 7.1 and Exchange 2010

I create en test environment with Netbackup 7.1 and Exchange 2010 (three nodes on a DAG environment). When I backup my Exchange mailbox database using the active node, everithing work just fine. However, if I change my policy to backup from a passive node, I got a VSS related error. At first, I though that I had a configuration problem with one of my node, so I move my active database from one node to another, but I always got the same result no matter witch node hold the mounted database.

This is the log I got when I try to backup from a passive node.

2011-07-13 11:08:54 - Info nbjm(pid=2972) starting backup job (jobid=13061) for client MUTAI, policy mosop, schedule Full 
2011-07-13 11:08:54 - Info nbjm(pid=2972) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=13061, request id:{44B74676-438D-495F-B533-E16467A75832}) 
2011-07-13 11:08:54 - requesting resource piscine
2011-07-13 11:08:54 - requesting resource quems0312.NBU_CLIENT.MAXJOBS.MUTAI
2011-07-13 11:08:54 - requesting resource quems0312.NBU_POLICY.MAXJOBS.mosop
2011-07-13 11:08:54 - granted resource quems0312.NBU_CLIENT.MAXJOBS.MUTAI
2011-07-13 11:08:54 - granted resource quems0312.NBU_POLICY.MAXJOBS.mosop
2011-07-13 11:08:54 - granted resource MediaID=@aaaa4;Path=E:\;MediaServer=quems0312
2011-07-13 11:08:54 - granted resource piscine
2011-07-13 11:08:54 - estimated 0 Kbytes needed
2011-07-13 11:08:54 - begin Parent Job
2011-07-13 11:08:54 - begin Unknown Type, Step By Condition
Status 0
2011-07-13 11:08:54 - end Unknown Type, Step By Condition; elapsed time: 00:00:00
2011-07-13 11:08:54 - begin Unknown Type, Read File List
Status 0
2011-07-13 11:08:54 - end Unknown Type, Read File List; elapsed time: 00:00:00
2011-07-13 11:08:54 - begin Unknown Type, Create Snapshot
2011-07-13 11:08:54 - started process bpbrm (4960)
2011-07-13 11:08:54 - started
2011-07-13 11:08:55 - Info bpbrm(pid=4960) MUTAI is the host to backup data from    
2011-07-13 11:09:00 - Info bpbrm(pid=4960) reading file list from client       
2011-07-13 11:09:00 - Info bpbrm(pid=4960) start bpfis on client        
2011-07-13 11:09:00 - begin Create Snapshot
2011-07-13 11:09:01 - Info bpfis(pid=3340) Backup started          
2011-07-13 11:15:38 - Critical bpbrm(pid=4960) from client MUTAI: FTL - snapshot creation failed - Error attempting to gather metadata., status 130
2011-07-13 11:15:38 - Info bpbrm(pid=4960) DB_BACKUP_STATUS is 156         
2011-07-13 11:15:38 - Critical bpbrm(pid=4960) from client MUTAI: FTL - snapshot creation failed, status 130  
2011-07-13 11:15:38 - Warning bpbrm(pid=4960) from client MUTAI: WRN - NEW_STREAM0 is not frozen   
2011-07-13 11:15:38 - Warning bpbrm(pid=4960) from client MUTAI: WRN - Microsoft Information Store:\quebec-2010 is not frozen 
2011-07-13 11:15:38 - Info bpfis(pid=3340) done. status: 130         
2011-07-13 11:15:38 - end Create Snapshot; elapsed time: 00:06:38
2011-07-13 11:15:41 - end writing
Status 130
2011-07-13 11:15:41 - end Unknown Type, Create Snapshot; elapsed time: 00:06:47
2011-07-13 11:15:41 - begin Unknown Type, Stop On Error
Status 0
2011-07-13 11:15:41 - end Unknown Type, Stop On Error; elapsed time: 00:00:00
2011-07-13 11:15:41 - begin Unknown Type, Delete Snapshot On Exit
2011-07-13 11:15:41 - begin Unknown Type, Delete Snapshot On Exit
2011-07-13 11:15:41 - started process bpbrm (2520)
2011-07-13 11:15:46 - Info bpfis(pid=0) done. status: 130: system error occurred      
2011-07-13 11:15:51 - end writing
Status 0
2011-07-13 11:15:51 - end Unknown Type, Delete Snapshot On Exit; elapsed time: 00:00:10
Status 130
2011-07-13 11:15:51 - end Unknown Type, Delete Snapshot On Exit; elapsed time: 00:00:10
system error occurred(130) 

And this is the message I got, when i backup from the active node

2011-07-13 10:45:54 - Info nbjm(pid=2972) starting backup job (jobid=13057) for client GEBRSELASSIE, policy mosop, schedule Full 
2011-07-13 10:45:54 - Info nbjm(pid=2972) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=13057, request id:{14E2F09A-72AC-4365-8F65-DB6FAEC32C41}) 
2011-07-13 10:45:54 - requesting resource piscine
2011-07-13 10:45:54 - requesting resource quems0312.NBU_CLIENT.MAXJOBS.GEBRSELASSIE
2011-07-13 10:45:54 - requesting resource quems0312.NBU_POLICY.MAXJOBS.mosop
2011-07-13 10:45:54 - awaiting resource piscine - Maximum job count has been reached for the storage unit
2011-07-13 10:56:50 - granted resource quems0312.NBU_CLIENT.MAXJOBS.GEBRSELASSIE
2011-07-13 10:56:50 - granted resource quems0312.NBU_POLICY.MAXJOBS.mosop
2011-07-13 10:56:50 - granted resource MediaID=@aaaa4;Path=E:\;MediaServer=quems0312
2011-07-13 10:56:50 - granted resource piscine
2011-07-13 10:56:50 - estimated 0 Kbytes needed
2011-07-13 10:56:50 - begin Parent Job
2011-07-13 10:56:50 - begin Unknown Type, Step By Condition
Status 0
2011-07-13 10:56:50 - end Unknown Type, Step By Condition; elapsed time: 00:00:00
2011-07-13 10:56:50 - begin Unknown Type, Read File List
Status 0
2011-07-13 10:56:50 - end Unknown Type, Read File List; elapsed time: 00:00:00
2011-07-13 10:56:50 - begin Unknown Type, Create Snapshot
2011-07-13 10:56:50 - started process bpbrm (3536)
2011-07-13 10:56:50 - started
2011-07-13 10:56:51 - Info bpbrm(pid=3536) GEBRSELASSIE is the host to backup data from    
2011-07-13 10:56:56 - Info bpbrm(pid=3536) reading file list from client       
2011-07-13 10:56:56 - Info bpbrm(pid=3536) start bpfis on client        
2011-07-13 10:56:56 - begin Create Snapshot
2011-07-13 10:56:57 - Info bpfis(pid=4380) Backup started          
2011-07-13 10:58:24 - Info bpfis(pid=4380) done. status: 0         
2011-07-13 10:58:24 - end Create Snapshot; elapsed time: 00:01:28
2011-07-13 10:58:28 - end writing
Status 0
2011-07-13 10:58:28 - end Unknown Type, Create Snapshot; elapsed time: 00:01:38
2011-07-13 10:58:28 - begin Unknown Type, Policy Execution Manager Preprocessed
2011-07-13 10:58:33 - Info bpfis(pid=0) done. status: 0: the requested operation was successfully completed   
Status 0
2011-07-13 11:00:56 - end Unknown Type, Policy Execution Manager Preprocessed; elapsed time: 00:02:28
2011-07-13 11:00:56 - begin Unknown Type, Delete Snapshot
2011-07-13 11:00:56 - started process bpbrm (5112)
2011-07-13 11:01:12 - end writing
Status 0
2011-07-13 11:01:12 - end Unknown Type, Delete Snapshot; elapsed time: 00:00:16
2011-07-13 11:01:12 - begin Unknown Type, Delete Snapshot On Exit
Status 0
2011-07-13 11:01:12 - end Unknown Type, Delete Snapshot On Exit; elapsed time: 00:00:00
Status 0
2011-07-13 11:01:12 - end Parent Job; elapsed time: 00:04:22
the requested operation was successfully completed(0) 

Any idea??

[RiaanBadenhorst]

Hi,

You're the 3rd person I've seen with this issue. All on 7.1 if I recall correctly. Only note available is this http://www.symantec.com/docs/TECH154784

If this doesn't resolve it, please open a case with Symantec and report back to us with a resolution.

[Louis_Rioux]

Hi Riaan

Thank you for your answer. I already look at that solution but this is not my case (if it was, my backup won't work either on the active node). I try to open a case, but I need either a technical account id, a support number or a technical case ID and nobody here seem to know what that number is. I try every number I found and none of them works.

I finally found the support number I needed. The case is open. I will post the solution when I receive the answer

Regards

[Jechar]

Hello,

I have the same issue, have you fix it ?

Best regards

JC

[J_H_Is_gone]

to see if there is any more detail.

Not sure - but as you are getting snapshot errors maybe the server that has the passive mode does not have enough free space to make the snapshot of the database before backup.

check free space on the active server vs the passive server.

[Jechar]

Hello,

I think the problem is not linked with free space because un change the dag server from passive to actif  and rerun backup, it's right ! i swap again the actif dag... error comes back

See below the bpfis log when error occured

16:52:35.924 [6976.6420] <2> map_integer_value: virtual_machine_supported=VMware, converted value=1, status=1
16:52:35.924 [6976.6420] <2> read_vfm_conf: Found FIM: NAS_Snapshot
16:52:35.924 [6976.6420] <2> read_vfm_conf: Found library: C:\Program Files\Veritas\NetBackup\bin\libfi_NAS_Snapshot.dll
16:52:35.924 [6976.6420] <2> parse_ssm_parms: Found keyword max_snapshots
16:52:35.924 [6976.6420] <2> parse_ssm_parms: Found data type %d
16:52:35.924 [6976.6420] <2> parse_ssm_parms: Found value specification 1-:1
16:52:35.924 [6976.6420] <2> parse_value_specification: Value specification='1-:1'
16:52:35.924 [6976.6420] <2> parse_value_specification: Null maximum value; using INT_MAX (2147483647)
16:52:35.924 [6976.6420] <2> parse_value_specification: Found default 1
16:52:35.924 [6976.6420] <2> parse_ssm_parms: Found prompt Maximum Snapshots (Instant Recovery only)
16:52:35.924 [6976.6420] <2> read_vfm_conf: Found FIM: VSS_Writer
16:52:35.924 [6976.6420] <2> read_vfm_conf: Found library: C:\Program Files\Veritas\NetBackup\bin\libfi_vss_writer.dll
16:52:35.940 [6976.6420] <2> vnet_pbxConnect: pbxConnectEx Succeeded
16:52:35.940 [6976.6420] <2> logconnections: BPRD CONNECT FROM 10.2.240.192.46338 TO 10.2.240.86.1556 fd = 604
16:52:36.127 [6976.6420] <8> bpfis: WRN - VfMS error 10; see following messages:
16:52:36.127 [6976.6420] <8> bpfis: WRN - Non-fatal method error was reported
16:52:36.127 [6976.6420] <8> bpfis: WRN - vfm_configure_fi_one: method: FlashSnap, type: FIM, function: FlashSnap_init
16:52:36.127 [6976.6420] <8> bpfis: WRN - VfMS method error 3; see following message:
16:52:36.127 [6976.6420] <8> bpfis: WRN - FlashSnap_init: Veritas Volume Manager not installed.
16:52:36.127 [6976.6420] <8> bpfis: WRN - VfMS error 10; see following messages:
16:52:36.127 [6976.6420] <8> bpfis: WRN - Non-fatal method error was reported
16:52:36.127 [6976.6420] <8> bpfis: WRN - vfm_configure_fi_one: method: vxvm, type: FIM, function: vxvm_init
16:52:36.127 [6976.6420] <8> bpfis: WRN - VfMS method error 3; see following message:
16:52:36.127 [6976.6420] <8> bpfis: WRN - vxvm_init: Veritas Volume Manager not installed.
16:52:36.127 [6976.6420] <4> bpfis: INF - FIS_ID=dag-lestrem_1312383070
16:52:36.127 [6976.6420] <4> bpfis: INF - Preparing freeze of NEW_STREAM0 using snapshot method VSS_Writer.
16:52:36.127 [6976.6420] <4> bpfis: INF - Created mount point C:\Program Files\Veritas\NetBackup\temp\_vrts_frzn_img_NEW_STREAM0_6976
16:52:36.127 [6976.6420] <4> bpfis: INF - Preparing freeze of Microsoft Information Store:\XDB101U05 using snapshot method VSS_Writer.
16:52:36.127 [6976.6420] <4> bpfis: INF - Created mount point C:\Program Files\Veritas\NetBackup\temp\_vrts_frzn_img_Microsoft Information Store_XDB101U05_6976
16:52:50.722 [6976.6420] <4> bpfis: INF - Deleted mount point C:\Program Files\Veritas\NetBackup\temp\_vrts_frzn_img_Microsoft Information Store_XDB101U05_6976
16:52:50.722 [6976.6420] <8> bpfis: WRN - VfMS error 10; see following messages:
16:52:50.722 [6976.6420] <8> bpfis: WRN - Non-fatal method error was reported
16:52:50.722 [6976.6420] <8> bpfis: WRN - vfm_freeze: method: VSS_Writer, type: FIM, function: VSS_Writer_freeze
16:52:50.722 [6976.6420] <8> bpfis: WRN - VfMS method error 8; see following message:
16:52:50.722 [6976.6420] <8> bpfis: WRN - config =prov_type=0,snap_attr=0,max_snapshots=1,APP_TYPE=FS,BACKUP_TIME=1312383155,POLICY_NAME=TEST_EXCH_2010_ALL,NBU_CLIENT=S101X06M,NBU_MASTER=s101s04,SCHED_NAME=daily,SCHED_TYPE=FULL,POLICY_TYPE=16,PFI_BACKUP=0,NBU_CATALOG=0,VSS_REPLICA=0,GRAN_BACKUP=0,EXCHANGE_DAG_NAME=dag-lestrem,STREAM_ID=TEST_EXCH_2010_ALL+6976,STREAM_NUMBER=1
16:52:54.050 [6976.6420] <32> bpfis: FTL - VfMS error 11; see following messages:
16:52:54.050 [6976.6420] <32> bpfis: FTL - Fatal method error was reported
16:52:54.050 [6976.6420] <32> bpfis: FTL - vfm_freeze_commit: method: VSS_Writer, type: FIM, function: VSS_Writer_freeze_commit
16:52:54.050 [6976.6420] <32> bpfis: FTL - VfMS method error 4; see following message:
16:52:54.050 [6976.6420] <32> bpfis: FTL - VSS_Writer_freeze_commit Pass up backup status for - XDB101U05
16:52:54.050 [6976.6420] <32> bpfis: FTL - VfMS error 11; see following messages:
16:52:54.050 [6976.6420] <32> bpfis: FTL - Fatal method error was reported
16:52:54.050 [6976.6420] <32> bpfis: FTL - vfm_freeze_commit: method: VSS_Writer, type: FIM, function: VSS_Writer_freeze_commit
16:52:54.050 [6976.6420] <32> bpfis: FTL - VfMS method error 4; see following message:
16:52:54.050 [6976.6420] <32> bpfis: FTL - VSS_Writer_freeze_commit Pass up backup status for - XDB101U05
16:52:54.050 [6976.6420] <4> bpfis: INF - Thawing NEW_STREAM0 using snapshot method VSS_Writer.
16:52:54.050 [6976.6420] <4> bpfis: INF - do_thaw return value: 0
16:52:54.050 [6976.6420] <4> bpfis: INF - Deleted mount point C:\Program Files\Veritas\NetBackup\temp\_vrts_frzn_img_NEW_STREAM0_6976
16:52:54.050 [6976.6420] <4> bpfis: INF - Thawing Microsoft Information Store:\XDB101U05 using snapshot method VSS_Writer.
16:52:54.050 [6976.6420] <4> bpfis: INF - do_thaw return value: 0
16:52:54.050 [6976.6420] <16> bpfis: FTL - snapshot creation failed - Error attempting to gather metadata., status 130
16:52:54.050 [6976.6420] <4> bpfis: INF - DB_BACKUP_STATUS:DB_status:EX_DB 9 XDB101U05:EX_SRVR 8 S101X06M:EX_STATUS 156
16:52:54.050 [6976.6420] <16> bpfis: FTL - snapshot creation failed, status 130
16:52:54.050 [6976.6420] <4> bpfis: INF - Thawing NEW_STREAM0 using snapshot method VSS_Writer.
16:52:54.050 [6976.6420] <8> bpfis: WRN - NEW_STREAM0 is not frozen
16:52:54.050 [6976.6420] <4> bpfis: INF - Thawing Microsoft Information Store:\XDB101U05 using snapshot method VSS_Writer.
16:52:54.050 [6976.6420] <8> bpfis: WRN - Microsoft Information Store:\XDB101U05 is not frozen
16:52:54.050 [6976.6420] <8> bpfis: WRN - snapshot delete returned status 20
16:52:54.050 [6976.6420] <4> bpfis: INF - EXIT STATUS 130: system error occurred
16:53:03.894 [6872.3472] <2> logparams: C:\Program Files\Veritas\NetBackup\bin\bpfis.exe delete -nbu -id dag-lestrem_1312383070 -bpstart_to 300 -bpend_to 300 -clnt S101X06M -pt 16 -st FULL -status 130 -S s101s04
16:53:03.909 [6872.3472] <2> vnet_pbxConnect: pbxConnectEx Succeeded
16:53:03.909 [6872.3472] <2> logconnections: BPRD CONNECT FROM 10.2.240.192.46399 TO 10.2.240.86.1556 fd = 560
16:53:05.050 [6872.3472] <4> bpfis: INF - BACKUP START 6872
16:53:05.050 [6872.3472] <32> bpfis: FTL - cannot open C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.dag-lestrem_1312383070.0
16:53:05.050 [6872.3472] <4> bpfis:  INF - Attempt to send status to the bpfis create process
16:53:06.050 [6872.3472] <4> bpfis: INF - EXIT STATUS 0: the requested operation was successfully completed

JC

[SlobodanS]

Hi, i had the same problem last week.

1. Can you enable the General log to 2, and verbose to 5.

2. Check BPFIS logs

3. Check Veritas\Temp\ folder.

4. Stop the backup. Purge the temp file. Restart the passive node.

It works for me.

Regards

Slobodan