Video Screencast Help

VMware delete snapshot failed

Created: 25 Jun 2014 • Updated: 31 Aug 2014 | 10 comments
This issue has been solved. See solution.

We are running Netbackup 7.6.0.2 on windows server 2008 SP1 R2.

My problem is with the VMs backup to msdp disk. The msdp disk is located in media server that also got Netbackup 7.6.0.2.

Before we upgraded  to 7.6.0.2 everything worked fine. Since the upgrade, I get now in some clients errors in delete snapshot after the backup.

This is the Detiales status of the job that shows the error:

23/06/2014 18:35:36 - end Application Snapshot, Resources For Cleanup; elapsed time: 0:00:00
23/06/2014 18:35:36 - begin Application Snapshot, Delete Snapshot
23/06/2014 18:35:38 - started process bpbrm (10352)
23/06/2014 18:35:40 - Info bpbrm(pid=10352) Starting delete snapshot processing        
23/06/2014 18:35:41 - Info bpfis(pid=11064) Backup started          
23/06/2014 18:35:48 - Info bpbrm(pid=10352) INF - vmwareLogger: RegisterExtensionAPI: SYM_VMC_ERROR:  SOAP_ERROR     
23/06/2014 18:35:48 - Info bpbrm(pid=10352) INF - vmwareLogger: SOAP 1.1 fault: "":ServerFaultCode [no subcode]   
23/06/2014 18:50:57 - Critical bpbrm(pid=10352) from client san-manager: VMware_thaw: VMware delete snapshot failed: Unrecognized error  
23/06/2014 18:51:00 - Info bpfis(pid=11064) done. status: 0         
23/06/2014 18:51:00 - end Application Snapshot, Delete Snapshot; elapsed time: 0:15:24
23/06/2014 18:51:00 - Info bpfis(pid=11064) done. status: 0: the requested operation was successfully completed   
23/06/2014 18:51:00 - end writing
Status 0
23/06/2014 18:51:00 - end operation
Status 0
23/06/2014 18:51:00 - end operation
the requested operation was successfully completed(0)

Please advise

Operating Systems:

Comments 10 CommentsJump to latest comment

RamNagalla's picture

Do you see any errors in Vcenter console?

please check in the Vcetner console for specific VM noce..

Sisso's picture

There is nothing on VC. Moreover, the job finish on status code 0.

Nate.D's picture

What version of VMware? Is it the same clients always failing or different ones?

If I was helpful in solving your issue please mark my post with a thumbs up or a solution!  Have a great day :)

Sisso's picture

This is Vsphere 5.1 and yes this is always the same clients.

RamNagalla's picture

Does VMware team see any orphaned snapshots for the VM that are showing these errors?

what are the permission that user accout have on Vsphere 5.1 which is added in Netbackup?

if possilbe please post the bpbrm and bpfis logs for now..

and since the job is ending with status code 0, did you validate the backup by doing the test restore?

how about the next backup job for the VM that is giving this error... is that failing with 156, or successfull?

what is the snaphost handle selected in vmware policy tab...?

SOLUTION
Sisso's picture

Nagalla,

Our Vmware team saw this orphaned snapshots that the netbackup didnt delete after the backup.

I already checked the permission of the user account which had administrator role.

This is your requested logs:

bpbrm:

