Unable to Complete Tape Restore - "The device is now being reused for one of the remaining families"

Please copy the TEXT in failed parent job and post here (not screenshot)

Have you created dbclient log before starting the restore?

We need to see the dbclient log.
Please copy to dbclient.txt and upload as File Attachment.

02/22/2016 12:19:12 - begin Restore
02/22/2016 12:19:14 - Info dbclient (pid=5660) INF - RESTORE STARTED USING
02/22/2016 12:19:14 - Info dbclient (pid=5660) Microsoft SQL Server 2008 R2 (SP2) - 10.50.4042.0 (X64) 
02/22/2016 12:19:14 - Info dbclient (pid=5660) Mar 26 2015 21:18:04 
02/22/2016 12:19:14 - Info dbclient (pid=5660) Copyright (c) Microsoft Corporation
02/22/2016 12:19:14 - Info dbclient (pid=5660) Enterprise Edition (64-bit) on Windows NT 6.1 <X64> (Build 7601: Service Pack 1) (Hypervisor) 
02/22/2016 12:19:14 - Info dbclient (pid=5660) Batch = C:\nbu\scripts\restore_1215.bch, Op# = 1.
02/22/2016 12:19:14 - Info dbclient (pid=5660) INF - Using backup image edc-assetmgmt-01.MSSQL7.EDC-ASSETMGMT-0.db.NorbusMutualFund.~.7.001of002.20151231225150..C
02/22/2016 12:19:15 - Info dbclient (pid=5660) INF - restore database "NorbusMutualFund_1215" from VIRTUAL_DEVICE='VNBU0-5660-3392-1456143833' with  stats = 10, blocksize = 65536, maxtransfersize = 4194304, buffercount = 2, replace , norecovery, move 'NorbusMutualFund' to 'D:\MSSQL\Data\NorbusMutualFund_1215.mdf', move 'NorbusMutualFund_log' to 'D:\MSSQL\Data\NorbusMutualFund_log_1215.ldf', replace
02/22/2016 12:19:15 - Info dbclient (pid=5660) INF - Number of stripes: 1, Number of buffers per stripe 2.
02/22/2016 12:19:15 - Info dbclient (pid=5660) INF - Created VDI object for SQL Server instance <EPG-NORBUSLV-01>. Connection timeout is <300> seconds.
02/22/2016 12:21:55 - Info dbclient (pid=5660) INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]10 percent processed.>.
02/22/2016 12:21:55 - Info dbclient (pid=5660) INF - SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]20 percent processed.>
02/22/2016 12:22:01 - Info dbclient (pid=5660) INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]30 percent processed.>.
02/22/2016 12:22:09 - Info dbclient (pid=5660) INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]40 percent processed.>.
02/22/2016 12:22:09 - Info dbclient (pid=5660) INF - SQL Message <3251><[Microsoft][ODBC SQL Server Driver][SQL Server]The media family on device 'VNBU0-5660-3392-1456143833' is complete. The device is now being reused for one of the remaining families.>
02/22/2016 12:37:20 - Info dbclient (pid=5660) ERR - Error in VxBSAEndData: 3.
02/22/2016 12:37:20 - Info dbclient (pid=5660)     CONTINUATION: - System detected error, operation aborted.
02/22/2016 12:37:22 - Info dbclient (pid=5660) INF - OPERATION #1 of batch C:\nbu\scripts\restore_1215.bch FAILED with STATUS 1 (0 is normal). Elapsed time = 1089(1089) seconds.
02/22/2016 12:37:25 - Info dbclient (pid=5660) INF - Results of executing <C:\nbu\scripts\restore_1215.bch>: 
02/22/2016 12:37:25 - Info dbclient (pid=5660) <0> operations succeeded. <1> operations failed.
 

That message is INF (Info) and not generated by NBU.
See : https://technet.microsoft.com/en-us/library/aa238243(v=sql.80).aspx 

You need the dbclient log on the SQL server to see what happened between these 2 timestamps:

02/22/2016 12:22:09 - 
02/22/2016 12:37:20 -

Best to have minimum logging level of 3 enabled to troubleshoot restore issues.

Seems the connection suddenly failed. :

