cancel
Showing results for 
Search instead for 
Did you mean: 

MSSQL backup jobs fails intermittent with status 6 the last 4-5 weeks

_Johan
Level 3
I have had som issues with MSSQL full backups the last 4-5 weeks, it seems only be a problem on full MSSQL backups and it seems that mostly its the larger databases that fails. If one server (or more) fails, they could work if you try again, or not, its very random it seems. i get the "status: 6: the backup failed to back up the requested files" This has not been a problem before, it started the weekend (first full backup for the large databases) after i upgraded the "primary" media server from 2.5.3 to 2.6.0.3 (the master server and the "secondary" media server was upgraded 2 weeks before) i tried to increase the Client Read Time to 7200, but it does not seems that it solved anything. Netbackup Master server: 7.6.0.3 Netbackup Media servers (5220 appliances): 2.6.0.3 Netbackup clients: 7.6.0.3 MSSQL servers: mix og 2008r2 and 2012 Any suggestions? thanks! /Johan Here is from the Job details from one of the failed jobs and i will also insert the dbclient log at the end: 2014-10-11 17:05:13 - Info nbjm(pid=3948) starting backup job (jobid=199848) for client CLIENTXXX, policy SAP-SQL-Weekly-Medium, schedule Default-Application-Backup 2014-10-11 17:05:13 - Info nbjm(pid=3948) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=199848, request id:{9E8B3EDF-D487-49DD-A7F9-6464CE813A46}) 2014-10-11 17:05:13 - requesting resource stu_disk_MASTERSERVER1 2014-10-11 17:05:13 - requesting resource MASTERXXX.NBU_CLIENT.MAXJOBS.CLIENTXXX 2014-10-11 17:05:13 - requesting resource MASTERXXX.NBU_POLICY.MAXJOBS.SAP-SQL-Weekly-Medium 2014-10-11 17:05:13 - granted resource MASTERXXX.NBU_CLIENT.MAXJOBS.CLIENTXXX 2014-10-11 17:05:13 - granted resource MASTERXXX.NBU_POLICY.MAXJOBS.SAP-SQL-Weekly-Medium 2014-10-11 17:05:13 - granted resource MediaID=@aaaab;DiskVolume=PureDiskVolume;DiskPool=dp_disk_MASTERSERVER1;Path=PureDiskVolume;StorageServer=MASTERSERVER1;MediaServer=MASTERSERVER1 2014-10-11 17:05:13 - granted resource stu_disk_MASTERSERVER1 2014-10-11 17:05:13 - estimated 0 Kbytes needed 2014-10-11 17:05:13 - Info nbjm(pid=3948) started backup (backupid=CLIENTXXX_1413039913) job for client CLIENTXXX, policy SAP-SQL-Weekly-Medium, schedule Default-Application-Backup on storage unit stu_disk_MASTERSERVER1 2014-10-11 17:05:15 - started process bpbrm (2222) 2014-10-11 17:05:15 - connecting 2014-10-11 17:05:18 - connected; connect time: 0:00:03 2014-10-11 17:05:39 - begin writing 2014-10-11 17:15:17 - Info bpbrm(pid=2222) CLIENTXXX is the host to backup data from 2014-10-11 17:15:17 - Info bpbrm(pid=2222) reading file list for client 2014-10-11 17:15:18 - Info bpbrm(pid=2222) listening for client connection 2014-10-11 17:15:19 - Info bpbrm(pid=2222) INF - Client read timeout = 7200 2014-10-11 17:15:20 - Info bpbrm(pid=2222) accepted connection from client 2014-10-11 17:15:20 - Info dbclient(pid=10360) Backup started 2014-10-11 17:15:20 - Info bpbrm(pid=2222) bptm pid: 2244 2014-10-11 17:15:21 - Info bptm(pid=2244) start 2014-10-11 17:15:31 - Info bptm(pid=2244) using 262144 data buffer size 2014-10-11 17:15:32 - Info bptm(pid=2244) using 30 data buffers 2014-10-11 17:15:34 - Info bptm(pid=2244) start backup 2014-10-11 17:15:41 - Info bptm(pid=2244) backup child process is pid 2309 2014-10-11 17:15:42 - Info dbclient(pid=10360) dbclient(pid=10360) wrote first buffer(size=65536) 2014-10-11 17:39:32 - end writing; write time: 0:33:53 2014-10-11 17:49:15 - Info dbclient(pid=10360) done. status: 6 2014-10-11 17:49:15 - Error bptm(pid=2309) system call failed - Connection reset by peer (at child.c.1306) 2014-10-11 17:49:16 - Error bptm(pid=2309) unable to perform read from client socket, connection may have been broken 2014-10-11 17:49:16 - Error bptm(pid=2244) media manager terminated by parent process 2014-10-11 17:49:34 - Info MASTERSERVER1(pid=2244) StorageServer=PureDisk:MASTERSERVER1; Report=PDDO Stats for (MASTERSERVER1): scanned: 138736905 KB, CR sent: 83718 KB, CR sent over FC: 0 KB, dedup: 99.9%, cache hits: 0 (0.0%) 2014-10-11 17:49:34 - Info dbclient(pid=10360) done. status: 6: the backup failed to back up the requested files the backup failed to back up the requested files And here is the dbclient log: 17:04:59.354 [10360.9856] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:04:59.355 [10360.9856] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.62524 TO YYY.YY.YYY.YY.1556 fd = 440 17:04:59.607 [10360.9856] <4> CGlobalInformation::VCSVirtualNameList: INF - Veritas Cluster Server is not installed. 17:04:59.607 [10360.9856] <1> CGlobalInformation::VCSVirtualNameList: CONTINUATION: - The system cannot find the path specified. 17:04:59.607 [10360.9856] <4> ODBCDataSource::isInstalled: INF - Searching for ODBC Driver: SQL Native Client 17:04:59.607 [10360.9856] <4> ODBCDataSource::isInstalled: INF - Registry Install Path: SOFTWARE\Microsoft\Microsoft SQL Native Client\ 17:04:59.607 [10360.9856] <4> ODBCDataSource::isInstalled: INF - ODBC Driver Entry Registry Path: SOFTWARE\ODBC\ODBCINST.INI\SQL Native Client\ 17:04:59.607 [10360.9856] <4> ODBCDataSource::isInstalled: INF - Registry entry not found for: SOFTWARE\Microsoft\Microsoft SQL Native Client\ 17:04:59.607 [10360.9856] <4> ODBCDataSource::isInstalled: INF - Searching for ODBC Driver: SQL Server 17:04:59.607 [10360.9856] <4> ODBCDataSource::isInstalled: INF - Registry Install Path: SOFTWARE\Microsoft\DataAccess\ 17:04:59.608 [10360.9856] <4> ODBCDataSource::isInstalled: INF - ODBC Driver Entry Registry Path: SOFTWARE\ODBC\ODBCINST.INI\SQL Server\ 17:04:59.608 [10360.9856] <4> ODBCDataSource::isInstalled: INF - ODBC Driver: SQL Server is installed on the system 17:04:59.608 [10360.9856] <4> ODBCDataSource::isInstalled: INF - Searching for ODBC Driver: SQL Server Native Client 10.0 17:04:59.608 [10360.9856] <4> ODBCDataSource::isInstalled: INF - Registry Install Path: SOFTWARE\Microsoft\Microsoft SQL Server Native Client 10.0\ 17:04:59.608 [10360.9856] <4> ODBCDataSource::isInstalled: INF - ODBC Driver Entry Registry Path: SOFTWARE\ODBC\ODBCINST.INI\SQL Server Native Client 10.0\ 17:04:59.608 [10360.9856] <4> ODBCDataSource::isInstalled: INF - ODBC Driver: SQL Server Native Client 10.0 is installed on the system 17:04:59.608 [10360.9856] <4> ODBCDataSource::isInstalled: INF - Searching for ODBC Driver: SQL Server Native Client 11.0 17:04:59.608 [10360.9856] <4> ODBCDataSource::isInstalled: INF - Registry Install Path: SOFTWARE\Microsoft\Microsoft SQL Server Native Client 11.0\ 17:04:59.608 [10360.9856] <4> ODBCDataSource::isInstalled: INF - ODBC Driver Entry Registry Path: SOFTWARE\ODBC\ODBCINST.INI\SQL Server Native Client 11.0\ 17:04:59.608 [10360.9856] <4> ODBCDataSource::isInstalled: INF - Registry entry not found for: SOFTWARE\Microsoft\Microsoft SQL Server Native Client 11.0\ 17:04:59.609 [10360.9856] <4> getServerName: Read server name from nb_master_config: MASTERXXX 17:04:59.610 [10360.9856] <4> CDBIniParms::CDBIniParms: INF - NT User is NBU-ACCOUNT 17:04:59.645 [10360.9856] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:04:59.646 [10360.9856] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.62525 TO YYY.YY.YYY.YY.1556 fd = 480 17:04:59.907 [10360.9856] <4> CGlobalInformation::CreateDSN: INF - Using ODBC Driver 17:04:59.921 [10360.9856] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cd9240>. 17:05:00.057 [10360.9856] <4> CGlobalInformation::CreateDSN: INF - A successful connection to SQL Server has been made using standard security with DSN 17:05:00.057 [10360.9856] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cd9240> 17:05:00.058 [10360.9856] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cd9240>. 17:05:00.094 [10360.9856] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cd9240> 17:05:00.095 [10360.9856] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cd9240>. 17:05:00.138 [10360.9856] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cd9240> 17:05:00.140 [10360.9856] <4> CDBbackcat::GetVirtualServer: INF - Accessing database instance on server . 17:05:00.145 [10360.9856] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:05:00.145 [10360.9856] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.62529 TO YYY.YY.YYY.YY.1556 fd = 484 17:05:00.769 [10360.9856] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:05:00.770 [10360.9856] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.62530 TO YYY.YY.YYY.YY.1556 fd = 484 17:05:01.013 [10360.9856] <4> CDBbackmain::OperationsAreGroupable: INF - The batch file is not groupable because a standard policy type has been selected for backup. 17:05:01.016 [10360.9856] <4> CGlobalInformation::CreateDSN: INF - Using ODBC Driver 17:05:01.032 [10360.9856] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cd9240>. 17:05:01.051 [10360.9856] <4> CGlobalInformation::CreateDSN: INF - A successful connection to SQL Server has been made using standard security with DSN 17:05:01.051 [10360.9856] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cd9240> 17:05:01.051 [10360.9856] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cd9240>. 17:05:01.081 [10360.9856] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cd9240> 17:05:01.082 [10360.9856] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cd9240>. 17:05:01.115 [10360.9856] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cd9240> 17:05:01.116 [10360.9856] <4> CDBbackcat::GetVirtualServer: INF - Accessing database instance on server . 17:05:01.120 [10360.9856] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:05:01.120 [10360.9856] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.62534 TO YYY.YY.YYY.YY.1556 fd = 688 17:05:01.372 [10360.9856] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:05:01.373 [10360.9856] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.62537 TO YYY.YY.YYY.YY.1556 fd = 576 17:05:01.658 [10360.9856] <4> CDBbackrec::CDBbackrec: INF - Use standard backup method with policy . 17:05:02.760 [10360.8612] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cd9520>. 17:05:02.789 [10360.8612] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cd9520> 17:05:02.789 [10360.8612] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cd9520>. 17:05:02.819 [10360.8612] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cd9520> 17:05:02.820 [10360.8612] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cd9520>. 17:05:02.848 [10360.8612] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cd9520> 17:05:02.849 [10360.8612] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cd9520>. 17:05:02.886 [10360.8612] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cd9520> 17:05:02.887 [10360.8612] <4> Dbbackrec::PerformNBOperation: INF - BACKUP STARTED USING Microsoft SQL Server 2008 (SP1) - 10.0.2531.0 (X64) Mar 29 2009 10:11:52 Copyright (c) 1988-2008 Microsoft Corporation Enterprise Edition (64-bit) on Windows NT 6.0 (Build 6002: Service Pack 2) (VM) Batch = C:\Program Files\Veritas\NetBackup\DbExt\MsSql\MSSQLSCRIPT_Full.bch, Op# = 1 17:05:02.905 [10360.8612] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:05:02.905 [10360.8612] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.62542 TO YYY.YY.YYY.YY.1556 fd = 720 17:05:03.021 [10360.8612] <4> InitPipeInfo: INF - Using backup image CLIENTXXX.MSSQL7.CLIENTXXX.db.DB2.~.7.001of001.20141011170501..C 17:05:03.025 [10360.8612] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:05:03.027 [10360.8612] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.62543 TO YYY.YY.YYY.YY.1556 fd = 720 17:05:03.103 [10360.8612] <4> Dbbackrec::CreateSQLcmdSyntax: INF - backup database "DB2" to VIRTUAL_DEVICE='VNBU0-10360-8612-1413039903' with stats = 10, blocksize = 65536, maxtransfersize = 4194304, buffercount = 2 17:05:03.107 [10360.8612] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:05:03.108 [10360.8612] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.62544 TO YYY.YY.YYY.YY.1556 fd = 728 17:05:03.114 [10360.11880] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:05:03.114 [10360.11880] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.62545 TO YYY.YY.YYY.YY.1556 fd = 776 17:05:03.253 [10360.8612] <4> Dbbackrec::CreateSQLcmdSyntax: INF - Number of stripes: 1, Number of buffers per stripe 2. 17:05:03.422 [10360.8612] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:05:03.423 [10360.8612] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.62547 TO YYY.YY.YYY.YY.1556 fd = 776 17:05:03.473 [10360.8612] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cd9800>. 17:05:03.506 [10360.8612] <4> CDBbackrec::InitDeviceSet(): INF - Created VDI object for SQL Server instance . Connection timeout is <300> seconds. 17:05:03.509 [10360.8612] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:05:03.510 [10360.8612] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.62549 TO YYY.YY.YYY.YY.1556 fd = 864 17:05:03.650 [10360.11880] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:05:03.651 [10360.11880] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.62550 TO YYY.YY.YYY.YY.1556 fd = 876 17:05:18.731 [10360.11880] <4> serverResponse: Not a candidate for alternate buffer method: shared memory is not in use. 17:11:07.165 [10360.8612] <4> CODBCaccess::LogODBCerr: INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]10 percent processed.>. 17:11:07.172 [10360.8612] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:11:07.173 [10360.8612] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.62725 TO YYY.YY.YYY.YY.1556 fd = 876 17:16:43.781 [10360.8612] <4> CODBCaccess::LogODBCerr: INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]20 percent processed.>. 17:16:43.786 [10360.8612] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:16:43.787 [10360.8612] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.62884 TO YYY.YY.YYY.YY.1556 fd = 892 17:21:55.378 [10360.8612] <4> CODBCaccess::LogODBCerr: INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]30 percent processed.>. 17:21:55.384 [10360.8612] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:21:55.385 [10360.8612] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63019 TO YYY.YY.YYY.YY.1556 fd = 876 17:26:26.972 [10360.8612] <4> CODBCaccess::LogODBCerr: INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]40 percent processed.>. 17:26:26.987 [10360.8612] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:26:26.989 [10360.8612] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63136 TO YYY.YY.YYY.YY.1556 fd = 876 17:30:43.576 [10360.8612] <4> CODBCaccess::LogODBCerr: INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]50 percent processed.>. 17:30:43.581 [10360.8612] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:30:43.583 [10360.8612] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63246 TO YYY.YY.YYY.YY.1556 fd = 876 17:34:25.134 [10360.8612] <4> CODBCaccess::LogODBCerr: INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]60 percent processed.>. 17:34:25.148 [10360.8612] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:34:25.150 [10360.8612] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63351 TO YYY.YY.YYY.YY.1556 fd = 876 17:38:11.739 [10360.8612] <4> CODBCaccess::LogODBCerr: INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]70 percent processed.>. 17:38:11.755 [10360.8612] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:38:11.758 [10360.8612] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63449 TO YYY.YY.YYY.YY.1556 fd = 876 17:39:13.480 [10360.11880] <16> writeToServer: ERR - send() to server on socket failed: 17:39:13.480 [10360.11880] <16> dbc_put: ERR - failed sending data to server 17:39:13.623 [10360.11880] <16> VxBSASendData: ERR - Could not do a bsa_put(). 17:39:13.648 [10360.11880] <4> getServerName: Read server name from nb_master_config: MASTERXXX 17:39:13.662 [10360.11880] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:39:13.663 [10360.11880] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63474 TO YYY.YY.YYY.YY.1556 fd = 872 17:39:13.826 [10360.11880] <4> getServerName: Read server name from nb_master_config: MASTERXXX 17:39:13.829 [10360.11880] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:39:13.830 [10360.11880] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63476 TO YYY.YY.YYY.YY.1556 fd = 872 17:39:16.224 [10360.11880] <16> DBthreads::dbclient: ERR - Error in VxBSASendData: 1. 17:39:16.229 [10360.11880] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:39:16.229 [10360.11880] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63481 TO YYY.YY.YYY.YY.1556 fd = 884 17:39:16.302 [10360.11880] <1> DBthreads::dbclient: CONTINUATION: - All backup jobs have completed. 17:39:16.316 [10360.11880] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:39:16.316 [10360.11880] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63482 TO YYY.YY.YYY.YY.1556 fd = 884 17:39:16.395 [10360.11880] <8> close_image: Session being terminated abnormally, cleaning up 17:39:16.395 [10360.11880] <4> close_image: INF - backup FAILED 17:39:16.395 [10360.11880] <4> close_image: INF ---- end of Backup --- 17:39:16.395 [10360.11880] <4> KillAllThreads: INF - Killing group #0 17:39:16.395 [10360.11880] <4> KillAllThreads: INF - Issuing SignalAbort to MS SQL Server VDI 17:39:16.395 [10360.11388] <4> KillAllThreads: INF - Killing group #0 17:39:16.395 [10360.10252] <4> KillAllThreads: INF - Killing group #0 17:39:16.397 [10360.11880] <16> CDBbackrec::ClientStatus: ERR - Internal error. See the dbclient log for more information. 17:39:16.401 [10360.11880] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:39:16.401 [10360.11880] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63485 TO YYY.YY.YYY.YY.1556 fd = 748 17:39:16.472 [10360.11880] <32> CDBbackrec::ClientStatus: ERR - Failed to get the client status because no BSA transaction is active. 17:39:16.473 [10360.11880] <16> CDBbackrec::ProcessVxBSAerror: ERR - Error in DBthreads::dbclient: 6. 17:39:16.487 [10360.11880] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:39:16.488 [10360.11880] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63486 TO YYY.YY.YYY.YY.1556 fd = 752 17:39:16.558 [10360.11880] <1> CDBbackrec::ProcessVxBSAerror: CONTINUATION: - The system cannot find the file specified. 17:39:16.562 [10360.11880] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:39:16.563 [10360.11880] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63487 TO YYY.YY.YYY.YY.1556 fd = 752 17:39:16.635 [10360.11880] <16> DBthreads::dbclient: ERR - Error in VxBSAEndData: 6. 17:39:16.639 [10360.11880] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:39:16.640 [10360.11880] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63488 TO YYY.YY.YYY.YY.1556 fd = 752 17:39:16.727 [10360.11880] <1> DBthreads::dbclient: CONTINUATION: - The handle used to associate this call with a previous VxBSAInit() call is invalid. 17:39:16.732 [10360.11880] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:39:16.733 [10360.11880] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63489 TO YYY.YY.YYY.YY.1556 fd = 748 17:39:19.398 [10360.8612] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cd9800> 17:39:19.398 [10360.8612] <4> getServerName: Read server name from nb_master_config: MASTERXXX 17:39:19.401 [10360.8612] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:39:19.402 [10360.8612] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63490 TO YYY.YY.YYY.YY.1556 fd = 760 17:39:21.518 [10360.8612] <4> Dbbackrec::Perform: INF - OPERATION #1 of batch C:\Program Files\Veritas\NetBackup\DbExt\MsSql\MSSQLSCRIPT_Full.bch FAILED with STATUS 1 (0 is normal). Elapsed time = 2060(2060) seconds. 17:39:21.533 [10360.8612] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:39:21.534 [10360.8612] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63493 TO YYY.YY.YYY.YY.1556 fd = 760 17:39:23.606 [10360.9856] <4> CGlobalInformation::CreateDSN: INF - Using ODBC Driver 17:39:23.631 [10360.9856] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cdfe70>. 17:39:23.667 [10360.9856] <4> CGlobalInformation::CreateDSN: INF - A successful connection to SQL Server has been made using standard security with DSN 17:39:23.667 [10360.9856] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cdfe70> 17:39:23.668 [10360.9856] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cdfe70>. 17:39:23.703 [10360.9856] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cdfe70> 17:39:23.703 [10360.9856] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cdfe70>. 17:39:23.738 [10360.9856] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cdfe70> 17:39:23.739 [10360.9856] <4> CDBbackcat::GetVirtualServer: INF - Accessing database instance on server . 17:39:23.754 [10360.9856] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:39:23.755 [10360.9856] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63497 TO YYY.YY.YYY.YY.1556 fd = 696 17:39:24.022 [10360.9856] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:39:24.023 [10360.9856] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63499 TO YYY.YY.YYY.YY.1556 fd = 696 17:39:24.297 [10360.9856] <4> CDBbackrec::CDBbackrec: INF - Use standard backup method with policy . 17:39:25.398 [10360.10868] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cdfe70>. 17:39:25.432 [10360.10868] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cdfe70> 17:39:25.433 [10360.10868] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cdfe70>. 17:39:25.467 [10360.10868] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cdfe70> 17:39:25.467 [10360.10868] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cdfe70>. 17:39:25.498 [10360.10868] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cdfe70> 17:39:25.499 [10360.10868] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cdfe70>. 17:39:25.531 [10360.10868] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cdfe70> 17:39:25.532 [10360.10868] <4> Dbbackrec::PerformNBOperation: INF - BACKUP STARTED USING Microsoft SQL Server 2008 (SP1) - 10.0.2531.0 (X64) Mar 29 2009 10:11:52 Copyright (c) 1988-2008 Microsoft Corporation Enterprise Edition (64-bit) on Windows NT 6.0 (Build 6002: Service Pack 2) (VM) Batch = C:\Program Files\Veritas\NetBackup\DbExt\MsSql\MSSQLSCRIPT_Full.bch, Op# = 2 17:39:25.549 [10360.10868] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:39:25.550 [10360.10868] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63504 TO YYY.YY.YYY.YY.1556 fd = 692 17:39:25.602 [10360.10868] <4> InitPipeInfo: INF - Using backup image CLIENTXXX.MSSQL7.CLIENTXXX.db.DB1.~.7.001of001.20141011173924..C 17:39:25.616 [10360.10868] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:39:25.617 [10360.10868] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63505 TO YYY.YY.YYY.YY.1556 fd = 692 17:39:25.695 [10360.10868] <4> Dbbackrec::CreateSQLcmdSyntax: INF - backup database "DB1" to VIRTUAL_DEVICE='VNBU0-10360-10868-1413041965' with stats = 10, blocksize = 65536, maxtransfersize = 4194304, buffercount = 2 17:39:25.700 [10360.10868] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:39:25.700 [10360.10868] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63506 TO YYY.YY.YYY.YY.1556 fd = 756 17:39:25.707 [10360.11352] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:39:25.708 [10360.11352] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63507 TO YYY.YY.YYY.YY.1556 fd = 876 17:39:25.786 [10360.10868] <4> Dbbackrec::CreateSQLcmdSyntax: INF - Number of stripes: 1, Number of buffers per stripe 2. 17:39:25.978 [10360.10868] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:39:25.979 [10360.10868] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63508 TO YYY.YY.YYY.YY.1556 fd = 876 17:39:26.069 [10360.10868] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cdfe70>. 17:39:26.106 [10360.10868] <4> CDBbackrec::InitDeviceSet(): INF - Created VDI object for SQL Server instance . Connection timeout is <300> seconds. 17:39:26.120 [10360.10868] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:39:26.121 [10360.10868] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63510 TO YYY.YY.YYY.YY.1556 fd = 932 17:39:26.205 [10360.11352] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:39:26.206 [10360.11352] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63511 TO YYY.YY.YYY.YY.1556 fd = 948 17:39:38.293 [10360.11352] <4> serverResponse: Not a candidate for alternate buffer method: shared memory is not in use. 17:40:04.672 [10360.10868] <4> CODBCaccess::LogODBCerr: INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]10 percent processed.>. 17:40:04.677 [10360.10868] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:40:04.678 [10360.10868] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63550 TO YYY.YY.YYY.YY.1556 fd = 952 17:40:12.413 [10360.10868] <4> CODBCaccess::LogODBCerr: INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]20 percent processed.>. 17:40:12.417 [10360.10868] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:40:12.418 [10360.10868] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63552 TO YYY.YY.YYY.YY.1556 fd = 952 17:40:12.488 [10360.10868] <4> CODBCaccess::LogODBCerr: INF - SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]30 percent processed.> 17:40:12.492 [10360.10868] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:40:12.493 [10360.10868] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63553 TO YYY.YY.YYY.YY.1556 fd = 952 17:40:12.570 [10360.10868] <4> CODBCaccess::LogODBCerr: INF - SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]40 percent processed.> 17:40:12.584 [10360.10868] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:40:12.585 [10360.10868] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63554 TO YYY.YY.YYY.YY.1556 fd = 948 17:40:12.630 [10360.10868] <4> CODBCaccess::LogODBCerr: INF - SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]50 percent processed.> 17:40:12.643 [10360.10868] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:40:12.644 [10360.10868] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63555 TO YYY.YY.YYY.YY.1556 fd = 948 17:40:12.695 [10360.10868] <4> CODBCaccess::LogODBCerr: INF - SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]60 percent processed.> 17:40:12.699 [10360.10868] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:40:12.700 [10360.10868] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63556 TO YYY.YY.YYY.YY.1556 fd = 948 17:40:19.144 [10360.7884] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cdff20>. 17:40:19.178 [10360.7884] <2> CDBbackcat::GetBackupWaitTimeFromCfg: DBG - Using a backup wait timeout from the BSA environment variable NBBSA_CLIENT_READ_TIMEOUT 17:40:19.178 [10360.7884] <2> CDBbackcat::GetSysBackupTime: DBG - Waiting for SQL Server to update it's backup history for up to 7200 second(s) 17:40:19.216 [10360.10868] <8> CODBCaccess::LogODBCerr: WARN - ODBC return code <1>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]70 percent processed.>. 17:40:19.216 [10360.10868] <8> CODBCaccess::LogODBCerr: WARN - SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]80 percent processed.> 17:40:19.216 [10360.10868] <8> CODBCaccess::LogODBCerr: WARN - SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]90 percent processed.> 17:40:19.216 [10360.10868] <8> CODBCaccess::LogODBCerr: WARN - SQL Message <4035><[Microsoft][ODBC SQL Server Driver][SQL Server]Processed 256576 pages for database 'DB1', file 'DB1DATA1' on file 1.> 17:40:19.216 [10360.10868] <8> CODBCaccess::LogODBCerr: WARN - SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]100 percent processed.> 17:40:19.216 [10360.10868] <8> CODBCaccess::LogODBCerr: WARN - SQL Message <4035><[Microsoft][ODBC SQL Server Driver][SQL Server]Processed 1 pages for database 'DB1', file 'DB1LOG1' on file 1.> 17:40:19.216 [10360.10868] <8> CODBCaccess::LogODBCerr: WARN - SQL Message <3014><[Microsoft][ODBC SQL Server Driver][SQL Server]BACKUP DATABASE successfully processed 256577 pages in 19.211 seconds (104.341 MB/sec).> 17:40:19.221 [10360.7884] <2> CDBbackcat::GetSysBackupTime: DBG - Succeeded in getting the backup timestamps from SQL Server after 0 retry(ies) 17:40:19.221 [10360.7884] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cdff20> 17:40:19.222 [10360.11352] <4> DBthreads::dbclient: INF - Thread has been closed for stripe #0 17:40:19.227 [10360.11352] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:40:19.228 [10360.11352] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63564 TO YYY.YY.YYY.YY.1556 fd = 888 17:40:19.301 [10360.11352] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cdff20>. 17:40:19.338 [10360.11352] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cdff20> 17:40:19.338 [10360.11352] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cdff20>. 17:40:19.374 [10360.11352] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cdff20> 17:40:19.375 [10360.11352] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cdff20>. 17:40:19.406 [10360.11352] <4> DBConnect: INF - Logging into SQL Server with DSN , SQL userid handle <0x00cdb6e0>. 17:40:19.440 [10360.11352] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cdb6e0> 17:40:19.443 [10360.11352] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cdff20> 17:40:23.561 [10360.10868] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x00cdfe70> 17:40:23.564 [10360.10868] <4> Dbbackrec::Perform: INF - OPERATION #2 of batch C:\Program Files\Veritas\NetBackup\DbExt\MsSql\MSSQLSCRIPT_Full.bch SUCCEEDED with STATUS 0 (0 is normal). Elapsed time = 59(20) seconds 17:40:23.579 [10360.10868] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:40:23.580 [10360.10868] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63570 TO YYY.YY.YYY.YY.1556 fd = 908 17:40:25.655 [10360.9856] <4> CDBbackmain::dbbackup: INF - Results of executing <>: <1> operations succeeded. <1> operations failed. 17:40:25.660 [10360.9856] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:40:25.661 [10360.9856] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63575 TO YYY.YY.YYY.YY.1556 fd = 576 17:40:25.745 [10360.9856] <4> CDBbackmain::dbbackup: INF - The following object(s) were not backed up successfully. 17:40:25.750 [10360.9856] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:40:25.751 [10360.9856] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63576 TO YYY.YY.YYY.YY.1556 fd = 576 17:40:25.825 [10360.9856] <4> CDBbackmain::dbbackup: INF - DB2 17:40:25.829 [10360.9856] <2> vnet_pbxConnect: pbxConnectEx Succeeded 17:40:25.830 [10360.9856] <2> logconnections: BPRD CONNECT FROM XXX.XX.XXX.XX.63577 TO YYY.YY.YYY.YY.1556 fd = 576 17:40:45.913 [10360.9856] <4> CGlobalInformation::DeleteDSN: INF - Using ODBC Driver 17:40:45.918 [10360.9856] <4> CGlobalInformation::DeleteDSN: INF - Using ODBC Driver 17:40:45.922 [10360.9856] <4> CGlobalInformation::DeleteDSN: INF - Using ODBC Driver
1 ACCEPTED SOLUTION

