MSSQL - Transaction log backup failures - "BACKUP ...

naughty_bits · ‎10-14-2009

Hi all,
Getting some MSSQL backup errors (SQL server 2005 running on Windows Server 2007, NBU v6.5.4) and I'm not sure how to interpret the error log. The logs say that the DB has never had a full backup, but if I look at the bplist output it appears to have a full backup:

"c:\Program Files\VERITAS\NetBackup\bin\bplist.exe" -C db-server -S master-server -t 15 -k DE_SQL_101CL_Full -R \|find /I "APPVIRTDB"

pmsql1.MSSQL7.DB-SERVER\CORPORATE.db.APPVIRTDB.~.7.001of001.20091013102724..C:\

pmsql1.MSSQL7.DB-SERVER\CORPORATE.trx.APPVIRTDB.~.7.001of001.20091005153117..C:\

pmsql1.MSSQL7.DB-SERVER\CORPORATE.db.APPVIRTDB.~.7.001of001.20091005152929..C:\

pmsql1.MSSQL7.DB-SERVER\CORPORATE.db.APPVIRTDB.~.7.001of001.20091005152809..C:\

Here's the log and other possible pertinent data:

11:13:58.795 [788.4856] <2> vnet_vnetd_service_socket: ..\libvlibs\vnet_vnetd.c.2046: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006

11:13:58.795 [788.4856] <2> vnet_vnetd_service_socket: ..\libvlibs\vnet_vnetd.c.2060: service: bprd

11:13:58.798 [788.4856] <2> logconnections: BPRD CONNECT FROM 10.125.4.152.57442 TO 10.125.24.160.13724

11:13:58.904 [788.4856] <4> CGlobalInformation::VCSVirtualNameList: INF - Veritas Cluster Server is not installed.

11:13:58.904 [788.4856] <1> CGlobalInformation::VCSVirtualNameList: CONTINUATION: - The system cannot find the path specified.

11:13:58.905 [788.4856] <4> getServerName: Read server name from nb_master_config: master-server

11:13:58.905 [788.4856] <4> CDBIniParms::CDBIniParms: INF - NT User is service_nbu-sql

11:13:58.938 [788.4856] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_1>, SQL userid <service_nbu-sql> handle <0x01a541a0>.

11:13:59.006 [788.4856] <4> CGlobalInformation::CreateDSN: INF - A successful connection to SQL Server <DB-SERVER\CORPORATE> has been made using standard security with DSN <NBMSSQL_788_4856_1>

11:13:59.006 [788.4856] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x01a541a0>

11:13:59.008 [788.4856] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_1>, SQL userid <service_nbu-sql> handle <0x01a541a0>.

11:13:59.021 [788.4856] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x01a541a0>

11:13:59.023 [788.4856] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_1>, SQL userid <service_nbu-sql> handle <0x01a541a0>.

11:13:59.035 [788.4856] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x01a541a0>

11:13:59.037 [788.4856] <4> CDBbackcat::GetVirtualServer: INF - Accessing database instance <DB-SERVER\CORPORATE> on virtual server <DB-SERVER>.

11:13:59.037 [788.4856] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_1>, SQL userid <service_nbu-sql> handle <0x01a541a0>.

11:13:59.065 [788.4856] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x01a541a0>

11:13:59.069 [788.4856] <4> CDBbackmain::OperationsAreGroupable: INF - The batch file is not groupable because at least one operation specifies a transaction log, filegroup, or file.

11:13:59.084 [788.4856] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_2>, SQL userid <service_nbu-sql> handle <0x01a541a0>.

11:13:59.096 [788.4856] <4> CGlobalInformation::CreateDSN: INF - A successful connection to SQL Server <DB-SERVER\CORPORATE> has been made using standard security with DSN <NBMSSQL_788_4856_2>

11:13:59.096 [788.4856] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x01a541a0>

11:13:59.098 [788.4856] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_2>, SQL userid <service_nbu-sql> handle <0x01a541a0>.

11:13:59.110 [788.4856] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x01a541a0>

11:13:59.112 [788.4856] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_2>, SQL userid <service_nbu-sql> handle <0x01a541a0>.

11:13:59.126 [788.4856] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x01a541a0>