12:23:51.403 [5660.5536] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:23:51.404 [5660.5536] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52715 TO 10.2.120.120.1556 fd = 484
12:23:51.414 [5660.5536] <4> CGlobalInformation::VCSVirtualNameList: INF - Veritas Cluster Server is not installed.
12:23:51.415 [5660.5536] <1> CGlobalInformation::VCSVirtualNameList:     CONTINUATION: - The system cannot find the path specified.
12:23:51.415 [5660.5536] <4> ODBCDataSource::isInstalled: INF - Searching for ODBC Driver: SQL Native Client
12:23:51.415 [5660.5536] <4> ODBCDataSource::isInstalled: INF - Registry Install Path: SOFTWARE\Microsoft\Microsoft SQL Native Client\
12:23:51.415 [5660.5536] <4> ODBCDataSource::isInstalled: INF - ODBC Driver Entry Registry Path: SOFTWARE\ODBC\ODBCINST.INI\SQL Native Client\
12:23:51.415 [5660.5536] <4> ODBCDataSource::isInstalled: INF - Registry entry not found for: SOFTWARE\Microsoft\Microsoft SQL Native Client\
12:23:51.415 [5660.5536] <4> ODBCDataSource::isInstalled: INF - Searching for ODBC Driver: SQL Server
12:23:51.415 [5660.5536] <4> ODBCDataSource::isInstalled: INF - Registry Install Path: SOFTWARE\Microsoft\DataAccess\
12:23:51.415 [5660.5536] <4> ODBCDataSource::isInstalled: INF - ODBC Driver Entry Registry Path: SOFTWARE\ODBC\ODBCINST.INI\SQL Server\
12:23:51.415 [5660.5536] <4> ODBCDataSource::isInstalled: INF - ODBC Driver: SQL Server is installed on the system
12:23:51.416 [5660.5536] <4> ODBCDataSource::isInstalled: INF - Searching for ODBC Driver: SQL Server Native Client 10.0
12:23:51.416 [5660.5536] <4> ODBCDataSource::isInstalled: INF - Registry Install Path: SOFTWARE\Microsoft\Microsoft SQL Server Native Client 10.0\
12:23:51.416 [5660.5536] <4> ODBCDataSource::isInstalled: INF - ODBC Driver Entry Registry Path: SOFTWARE\ODBC\ODBCINST.INI\SQL Server Native Client 10.0\
12:23:51.416 [5660.5536] <4> ODBCDataSource::isInstalled: INF - ODBC Driver: SQL Server Native Client 10.0 is installed on the system
12:23:51.416 [5660.5536] <4> ODBCDataSource::isInstalled: INF - Searching for ODBC Driver: SQL Server Native Client 11.0
12:23:51.416 [5660.5536] <4> ODBCDataSource::isInstalled: INF - Registry Install Path: SOFTWARE\Microsoft\Microsoft SQL Server Native Client 11.0\
12:23:51.416 [5660.5536] <4> ODBCDataSource::isInstalled: INF - ODBC Driver Entry Registry Path: SOFTWARE\ODBC\ODBCINST.INI\SQL Server Native Client 11.0\
12:23:51.416 [5660.5536] <4> ODBCDataSource::isInstalled: INF - Registry entry not found for: SOFTWARE\Microsoft\Microsoft SQL Server Native Client 11.0\
12:23:51.417 [5660.5536] <4> getServerName: Read server name from nb_master_config: pdc-symmaster-01.ecobank.group
12:23:51.417 [5660.5536] <4> CDBIniParms::CDBIniParms: INF - NT User is kigiri
12:23:51.471 [5660.5536] <4> CGlobalInformation::CreateDSN: INF - Using ODBC Driver <SQL Server>
12:23:51.498 [5660.5536] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_5660_5536_1>, SQL userid <ECOBANKGROUP\kigiri> handle <0x005093e0>.
12:23:51.822 [5660.5536] <4> CGlobalInformation::CreateDSN: INF - A successful connection to SQL Server <EPG-NORBUSLV-01\> has been made using standard security with DSN <NBMSSQL_5660_5536_1>
12:23:51.822 [5660.5536] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x005093e0>
12:23:51.823 [5660.5536] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_5660_5536_1>, SQL userid <ECOBANKGROUP\kigiri> handle <0x005093e0>.
12:23:51.886 [5660.5536] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x005093e0>
12:23:51.887 [5660.5536] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_5660_5536_1>, SQL userid <ECOBANKGROUP\kigiri> handle <0x005093e0>.
12:23:51.943 [5660.5536] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x005093e0>
12:23:51.943 [5660.5536] <4> CDBbackcat::GetVirtualServer: INF - Accessing database instance <EPG-NORBUSLV-01> on server <EPG-NORBUSLV-01>.
12:23:51.954 [5660.5536] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:23:51.955 [5660.5536] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52719 TO 10.2.120.120.1556 fd = 572
12:23:53.650 [5660.3392] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_5660_5536_1>, SQL userid <ECOBANKGROUP\kigiri> handle <0x005099a0>.
12:23:53.730 [5660.3392] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x005099a0>
12:23:53.731 [5660.3392] <4> Dbbackrec::PerformNBOperation: INF - RESTORE STARTED USING
Microsoft SQL Server 2008 R2 (SP2) - 10.50.4042.0 (X64)
Mar 26 2015 21:18:04
Copyright (c) Microsoft Corporation
Enterprise Edition (64-bit) on Windows NT 6.1 <X64> (Build 7601: Service Pack 1) (Hypervisor)
Batch = C:\nbu\scripts\restore_1215.bch, Op# = 1.
12:23:53.752 [5660.3392] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:23:53.754 [5660.3392] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52721 TO 10.2.120.120.1556 fd = 780
12:23:53.990 [5660.3392] <4> InitPipeInfo: INF - Using backup image edc-assetmgmt-01.MSSQL7.EDC-ASSETMGMT-0.db.NorbusMutualFund.~.7.001of002.20151231225150..C
12:23:53.995 [5660.3392] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:23:53.996 [5660.3392] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52722 TO 10.2.120.120.1556 fd = 784
12:23:54.160 [5660.3392] <4> Dbbackrec::CreateSQLcmdSyntax: INF - restore database "NorbusMutualFund_1215" from VIRTUAL_DEVICE='VNBU0-5660-3392-1456143833' with  stats = 10, blocksize = 65536, maxtransfersize = 4194304, buffercount = 2, replace , norecovery, move 'NorbusMutualFund' to 'D:\MSSQL\Data\NorbusMutualFund_1215.mdf', move 'NorbusMutualFund_log' to 'D:\MSSQL\Data\NorbusMutualFund_log_1215.ldf', replace
12:23:54.212 [5660.3392] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:23:54.214 [5660.3392] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52723 TO 10.2.120.120.1556 fd = 804
12:23:54.222 [5660.5436] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:23:54.224 [5660.5436] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52724 TO 10.2.120.120.1556 fd = 832
12:23:54.358 [5660.3392] <4> Dbbackrec::CreateSQLcmdSyntax: INF - Number of stripes: 1, Number of buffers per stripe 2.
12:23:54.369 [5660.3392] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:23:54.370 [5660.3392] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52725 TO 10.2.120.120.1556 fd = 804
12:23:54.580 [5660.3392] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_5660_5536_1>, SQL userid <ECOBANKGROUP\kigiri> handle <0x0050ac30>.
12:23:54.669 [5660.3392] <4> CDBbackrec::InitDeviceSet(): INF - Created VDI object for SQL Server instance <EPG-NORBUSLV-01>. Connection timeout is <300> seconds.
12:23:54.684 [5660.3392] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:23:54.685 [5660.3392] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52727 TO 10.2.120.120.1556 fd = 936
12:23:54.800 [5660.5436] <4> DBthreads::dbclient: INF - wait for addr assigned 1
12:23:54.805 [5660.5436] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:23:54.807 [5660.5436] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52728 TO 10.2.120.120.1556 fd = 944
12:23:55.306 [5660.5436] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:23:55.308 [5660.5436] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52729 TO 10.2.120.120.1556 fd = 944
12:23:55.499 [5660.5436] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:23:55.500 [5660.5436] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52730 TO 10.2.120.120.1556 fd = 944
12:23:56.069 [5660.5436] <4> DBthreads::dbclient: INF - Alternate buffer restore rejected because backup did not use alternate method.
12:23:56.074 [5660.5436] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:23:56.074 [5660.5436] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52731 TO 10.2.120.120.1556 fd = 952
12:26:24.116 [5660.5436] <4> DBthreads::dbclient: INF - DBClient has opened for stripe <0>
12:26:34.098 [5660.3392] <4> CODBCaccess::LogODBCerr: INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]10 percent processed.>.
12:26:34.106 [5660.3392] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:26:34.108 [5660.3392] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52788 TO 10.2.120.120.1556 fd = 956
12:26:34.188 [5660.3392] <4> CODBCaccess::LogODBCerr: INF - SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]20 percent processed.>
12:26:34.215 [5660.3392] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:26:34.217 [5660.3392] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52789 TO 10.2.120.120.1556 fd = 976
12:26:40.885 [5660.3392] <4> CODBCaccess::LogODBCerr: INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]30 percent processed.>.
12:26:40.907 [5660.3392] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:26:40.909 [5660.3392] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52790 TO 10.2.120.120.1556 fd = 976
12:26:46.694 [5660.2556] <4> WriteToVirtualDevice: INF - Loading image <edc-assetmgmt-01.MSSQL7.EDC-ASSETMGMT-0.db.NorbusMutualFund.~.7.002of002.20151231225150..C> on stripe <0>
12:26:48.189 [5660.3392] <4> CODBCaccess::LogODBCerr: INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]40 percent processed.>.
12:26:48.192 [5660.3392] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:26:48.193 [5660.3392] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52791 TO 10.2.120.120.1556 fd = 976
12:26:48.405 [5660.3392] <4> CODBCaccess::LogODBCerr: INF - SQL Message <3251><[Microsoft][ODBC SQL Server Driver][SQL Server]The media family on device 'VNBU0-5660-3392-1456143833' is complete. The device is now being reused for one of the remaining families.>
12:26:48.408 [5660.3392] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:26:48.409 [5660.3392] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52792 TO 10.2.120.120.1556 fd = 976
12:33:07.246 [5936.5780] <16> readCommFile: ERR - timed out after 900 seconds while reading from C:\Program Files\Veritas\NetBackup\Logs\user_ops\dbext\logs\5780.0.1456143173
12:33:07.248 [5936.5780] <8> serverExitStatus: timeout reading from comm file, sending keepalive to see if bpbrm is still active
12:33:07.249 [5936.5780] <16> writeToServer: ERR - send() to server on socket failed:
12:33:07.249 [5936.5780] <16> serverExitStatus: ERR - sending keep alive to bpbrm failed
12:33:07.250 [5936.5780] <4> close_image: INF - restore FAILED
12:33:07.250 [5936.5780] <4> close_image: INF ---- end of Restore ---

