SQL 2008 tape restore failed

Yet · ‎11-15-2012

Hi,

I've been haunted for days now by this failure. I'm unable to restore SQL database from tape but from disk is fine. unfortunately, i have to restore this particular image and copy is only on tape.

Netbackup: 7.5.0.3 (SFHA clustered)

Master server: Windows 2008

Media server: 5220 Appliance (LTO3 tape is connected here)

client SQL: 2008

client OS: Windows 2008

I've changed the CLIENT_READ_TIMEOUT (both client & media server) to 10800 thinking that reading just taking so much time but nothing.

I've changed STU max fragment size to 2GB thinking that it just cannot handle large fragment but nothing.

I have here snippets of the logs. sorry I don't know how to attach this as file.

Would appreciate much if anyone can shed some light.

From client,

INF - RESTORE STARTED USING

Microsoft SQL Server 2008 (SP2) - 10.0.4000.0 (X64)

Sep 16 2010 19:43:16

Standard Edition (64-bit) on Windows NT 6.1 <X64> (Build 7601: Service Pack 1)

Batch = C:\Users\backupadmin\Desktop\sms_rcc_2410.bch, Op# = 1.

INF - Restoring from <2> images. The first is <RCJSCCM.MSSQL7.RCJSCCM.db.SMS_RCC.~.7.001of002.20121011000400..C>.

INF - restore database "SMS_RCC_2410" from VIRTUAL_DEVICE='VNBU0-10016-13196-1353008193', VIRTUAL_DEVICE='VNBU1-10016-13196-1353008193' with stats = 10, blocksize = 65536, maxtransfersize = 4194304, buffercount = 2, replace , norecovery, move 'SMS_RCC' to 'D:\Program Files\Microsoft SQL Server\MSSQL10.MSSQLSERVER\MSSQL\Data\SMS_RCC_2410.mdf', move 'SMS_RCC_log' to 'D:\Program Files\Microsoft SQL Server\MSSQL10.MSSQLSERVER\MSSQL\Data\SMS_RCC_2410_log.LDF', replace

INF - Number of stripes: 2, Number of buffers per stripe 1.

INF - Created VDI object for SQL Server instance <RCJSCCM>. Connection timeout is <300> seconds.

Restore started Thu Nov 15 22:36:34 2012

01:37:18.328 [10016.424] <4> : 01:37:17 (67695.001) INF - Waiting for positioning of media id 000351 on server rcjnbuapl1 for reading.

ERR - Error in VxBSAGetData: 3.

CONTINUATION: - System detected error, operation aborted.

ERR - Internal error. See the dbclient log for more information.

ERR - Error in DBthreads::dbclient: 6.

CONTINUATION: - The system cannot find the file specified.

ERR - Error in VxBSAEndData: 6.

CONTINUATION: - The handle used to associate this call with a previous VxBSAInit() call is invalid.

INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]10 percent processed.>.

INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]20 percent processed.>.

INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]30 percent processed.>.

INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]40 percent processed.>.

From admin console job details,

11/15/2012 10:36:25 PM - Info bpbrm(pid=29545) rcjsccm is the host to restore to

11/15/2012 10:36:25 PM - Info bpbrm(pid=29545) telling media manager to start restore on client

11/15/2012 10:36:26 PM - Info bpbrm(pid=29545) spawning a brm child process

11/15/2012 10:36:26 PM - Info bpbrm(pid=29545) child pid: 29550

11/15/2012 10:36:26 PM - Info bpbrm(pid=29545) listening for client connection

11/15/2012 10:36:27 PM - Info bpbrm(pid=29545) accepted connection from client

11/15/2012 10:36:27 PM - Info tar(pid=10016) Restore started.

11/15/2012 10:36:27 PM - connected

11/15/2012 10:36:29 PM - mounted

11/15/2012 10:36:29 PM - Info bptm(pid=29548) 000351

11/15/2012 10:36:30 PM - Info bptm(pid=29548) INF - Waiting for positioning of media id 000351 on server rcjnbuapl1 for reading.

11/15/2012 10:36:30 PM - positioning 000351 to file 30

11/15/2012 10:36:38 PM - begin Restore

11/15/2012 10:36:39 PM - 1 images required

11/15/2012 10:36:39 PM - media 000351 required

11/15/2012 10:36:41 PM - restoring image rcjsccm_1349903048

11/15/2012 10:36:46 PM - requesting resource 000351

11/15/2012 10:36:46 PM - granted resource 000351

11/15/2012 10:36:46 PM - granted resource Drive002

11/15/2012 10:36:48 PM - positioned 000351; position time: 00:00:18