11:13:59.128 [788.4856] <4> CDBbackcat::GetVirtualServer: INF - Accessing database instance <DB-SERVER\CORPORATE> on virtual server <DB-SERVER>.

11:13:59.128 [788.4856] <4> CDBbackrec::CDBbackrec: INF - Use standard backup method with policy <DE_SQL_101CL_Logs>.

11:14:00.229 [788.9124] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_2>, SQL userid <service_nbu-sql> handle <0x01a541a0>.

11:14:00.243 [788.9124] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x01a541a0>

11:14:00.245 [788.9124] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_2>, SQL userid <service_nbu-sql> handle <0x01a541a0>.

11:14:00.258 [788.9124] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x01a541a0>

11:14:00.260 [788.9124] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_2>, SQL userid <service_nbu-sql> handle <0x01a541a0>.

11:14:00.273 [788.9124] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x01a541a0>

11:14:00.275 [788.9124] <4> Dbbackrec::PerformNBOperation: INF - BACKUP STARTED USING Microsoft SQL Server 2005 - 9.00.4035.00 (X64) Nov 24 2008 16:17:31 Copyright (c) 1988-2005 Microsoft Corporation Standard Edition (64-bit) on Windows NT 6.0 (Build 6002: Service Pack 2) Batch = G:\nbu_scripts\sql_trans.bch, Op# = 1

11:14:00.275 [788.9124] <4> InitPipeInfo: INF - Using backup image pmsql1.MSSQL7.DB-SERVER\CORPORATE.trx.Akonix.~.7.001of001.20091013111359..C

11:14:00.275 [788.9124] <4> Dbbackrec::CreateSQLcmdSyntax: INF - backup log "Akonix" to VIRTUAL_DEVICE='VNBU0-788-9124-1255446840' with stats = 10, blocksize = 65536, maxtransfersize = 1048576, buffercount = 16

11:14:00.275 [788.9124] <4> Dbbackrec::CreateSQLcmdSyntax: INF - Number of stripes: 1, Number of buffers per stripe 16.

11:14:00.275 [788.9124] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_2>, SQL userid <service_nbu-sql> handle <0x01a541a0>.

11:14:00.293 [788.9124] <4> CDBbackrec::InitDeviceSet(): INF - Created VDI object for SQL Server instance <CORPORATE>. Connection timeout is <300> seconds.

11:14:00.364 [788.3568] <2> vnet_vnetd_service_socket: ..\libvlibs\vnet_vnetd.c.2046: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006

11:14:00.364 [788.3568] <2> vnet_vnetd_service_socket: ..\libvlibs\vnet_vnetd.c.2060: service: bprd

11:14:00.366 [788.3568] <2> logconnections: BPRD CONNECT FROM 10.125.4.152.57453 TO 10.125.24.160.13724

11:14:00.638 [788.3568] <2> vnet_vnetd_service_socket: ..\libvlibs\vnet_vnetd.c.2046: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006

11:14:00.638 [788.3568] <2> vnet_vnetd_service_socket: ..\libvlibs\vnet_vnetd.c.2060: service: bprd

11:14:00.642 [788.3568] <2> logconnections: BPRD CONNECT FROM 10.125.4.152.57460 TO 10.125.24.160.13724

11:14:20.659 [788.3568] <4> serverResponse: Not a candidate for alternate buffer method: shared memory is not in use.

11:14:37.217 [788.3568] <4> DBthreads::dbclient: INF - Thread has been closed for stripe #0

11:14:37.217 [788.3568] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_2>, SQL userid <service_nbu-sql> handle <0x01a54300>.

11:14:37.227 [788.3568] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x01a54300>

11:14:37.227 [788.3568] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_2>, SQL userid <service_nbu-sql> handle <0x01a54300>.

11:14:37.233 [788.3568] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x01a54300>

11:14:37.234 [788.3568] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_2>, SQL userid <service_nbu-sql> handle <0x01a54300>.

11:14:37.240 [788.3568] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x01a54300>

11:14:37.240 [788.3568] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_2>, SQL userid <service_nbu-sql> handle <0x01a54300>.