Accepted Solutions

Michael_G_Ander
Level 6
Certified

Could be a timeout issue as it only the full & mostly large databases that fail, have had to increase CLIENT_CONNECT_TIMEOUT and VDITIMEOUT for some systems to get rid of intermittent status 6.

As you are running through a firewall the windows TCPKEEPALIVE parameter might also be worth looking at, default is around 2 hours and most firewalls cuts an "idle" session at around 5 minutes

The standard questions: Have you checked: 1) What has changed. 2) The manual 3) If there are any tech notes or VOX posts regarding the issue

View solution in original post

6 REPLIES 6

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified

It looks like a network problem 70% into the backup of the 1st database.

I do not see a problem from NBU point of view. Both dbclient on the client and bptm on the media server reported network disconnect.

Get your network team involved.

rookie11
Moderator
Moderator
   VIP   

create a test policy and run only full backup of database which failed. (select only 1 database which failed from SQL GUI agent by logging into client). It will give insight.

_Johan
Level 3

Thanks for the replies.

I logged a case to symantec this monday and have sent tons of logs theese past days.
They also suspects network issues but the network and firewall guys have not found anything wrong eighter.

 

//Johan

 

 

rookie11
Moderator
Moderator
   VIP   

sadly network n firewall guys will never get to root of problem. they will only ping and reply everything is fine.

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified

The problem with intermittent issues is that monitoring needs to be in place as and when the issue happens.

Ad hoc testing will not help.

Get your network and firewall guys to put some sort of continuous monitoring or logging in place.

Michael_G_Ander
Level 6
Certified

Could be a timeout issue as it only the full & mostly large databases that fail, have had to increase CLIENT_CONNECT_TIMEOUT and VDITIMEOUT for some systems to get rid of intermittent status 6.

As you are running through a firewall the windows TCPKEEPALIVE parameter might also be worth looking at, default is around 2 hours and most firewalls cuts an "idle" session at around 5 minutes

The standard questions: Have you checked: 1) What has changed. 2) The manual 3) If there are any tech notes or VOX posts regarding the issue