11/15/2012 10:36:48 PM - begin reading

11/16/2012 1:36:49 AM - Error bpbrm(pid=29550) socket read failed: errno = 62 - Timer expired

11/16/2012 1:36:49 AM - Info bpbrm(pid=29545) sending message to media manager: STOP RESTORE rcjsccm_1349903048

11/16/2012 1:36:50 AM - Info bpbrm(pid=29545) media manager for backup id rcjsccm_1349903048 exited with status 150: termination requested by administrator

11/16/2012 1:37:07 AM - restored image rcjsccm_1349903048 - (file read failed(13)); restore time 03:00:26

11/16/2012 1:37:14 AM - end Restore; elapsed time: 03:00:36

Restore error(2850)

From another child job,

11/15/2012 10:36:32 PM - begin Restore

11/15/2012 10:36:33 PM - Info dbclient(pid=10016) INF - RESTORE STARTED USING

11/15/2012 10:36:33 PM - Info dbclient(pid=10016) Microsoft SQL Server 2008 (SP2) - 10.0.4000.0 (X64)

11/15/2012 10:36:33 PM - Info dbclient(pid=10016) Sep 16 2010 19:43:16

11/15/2012 10:36:33 PM - Info dbclient(pid=10016) Standard Edition (64-bit) on Windows NT 6.1 <X64> (Build 7601: Service Pack 1)

11/15/2012 10:36:33 PM - Info dbclient(pid=10016) Batch = C:\Users\backupadmin\Desktop\sms_rcc_2410.bch, Op# = 1.

11/15/2012 10:36:33 PM - Info dbclient(pid=10016) INF - Restoring from <2> images. The first is <RCJSCCM.MSSQL7.RCJSCCM.db.SMS_RCC.~.7.001of002.20121011000400..C>.

11/15/2012 10:36:33 PM - Info dbclient(pid=10016) INF - restore database "SMS_RCC_2410" from VIRTUAL_DEVICE='VNBU0-10016-13196-1353008193', VIRTUAL_DEVICE='VNBU1-10016-13196-1353008193' with stats = 10, blocksize = 65536, maxtransfersize = 4194304, buffercount = 2, replace , norecovery, move 'SMS_RCC' to 'D:\Program Files\Microsoft SQL Server\MSSQL10.MSSQLSERVER\MSSQL\Data\SMS_RCC_2410.mdf', move 'SMS_RCC_log' to 'D:\Program Files\Microsoft SQL Server\MSSQL10.MSSQLSERVER\MSSQL\Data\SMS_RCC_2410_log.LDF', replace

11/15/2012 10:36:33 PM - Info dbclient(pid=10016) INF - Number of stripes: 2, Number of buffers per stripe 1.

11/15/2012 10:36:34 PM - Info dbclient(pid=10016) INF - Created VDI object for SQL Server instance <RCJSCCM>. Connection timeout is <300> seconds.

11/16/2012 1:37:32 AM - Info dbclient(pid=10016) ERR - Error in VxBSAGetData: 3.

11/16/2012 1:37:32 AM - Info dbclient(pid=10016) CONTINUATION: - System detected error, operation aborted.

11/16/2012 1:37:42 AM - Info dbclient(pid=10016) ERR - Internal error. See the dbclient log for more information.

11/16/2012 1:37:42 AM - Info dbclient(pid=10016) ERR - Error in DBthreads::dbclient: 6.

11/16/2012 1:37:42 AM - Info dbclient(pid=10016) CONTINUATION: - The system cannot find the file specified.

11/16/2012 1:37:42 AM - Info dbclient(pid=10016) ERR - Error in VxBSAEndData: 6.

11/16/2012 1:37:43 AM - Info dbclient(pid=10016) CONTINUATION: - The handle used to associate this call with a previous VxBSAInit() call is invalid.

11/16/2012 1:38:18 AM - Info dbclient(pid=10016) INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]10 percent processed.>.

11/16/2012 1:38:40 AM - Info dbclient(pid=10016) INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]20 percent processed.>.

11/16/2012 1:39:07 AM - Info dbclient(pid=10016) INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]30 percent processed.>.

11/16/2012 1:39:28 AM - Info dbclient(pid=10016) INF - ODBC return code <2>, SQL State <01000>, SQL Message <3211><[Microsoft][ODBC SQL Server Driver][SQL Server]40 percent processed.>.

from media server (bptm) log,

