cancel
Showing results for 
Search instead for 
Did you mean: 

Restore jobs hangs in GUI, and never completes "vmware single files"

AndersA
Level 4

Hi all.

When i do a restore of single files from a vmware backup. the gui hangs, the restore completes but the job never gets done.

from the log file:

10:35:28 (5485091.001) INF - TAR EXITING WITH STATUS = 0
10:35:28 (5485091.001) INF - TAR RESTORED 1095 OF 1095 FILES SUCCESSFULLY
10:35:28 (5485091.001) INF - TAR KEPT 0 EXISTING FILES
10:35:28 (5485091.001) INF - TAR PARTIALLY RESTORED 0 FILES

10:35:30 INF - Beginning read-blockmap

 

Have anybody seen this before ??

 

 

 

 

22 REPLIES 22

Lowell_Palecek
Level 6
Employee

What version of NetBackup? Does the tar log end? What does the bpbrm log say after receiving the TAR exit messages? What does the bprd log say after starting bpbrm?

Netbackup 8, both on client and master/media server......I asume its  logs log on the master right :)

jbp-* log.

09:43:24 (5488089.001) INF - TAR EXITING WITH STATUS = 0
09:43:24 (5488089.001) INF - TAR RESTORED 1095 OF 1095 FILES SUCCESSFULLY
09:43:24 (5488089.001) INF - TAR KEPT 0 EXISTING FILES
09:43:24 (5488089.001) INF - TAR PARTIALLY RESTORED 0 FILES

09:43:26 INF - Beginning read-blockmap on server nbu-server1 of client web, reading file @aaabn.

bprd log

