Highlighted

SQL 62 Timer expired

Hi,

 

So we got this sql 2012 srv on win7 64bit with sysadmin+dbcreator+serveradmin roles.

Netbackup client services running with the same user as sql.

Netbackup SQL Agent is connected with SQL Server DBS.

The NB Env. master 7.6.0.1 server it`s a linux distr. and because this clinet (7.6.0.1) is in another country there is an media appliance at client location , linux distr.

Job Detail log:

03-06-2015 11:56:23 - Error bpbrm(pid=56118) socket read failed: errno = 62 - Timer expired    
03-06-2015 11:56:25 - Error bptm(pid=56157) media manager terminated by parent process          
03-06-2015 11:57:06 - end writing; write time: 0:05:43
file read failed(13)

On Client side view satus report:

ERR - Error in GetConfiguration: 0x80770003.
    CONTINUATION: - The api was waiting and the timeout interval had elapsed.
DBMS MSG - ODBC return code <-1>, SQL State <37000>, SQL Message <4214><[Microsoft][ODBC SQL Server Driver][SQL Server]BACKUP LOG cannot be performed because there is no current database backup.>.
DBMS MSG - SQL Message <3013><[Microsoft][ODBC SQL Server Driver][SQL Server]BACKUP LOG is terminating abnormally.>
ERR - Error found executing <backup log "model" to VIRTUAL_DEVICE='VNBU0-720-10824-1433320822' with  stats = 10, blocksize = 65536, maxtransfersize = 4194304, buffercount = 2>.
INF - OPERATION #2 of batch C:\Program Files\Veritas\NetBackup\DbExt\MsSql\trans.bch FAILED with STATUS 1 (0 is normal). Elapsed time = 304(304) seconds.
USER - Operation inhibited by NetBackup for Microsoft SQL Server: Only a full or incremental database backup can be performed on database <msdb> because it uses the simple recovery model or has 'truncate log on checkpoint' set.
INF - OPERATION #3 of batch C:\Program Files\Veritas\NetBackup\DbExt\MsSql\trans.bch FAILED with STATUS 1 (0 is normal). Elapsed time = 1(1) seconds.
INF - BACKUP STARTED USING
Microsoft SQL Server 2012 - 11.0.5058.0 (X64) 
May 14 2014 18:34:29 
Copyright (c) Microsoft Corporation
Standard Edition (64-bit) on Windows NT 6.3 <X64> (Build 9600: ) 
Batch = C:\Program Files\Veritas\NetBackup\DbExt\MsSql\trans.bch, Op# = 4
INF - Using backup image SQLUKNO0010.MSSQL7.SQLUKNO0010.trx.OLSharedServices.~.7.001of001.20150603094551..C
INF - backup log "OLSharedServices" to VIRTUAL_DEVICE='VNBU0-720-7464-1433321152' with  stats = 10, blocksize = 65536, maxtransfersize = 4194304, buffercount = 2
INF - Number of stripes: 1, Number of buffers per stripe 2.
INF - Created VDI object for SQL Server instance <SQLUKNO0010>. Connection timeout is <300> seconds.
ERR - Error in GetConfiguration: 0x80770003.
    CONTINUATION: - The api was waiting and the timeout interval had elapsed.
DBMS MSG - ODBC return code <-1>, SQL State <37000>, SQL Message <4214><[Microsoft][ODBC SQL Server Driver][SQL Server]BACKUP LOG cannot be performed because there is no current database backup.>.
DBMS MSG - SQL Message <3013><[Microsoft][ODBC SQL Server Driver][SQL Server]BACKUP LOG is terminating abnormally.>
ERR - Error found executing <backup log "OLSharedServices" to VIRTUAL_DEVICE='VNBU0-720-7464-1433321152' with  stats = 10, blocksize = 65536, maxtransfersize = 4194304, buffercount = 2>.
INF - OPERATION #4 of batch C:\Program Files\Veritas\NetBackup\DbExt\MsSql\trans.bch FAILED with STATUS 1 (0 is normal). Elapsed time = 303(303) seconds.
INF - BACKUP STARTED USING
Microsoft SQL Server 2012 - 11.0.5058.0 (X64) 
May 14 2014 18:34:29 
Copyright (c) Microsoft Corporation
Standard Edition (64-bit) on Windows NT 6.3 <X64> (Build 9600: ) 
Batch = C:\Program Files\Veritas\NetBackup\DbExt\MsSql\trans.bch, Op# = 5
INF - Using backup image SQLUKNO0010.MSSQL7.SQLUKNO0010.trx.OpenLabDS.~.7.001of001.20150603095107..C
INF - backup log "OpenLabDS" to VIRTUAL_DEVICE='VNBU0-720-7380-1433321468' with  stats = 10, blocksize = 65536, maxtransfersize = 4194304, buffercount = 2
INF - Number of stripes: 1, Number of buffers per stripe 2.
INF - Created VDI object for SQL Server instance <SQLUKNO0010>. Connection timeout is <300> seconds.
ERR - Error in GetConfiguration: 0x80770003.
    CONTINUATION: - The api was waiting and the timeout interval had elapsed.
DBMS MSG - ODBC return code <-1>, SQL State <37000>, SQL Message <4214><[Microsoft][ODBC SQL Server Driver][SQL Server]BACKUP LOG cannot be performed because there is no current database backup.>.
DBMS MSG - SQL Message <3013><[Microsoft][ODBC SQL Server Driver][SQL Server]BACKUP LOG is terminating abnormally.>
ERR - Error found executing <backup log "OpenLabDS" to VIRTUAL_DEVICE='VNBU0-720-7380-1433321468' with  stats = 10, blocksize = 65536, maxtransfersize = 4194304, buffercount = 2>.
INF - OPERATION #5 of batch C:\Program Files\Veritas\NetBackup\DbExt\MsSql\trans.bch FAILED with STATUS 1 (0 is normal). Elapsed time = 304(304) seconds.
INF - Results of executing <C:\Program Files\Veritas\NetBackup\DbExt\MsSql\trans.bch>: 

bpclntcmd cmds:

C:\Program Files\Veritas\NetBackup\bin>bpclntcmd.exe -pn
expecting response from server smctup22.smc-dk.dk
10.199.72.5 *NULL* 10.199.72.5 55886

C:\Program Files\Veritas\NetBackup\bin>bpclntcmd.exe -ip smctup22.smc-dk.dk
host smctup22.smc-dk.dk: smctup22.smc-dk.dk at 10.192.96.211
aliases:     smctup22.smc-dk.dk     10.192.96.211

C:\Program Files\Veritas\NetBackup\bin>bpclntcmd.exe -self
gethostname() returned: sqlukno0010.nzww.nzcorp.net
host sqlukno0010.nzww.nzcorp.net: SQLUKNO0010.nzww.nzcorp.net at ::1
host sqlukno0010.nzww.nzcorp.net: SQLUKNO0010.nzww.nzcorp.net at 10.199.72.5
aliases:     SQLUKNO0010.nzww.nzcorp.net     ::1     10.199.72.5
getfqdn(sqlukno0010.nzww.nzcorp.net) returned: SQLUKNO0010.nzww.nzcorp.net

Attached you can find bpkar log and dbclient.

I have no Ideea why this happens.

//George

1 Solution

Accepted Solutions
Accepted Solution!

Windows policy does not

Windows policy does not require comms between master and client, only between media server and client. Db backups need comms between master and client.

View solution in original post

10 Replies

What is in Job Details before

What is in Job Details before the 'Timer expired' error?

This error is normally associated with Client Read Timeout on the media server.

For databases, this value should be at least 1800.

Oh! You need to check the NBSERVER entry in the SQL backup script. It MUST be the master server, not media server.
I see  in dbclient log that client is trying to connect to master server  UKNO01BCK.NZWW.NZCORP.NET, but bpclntcm -pn lists the master as smctup22.smc-dk.dk.

Please add hosts entry on master and client for one another and ensure Client name in SQL policy is the same as SQLHOST in the backup script.

Full Job Details

Full Job Details Status:

 

03-06-2015 12:37:46 - Info nbjm(pid=28382) starting backup job (jobid=2195647) for client sqlukno0010.nzww.nzcorp.net, policy nz_ukno_mssql_physical, schedule Default-Application-Backup  
03-06-2015 12:37:46 - Info nbjm(pid=28382) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=2195647, request id:{93A19EB4-09DC-11E5-913A-D5557A7B263B})  
03-06-2015 12:37:46 - requesting resource stu_disk_ukno01bck
03-06-2015 12:37:46 - requesting resource smctup22.smc-dk.dk.NBU_CLIENT.MAXJOBS.sqlukno0010.nzww.nzcorp.net
03-06-2015 12:37:46 - requesting resource smctup22.smc-dk.dk.NBU_POLICY.MAXJOBS.nz_ukno_mssql_physical
03-06-2015 12:37:47 - granted resource smctup22.smc-dk.dk.NBU_CLIENT.MAXJOBS.sqlukno0010.nzww.nzcorp.net
03-06-2015 12:37:47 - granted resource smctup22.smc-dk.dk.NBU_POLICY.MAXJOBS.nz_ukno_mssql_physical
03-06-2015 12:37:47 - granted resource MediaID=@aaaaq;DiskVolume=PureDiskVolume;DiskPool=dp_disk_ukno01bck;Path=PureDiskVolume;StorageServer=ukno01bck;MediaServer=ukno01bck
03-06-2015 12:37:47 - granted resource stu_disk_ukno01bck
03-06-2015 12:37:47 - estimated 0 Kbytes needed
03-06-2015 12:37:47 - Info nbjm(pid=28382) started backup (backupid=sqlukno0010.nzww.nzcorp.net_1433327868) job for client sqlukno0010.nzww.nzcorp.net, policy nz_ukno_mssql_physical, schedule Default-Application-Backup on storage unit stu_disk_ukno01bck
03-06-2015 12:37:48 - started process bpbrm (60727)
03-06-2015 12:37:49 - Info bpbrm(pid=60727) sqlukno0010.nzww.nzcorp.net is the host to backup data from     
03-06-2015 12:37:49 - Info bpbrm(pid=60727) reading file list for client        
03-06-2015 12:37:49 - Info bpbrm(pid=60727) listening for client connection         
03-06-2015 12:37:49 - connecting
03-06-2015 12:37:50 - Info bpbrm(pid=60727) INF - Client read timeout = 300      
03-06-2015 12:37:51 - Info bpbrm(pid=60727) accepted connection from client         
03-06-2015 12:37:51 - Info dbclient(pid=9948) Backup started           
03-06-2015 12:37:51 - Info bpbrm(pid=60727) bptm pid: 60728          
03-06-2015 12:37:51 - Info bptm(pid=60728) start            
03-06-2015 12:37:51 - connected; connect time: 0:00:02
03-06-2015 12:37:53 - Info bptm(pid=60728) using 262144 data buffer size        
03-06-2015 12:37:53 - Info bptm(pid=60728) using 30 data buffers         
03-06-2015 12:37:55 - Info bptm(pid=60728) start backup           
03-06-2015 12:37:57 - Info bptm(pid=60728) backup child process is pid 60737       
03-06-2015 12:37:57 - begin writing
03-06-2015 12:42:57 - Error bpbrm(pid=60727) socket read failed: errno = 62 - Timer expired    
03-06-2015 12:42:59 - Error bptm(pid=60728) media manager terminated by parent process       
03-06-2015 12:43:31 - Info ukno01bck(pid=60728) StorageServer=PureDisk:ukno01bck; Report=PDDO Stats for (ukno01bck): scanned: 3 KB, CR sent: 0 KB, CR sent over FC: 0 KB, dedup: 100.0%, cache disabled
03-06-2015 12:43:31 - Info dbclient(pid=9948) done. status: 13: file read failed       
03-06-2015 12:43:31 - end writing; write time: 0:05:34
file read failed(13)

 

NBSERVER "SMCTUP22.SMC-DK.DK" is correct in every bch.

We don`t use hosts file becasue they use DNS servers.

