SQL Restore fails at the end of the restore status 2850

[Ramiro-Magan]

Hi guys,

I am doing a SQL restore, cross restore from production to testing, and  I am getting this weir situation where the backup is fully done, but when closing, it will fail with status 2850.

I have done the same for other DBs and it works fine, but this one is over 150gb, while the other DBs are way smaller.

I checke dthe error message and could not find and article that I could relate to.

Here is the output from the job.

26/05/2016 16:07:39 - begin Restore
26/05/2016 16:07:39 - Info bprd(pid=6028) Found (5) files in (1) images for Restore Job ID 731842.xxx  
26/05/2016 16:07:40 - 1 images required
26/05/2016 16:07:40 - media OLL026 required
26/05/2016 16:07:41 - restoring image tahq002vw0186.tarjeta.local_1464053533
26/05/2016 16:07:44 - Info bpbrm(pid=5016) TAHQ004vw0206 is the host to restore to      
26/05/2016 16:07:44 - Info bpbrm(pid=5016) telling media manager to start restore on client     
26/05/2016 16:07:48 - Info bpbrm(pid=4468) TAHQ004vw0206 is the host to restore to      
26/05/2016 16:07:48 - Info bpbrm(pid=4468) listening for client connection         
26/05/2016 16:07:50 - Info bptm(pid=1328) Waiting for mount of media id OLL026 (copy 1) on server myarsw00200bk01. 
26/05/2016 16:07:50 - started process bptm (1328)
26/05/2016 16:07:50 - mounting OLL026
26/05/2016 16:07:50 - requesting resource OLL026
26/05/2016 16:07:50 - granted resource OLL026
26/05/2016 16:07:50 - granted resource IBM.ULTRIUM-TD3.004
26/05/2016 16:07:52 - Info bptm(pid=1328) INF - Waiting for mount of media id OLL026 on server myarsw00200bk01 for reading.
26/05/2016 16:07:55 - Info bpbrm(pid=4468) accepted connection from client         
26/05/2016 16:07:55 - Info tar32(pid=1788) Restore started.           
26/05/2016 16:07:55 - connected
26/05/2016 16:08:00 - mounted; mount time: 0:00:10
26/05/2016 16:08:00 - Info bptm(pid=1328) OLL026            
26/05/2016 16:08:02 - Info bptm(pid=1328) INF - Waiting for positioning of media id OLL026 on server myarsw00200bk01 for reading.
26/05/2016 16:08:02 - positioning OLL026 to file 14
26/05/2016 16:08:02 - positioned OLL026; position time: 0:00:00
26/05/2016 16:08:02 - begin reading
26/05/2016 19:58:26 - Error bpbrm(pid=4468) socket read failed, An existing connection was forcibly closed by the remote host.  (10054)
26/05/2016 19:58:26 - end reading; read time: 3:50:24
26/05/2016 19:58:26 - Info bpbrm(pid=5016) sending message to media manager: STOP RESTORE tahq002vw0186.tarjeta.local_1464053533     
26/05/2016 19:58:27 - Info bpbrm(pid=5016) media manager for backup id tahq002vw0186.tarjeta.local_1464053533 exited with status 0: the requested operation was successfully completed
26/05/2016 19:58:27 - restored image tahq002vw0186.tarjeta.local_1464053533 - (file read failed(13)); restore time 3:50:46
26/05/2016 19:58:28 - end Restore; elapsed time: 3:50:49
Restore error (2850)

Thanks.

[Marianne]

This looks like a timeout. SQL restores need looooong Client Read Timeout on the media server. I usually recommend 3 hours. For further troubleshooting, create bptm and bpbrm log folders on the media server and dbclient on SQL client.

[Ramiro-Magan]

Marianne, here is the dbclient log.

I also checked the detailed status on the parent job.

***************************************************************************************************