00:01:20.920 [14734] <2> bptm: INITIATING (VERBOSE = 0): -rptdrv -jobid -1352290465 -jm
00:01:20.920 [14734] <2> ParseConfigExA: Option (CLIENT_READ_TIMEOUT) redefined on line 30, discarding definition on line 18.
00:01:20.921 [14734] <2> drivename_open: Called with Create 0, file Drive002
00:01:20.921 [14734] <2> drivename_checklock: Called
00:01:20.921 [14734] <2> drivename_checklock: PID 29548 has lock
00:01:20.921 [14734] <2> report_drives: DRIVE = Drive002 LOCK = TRUE CURTIME = 1353012856
00:01:20.927 [14734] <2> report_drives: MODE = 0
00:01:20.927 [14734] <2> report_drives: TIME = 1353008189
00:01:20.927 [14734] <2> report_drives: SR_KEY = 0 1
00:01:20.927 [14734] <2> report_drives: PATH = /dev/nst0
00:01:20.927 [14734] <2> report_drives: MEDIA = 000351
00:01:20.927 [14734] <2> report_drives: REQID = 67694
00:01:20.928 [14734] <2> report_drives: ALOCID = 470537
00:01:20.928 [14734] <2> report_drives: RBID = {96E7C896-CED5-4CF5-AC3C-E65FEEC20989}
00:01:20.928 [14734] <2> report_drives: PID = 29548
00:01:20.928 [14734] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_Drive002
00:01:20.928 [14734] <2> drivename_open: Called with Create 0, file Drive004
00:01:20.928 [14734] <2> drivename_checklock: Called
00:01:20.928 [14734] <2> drivename_checklock: PID 26138 has lock
00:01:20.928 [14734] <2> report_drives: DRIVE = Drive004 LOCK = TRUE CURTIME = 1353012856
00:01:20.928 [14734] <2> report_drives: MODE = 0
00:01:20.928 [14734] <2> report_drives: TIME = 1353005437
00:01:20.928 [14734] <2> report_drives: SR_KEY = 0 1
00:01:20.928 [14734] <2> report_drives: PATH = /dev/nst2
00:01:20.928 [14734] <2> report_drives: MEDIA = 000741
00:01:20.928 [14734] <2> report_drives: REQID = 67575
00:01:20.928 [14734] <2> report_drives: ALOCID = 470536
00:01:20.928 [14734] <2> report_drives: RBID = {F85CEED5-37D5-4DA0-9B10-500ED76E7AE1}
00:01:20.928 [14734] <2> report_drives: PID = 26138
00:01:20.928 [14734] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_Drive004
00:01:20.928 [14734] <2> main: Sending [EXIT STATUS 0] to NBJM
00:01:20.928 [14734] <2> bptm: EXITING with status 0 <----------
…..

