Restore has been failing with error code 2826

[wannawin]

Hello Team

Source client for restore is : Windows Master server

Destination client for restore is Linux Server

when i restore single file then restore completed successfully but when i am trying to restore full folder then restore has been failed with below mentioned error

8/7/2013 4:05:22 PM - begin Restore
8/7/2013 4:05:24 PM - 1 images required
8/7/2013 4:05:24 PM - media GR1092 required
8/7/2013 4:05:58 PM - restoring image auviua0002_1375348779
8/7/2013 4:05:59 PM - Info bpbrm(pid=9204) auviua0002 is the host to restore to     
8/7/2013 4:05:59 PM - Info bpbrm(pid=9204) telling media manager to start restore on client    
8/7/2013 4:06:00 PM - Info bptm(pid=8340) Waiting for mount of media id GR1092 (copy 1) on server auvisb5500.
8/7/2013 4:06:00 PM - started process bptm (8340)
8/7/2013 4:06:00 PM - mounting GR1092
8/7/2013 4:06:00 PM - Info bptm(pid=8340) INF - Waiting for mount of media id GR1092 on server auvisb5500 for reading.
8/7/2013 4:06:00 PM - Info bpbrm(pid=4740) auviua0002 is the host to restore to     
8/7/2013 4:06:00 PM - connecting
8/7/2013 4:06:00 PM - requesting resource GR1092
8/7/2013 4:06:00 PM - granted resource GR1092
8/7/2013 4:06:00 PM - granted resource HP.ULTRIUM4-SCSI.004
8/7/2013 4:06:02 PM - Info bpbrm(pid=4740) start tar32 on client        
8/7/2013 4:06:02 PM - Info tar32(pid=1621) Restore started.          
8/7/2013 4:06:02 PM - connected; connect time: 00:00:02
8/7/2013 4:07:06 PM - mounted; mount time: 00:01:06
8/7/2013 4:07:06 PM - Info bptm(pid=8340) GR1092           
8/7/2013 4:07:06 PM - Info bptm(pid=8340) INF - Waiting for positioning of media id GR1092 on server auvisb5500 for reading.
8/7/2013 4:07:06 PM - positioning GR1092 to file 74
8/7/2013 4:07:52 PM - positioned GR1092; position time: 00:00:46
8/7/2013 4:07:52 PM - begin reading
8/7/2013 5:08:09 PM - Info bpbrm(pid=9204) child done, status 41        
8/7/2013 5:08:09 PM - Info bpbrm(pid=9204) sending message to media manager: STOP RESTORE auviua0002_1375348779    
8/7/2013 5:08:10 PM - Error bptm(pid=8336) The following files/folders were not restored:      
8/7/2013 5:08:10 PM - Error bptm(pid=8336) UTF - /backup/backup4/inlive91/inlive91mfg.bck.gz         
8/7/2013 5:08:10 PM - Error bptm(pid=8336) UTF - /backup/backup4/inlive91/inlive91mfg.def         
8/7/2013 5:08:10 PM - Error bptm(pid=8336) UTF - /backup/backup4/inlive91/inlive91mfg.lg         
8/7/2013 5:08:10 PM - Error bptm(pid=8336) UTF - /backup/backup4/inlive91/inlive91mfg.st         
8/7/2013 5:08:10 PM - Error bptm(pid=8336) UTF - /backup/backup4/inlive91/inlive91mfg_add.st         
8/7/2013 5:08:10 PM - Error bptm(pid=8336) UTF - /backup/backup4/inlive91/inlive91mfg_srv.pf         
8/7/2013 5:08:10 PM - Error bptm(pid=8336) UTF - /backup/backup4/inlive91/inlive91mfg_usr.pf         
8/7/2013 5:08:10 PM - Error bptm(pid=8336) UTF - /backup/backup4/inlive91/inlive91mlp.bck.gz         
8/7/2013 5:08:10 PM - Error bptm(pid=8336) UTF - /backup/backup4/inlive91/inlive91mlp.def         
8/7/2013 5:08:10 PM - Error bptm(pid=8336) UTF - /backup/backup4/inlive91/inlive91mlp.lg         
8/7/2013 5:08:10 PM - Error bptm(pid=8336) more than 10 files were not restored, remaining ones are shown in the progress log.
8/7/2013 5:08:10 PM - Info bpbrm(pid=9204) media manager for backup id auviua0002_1375348779 exited with status 150: termination requested by administrator
8/7/2013 5:08:10 PM - restored image auviua0002_1375348779 - (network connection timed out(41)); restore time 01:02:12
8/7/2013 5:08:11 PM - end Restore; elapsed time: 01:02:49
invalid error number(2826)