18:50:19.184 [11180.5880] <2> bpcr_get_version_rqst: bpcd version: 07600002
18:50:19.184 [11180.5880] <2> getPatchLevel: CLIENT_CMD_SOCK from bpcr = 612
18:50:19.184 [11180.5880] <2> getPatchLevel: got client socket
18:50:19.184 [11180.5880] <2> getPatchLevel: file num = 3, file size = 109
18:50:19.184 [11180.5880] <2> bpcr_read_rqst: completed send of file number 3
18:50:19.184 [11180.5880] <2> bpcr_read_rqst: completed send of transfer_count = 16383
18:50:19.184 [11180.5880] <2> bpcr_read_rqst: Before readclientstatus on socket 624
18:50:19.184 [11180.5880] <2> bpcr_read_rqst: Num bytes to be sent by client = 109
18:50:19.184 [11180.5880] <2> getPatchLevel: total chars read = 109
18:50:19.184 [11180.5880] <2> getPatchLevel: level = >7.6.0.2<
18:50:19.184 [11180.5880] <2> decode_fim_attr: not key=value pair for: VMware_v2
18:50:19.184 [11180.5880] <2> ConnectionCache::connectAndCache: Acquiring new connection for host msrub1, query type 223
18:50:19.199 [11180.5880] <2> vnet_pbxConnect: pbxConnectEx Succeeded
18:50:19.199 [11180.5880] <2> logconnections: BPDBM CONNECT FROM xxx.xxx.xxx.xxx.55904 TO xxx.xxx.xxx.xxx.1556 fd = 624
18:50:19.277 [11180.5880] <2> db_CLIENTsend: reset client protocol version from 0 to 8
18:50:19.511 [11180.5880] <2> db_end: Need to collect reply
18:50:19.511 [11180.5880] <2> db_freeEXDB_INFO: ?
18:50:19.511 [11180.5880] <2> local_getHostInfo: found TSS cached host msrub2 type 67
18:50:19.511 [11180.5880] <2> bpbrm create_events: created suspend event name Global\NetBackup Suspend Event, pid: 11180
18:50:19.511 [11180.5880] <2> vnet_pbxConnect: pbxConnectEx Succeeded
18:50:19.511 [11180.5880] <2> job_connect: SO_KEEPALIVE set on socket 652 for client msrub1
18:50:19.511 [11180.5880] <2> logconnections: BPJOBD CONNECT FROM xxx.xxx.xxx.xxx.55905 TO xxx.xxx.xxx.xxx.1556 fd = 652
18:50:19.511 [11180.5880] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
18:50:19.527 [11180.5880] <2> job_connect: Connected to the host msrub1 contype 53 jobid <52701> socket <652>
18:50:19.527 [11180.5880] <2> job_connect: Connected on port 55905
18:50:19.527 [11180.5880] <4> bpfis_start: Processing snapshot create request...
18:50:19.527 [11180.5880] <2> logconnections: BPCD CONNECT FROM xxx.xxx.xxx.xxx.55907 TO xxx.xxx.xxx.xxx.13782 fd = 664
18:50:19.621 [11180.5880] <2> bpcr_get_version_rqst: bpcd version: 07600002
18:50:19.621 [11180.5880] <2> bpcr_get_version_rqst: bpcd version: 07600002
18:50:19.621 [11180.5880] <4> vmware_blib_bpfis_state_cleanup: bpfis state files cleanup: D:\Program Files\Veritas\NetBackup\bin\admincmd\bppficorr.exe -client "msrub1" -proxy_client "msrub2" -vm_client "TMTAPP01" -policy "VM-vSphere-CL04-Auto" -prev_bli_bt 1403460534 -vm_bli_cleanup
18:50:22.460 [11180.5880] <2> get_cached_client_version: Using cached version. CLNT=msrub2 V=123731970 Fetched=Mon Jun 23 18:50:22 2014

18:50:22.460 [11180.5880] <2> get_cached_client_version: Using cached version. CLNT=msrub2 V=123731970 Fetched=Mon Jun 23 18:50:22 2014

18:50:22.460 [11180.5880] <2> get_cached_client_version: Using cached version. CLNT=msrub2 V=123731970 Fetched=Mon Jun 23 18:50:22 2014

18:50:22.460 [11180.5880] <4> RedirectNBLoggerToLegacyLog: Setting up redirection of VxUL messages to legacy log
18:50:22.476 [11180.5880] <4> RedirectNBLoggerToLegacyLog: Verbosity from VxUL configuration: 1
18:50:22.476 [11180.5880] <4> RedirectNBLoggerToLegacyLog: logmsg verbosity set: 1
18:50:22.476 [11180.5880] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:708)
18:50:22.476 [11180.5880] <2> Orb::init: initializing ORB Default_CLIENT_Orb with: Unknown -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static Resource_Factory '-ORBNativeCharCodeSet UTF-8'" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBDefaultInitRef '' -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb Default_CLIENT_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:920)
18:50:22.476 [11180.5880] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:935)
18:50:22.678 [11180.5880] <2> get_cached_client_version: Using cached version. CLNT=msrub2 V=123731970 Fetched=Mon Jun 23 18:50:22 2014