01:43:53.923 [29548] <2> read_brm_msg: STOP RESTORE client_1349903048
01:43:53.923 [29548] <2> notify: executing - /usr/openv/netbackup/bin/restore_notify bptm client_1349903048 restore
01:43:53.956 [29548] <2> Media_dispatch_signal: calling child_wait (tmcommon.c:3963) delay 0 seconds
01:43:53.956 [29548] <2> KILL_MM_CHILD: Sending SIGUSR2 (kill) to child 29549 (tmmpx.c:1749)
01:43:53.956 [29549] <2> write_to_out: Terminating child for partial DB restore
01:43:53.956 [29549] <2> terminate_restore: [29548] waited for full buffer 1 times, delayed 1 times
01:43:53.956 [29549] <2> terminate_restore: [29548] sent 1 directories/files to client client
01:43:53.967 [29548] <2> send_brm_msg: EXIT client_1349903048 150
01:43:53.967 [29548] <2> bct_clear_active: Set BCTable entry 0 to inactive, ACTIVE_GC count decremented to 0
01:43:53.983 [29548] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1
01:43:53.984 [29548] <2> ParseConfigExA: Option (CLIENT_READ_TIMEOUT) redefined on line 30, discarding definition on line 18.
01:43:53.984 [29548] <2> ParseConfigExA: Option (CLIENT_READ_TIMEOUT) redefined on line 30, discarding definition on line 18.
01:43:53.985 [29548] <2> ParseConfigExA: Option (CLIENT_READ_TIMEOUT) redefined on line 30, discarding definition on line 18.
01:43:53.985 [29548] <2> ParseConfigExA: Option (CLIENT_READ_TIMEOUT) redefined on line 30, discarding definition on line 18.
01:43:53.985 [29548] <2> ParseConfigExA: Option (CLIENT_READ_TIMEOUT) redefined on line 30, discarding definition on line 18.
01:43:53.985 [29548] <2> ParseConfigExA: Option (CLIENT_READ_TIMEOUT) redefined on line 30, discarding definition on line 18.
01:43:53.993 [29548] <2> vnet_pbxConnect: pbxConnectEx Succeeded
01:43:53.994 [29548] <2> logconnections: BPDBM CONNECT FROM 10.10.40.95.50184 TO 10.10.40.88.1556 fd = 20
01:43:53.994 [29548] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
01:43:54.039 [29548] <2> db_end: Need to collect reply
01:43:54.043 [29548] <4> report_throughput: VBRT 1 29548 4 1 Drive002 000351 0 0 2176 (mpxrestore.c.1479)
01:43:54.043 [29548] <2> mpx_read_data: waited for empty buffer 2 times, delayed 671395 times
01:43:54.043 [29548] <2> send_brm_msg: MEDIA NOT READY
01:43:54.043 [29548] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_Drive002, from mpxrestore.c.3102
01:43:54.043 [29548] <2> mpx_waiting_term: waiting for TERMINATE or another START RESTORE
01:43:54.475 [29548] <2> read_brm_msg: TERMINATE
01:43:54.476 [29548] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tpunmount)
01:43:54.476 [29548] <2> drivename_write: Called with mode 1
01:43:54.476 [29548] <2> drivename_unlock: unlocked
01:43:54.476 [29548] <2> drivename_close: Called for file Drive002
01:43:54.476 [29548] <2> tpunmount: NOP: MEDIA_DONE 0 0 0 000351 4000220 180 {96E7C896-CED5-4CF5-AC3C-E65FEEC20989}
01:43:54.477 [29548] <2> ConnectionCache::connectAndCache: Acquiring new connection for host masterserver, query type 1
01:43:54.477 [29548] <2> ParseConfigExA: Option (CLIENT_READ_TIMEOUT) redefined on line 30, discarding definition on line 18.
01:43:54.477 [29548] <2> ParseConfigExA: Option (CLIENT_READ_TIMEOUT) redefined on line 30, discarding definition on line 18.
01:43:54.478 [29548] <2> ParseConfigExA: Option (CLIENT_READ_TIMEOUT) redefined on line 30, discarding definition on line 18.
01:43:54.478 [29548] <2> ParseConfigExA: Option (CLIENT_READ_TIMEOUT) redefined on line 30, discarding definition on line 18.
01:43:54.479 [29548] <2> ParseConfigExA: Option (CLIENT_READ_TIMEOUT) redefined on line 30, discarding definition on line 18.
01:43:54.479 [29548] <2> ParseConfigExA: Option (CLIENT_READ_TIMEOUT) redefined on line 30, discarding definition on line 18.
01:43:54.488 [29548] <2> vnet_pbxConnect: pbxConnectEx Succeeded
01:43:54.489 [29548] <2> logconnections: BPDBM CONNECT FROM 10.10.40.95.44316 TO 10.10.40.88.1556 fd = 18
01:43:54.489 [29548] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
01:43:54.538 [29548] <2> db_end: Need to collect reply
01:43:54.542 [29548] <4> mpx_read_backup: successfully restored 0 of 1 requests, read total of 2176 Kbytes at 0.201 Kbytes/sec
01:43:54.543 [29548] <2> bptm: Calling tpunmount for media 000351
01:43:54.543 [29548] <2> send_MDS_msg: MEDIA_DONE 0 67694 0 000351 4000220 180 {96E7C896-CED5-4CF5-AC3C-E65FEEC20989}
01:43:54.543 [29548] <2> packageBptmResourceDoneMsg: msg (MEDIA_DONE 0 67694 0 000351 4000220 180 {96E7C896-CED5-4CF5-AC3C-E65FEEC20989})
01:43:54.543 [29548] <2> packageBptmResourceDoneMsg: keyword MEDIA_DONE version 0 jobid 67694 copyNum 0 mediaId 000351 mediaKey 4000220 unloadDelay 180 allocId {96E7C896-CED5-4CF5-AC3C-E65FEEC20989}
01:43:54.543 [29548] <2> packageBptmResourceDoneMsg: returns 0
01:43:54.568 [29548] <2> JobInst::sendIrmMsg: returning
01:43:54.568 [29548] <2> bptm: EXITING with status 0 <----------

from media server (bpbrm) log,