Regards,

Davinder

[Marianne]

You need the following logs to troubleshoot:

On media server: bptm and bpbrm

On client: tar

If the files to be restored are quite big, it may be a good idea to increase Client Read Timeout to a higher value. If timeout is the default of 300 (5 min), try 900.
Ensure above log folders exist before you attempt another restore.

If restore still fails with higher Client Read Timeout value, please copy log files to .txt files (e.g. bptm.txt) and post as File attachments.

[wannawin]

Hello Marianne.

client read time out has been increased but restore has been failed again.

Please find attached bptm and bpbrm logs and will attach TAR logs shortly

[Marianne]

The logs are quite big because of level 5 logging.

Please tell us what time was the last restore attempt and show all text in Details tab. 

We need to see the tar log as well,

****EDIT ****

We REALLY need to see what happened on the client.

I can see in bptm log that the data was sent to the client:

23:02:35.744 [11920.11196] <2> wait_for_ready_socket: [2856] sent 48 directories/files to client auviua0002

tar log on client should tell us....

[wannawin]

Hello Marianne.

Please find detail status below..

8/7/2013 9:19:56 PM - begin Restore
8/7/2013 9:19:58 PM - 1 images required
8/7/2013 9:19:58 PM - media GR1092 required
8/7/2013 9:20:32 PM - restoring image auviua0002_1375348779
8/7/2013 9:20:34 PM - Info bpbrm(pid=11276) auviua0002 is the host to restore to     
8/7/2013 9:20:34 PM - Info bpbrm(pid=11276) telling media manager to start restore on client    
8/7/2013 9:20:35 PM - Info bpbrm(pid=11712) auviua0002 is the host to restore to     
8/7/2013 9:20:35 PM - connecting
8/7/2013 9:20:35 PM - requesting resource GR1092
8/7/2013 9:20:35 PM - awaiting resource GR1092 Reason: Drives are in use, Media Server: auvisb5500.hospira.corp,
  Robot Number: 0, Robot Type: TLD, Media ID: N/A, Drive Name: N/A,
  Volume Pool: N/A, Storage Unit: N/A, Drive Scan Host: N/A
 