[61548.61548] <4> bprd.sfr: bptm_end: sending exit status 0 to bptm
09:43:24.775 [61548.61548] <4> check_bpbrm_status: bpbrm exit status = 0
09:43:24.775 [61548.61548] <4> bprd.sfr: check_bpbrm_status: bpbrm returned EC_success
09:43:24.775 [61548.61548] <4> bprd.sfr: sfr: closing bptmfd=28
09:43:24.775 [61548.61548] <4> bprd.sfr: get_bxmap_params: path=/\\.\VMFILE2_1507067141_CBBITMAP
09:43:24.775 [61548.61548] <8> vnet_get_user_credential_path: [vnet_vxss.c:1552] status 35 0x23
09:43:24.775 [61548.61548] <8> vnet_check_user_certificate: [vnet_vxss_helper.c:3879] vnet_get_user_credential_path failed 35 0x23
09:43:24.775 [61548.61548] <2> ConnectionCache::connectAndCache: Acquiring new connection for host nbu-master, query type 79
09:43:24.776 [61548.61548] <2> vnet_pbxConnect: pbxConnectEx Succeeded
09:43:24.776 [61548.61548] <2> logconnections: BPDBM CONNECT FROM 10.216.0.5.46644 TO 10.216.0.5.1556 fd = 7
09:43:24.803 [61548.61548] <4> bprd.sfr: get_bxmap_params: no pseudo record of type _CBBITMAP
09:43:24.803 [61548.61548] <2> db_end: Need to collect reply
09:43:24.809 [61548.61548] <2> db_end: no DONE from db_getreply(): no entity was found
09:43:24.810 [61548.61548] <4> bprd.sfr: sfr_cb: no changed blocks
09:43:24.810 [61548.61548] <4> bprd.sfr: sfr: restoring files in partition /home/
09:43:24.810 [61548.61548] <4> bprd.sfr: get_bxmap_params: path=/\\.\VMFILE2_1507067141_BITMAP
09:43:24.810 [61548.61548] <8> vnet_get_user_credential_path: [vnet_vxss.c:1552] status 35 0x23
09:43:24.811 [61548.61548] <8> vnet_check_user_certificate: [vnet_vxss_helper.c:3879] vnet_get_user_credential_path failed 35 0x23
09:43:24.811 [61548.61548] <2> ConnectionCache::connectAndCache: Acquiring new connection for host nbu-master, query type 79
09:43:24.811 [61548.61548] <2> vnet_pbxConnect: pbxConnectEx Succeeded
09:43:24.811 [61548.61548] <2> logconnections: BPDBM CONNECT FROM 10.216.0.5.50673 TO 10.216.0.5.1556 fd = 7
09:43:24.836 [61548.61548] <4> bprd.sfr: get_bxmap_params: no pseudo record of type _BITMAP
09:43:24.836 [61548.61548] <2> db_end: Need to collect reply
09:43:24.842 [61548.61548] <2> db_end: no DONE from db_getreply(): no entity was found
09:43:24.842 [61548.61548] <8> vnet_get_user_credential_path: [vnet_vxss.c:1552] status 35 0x23
09:43:24.842 [61548.61548] <8> vnet_check_user_certificate: [vnet_vxss_helper.c:3879] vnet_get_user_credential_path failed 35 0x23
09:43:24.842 [61548.61548] <2> ConnectionCache::connectAndCache: Acquiring new connection for host nbu-master[61548.61548] <4> bprd.sfr: bptm_end: sending exit status 0 to bptm
09:43:24.775 [61548.61548] <4> check_bpbrm_status: bpbrm exit status = 0
09:43:24.775 [61548.61548] <4> bprd.sfr: check_bpbrm_status: bpbrm returned EC_success
09:43:24.775 [61548.61548] <4> bprd.sfr: sfr: closing bptmfd=28
09:43:24.775 [61548.61548] <4> bprd.sfr: get_bxmap_params: path=/\\.\VMFILE2_1507067141_CBBITMAP
09:43:24.775 [61548.61548] <8> vnet_get_user_credential_path: [vnet_vxss.c:1552] status 35 0x23
09:43:24.775 [61548.61548] <8> vnet_check_user_certificate: [vnet_vxss_helper.c:3879] vnet_get_user_credential_path failed 35 0x23
09:43:24.775 [61548.61548] <2> ConnectionCache::connectAndCache: Acquiring new connection for host nbu-master, query type 79
09:43:24.776 [61548.61548] <2> vnet_pbxConnect: pbxConnectEx Succeeded
09:43:24.776 [61548.61548] <2> logconnections: BPDBM CONNECT FROM 10.216.0.5.46644 TO 10.216.0.5.1556 fd = 7
09:43:24.803 [61548.61548] <4> bprd.sfr: get_bxmap_params: no pseudo record of type _CBBITMAP
09:43:24.803 [61548.61548] <2> db_end: Need to collect reply
09:43:24.809 [61548.61548] <2> db_end: no DONE from db_getreply(): no entity was found
09:43:24.810 [61548.61548] <4> bprd.sfr: sfr_cb: no changed blocks
09:43:24.810 [61548.61548] <4> bprd.sfr: sfr: restoring files in partition /home/
09:43:24.810 [61548.61548] <4> bprd.sfr: get_bxmap_params: path=/\\.\VMFILE2_1507067141_BITMAP
09:43:24.810 [61548.61548] <8> vnet_get_user_credential_path: [vnet_vxss.c:1552] status 35 0x23
09:43:24.811 [61548.61548] <8> vnet_check_user_certificate: [vnet_vxss_helper.c:3879] vnet_get_user_credential_path failed 35 0x23
09:43:24.811 [61548.61548] <2> ConnectionCache::connectAndCache: Acquiring new connection for host nbu-master query type 79
09:43:24.811 [61548.61548] <2> vnet_pbxConnect: pbxConnectEx Succeeded
09:43:24.811 [61548.61548] <2> logconnections: BPDBM CONNECT FROM 10.216.0.5.50673 TO 10.216.0.5.1556 fd = 7
09:43:24.836 [61548.61548] <4> bprd.sfr: get_bxmap_params: no pseudo record of type _BITMAP
09:43:24.836 [61548.61548] <2> db_end: Need to collect reply
09:43:24.842 [61548.61548] <2> db_end: no DONE from db_getreply(): no entity was found
09:43:24.842 [61548.61548] <8> vnet_get_user_credential_path: [vnet_vxss.c:1552] status 35 0x23
09:43:24.842 [61548.61548] <8> vnet_check_user_certificate: [vnet_vxss_helper.c:3879] vnet_get_user_credential_path failed 35 0x23
09:43:24.842 [61548.61548] <2> ConnectionCache::connectAndCache: Acquiring new connection for host nbu-master, query type 79
09:43:24.842 [61548.61548] <2> vnet_pbxConnect: pbxConnectEx Succeeded
09:43:24.842 [61548.61548] <2> logconnections: BPDBM CONNECT FROM 10.216.0.5.52164 TO 10.216.0.5.1556 fd = 7
09:43:24.867 [61548.61548] <4> bprd.sfr: get_fsmap_params: non-Auspex image: filenum=81123 recno=102205 size=102187
09:43:24.907 [61548.61548] <2> db_end: Need to collect reply
09:43:24.913 [61548.61548] <4> bprd.sfr: sfr: partial: 0
09:43:24.913 [61548.61548] <4> bprd.sfr: sort_blockmap: rpspec->rp_nfiles = 1098
09:43:24.913 [61548.61548] <4> bprd.sfr: sort_blockmap: rpspec->rp_fsmapfilnum = 81123
09:43:24.913 [61548.61548] <4> bprd.sfr: sort_blockmap: rpspec->rp_fsmaprecno = 102205
09:43:24.913 [61548.61548] <4> bprd.sfr: sort_blockmap: rpspec->rp_fsmapsiz = 102187
09:43:24.913 [61548.61548] <4> bprd.sfr: start_bptm_reader: calling bptm_get
09:43:24.913 [61548.61548] <4> bprd.sfr: bptm_get: ri_file_name = /home/ ri_file_num=274927 ri_datarecno=307213
09:43:24.913 [61548.61548] <4> bprd.sfr: bptm_get: rp_nfiles = 1098 recno = 102205 rp_fsmapfilnum = 81123
09:43:24.913 [61548.61548] <4> bprd.sfr: bptm_get: rp_fsmapsiz = 102187
09:43:24.919 [61548.61548] <2> vnet_pbxConnect: pbxConnectEx Succeeded
09:43:24.919 [61548.61548] <2> logconnections: BPCD CONNECT FROM 10.216.0.5.38425 TO 10.216.0.10.1556 fd = 7
09:43:24.923 [61548.61548] <2> vnet_pbxConnect: pbxConnectEx Succeeded
09:43:24.926 [61548.61548] <8> do_pbx_service: [vnet_connect.c:2186] via PBX VNETD CONNECT FROM 10.216.0.5.51447 TO 10.216.0.10.1556 fd = 23
09:43:24.926 [61548.61548] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:455] VN_REQUEST_CONNECT_FORWARD_SOCKET 10 0xa
09:43:24.970 [61548.61548] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:480] ipc_string /usr/openv/var/tmp/vnet-24889507103004961326000002526-lsQD7p
09:43:25.060 [61548.61548] <2> bpcr_get_version_rqst: bpcd version: 08000000
09:43:25.060 [61548.61548] <4> bprd.sfr: start_bptm_reader: bptmfd = 7
09:43:25.060 [61548.61548] <4> bprd.sfr: start_bptm_reader: statfd = 23
09:43:25.060 [61548.61548] <4> bprd.sfr: open_sort_blockmap_files: bmetag file = /usr/openv/netbackup/SFR_TMPDIR/bmetag.61548
09:43:25.060 [61548.61548] <4> bprd.sfr: open_sort_blockmap_files: bmetagfd = 24
09:43:25.060 [61548.61548] <4> bprd.sfr: open_sort_blockmap_files: filhdr file = /usr/openv/netbackup/SFR_TMPDIR/filhdr.61548
09:43:25.060 [61548.61548] <4> bprd.sfr: open_sort_blockmap_files: filhdrfd = 25
09:43:25.060 [61548.61548] <4> bprd.sfr: sort_blockmap: bmetagfd = 24 filhdrfd = 25
09:43:25.060 [61548.61548] <4> bprd.sfr: sort_blockmap: bptmfd = 7 statfd = 23
09:43:25.060 [61548.61548] <4> bprd.sfr: sort_blockmap: sending mm_msg.x_msg = XFERBLOCK 102205 102187
09:43:25.060 [61548.61548] <4> bprd.sfr: find_imghdr: currec = 102204
09:43:26.185 [61548.61548] <4> bprd.sfr: find_imghdr: imghdr->ih_magic = 0x47f923e4
09:43:26.185 [61548.61548] <4> bprd.sfr: find_imghdr: vix_file_based set to 1
09:43:26.185 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.185 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.185 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.185 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.185 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.185 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.185 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.185 [61548.61548] <4> bprd.sfr: get_bxmap_params: path=/\\.\VMFILE2_1507067141_BITMAP
09:43:26.185 [61548.61548] <8> vnet_get_user_credential_path: [vnet_vxss.c:1552] status 35 0x23
09:43:26.185 [61548.61548] <8> vnet_check_user_certificate: [vnet_vxss_helper.c:3879] vnet_get_user_credential_path failed 35 0x23
09:43:26.185 [61548.61548] <2> ConnectionCache::connectAndCache: Acquiring new connection for host nbu-master, query type 79
09:43:26.186 [61548.61548] <2> vnet_pbxConnect: pbxConnectEx Succeeded
09:43:26.186 [61548.61548] <2> logconnections: BPDBM CONNECT FROM 10.216.0.5.44467 TO 10.216.0.5.1556 fd = 29
09:43:26.212 [61548.61548] <4> bprd.sfr: get_bxmap_params: no pseudo record of type _BITMAP
09:43:26.212 [61548.61548] <2> db_end: Need to collect reply
09:43:26.219 [61548.61548] <2> db_end: no DONE from db_getreply(): no entity was found
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr:cluster size = 4096
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: found image header
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: currec=102206
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: flags=b800000
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: machtype =b fstype=0
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: byteorder=1 IH_BYTEORDER=1
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: fiid file size=26112
09:43:26.219 [61548.61548] <2> sort_blockmap: vxms_directed = 1, BLIB_VIX = 0
09:43:26.219 [61548.61548] <4> bprd.sfr: vxms_sort_blockmap: entering ...
09:43:31.997 [12492.12492] <4> msgbackup: waiting for response from nbpem
09:43:45.353 [15775.15775] <4> msgbackup: waiting for response from nbpem
09:44:03.999 [12492.12492] <4> msgbackup: waiting for response from nbpem
, query type 79
09:43:24.842 [61548.61548] <2> vnet_pbxConnect: pbxConnectEx Succeeded
09:43:24.842 [61548.61548] <2> logconnections: BPDBM CONNECT FROM 10.216.0.5.52164 TO 10.216.0.5.1556 fd = 7
09:43:24.867 [61548.61548] <4> bprd.sfr: get_fsmap_params: non-Auspex image: filenum=81123 recno=102205 size=102187
09:43:24.907 [61548.61548] <2> db_end: Need to collect reply
09:43:24.913 [61548.61548] <4> bprd.sfr: sfr: partial: 0
09:43:24.913 [61548.61548] <4> bprd.sfr: sort_blockmap: rpspec->rp_nfiles = 1098
09:43:24.913 [61548.61548] <4> bprd.sfr: sort_blockmap: rpspec->rp_fsmapfilnum = 81123
09:43:24.913 [61548.61548] <4> bprd.sfr: sort_blockmap: rpspec->rp_fsmaprecno = 102205
09:43:24.913 [61548.61548] <4> bprd.sfr: sort_blockmap: rpspec->rp_fsmapsiz = 102187
09:43:24.913 [61548.61548] <4> bprd.sfr: start_bptm_reader: calling bptm_get
09:43:24.913 [61548.61548] <4> bprd.sfr: bptm_get: ri_file_name = /home/ ri_file_num=274927 ri_datarecno=307213
09:43:24.913 [61548.61548] <4> bprd.sfr: bptm_get: rp_nfiles = 1098 recno = 102205 rp_fsmapfilnum = 81123
09:43:24.913 [61548.61548] <4> bprd.sfr: bptm_get: rp_fsmapsiz = 102187
09:43:24.919 [61548.61548] <2> vnet_pbxConnect: pbxConnectEx Succeeded
09:43:24.919 [61548.61548] <2> logconnections: BPCD CONNECT FROM 10.216.0.5.38425 TO 10.216.0.10.1556 fd = 7
09:43:24.923 [61548.61548] <2> vnet_pbxConnect: pbxConnectEx Succeeded
09:43:24.926 [61548.61548] <8> do_pbx_service: [vnet_connect.c:2186] via PBX VNETD CONNECT FROM 10.216.0.5.51447 TO 10.216.0.10.1556 fd = 23
09:43:24.926 [61548.61548] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:455] VN_REQUEST_CONNECT_FORWARD_SOCKET 10 0xa
09:43:24.970 [61548.61548] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:480] ipc_string /usr/openv/var/tmp/vnet-24889507103004961326000002526-lsQD7p
09:43:25.060 [61548.61548] <2> bpcr_get_version_rqst: bpcd version: 08000000
09:43:25.060 [61548.61548] <4> bprd.sfr: start_bptm_reader: bptmfd = 7
09:43:25.060 [61548.61548] <4> bprd.sfr: start_bptm_reader: statfd = 23
09:43:25.060 [61548.61548] <4> bprd.sfr: open_sort_blockmap_files: bmetag file = /usr/openv/netbackup/SFR_TMPDIR/bmetag.61548
09:43:25.060 [61548.61548] <4> bprd.sfr: open_sort_blockmap_files: bmetagfd = 24
09:43:25.060 [61548.61548] <4> bprd.sfr: open_sort_blockmap_files: filhdr file = /usr/openv/netbackup/SFR_TMPDIR/filhdr.61548
09:43:25.060 [61548.61548] <4> bprd.sfr: open_sort_blockmap_files: filhdrfd = 25
09:43:25.060 [61548.61548] <4> bprd.sfr: sort_blockmap: bmetagfd = 24 filhdrfd = 25
09:43:25.060 [61548.61548] <4> bprd.sfr: sort_blockmap: bptmfd = 7 statfd = 23
09:43:25.060 [61548.61548] <4> bprd.sfr: sort_blockmap: sending mm_msg.x_msg = XFERBLOCK 102205 102187
09:43:25.060 [61548.61548] <4> bprd.sfr: find_imghdr: currec = 102204
09:43:26.185 [61548.61548] <4> bprd.sfr: find_imghdr: imghdr->ih_magic = 0x47f923e4
09:43:26.185 [61548.61548] <4> bprd.sfr: find_imghdr: vix_file_based set to 1
09:43:26.185 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.185 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.185 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.185 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.185 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.185 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.185 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.185 [61548.61548] <4> bprd.sfr: get_bxmap_params: path=/\\.\VMFILE2_1507067141_BITMAP
09:43:26.185 [61548.61548] <8> vnet_get_user_credential_path: [vnet_vxss.c:1552] status 35 0x23
09:43:26.185 [61548.61548] <8> vnet_check_user_certificate: [vnet_vxss_helper.c:3879] vnet_get_user_credential_path failed 35 0x23
09:43:26.185 [61548.61548] <2> ConnectionCache::connectAndCache: Acquiring new connection for host nbu-master, query type 79
09:43:26.186 [61548.61548] <2> vnet_pbxConnect: pbxConnectEx Succeeded
09:43:26.186 [61548.61548] <2> logconnections: BPDBM CONNECT FROM 10.216.0.5.44467 TO 10.216.0.5.1556 fd = 29
09:43:26.212 [61548.61548] <4> bprd.sfr: get_bxmap_params: no pseudo record of type _BITMAP
09:43:26.212 [61548.61548] <2> db_end: Need to collect reply
09:43:26.219 [61548.61548] <2> db_end: no DONE from db_getreply(): no entity was found
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: change datarecno 307213 to 307213
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr:cluster size = 4096
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: found image header
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: currec=102206
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: flags=b800000
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: machtype =b fstype=0
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: byteorder=1 IH_BYTEORDER=1
09:43:26.219 [61548.61548] <4> bprd.sfr: find_imghdr: fiid file size=26112
09:43:26.219 [61548.61548] <2> sort_blockmap: vxms_directed = 1, BLIB_VIX = 0
09:43:26.219 [61548.61548] <4> bprd.sfr: vxms_sort_blockmap: entering ...
09:43:31.997 [12492.12492] <4> msgbackup: waiting for response from nbpem
09:43:45.353 [15775.15775] <4> msgbackup: waiting for response from nbpem
09:44:03.999 [12492.12492] <4> msgbackup: waiting for response from nbpem

 

