10-11-2016 05:11 AM
NBU 7.6.0.3
i have a dbclient log now. to summarise, i keep getting this error level 1 message:
0/11/2016 2:10:21 PM - Info dbclient(pid=26984) INF - Created VDI object for SQL Server instance <DB1>. Connection timeout is <1800> seconds. 10/11/2016 2:40:22 PM - Info dbclient(pid=26984) ERR - Error in GetConfiguration: 0x80770003. 10/11/2016 2:40:22 PM - Info dbclient(pid=26984) CONTINUATION: - The api was waiting and the timeout interval had elapsed. 10/11/2016 2:40:25 PM - Info dbclient(pid=26984) INF - OPERATION #2 of batch C:\Program Files\VERITAS\NetBackup\dbext\Mssql\dbDiffBackup.bch FAILED with STATUS 1 (0 is normal). Elapsed time = 1805(1805) seconds. 10/11/2016 2:40:27 PM - Info dbclient(pid=26984) INF - Results of executing <C:\Program Files\VERITAS\NetBackup\dbext\Mssql\dbDiffBackup.bch>: 10/11/2016 2:40:27 PM - Info dbclient(pid=26984) <1> operations succeeded. <1> operations failed. 10/11/2016 2:40:28 PM - Info dbclient(pid=26984) INF - The following object(s) were not backed up successfully. 10/11/2016 2:40:28 PM - Info dbclient(pid=26984) INF - BMB 10/11/2016 2:40:48 PM - Error bpbrm(pid=29859) from client db1: ERR - command failed: the requested operation was partially successful (1) 10/11/2016 2:40:48 PM - Error bpbrm(pid=29859) from client db1: ERR - bphdb exit status = 1: the requested operation was partially successful 10/11/2016 2:40:48 PM - Info bpbrm(pid=29859) validating image for client db1 10/11/2016 2:40:48 PM - Info bphdb(pid=28892) done. status: 1: the requested operation was partially successful 10/11/2016 2:40:48 PM - end writing the requested operation was partially successful(1)
i skimmed the log and couldn't find (understand) what i'm supposed to be looking for.
i have dbclient log and will send them via PM (if that's possible).
10-11-2016 05:28 AM
Look for lines with <8> (Warning), <16> (Error) or <32> (Severe Error).
Especially <16> and/or <32>.
Then scroll up a few lines for the <2> (Debug) lines that led to the Error.
By the looks of it, this is a Timeout error as we see exactly 30 minutes between these 2 timestamps:
10/11/2016 2:10:21 PM - Info dbclient(pid=26984) INF - Created VDI object for SQL Server instance <DB1>. Connection timeout is <1800> seconds. 10/11/2016 2:40:22 PM - Info dbclient(pid=26984) ERR - Error in GetConfiguration: 0x80770003.
For some reason, SQL did not respond within the 30 minute timeout.
I do not recommend increasing the timeout - rather look at SQL logs to see what happened after 2PM that could cause the timeout.
Look in Event Viewer Application logs, SQL Errorlog and SQL VDI logs.
Extract from http://www.veritas.com/docs/000029177:
- The SQL error log (named ERRORLOG, and usually located in the <install_path>\mssql\log directory)
- The VDI log (named vdi.log and usually located in the <install_path>\mssql\log directory)
- The Microsoft Application Event Viewer log
Since the backup ran during the day, maybe a good idea to log into the SQL server to see what 'else' is running at this time and monitor system resources.
10-11-2016 05:38 AM
i don't have that <install path>\mssql\log folder but i found a "mssql_backup_failures" log that contains the following:
TIMESTAMP 20161011144024 MASTERSERVER OVMMANAGER CLIENT DB1 INSTANCE ABC DATABASE BMB OPERATION BACKUP OBJECTTYPE DATABASE OPTION INCREMENTAL STATUS -1 INFO Error in GetConfiguration: 0x80770003. INFO The api was waiting and the timeout interval had elapsed. ENDOPER TRUE
i have a VDITIMEOUT set for 1800 which is at the bottom of the command block. so i move it up. i don't know if that would help.
GROUPSIZE 2 OPERATION BACKUP DATABASE "BMB" SQLHOST "DB1" NBSERVER "OVMMANAGER" VDITIMEOUTSECONDS 1800 <=== MAXTRANSFERSIZE 6 BLOCKSIZE 7 DUMPOPTION INCREMENTAL NUMBUFS 2 ENDOPER TRUE
10-11-2016 05:44 AM
The problem is not with the VDI Timeout or with it's location in the script.
The entry is working - the default is 5 minutes.
Without the
VDITIMEOUTSECONDS 1800
in the script, the backup would've failed sooner.
You need to find out what is happening within SQL and/or the OS in this 30 minutes as suggested in my previous post.
10-11-2016 06:10 AM
Hi rino,
As per the error : 0x80770003 , i could see the below post which says if DB is involved in shrink task (or any other task ) during backup time , backup would fail.
Could you check if there was any native operations performed during that time with the help of your SQL DBA and try running the backup again .
TN : https://www.veritas.com/support/en_US/article.TECH205329
10-11-2016 10:04 PM
i've asked our DBA to have a look on the load part. in the meantime, in the dbclient log somewhere at the start i saw this:
05:00:30.474 [5100.5528] <4> VxBSAInit: Veritas NetBackup XBSA Interface - 7.6 0 05:00:30.520 [5100.5528] <2> vnet_pbxConnect: pbxConnectEx Succeeded 05:00:30.521 [5100.5528] <2> logconnections: BPRD CONNECT FROM 10.10.10.122.48058 TO 10.10.10.39.1556 fd = 528 05:00:30.521 [5100.5528] <2> vnet_check_vxss_client_magic_with_info_ex: [vnet_vxss_helper.c:898] Assuming no VxSS for DB Agents 0 0x0 05:00:30.542 [5100.5528] <4> CGlobalInformation::VCSVirtualNameList: INF - Veritas Cluster Server is not installed. 05:00:30.543 [5100.5528] <1> CGlobalInformation::VCSVirtualNameList: CONTINUATION: - The system cannot find the path specified. 05:00:30.543 [5100.5528] <4> ODBCDataSource::isInstalled: INF - Searching for ODBC Driver: SQL Native Client 05:00:30.543 [5100.5528] <4> ODBCDataSource::isInstalled: INF - Registry Install Path: SOFTWARE\Microsoft\Microsoft SQL Native Client\ 05:00:30.543 [5100.5528] <4> ODBCDataSource::isInstalled: INF - ODBC Driver Entry Registry Path: SOFTWARE\ODBC\ODBCINST.INI\SQL Native Client\ 05:00:30.543 [5100.5528] <4> ODBCDataSource::isInstalled: INF - Registry entry not found for: SOFTWARE\Microsoft\Microsoft SQL Native Client\ 05:00:30.543 [5100.5528] <4> ODBCDataSource::isInstalled: INF - Searching for ODBC Driver: SQL Server 05:00:30.543 [5100.5528] <4> ODBCDataSource::isInstalled: INF - Registry Install Path: SOFTWARE\Microsoft\DataAccess\ 05:00:30.543 [5100.5528] <4> ODBCDataSource::isInstalled: INF - ODBC Driver Entry Registry Path: SOFTWARE\ODBC\ODBCINST.INI\SQL Server\ 05:00:30.543 [5100.5528] <4> ODBCDataSource::isInstalled: INF - ODBC Driver: SQL Server is installed on the system 05:00:30.543 [5100.5528] <4> ODBCDataSource::isInstalled: INF - Searching for ODBC Driver: SQL Server Native Client 10.0 05:00:30.543 [5100.5528] <4> ODBCDataSource::isInstalled: INF - Registry Install Path: SOFTWARE\Microsoft\Microsoft SQL Server Native Client 10.0\ 05:00:30.543 [5100.5528] <4> ODBCDataSource::isInstalled: INF - ODBC Driver Entry Registry Path: SOFTWARE\ODBC\ODBCINST.INI\SQL Server Native Client 10.0\ 05:00:30.543 [5100.5528] <4> ODBCDataSource::isInstalled: INF - ODBC Driver: SQL Server Native Client 10.0 is installed on the system 05:00:30.543 [5100.5528] <4> ODBCDataSource::isInstalled: INF - Searching for ODBC Driver: SQL Server Native Client 11.0 05:00:30.543 [5100.5528] <4> ODBCDataSource::isInstalled: INF - Registry Install Path: SOFTWARE\Microsoft\Microsoft SQL Server Native Client 11.0\ 05:00:30.543 [5100.5528] <4> ODBCDataSource::isInstalled: INF - ODBC Driver Entry Registry Path: SOFTWARE\ODBC\ODBCINST.INI\SQL Server Native Client 11.0\ 05:00:30.555 [5100.5528] <4> ODBCDataSource::isInstalled: INF - ODBC Driver: SQL Server Native Client 11.0 is installed on the system 05:00:30.555 [5100.5528] <4> getServerName: Read server name from nb_master_config: ovmmanager 05:00:30.555 [5100.5528] <4> CDBIniParms::CDBIniParms: INF - NT User is SYSTEM 05:00:30.650 [5100.5528] <4> CDBbackmain::OperationsAreGroupable: INF - The batch file is not groupable because at least one operation is for a differential backup. 05:00:30.652 [5100.5528] <4> CGlobalInformation::CreateDSN: INF - Using ODBC Driver <SQL Server> 05:00:30.789 [5100.5528] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_5100_5528_1>, SQL userid <sa> handle <0x004394f0>. 05:00:30.800 [5100.5528] <4> CGlobalInformation::CreateDSN: INF - A successful connection to SQL Server <service1\> has been made using standard security with DSN <NBMSSQL_5100_5528_1>
why is it looking for cluster server?
also this line
The batch file is not groupable because at least one operation is for a differential backup
i checked the backup script and all are in order as far as i can tell.
10-11-2016 10:43 PM
HI ,
Check whether any local Database Backup's are running . If not kill all the dbext process running in client end and run backup again. Even restart Netbackup services in client end,
10-12-2016 01:11 AM
You are looking at <4> (INFO) messages that are perfectly normal and nothing to do with the problem.
I have tried previously to guide you what to look for....
10-12-2016 02:04 AM
i don't have any <16> or <32> just a bunch of 2, 4, and a few 8:
05:31:36.455 [5100.4808] <8> CODBCaccess::LogODBCerr: WARN - ODBC return code <1>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]21 percent processed.>. 05:31:36.455 [5100.4808] <8> CODBCaccess::LogODBCerr: WARN - SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]49 percent processed.> 05:31:36.455 [5100.4808] <8> CODBCaccess::LogODBCerr: WARN - SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]99 percent processed.> 05:31:36.455 [5100.4808] <8> CODBCaccess::LogODBCerr: WARN - SQL Message <4035><[Microsoft][ODBC SQL Server Driver][SQL Server]Processed 304 pages for database 'MEM', file 'MEM' on file 1.> 05:31:36.455 [5100.4808] <8> CODBCaccess::LogODBCerr: WARN - SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]100 percent processed.> 05:31:36.455 [5100.4808] <8> CODBCaccess::LogODBCerr: WARN - SQL Message <4035><[Microsoft][ODBC SQL Server Driver][SQL Server]Processed 1 pages for database 'MEM', file 'MEM_log' on file 1.> 05:31:36.455 [5100.4808] <8> CODBCaccess::LogODBCerr: WARN - SQL Message <3014><[Microsoft][ODBC SQL Server Driver][SQL Server]BACKUP DATABASE WITH DIFFERENTIAL successfully processed 305 pages in 0.119 seconds (19.966 MB/sec).>
which are backup progress. that's why i started looking elsewhere for clues, hence the <4>s.
10-12-2016 02:10 AM
Those entries are coming from a backup that seem to be running fine...
You need to look at the yesterday's log for the 2pm backup that failed.