Our Client Read Timeout is 4000 sec on master server.

On media server: UKNO01BCK.NZWW.NZCORP.NET which is a linux server i think it`s 300. I will search to know where to change it.

 

//George

Host Properties -> Media

Host Properties -> Media Servers (Select media server) -> Timeouts

bpclntcmd -pn seem to have returned IP address for client, meaning that the master can probably not resolve client IP to hostname.

Please check bpclntcmd commands on master server as well:

bpclntcmd -hn <client-name>

bpclntcmd -ip <client-IP>

The hostname resolved by client-IP must be same as Client name in the policy.

 

Have you ever taken full

Have you ever taken full backup of these databases from Netbackup.?

backup log "OLSharedServices"

 

 

backup log "OLSharedServices" to VIRTUAL_DEVICE='VNBU0-720-7464-1433321152'

DBMS MSG - ODBC return code <-1>, SQL State <37000>, SQL Message <4214><[Microsoft][ODBC SQL Server Driver][SQL Server]BACKUP LOG cannot be performed because there is no current database backup.>. DBMS MSG - SQL Message <3013><[Microsoft][ODBC SQL Server Driver][SQL Server]BACKUP LOG is terminating abnormally.>

 

check this.. Try run a full backup, then try trx log backup

Yes it is the

Yes it is the same:

[nbadmin@smctup22 bin]$ ./bpclntcmd -hn sqlukno0010
host sqlukno0010: sqlukno0010.nzww.nzcorp.net at 10.199.19.242
aliases:     sqlukno0010.nzww.nzcorp.net     sqlukno0010     10.199.19.242
[nbadmin@smctup22 bin]$ ./bpclntcmd -hn 10.199.19.242
host 10.199.19.242: sqlukno0010.nzww.nzcorp.net at 10.199.19.242
aliases:     sqlukno0010.nzww.nzcorp.net     10.199.19.242

But this is the full, I just eliminated trans.bch from full backup and left out just full.bch to see what happens.

But the same issues is happening, so it`s not that the full was no made before a trans.