22:43:27.894 [29545] <2> bpbrm main: INITIATING (VERBOSE = 0): version NetBackup 7.5 2012050902
22:43:27.894 [29545] <2> logparams: -restore -mpx_restore -S rcjnbu -mt 2 -to 0 -mud 180 -mediasvr rcjnbuapl1 -masterversion 750000
22:43:27.894 [29545] <4> bpbrm main: ensured stderr cannot be used
22:43:27.895 [29545] <2> ParseConfigExA: Option (CLIENT_READ_TIMEOUT) redefined on line 30, discarding definition on line 18.
22:43:27.921 [29545] <2> vnet_pbxConnect: pbxConnectEx Succeeded
22:43:27.921 [29545] <2> logconnections: BPRD CONNECT FROM 10.10.40.95.60300 TO 10.10.40.88.1556 fd = 4
22:43:27.921 [29545] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
22:43:28.033 [29545] <2> ParseConfigExA: Option (CLIENT_READ_TIMEOUT) redefined on line 30, discarding definition on line 18.
22:43:28.033 [29545] <2> brm_update_local_resiliency: changed = 0
22:43:28.047 [29545] <2> bpbrm send_parent_msg: PID of bpbrm = 29545

22:43:28.047 [29545] <2> ConnectionCache::connectAndCache: Acquiring new connection for host rcjnbu, query type 223
22:43:28.051 [29545] <2> vnet_pbxConnect: pbxConnectEx Succeeded
22:43:28.052 [29545] <2> logconnections: BPDBM CONNECT FROM 10.10.40.95.42034 TO 10.10.40.88.1556 fd = 4
22:43:28.052 [29545] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
22:43:28.097 [29545] <2> db_CLIENTsend: reset client protocol version from 0 to 8
22:43:28.301 [29545] <2> db_getCLIENT: db_CLIENTreceive: no entity was found 227
22:43:28.303 [29545] <2> vnet_pbxConnect: pbxConnectEx Succeeded
22:43:28.304 [29545] <2> logconnections: BPCD CONNECT FROM 10.10.40.95.53027 TO 10.10.40.95.1556 fd = 4
22:43:28.306 [29545] <2> vnet_pbxConnect: pbxConnectEx Succeeded
22:43:28.307 [29545] <8> do_pbx_service: [vnet_connect.c:2108] via PBX VNETD CONNECT FROM 10.10.40.95.48186 TO 10.10.40.95.1556 fd = 5
22:43:28.307 [29545] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:443] VN_REQUEST_CONNECT_FORWARD_SOCKET 10 0xa
22:43:28.346 [29545] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:460] ipc_string /tmp/vnet-29547353008184345871000000561-WzkuoM
22:43:28.429 [29545] <2> bpbrm start_bpcd_stat: DATA_SOCK from bpcr = 4
22:43:28.429 [29545] <2> bpbrm start_bpcd_stat: NAME_SOCK from bpcr = 5
22:43:28.429 [29545] <2> bpbrm multiplexed_restore: Started media manager using bpcd successfully.
22:43:28.430 [29545] <2> bpbrm multiplexed_restore: calling read_media_msg for media manager PID.
22:43:28.729 [29545] <2> bpbrm read_media_msg: read from media manager: PID of bpxm = 29548
22:43:28.729 [29545] <2> bpbrm read_parent_msg: read from parent START RESTORE -k 0 -c rcjsccm -hostname rcjsccm -rclnt rcjsccm -rclnthostname rcjsccm -browse_clnt RCJSCCM -ru root -firstblk 0 -cl SQL_RCJSCCM_Weekly -bt 1349903048 -st 2 -secure 1 -b rcjsccm_1349903048 -cn 2 -rst 1353008194 -ct 15 -flport 0 -flipc 57345 -restoreid 67694.001 -jobid 67694 -job_total 1 -m 000351 -rg root -cv -L /C/Program��Files/Veritas/NetBackup/Logs/user_ops/mssql/logs/1115112223632-10016-1872-000-000-prg -hqdb -cfc -clnt_lc_messages C -clnt_lc_time C -clnt_lc_ctype C -clnt_lc_collate C -clnt_lc_numeric C
22:43:28.730 [29545] <2> bpbrm process_start_restore_msg: processing START RESTORE message.
22:43:28.730 [29545] <2> ConnectionCache::connectAndCache: Acquiring new connection for host rcjnbu, query type 223
22:43:28.733 [29545] <2> vnet_pbxConnect: pbxConnectEx Succeeded
22:43:28.733 [29545] <2> logconnections: BPDBM CONNECT FROM 10.10.40.95.59337 TO 10.10.40.88.1556 fd = 7
22:43:28.734 [29545] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
22:43:28.778 [29545] <2> db_CLIENTsend: reset client protocol version from 0 to 8
22:43:28.988 [29545] <2> db_end: Need to collect reply
22:43:28.988 [29545] <2> db_freeEXDB_INFO: ?
22:43:28.996 [29545] <2> vnet_pbxConnect: pbxConnectEx Succeeded
22:43:28.996 [29545] <2> logconnections: BPCD CONNECT FROM 10.10.40.95.57808 TO 10.10.40.84.1556 fd = 7
22:43:29.000 [29545] <2> vnet_pbxConnect: pbxConnectEx Succeeded
22:43:29.056 [29545] <8> do_pbx_service: [vnet_connect.c:2108] via PBX VNETD CONNECT FROM 10.10.40.95.46985 TO 10.10.40.84.1556 fd = 8
22:43:29.056 [29545] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:443] VN_REQUEST_CONNECT_FORWARD_SOCKET 10 0xa
22:43:29.252 [29545] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:460] ipc_string 54059
22:43:29.402 [29545] <2> bpbrm start_bpcd_stat: DATA_SOCK from bpcr = 7
22:43:29.402 [29545] <2> bpbrm start_bpcd_stat: NAME_SOCK from bpcr = 8
22:43:29.403 [29545] <2> bpcr_get_version_rqst: bpcd version: 07500003
22:43:29.410 [29545] <2> vnet_pbxConnect: pbxConnectEx Succeeded
22:43:29.410 [29545] <2> job_connect: SO_KEEPALIVE set on socket 7 for client rcjnbu
22:43:29.410 [29545] <2> logconnections: BPJOBD CONNECT FROM 10.10.40.95.42124 TO 10.10.40.88.1556 fd = 7
22:43:29.410 [29545] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
22:43:29.411 [29545] <2> job_connect: Connected to the host rcjnbu contype 53 jobid <67694> socket <7>
22:43:29.411 [29545] <2> job_connect: Connected on port 42124
22:43:29.412 [29545] <2> allocate_ft_media: Request FT resources with 1
22:43:29.418 [29545] <2> ParseConfigExA: Option (CLIENT_READ_TIMEOUT) redefined on line 30, discarding definition on line 18.
22:43:29.419 [29545] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:594)
22:43:29.419 [29545] <2> Orb::init: initializing ORB EMMlib_Orb with: bpbrm -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static Resource_Factory '-ORBNativeCharCodeSet UTF-8'" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBDefaultInitRef '' -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb EMMlib_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBSvcConf /dev/null -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:825)
22:43:29.422 [29545] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:840)
22:43:29.423 [29545] <2> Orb::setOrbConnectTimeout: timeout seconds: 60(Orb.cpp:1481)
22:43:29.423 [29545] <2> Orb::setOrbRequestTimeout: timeout seconds: 1800(Orb.cpp:1490)
22:43:29.425 [29545] <2> ParseConfigExA: Option (CLIENT_READ_TIMEOUT) redefined on line 30, discarding definition on line 18.
22:43:29.425 [29545] <2> ParseConfigExA: Option (CLIENT_READ_TIMEOUT) redefined on line 30, discarding definition on line 18.
22:43:29.446 [29545] <2> shouldWeAllocateFT: client rcjsccm is not a SAN client (2000000)
22:43:29.446 [29545] <2> bpbrm tell_mm_to_start_restore: telling media manager to start.
22:43:29.447 [29545] <2> bpbrm multiplexed_restore: calling read_media_msg for DATASOCKET.
22:43:30.145 [29545] <2> bpbrm read_media_msg: read from media manager: NCB_DATASOCKET rcjsccm_1349903048 54061;92383510782aff71be10cb6e69081ef2;11;900
22:43:30.145 [29545] <2> bpbrm multiplexed_restore: DATASOCKET = 0 for backup_id rcjsccm_1349903048
22:43:30.145 [29545] <2> bpbrm spawn_brm_child: spawning child
22:43:30.151 [29550] <2> vnet_pbxConnect: pbxConnectEx Succeeded
22:43:30.151 [29550] <2> job_connect: SO_KEEPALIVE set on socket 7 for client rcjnbu
22:43:30.152 [29550] <2> logconnections: BPJOBD CONNECT FROM 10.10.40.95.40536 TO 10.10.40.88.1556 fd = 7
22:43:30.152 [29550] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
22:43:30.152 [29550] <2> job_connect: Connected to the host rcjnbu contype 53 jobid <67694> socket <7>
22:43:30.152 [29550] <2> job_connect: Connected on port 40536
22:43:30.152 [29550] <2> bpbrm listen_for_client: HOT_SQL_SERVER_DB_RESTORE
22:43:30.157 [29550] <2> vnet_pbxConnect: pbxConnectEx Succeeded
22:43:30.209 [29550] <8> do_pbx_service: [vnet_connect.c:2108] via PBX VNETD CONNECT FROM 10.10.40.95.43344 TO 10.10.40.84.1556 fd = 13
22:43:30.210 [29550] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:443] VN_REQUEST_CONNECT_FORWARD_SOCKET 10 0xa
22:43:30.345 [29545] <2> bpbrm spawn_brm_child: bpbrm child pid = 29550
22:43:30.418 [29550] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:460] ipc_string 54062
22:43:30.461 [29550] <2> vnet_pbxConnect: pbxConnectEx Succeeded
22:43:30.514 [29550] <8> do_pbx_service: [vnet_connect.c:2108] via PBX VNETD CONNECT FROM 10.10.40.95.35215 TO 10.10.40.84.1556 fd = 14
22:43:30.514 [29550] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:443] VN_REQUEST_CONNECT_FORWARD_SOCKET 10 0xa
22:43:30.712 [29550] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:460] ipc_string 54064
22:43:30.754 [29550] <2> ParseConfigExA: Option (CLIENT_READ_TIMEOUT) redefined on line 30, discarding definition on line 18.
22:43:30.758 [29550] <2> vnet_pbxConnect: pbxConnectEx Succeeded
22:43:30.758 [29550] <2> logconnections: BPCD CONNECT FROM 10.10.40.95.39443 TO 10.10.40.84.1556 fd = 15
22:43:30.762 [29550] <2> vnet_pbxConnect: pbxConnectEx Succeeded
22:43:30.816 [29550] <8> do_pbx_service: [vnet_connect.c:2108] via PBX VNETD CONNECT FROM 10.10.40.95.53806 TO 10.10.40.84.1556 fd = 16
22:43:30.817 [29550] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:443] VN_REQUEST_CONNECT_FORWARD_SOCKET 10 0xa
22:43:31.025 [29550] <8> vnet_vnetd_connect_forward_socket_begin: [vnet_vnetd.c:460] ipc_string 54066
22:43:31.148 [29550] <2> bpbrm send_info_via_progress_file: CLIENT_CMD_SOCK from bpcr = 15
22:43:31.148 [29550] <2> bpbrm send_info_via_progress_file: CLIENT_STAT_SOCK from bpcr = 16
22:43:31.149 [29550] <2> bpcr_get_peername_rqst: Server peername length = 24
22:43:31.153 [29550] <2> bpbrm write_msg_to_progress_file: (67694.001) INF - Data socket = rcjnbuapl1.jubail.rc.gov.IPC:54062;3c88d0f1eb1686af28382ea3f6101082;11;900

