cancel
Showing results for 
Search instead for 
Did you mean: 

how do i troubleshoot this sql backup error

manatee
Level 6

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).

9 REPLIES 9

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified

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. 

 

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

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified

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.

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 

Kesavan.P

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.

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,

 

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified

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.... 

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.

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified

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.