bpbrm log

none

 

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified

There is no record of restore in the bprd extract in your post above.

We need yesterday's bprd log on the master that corresponds with restore start and end time.
Please copy to bprd.txt and upload as attachment. 
The bprd PID can be found in Activity Monitor Job Details.

bpbrm is locatated on the media server (if the folder exists).

tar log on the backup host could also be helpful. 

Ok...i will try and find the logs....

the bprd log is one i just did with a restore though.

should i raise logs to verbose = 5 for this.

 

 

bpbrd.log

tar.log

bpbrm.log

jbp.log

 

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified

Please show us all text in Job Details so that we can easily locate the PIDs in the logs.

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified

Apologies - I see you have already extracted relevant PIDs.

No Worries :), thx for your help :)

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified

Observations from logs:

bprd (PID 43118) hands down to bpbrm:

10:21:32.559 [43118.43118] <2> start_brm: backup restore server = nbu-pdde0c.""
......
10:21:32.682 [43118.43118] <2> start_brm: /usr/openv/netbackup/bin/bpbrm bpbrm -restore -mt 0 -mst 6 -k 0 -c webhotelp."" -rclnt nbu-master."" -cl I.....

Successful restore logged for this PID:

10:21:34.251 [43118.43118] <4> bprd.sfr: restore_regfiles: processsed 62 zero length files
....
10:21:34.251 [43118.43118] <4> bprd.sfr: sfr: flags 0 partial 0
10:21:34.251 [43118.43118] <4> bprd.sfr: bptm_end: sending exit status 0 to bptm
10:21:35.052 [43118.43118] <8> check_bpbrm_status: CKP - 5488091.001 1507105294 0 0 0 1 0 5 27 /home/web/prod/bbstatistik/
10:21:36.954 [43118.43118] <4> check_bpbrm_status: bpbrm exit status = 0
10:21:36.954 [43118.43118] <4> bprd.sfr: check_bpbrm_status: bpbrm returned EC_success
.....

