noneatnoone
6 years agoLevel 3
hyper-v backups failing 4207/4201
14:23:55.459 [31606.31606] <2> dump_proxy_info: local_proxy_info: 14:23:55.459 [31606.31606] <2> dump_proxy_info: ----pid: 11705 14:23:55.459 [31606.31606] <2> dump_proxy_info: ----connection_id: {2181A948-5D50-11E9-BF83-DC144838C133}:OUTBOUND 14:23:55.459 [31606.31606] <2> dump_proxy_info: ----ca_roots: 62c6785f-7010-436d-b140-ebb9843d84b1 14:23:55.459 [31606.31606] <2> dump_proxy_info: ----ca_roots_excluded: UNCONSTRAINED 14:23:55.459 [31606.31606] <2> dump_proxy_info: remote_proxy_info: 14:23:55.459 [31606.31606] <2> dump_proxy_info: ----pid: 11856 14:23:55.459 [31606.31606] <2> dump_proxy_info: ----connection_id: {405A96F3-31B2-4044-B103-2FC5EA45E697}:INBOUND 14:23:55.459 [31606.31606] <2> dump_proxy_info: ----ca_roots: 62c6785f-7010-436d-b140-ebb9843d84b1 14:23:55.459 [31606.31606] <2> dump_proxy_info: ----ca_roots_excluded: UNCONSTRAINED 14:23:55.459 [31606.31606] <2> dump_proxy_info: remote_endpoint_info: 14:23:55.459 [31606.31606] <2> dump_proxy_info: ----pid: 23064 14:23:55.459 [31606.31606] <2> dump_proxy_info: ----local_hostname: vme02.hidden 14:23:55.459 [31606.31606] <2> dump_proxy_info: domain_constraints_set: 14:23:55.459 [31606.31606] <2> dump_proxy_info: ----process_hint_server_name: netbackup02.hidden 14:23:55.459 [31606.31606] <2> dump_proxy_info: ----process_hint: 62c6785f-7010-436d-b140-ebb9843d84b1 14:23:55.459 [31606.31606] <2> dump_proxy_info: ----process_hint_reason: there was no inherited hint, the connected peer was not a master server, so defaulted to primary master 14:23:55.459 [31606.31606] <2> is_connection_INBOUND: Connection-Is-INBOUND:[FALSE] 14:23:55.459 [31606.31606] <2> vnet_same_host_and_update: [vnet_addrinfo.c:3021] Comparing name1:[localhost] name2:[127.0.0.1] 14:23:55.460 [31606.31606] <2> is_connection_INBOUND: Connection-Is-INBOUND:[FALSE] 14:23:55.460 [31606.31606] <8> do_pbx_service: [vnet_connect.c:2579] via PBX VNETD CONNECT FROM 172.31.7.235.53661 TO 172.31.7.209.1556 fd = 6 14:23:55.461 [31606.31606] <2> is_connection_INBOUND: Connection-Is-INBOUND:[FALSE] 14:23:55.461 [31606.31606] <2> async_connect: [vnet_connect.c:2072] connect async CONNECT FROM 172.31.7.235.53661 TO 172.31.7.209.1556 fd = 6 14:23:55.461 [31606.31606] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO vme02 172.31.7.209 vnetd VIA pbx 14:23:55.461 [31606.31606] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:458] VN_REQUEST_CONNECT_FORWARD_SOCKET 10 0xa 14:23:55.469 [31606.31606] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:483] ipc_string 53028 14:23:55.470 [31606.31606] <2> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:494] hash_str1 14946a33a34a31100786ed01d94a02ea 14:23:55.601 [31606.31606] <2> is_connection_INBOUND: Connection-Is-INBOUND:[FALSE] 14:23:55.630 [31606.31606] <2> bpcr_get_version_rqst: bpcd version: 08100000 14:23:55.630 [31606.31606] <2> ddns_check: Entering 14:23:55.630 [31606.31606] <2> is_connection_INBOUND: Connection-Is-INBOUND:[FALSE] 14:23:55.830 [31606.31606] <2> bpcr_get_hostname_rqst: Server hostname length = 19 14:23:55.830 [31606.31606] <2> bpbrm start_bpcd_stat: DATA_SOCK from bpcr = 5 14:23:55.830 [31606.31606] <2> bpbrm start_bpcd_stat: NAME_SOCK from bpcr = 6 14:23:55.831 [31606.31606] <2> pfi_start_client: command = /usr/openv/netbackup/bin/bpfis bpfis delete -nbu -id ex-onprem01_1555093374 -bpstart_to 300 -bpend_to 300 -clnt vme02 -jobgrpid 293 -jobid 293 -copy 1 -pt 41 -st FULL -status 4201 -S netbackup02.hidden -fim Hyper-V_v2:allow_offline_backup=1,prov_type=0,csv_timeout=180,nameuse=1,Virtual_machine_backup=2,snap_attr=0 14:23:55.831 [31606.31606] <2> pfi_start_client: (../bpbrm.c:27069) (Jobid: 293) Using bpcr_fork_cmd_rqst to start bpfis 14:23:55.831 [31606.31606] <2> pfi_start_client: (../bpbrm.c:27112) (Jobid: 293) Connected to bpfis, data socket 5 is proxied, name socket 6 is proxied 14:23:55.831 [31606.31606] <2> pfi_start_client: received bpcd success message 14:23:58.184 [31606.31606] <2> pfi_start_client: read start message from vme02, msg=<INF - BACKUP START 25684> 14:23:58.184 [31606.31606] <2> set_job_details: Tfile (293): LOG 1555093438 4 bpfis 25684 Backup started 14:23:58.184 [31606.31606] <2> send_job_file: job ID 293, ftype = 3 msg len = 44, msg = LOG 1555093438 4 bpfis 25684 Backup started 14:23:58.185 [31606.31606] <2> get_bpfis_msg: bpfis buff: WRN - cannot open C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.ex-onprem01_1555093374.1.0 14:23:58.185 [31606.31606] <8> get_bpfis_msg: from client ex-onprem01: WRN - cannot open C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.ex-onprem01_1555093374.1.0 14:23:58.185 [31606.31606] <2> set_job_details: Tfile (293): LOG 1555093438 8 bpbrm 31606 from client ex-onprem01: cannot open C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.ex-onprem01_1555093374.1.0 14:23:58.185 [31606.31606] <2> send_job_file: job ID 293, ftype = 3 msg len = 158, msg = LOG 1555093438 8 bpbrm 31606 from client ex-onprem01: cannot open C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.ex-onprem01_1555093374.1.0 14:23:58.185 [31606.31606] <4> db_error_add_to_file: from client ex-onprem01: cannot open C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.ex-onprem01_1555093374.1.0 14:23:58.186 [31606.31606] <2> set_job_details: Tfile (293): LOG 1555093438 4 bpfis 25684 done. status: 4207 14:23:58.186 [31606.31606] <2> send_job_file: job ID 293, ftype = 3 msg len = 48, msg = LOG 1555093438 4 bpfis 25684 done. status: 4207 14:23:58.186 [31606.31606] <2> set_job_details: Tfile (293): END_OPERATION 1555093438 14:23:58.186 [31606.31606] <2> send_job_file: job ID 293, ftype = 3 msg len = 25, msg = END_OPERATION 1555093438 14:23:58.187 [31606.31606] <2> set_job_details: Tfile (293): LOG 1555093438 4 bpfis 25684 done. status: 4207: Could not fetch snapshot metadata or state files 14:23:58.187 [31606.31606] <2> send_job_file: job ID 293, ftype = 3 msg len = 98, msg = LOG 1555093438 4 bpfis 25684 done. status: 4207: Could not fetch snapshot metadata or state files 14:23:58.187 [31606.31606] <2> bpbrm Exit: client snapshot EXIT STATUS 4207: Could not fetch snapshot metadata or state files 14:23:58.187 [31606.31606] <2> vnet_close_socket_safely_ex: [vnet.c:1176] safe close 0 0x0 14:23:58.187 [31606.31606] <4> JobdSockList::UnregisterSocket: Unregister socket (4). 14:23:58.187 [31606.31606] <2> job_monitoring_exex: ACK disconnect status: 4207: Could not fetch snapshot metadata or state files 14:23:58.187 [31606.31606] <2> job_disconnect: Disconnected ~ ~ ________________________________________________ additional logs Apr 12, 2019 2:34:39 PM - Info nbjm (pid=12770) starting backup job (jobid=294) for client ex-onprem01, policy exon, schedule Full Apr 12, 2019 2:34:39 PM - Info nbjm (pid=12770) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=294, request id:{A165EE48-5D51-11E9-A660-EA8D4063A3A0}) Apr 12, 2019 2:34:39 PM - requesting resource stu_disk_netbackup02 Apr 12, 2019 2:34:39 PM - requesting resource netbackup02.centric.local.NBU_CLIENT.MAXJOBS.ex-onprem01 Apr 12, 2019 2:34:39 PM - requesting resource netbackup02.centric.local.NBU_POLICY.MAXJOBS.exon Apr 12, 2019 2:34:39 PM - granted resource netbackup02.centric.local.NBU_CLIENT.MAXJOBS.ex-onprem01 Apr 12, 2019 2:34:39 PM - granted resource netbackup02.centric.local.NBU_POLICY.MAXJOBS.exon Apr 12, 2019 2:34:39 PM - granted resource MediaID=@aaaab;DiskVolume=PureDiskVolume;DiskPool=dp_disk_netbackup02;Path=PureDiskVolume;StorageServer=netbackup02.centric.local;MediaServer=netbackup02.centric.local Apr 12, 2019 2:34:39 PM - granted resource stu_disk_netbackup02 Apr 12, 2019 2:34:39 PM - estimated 0 kbytes needed Apr 12, 2019 2:34:39 PM - begin Parent Job Apr 12, 2019 2:34:39 PM - begin Hyper-V: Start Notify Script Apr 12, 2019 2:34:39 PM - Info RUNCMD (pid=34474) started Apr 12, 2019 2:34:39 PM - Info RUNCMD (pid=34474) exiting with status: 0 Operation Status: 0 Apr 12, 2019 2:34:39 PM - end Hyper-V: Start Notify Script; elapsed time 0:00:00 Apr 12, 2019 2:34:39 PM - begin Hyper-V: Step By Condition Operation Status: 0 Apr 12, 2019 2:34:39 PM - end Hyper-V: Step By Condition; elapsed time 0:00:00 Apr 12, 2019 2:34:39 PM - begin Hyper-V: Read File List Operation Status: 0 Apr 12, 2019 2:34:39 PM - end Hyper-V: Read File List; elapsed time 0:00:00 Apr 12, 2019 2:34:39 PM - begin Hyper-V: Create Snapshot Apr 12, 2019 2:34:39 PM - started process bpbrm (pid=34483) Apr 12, 2019 2:34:45 PM - Info bpbrm (pid=34483) ex-onprem01 is the host to backup data from Apr 12, 2019 2:34:45 PM - Info bpbrm (pid=34483) reading file list for client Apr 12, 2019 2:34:46 PM - Info bpbrm (pid=34483) start bpfis on client Apr 12, 2019 2:34:46 PM - Info bpbrm (pid=34483) Starting create snapshot processing Apr 12, 2019 2:34:48 PM - Info bpfis (pid=14428) Backup started Apr 12, 2019 2:35:37 PM - Info bpfis (pid=14428) Unexpected error. The error code is logged in the error log file Apr 12, 2019 2:35:37 PM - Critical bpbrm (pid=34483) from client ex-onprem01: FTL - vfm_freeze_commit: method: Hyper-V_v2, type: FIM, function: Hyper-V_v2_make Apr 12, 2019 2:35:37 PM - Critical bpbrm (pid=34483) from client ex-onprem01: FTL - snapshot services: snapshot creation failed: provider-private error. Apr 12, 2019 2:35:37 PM - Critical bpbrm (pid=34483) from client ex-onprem01: FTL - vfm_freeze_commit: method: Hyper-V_v2, type: FIM, function: Hyper-V_v2_make Apr 12, 2019 2:35:37 PM - Critical bpbrm (pid=34483) from client ex-onprem01: FTL - snapshot services: snapshot creation failed: provider-private error. Apr 12, 2019 2:35:37 PM - Critical bpbrm (pid=34483) from client ex-onprem01: FTL - snapshot processing failed, status 4201 Apr 12, 2019 2:35:37 PM - Critical bpbrm (pid=34483) from client ex-onprem01: FTL - snapshot creation failed, status 4201 Apr 12, 2019 2:35:37 PM - Warning bpbrm (pid=34483) from client ex-onprem01: WRN - ALL_LOCAL_DRIVES is not frozen Apr 12, 2019 2:35:37 PM - Info bpfis (pid=14428) done. status: 4201 Apr 12, 2019 2:35:37 PM - end Hyper-V: Create Snapshot; elapsed time 0:00:58 Apr 12, 2019 2:35:37 PM - Info bpfis (pid=14428) done. status: 4201: Incorrect snapshot method configuration or snapshot method not compatible for protecting backup selection entries. Apr 12, 2019 2:35:37 PM - end writing Operation Status: 4201 Apr 12, 2019 2:35:37 PM - end Parent Job; elapsed time 0:00:58 Apr 12, 2019 2:35:37 PM - begin Hyper-V: Stop On Error Operation Status: 0 Apr 12, 2019 2:35:37 PM - end Hyper-V: Stop On Error; elapsed time 0:00:00 Apr 12, 2019 2:35:37 PM - begin Hyper-V: Delete Snapshot Apr 12, 2019 2:35:37 PM - started process bpbrm (pid=34750) Apr 12, 2019 2:35:44 PM - Info bpbrm (pid=34750) Starting delete snapshot processing Apr 12, 2019 2:35:47 PM - Info bpfis (pid=19704) Backup started Apr 12, 2019 2:35:47 PM - Warning bpbrm (pid=34750) from client ex-onprem01: cannot open C:\Program Files\Veritas\NetBackup\online_util\fi_cntl\bpfis.fim.ex-onprem01_1555094079.1.0 Apr 12, 2019 2:35:47 PM - Info bpfis (pid=19704) done. status: 4207 Apr 12, 2019 2:35:47 PM - end Hyper-V: Delete Snapshot; elapsed time 0:00:10 Apr 12, 2019 2:35:47 PM - Info bpfis (pid=19704) done. status: 4207: Could not fetch snapshot metadata or state files Apr 12, 2019 2:35:47 PM - end writing Operation Status: 4207 Apr 12, 2019 2:35:47 PM - begin Hyper-V: End Notify Script Apr 12, 2019 2:35:47 PM - Info RUNCMD (pid=34773) started Apr 12, 2019 2:35:47 PM - Info RUNCMD (pid=34773) exiting with status: 0 Operation Status: 0 Apr 12, 2019 2:35:47 PM - end Hyper-V: End Notify Script; elapsed time 0:00:00 Operation Status: 4201 Incorrect snapshot method configuration or snapshot method not compatible for protecting backup selection entries (4201)
it was the VSS storage for Snapshots, I ran the powershell to create vss storage snapshot space and it started working,