11:14:37.243 [788.9124] <8> CODBCaccess::LogODBCerr: WARN - ODBC return code <1>, SQL State <01000>, SQL Message <3211><[Microsoft][SQL Native Client][SQL Server]100 percent processed.>.

11:14:37.243 [788.9124] <8> CODBCaccess::LogODBCerr: WARN - SQL Message <4035><[Microsoft][SQL Native Client][SQL Server]Processed 0 pages for database 'Akonix', file 'akonix_prod_log' on file 1.>

11:14:37.244 [788.9124] <8> CODBCaccess::LogODBCerr: WARN - SQL Message <3014><[Microsoft][SQL Native Client][SQL Server]BACKUP LOG successfully processed 0 pages in 1.506 seconds (0.000 MB/sec).>

11:14:37.246 [788.3568] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_2>, SQL userid <service_nbu-sql> handle <0x01a54250>.

11:14:37.251 [788.3568] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_2>, SQL userid <service_nbu-sql> handle <0x01a54460>.

11:14:37.258 [788.3568] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x01a54460>

11:14:47.380 [788.9124] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x01a541a0>

11:14:47.381 [788.9124] <4> Dbbackrec::Perform: INF - OPERATION #1 of batch G:\nbu_scripts\sql_trans.bch SUCCEEDED with STATUS 0 (0 is normal). Elapsed time = 48(2) seconds

11:14:49.394 [788.4856] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_3>, SQL userid <service_nbu-sql> handle <0x01a541a0>.

11:14:49.400 [788.4856] <4> CGlobalInformation::CreateDSN: INF - A successful connection to SQL Server <DB-SERVER\CORPORATE> has been made using standard security with DSN <NBMSSQL_788_4856_3>

11:14:49.400 [788.4856] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x01a541a0>

11:14:49.401 [788.4856] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_3>, SQL userid <service_nbu-sql> handle <0x01a541a0>.

11:14:49.407 [788.4856] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x01a541a0>

11:14:49.407 [788.4856] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_3>, SQL userid <service_nbu-sql> handle <0x01a541a0>.

11:14:49.412 [788.4856] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x01a541a0>

11:14:49.413 [788.4856] <4> CDBbackcat::GetVirtualServer: INF - Accessing database instance <DB-SERVER\CORPORATE> on virtual server <DB-SERVER>.

11:14:49.413 [788.4856] <4> CDBbackrec::CDBbackrec: INF - Use standard backup method with policy <DE_SQL_101CL_Logs>.

11:15:00.519 [788.7736] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_3>, SQL userid <service_nbu-sql> handle <0x01a541a0>.

11:15:00.526 [788.7736] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x01a541a0>

11:15:00.526 [788.7736] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_3>, SQL userid <service_nbu-sql> handle <0x01a541a0>.

11:15:00.534 [788.7736] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x01a541a0>

11:15:00.534 [788.7736] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_3>, SQL userid <service_nbu-sql> handle <0x01a541a0>.

11:15:00.541 [788.7736] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x01a541a0>

11:15:00.542 [788.7736] <4> Dbbackrec::PerformNBOperation: INF - BACKUP STARTED USING Microsoft SQL Server 2005 - 9.00.4035.00 (X64) Nov 24 2008 16:17:31 Copyright (c) 1988-2005 Microsoft Corporation Standard Edition (64-bit) on Windows NT 6.0 (Build 6002: Service Pack 2) Batch = G:\nbu_scripts\sql_trans.bch, Op# = 2

11:15:00.542 [788.7736] <4> InitPipeInfo: INF - Using backup image pmsql1.MSSQL7.DB-SERVER\CORPORATE.trx.APPVIRTDB.~.7.001of001.20091013111459..C

11:15:00.543 [788.7736] <4> Dbbackrec::CreateSQLcmdSyntax: INF - backup log "APPVIRTDB" to VIRTUAL_DEVICE='VNBU0-788-7736-1255446900' with stats = 10, blocksize = 65536, maxtransfersize = 1048576, buffercount = 16

11:15:00.543 [788.7736] <4> Dbbackrec::CreateSQLcmdSyntax: INF - Number of stripes: 1, Number of buffers per stripe 16.

11:15:00.543 [788.7736] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_3>, SQL userid <service_nbu-sql> handle <0x01a541a0>.