18:50:22.678 [11180.5880] <2> bpfis_start: DBG: BPFIS Commands [828] - /usr/openv/netbackup/bin/bpfis bpfis create -nbu -owner NBU -id TMTAPP01_1403542216 -bpstart_to 900 -bpend_to 900 -backup_copy 0 -ru root -pt 40 -vm_type 2 -vm_client TMTAPP01 -clnt msrub2 -st FULL -fscp 1 -fscp_cksv 0 -storage_server msrub2 -block_incr -prev_bli_incr 1403460534 -last_bli_full 1403460534 -dt 0 -rg root -fim VMware_v2:Virtual_machine_backup=2,disable_quiesce=1,drive_selection=0,enable_vCloud=0,exclude_swap=1,file_system_optimization=1,ignore_irvm=1,multi_org=0,nameuse=1,post_events=1,rHz=10,rLim=10,rTO=0,skipnodisk=0,snapact=2,trantype=san:nbd,vsrvr=tvmwvc01.bnhpgroup.com,uuid=503db576-0829-3f88-aa01-27ed98fb6b2a,nip=(172.31.54.73),nameuse=1 -class VM-vSphere-CL04-Auto -sched Full-Ret1M -fso -S msrub1 -jobid 52701 -nbu_version 123731970 -lsuinfo msrub2:PureDisk:PureDiskVolume -application_consistent 1
18:50:22.678 [11180.5880] <2> logconnections: BPCD CONNECT FROM xxx.xxx.xxx.xxx.55916 TO xxx.xxx.xxx.xxx.13782 fd = 920
18:50:22.756 [11180.5880] <2> bpcr_get_version_rqst: bpcd version: 07600002
18:50:22.756 [11180.5880] <2> bpbrm start_bpcd_stat: DATA_SOCK from bpcr = 920
18:50:22.756 [11180.5880] <2> bpbrm start_bpcd_stat: NAME_SOCK from bpcr = 932
18:50:22.756 [11180.5880] <2> pfi_start_client: command = /usr/openv/netbackup/bin/bpfis bpfis create -nbu -owner NBU -id TMTAPP01_1403542216 -bpstart_to 900 -bpend_to 900 -backup_copy 0 -ru root -pt 40 -vm_type 2 -vm_client TMTAPP01 -clnt msrub2 -st FULL -fscp 1 -fscp_cksv 0 -storage_server msrub2 -block_incr -prev_bli_incr 1403460534 -last_bli_full 1403460534 -dt 0 -rg root -fim VMware_v2:Virtual_machine_backup=2,disable_quiesce=1,drive_selection=0,enable_vCloud=0,exclude_swap=1,file_system_optimization=1,ignore_irvm=1,multi_org=0,nameuse=1,post_events=1,rHz=10,rLim=10,rTO=0,skipnodisk=0,snapact=2,trantype=san:nbd,vsrvr=tvmwvc01.bnhpgroup.com,uuid=503db576-0829-3f88-aa01-27ed98fb6b2a,nip=(172.31.54.73),nameuse=1 -class VM-vSphere-CL04-Auto -sched Full-Ret1M -fso -S msrub1 -jobid 52701 -nbu_version 123731970 -lsuinfo msrub2:PureDisk:PureDiskVolume -application_consistent 1
18:50:22.756 [11180.5880] <2> pfi_start_client: received bpcd success message
18:50:23.396 [11180.5880] <2> pfi_start_client: read start message from msrub2, msg=<INF - BACKUP START 8144>
18:50:23.396 [11180.5880] <2> write_file_names: buffering file name 'NEW_STREAM' for output
18:50:23.396 [11180.5880] <2> write_file_names: buffering file name 'ALL_LOCAL_DRIVES' for output
18:50:23.396 [11180.5880] <2> write_file_names: successfully wrote buffer to COMM_SOCK
18:50:23.396 [11180.5880] <2> bpbrm write_filelist: wrote CONTINUE on COMM_SOCK
18:50:57.920 [10352.10772] <32> get_bpfis_msg: from client san-manager: FTL - VMware_thaw: VMware delete snapshot failed: Unrecognized error
18:50:57.920 [10352.10772] <2> ConnectionCache::connectAndCache: Acquiring new connection for host msrub1, query type 1
18:50:57.920 [10352.10772] <2> vnet_pbxConnect: pbxConnectEx Succeeded
18:50:57.920 [10352.10772] <2> logconnections: BPDBM CONNECT FROMxxx.xxx.xxx.xxx.55968 TO xxx.xxx.xxx.xxx.1556 fd = 676
18:50:57.982 [10352.10772] <2> db_end: Need to collect reply
18:51:00.541 [10352.10772] <2> bpbrm Exit: client backup EXIT STATUS 0: the requested operation was successfully completed
18:51:00.759 [8688.8460] <32> get_bpfis_msg: from client dopxprvl2: FTL - VMware_freeze: VIXAPI freeze (VMware snapshot) failed with 53: SYM_VMC_RETRIEVE_SNAPSHOT_MOR_FAILED
18:51:00.775 [8688.8460] <2> ConnectionCache::connectAndCache: Acquiring new connection for host msrub1, query type 1
18:51:00.775 [8688.8460] <2> vnet_pbxConnect: pbxConnectEx Succeeded
18:51:00.775 [8688.8460] <2> logconnections: BPDBM CONNECT FROM xxx.xxx.xxx.xxx.55975 TO xxx.xxx.xxx.xxx.1556 fd = 580
18:51:01.024 [10352.10772] <2> job_monitoring_exex: ACK disconnect
18:51:01.024 [10352.10772] <2> job_disconnect: Disconnected
18:51:01.211 [8688.8460] <2> db_end: Need to collect reply
18:51:01.258 [8688.8460] <4> get_bpfis_msg: from client dopxprvl2: INF - vmwareLogger: RegisterExtensionAPI: SYM_VMC_ERROR:  SOAP_ERROR
18:51:01.258 [8688.8460] <4> get_bpfis_msg: from client dopxprvl2: INF - vmwareLogger: SOAP 1.1 fault: "":ServerFaultCode [no subcode]
18:51:01.258 [8688.8460] <32> get_bpfis_msg: from client dopxprvl2: FTL - vfm_freeze: method: VMware_v2, type: FIM, function: VMware_v2_freeze
18:51:01.258 [8688.8460] <2> ConnectionCache::connectAndCache: Acquiring new connection for host msrub1, query type 1
18:51:01.274 [8688.8460] <2> vnet_pbxConnect: pbxConnectEx Succeeded
18:51:01.274 [8688.8460] <2> logconnections: BPDBM CONNECT FROM xxx.xxx.xxx.xxx.55976 TO xxx.xxx.xxx.xxx.1556 fd = 580
18:51:01.477 [10048.4104] <2> bpbrm main: client rmvudbprcs1 EXIT STATUS = 0: the requested operation was successfully completed
18:51:01.477 [10048.4104] <2> ConnectionCache::connectAndCache: Acquiring new connection for host msrub1, query type 78
18:51:01.477 [10048.4104] <2> vnet_pbxConnect: pbxConnectEx Succeeded
18:51:01.477 [10048.4104] <2> logconnections: BPDBM CONNECT FROM xxx.xxx.xxx.xxx.55977 TO xxx.xxx.xxx.xxx.1556 fd = 668
18:51:01.711 [8688.8460] <2> db_end: Need to collect reply
18:51:01.757 [8688.8460] <32> get_bpfis_msg: from client dopxprvl2: FTL -
18:51:01.757 [8688.8460] <2> ConnectionCache::connectAndCache: Acquiring new connection for host msrub1, query type 1
18:51:01.773 [8688.8460] <2> vnet_pbxConnect: pbxConnectEx Succeeded
18:51:01.773 [8688.8460] <2> logconnections: BPDBM CONNECT FROM xxx.xxx.xxx.xxx.55979 TO xxx.xxx.xxx.xxx.1556 fd = 580
18:51:01.976 [10048.4104] <2> db_end: Need to collect reply
18:51:02.428 [8688.8460] <2> db_end: Need to collect reply
18:51:02.459 [8688.8460] <32> get_bpfis_msg: from client dopxprvl2: FTL - vfm_freeze: method: VMware_v2, type: FIM, function: VMware_v2_freeze
18:51:02.459 [8688.8460] <2> ConnectionCache::connectAndCache: Acquiring new connection for host msrub1, query type 1
18:51:02.475 [8688.8460] <2> vnet_pbxConnect: pbxConnectEx Succeeded
18:51:02.475 [8688.8460] <2> logconnections: BPDBM CONNECT FROM xxx.xxx.xxx.xxx.55980 TO xxx.xxx.xxx.xxx.1556 fd = 936
18:51:02.615 [10048.4104] <2> bpbrm wait_for_child: start
18:51:02.912 [8688.8460] <2> db_end: Need to collect reply
18:51:02.943 [8688.8460] <32> get_bpfis_msg: from client dopxprvl2: FTL -
18:51:02.943 [8688.8460] <2> ConnectionCache::connectAndCache: Acquiring new connection for host msrub1, query type 1
18:51:02.959 [8688.8460] <2> vnet_pbxConnect: pbxConnectEx Succeeded
18:51:02.959 [8688.8460] <2> logconnections: BPDBM CONNECT FROM xxx.xxx.xxx.xxx.55981 TO xxx.xxx.xxx.xxx.1556 fd = 936
18:51:03.130 [8688.8460] <2> db_end: Need to collect reply
18:51:03.161 [8688.8460] <32> get_bpfis_msg: from client dopxprvl2: FTL - snapshot processing failed, status 156
18:51:03.161 [8688.8460] <2> ConnectionCache::connectAndCache: Acquiring new connection for host msrub1, query type 1
18:51:03.177 [8688.8460] <2> vnet_pbxConnect: pbxConnectEx Succeeded
18:51:03.177 [8688.8460] <2> logconnections: BPDBM CONNECT FROM xxx.xxx.xxx.xxx.55982 TO xxx.xxx.xxx.xxx.1556 fd = 580
18:51:03.302 [8688.8460] <2> db_end: Need to collect reply
18:51:03.364 [8688.8460] <32> get_bpfis_msg: from client dopxprvl2: FTL - snapshot creation failed, status 156
18:51:03.364 [8688.8460] <2> ConnectionCache::connectAndCache: Acquiring new connection for host msrub1, query type 1
18:51:03.380 [8688.8460] <2> vnet_pbxConnect: pbxConnectEx Succeeded
18:51:03.380 [8688.8460] <2> logconnections: BPDBM CONNECT FROM xxx.xxx.xxx.xxx.55983 TO xxx.xxx.xxx.xxx.1556 fd = 936
18:51:03.489 [8688.8460] <2> db_end: Need to collect reply
18:51:03.551 [8688.8460] <8> get_bpfis_msg: from client dopxprvl2: WRN - ALL_LOCAL_DRIVES is not frozen
18:51:03.551 [8688.8460] <2> ConnectionCache::connectAndCache: Acquiring new connection for host msrub1, query type 1
18:51:03.551 [8688.8460] <2> vnet_pbxConnect: pbxConnectEx Succeeded
18:51:03.551 [8688.8460] <2> logconnections: BPDBM CONNECT FROM xxx.xxx.xxx.xxx.55984 TO xxx.xxx.xxx.xxx.1556 fd = 936
18:51:03.692 [8688.8460] <2> db_end: Need to collect reply
18:51:03.739 [8688.8460] <2> bpbrm kill_child_process_Ex: start
18:51:03.739 [8688.8460] <2> bpbrm Exit: client backup EXIT STATUS 156: snapshot error encountered
18:51:03.863 [8688.8460] <2> job_monitoring_exex: ACK disconnect
18:51:03.863 [8688.8460] <2> job_disconnect: Disconnected
18:51:05.735 [2408.9472] <4> bpbrm main: logging will continue into new log at midnight
18:51:05.735 [2408.9472] <2> bpbrm main: INITIATING (VERBOSE = 0): version NetBackup 7.6 2014042415
18:51:05.735 [2408.9472] <2> logparams: -c dopxprvl2 -cl VM-vSphere-CL04-Auto -ct 40 -id dopxprvl2_1403541282 -nbu -sched Full-Ret1M -st 0 -secure 1 -S msrub1 -storagesvr msrub2 -sts_type PureDisk -stunit msrub2-MSDP -block_incr -prev_bli_incr 1403473492 -last_bli_full 1403473492 -use_ofb -use_otm -fi -fim VMware_v2:Virtual_machine_backup=2,disable_quiesce=1,drive_selection=0,enable_vCloud=0,exclude_swap=1,file_system_optimization=1,ignore_irvm=1,multi_org=0,nameuse=1,post_events=1,rHz=10,rLim=10,rTO=0,serverlist=,skipnodisk=0,snapact=2,trantype=san:nbd -vm_proxy msrub2 -nbu -dfim vsrvr=tvmwvc01.bnhpgroup.com,uuid=501a5a4c-9d78-90b7-7ba8-f890c4795c8a,nip=(172.22.110.26) -jobid 52703 -jobgrpid 52598 -vm_proxy msrub2 -fscp -status 156 -b dopxprvl2_1403541282 -rp 3024000 -rtype 0
18:51:05.735 [2408.9472] <2> bpbrm main: DBG - Snapshot method [251] - VMware_v2:Virtual_machine_backup=2,disable_quiesce=1,drive_selection=0,enable_vCloud=0,exclude_swap=1,file_system_optimization=1,ignore_irvm=1,multi_org=0,nameuse=1,post_events=1,rHz=10,rLim=10,rTO=0,serverlist=,skipnodisk=0,snapact=2,trantype=san:nbd
18:51:05.735 [2408.9472] <2> bpbrm main: DBG - Snapshot method [342] - VMware_v2:Virtual_machine_backup=2,disable_quiesce=1,drive_selection=0,enable_vCloud=0,exclude_swap=1,file_system_optimization=1,ignore_irvm=1,multi_org=0,nameuse=1,post_events=1,rHz=10,rLim=10,rTO=0,serverlist=,skipnodisk=0,snapact=2,trantype=san:nbd,vsrvr=tvmwvc01.bnhpgroup.com,uuid=501a5a4c-9d78-90b7-7ba8-f890c4795c8a,nip=(172.22.110.26)
18:51:05.751 [2408.9472] <2> vnet_pbxConnect: pbxConnectEx Succeeded
18:51:05.751 [2408.9472] <2> logconnections: BPRD CONNECT FROM xxx.xxx.xxx.xxx.55989 TO xxx.xxx.xxx.xxx.1556 fd = 612
18:51:06.063 [2408.9472] <2> brm_update_local_resiliency: changed = 0
18:51:06.063 [2408.9472] <2> bpbrm main: max_entries_per_add = 95000
18:51:06.063 [2408.9472] <2> ConnectionCache::connectAndCache: Acquiring new connection for host msrub1, query type 223
18:51:06.063 [2408.9472] <2> vnet_pbxConnect: pbxConnectEx Succeeded
18:51:06.063 [2408.9472] <2> logconnections: BPDBM CONNECT FROM xxx.xxx.xxx.xxx.55990 TO xxx.xxx.xxx.xxx.1556 fd = 616