12:33:07.250 [5936.5780] <16> VxBSAEndData: ERR - EndData unable to successfully close object
12:33:07.250 [5936.5780] <4> getServerName: Read server name from nb_master_config: pdc-symmaster-01.ecobank.group
12:33:07.257 [5936.5780] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:33:07.258 [5936.5780] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52835 TO 10.2.120.120.1556 fd = 1000
12:33:07.276 [5936.5220] <16> readCommFile: ERR - timed out after 900 seconds while reading from C:\Program Files\Veritas\NetBackup\Logs\user_ops\mssql\logs\0222116121249-5936-1852-000-000-prg
12:33:07.276 [5936.5220] <8> serverExitStatus: timeout reading from comm file, sending keepalive to see if bpbrm is still active
12:33:07.276 [5936.5220] <16> writeToServer: ERR - send() to server on socket failed:
12:33:07.276 [5936.5220] <16> serverExitStatus: ERR - sending keep alive to bpbrm failed
12:33:07.276 [5936.5220] <4> close_image: INF - restore FAILED
12:33:07.276 [5936.5220] <4> close_image: INF ---- end of Restore ---

12:33:07.276 [5936.5220] <16> VxBSAEndData: ERR - EndData unable to successfully close object
12:33:07.277 [5936.5220] <4> getServerName: Read server name from nb_master_config: pdc-symmaster-01.ecobank.group
12:33:07.289 [5936.5220] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:33:07.290 [5936.5220] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52836 TO 10.2.120.120.1556 fd = 1008
12:33:07.834 [5936.5780] <4> getServerName: Read server name from nb_master_config: pdc-symmaster-01.ecobank.group
12:33:07.837 [5936.5220] <4> getServerName: Read server name from nb_master_config: pdc-symmaster-01.ecobank.group
12:33:07.851 [5936.5780] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:33:07.852 [5936.5780] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52837 TO 10.2.120.120.1556 fd = 1000
12:33:07.862 [5936.5220] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:33:07.863 [5936.5220] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52838 TO 10.2.120.120.1556 fd = 1008
12:33:08.723 [5936.5780] <16> DBthreads::dbclient: ERR - Error in VxBSAEndData: 3.
12:33:08.737 [5936.5780] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:33:08.738 [5936.5780] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52846 TO 10.2.120.120.1556 fd = 500
12:33:08.935 [5936.5220] <16> DBthreads::dbclient: ERR - Error in VxBSAEndData: 3.
12:33:08.949 [5936.5220] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:33:08.950 [5936.5220] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52848 TO 10.2.120.120.1556 fd = 996
12:33:09.060 [5936.5780] <1> DBthreads::dbclient:     CONTINUATION: - System detected error, operation aborted.
12:33:09.060 [5936.5220] <1> DBthreads::dbclient:     CONTINUATION: - System detected error, operation aborted.
12:33:09.064 [5936.5780] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:33:09.064 [5936.5780] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52849 TO 10.2.120.120.1556 fd = 996
12:33:09.067 [5936.5220] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:33:09.067 [5936.5220] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52850 TO 10.2.120.120.1556 fd = 500
12:33:09.309 [5936.5220] <8> close_image: Session being terminated abnormally, cleaning up
12:33:09.310 [5936.5220] <4> close_image: INF - restore FAILED
12:33:09.310 [5936.5220] <4> close_image: INF ---- end of Restore ---