11:15:00.554 [788.7736] <4> CDBbackrec::InitDeviceSet(): INF - Created VDI object for SQL Server instance <CORPORATE>. Connection timeout is <300> seconds.

11:15:00.656 [788.5784] <2> vnet_vnetd_service_socket: ..\libvlibs\vnet_vnetd.c.2046: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006

11:15:00.656 [788.5784] <2> vnet_vnetd_service_socket: ..\libvlibs\vnet_vnetd.c.2060: service: bprd

11:15:00.659 [788.5784] <2> logconnections: BPRD CONNECT FROM 10.125.4.152.57500 TO 10.125.24.160.13724

11:20:00.706 [788.7736] <4> getServerName: Read server name from nb_master_config: master-server

11:20:00.789 [788.7736] <2> vnet_vnetd_service_socket: ..\libvlibs\vnet_vnetd.c.2046: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006

11:20:00.789 [788.7736] <2> vnet_vnetd_service_socket: ..\libvlibs\vnet_vnetd.c.2060: service: bprd

11:20:00.791 [788.7736] <2> logconnections: BPRD CONNECT FROM 10.125.4.152.57532 TO 10.125.24.160.13724

11:20:01.310 [788.7736] <4> getServerName: Read server name from nb_master_config: master-server

11:20:01.399 [788.7736] <2> vnet_vnetd_service_socket: ..\libvlibs\vnet_vnetd.c.2046: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006

11:20:01.399 [788.7736] <2> vnet_vnetd_service_socket: ..\libvlibs\vnet_vnetd.c.2060: service: bprd

11:20:01.402 [788.7736] <2> logconnections: BPRD CONNECT FROM 10.125.4.152.57536 TO 10.125.24.160.13724

11:20:02.500 [788.7736] <16> CDBbackrec::InitDeviceSet_Part2(): ERR - Error in GetConfiguration: 0x80770003.

11:20:02.501 [788.7736] <1> CDBbackrec::InitDeviceSet_Part2(): CONTINUATION: - The api was waiting and the timeout interval had elapsed.

11:20:02.501 [788.7736] <4> KillAllThreads: INF - Killing group #0

11:20:02.501 [788.7736] <4> KillAllThreads: INF - Issuing SignalAbort to MS SQL Server VDI

11:20:02.501 [788.5832] <4> KillAllThreads: INF - Killing group #0

11:20:02.502 [788.5784] <4> KillAllThreads: INF - Killing group #0

11:20:02.516 [788.7100] <4> KillAllThreads: INF - Killing group #0

11:20:02.516 [788.7736] <16> CODBCaccess::LogODBCerr: DBMS MSG - ODBC return code <-1>, SQL State <37000>, SQL Message <4214><[Microsoft][SQL Native Client][SQL Server]BACKUP LOG cannot be performed because there is no current database backup.>.

11:20:02.516 [788.7736] <16> CODBCaccess::LogODBCerr: DBMS MSG - SQL Message <3013><[Microsoft][SQL Native Client][SQL Server]BACKUP LOG is terminating abnormally.>

11:20:02.516 [788.7736] <16> Dbbackrec::PerformNBOperation: ERR - Error found executing <backup log "APPVIRTDB" to VIRTUAL_DEVICE='VNBU0-788-7736-1255446900' with stats = 10, blocksize = 65536, maxtransfersize = 1048576, buffercount = 16>.

11:20:02.516 [788.7736] <4> DBConnect: INF - Logging into SQL Server with DSN <NBMSSQL_788_4856_3>, SQL userid <service_nbu-sql> handle <0x01a54510>.

11:20:02.523 [788.7736] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x01a54510>

11:20:02.523 [788.7736] <4> DBDisconnect: INF - Logging out of SQL Server with handle <0x01a541a0>

11:20:02.523 [788.7736] <4> getServerName: Read server name from nb_master_config: master-server

11:20:02.610 [788.7736] <2> vnet_vnetd_service_socket: ..\libvlibs\vnet_vnetd.c.2046: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006

11:20:02.610 [788.7736] <2> vnet_vnetd_service_socket: ..\libvlibs\vnet_vnetd.c.2060: service: bprd