22:43:31.153 [29550] <2> bpbrm write_msg_to_progress_file: (67694.001) INF - Name socket = rcjnbuapl1.jubail.rc.gov.IPC:54064;831d27ebb0d32fad49b88ef3dbe56319;11;900

22:43:31.154 [29550] <2> bpbrm write_msg_to_progress_file: (67694.001) INF - Job id = 67694

22:43:31.154 [29550] <2> bpbrm write_msg_to_progress_file: (67694.001) INF - Backup id = rcjsccm_1349903048

22:43:31.158 [29550] <2> bpbrm write_msg_to_progress_file: (67694.001) INF - Media server = rcjnbuapl1

22:43:31.158 [29550] <2> bpbrm write_msg_to_progress_file: (67694.001) INF - New data socket = rcjnbuapl1.jubail.rc.gov.IPC:54061;92383510782aff71be10cb6e69081ef2;11;900

22:43:31.159 [29550] <2> bpbrm write_msg_to_progress_file: (67694.001) INF - Use shared memory = 0

22:43:31.159 [29550] <2> bpbrm write_msg_to_progress_file: (67694.001) INF - Restore id = 67694.001

22:43:31.160 [29550] <2> bpbrm write_msg_to_progress_file: (67694.001) INF - Encrypt = 0

22:43:31.161 [29550] <2> bpbrm write_msg_to_progress_file: (67694.001) INF - Client read timeout = 10800