Full BCH:

OPERATION BACKUP
DATABASE $ALL
SQLHOST "SQLUKNO0010"
NBSERVER "SMCTUP22.SMC-DK.DK"
MAXTRANSFERSIZE 6
BLOCKSIZE 7
NUMBUFS 2
ENDOPER TRUE

I`ve just added CLIENT_READ_TIMEOUT = 1800 to media server who`s handleing this server.

//George

This must actually be -ip,

This must actually be -ip, not -hn:

bpclntcmd -hn 10.199.19.242

So, command should be: 

bpclntcmd -ip 10.199.19.242

Oh! The master is resolving hostname to incorrect IP address!

bpclntcmd -pn shows that connection from client arrives at the master with a different IP address: 

C:\Program Files\Veritas\NetBackup\bin>bpclntcmd.exe -pn expecting response from server smctup22.smc-dk.dk
10
.199.72.5 *NULL* 10.199.72.5 55886

bpclntcmd -self on client also shows IP address of 10.199.72.5.

So, you can see client connection arrives at the master with IP of 10.199.72.5, but master knows IP address of 10.199.19.242.

Either DNS or hosts issue. 
You will need to fix this followed by clearing NBU host cache.

This is strange beucase this

This is strange beucase this client is also in a windows policy and it`s owrking perfectly.

 

03-06-2015 03:59:59 - Info nbjm(pid=28382) starting backup job (jobid=2195409) for client sqlukno0010.nzww.nzcorp.net, policy nz_ukno_windows_file, schedule incr  
03-06-2015 03:59:59 - Info nbjm(pid=28382) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=2195409, request id:{3DCA7F08-0994-11E5-A843-D5631F6A33A3})  
03-06-2015 03:59:59 - requesting resource stu_disk_ukno01bck
03-06-2015 03:59:59 - requesting resource smctup22.smc-dk.dk.NBU_CLIENT.MAXJOBS.sqlukno0010.nzww.nzcorp.net
03-06-2015 03:59:59 - requesting resource smctup22.smc-dk.dk.NBU_POLICY.MAXJOBS.nz_ukno_windows_file
03-06-2015 04:00:01 - granted resource smctup22.smc-dk.dk.NBU_CLIENT.MAXJOBS.sqlukno0010.nzww.nzcorp.net
03-06-2015 04:00:01 - granted resource smctup22.smc-dk.dk.NBU_POLICY.MAXJOBS.nz_ukno_windows_file
03-06-2015 04:00:01 - granted resource MediaID=@aaaaq;DiskVolume=PureDiskVolume;DiskPool=dp_disk_ukno01bck;Path=PureDiskVolume;StorageServer=ukno01bck;MediaServer=ukno01bck
03-06-2015 04:00:01 - granted resource stu_disk_ukno01bck
03-06-2015 04:00:15 - estimated 52765768 Kbytes needed
03-06-2015 04:00:15 - Info nbjm(pid=28382) started backup (backupid=sqlukno0010.nzww.nzcorp.net_1433296816) job for client sqlukno0010.nzww.nzcorp.net, policy nz_ukno_windows_file, schedule incr on storage unit stu_disk_ukno01bck
03-06-2015 04:00:15 - started
03-06-2015 04:00:17 - started process bpbrm (5193)
03-06-2015 04:00:18 - Info bpbrm(pid=5193) sqlukno0010.nzww.nzcorp.net is the host to backup data from     
03-06-2015 04:00:18 - Info bpbrm(pid=5193) reading file list for client        
03-06-2015 04:00:18 - connecting
03-06-2015 04:00:19 - Info bpbrm(pid=5193) starting bpbkar on client         
03-06-2015 04:00:19 - connected; connect time: 0:00:01
03-06-2015 04:00:20 - Info bpbkar(pid=9396) Backup started           
03-06-2015 04:00:20 - Info bpbrm(pid=5193) bptm pid: 5194          
03-06-2015 04:00:20 - Info bpbkar(pid=9396) change time comparison:<disabled>          
03-06-2015 04:00:20 - Info bpbkar(pid=9396) archive bit processing:<enabled>          
03-06-2015 04:00:20 - Info bptm(pid=5194) start            
03-06-2015 04:00:22 - Info bptm(pid=5194) using 262144 data buffer size        
03-06-2015 04:00:22 - Info bptm(pid=5194) using 30 data buffers         
03-06-2015 04:00:23 - Info bptm(pid=5194) start backup           
03-06-2015 04:00:25 - Info bptm(pid=5194) backup child process is pid 5210       
03-06-2015 04:00:25 - begin writing
03-06-2015 04:00:28 - Info bpbkar(pid=9396) not using change journal data for <C:\>: not enabled    
03-06-2015 04:00:28 - Info bpbkar(pid=9396) not using change journal data for <E:\>: not enabled    
03-06-2015 04:00:28 - Info bpbkar(pid=9396) not using change journal data for <H:\>: not enabled    
03-06-2015 04:00:28 - Info bpbkar(pid=9396) not using change journal data for <L:\>: not enabled    
03-06-2015 04:00:28 - Info bpbkar(pid=9396) not using change journal data for <Q:\>: not enabled    
03-06-2015 04:00:28 - Info bpbkar(pid=9396) not using change journal data for <T:\>: not enabled    
03-06-2015 04:15:15 - Info bpbkar(pid=9396) 5000 entries sent to bpdbm        
03-06-2015 04:15:54 - Info bpbkar(pid=9396) 10000 entries sent to bpdbm        
03-06-2015 04:17:47 - Info bpbkar(pid=9396) 15000 entries sent to bpdbm        
03-06-2015 04:19:09 - Info bpbkar(pid=9396) 20000 entries sent to bpdbm        
03-06-2015 04:21:40 - Info bptm(pid=5194) waited for full buffer 43470 times, delayed 83275 times    
03-06-2015 04:21:42 - Info bptm(pid=5194) EXITING with status 0 <----------        
03-06-2015 04:21:43 - Info ukno01bck(pid=5194) StorageServer=PureDisk:ukno01bck; Report=PDDO Stats (multi-threaded stream used) for (ukno01bck): scanned: 11140594 KB, CR sent: 112610 KB, CR sent over FC: 0 KB, dedup: 99.0%, cache disabled
03-06-2015 04:21:43 - Info bpbrm(pid=5193) validating image for client sqlukno0010.nzww.nzcorp.net        
03-06-2015 04:21:44 - Info bpbkar(pid=9396) done. status: 0: the requested operation was successfully completed    
03-06-2015 04:21:44 - end writing; write time: 0:21:19
the requested operation was successfully completed(0)

This is strange.

Accepted Solution!

Windows policy does not

Windows policy does not require comms between master and client, only between media server and client. Db backups need comms between master and client.

View solution in original post

Hi, That was it, Didn`t know

Hi,

 

That was it, Didn`t know that for sql backup, the sql server needs master srv connection, and because the filebase backup was working, I never looked at the ips, I thought they were ok.

I setted up the right ip and now it`s working.

 

Thank you all for help

//George