11:20:02.612 [788.7736] <2> logconnections: BPRD CONNECT FROM 10.125.4.152.57540 TO 10.125.24.160.13724

11:20:03.720 [788.7736] <16> CDBbackrec::FreeDeviceSet(): ERR - Error in VDS->Close: 0x80770004.

11:20:03.720 [788.7736] <1> CDBbackrec::FreeDeviceSet(): CONTINUATION: - An abort request is preventing anything except termination actions.

11:20:03.720 [788.7736] <4> Dbbackrec::Perform: INF - OPERATION #2 of batch G:\nbu_scripts\sql_trans.bch FAILED with STATUS 1 (0 is normal). Elapsed time = 304(304) seconds.

11:20:05.720 [788.4856] <4> CDBbackmain::dbbackup: INF - Results of executing <G:\nbu_scripts\sql_trans.bch>: <1> operations succeeded. <1> operations failed.

11:20:05.720 [788.4856] <4> CDBbackmain::dbbackup: INF - The following object(s) were not backed up successfully.

11:20:05.720 [788.4856] <4> CDBbackmain::dbbackup: INF - APPVIRTDB

Batch scripts:

Sql_full.bch

OPERATION BACKUP

DATABASE $ALL

SQLHOST "DB-SERVER"

SQLINSTANCE "CORPORATE"

NBSERVER "MASTER-SERVER"

MAXTRANSFERSIZE 4

BLOCKSIZE 7

#POLICY DE_SQL_101CL_Full

BROWSECLIENT "DB-SERVER"

BUFFERS 16

ENDOPER TRUE

Sql_trans.bch

OPERATION BACKUP

DATABASE $ALL

SQLHOST "DB-SERVER"

SQLINSTANCE "CORPORATE"

NBSERVER "MASTER-SERVER"

EXCLUDE "master"

EXCLUDE "msdb"

MAXTRANSFERSIZE 4

BLOCKSIZE 7

#POLICY DE_SQL_101CL_Full

BROWSECLIENT "DB-SERVER"

OBJECTTYPE TRXLOG

BUFFERS 16

ENDOPER TRUE

Any help would be appreciated.

Mouse · ‎10-17-2009

Last time saw thing like that when ppl were using maintenance plan along with nbu. check that all your maintenance plans (log truncations, db backups) disabled

naughty_bits · ‎03-18-2010

I meant to send update about this but didn't realize I need to subscribe to my own posts to get updates on them. DOH!

Anyway, this issue was due to a bug with the 6.5.4/MSSQL and support suggested that I downgrade to 6.5.3; This resolved the issue and we're now backing up all DB's successfully.

Thanks!

naughty_bits · ‎03-18-2010

Found an autosubscribe option in the profile section that wasn't checked! Duh!

Hemanth · ‎03-28-2010

I am using Net Backup 6.5.2A i need to take Transaction Logs backup for a MS SQL Database.
I tried a bch file for the same, while running that it is giving me a error.

Please fine the error message and help how to resolve this issue.

OPERATION BACKUP
DATABASE "SOL"
SQLHOST "XXXX"
NBSERVER "XXXX"
MAXTRANSFERSIZE 6
BLOCKSIZE 7
POLICY SOL_TR
OBJECTTYPE TRXLOG
NUMBUFS 2
ENDOPER TRUE

USER - Operation inhibited by NetBackup for Microsoft SQL Server: Only a full or incremental database backup can be performed on database <SOL> because it uses the simple recovery model or has 'truncate log on checkpoint' set.
INF - OPERATION #1 of batch C:\Program Files\Veritas\NetBackup\dbext\mssql\temp\__19_58_35_495_00.bch FAILED with STATUS 1 (0 is normal). Elapsed time = 7(7) seconds.
INF - Results of executing <C:\Program Files\Veritas\NetBackup\dbext\mssql\temp\__19_58_35_495_00.bch>:
<0> operations succeeded. <1> operations failed.
INF - The following object(s) were not backed up successfully.
INF - SOL

Thanks

naughty_bits · ‎03-29-2010

I looks like you either havent had a successful fullbackup of that SOL DB or its set to simple in the recovery. Double check those things.

Good luck!

VOX

MSSQL - Transaction log backup failures - "BACKUP LOG cannot be performed because there is no current database backup."