11/16/2015 8:00:01 AM - begin Duplicate
11/16/2015 8:00:02 AM - requesting resource LocalTape
11/16/2015 8:00:02 AM - requesting resource 0563
11/16/2015 8:00:02 AM - reserving resource 0563
11/16/2015 8:00:02 AM - reserving resource 0237
11/16/2015 8:00:02 AM - reserving resource 0560
11/16/2015 8:00:02 AM - reserving resource 0510
11/16/2015 8:00:02 AM - reserving resource 0319
11/16/2015 8:00:02 AM - reserving resource 0330
11/16/2015 8:00:02 AM - reserving resource 0577
11/16/2015 8:00:02 AM - reserving resource 0546
11/16/2015 8:00:02 AM - reserving resource 0498
11/16/2015 8:00:02 AM - reserved resource 0563
11/16/2015 8:00:02 AM - reserved resource 0237
11/16/2015 8:00:02 AM - reserved resource 0560
11/16/2015 8:00:02 AM - reserved resource 0510
11/16/2015 8:00:02 AM - reserved resource 0319
11/16/2015 8:00:02 AM - reserved resource 0330
11/16/2015 8:00:02 AM - reserved resource 0577
11/16/2015 8:00:02 AM - reserved resource 0546
11/16/2015 8:00:02 AM - reserved resource 0498
11/16/2015 8:00:02 AM - granted resource 0260
11/16/2015 8:00:02 AM - granted resource LTO4-3
11/16/2015 8:00:02 AM - granted resource LocalTape
11/16/2015 8:00:02 AM - granted resource 0563
11/16/2015 8:00:02 AM - granted resource LTO4-6
11/16/2015 8:00:03 AM - Info bptm(pid=25964) start            
11/16/2015 8:00:03 AM - started process bptm (25964)
11/16/2015 8:00:04 AM - Info bptm(pid=25964) start backup           
11/16/2015 8:00:05 AM - Info bptm(pid=27440) start            
11/16/2015 8:00:05 AM - started process bptm (27440)
11/16/2015 8:00:05 AM - Info bpdm(pid=27440) reading backup image          
11/16/2015 8:00:05 AM - Info bptm(pid=27440) using 128 data buffers         
11/16/2015 8:00:05 AM - Info bptm(pid=27440) Waiting for mount of media id 0563 (copy 1) on server mailbck1. 
11/16/2015 8:00:05 AM - started process bptm (27440)
11/16/2015 8:00:05 AM - mounting 0563
11/16/2015 8:00:05 AM - Info bptm(pid=27440) INF - Waiting for mount of media id 0563 on server mailbck1 for reading.
11/16/2015 8:00:05 AM - Info bptm(pid=25964) Waiting for mount of media id 0260 (copy 2) on server mailbck1. 
11/16/2015 8:00:05 AM - started process bptm (25964)
11/16/2015 8:00:05 AM - mounting 0260
11/16/2015 8:00:05 AM - Info bptm(pid=25964) INF - Waiting for mount of media id 0260 on server mailbck1 for writing.
11/16/2015 8:01:24 AM - mounted; mount time: 00:01:19
11/16/2015 8:01:24 AM - Info bptm(pid=27440) 0563            
11/16/2015 8:01:24 AM - Info bptm(pid=27440) INF - Waiting for positioning of media id 0563 on server mailbck1 for reading.
11/16/2015 8:01:24 AM - positioning 0563 to file 7
11/16/2015 8:02:19 AM - Info bptm(pid=25964) media id 0260 mounted on drive index 3, drivepath {2,0,4,0}, drivename LTO4-3, copy 2
11/16/2015 8:02:26 AM - Info bptm(pid=25964) INF - Waiting for positioning of media id 0260 on server mailbck1 for writing.
11/16/2015 8:03:17 AM - positioned 0563; position time: 00:01:53
11/16/2015 8:03:18 AM - begin reading
11/16/2015 8:30:42 AM - Info bptm(pid=27440) waited for empty buffer 4227 times, delayed 22750 times    
11/16/2015 8:30:42 AM - end reading; read time: 00:27:24
11/16/2015 8:30:42 AM - positioning 0563 to file 8
11/16/2015 8:30:42 AM - positioned 0563; position time: 00:00:00
11/16/2015 8:30:42 AM - begin reading
11/16/2015 8:36:36 AM - Info bptm(pid=27440) waited for empty buffer 633 times, delayed 3954 times    
11/16/2015 8:36:36 AM - end reading; read time: 00:05:54
11/16/2015 8:36:36 AM - positioning 0563 to file 9
11/16/2015 8:36:36 AM - positioned 0563; position time: 00:00:00
11/16/2015 8:36:36 AM - begin reading
11/16/2015 8:41:39 AM - Info bptm(pid=25964) Waiting for mount of media id 0568 (copy 2) on server mailbck1. 
11/16/2015 8:41:39 AM - started process bptm (25964)
11/16/2015 8:41:39 AM - mounting 0568
11/16/2015 8:41:39 AM - Info bptm(pid=25964) INF - Waiting for mount of media id 0568 on server mailbck1 for writing.
11/16/2015 8:41:39 AM - current media 0260 complete, requesting next resource Any
11/16/2015 8:41:39 AM - granted resource 0568
11/16/2015 8:41:39 AM - granted resource LTO4-2
11/16/2015 8:41:39 AM - granted resource LocalTape
11/16/2015 8:42:54 AM - Info bptm(pid=25964) media id 0568 mounted on drive index 1, drivepath {1,0,2,0}, drivename LTO4-2, copy 2
11/16/2015 9:07:14 AM - Info bptm(pid=27440) waited for empty buffer 4687 times, delayed 30996 times    
11/16/2015 9:07:14 AM - end reading; read time: 00:30:38
11/16/2015 9:07:14 AM - positioning 0563 to file 10
11/16/2015 9:07:14 AM - positioned 0563; position time: 00:00:00
11/16/2015 9:07:14 AM - begin reading
11/16/2015 9:14:07 AM - Info bptm(pid=27440) waited for empty buffer 1274 times, delayed 10536 times    
11/16/2015 9:14:07 AM - end reading; read time: 00:06:53
11/16/2015 9:14:07 AM - positioning 0563 to file 11
11/16/2015 9:14:07 AM - positioned 0563; position time: 00:00:00
11/16/2015 9:14:07 AM - begin reading
11/16/2015 9:44:40 AM - Info bptm(pid=27440) waited for empty buffer 5772 times, delayed 26721 times    
11/16/2015 9:44:40 AM - end reading; read time: 00:30:33
11/16/2015 9:44:40 AM - positioning 0563 to file 12
11/16/2015 9:44:40 AM - positioned 0563; position time: 00:00:00
11/16/2015 9:44:40 AM - begin reading
11/16/2015 9:51:27 AM - Info bptm(pid=27440) waited for empty buffer 676 times, delayed 3665 times    
11/16/2015 9:51:27 AM - end reading; read time: 00:06:47
11/16/2015 9:51:27 AM - positioning 0563 to file 13
11/16/2015 9:51:27 AM - positioned 0563; position time: 00:00:00
11/16/2015 9:51:27 AM - begin reading
11/16/2015 10:21:57 AM - Info bptm(pid=27440) waited for empty buffer 6257 times, delayed 31226 times    
11/16/2015 10:21:57 AM - end reading; read time: 00:30:30
11/16/2015 10:21:57 AM - positioning 0563 to file 14
11/16/2015 10:21:57 AM - positioned 0563; position time: 00:00:00
11/16/2015 10:21:57 AM - begin reading
11/16/2015 10:27:59 AM - Info bptm(pid=27440) waited for empty buffer 541 times, delayed 2371 times    
11/16/2015 10:27:59 AM - end reading; read time: 00:06:02
11/16/2015 10:27:59 AM - positioning 0563 to file 15
11/16/2015 10:27:59 AM - positioned 0563; position time: 00:00:00
11/16/2015 10:27:59 AM - begin reading
11/16/2015 10:56:03 AM - Info bptm(pid=27440) waited for empty buffer 4227 times, delayed 19446 times    
11/16/2015 10:56:03 AM - end reading; read time: 00:28:04
11/16/2015 10:56:03 AM - positioning 0563 to file 16
11/16/2015 10:56:03 AM - positioned 0563; position time: 00:00:00
11/16/2015 10:56:03 AM - begin reading
11/16/2015 11:01:27 AM - Info bptm(pid=27440) waited for empty buffer 748 times, delayed 5416 times    
11/16/2015 11:01:27 AM - end reading; read time: 00:05:24
11/16/2015 11:01:27 AM - Info bptm(pid=27440) Waiting for mount of media id 0237 (copy 1) on server mailbck1. 
11/16/2015 11:01:27 AM - started process bptm (27440)
11/16/2015 11:01:27 AM - mounting 0237
11/16/2015 11:01:27 AM - Info bptm(pid=27440) INF - Waiting for mount of media id 0237 on server mailbck1 for reading.
11/16/2015 11:01:27 AM - current media 0563 complete, requesting next resource LTO4-6:0237
11/16/2015 11:01:27 AM - granted resource 0237
11/16/2015 11:01:27 AM - granted resource LTO4-5
11/16/2015 11:02:37 AM - mounted; mount time: 00:01:10
11/16/2015 11:02:37 AM - Info bptm(pid=27440) 0237            
11/16/2015 11:02:37 AM - Info bptm(pid=27440) INF - Waiting for positioning of media id 0237 on server mailbck1 for reading.
11/16/2015 11:02:37 AM - positioning 0237 to file 1
11/16/2015 11:02:37 AM - positioned 0237; position time: 00:00:00
11/16/2015 11:02:37 AM - begin reading
11/16/2015 11:08:40 AM - Info bptm(pid=27440) waited for empty buffer 1187 times, delayed 2717 times    
11/16/2015 11:08:40 AM - end reading; read time: 00:06:03
11/16/2015 11:08:40 AM - positioning 0237 to file 2
11/16/2015 11:08:40 AM - positioned 0237; position time: 00:00:00
11/16/2015 11:08:40 AM - begin reading
11/16/2015 11:36:44 AM - Info bptm(pid=27440) waited for empty buffer 4759 times, delayed 19136 times    
11/16/2015 11:36:44 AM - end reading; read time: 00:28:04
11/16/2015 11:36:44 AM - positioning 0237 to file 3
11/16/2015 11:36:44 AM - positioned 0237; position time: 00:00:00
11/16/2015 11:36:44 AM - begin reading
11/16/2015 11:42:01 AM - Info bptm(pid=27440) waited for empty buffer 742 times, delayed 3991 times    
11/16/2015 11:42:01 AM - end reading; read time: 00:05:17
11/16/2015 11:42:01 AM - Info bptm(pid=25964) waited for full buffer 228238 times, delayed 404893 times    
11/16/2015 11:42:02 AM - Info bptm(pid=25964) setting receive network buffer to 525312 bytes      
11/16/2015 11:42:02 AM - positioning 0237 to file 4
11/16/2015 11:42:02 AM - positioned 0237; position time: 00:00:00
11/16/2015 11:42:02 AM - Info bptm(pid=27440) completed reading backup image         
11/16/2015 11:42:02 AM - Info bptm(pid=27440) EXITING with status 0 <----------        
11/16/2015 11:42:11 AM - Info bptm(pid=25964) EXITING with status 0 <----------        
11/16/2015 11:42:12 AM - Info bptm(pid=28404) start            
11/16/2015 11:42:12 AM - started process bptm (28404)
11/16/2015 11:42:12 AM - requesting resource LocalTape
11/16/2015 11:42:12 AM - granted resource 0568
11/16/2015 11:42:12 AM - granted resource LTO4-2
11/16/2015 11:42:12 AM - granted resource LocalTape
11/16/2015 11:42:13 AM - Info bptm(pid=28404) start backup           
11/16/2015 11:42:13 AM - Info bptm(pid=23148) start            
11/16/2015 11:42:13 AM - started process bptm (23148)
11/16/2015 11:42:13 AM - Info bpdm(pid=23148) reading backup image          
11/16/2015 11:42:13 AM - Info bptm(pid=23148) using 128 data buffers         
11/16/2015 11:42:13 AM - Info bptm(pid=23148) Waiting for mount of media id 0560 (copy 1) on server mailbck1. 
11/16/2015 11:42:13 AM - started process bptm (23148)
11/16/2015 11:42:13 AM - mounting 0560
11/16/2015 11:42:13 AM - Info bptm(pid=23148) INF - Waiting for mount of media id 0560 on server mailbck1 for reading.
11/16/2015 11:42:13 AM - requesting resource 0560
11/16/2015 11:42:13 AM - granted resource 0560
11/16/2015 11:42:13 AM - granted resource LTO4-6
11/16/2015 11:42:14 AM - Info bptm(pid=28404) media id 0568 mounted on drive index 1, drivepath {1,0,2,0}, drivename LTO4-2, copy 2
11/16/2015 11:42:14 AM - Info bptm(pid=28404) INF - Waiting for positioning of media id 0568 on server mailbck1 for writing.
11/16/2015 11:43:32 AM - mounted; mount time: 00:01:19
11/16/2015 11:43:32 AM - Info bptm(pid=23148) 0560            
11/16/2015 11:43:32 AM - Info bptm(pid=23148) INF - Waiting for positioning of media id 0560 on server mailbck1 for reading.
11/16/2015 11:43:32 AM - positioning 0560 to file 4
11/16/2015 11:46:29 AM - positioned 0560; position time: 00:02:57
11/16/2015 11:46:29 AM - begin reading
11/16/2015 12:06:50 PM - Info bptm(pid=23148) waited for empty buffer 6782 times, delayed 17423 times    
11/16/2015 12:06:50 PM - end reading; read time: 00:20:21
11/16/2015 12:06:50 PM - positioning 0560 to file 5
11/16/2015 12:06:50 PM - positioned 0560; position time: 00:00:00
11/16/2015 12:06:50 PM - begin reading
11/16/2015 12:10:09 PM - Info bptm(pid=23148) waited for empty buffer 494 times, delayed 1566 times    
11/16/2015 12:10:09 PM - end reading; read time: 00:03:19
11/16/2015 12:10:09 PM - positioning 0560 to file 6
11/16/2015 12:10:09 PM - positioned 0560; position time: 00:00:00
11/16/2015 12:10:09 PM - begin reading
11/16/2015 12:27:18 PM - Info bptm(pid=23148) waited for empty buffer 3807 times, delayed 10768 times    
11/16/2015 12:27:18 PM - end reading; read time: 00:17:09
11/16/2015 12:27:18 PM - positioning 0560 to file 7
11/16/2015 12:27:18 PM - positioned 0560; position time: 00:00:00
11/16/2015 12:27:18 PM - begin reading
11/16/2015 12:33:13 PM - Info bptm(pid=23148) waited for empty buffer 940 times, delayed 6499 times    
11/16/2015 12:33:13 PM - end reading; read time: 00:05:55
11/16/2015 12:33:13 PM - positioning 0560 to file 8
11/16/2015 12:33:13 PM - positioned 0560; position time: 00:00:00
11/16/2015 12:33:13 PM - begin reading
11/16/2015 12:33:58 PM - Info bptm(pid=28404) Waiting for mount of media id 0257 (copy 2) on server mailbck1. 
11/16/2015 12:33:58 PM - started process bptm (28404)
11/16/2015 12:33:58 PM - mounting 0257
11/16/2015 12:33:58 PM - Info bptm(pid=28404) INF - Waiting for mount of media id 0257 on server mailbck1 for writing.
11/16/2015 12:33:58 PM - current media 0568 complete, requesting next resource Any
11/16/2015 12:33:58 PM - granted resource 0257
11/16/2015 12:33:58 PM - granted resource LTO4-1
11/16/2015 12:33:58 PM - granted resource LocalTape
11/16/2015 12:35:07 PM - Info bptm(pid=28404) media id 0257 mounted on drive index 0, drivepath {2,0,3,0}, drivename LTO4-1, copy 2
11/16/2015 12:49:42 PM - Info bptm(pid=23148) waited for empty buffer 5701 times, delayed 17714 times    
11/16/2015 12:49:42 PM - end reading; read time: 00:16:29
11/16/2015 12:49:42 PM - positioning 0560 to file 9
11/16/2015 12:49:42 PM - positioned 0560; position time: 00:00:00
11/16/2015 12:49:42 PM - begin reading
11/16/2015 12:54:54 PM - Info bptm(pid=23148) waited for empty buffer 783 times, delayed 2119 times    
11/16/2015 12:54:54 PM - end reading; read time: 00:05:12
11/16/2015 12:54:54 PM - positioning 0560 to file 10
11/16/2015 12:54:54 PM - positioned 0560; position time: 00:00:00
11/16/2015 12:54:54 PM - begin reading
11/16/2015 1:10:54 PM - Info bptm(pid=23148) waited for empty buffer 6328 times, delayed 12116 times    
11/16/2015 1:10:54 PM - end reading; read time: 00:16:00
11/16/2015 1:10:54 PM - positioning 0560 to file 11
11/16/2015 1:10:54 PM - positioned 0560; position time: 00:00:00
11/16/2015 1:10:54 PM - begin reading
11/16/2015 1:16:45 PM - Info bptm(pid=23148) waited for empty buffer 1836 times, delayed 4793 times    
11/16/2015 1:16:45 PM - end reading; read time: 00:05:51
11/16/2015 1:16:45 PM - positioning 0560 to file 12
11/16/2015 1:16:45 PM - positioned 0560; position time: 00:00:00
11/16/2015 1:16:45 PM - begin reading
11/16/2015 1:32:54 PM - Info bptm(pid=23148) waited for empty buffer 4260 times, delayed 10646 times    
11/16/2015 1:32:54 PM - end reading; read time: 00:16:09
11/16/2015 1:32:54 PM - positioning 0560 to file 13
11/16/2015 1:32:54 PM - positioned 0560; position time: 00:00:00
11/16/2015 1:32:54 PM - begin reading
11/16/2015 1:37:00 PM - Info bptm(pid=23148) waited for empty buffer 1248 times, delayed 2110 times    
11/16/2015 1:37:00 PM - end reading; read time: 00:04:06
11/16/2015 1:37:00 PM - positioning 0560 to file 14
11/16/2015 1:37:00 PM - positioned 0560; position time: 00:00:00
11/16/2015 1:37:00 PM - begin reading
11/16/2015 1:48:42 PM - Info bptm(pid=23148) waited for empty buffer 2893 times, delayed 8709 times    
11/16/2015 1:48:42 PM - end reading; read time: 00:11:42
11/16/2015 1:48:42 PM - positioning 0560 to file 15
11/16/2015 1:48:42 PM - positioned 0560; position time: 00:00:00
11/16/2015 1:48:42 PM - begin reading
11/16/2015 1:53:07 PM - Info bptm(pid=23148) waited for empty buffer 1499 times, delayed 3625 times    
11/16/2015 1:53:07 PM - end reading; read time: 00:04:25
11/16/2015 1:53:07 PM - Info bptm(pid=28404) waited for full buffer 119727 times, delayed 187928 times    
11/16/2015 1:53:08 PM - Info bptm(pid=28404) setting receive network buffer to 525312 bytes      
11/16/2015 1:53:08 PM - positioning 0560 to file 16
11/16/2015 1:53:08 PM - positioned 0560; position time: 00:00:00
11/16/2015 1:53:09 PM - Info bptm(pid=23148) completed reading backup image         
11/16/2015 1:53:09 PM - Info bptm(pid=23148) EXITING with status 0 <----------        
11/16/2015 1:53:17 PM - Info bptm(pid=28404) EXITING with status 0 <----------        
11/16/2015 1:53:18 PM - Info bptm(pid=28544) start            
11/16/2015 1:53:18 PM - started process bptm (28544)
11/16/2015 1:53:18 PM - requesting resource LocalTape
11/16/2015 1:53:18 PM - granted resource 0257
11/16/2015 1:53:18 PM - granted resource LTO4-1
11/16/2015 1:53:18 PM - granted resource LocalTape
11/16/2015 1:53:19 PM - Info bptm(pid=28544) start backup           
11/16/2015 1:53:19 PM - Info bptm(pid=18888) start            
11/16/2015 1:53:19 PM - started process bptm (18888)
11/16/2015 1:53:19 PM - Info bpdm(pid=18888) reading backup image          
11/16/2015 1:53:19 PM - Info bptm(pid=18888) using 128 data buffers         
11/16/2015 1:53:19 PM - requesting resource 0560
11/16/2015 1:53:19 PM - granted resource 0560
11/16/2015 1:53:19 PM - granted resource LTO4-6
11/16/2015 1:53:20 PM - Info bptm(pid=28544) media id 0257 mounted on drive index 0, drivepath {2,0,3,0}, drivename LTO4-1, copy 2
11/16/2015 1:53:20 PM - Info bptm(pid=28544) INF - Waiting for positioning of media id 0257 on server mailbck1 for writing.
11/16/2015 1:53:20 PM - mounted
11/16/2015 1:53:20 PM - Info bptm(pid=18888) 0560            
11/16/2015 1:53:20 PM - Info bptm(pid=18888) INF - Waiting for positioning of media id 0560 on server mailbck1 for reading.
11/16/2015 1:53:20 PM - positioning 0560 to file 17
11/16/2015 1:53:20 PM - positioned 0560; position time: 00:00:00
11/16/2015 1:53:20 PM - begin reading
11/16/2015 2:07:06 PM - Info bptm(pid=18888) waited for empty buffer 4788 times, delayed 6749 times    
11/16/2015 2:07:06 PM - end reading; read time: 00:13:46
11/16/2015 2:07:06 PM - positioning 0560 to file 18
11/16/2015 2:07:06 PM - positioned 0560; position time: 00:00:00
11/16/2015 2:07:06 PM - begin reading
11/16/2015 2:10:36 PM - Info bptm(pid=18888) waited for empty buffer 185 times, delayed 601 times    
11/16/2015 2:10:36 PM - end reading; read time: 00:03:30
11/16/2015 2:10:36 PM - positioning 0560 to file 19
11/16/2015 2:10:36 PM - positioned 0560; position time: 00:00:00
11/16/2015 2:10:36 PM - begin reading
11/16/2015 2:10:43 PM - Info bptm(pid=18888) waited for empty buffer 1 times, delayed 139 times    
11/16/2015 2:10:43 PM - end reading; read time: 00:00:07
11/16/2015 2:10:43 PM - Info bptm(pid=18888) Waiting for mount of media id 0510 (copy 1) on server mailbck1. 
11/16/2015 2:10:43 PM - started process bptm (18888)
11/16/2015 2:10:43 PM - mounting 0510
11/16/2015 2:10:43 PM - Info bptm(pid=18888) INF - Waiting for mount of media id 0510 on server mailbck1 for reading.
11/16/2015 2:10:43 PM - current media 0560 complete, requesting next resource LTO4-6:0510
11/16/2015 2:10:43 PM - granted resource 0510
11/16/2015 2:10:43 PM - granted resource LTO4-2
11/16/2015 2:12:00 PM - mounted; mount time: 00:01:17
11/16/2015 2:12:00 PM - Info bptm(pid=18888) 0510            
11/16/2015 2:12:00 PM - Info bptm(pid=18888) INF - Waiting for positioning of media id 0510 on server mailbck1 for reading.
11/16/2015 2:12:00 PM - positioning 0510 to file 1
11/16/2015 2:12:00 PM - positioned 0510; position time: 00:00:00
11/16/2015 2:12:00 PM - begin reading
11/16/2015 2:32:54 PM - Info bptm(pid=18888) waited for empty buffer 6965 times, delayed 23548 times    
11/16/2015 2:32:54 PM - end reading; read time: 00:20:54
11/16/2015 2:32:54 PM - positioning 0510 to file 2
11/16/2015 2:32:54 PM - positioned 0510; position time: 00:00:00
11/16/2015 2:32:54 PM - begin reading
11/16/2015 2:38:46 PM - Info bptm(pid=18888) waited for empty buffer 787 times, delayed 3760 times    
11/16/2015 2:38:46 PM - end reading; read time: 00:05:52
11/16/2015 2:38:46 PM - positioning 0510 to file 3
11/16/2015 2:38:46 PM - positioned 0510; position time: 00:00:00
11/16/2015 2:38:46 PM - begin reading
11/16/2015 3:04:22 PM - Info bptm(pid=18888) waited for empty buffer 6942 times, delayed 28449 times    
11/16/2015 3:04:22 PM - end reading; read time: 00:25:36
11/16/2015 3:04:22 PM - positioning 0510 to file 4
11/16/2015 3:04:22 PM - positioned 0510; position time: 00:00:00
11/16/2015 3:04:22 PM - begin reading
11/16/2015 3:09:25 PM - Info bptm(pid=18888) waited for empty buffer 1142 times, delayed 2161 times    
11/16/2015 3:09:25 PM - end reading; read time: 00:05:03
11/16/2015 3:09:25 PM - positioning 0510 to file 5
11/16/2015 3:09:25 PM - positioned 0510; position time: 00:00:00
11/16/2015 3:09:25 PM - begin reading
11/16/2015 3:26:22 PM - Info bptm(pid=18888) waited for empty buffer 5168 times, delayed 7382 times    
11/16/2015 3:26:22 PM - end reading; read time: 00:16:57
11/16/2015 3:26:22 PM - positioning 0510 to file 6
11/16/2015 3:26:22 PM - positioned 0510; position time: 00:00:00
11/16/2015 3:26:22 PM - begin reading
11/16/2015 3:31:29 PM - Info bptm(pid=28544) Waiting for mount of media id 0570 (copy 2) on server mailbck1. 
11/16/2015 3:31:29 PM - started process bptm (28544)
11/16/2015 3:31:29 PM - mounting 0570
11/16/2015 3:31:29 PM - Info bptm(pid=28544) INF - Waiting for mount of media id 0570 on server mailbck1 for writing.
11/16/2015 3:31:29 PM - current media 0257 complete, requesting next resource Any
11/16/2015 3:31:29 PM - granted resource 0570
11/16/2015 3:31:29 PM - granted resource LTO4-4
11/16/2015 3:31:29 PM - granted resource LocalTape
11/16/2015 3:32:36 PM - Info bptm(pid=28544) media id 0570 mounted on drive index 2, drivepath {1,0,3,0}, drivename LTO4-4, copy 2
11/16/2015 3:33:37 PM - Info bptm(pid=18888) waited for empty buffer 1977 times, delayed 13141 times    
11/16/2015 3:33:37 PM - end reading; read time: 00:07:15
11/16/2015 3:33:37 PM - positioning 0510 to file 7
11/16/2015 3:33:37 PM - positioned 0510; position time: 00:00:00
11/16/2015 3:33:37 PM - begin reading
11/16/2015 3:41:34 PM - Info bptm(pid=18888) waited for empty buffer 2389 times, delayed 8895 times    
11/16/2015 3:41:34 PM - end reading; read time: 00:07:57
11/16/2015 3:41:34 PM - positioning 0510 to file 8
11/16/2015 3:41:34 PM - positioned 0510; position time: 00:00:00
11/16/2015 3:41:34 PM - begin reading
11/16/2015 4:00:09 PM - Info bptm(pid=18888) waited for empty buffer 9289 times, delayed 16586 times    
11/16/2015 4:00:09 PM - end reading; read time: 00:18:35
11/16/2015 4:00:09 PM - positioning 0510 to file 9
11/16/2015 4:00:09 PM - positioned 0510; position time: 00:00:00
11/16/2015 4:00:09 PM - begin reading
11/16/2015 4:02:50 PM - Info bptm(pid=18888) waited for empty buffer 793 times, delayed 1249 times    
11/16/2015 4:02:50 PM - end reading; read time: 00:02:41
11/16/2015 4:02:50 PM - positioning 0510 to file 10
11/16/2015 4:02:50 PM - positioned 0510; position time: 00:00:00
11/16/2015 4:02:50 PM - begin reading
11/16/2015 4:02:52 PM - Info bptm(pid=18888) waited for empty buffer 2 times, delayed 140 times    
11/16/2015 4:02:52 PM - end reading; read time: 00:00:02
11/16/2015 4:02:52 PM - positioning 0510 to file 11
11/16/2015 4:02:52 PM - positioned 0510; position time: 00:00:00
11/16/2015 4:02:52 PM - begin reading
11/16/2015 4:02:59 PM - Info bptm(pid=18888) waited for empty buffer 1 times, delayed 142 times    
11/16/2015 4:02:59 PM - end reading; read time: 00:00:07
11/16/2015 4:02:59 PM - Info bptm(pid=28544) waited for full buffer 108378 times, delayed 181477 times    
11/16/2015 4:03:00 PM - positioning 0510 to file 12
11/16/2015 4:03:00 PM - positioned 0510; position time: 00:00:00
11/16/2015 4:03:00 PM - Info bptm(pid=28544) setting receive network buffer to 525312 bytes      
11/16/2015 4:03:01 PM - Info bptm(pid=18888) completed reading backup image         
11/16/2015 4:03:01 PM - Info bptm(pid=18888) EXITING with status 0 <----------        
11/16/2015 4:03:07 PM - Info bptm(pid=28544) EXITING with status 0 <----------        
11/16/2015 4:03:07 PM - Info bptm(pid=28312) start            
11/16/2015 4:03:07 PM - started process bptm (28312)
11/16/2015 4:03:07 PM - requesting resource LocalTape
11/16/2015 4:03:08 PM - Info bptm(pid=28312) start backup           
11/16/2015 4:03:08 PM - Info bptm(pid=19764) start            
11/16/2015 4:03:08 PM - started process bptm (19764)
11/16/2015 4:03:08 PM - Info bpdm(pid=19764) reading backup image          
11/16/2015 4:03:08 PM - granted resource 0175
11/16/2015 4:03:08 PM - granted resource LTO4-1
11/16/2015 4:03:08 PM - granted resource LocalTape
11/16/2015 4:03:09 PM - Info bptm(pid=19764) using 128 data buffers         
11/16/2015 4:03:09 PM - Info bptm(pid=28312) Waiting for mount of media id 0175 (copy 2) on server mailbck1. 
11/16/2015 4:03:09 PM - started process bptm (28312)
11/16/2015 4:03:09 PM - mounting 0175
11/16/2015 4:03:09 PM - Info bptm(pid=28312) INF - Waiting for mount of media id 0175 on server mailbck1 for writing.
11/16/2015 4:03:09 PM - Info bptm(pid=19764) Waiting for mount of media id 0319 (copy 1) on server mailbck1. 
11/16/2015 4:03:09 PM - started process bptm (19764)
11/16/2015 4:03:09 PM - mounting 0319
11/16/2015 4:03:09 PM - Info bptm(pid=19764) INF - Waiting for mount of media id 0319 on server mailbck1 for reading.
11/16/2015 4:03:09 PM - requesting resource 0319
11/16/2015 4:03:09 PM - granted resource 0319
11/16/2015 4:03:09 PM - granted resource LTO4-5
11/16/2015 4:04:18 PM - Info bptm(pid=28312) media id 0175 mounted on drive index 0, drivepath {2,0,3,0}, drivename LTO4-1, copy 2
11/16/2015 4:04:24 PM - Info bptm(pid=28312) INF - Waiting for positioning of media id 0175 on server mailbck1 for writing.
11/16/2015 4:05:21 PM - mounted; mount time: 00:02:12
11/16/2015 4:05:21 PM - Info bptm(pid=19764) 0319            
11/16/2015 4:05:21 PM - Info bptm(pid=19764) INF - Waiting for positioning of media id 0319 on server mailbck1 for reading.
11/16/2015 4:05:21 PM - positioning 0319 to file 10
11/16/2015 4:08:32 PM - positioned 0319; position time: 00:03:11
11/16/2015 4:08:32 PM - begin reading
11/16/2015 4:11:12 PM - Info bptm(pid=19764) waited for empty buffer 131 times, delayed 400 times    
11/16/2015 4:11:12 PM - end reading; read time: 00:02:40
11/16/2015 4:11:12 PM - Info bptm(pid=19764) Waiting for mount of media id 0330 (copy 1) on server mailbck1. 
11/16/2015 4:11:12 PM - started process bptm (19764)
11/16/2015 4:11:12 PM - mounting 0330
11/16/2015 4:11:12 PM - Info bptm(pid=19764) INF - Waiting for mount of media id 0330 on server mailbck1 for reading.
11/16/2015 4:11:12 PM - current media 0319 complete, requesting next resource LTO4-5:0330
11/16/2015 4:11:12 PM - granted resource 0330
11/16/2015 4:11:12 PM - granted resource LTO4-2
11/16/2015 4:12:27 PM - mounted; mount time: 00:01:15
11/16/2015 4:12:27 PM - Info bptm(pid=19764) 0330            
11/16/2015 4:12:27 PM - Info bptm(pid=19764) INF - Waiting for positioning of media id 0330 on server mailbck1 for reading.
11/16/2015 4:12:27 PM - positioning 0330 to file 1
11/16/2015 4:12:27 PM - positioned 0330; position time: 00:00:00
11/16/2015 4:12:27 PM - begin reading
11/16/2015 4:37:14 PM - Info bptm(pid=19764) waited for empty buffer 2309 times, delayed 10280 times    
11/16/2015 4:37:14 PM - end reading; read time: 00:24:47
11/16/2015 4:37:14 PM - positioning 0330 to file 2
11/16/2015 4:37:14 PM - positioned 0330; position time: 00:00:00
11/16/2015 4:37:14 PM - begin reading
11/16/2015 4:46:53 PM - Info bptm(pid=19764) waited for empty buffer 1382 times, delayed 10074 times    
11/16/2015 4:46:53 PM - end reading; read time: 00:09:39
11/16/2015 4:46:53 PM - positioning 0330 to file 3
11/16/2015 4:46:53 PM - positioned 0330; position time: 00:00:00
11/16/2015 4:46:53 PM - begin reading
11/16/2015 5:22:11 PM - Info bptm(pid=19764) waited for empty buffer 7271 times, delayed 32773 times    
11/16/2015 5:22:11 PM - end reading; read time: 00:35:18
11/16/2015 5:22:11 PM - positioning 0330 to file 4
11/16/2015 5:22:11 PM - positioned 0330; position time: 00:00:00
11/16/2015 5:22:11 PM - begin reading
11/16/2015 5:30:48 PM - Info bptm(pid=19764) waited for empty buffer 1506 times, delayed 7622 times    
11/16/2015 5:30:48 PM - end reading; read time: 00:08:37
11/16/2015 5:30:48 PM - positioning 0330 to file 5
11/16/2015 5:30:48 PM - positioned 0330; position time: 00:00:00
11/16/2015 5:30:48 PM - begin reading
11/16/2015 6:05:05 PM - Info bptm(pid=19764) waited for empty buffer 6843 times, delayed 29173 times    
11/16/2015 6:05:05 PM - end reading; read time: 00:34:17
11/16/2015 6:05:05 PM - positioning 0330 to file 6
11/16/2015 6:05:05 PM - positioned 0330; position time: 00:00:00
11/16/2015 6:05:05 PM - begin reading
11/16/2015 6:15:13 PM - Info bptm(pid=19764) waited for empty buffer 1913 times, delayed 12088 times    
11/16/2015 6:15:13 PM - end reading; read time: 00:10:08
11/16/2015 6:15:13 PM - positioning 0330 to file 7
11/16/2015 6:15:13 PM - positioned 0330; position time: 00:00:00
11/16/2015 6:15:13 PM - begin reading
11/16/2015 6:41:31 PM - Info bptm(pid=19764) waited for empty buffer 4075 times, delayed 18556 times    
11/16/2015 6:41:31 PM - end reading; read time: 00:26:18
11/16/2015 6:41:31 PM - positioning 0330 to file 8
11/16/2015 6:41:31 PM - positioned 0330; position time: 00:00:00
11/16/2015 6:41:31 PM - begin reading
11/16/2015 6:45:53 PM - Info bptm(pid=19764) waited for empty buffer 157 times, delayed 670 times    
11/16/2015 6:45:53 PM - end reading; read time: 00:04:22
11/16/2015 6:45:53 PM - positioning 0330 to file 9
11/16/2015 6:45:53 PM - positioned 0330; position time: 00:00:00
11/16/2015 6:45:53 PM - begin reading
11/16/2015 7:12:40 PM - Info bptm(pid=19764) waited for empty buffer 4535 times, delayed 17981 times    
11/16/2015 7:12:41 PM - end reading; read time: 00:26:48
11/16/2015 7:12:41 PM - positioning 0330 to file 10
11/16/2015 7:12:41 PM - positioned 0330; position time: 00:00:00
11/16/2015 7:12:41 PM - begin reading
11/16/2015 7:19:36 PM - Info bptm(pid=19764) waited for empty buffer 969 times, delayed 3655 times    
11/16/2015 7:19:36 PM - end reading; read time: 00:06:55
11/16/2015 7:19:36 PM - positioning 0330 to file 11
11/16/2015 7:19:36 PM - positioned 0330; position time: 00:00:00
11/16/2015 7:19:36 PM - begin reading
11/16/2015 7:20:43 PM - Info bptm(pid=19764) waited for empty buffer 1 times, delayed 142 times    
11/16/2015 7:20:43 PM - end reading; read time: 00:01:07
11/16/2015 7:20:43 PM - current media 0330 complete, requesting next resource LTO4-2:0577
11/16/2015 7:20:43 PM - granted resource 0577
11/16/2015 7:20:43 PM - granted resource LTO4-5
11/16/2015 7:20:44 PM - Info bptm(pid=19764) Waiting for mount of media id 0577 (copy 1) on server mailbck1. 
11/16/2015 7:20:44 PM - started process bptm (19764)
11/16/2015 7:20:44 PM - mounting 0577
11/16/2015 7:20:44 PM - Info bptm(pid=19764) INF - Waiting for mount of media id 0577 on server mailbck1 for reading.
11/16/2015 7:21:53 PM - mounted; mount time: 00:01:09
11/16/2015 7:21:53 PM - Info bptm(pid=19764) 0577            
11/16/2015 7:21:53 PM - Info bptm(pid=19764) INF - Waiting for positioning of media id 0577 on server mailbck1 for reading.
11/16/2015 7:21:53 PM - positioning 0577 to file 1
11/16/2015 7:21:53 PM - positioned 0577; position time: 00:00:00
11/16/2015 7:21:53 PM - begin reading
11/16/2015 7:59:23 PM - Info bptm(pid=19764) waited for empty buffer 7978 times, delayed 43192 times    
11/16/2015 7:59:23 PM - end reading; read time: 00:37:30
11/16/2015 7:59:23 PM - positioning 0577 to file 2
11/16/2015 7:59:23 PM - positioned 0577; position time: 00:00:00
11/16/2015 7:59:23 PM - begin reading
11/16/2015 8:07:33 PM - current media 0175 complete, requesting next resource Any
11/16/2015 8:07:34 PM - Info bptm(pid=28312) Waiting for mount of media id 0495 (copy 2) on server mailbck1. 
11/16/2015 8:07:34 PM - started process bptm (28312)
11/16/2015 8:07:34 PM - mounting 0495
11/16/2015 8:07:34 PM - Info bptm(pid=28312) INF - Waiting for mount of media id 0495 on server mailbck1 for writing.
11/16/2015 8:07:34 PM - granted resource 0495
11/16/2015 8:07:34 PM - granted resource LTO4-3
11/16/2015 8:07:34 PM - granted resource LocalTape
11/16/2015 8:08:42 PM - Info bptm(pid=28312) media id 0495 mounted on drive index 3, drivepath {2,0,4,0}, drivename LTO4-3, copy 2
11/16/2015 8:09:07 PM - Info bptm(pid=19764) waited for empty buffer 1238 times, delayed 10084 times    
11/16/2015 8:09:07 PM - end reading; read time: 00:09:44
11/16/2015 8:09:07 PM - Info bptm(pid=28312) waited for full buffer 232106 times, delayed 468666 times    
11/16/2015 8:09:09 PM - Info bptm(pid=28312) setting receive network buffer to 525312 bytes      
11/16/2015 8:09:09 PM - positioning 0577 to file 3
11/16/2015 8:09:09 PM - positioned 0577; position time: 00:00:00
11/16/2015 8:09:09 PM - Info bptm(pid=19764) completed reading backup image         
11/16/2015 8:09:09 PM - Info bptm(pid=19764) EXITING with status 0 <----------        
11/16/2015 8:09:18 PM - Info bptm(pid=28312) EXITING with status 0 <----------        
11/16/2015 8:09:18 PM - Info bptm(pid=26228) start            
11/16/2015 8:09:18 PM - started process bptm (26228)
11/16/2015 8:09:18 PM - requesting resource LocalTape
11/16/2015 8:09:18 PM - granted resource 0495
11/16/2015 8:09:18 PM - granted resource LTO4-3
11/16/2015 8:09:18 PM - granted resource LocalTape
11/16/2015 8:09:19 PM - Info bptm(pid=26228) start backup           
11/16/2015 8:09:19 PM - Info bptm(pid=17484) start            
11/16/2015 8:09:19 PM - started process bptm (17484)
11/16/2015 8:09:19 PM - Info bpdm(pid=17484) reading backup image          
11/16/2015 8:09:19 PM - Info bptm(pid=17484) using 128 data buffers         
11/16/2015 8:09:19 PM - requesting resource 0546
11/16/2015 8:09:20 PM - Info bptm(pid=17484) Waiting for mount of media id 0546 (copy 1) on server mailbck1. 
11/16/2015 8:09:20 PM - started process bptm (17484)
11/16/2015 8:09:20 PM - mounting 0546
11/16/2015 8:09:20 PM - Info bptm(pid=17484) INF - Waiting for mount of media id 0546 on server mailbck1 for reading.
11/16/2015 8:09:20 PM - Info bptm(pid=26228) media id 0495 mounted on drive index 3, drivepath {2,0,4,0}, drivename LTO4-3, copy 2
11/16/2015 8:09:20 PM - Info bptm(pid=26228) INF - Waiting for positioning of media id 0495 on server mailbck1 for writing.
11/16/2015 8:09:20 PM - granted resource 0546
11/16/2015 8:09:20 PM - granted resource LTO4-1
11/16/2015 8:10:36 PM - mounted; mount time: 00:01:16
11/16/2015 8:10:36 PM - Info bptm(pid=17484) 0546            
11/16/2015 8:10:37 PM - Info bptm(pid=17484) INF - Waiting for positioning of media id 0546 on server mailbck1 for reading.
11/16/2015 8:10:37 PM - positioning 0546 to file 6
11/16/2015 8:12:05 PM - positioned 0546; position time: 00:01:28
11/16/2015 8:12:05 PM - begin reading
11/16/2015 8:30:03 PM - Info bptm(pid=17484) waited for empty buffer 9151 times, delayed 18590 times    
11/16/2015 8:30:03 PM - end reading; read time: 00:17:58
11/16/2015 8:30:03 PM - positioning 0546 to file 7
11/16/2015 8:30:03 PM - positioned 0546; position time: 00:00:00
11/16/2015 8:30:03 PM - begin reading
11/16/2015 8:33:27 PM - Info bptm(pid=17484) waited for empty buffer 1003 times, delayed 2598 times    
11/16/2015 8:33:27 PM - end reading; read time: 00:03:24
11/16/2015 8:33:27 PM - positioning 0546 to file 8
11/16/2015 8:33:27 PM - positioned 0546; position time: 00:00:00
11/16/2015 8:33:27 PM - begin reading
11/16/2015 8:50:35 PM - Info bptm(pid=17484) waited for empty buffer 9335 times, delayed 14242 times    
11/16/2015 8:50:35 PM - end reading; read time: 00:17:08
11/16/2015 8:50:35 PM - positioning 0546 to file 9
11/16/2015 8:50:35 PM - positioned 0546; position time: 00:00:00
11/16/2015 8:50:35 PM - begin reading
11/16/2015 8:53:42 PM - Info bptm(pid=17484) waited for empty buffer 1265 times, delayed 1982 times    
11/16/2015 8:53:42 PM - end reading; read time: 00:03:07
11/16/2015 8:53:42 PM - positioning 0546 to file 10
11/16/2015 8:53:42 PM - positioned 0546; position time: 00:00:00
11/16/2015 8:53:42 PM - begin reading
11/16/2015 9:05:15 PM - Info bptm(pid=17484) waited for empty buffer 6833 times, delayed 12292 times    
11/16/2015 9:05:15 PM - end reading; read time: 00:11:33
11/16/2015 9:05:15 PM - Info bptm(pid=17484) Waiting for mount of media id 0498 (copy 1) on server mailbck1. 
11/16/2015 9:05:15 PM - started process bptm (17484)
11/16/2015 9:05:15 PM - mounting 0498
11/16/2015 9:05:15 PM - Info bptm(pid=17484) INF - Waiting for mount of media id 0498 on server mailbck1 for reading.
11/16/2015 9:05:15 PM - current media 0546 complete, requesting next resource LTO4-1:0498
11/16/2015 9:05:15 PM - granted resource 0498
11/16/2015 9:05:15 PM - granted resource LTO4-2
11/16/2015 9:06:32 PM - mounted; mount time: 00:01:17
11/16/2015 9:06:32 PM - Info bptm(pid=17484) 0498            
11/16/2015 9:06:32 PM - Info bptm(pid=17484) INF - Waiting for positioning of media id 0498 on server mailbck1 for reading.
11/16/2015 9:06:32 PM - positioning 0498 to file 1
11/16/2015 9:06:32 PM - positioned 0498; position time: 00:00:00
11/16/2015 9:06:32 PM - begin reading
11/16/2015 9:16:23 PM - Info bptm(pid=17484) waited for empty buffer 3476 times, delayed 12946 times    
11/16/2015 9:16:23 PM - end reading; read time: 00:09:51
11/16/2015 9:16:23 PM - positioning 0498 to file 2
11/16/2015 9:16:23 PM - positioned 0498; position time: 00:00:00
11/16/2015 9:16:23 PM - begin reading
11/16/2015 9:19:21 PM - Info bptm(pid=17484) waited for empty buffer 939 times, delayed 1402 times    
11/16/2015 9:19:21 PM - end reading; read time: 00:02:58
11/16/2015 9:19:21 PM - positioning 0498 to file 3
11/16/2015 9:19:21 PM - positioned 0498; position time: 00:00:00
11/16/2015 9:19:21 PM - begin reading
11/16/2015 9:34:09 PM - Info bptm(pid=17484) waited for empty buffer 6435 times, delayed 8840 times    
11/16/2015 9:34:09 PM - end reading; read time: 00:14:48
11/16/2015 9:34:09 PM - positioning 0498 to file 4
11/16/2015 9:34:09 PM - positioned 0498; position time: 00:00:00
11/16/2015 9:34:09 PM - begin reading
11/16/2015 9:36:16 PM - Info bptm(pid=17484) waited for empty buffer 240 times, delayed 439 times    
11/16/2015 9:36:16 PM - end reading; read time: 00:02:07
11/16/2015 9:36:16 PM - positioning 0498 to file 5
11/16/2015 9:36:16 PM - positioned 0498; position time: 00:00:00
11/16/2015 9:36:16 PM - begin reading
11/16/2015 9:50:19 PM - Info bptm(pid=17484) waited for empty buffer 5503 times, delayed 9418 times    
11/16/2015 9:50:19 PM - end reading; read time: 00:14:03
11/16/2015 9:50:19 PM - positioning 0498 to file 6
11/16/2015 9:50:19 PM - positioned 0498; position time: 00:00:00
11/16/2015 9:50:19 PM - begin reading
11/16/2015 9:58:53 PM - Info bptm(pid=17484) waited for empty buffer 1878 times, delayed 8711 times    
11/16/2015 9:58:53 PM - end reading; read time: 00:08:34
11/16/2015 9:58:53 PM - positioning 0498 to file 7
11/16/2015 9:58:53 PM - positioned 0498; position time: 00:00:00
11/16/2015 9:58:53 PM - begin reading
11/16/2015 10:26:12 PM - Info bptm(pid=17484) waited for empty buffer 10451 times, delayed 31759 times    
11/16/2015 10:26:12 PM - end reading; read time: 00:27:19
11/16/2015 10:26:12 PM - positioning 0498 to file 8
11/16/2015 10:26:12 PM - positioned 0498; position time: 00:00:00
11/16/2015 10:26:12 PM - begin reading
11/16/2015 10:29:07 PM - Info bptm(pid=17484) waited for empty buffer 654 times, delayed 1111 times    
11/16/2015 10:29:07 PM - end reading; read time: 00:02:55
11/16/2015 10:29:07 PM - Info bptm(pid=26228) waited for full buffer 86428 times, delayed 160740 times    
11/16/2015 10:29:08 PM - Info bptm(pid=26228) setting receive network buffer to 525312 bytes      
11/16/2015 10:29:08 PM - positioning 0498 to file 9
11/16/2015 10:29:08 PM - positioned 0498; position time: 00:00:00
11/16/2015 10:29:08 PM - Info bptm(pid=17484) completed reading backup image         
11/16/2015 10:29:08 PM - Info bptm(pid=17484) EXITING with status 0 <----------        
11/16/2015 10:29:17 PM - Info bptm(pid=26228) EXITING with status 0 <----------        
11/16/2015 10:29:17 PM - end Duplicate; elapsed time: 14:29:16
the requested operation was successfully completed(0)