12:33:09.313 [5936.5004] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x002db1f0>
12:33:09.316 [5936.5004] <4> Dbbackrec::Perform: INF - OPERATION #1 of batch C:\nbu\scripts\restore_21022016.bch FAILED with STATUS 1 (0 is normal). Elapsed time = 1220(1220) seconds.
12:33:09.323 [5936.5004] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:33:09.326 [5936.5004] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52851 TO 10.2.120.120.1556 fd = 1028
12:33:11.496 [5936.1852] <4> CDBbackmain::dbbackup: INF - Results of executing <C:\nbu\scripts\restore_21022016.bch>:
<0> operations succeeded. <1> operations failed.
12:33:11.499 [5936.1852] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:33:11.500 [5936.1852] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52852 TO 10.2.120.120.1556 fd = 612
12:33:11.698 [5936.1852] <4> CGlobalInformation::DeleteDSN: INF - Using ODBC Driver <SQL Server>
12:35:57.158 [5744.4896] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:35:57.159 [5744.4896] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52869 TO 10.2.120.120.1556 fd = 484
12:35:57.169 [5744.4896] <4> CGlobalInformation::VCSVirtualNameList: INF - Veritas Cluster Server is not installed.
12:35:57.170 [5744.4896] <1> CGlobalInformation::VCSVirtualNameList:     CONTINUATION: - The system cannot find the path specified.
12:35:57.170 [5744.4896] <4> ODBCDataSource::isInstalled: INF - Searching for ODBC Driver: SQL Native Client
12:35:57.170 [5744.4896] <4> ODBCDataSource::isInstalled: INF - Registry Install Path: SOFTWARE\Microsoft\Microsoft SQL Native Client\
12:35:57.170 [5744.4896] <4> ODBCDataSource::isInstalled: INF - ODBC Driver Entry Registry Path: SOFTWARE\ODBC\ODBCINST.INI\SQL Native Client\
12:35:57.170 [5744.4896] <4> ODBCDataSource::isInstalled: INF - Registry entry not found for: SOFTWARE\Microsoft\Microsoft SQL Native Client\
12:35:57.170 [5744.4896] <4> ODBCDataSource::isInstalled: INF - Searching for ODBC Driver: SQL Server
12:35:57.171 [5744.4896] <4> ODBCDataSource::isInstalled: INF - Registry Install Path: SOFTWARE\Microsoft\DataAccess\
12:35:57.171 [5744.4896] <4> ODBCDataSource::isInstalled: INF - ODBC Driver Entry Registry Path: SOFTWARE\ODBC\ODBCINST.INI\SQL Server\
12:35:57.171 [5744.4896] <4> ODBCDataSource::isInstalled: INF - ODBC Driver: SQL Server is installed on the system
12:35:57.171 [5744.4896] <4> ODBCDataSource::isInstalled: INF - Searching for ODBC Driver: SQL Server Native Client 10.0
12:35:57.171 [5744.4896] <4> ODBCDataSource::isInstalled: INF - Registry Install Path: SOFTWARE\Microsoft\Microsoft SQL Server Native Client 10.0\
12:35:57.171 [5744.4896] <4> ODBCDataSource::isInstalled: INF - ODBC Driver Entry Registry Path: SOFTWARE\ODBC\ODBCINST.INI\SQL Server Native Client 10.0\
12:35:57.171 [5744.4896] <4> ODBCDataSource::isInstalled: INF - ODBC Driver: SQL Server Native Client 10.0 is installed on the system
12:35:57.171 [5744.4896] <4> ODBCDataSource::isInstalled: INF - Searching for ODBC Driver: SQL Server Native Client 11.0
12:35:57.171 [5744.4896] <4> ODBCDataSource::isInstalled: INF - Registry Install Path: SOFTWARE\Microsoft\Microsoft SQL Server Native Client 11.0\
12:35:57.171 [5744.4896] <4> ODBCDataSource::isInstalled: INF - ODBC Driver Entry Registry Path: SOFTWARE\ODBC\ODBCINST.INI\SQL Server Native Client 11.0\
12:35:57.171 [5744.4896] <4> ODBCDataSource::isInstalled: INF - Registry entry not found for: SOFTWARE\Microsoft\Microsoft SQL Server Native Client 11.0\
12:35:57.173 [5744.4896] <4> getServerName: Read server name from nb_master_config: pdc-symmaster-01.ecobank.group
12:35:57.173 [5744.4896] <4> CDBIniParms::CDBIniParms: INF - NT User is kigiri
12:35:57.239 [5744.4896] <4> CGlobalInformation::CreateDSN: INF - Using ODBC Driver <SQL Server>
12:35:57.277 [5744.4896] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_5744_4896_1>, SQL userid <ECOBANKGROUP\kigiri> handle <0x003f93e0>.
12:35:57.556 [5744.4896] <4> CGlobalInformation::CreateDSN: INF - A successful connection to SQL Server <EPG-NORBUSLV-01\> has been made using standard security with DSN <NBMSSQL_5744_4896_1>
12:35:57.556 [5744.4896] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x003f93e0>
12:35:57.557 [5744.4896] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_5744_4896_1>, SQL userid <ECOBANKGROUP\kigiri> handle <0x003f93e0>.
12:35:57.632 [5744.4896] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x003f93e0>
12:35:57.633 [5744.4896] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_5744_4896_1>, SQL userid <ECOBANKGROUP\kigiri> handle <0x003f93e0>.
12:35:57.687 [5744.4896] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x003f93e0>
12:35:57.687 [5744.4896] <4> CDBbackcat::GetVirtualServer: INF - Accessing database instance <EPG-NORBUSLV-01> on server <EPG-NORBUSLV-01>.
12:35:57.709 [5744.4896] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:35:57.710 [5744.4896] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52873 TO 10.2.120.120.1556 fd = 572
12:35:59.087 [5744.4044] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_5744_4896_1>, SQL userid <ECOBANKGROUP\kigiri> handle <0x003f99a0>.
12:35:59.154 [5744.4044] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x003f99a0>
12:35:59.155 [5744.4044] <4> Dbbackrec::PerformNBOperation: INF - RESTORE STARTED USING
Microsoft SQL Server 2008 R2 (SP2) - 10.50.4042.0 (X64)
Mar 26 2015 21:18:04
Copyright (c) Microsoft Corporation
Enterprise Edition (64-bit) on Windows NT 6.1 <X64> (Build 7601: Service Pack 1) (Hypervisor)
Batch = C:\nbu\scripts\restore_0615.bch, Op# = 1.
12:35:59.174 [5744.4044] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:35:59.175 [5744.4044] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52875 TO 10.2.120.120.1556 fd = 776
12:35:59.439 [5744.4044] <4> InitPipeInfo: INF - Using backup image edc-assetmgmt-01.MSSQL7.EDC-ASSETMGMT-0.db.NorbusMutualFund.~.7.001of002.20150731224950..C
12:35:59.443 [5744.4044] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:35:59.445 [5744.4044] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52876 TO 10.2.120.120.1556 fd = 776
12:35:59.594 [5744.4044] <4> Dbbackrec::CreateSQLcmdSyntax: INF - restore database "NorbusMutualFund_0615" from VIRTUAL_DEVICE='VNBU0-5744-4044-1456144559' with  stats = 10, blocksize = 65536, maxtransfersize = 4194304, buffercount = 2, replace , norecovery, move 'NorbusMutualFund' to 'D:\MSSQL\Data\NorbusMutualFund_0615.mdf', move 'NorbusMutualFund_log' to 'D:\MSSQL\Log\NorbusMutualFund_log_0615.ldf', replace
12:35:59.599 [5744.4044] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:35:59.600 [5744.4044] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52877 TO 10.2.120.120.1556 fd = 800
12:35:59.607 [5744.5196] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:35:59.608 [5744.5196] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52878 TO 10.2.120.120.1556 fd = 824
12:35:59.794 [5744.4044] <4> Dbbackrec::CreateSQLcmdSyntax: INF - Number of stripes: 1, Number of buffers per stripe 2.
12:35:59.799 [5744.4044] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:35:59.800 [5744.4044] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52879 TO 10.2.120.120.1556 fd = 800
12:35:59.994 [5744.4044] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_5744_4896_1>, SQL userid <ECOBANKGROUP\kigiri> handle <0x003fac30>.
12:36:00.070 [5744.4044] <4> CDBbackrec::InitDeviceSet(): INF - Created VDI object for SQL Server instance <EPG-NORBUSLV-01>. Connection timeout is <300> seconds.
12:36:00.073 [5744.4044] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:36:00.075 [5744.4044] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52881 TO 10.2.120.120.1556 fd = 928
12:36:00.231 [5744.5196] <4> DBthreads::dbclient: INF - wait for addr assigned 1
12:36:00.240 [5744.5196] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:36:00.241 [5744.5196] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52882 TO 10.2.120.120.1556 fd = 936
12:36:00.709 [5744.5196] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:36:00.710 [5744.5196] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52883 TO 10.2.120.120.1556 fd = 936
12:36:00.847 [5744.5196] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:36:00.848 [5744.5196] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52884 TO 10.2.120.120.1556 fd = 940
12:36:01.424 [5744.5196] <4> DBthreads::dbclient: INF - Alternate buffer restore rejected because backup did not use alternate method.
12:36:01.428 [5744.5196] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:36:01.428 [5744.5196] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52885 TO 10.2.120.120.1556 fd = 948
12:38:39.839 [5744.5196] <4> DBthreads::dbclient: INF - DBClient has opened for stripe <0>
12:38:49.374 [5744.4044] <4> CODBCaccess::LogODBCerr: INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]10 percent processed.>.
12:38:49.396 [5744.4044] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:38:49.397 [5744.4044] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52937 TO 10.2.120.120.1556 fd = 964
12:38:49.457 [5744.4044] <4> CODBCaccess::LogODBCerr: INF - SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]20 percent processed.>
12:38:49.471 [5744.4044] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:38:49.472 [5744.4044] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52938 TO 10.2.120.120.1556 fd = 964
12:38:58.556 [5744.5924] <4> WriteToVirtualDevice: INF - Loading image <edc-assetmgmt-01.MSSQL7.EDC-ASSETMGMT-0.db.NorbusMutualFund.~.7.002of002.20150731224950..C> on stripe <0>
12:39:01.160 [5744.4044] <4> CODBCaccess::LogODBCerr: INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]30 percent processed.>.
12:39:01.164 [5744.4044] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:39:01.165 [5744.4044] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52939 TO 10.2.120.120.1556 fd = 400
12:39:01.296 [5744.4044] <4> CODBCaccess::LogODBCerr: INF - SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]40 percent processed.>
12:39:01.299 [5744.4044] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:39:01.300 [5744.4044] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52940 TO 10.2.120.120.1556 fd = 400
12:39:01.494 [5744.4044] <4> CODBCaccess::LogODBCerr: INF - SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]50 percent processed.>
12:39:01.498 [5744.4044] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:39:01.498 [5744.4044] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52941 TO 10.2.120.120.1556 fd = 400
12:39:01.689 [5744.4044] <4> CODBCaccess::LogODBCerr: INF - SQL Message <3251><[Microsoft][ODBC SQL Server Driver][SQL Server]The media family on device 'VNBU0-5744-4044-1456144559' is complete. The device is now being reused for one of the remaining families.>
12:39:01.696 [5744.4044] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:39:01.697 [5744.4044] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52942 TO 10.2.120.120.1556 fd = 400
12:41:57.877 [5660.5436] <16> readCommFile: ERR - timed out after 900 seconds while reading from C:\Program Files\Veritas\NetBackup\Logs\user_ops\mssql\logs\0222116122351-5660-5536-000-000-prg
12:41:57.877 [5660.5436] <8> serverExitStatus: timeout reading from comm file, sending keepalive to see if bpbrm is still active
12:41:57.877 [5660.5436] <16> writeToServer: ERR - send() to server on socket failed:
12:41:57.877 [5660.5436] <16> serverExitStatus: ERR - sending keep alive to bpbrm failed
12:41:57.877 [5660.5436] <4> close_image: INF - restore FAILED
12:41:57.877 [5660.5436] <4> close_image: INF ---- end of Restore ---
 