5/27/2016 9:27:56 AM - begin Restore
5/27/2016 9:27:57 AM - Info dbclient(pid=4968) INF - RESTORE STARTED USING        
5/27/2016 9:27:57 AM - Info dbclient(pid=4968) Microsoft SQL Server 2008 R2 (RTM) - 10.50.1617.0 (X64)    
5/27/2016 9:27:57 AM - Info dbclient(pid=4968) Apr 22 2011 19:23:43         
5/27/2016 9:27:57 AM - Info dbclient(pid=4968) Copyright (c) Microsoft Corporation         
5/27/2016 9:27:57 AM - Info dbclient(pid=4968) Standard Edition (64-bit) on Windows NT 6.1 <X64> (Build 7601: Service Pack 1) (Hypervisor) 
5/27/2016 9:27:57 AM - Info dbclient(pid=4968) Batch = C:\Users\adm-900000009\Desktop\Restore Carta Mayo 2016 - 2.bch, Op# = 1.  
5/27/2016 9:27:57 AM - Info dbclient(pid=4968) INF - Using backup image TAHQ002vw0186.MSSQL7.TAHQ002VW0186.db.Carta.~.7.001of001.20160523223056..C       
5/27/2016 9:27:57 AM - Info dbclient(pid=4968) INF - restore database "Carta" from VIRTUAL_DEVICE='VNBU0-4968-5252-1464352077' with  stats = 10, blocksize = 65536, maxtransfersize = 4194304, buffercount = 2, replace , norecovery, move 'Carta_Data' to 'D:\Databases\SqlServer\Carta.mdf', move 'Carta_Log' to 'D:\Databases\SqlServer\Carta.ldf', replace
5/27/2016 9:27:58 AM - Info dbclient(pid=4968) INF - Number of stripes: 1, Number of buffers per stripe 2. 
5/27/2016 9:27:58 AM - Info dbclient(pid=4968) INF - Created VDI object for SQL Server instance <TAHQ004vw0206.tarjeta.local>. Connection timeout is <300> seconds.
5/27/2016 9:51:32 AM - Info dbclient(pid=4968) INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]10 percent processed.>.
5/27/2016 10:14:24 AM - Info dbclient(pid=4968) INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]20 percent processed.>.
5/27/2016 10:37:56 AM - Info dbclient(pid=4968) INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]30 percent processed.>.
5/27/2016 11:00:48 AM - Info dbclient(pid=4968) INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]40 percent processed.>.
5/27/2016 11:23:50 AM - Info dbclient(pid=4968) INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]50 percent processed.>.
5/27/2016 11:46:57 AM - Info dbclient(pid=4968) INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]60 percent processed.>.
5/27/2016 12:09:44 PM - Info dbclient(pid=4968) INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]70 percent processed.>.
5/27/2016 12:33:01 PM - Info dbclient(pid=4968) INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]80 percent processed.>.
5/27/2016 12:55:53 PM - Info dbclient(pid=4968) INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]90 percent processed.>.
5/27/2016 1:18:53 PM - Info dbclient(pid=4968) ERR - Error in GetCommand: 0x80770004.       
5/27/2016 1:18:53 PM - Info dbclient(pid=4968)     CONTINUATION: - An abort request is preventing anything except termination actions.
5/27/2016 1:18:53 PM - Info dbclient(pid=4968) DBMS MSG - ODBC return code <-1>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]100 percent processed.>.
5/27/2016 1:18:53 PM - Info dbclient(pid=4968) DBMS MSG - SQL Message <3241><[Microsoft][ODBC SQL Server Driver][SQL Server]The media family on device 'VNBU0-4968-5252-1464352077' is incorrectly formed. SQL Server cannot process this media family.>
5/27/2016 1:18:53 PM - Info dbclient(pid=4968) DBMS MSG - SQL Message <3013><[Microsoft][ODBC SQL Server Driver][SQL Server]RESTORE DATABASE is terminating abnormally.>
5/27/2016 1:18:53 PM - Info dbclient(pid=4968) ERR - Error found executing <restore database "Carta" from VIRTUAL_DEVICE='VNBU0-4968-5252-1464352077' with  stats = 10, blocksize = 65536, maxtransfersize = 4194304, buffercount = 2, replace , norecovery, move 'Carta_Data' to 'D:\Databases\SqlServer\Carta.mdf', move 'Carta_Log' to 'D:\Databases\SqlServer\Carta.ldf', replace>.
5/27/2016 1:18:54 PM - Info dbclient(pid=4968) ERR - Error in VDS->Close: 0x80770004.       
5/27/2016 1:18:54 PM - Info dbclient(pid=4968)     CONTINUATION: - An abort request is preventing anything except termination actions.
5/27/2016 1:18:55 PM - Info dbclient(pid=4968) INF - OPERATION #1 of batch C:\Users\adm-900000009\Desktop\Restore Carta Mayo 2016 - 2.bch FAILED with STATUS 1 (0 is normal). Elapsed time = 13858(13858) seconds.
5/27/2016 1:18:57 PM - Info dbclient(pid=4968) INF - Results of executing <C:\Users\adm-900000009\Desktop\Restore Carta Mayo 2016 - 2.bch>:  
5/27/2016 1:18:57 PM - Info dbclient(pid=4968) <0> operations succeeded. <1> operations failed.  