bfis:

18:50:01.056 [11036.1164] <4> bpfis: INF - Deleted mount point D:\Program Files\Veritas\NetBackup\temp\_vrts_frzn_img_ALL_LOCAL_DRIVES_11036_1
18:50:01.056 [11036.1164] <32> bpfis: FTL - VfMS error 11; see following messages:
18:50:01.056 [11036.1164] <32> bpfis: FTL - Fatal method error was reported
18:50:01.056 [11036.1164] <32> bpfis: FTL - vfm_freeze: method: VMware_v2, type: FIM, function: VMware_v2_freeze
18:50:01.056 [11036.1164] <32> bpfis: FTL - VfMS method error 0; see following message:
18:50:01.056 [11036.1164] <32> bpfis: FTL -
18:50:01.056 [11036.1164] <32> bpfis: FTL - VfMS error 11; see following messages:
18:50:01.056 [11036.1164] <32> bpfis: FTL - Fatal method error was reported
18:50:01.056 [11036.1164] <32> bpfis: FTL - vfm_freeze: method: VMware_v2, type: FIM, function: VMware_v2_freeze
18:50:01.056 [11036.1164] <32> bpfis: FTL - VfMS method error 0; see following message:
18:50:01.056 [11036.1164] <32> bpfis: FTL -
18:50:01.056 [11036.1164] <16> bpfis: FTL - snapshot creation failed, status 156
18:50:01.056 [11036.1164] <4> bpfis: INF - Thawing ALL_LOCAL_DRIVES using snapshot method VMware_v2.
18:50:01.056 [11036.1164] <8> bpfis: WRN - ALL_LOCAL_DRIVES is not frozen
18:50:01.056 [11036.1164] <8> bpfis: WRN - snapshot delete returned status 20
18:50:01.072 [11036.1164] <4> bpfis: Starting keep alive thread.
18:50:01.072 [11036.1164] <4> bpfis: INF - EXIT STATUS 156: snapshot error encountered
18:50:02.679 [10692.11072] <4> bpfis: INF - Deleted mount point D:\Program Files\Veritas\NetBackup\temp\_vrts_frzn_img_ALL_LOCAL_DRIVES_10692_1
18:50:02.679 [10692.11072] <32> bpfis: FTL - VfMS error 11; see following messages:
18:50:02.679 [10692.11072] <32> bpfis: FTL - Fatal method error was reported
18:50:02.679 [10692.11072] <32> bpfis: FTL - vfm_freeze: method: VMware_v2, type: FIM, function: VMware_v2_freeze
18:50:02.679 [10692.11072] <32> bpfis: FTL - VfMS method error 0; see following message:
18:50:02.679 [10692.11072] <32> bpfis: FTL -
18:50:02.679 [10692.11072] <32> bpfis: FTL - VfMS error 11; see following messages:
18:50:02.679 [10692.11072] <32> bpfis: FTL - Fatal method error was reported
18:50:02.679 [10692.11072] <32> bpfis: FTL - vfm_freeze: method: VMware_v2, type: FIM, function: VMware_v2_freeze
18:50:02.679 [10692.11072] <32> bpfis: FTL - VfMS method error 0; see following message:
18:50:02.679 [10692.11072] <32> bpfis: FTL -
18:50:02.679 [10692.11072] <16> bpfis: FTL - snapshot creation failed, status 156
18:50:02.694 [10692.11072] <4> bpfis: INF - Thawing ALL_LOCAL_DRIVES using snapshot method VMware_v2.
18:50:02.694 [10692.11072] <8> bpfis: WRN - ALL_LOCAL_DRIVES is not frozen
18:50:02.694 [10692.11072] <8> bpfis: WRN - snapshot delete returned status 20
18:50:02.710 [10692.11072] <4> bpfis: Starting keep alive thread.
18:50:02.710 [10692.11072] <4> bpfis: INF - EXIT STATUS 156: snapshot error encountered
18:50:06.080 [6396.10836] <2> logparams: D:\Program Files\Veritas\NetBackup\bin\bpfis.exe delete -nbu -id TBLOPXFAX_1403541246 -bpstart_to 900 -bpend_to 900 -clnt msrub2 -jobgrpid 52598 -jobid 52702 -fscp 1 -fscp_cksv 0 -copy 1 -rp 3024000 -rtype 0 -backupid TBLOPXFAX_1403541246 -status 156 -S msrub1 -noserverstate -fim VMware_v2:Virtual_machine_backup=2,disable_quiesce=1,drive_selection=0,enable_vCloud=0,exclude_swap=1,file_system_optimization=1,ignore_irvm=1,multi_org=0,nameuse=1,post_events=1,rHz=10,rLim=10,rTO=0,skipnodisk=0,snapact=2,trantype=san:nbd,vsrvr=tvmwvc01.bnhpgroup.com,uuid=501a43fb-3963-e94f-33d9-f63c93a3c8f4,nip=(fe80::e991:feda:3390:58ca)(xxx.xxx.xxx.xxx)
18:50:06.080 [6396.10836] <2> bpfis main: received FIM as [357] VMware_v2:Virtual_machine_backup=2,disable_quiesce=1,drive_selection=0,enable_vCloud=0,exclude_swap=1,file_system_optimization=1,ignore_irvm=1,multi_org=0,nameuse=1,post_events=1,rHz=10,rLim=10,rTO=0,skipnodisk=0,snapact=2,trantype=san:nbd,vsrvr=tvmwvc01.bnhpgroup.com,uuid=501a43fb-3963-e94f-33d9-f63c93a3c8f4,nip=(fe80::e991:feda:3390:58ca)(172.22.110.42)
18:50:06.080 [6396.10836] <4> bpfis: Starting keep alive thread.
18:50:06.080 [6396.10836] <4> bpfis: Acquiring snapshot lock:retry count [0]
18:50:06.080 [6396.10836] <2> getFileName:  FileName is [D:\Program Files\Veritas\NetBackup\online_util\fi_cntl\TBLOPXFAX_1403541246_copy1.lock]
18:50:06.080 [6396.10836] <2> getFileName:  FileName is [D:\Program Files\Veritas\NetBackup\online_util\fi_cntl\TBLOPXFAX_1403541246_copy1.lock]
18:50:06.095 [6396.10836] <4> bpfis: INF - BACKUP START 6396
18:50:06.095 [6396.10836] <32> bpfis: FTL - cannot open D:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.TBLOPXFAX_1403541246.1.0
18:50:06.095 [6396.10836] <4> bpfis: Starting keep alive thread.
18:50:06.095 [6396.10836] <2> deleteReference:    reference not found in the list
18:50:06.095 [6396.10836] <4> bpfis: Delete reference: status [-4]
18:50:06.095 [6396.10836] <2> writeSnapshotLockFile:    Writing type[2] refcount[0]
18:50:06.095 [6396.10836] <2> writeSnapshotLockFile:    Writing Flags [0] [0]
18:50:06.095 [6396.10836] <2> writeSnapshotLockFile:   Writing Last addReffernt Time [Thu Jan 01 02:00:00 1970
]
18:50:06.095 [6396.10836] <2> writeSnapshotLockFile:   Writing Last Hostname []
18:50:06.111 [6396.10836] <2> getFileName:  FileName is [D:\Program Files\Veritas\NetBackup\online_util\fi_cntl\TBLOPXFAX_1403541246_copy1.lock]
18:50:06.111 [6396.10836] <2> getFileName:  FileName is [D:\Program Files\Veritas\NetBackup\online_util\fi_cntl\TBLOPXFAX_1403541246_copy1.lock]
18:50:06.111 [6396.10836] <2> unlockSnapshot:    file[D:\Program Files\Veritas\NetBackup\online_util\fi_cntl\TBLOPXFAX_1403541246_copy1.lock] : zero reference count
18:50:06.111 [6396.10836] <4> bpfis: Released snapshot lock: status [0]
18:50:06.111 [6396.10836] <4> do_post_processing: Deleting snapshot lock files from client for id [TBLOPXFAX_1403541246] and copy_number [1]
18:50:06.111 [6396.10836] <2> getFileName:  FileName is [D:\Program Files\Veritas\NetBackup\online_util\fi_cntl\TBLOPXFAX_1403541246_copy1.lock]
18:50:06.111 [6396.10836] <2> getFileName:  FileName is [D:\Program Files\Veritas\NetBackup\online_util\fi_cntl\TBLOPXFAX_1403541246_copy1.lock]
18:50:06.111 [6396.10836] <2> deleteSnapshotLockFile:    file[D:\Program Files\Veritas\NetBackup\online_util\fi_cntl\TBLOPXFAX_1403541246_copy1.lock] deleted: status[0]
18:50:06.111 [6396.10836] <4> bpfis: INF - EXIT STATUS 4207: Could not fetch snapshot metadata or state files
18:50:07.094 [8172.8636] <2> logparams: D:\Program Files\Veritas\NetBackup\bin\bpfis.exe delete -nbu -id PRBLALSMTRBX_1403541249 -bpstart_to 900 -bpend_to 900 -clnt msrub2 -jobgrpid 52598 -jobid 52704 -fscp 1 -fscp_cksv 0 -copy 1 -rp 3024000 -rtype 0 -backupid PRBLALSMTRBX_1403541249 -status 156 -S msrub1 -noserverstate -fim VMware_v2:Virtual_machine_backup=2,disable_quiesce=1,drive_selection=0,enable_vCloud=0,exclude_swap=1,file_system_optimization=1,ignore_irvm=1,multi_org=0,nameuse=1,post_events=1,rHz=10,rLim=10,rTO=0,skipnodisk=0,snapact=2,trantype=san:nbd,vsrvr=tvmwvc01.bnhpgroup.com,uuid=501ad7ab-e6f6-bfe1-e34e-bf4905e8ec89,nip=(xxx.xxx.xxx.xxx)
18:50:07.094 [8172.8636] <2> bpfis main: received FIM as [330] VMware_v2:Virtual_machine_backup=2,disable_quiesce=1,drive_selection=0,enable_vCloud=0,exclude_swap=1,file_system_optimization=1,ignore_irvm=1,multi_org=0,nameuse=1,post_events=1,rHz=10,rLim=10,rTO=0,skipnodisk=0,snapact=2,trantype=san:nbd,vsrvr=tvmwvc01.bnhpgroup.com,uuid=501ad7ab-e6f6-bfe1-e34e-bf4905e8ec89,nip=(172.22.110.25)
18:50:07.094 [8172.8636] <4> bpfis: Starting keep alive thread.
18:50:07.094 [8172.8636] <4> bpfis: Acquiring snapshot lock:retry count [0]
18:50:07.094 [8172.8636] <2> getFileName:  FileName is [D:\Program Files\Veritas\NetBackup\online_util\fi_cntl\PRBLALSMTRBX_1403541249_copy1.lock]
18:50:07.094 [8172.8636] <2> getFileName:  FileName is [D:\Program Files\Veritas\NetBackup\online_util\fi_cntl\PRBLALSMTRBX_1403541249_copy1.lock]
18:50:07.094 [8172.8636] <4> bpfis: INF - BACKUP START 8172
18:50:07.094 [8172.8636] <32> bpfis: FTL - cannot open D:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.PRBLALSMTRBX_1403541249.1.0
18:50:07.094 [8172.8636] <4> bpfis: Starting keep alive thread.
18:50:07.094 [8172.8636] <2> deleteReference:    reference not found in the list
18:50:07.094 [8172.8636] <4> bpfis: Delete reference: status [-4]
18:50:07.094 [8172.8636] <2> writeSnapshotLockFile:    Writing type[2] refcount[0]
18:50:07.094 [8172.8636] <2> writeSnapshotLockFile:    Writing Flags [0] [0]
18:50:07.094 [8172.8636] <2> writeSnapshotLockFile:   Writing Last addReffernt Time [Thu Jan 01 02:00:00 1970

About the backup after it end with status code, I did not validate it but it yet.

RamNagalla's picture

i just missed out this post...

do you still have the issues,..?

ChAmp35's picture

Hi Sisso

Could You please check and confirm if oprhaned snapshots are containing keyword "NBU" ?

NBU only create snapshots starting or conating "NBU" keyword.

Sisso's picture

Thank you guys, but this issue is already solved, the problem was because a permissions issue.

RamNagalla's picture

Thansk for the update...

so my guess was right...  smiley