Last couple of bprd entries for this PID (that I don't quite understand...) 
10:21:38.250 [43118.43118] <4> bprd.sfr: find_imghdr: byteorder=1 IH_BYTEORDER=1
10:21:38.250 [43118.43118] <4> bprd.sfr: find_imghdr: fiid file size=26112
10:21:38.250 [43118.43118] <2> sort_blockmap: vxms_directed = 1, BLIB_VIX = 0
10:21:38.250 [43118.43118] <4> bprd.sfr: vxms_sort_blockmap: entering ...

bpbrm logs successful restore with the last 'disconnect' entry at 10:26:

10:21:36.859 [3149.3149] <2> set_job_details: Tfile (5488091): LOG 1507105296 4 tar 29858 done. status: 0: the requested operation was successfully completed
10:21:36.859 [3149.3149] <2> send_job_file: job ID 5488091, ftype = 3 msg len = 95, msg = LOG 1507105296 4 tar 29858 done. status: 0: the requested operation was successfully completed
10:21:36.859 [3149.3149] <2> bpbrm Exit: client restore EXIT STATUS 0: the requested operation was successfully completed
10:26:36.985 [3149.3149] <2> vnet_close_socket_safely: [vnet.c:1109] safe close 0 0x0
10:26:36.987 [3149.3149] <2> job_monitoring_exex: ACK disconnect
10:26:36.987 [3149.3149] <2> job_disconnect: Disconnected

Strange that there is exactly 5 minutes between 'success' and 'disconnect'.
We know that most default timeouts in NBU is 5 minutes.

tar log ends at 10:21:

10:21:36.854 [29858.29858] <4> cTarMain::appMain: INF - TAR exiting with status: 0
10:21:36.854 [29858.29858] <4> shutdown: INF - Shutting down event handler
10:21:36.854 [29858.29858] <4> cTarEventHandler::unregisterSignalHandler: INF - Un-registering signal handler
10:21:36.854 [29858.29858] <4> cTarEventHandler::unregisterSignalHandler: INF - Successfully un-registered signal handler
10:21:36.854 [29858.29858] <4> stopKeepAlive: INF - Stopping keepalive thread
10:21:36.855 [29858.29858] <4> stopKeepAlive: INF - Successfully stopped keepalive thread
10:21:36.855 [29858.29858] <2> NCFBlockUntil::finished: DBG - Object 0xb1aeb0 (unknown object name) removed from blocker (../NcfRefCounted.cpp:146)
10:21:36.855 [29858.29858] <2> cTarMain::appCleanup: DBG - Waiting for event handler to cleanup
10:21:36.855 [29858.29858] <2> cTarMain::appCleanup: DBG - Event handler cleanup done
10:21:36.855 [29858.29858] <4> cTarMain::closeConnections: INF - Closing stderr connection
10:21:36.859 [29858.29858] <2> vnet_close_socket_safely: [vnet.c:1109] safe close 0 0x0
10:21:36.859 [29858.29858] <4> cTarMain::closeConnections: INF - Closing stdout connection
10:21:36.859 [29858.29858] <2> vnet_close_socket_safely: [vnet.c:1109] safe close 0 0x0
10:21:36.859 [29858.29858] <4> cTarMain::closeConnections: INF - Closing stdin/stdout connection
10:21:36.859 [29858.29858] <2> vnet_close_socket_safely: [vnet.c:1109] safe close 0 0x0
10:21:36.860 [29858.29858] <2> Unpacker::close(): DBG - close() has already been called. (../Unpacker.cpp:133)

Not sure why we are seeing this entry (after successful restore) in jbp log - as if the restore is carry on? 

10:21:36 (5488091.001) INF - TAR PARTIALLY RESTORED 0 FILES

10:21:38 INF - Beginning read-blockmap on server nbu-pdde0c."" of client webhotel, reading file @aaabn.

Looking at the process flow diagram it seems that bptm needs to notify nbjm.
At this point the job appears as “Done” in the Activity Monitor.

So it seems that you will need bptm log (on the media server) and vxlogview output of nbjm as well. 

Ok

Thank you very mutch, I wil try and locate these on the media sever and upload them :)

 