22:43:31.161 [29550] <2> bpbrm write_msg_to_progress_file: (67694.001) INF - Media mount timeout = 0

22:43:31.162 [29550] <2> bpbrm write_msg_to_progress_file: (67694.001) INF - client = rcjsccm

22:43:31.163 [29550] <2> bpbrm write_msg_to_progress_file: (67694.001) INF - requesting_client = rcjsccm

22:43:31.163 [29550] <2> bpbrm write_msg_to_progress_file: (67694.001) INF - browse_client = RCJSCCM

22:43:31.445 [29550] <2> bpbrm listen_for_client: DATA_SOCK for client = 13
22:43:31.445 [29550] <2> bpbrm listen_for_client: NAME_SOCK for client = 14
22:43:31.495 [29550] <2> bpbrm handle_restore: read tar start message from rcjsccm
22:43:52.757 [29545] <2> bpbrm read_media_msg: read from media manager: CURRENT POSITION 000351 30
22:43:52.757 [29545] <2> bpbrm send_parent_msg: CURRENT POSITION 000351 30
22:43:52.861 [29545] <2> bpbrm read_parent_msg: read from parent CONTINUE RESTORE
22:43:52.861 [29545] <2> bpbrm tell_mm: sending media manager msg: CONTINUE RESTORE
22:43:53.797 [29545] <2> bpbrm read_media_msg: read from media manager: MEDIA READY
22:43:53.797 [29545] <2> bpbrm signal_bpbrm_child: sending SIGUSR1 to bpbrm child 29550
22:43:53.797 [29550] <2> bpbrm mm_sig: received ready signal from media manager
22:48:54.046 [29545] <2> bpbrm send_parent_msg: KEEP_ALIVE 1