8/7/2013 9:20:37 PM - Info bpbrm(pid=11712) start tar32 on client        
8/7/2013 9:20:37 PM - Info tar32(pid=4609) Restore started.          
8/7/2013 9:20:37 PM - connected; connect time: 00:00:02
8/7/2013 10:00:27 PM - Info bptm(pid=2856) Waiting for mount of media id GR1092 (copy 1) on server auvisb5500.
8/7/2013 10:00:27 PM - started process bptm (2856)
8/7/2013 10:00:27 PM - mounting GR1092
8/7/2013 10:00:27 PM - Info bptm(pid=2856) INF - Waiting for mount of media id GR1092 on server auvisb5500 for reading.
8/7/2013 10:00:27 PM - granted resource GR1092
8/7/2013 10:00:27 PM - granted resource HP.ULTRIUM4-SCSI.002
8/7/2013 10:01:32 PM - mounted; mount time: 00:01:05
8/7/2013 10:01:32 PM - Info bptm(pid=2856) GR1092           
8/7/2013 10:01:32 PM - Info bptm(pid=2856) INF - Waiting for positioning of media id GR1092 on server auvisb5500 for reading.
8/7/2013 10:01:32 PM - positioning GR1092 to file 74
8/7/2013 10:02:16 PM - positioned GR1092; position time: 00:00:44
8/7/2013 10:02:16 PM - begin reading
8/7/2013 11:02:35 PM - Info bpbrm(pid=11276) child done, status 41        
8/7/2013 11:02:35 PM - Info bpbrm(pid=11276) sending message to media manager: STOP RESTORE auviua0002_1375348779    
8/7/2013 11:02:36 PM - Error bptm(pid=11920) The following files/folders were not restored:      
8/7/2013 11:02:36 PM - Error bptm(pid=11920) UTF - /backup/backup4/inlive91/inlive91mfg.bck.gz         
8/7/2013 11:02:36 PM - Error bptm(pid=11920) UTF - /backup/backup4/inlive91/inlive91mfg.def         
8/7/2013 11:02:36 PM - Error bptm(pid=11920) UTF - /backup/backup4/inlive91/inlive91mfg.lg         
8/7/2013 11:02:36 PM - Error bptm(pid=11920) UTF - /backup/backup4/inlive91/inlive91mfg.st         
8/7/2013 11:02:36 PM - Error bptm(pid=11920) UTF - /backup/backup4/inlive91/inlive91mfg_add.st         
8/7/2013 11:02:36 PM - Error bptm(pid=11920) UTF - /backup/backup4/inlive91/inlive91mfg_srv.pf         
8/7/2013 11:02:36 PM - Error bptm(pid=11920) UTF - /backup/backup4/inlive91/inlive91mfg_usr.pf         
8/7/2013 11:02:36 PM - Error bptm(pid=11920) UTF - /backup/backup4/inlive91/inlive91mlp.bck.gz         
8/7/2013 11:02:36 PM - Error bptm(pid=11920) UTF - /backup/backup4/inlive91/inlive91mlp.def         
8/7/2013 11:02:36 PM - Error bptm(pid=11920) UTF - /backup/backup4/inlive91/inlive91mlp.lg         
8/7/2013 11:02:36 PM - Error bptm(pid=11920) more than 10 files were not restored, remaining ones are shown in the progress log.
8/7/2013 11:02:36 PM - Info bpbrm(pid=11276) media manager for backup id auviua0002_1375348779 exited with status 150: termination requested by administrator
8/7/2013 11:02:36 PM - restored image auviua0002_1375348779 - (network connection timed out(41)); restore time 01:42:04
8/7/2013 11:02:37 PM - Warning bprd(pid=10116) Restore must be resumed prior to first image expiration on 9/1/2013 7:19:39 PM
8/7/2013 11:02:37 PM - end Restore; elapsed time: 01:42:41
invalid error number(2826)

[wannawin]

Hello Marianne.

Sorry for Delay, Please find TAR logs below..

[root@auviua0002 tar]# more log.081213

20:05:40 (161844.001) INF - TAR STARTED 31902

20:05:40 (161844.001) Setting network receive buffer size to 32032 bytes

20:07:34 (161844.001) CKP - 161844.001 1376302054 0 0 2 1 0 0 38 /backup/backup4/chqliv/chqempty.bck.gz

20:24:35 (161846.001) INF - TAR STARTED 32074

20:24:35 (161846.001) Setting network receive buffer size to 32032 bytes

20:27:48 (161846.001) CKP - 161846.001 1376303268 0 0 3 2 0 0 38 /backup/backup4/chqliv/chqempty.bck.gz

[root@auviua0002 tar]# more log.081013

02:49:16 (160931.002) INF - TAR STARTED 27640

02:49:16 (160931.002) Setting network receive buffer size to 32032 bytes

02:59:05 (160931.002) CKP - 160931.002 1376067545 0 0 2 1 0 0 36 /backup/backup4/inlive91/inlive91.pf

03:11:35 (161017.001) INF - TAR STARTED 27864

