Someone also has a problem with duplication after upgrading the FW to version 3.18.18 on HPE StoreOnce 5100.
I have Veritas NetBackup version 8.2 and HPE StoreOnce Catalyst Plug-in 4.2.2 for veritas NetBackup.
I have a problem with duplication in Veritas NetBackup over SLP.
Since the change of FW on StoreOnce to version 3.18.18, I have some duplications as can be seen in the job detail
I primarily make a backup - 1st copy on StoreOnce 5100 to storage pools. Subsequently, images are duplicated via SLP to the 2nd copy on the same StoreOnce 5100 in another location via SAN, the 3rd copy is created in parallel to the msdp pool on the master server and then the 4th copy from it to the msdp pool on the media server in another remote location via LAN..
20.5.2020 2:10:54 - begin Duplicate
20.5.2020 2:10:54 - requesting resource LCM_bck1-dp-stu
20.5.2020 2:10:54 - granted resource LCM_bck1-dp-stu
20.5.2020 2:10:54 - started process RUNCMD (pid=9115)
20.5.2020 2:10:55 - Info bpduplicate (pid=9115) window close behavior: Suspend
20.5.2020 2:10:55 - Info bptm (pid=11024) start
20.5.2020 2:10:55 - started process bptm (pid=11024)
20.5.2020 2:10:55 - requesting resource bck1-dp-stu
20.5.2020 2:10:55 - requesting resource @aaaaK
20.5.2020 2:10:55 - reserving resource @aaaaK
20.5.2020 2:10:55 - resource @aaaaK reserved
20.5.2020 2:10:55 - granted resource MediaID=@aaabg;DiskVolume=PureDiskVolume;DiskPool=bck1-dp;Path=PureDiskVolume;StorageServer=bck1;MediaServer=oradb1bck
20.5.2020 2:10:55 - granted resource bck1-dp-stu
20.5.2020 2:10:55 - granted resource MediaID=@aaaaK;DiskVolume=HTPCatWinVM1;DiskPool=HTPCatWinVM-POOL1;Path=HTPCatWinVM1;StorageServer=COFC-CZ3743V40101;MediaServer=oradb1bck
20.5.2020 2:10:55 - ended process 0 (pid=9115)
20.5.2020 2:10:56 - Info bptm (pid=11024) start backup
20.5.2020 2:10:58 - Info bpdm (pid=11052) started
20.5.2020 2:10:58 - started process bpdm (pid=11052)
20.5.2020 2:10:58 - Info bpdm (pid=11052) reading backup image
20.5.2020 2:10:58 - Info bpdm (pid=11052) using 64 data buffers
20.5.2020 2:10:58 - Info bpdm (pid=11052) requesting nbjm for media
20.5.2020 2:10:59 - begin reading
20.5.2020 2:11:30 - Info bptm (pid=11024) waited for full buffer 432 times, delayed 1989 times
20.5.2020 2:11:33 - end reading; read time: 0:00:34
20.5.2020 2:11:34 - Info bpdm (pid=11052) completed reading backup image
20.5.2020 2:11:36 - Info bpdm (pid=11052) using 64 data buffers
20.5.2020 2:11:36 - begin reading
20.5.2020 2:11:52 - Info bptm (pid=11024) waited for full buffer 58 times, delayed 741 times
20.5.2020 2:11:53 - end reading; read time: 0:00:17
20.5.2020 2:11:55 - Info bpdm (pid=11052) completed reading backup image
20.5.2020 2:11:56 - Info bpdm (pid=11052) using 64 data buffers
20.5.2020 2:11:56 - begin reading
20.5.2020 2:12:11 - Info bptm (pid=11024) waited for full buffer 53 times, delayed 631 times
20.5.2020 2:12:12 - end reading; read time: 0:00:16
20.5.2020 2:12:14 - Info bpdm (pid=11052) completed reading backup image
20.5.2020 2:12:16 - Info bpdm (pid=11052) using 64 data buffers
20.5.2020 2:12:16 - begin reading
20.5.2020 2:12:32 - Info bptm (pid=11024) waited for full buffer 43 times, delayed 673 times
20.5.2020 2:12:33 - end reading; read time: 0:00:17
20.5.2020 2:12:36 - Info bpdm (pid=11052) completed reading backup image
20.5.2020 2:12:38 - Info bpdm (pid=11052) using 64 data buffers
20.5.2020 2:12:38 - begin reading
20.5.2020 2:13:00 - Info bptm (pid=11024) waited for full buffer 36 times, delayed 924 times
20.5.2020 2:13:01 - end reading; read time: 0:00:23
20.5.2020 2:13:03 - Info bpdm (pid=11052) completed reading backup image
20.5.2020 2:13:04 - Info bpdm (pid=11052) using 64 data buffers
20.5.2020 2:13:04 - begin reading
20.5.2020 2:13:48 - Info bptm (pid=11024) waited for full buffer 87 times, delayed 2115 times
20.5.2020 2:13:49 - end reading; read time: 0:00:45
20.5.2020 2:13:53 - Info bpdm (pid=11052) completed reading backup image
20.5.2020 2:13:54 - Info bpdm (pid=11052) using 64 data buffers
20.5.2020 2:13:54 - begin reading
20.5.2020 2:14:00 - Critical bptm (pid=11024) image write failed: error 2060022: software error
20.5.2020 2:14:03 - Error bptm (pid=11024) cannot write image to disk, Invalid argument
20.5.2020 2:14:03 - Info bptm (pid=11024) EXITING with status 84 <----------
20.5.2020 2:14:03 - Info oradb1bck (pid=11024) StorageServer=PureDisk:bck1; Report=PDDO Stats (multi-threaded stream used) for (bck1): scanned: 7294145 KB, CR sent: 348888 KB, CR sent over FC: 0 KB, dedup: 95.2%, cache disabled, where dedup space saving:81.2%, compression space saving:14.0%
20.5.2020 2:14:05 - Error bpdm (pid=11052) media manager terminated by parent process
20.5.2020 2:14:11 - Error bpduplicate (pid=9115) host oradb1bck backup id S4B-Edge2_1589932845 read failed, media manager killed by signal (82).
20.5.2020 2:14:11 - Error bpduplicate (pid=9115) host oradb1bck backupid S4B-Edge2_1589932845 write failed, media write error (84).
20.5.2020 2:14:11 - Error bpduplicate (pid=9115) Duplicate of backupid S4B-Edge2_1589932845 failed, media write error (84).
20.5.2020 2:14:11 - Info bptm (pid=42166) start
20.5.2020 2:14:11 - started process bptm (pid=42166)
20.5.2020 2:14:11 - requesting resource @aaaaK
20.5.2020 2:14:11 - granted resource MediaID=@aaaaK;DiskVolume=HTPCatWinVM1;DiskPool=HTPCatWinVM-POOL1;Path=HTPCatWinVM1;StorageServer=COFC-CZ3743V40101;MediaServer=oradb1bck
20.5.2020 2:14:11 - requesting resource bck1-dp-stu
20.5.2020 2:14:11 - granted resource MediaID=@aaabg;DiskVolume=PureDiskVolume;DiskPool=bck1-dp;Path=PureDiskVolume;StorageServer=bck1;MediaServer=oradb1bck
20.5.2020 2:14:11 - granted resource bck1-dp-stu
20.5.2020 2:14:16 - Info oradb1bck (pid=11052) StorageServer=hp-StoreOnceCatalyst:COFC-CZ3743V40101; Report=scanned: 0 KB, CR sent: 0 KB, dedup: 0.00%
20.5.2020 2:14:16 - Info bptm (pid=42166) start backup
20.5.2020 2:14:17 - Info bpdm (pid=42212) started
20.5.2020 2:14:18 - started process bpdm (pid=42212)
20.5.2020 2:14:19 - Info bpdm (pid=42212) reading backup image
20.5.2020 2:14:19 - Info bpdm (pid=42212) using 64 data buffers
20.5.2020 2:14:19 - Info bpdm (pid=42212) requesting nbjm for media
20.5.2020 2:14:20 - begin reading
20.5.2020 2:14:37 - Info bptm (pid=42166) waited for full buffer 308 times, delayed 1146 times
20.5.2020 2:14:38 - end reading; read time: 0:00:18
20.5.2020 2:14:41 - Info bpdm (pid=42212) completed reading backup image
20.5.2020 2:14:42 - Info bpdm (pid=42212) using 64 data buffers
20.5.2020 2:14:42 - begin reading
20.5.2020 2:15:04 - Info bptm (pid=42166) waited for full buffer 40 times, delayed 753 times
20.5.2020 2:15:06 - end reading; read time: 0:00:24
20.5.2020 2:15:07 - Info bpdm (pid=42212) completed reading backup image
20.5.2020 2:15:08 - Info bpdm (pid=42212) using 64 data buffers
20.5.2020 2:15:08 - begin reading
20.5.2020 2:15:56 - Info bptm (pid=42166) waited for full buffer 91 times, delayed 1957 times
20.5.2020 2:15:58 - end reading; read time: 0:00:50
20.5.2020 2:16:01 - Info bpdm (pid=42212) completed reading backup image
20.5.2020 2:16:02 - Info bpdm (pid=42212) using 64 data buffers
20.5.2020 2:16:02 - begin reading
20.5.2020 2:16:05 - Critical bptm (pid=42166) image write failed: error 2060022: software error
20.5.2020 2:16:08 - Error bptm (pid=42166) cannot write image to disk, Invalid argument
20.5.2020 2:16:08 - Info bptm (pid=42166) EXITING with status 84 <----------
20.5.2020 2:16:08 - Info oradb1bck (pid=42166) StorageServer=PureDisk:bck1; Report=PDDO Stats (multi-threaded stream used) for (bck1): scanned: 4176479 KB, CR sent: 546514 KB, CR sent over FC: 0 KB, dedup: 86.9%, cache disabled, where dedup space saving:65.8%, compression space saving:21.1%
20.5.2020 2:16:10 - Error bpdm (pid=42212) media manager terminated by parent process
20.5.2020 2:16:16 - Error bpduplicate (pid=9115) host oradb1bck backup id PKI-ZTP_1589932854 read failed, media manager killed by signal (82).
20.5.2020 2:16:16 - Error bpduplicate (pid=9115) host oradb1bck backupid PKI-ZTP_1589932854 write failed, media write error (84).
20.5.2020 2:16:16 - Error bpduplicate (pid=9115) Duplicate of backupid PKI-ZTP_1589932854 failed, media write error (84).
20.5.2020 2:16:16 - requesting resource @aaaaK
20.5.2020 2:16:16 - granted resource MediaID=@aaaaK;DiskVolume=HTPCatWinVM1;DiskPool=HTPCatWinVM-POOL1;Path=HTPCatWinVM1;StorageServer=COFC-CZ3743V40101;MediaServer=oradb1bck
20.5.2020 2:16:16 - Info bptm (pid=59543) start
20.5.2020 2:16:16 - started process bptm (pid=59543)
20.5.2020 2:16:16 - requesting resource bck1-dp-stu
20.5.2020 2:16:16 - granted resource MediaID=@aaabg;DiskVolume=PureDiskVolume;DiskPool=bck1-dp;Path=PureDiskVolume;StorageServer=bck1;MediaServer=oradb1bck
20.5.2020 2:16:16 - granted resource bck1-dp-stu
20.5.2020 2:16:17 - Info bptm (pid=59543) start backup
20.5.2020 2:16:19 - Info bpdm (pid=59576) started
20.5.2020 2:16:19 - started process bpdm (pid=59576)
20.5.2020 2:16:19 - Info bpdm (pid=59576) reading backup image
20.5.2020 2:16:19 - Info bpdm (pid=59576) using 64 data buffers
20.5.2020 2:16:19 - Info bpdm (pid=59576) requesting nbjm for media
20.5.2020 2:16:20 - begin reading
20.5.2020 2:16:21 - Info oradb1bck (pid=42212) StorageServer=hp-StoreOnceCatalyst:COFC-CZ3743V40101; Report=scanned: 0 KB, CR sent: 0 KB, dedup: 0.00%
20.5.2020 2:17:12 - Info bptm (pid=59543) waited for full buffer 640 times, delayed 3372 times
20.5.2020 2:17:13 - end reading; read time: 0:00:53
20.5.2020 2:17:16 - Info bpdm (pid=59576) completed reading backup image
20.5.2020 2:17:17 - Info bpdm (pid=59576) using 64 data buffers
20.5.2020 2:17:17 - begin reading
20.5.2020 2:20:03 - Info bptm (pid=59543) waited for full buffer 479 times, delayed 7011 times
20.5.2020 2:20:05 - end reading; read time: 0:02:48
20.5.2020 2:20:09 - Info bpdm (pid=59576) completed reading backup image
20.5.2020 2:20:10 - Info bpdm (pid=59576) using 64 data buffers
20.5.2020 2:20:10 - begin reading
20.5.2020 2:20:51 - Info bptm (pid=59543) waited for full buffer 53 times, delayed 2021 times
20.5.2020 2:20:52 - end reading; read time: 0:00:42
20.5.2020 2:20:59 - Info bpdm (pid=59576) completed reading backup image
20.5.2020 2:21:00 - Info bpdm (pid=59576) using 64 data buffers
20.5.2020 2:21:01 - begin reading
20.5.2020 2:21:53 - Info bptm (pid=59543) waited for full buffer 57 times, delayed 2630 times
20.5.2020 2:21:54 - end reading; read time: 0:00:53
20.5.2020 2:21:59 - Info bpdm (pid=59576) completed reading backup image
20.5.2020 2:22:01 - Info bpdm (pid=59576) using 64 data buffers
20.5.2020 2:22:02 - begin reading
20.5.2020 2:22:40 - Info bptm (pid=59543) waited for full buffer 60 times, delayed 1975 times
20.5.2020 2:22:41 - end reading; read time: 0:00:39
20.5.2020 2:22:42 - Info bpdm (pid=59576) completed reading backup image
20.5.2020 2:22:43 - Info bpdm (pid=59576) using 64 data buffers
20.5.2020 2:22:44 - begin reading
20.5.2020 2:22:46 - Info bptm (pid=59543) waited for full buffer 1 times, delayed 170 times
20.5.2020 2:22:47 - end reading; read time: 0:00:03
20.5.2020 2:22:50 - Info bpdm (pid=59576) completed reading backup image
20.5.2020 2:22:52 - Info bpdm (pid=59576) using 64 data buffers
20.5.2020 2:22:52 - begin reading
20.5.2020 2:24:25 - Info bptm (pid=59543) waited for full buffer 124 times, delayed 4441 times
20.5.2020 2:24:27 - end reading; read time: 0:01:35
20.5.2020 2:24:30 - Info bpdm (pid=59576) completed reading backup image
20.5.2020 2:24:31 - Info bpdm (pid=59576) using 64 data buffers
20.5.2020 2:24:31 - begin reading
20.5.2020 2:25:30 - Info bptm (pid=59543) waited for full buffer 86 times, delayed 2919 times
20.5.2020 2:25:31 - end reading; read time: 0:01:00
20.5.2020 2:25:35 - Info bpdm (pid=59576) completed reading backup image
20.5.2020 2:25:36 - Info bpdm (pid=59576) using 64 data buffers
20.5.2020 2:25:36 - begin reading
20.5.2020 2:27:41 - Info bptm (pid=59543) waited for full buffer 140 times, delayed 5225 times
20.5.2020 2:27:43 - end reading; read time: 0:02:07
20.5.2020 2:27:48 - Info bpdm (pid=59576) completed reading backup image
20.5.2020 2:27:49 - Info bpdm (pid=59576) using 64 data buffers
20.5.2020 2:27:49 - begin reading
20.5.2020 2:28:36 - Info bptm (pid=59543) waited for full buffer 35 times, delayed 2674 times
20.5.2020 2:28:38 - end reading; read time: 0:00:49
20.5.2020 2:28:43 - Info bpdm (pid=59576) completed reading backup image
20.5.2020 2:28:44 - Info bpdm (pid=59576) using 64 data buffers
20.5.2020 2:28:44 - begin reading
20.5.2020 2:29:35 - Info bptm (pid=59543) waited for full buffer 28 times, delayed 2864 times
20.5.2020 2:29:36 - end reading; read time: 0:00:52
20.5.2020 2:29:42 - Info bpdm (pid=59576) completed reading backup image
20.5.2020 2:29:44 - Info bpdm (pid=59576) using 64 data buffers
20.5.2020 2:29:44 - begin reading
20.5.2020 2:30:51 - Info bptm (pid=59543) waited for full buffer 77 times, delayed 3625 times
20.5.2020 2:30:52 - end reading; read time: 0:01:08
20.5.2020 2:30:59 - Info bpdm (pid=59576) completed reading backup image
20.5.2020 2:31:00 - Info bpdm (pid=59576) using 64 data buffers
20.5.2020 2:31:02 - begin reading
20.5.2020 2:32:16 - Info bptm (pid=59543) waited for full buffer 70 times, delayed 4187 times
20.5.2020 2:32:17 - end reading; read time: 0:01:15
20.5.2020 2:32:26 - Info bpdm (pid=59576) completed reading backup image
20.5.2020 2:32:28 - Info bpdm (pid=59576) using 64 data buffers
20.5.2020 2:32:28 - begin reading
20.5.2020 2:33:32 - Info bptm (pid=59543) waited for full buffer 60 times, delayed 3488 times
20.5.2020 2:33:33 - end reading; read time: 0:01:05
20.5.2020 2:33:44 - Info bpdm (pid=59576) completed reading backup image
20.5.2020 2:33:44 - Info bpdm (pid=59576) EXITING with status 0
20.5.2020 2:33:44 - Info oradb1bck (pid=59576) StorageServer=hp-StoreOnceCatalyst:COFC-CZ3743V40101; Report=scanned: 0 KB, CR sent: 0 KB, dedup: 0.00%
20.5.2020 2:33:44 - Info bptm (pid=59543) EXITING with status 0 <----------
20.5.2020 2:33:44 - Error bpduplicate (pid=9115) Status = successfully duplicated 23 of 25 images.
20.5.2020 2:33:44 - Error bpduplicate (pid=9115) Status = the requested operation was partially successful.
20.5.2020 2:33:44 - end Duplicate; elapsed time 0:22:50
20.5.2020 2:33:44 - Info oradb1bck (pid=59543) StorageServer=PureDisk:bck1; Report=PDDO Stats (multi-threaded stream used) for (bck1): scanned: 33599667 KB, CR sent: 2720453 KB, CR sent over FC: 0 KB, dedup: 91.9%, cache disabled, where dedup space saving:69.1%, compression space saving:22.8%
The requested operation was partially successful (1)