22:48:54.098 [29545] <2> bpbrm read_parent_msg: read from parent ACK_KEEP_ALIVE

…..
01:34:27.145 [29545] <2> bpbrm read_parent_msg: read from parent ACK_KEEP_ALIVE
01:39:28.030 [29545] <2> bpbrm send_parent_msg: KEEP_ALIVE 35

01:39:28.134 [29545] <2> bpbrm read_parent_msg: read from parent ACK_KEEP_ALIVE
01:43:53.799 [29550] <16> bpbrm readline: socket read failed: errno = 62 - Timer expired
01:43:53.799 [29550] <2> ConnectionCache::connectAndCache: Acquiring new connection for host rcjnbu, query type 1
01:43:53.847 [29550] <2> vnet_pbxConnect: pbxConnectEx Succeeded
01:43:53.848 [29550] <2> logconnections: BPDBM CONNECT FROM 10.10.40.95.36589 TO 10.10.40.88.1556 fd = 15
01:43:53.848 [29550] <8> vnet_check_vxss_client_magic_with_info: [vnet_vxss_helper.c:871] Ignoring VxSS authentication 2 0x2
01:43:53.897 [29550] <2> db_end: Need to collect reply
01:43:53.922 [29545] <2> bpbrm brm_sigcld: SIGCLD caught by bpbrm
01:43:53.922 [29545] <2> bpbrm brm_sigcld: bpbrm child 29550 exit_status = 13, signal_status = 0
01:43:53.922 [29545] <2> bpbrm brm_sigcld: child 29550 exited with status 13: file read failed
01:43:53.922 [29545] <2> bpbrm send_status_to_parent: bpbrm child is done, but the media manager child is not.
01:43:53.922 [29545] <2> bpbrm tell_mm: sending media manager msg: STOP RESTORE rcjsccm_1349903048
01:43:54.423 [29545] <2> bpbrm read_media_msg: read from media manager: EXIT rcjsccm_1349903048 150
01:43:54.423 [29545] <2> bpbrm process_media_msg: media manager for backup id rcjsccm_1349903048 exited with status 150: termination requested by administrator
01:43:54.423 [29545] <2> bpbrm send_status_to_parent: EXIT rcjsccm_1349903048 13 sent to parent process for jobid = 67694.
01:43:54.423 [29545] <2> bpbrm read_media_msg: read from media manager: MEDIA NOT READY
01:43:54.475 [29545] <2> bpbrm read_parent_msg: read from parent TERMINATE
01:43:54.475 [29545] <2> bpbrm tell_mm: sending media manager msg: TERMINATE

Yasuhisa_Ishika · ‎11-15-2012

First of all, have you already tried to duplicate backup images on tape to disk?
If not, please try and tell us the result.

Yet · ‎11-15-2012

Yes, the copy i'm trying to restore is a duplicated backup from disk. the image from disk already expired.

Yet · ‎11-15-2012

oops, sorry i got confused on your question. No, i have not. Leet me try that.

V4 · ‎11-16-2012

duplication would also ensure that tape blocks are readable and healthy for restores.

Also you can increase VDITIMEOUTINSECONDS to 3600 in restore script. check if this helps

Yet · ‎11-16-2012

I got it duplicated to disk and even used that disk copy to restore ok,

(1) why is it that it fails when getting from tape? btw, the tape copy is a 2nd copy duplicated to disk originally.

I have deduplication on the original disk copy,

(2) does it matter restoring from tape (duplicated copy)?

Also, I'm not using BAR, i'm using Netbackup Database Extension GUI. it creates script so i cannot determine the required images, not until the restore started from Admin Console.

(3) how could i list the images required on restoring sql database?

VOX

SQL 2008 tape restore failed