nbjm log is on master.

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified

Thanks @Lowell_Palecek

I forgot to mention that nbjm runs on the master server. (I sometimes assume that this is general knowledge).

@AndersA the process flow diagram for restores can be found in NetBackup Logging Reference Guide

This doc shows which processes run on which server.

HTH

thx i figured it was on the master .....because it made no output on the media server :)

bptm.log

nbjm.log

 

bptm logs shows that job has completed at 10:21am...

10:21:36.708 [3150] <2> packageBptmResourceDoneMsg: keyword MEDIA_DONE version 0 jobid 5488091 copyNum 0 mediaId @aaabn mediaKey 77 unloadDelay 0 allocId {0785DD76-A8DD-11E7-8C92-3FA6642622C6}
10:21:36.709 [3150] <2> packageBptmResourceDoneMsg: returns 0

Is that jobid the correct one in your job details?

As for nbjm, there are many messages of:

10/04/2017 10:21:37.545 [JobMapper::openParentJob] (0xed70e0) invalid parent jobid(JobMapper.cpp:215)
10/04/2017 10:21:52.084 [BPCRConnection::unlinkFromRequester] marking connection not reusable because parser is not reusable 

Cannot find the parent jobid, that is a bit strange because it should still be there, unless the connect-back socket has been terminated (still unlikely if it's not too busy). What's the number of WAIT sockets in your master server? Do a "netstat -an | grep WAIT | wc" to find out. 

sadly my restore job has been removed so the job details are gone.

I get this when i do a word count

 

netstat -an | grep WAIT | wc    9      54     720

 

netstat -an | grep WAIT | wc
     62     372    4960

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified

You say that the ".. restore job has been removed  ".

Does this mean that the job eventually finished? Or maybe killed it? 

Is it just this job that behaved like this? All other restores completed successfully?

It maybe a good idea to perform a couple of test restores to determine if there is some sort of a pattern.