======================================================================

From SQL Server Error logs it seems the tape became unreadable. Not sure though...

---------------------------------------------------

Date        2/22/2016 12:42:04 PM
Log        SQL Server (Current - 11/28/2015 5:54:00 PM)

Source        Backup

Message
BackupIoRequest::ReportIoError: read failure on backup device 'VNBU0-5660-3392-1456143833'. Operating system error 995(The I/O operation has been aborted because of either a thread exit or an application request.).
 

DBClient

It looks to me like you get a 15 minute timeout hit during the restore.

In the admin console go to the Host Properties - Media Servers section and connect to the master and media servers and in the Timeouts Section put the "client connect", "client read" and "file browse" timeouts up to 9200 and then try it again. Do the same for the client itself under client host properties.

09:49:31.517 [4000.5936] <16> readCommFile: ERR - timed out after 900 seconds while reading from C:\Program Files\Veritas\NetBackup\Logs\user_ops\dbext\logs\5936.0.1456133670

Also note a rights issue can creep in here ... the error above is reporting the Master Server is not reading that log which is on the client itself .. so check the roghts of the logged in user used during the restore along with any service accounts you have in use.

In addition to my previous i also seen other errors indicating that the database cannot be restored to the location requested and that a MOVE is required.... is this the same restore or an earlier attempt?