03:11:35 (161017.001) Setting network receive buffer size to 32032 bytes

03:12:33 (161017.001) CKP - 161017.001 1376068353 0 0 2 1 0 0 30 /backup/backup4/rpt/chqliv.tar

03:12:48 (161017.001) INF - TAR EXITING WITH STATUS = 0

03:12:48 (161017.001) INF - TAR RESTORED 9 OF 9 FILES SUCCESSFULLY

03:12:48 (161017.001) INF - TAR KEPT 0 EXISTING FILES

03:12:48 (161017.001) INF - TAR PARTIALLY RESTORED 0 FILES

03:26:45 (161018.001) INF - TAR STARTED 28019

03:26:45 (161018.001) Setting network receive buffer size to 32032 bytes

03:27:11 (161018.001) Write interrupted by SIGPIPE.

03:27:11 (161018.001) INF - TAR EXITING WITH STATUS = 40

03:27:11 (161018.001) INF - TAR RESTORED 0 OF 0 FILES SUCCESSFULLY

03:27:11 (161018.001) INF - TAR KEPT 0 EXISTING FILES

03:27:11 (161018.001) INF - TAR PARTIALLY RESTORED 0 FILES

03:30:46 (161019.001) INF - TAR STARTED 28040

03:30:46 (161019.001) Setting network receive buffer size to 32032 bytes

03:33:35 (161019.001) CKP - 161019.001 1376069615 0 0 2 1 0 0 36 /backup/backup4/nzlive91/nzlive91.pf

03:40:17 (161020.001) INF - TAR STARTED 28175

03:40:17 (161020.001) Setting network receive buffer size to 32032 bytes

03:43:04 (161020.001) CKP - 161020.001 1376070184 0 0 2 1 0 0 36 /backup/backup4/infalive/infalive.pf

03:47:46 (161021.001) INF - TAR STARTED 28843

03:47:46 (161021.001) Setting network receive buffer size to 32032 bytes

03:50:34 (161021.001) CKP - 161021.001 1376070634 0 0 2 1 0 0 36 /backup/backup4/inlive91/inlive91.pf

03:57:10 (161022.001) INF - TAR STARTED 28893

03:57:10 (161022.001) Setting network receive buffer size to 32032 bytes

04:05:31 (161022.001) CKP - 161022.001 1376071531 0 0 2 1 0 0 38 /backup/backup4/chqliv/chqempty.bck.gz

[Marianne]

03:12:48 (161017.001) INF - TAR EXITING WITH STATUS = 0

03:12:48 (161017.001) INF - TAR RESTORED 9 OF 9 FILES SUCCESSFULLY

Here we see a successful restore.

03:27:11 (161018.001) Write interrupted by SIGPIPE.

03:27:11 (161018.001) INF - TAR EXITING WITH STATUS = 40

>bperror -S 40 -r

network connection broken

The connection between the client and the server was broken. This status code can also appear if the connection is broken between the master and the media server during a backup.

The above is obviously applicable to a restore as well.

Please get your network team to monitor network traffic between media server and client. This seems to be network problem - not NBU.

You have showed us bptm and bpbrm logs dated some time last week, but tar file for today. This does not help at all.
You need to look at matching logs on media server and client.
 

03:57:10 (161022.001) INF - TAR STARTED 28893

03:57:10 (161022.001) Setting network receive buffer size to 32032 bytes

04:05:31 (161022.001) CKP - 161022.001 1376071531 0 0 2 1 0 0 38 /backup/backup4/chqliv/chqempty.bck.gz

This looks like a restore that is still in progress.

[wannawin]

Hello Marianne.

This time i fired a restore of different date full backup, will let you know whether its failed or completed..

And will paste TAR logs once again ..

[wannawin]

Hello Marianne.

But backup of this client completed successfully daily, no failure reported during backup , then why it shows network failure during restore??

[Marianne]

Maybe you should ask your network team.

Restore data flow is going in opposite direction.