duplication from disk to tape is partially successful with status code 1

[Michael_Kaish1]

Hello

Has anyone seen this type of behavior before?  We currently backup to disk then we vault off to tape.  On a regular basis for the past few months I have been getting partial successful duplication.  The job finishes with a status of 1 and only 60 out of 61 images are duplicated successfully.  Here's an example of the vault job:

5/29/2007 2:00:23 AM - begin Duplicate
5/29/2007 2:00:24 AM - requesting resource backup-03-hcart3-robot-tld-0
5/29/2007 2:00:24 AM - granted resource 1360L3
5/29/2007 2:00:24 AM - granted resource HP.Ultrium3-SCSI.003
5/29/2007 2:00:24 AM - granted resource backup-03-hcart3-robot-tld-0
5/29/2007 2:00:28 AM - started process bptm (5292)
5/29/2007 2:00:32 AM - started process bpdm (1352)
5/29/2007 2:00:33 AM - begin reading
5/29/2007 2:00:34 AM - started process bptm (5292)
5/29/2007 2:00:34 AM - mounting 1360L3
5/29/2007 2:42:19 AM - end reading; read time: 00:41:46
5/29/2007 2:42:20 AM - started process bpdm (7180)
5/29/2007 2:42:21 AM - begin reading
5/29/2007 3:22:08 AM - end reading; read time: 00:39:47
5/29/2007 3:22:09 AM - started process bpdm (9948)
5/29/2007 3:22:10 AM - begin reading
5/29/2007 4:14:24 AM - Error bpdm(pid=9948) cannot read image from disk, Unknown error     
5/29/2007 4:14:24 AM - Error bpduplicate(pid=9984) host backup-03 backup id XXXX-01_1180303205 read failed, media read error (85). 
5/29/2007 4:14:25 AM - Error bpduplicate(pid=9984) host backup-03 backupid XXXX-01_1180303205 write failed, media manager killed by signal (82).
5/29/2007 4:14:25 AM - Error bpduplicate(pid=9984) Duplicate of backup id XXXX-01_1180303205 failed, media manager killed by signal (82).
5/29/2007 4:14:25 AM - started process bptm (9724)
5/29/2007 4:14:26 AM - requesting resource backup-03-hcart3-robot-tld-0
5/29/2007 4:14:26 AM - granted resource 1361L3
5/29/2007 4:14:26 AM - granted resource HP.Ultrium3-SCSI.001
5/29/2007 4:14:26 AM - granted resource backup-03-hcart3-robot-tld-0
5/29/2007 4:14:28 AM - started process bpdm (10060)
5/29/2007 4:14:29 AM - begin reading
5/29/2007 4:15:39 AM - end reading; read time: 00:01:10
5/29/2007 4:15:40 AM - started process bpdm (5680)
5/29/2007 4:15:41 AM - begin reading
5/29/2007 4:15:46 AM - end reading; read time: 00:00:05
5/29/2007 4:15:46 AM - started process bpdm (9440)
5/29/2007 4:15:47 AM - begin reading
5/29/2007 4:15:52 AM - end reading; read time: 00:00:05
5/29/2007 4:15:52 AM - started process bpdm (5816)
5/29/2007 4:15:53 AM - begin reading
5/29/2007 4:15:58 AM - end reading; read time: 00:00:05
5/29/2007 4:15:59 AM - started process bpdm (8312)
5/29/2007 4:15:59 AM - begin reading
5/29/2007 4:16:04 AM - end reading; read time: 00:00:05
5/29/2007 4:16:05 AM - started process bpdm (8512)
5/29/2007 4:16:05 AM - begin reading
5/29/2007 4:16:10 AM - end reading; read time: 00:00:05
5/29/2007 4:16:10 AM - started process bpdm (9132)
5/29/2007 4:16:11 AM - begin reading
5/29/2007 4:16:15 AM - end reading; read time: 00:00:04
5/29/2007 4:16:16 AM - started process bpdm (7980)
5/29/2007 4:16:17 AM - begin reading
5/29/2007 4:16:21 AM - end reading; read time: 00:00:04
5/29/2007 4:16:22 AM - started process bpdm (1012)
5/29/2007 4:16:23 AM - begin reading
5/29/2007 4:16:27 AM - end reading; read time: 00:00:04
5/29/2007 4:16:28 AM - started process bpdm (2460)
5/29/2007 4:16:28 AM - begin reading
5/29/2007 4:16:33 AM - end reading; read time: 00:00:05
5/29/2007 4:16:34 AM - started process bpdm (8596)
5/29/2007 4:16:34 AM - begin reading
5/29/2007 4:16:39 AM - end reading; read time: 00:00:05
5/29/2007 4:16:40 AM - started process bpdm (5996)
5/29/2007 4:16:40 AM - begin reading
5/29/2007 4:16:45 AM - end reading; read time: 00:00:05
5/29/2007 4:16:46 AM - started process bpdm (9832)
5/29/2007 4:16:46 AM - begin reading
5/29/2007 4:16:51 AM - end reading; read time: 00:00:05
5/29/2007 4:16:52 AM - started process bpdm (7300)
5/29/2007 4:16:52 AM - begin reading
5/29/2007 4:16:57 AM - end reading; read time: 00:00:05
5/29/2007 4:16:57 AM - started process bpdm (8100)
5/29/2007 4:16:58 AM - begin reading
5/29/2007 4:17:03 AM - end reading; read time: 00:00:05
5/29/2007 4:17:04 AM - started process bpdm (9716)
5/29/2007 4:17:04 AM - begin reading
5/29/2007 4:17:09 AM - end reading; read time: 00:00:05
5/29/2007 4:17:10 AM - started process bpdm (7024)
5/29/2007 4:17:10 AM - begin reading
5/29/2007 4:17:16 AM - end reading; read time: 00:00:06
5/29/2007 4:17:16 AM - started process bpdm (8596)
5/29/2007 4:17:17 AM - begin reading
5/29/2007 4:17:23 AM - end reading; read time: 00:00:06
5/29/2007 4:17:24 AM - started process bpdm (8816)
5/29/2007 4:17:24 AM - begin reading
5/29/2007 4:17:31 AM - end reading; read time: 00:00:07
5/29/2007 4:17:32 AM - started process bpdm (7324)
5/29/2007 4:17:32 AM - begin reading
5/29/2007 4:17:38 AM - end reading; read time: 00:00:06
5/29/2007 4:17:39 AM - started process bpdm (8656)
5/29/2007 4:17:40 AM - begin reading
5/29/2007 4:17:47 AM - end reading; read time: 00:00:07
5/29/2007 4:17:47 AM - started process bpdm (10072)
5/29/2007 4:17:48 AM - begin reading
5/29/2007 4:17:54 AM - end reading; read time: 00:00:06
5/29/2007 4:17:55 AM - started process bpdm (6672)
5/29/2007 4:17:55 AM - begin reading
5/29/2007 4:18:02 AM - end reading; read time: 00:00:07
5/29/2007 4:18:02 AM - started process bpdm (9800)
5/29/2007 4:18:03 AM - begin reading
5/29/2007 4:18:10 AM - end reading; read time: 00:00:07
5/29/2007 4:18:10 AM - started process bpdm (7392)
5/29/2007 4:18:11 AM - begin reading
5/29/2007 4:18:19 AM - end reading; read time: 00:00:08
5/29/2007 4:18:19 AM - started process bpdm (10192)
5/29/2007 4:18:20 AM - begin reading
5/29/2007 4:18:27 AM - end reading; read time: 00:00:07
5/29/2007 4:18:28 AM - started process bpdm (9052)
5/29/2007 4:18:28 AM - begin reading
5/29/2007 4:18:36 AM - end reading; read time: 00:00:08
5/29/2007 4:18:37 AM - started process bpdm (984)
5/29/2007 4:18:38 AM - begin reading
5/29/2007 4:18:46 AM - end reading; read time: 00:00:08
5/29/2007 4:18:47 AM - started process bpdm (7980)
5/29/2007 4:18:47 AM - begin reading
5/29/2007 4:19:02 AM - end reading; read time: 00:00:15
5/29/2007 4:19:03 AM - started process bpdm (9932)
5/29/2007 4:19:03 AM - begin reading
5/29/2007 4:19:13 AM - end reading; read time: 00:00:10
5/29/2007 4:19:14 AM - started process bpdm (9852)
5/29/2007 4:19:17 AM - begin reading
5/29/2007 4:19:32 AM - end reading; read time: 00:00:15
5/29/2007 4:19:33 AM - started process bpdm (7204)
5/29/2007 4:19:33 AM - begin reading
5/29/2007 4:19:46 AM - end reading; read time: 00:00:13
5/29/2007 4:19:47 AM - started process bpdm (7928)
5/29/2007 4:19:47 AM - begin reading
5/29/2007 4:20:02 AM - end reading; read time: 00:00:15
5/29/2007 4:20:03 AM - started process bpdm (988)
5/29/2007 4:20:04 AM - begin reading
5/29/2007 4:20:22 AM - end reading; read time: 00:00:18
5/29/2007 4:20:23 AM - started process bpdm (7704)
5/29/2007 4:20:23 AM - begin reading
5/29/2007 4:20:39 AM - end reading; read time: 00:00:16
5/29/2007 4:20:40 AM - started process bpdm (7584)
5/29/2007 4:20:41 AM - begin reading
5/29/2007 4:20:55 AM - end reading; read time: 00:00:14
5/29/2007 4:20:56 AM - started process bpdm (7556)
5/29/2007 4:20:56 AM - begin reading
5/29/2007 4:21:14 AM - end reading; read time: 00:00:18
5/29/2007 4:21:14 AM - started process bpdm (8292)
5/29/2007 4:21:15 AM - begin reading
5/29/2007 4:21:31 AM - end reading; read time: 00:00:16
5/29/2007 4:21:32 AM - started process bpdm (9552)
5/29/2007 4:21:32 AM - begin reading
5/29/2007 4:21:50 AM - end reading; read time: 00:00:18
5/29/2007 4:21:51 AM - started process bpdm (8020)
5/29/2007 4:21:52 AM - begin reading
5/29/2007 4:22:19 AM - end reading; read time: 00:00:27
5/29/2007 4:22:19 AM - started process bpdm (8784)
5/29/2007 4:22:20 AM - begin reading
5/29/2007 4:22:45 AM - end reading; read time: 00:00:25
5/29/2007 4:22:46 AM - started process bpdm (1992)
5/29/2007 4:22:46 AM - begin reading
5/29/2007 4:23:24 AM - end reading; read time: 00:00:38
5/29/2007 4:23:25 AM - started process bpdm (7040)
5/29/2007 4:23:26 AM - begin reading
5/29/2007 4:24:01 AM - end reading; read time: 00:00:35
5/29/2007 4:24:02 AM - started process bpdm (3096)
5/29/2007 4:24:03 AM - begin reading
5/29/2007 4:24:59 AM - end reading; read time: 00:00:56
5/29/2007 4:25:00 AM - started process bpdm (10232)
5/29/2007 4:25:01 AM - begin reading
5/29/2007 4:25:56 AM - end reading; read time: 00:00:55
5/29/2007 4:25:56 AM - started process bpdm (2668)
5/29/2007 4:25:57 AM - begin reading
5/29/2007 4:26:47 AM - end reading; read time: 00:00:50
5/29/2007 4:26:48 AM - started process bpdm (10156)
5/29/2007 4:26:48 AM - begin reading
5/29/2007 4:27:48 AM - end reading; read time: 00:01:00
5/29/2007 4:27:49 AM - started process bpdm (8928)
5/29/2007 4:27:49 AM - begin reading
5/29/2007 4:28:59 AM - end reading; read time: 00:01:10
5/29/2007 4:29:00 AM - started process bpdm (9832)
5/29/2007 4:29:00 AM - begin reading
5/29/2007 4:30:15 AM - end reading; read time: 00:01:15
5/29/2007 4:30:16 AM - started process bpdm (8552)
5/29/2007 4:30:17 AM - begin reading
5/29/2007 4:31:45 AM - end reading; read time: 00:01:28
5/29/2007 4:31:46 AM - started process bpdm (6112)
5/29/2007 4:31:46 AM - begin reading
5/29/2007 4:33:18 AM - end reading; read time: 00:01:32
5/29/2007 4:33:19 AM - started process bpdm (3828)
5/29/2007 4:33:20 AM - begin reading
5/29/2007 4:34:30 AM - end reading; read time: 00:01:10
5/29/2007 4:34:31 AM - started process bpdm (7736)
5/29/2007 4:34:31 AM - begin reading
5/29/2007 4:37:21 AM - end reading; read time: 00:02:50
5/29/2007 4:37:22 AM - started process bpdm (6080)
5/29/2007 4:37:22 AM - begin reading
5/29/2007 4:42:50 AM - end reading; read time: 00:05:28
5/29/2007 4:42:51 AM - started process bpdm (7788)
5/29/2007 4:42:51 AM - begin reading
5/29/2007 4:50:12 AM - end reading; read time: 00:07:21
5/29/2007 4:50:12 AM - started process bpdm (7148)
5/29/2007 4:50:13 AM - begin reading
5/29/2007 5:00:41 AM - end reading; read time: 00:10:28
5/29/2007 5:00:42 AM - started process bpdm (3296)
5/29/2007 5:00:42 AM - begin reading
5/29/2007 5:24:51 AM - end reading; read time: 00:24:09
5/29/2007 5:24:52 AM - started process bpdm (6240)
5/29/2007 5:24:53 AM - begin reading
5/29/2007 6:20:08 AM - end reading; read time: 00:55:15
5/29/2007 6:20:08 AM - Error bpduplicate(pid=9984) Status = successfully duplicated 60 of 61 images.    
5/29/2007 6:20:08 AM - Error bpduplicate(pid=9984) Status = the requested operation was partially successful.    
5/29/2007 6:20:08 AM - end Duplicate; elapsed time: 04:19:45
the requested operation was partially successful(1)

The job was successfully completed, but some files may have been
busy or unaccessible. See the problems report or the client's logs for more details.

[Stumpr2]

Is a subsequent duplication attempt of the failed image successfull?

[Michael_Kaish1]

Hi

I was able to fix the problem by changing the client wait time to 900 vs 600.  Also ran cleaning on the 4 tape drives.  The failure was not with just one image it was always with various different images.  Thank You for your post.

[Stumpr2]

While on this topic you may want to also check out this technote concerning buffers

Slow performance on Disk Storage Units and Disk Staging Storage Units

http://support.veritas.com/docs/273532

Check your results for SIZE_DATA_BUFFERS_DISK in the netbackup/logs/bpdm/