12:05:21.833 [5588.708] <16> CODBCaccess::LogODBCerr: DBMS MSG - ODBC return code <-1>, SQL State <37000>, SQL Message <1834><[Microsoft][ODBC SQL Server Driver][SQL Server]The file 'D:\MSSQL\Data\NorbusMutualFund.mdf' cannot be overwritten.  It is being used by database 'NorbusMutualFund'.>.
12:05:21.861 [5588.708] <2> vnet_pbxConnect: pbxConnectEx Succeeded
12:05:21.863 [5588.708] <2> logconnections: BPRD CONNECT FROM 10.2.100.44.52490 TO 10.2.120.120.1556 fd = 1052
12:05:22.063 [5588.5596] <32> DBthreads::dbclient: ERR - Bad client VxBSAstatus 1 for pipe #0.
12:05:22.064 [5588.4344] <32> DBthreads::dbclient: ERR - Bad client VxBSAstatus 1 for pipe #1.
12:05:22.070 [5588.708] <16> CODBCaccess::LogODBCerr: DBMS MSG - SQL Message <3156><[Microsoft][ODBC SQL Server Driver][SQL Server]File 'NorbusMutualFund' cannot be restored to 'D:\MSSQL\Data\NorbusMutualFund.mdf'. Use WITH MOVE to identify a valid location for the file.>

Thanks Mark. I will check your last two posts and get back.

I think I should add that I am able to restore backup sitting on MSDP smoothly. This problem is only occuring for taps. Could it be that the tape library is slow?

How long does the restore from MSDP take?

If only a few minutes then yes it could just be the tape causing the slow down ... having said that it is worth having decent timeouts for SQL servers as they dont talk much during restores and can easily drop the connection ... then after 1 hour you can get firewall keepalive ... and after 2 hours you can hit the Windows keepalive ....