********************************************************************************

I am looking into this errors now, see if I get any luck.

[Marianne]

Do you have bpbrm and bptm log folders on the media server?

Two TNs that may help:

​http://www.veritas.com/docs/000040093  

http://www.veritas.com/docs/000083083

[Ramiro-Magan]

Just changed the settings as it says in the articles, we´ll see what happens.

Here are the bpbrm and btm.

thanks for all your help Marianne.

[PatS729]

I didnt seen the job details posted for which the logs have gatherd, so couldnt trace the PID's of BPTM and BPBRM. However, this is what is logged in BPTM and BPBRM:

BPTM
12:07:14.066 [7140.4108] <2> put_length_bytes_nonblocking: cannot write data to network:  An existing connection was forcibly closed by the remote host.
12:07:14.066 [7140.4108] <16> send_job_file: Failed to send request [job ID 734018, ftype = 3 msg len = 74, msg = LOG 1464620834 4 bptm 7140 setting receive network buffer to 263168 bytes
]
12:07:14.066 [7140.4108] <2> set_job_details: Can't send tfile buffer, errno 2
12:07:14.066 [7140.4108] <16> bptm event_msg_to_monitor: failed to set job_details on master server myarsw00403bk01

BPTM
14:06:25.931 [4968.2752] <2> db_end: Need to collect reply
14:06:25.962 [4968.2752] <16> get_next_file: get_string() failed reading file list from bprd, (10054), network read error
14:06:26.555 [5204.6656] <2> mm_child_done: SIGCHLD: exit=23, pid=4968
14:06:26.555 [5204.6656] <2> notify: executing - D:\GEAplications\Veritas\NetBackup\bin\restore_notify.cmd bptm tahq002vw0186.tarjeta.local_1464490903 restore

BPBRM
14:06:26.727 [6804.7056] <2> put_length_bytes_nonblocking: cannot write data to network:  An existing connection was forcibly closed by the remote host.
14:06:26.727 [6804.7056] <16> send_job_file: Failed to send request [job ID 734014, ftype = 3 msg len = 137, msg = LOG 1464627986 4 bpbrm 6804 media manager for backup id tahq002vw0186.tarjeta.local_1464490903 exited with status 23: socket read failed
]
14:06:26.727 [6804.7056] <2> set_job_details: Can't send tfile buffer, errno 0
14:06:26.727 [6804.7056] <16> bpbrm send_event_msg_to_monitor: failed to set job_details on master server YÖô–ï¾   

14:06:26.727 [6804.7056] <2> put_length_bytes_nonblocking: cannot write data to network:  An operation was attempted on something that is not a socket.
14:06:26.727 [6804.7056] <2> job_disconnect: Failed to send request

There is something bad at the Network between Master/Media and Client. Please involve your Network Team to investigate Network Performance.

[Marianne · Accepted solution]

Try to change KeepAlive settings on master, media and destination client. This discussion is about a different status code, but use the URLs to see how to change KeepAlive settings: https://www.veritas.com/community/forums/error-636

[Michael_G_Ander]

Also look at the instant file creation in the SQL admin guide, as I understand it does that the SQL server dosn't "format" the files before writning to them.

[Ramiro-Magan]

I adjusted tcpip parameter to match the recomended 15 minutes.

Also checked connectivity, I had a problem between the originating host and the media server, kind of strange as it takes backups every single day.

Anyway, don´t know if it matters, but the way things are setup, I didn´t mention it before, I have two locations.

Location 1:

Master Server

Destination Client

Location 2

Media Server

Originating client

I am doing a cross site restore, again, with small DBs it works just fine.

I am waiting to restart the servers and try again with the new changes.

Thanks you all for the help, will keep you posted as soon as it finishes.

[PatS729]

I would suggest to fix Network inconsistency first.

[Ramiro-Magan]

Well, thread can be closed.

The connectivity problem was with the originating server, which I understand it´s not really used in this restore, as it is only used for the name.

So the TTL should have been the one that did the trick.

Thank you all for your help, I can always rely on you guys.

[Marianne]

You can close the thread by marking a Solution or Split Solution.