Duplication problems drive me crazy (code 191)

[keyz]

Hi,

Here is my config :

Master : Netbackup 6.5.1 Solaris 10
Media Server : Netbackup 6.5.1 AIX
STK L700 Library (LTO 3 drives FC)
VTL FalconStor

Backup are fine but when i try to duplicate some (not all) images it fails after a couple of hours :

1 sept. 2010 05:24:03 - positioning VB0307 to file 308
1 sept. 2010 05:24:03 - positioned VB0307; position time: 0:00:00
1 sept. 2010 06:11:29 - Error bpduplicate (pid=19736) socket read failed: errno = 131 - Connection reset by peer
1 sept. 2010 06:11:29 - Error bpduplicate (pid=19736) host xxxxx backup id xxxxxxxxxxx_1283289040 read process failed, file read failed (13).
1 sept. 2010 06:11:32 - Error bpduplicate (pid=19736) Duplicate of backup id xxxxxxxxxxxxxxx_1283289040 failed, file read failed (13).
1 sept. 2010 06:11:32 - Error bpduplicate (pid=19736) Status = no images were successfully processed.
1 sept. 2010 06:11:33 - end Duplicate; elapsed time 3:31:33

Verify of the SAME image is correct

1 sept. 2010 10:05:39 - positioning VB0307 to file 308
1 sept. 2010 10:05:39 - positioned VB0307; position time: 0:00:00
1 sept. 2010 10:05:20 - end Verify; elapsed time 0:56:30
the requested operation was successfully completed (0)

It seems that the duplication go until the end (file 308) but failed after that. This is driving me NUTS ! I have activated all the logs on master and media server but i can't find anything except a "put_short: (10) network write() error: Broken pipe (32); socket = 13

Other images from the same media server are fine. The problem appears with only 3 or 4 images, even if i use the GUI or the bpduplicate command

Any idea ?






 

[keyz]

i just found this :

20100902.22928349.BPTM____.00039370 xxxxxxxxxxx______ 06:22:08.349 [1839150] <2> bptm: EXITING with status 0 <----------
20100902.22957500.ADMIN___.00004955 xxxxxxxxxxx______ 06:22:37.500 [18240] <2> bpduplicate: Received keep alive
20100902.23017510.ADMIN___.00004956 xxxxxxxxxxx______ 06:23:37.510 [18240] <2> bpduplicate: Received keep alive
20100902.23077520.ADMIN___.00004959 xxxxxxxxxxx______ 06:24:37.520 [18240] <2> bpduplicate: Received keep alive
20100902.23137530.ADMIN___.00005000 xxxxxxxxxxx______ 06:25:37.530 [18240] <2> bpduplicate: Received keep alive
20100902.23197540.ADMIN___.00005001 xxxxxxxxxxx______ 06:26:37.540 [18240] <2> bpduplicate: Received keep alive
20100902.23257550.ADMIN___.00005002 xxxxxxxxxxx______ 06:27:37.550 [18240] <2> bpduplicate: Received keep alive
20100902.23317560.ADMIN___.00005003 xxxxxxxxxxx______ 06:28:37.560 [18240] <2> bpduplicate: Received keep alive
20100902.23377570.ADMIN___.00005006 xxxxxxxxxxx______ 06:29:37.570 [18240] <2> bpduplicate: Received keep alive
20100902.23437580.ADMIN___.00005180 xxxxxxxxxxx______ 06:30:37.580 [18240] <2> bpduplicate: Received keep alive
20100902.23497590.ADMIN___.00005182 xxxxxxxxxxx______ 06:31:37.590 [18240] <2> bpduplicate: Received keep alive
20100902.23557600.ADMIN___.00005184 xxxxxxxxxxx______ 06:32:37.600 [18240] <2> bpduplicate: Received keep alive
20100902.23617610.ADMIN___.00005186 xxxxxxxxxxx______ 06:33:37.610 [18240] <2> bpduplicate: Received keep alive
20100902.23677620.ADMIN___.00005190 xxxxxxxxxxx______ 06:34:37.620 [18240] <2> bpduplicate: Received keep alive
20100902.23737630.ADMIN___.00005192 xxxxxxxxxxx______ 06:35:37.630 [18240] <2> bpduplicate: Received keep alive
20100902.23797640.ADMIN___.00005194 xxxxxxxxxxx______ 06:36:37.640 [18240] <2> bpduplicate: Received keep alive
20100902.23857650.ADMIN___.00005196 xxxxxxxxxxx______ 06:37:37.650 [18240] <2> bpduplicate: Received keep alive
20100902.23917660.ADMIN___.00005213 xxxxxxxxxxx______ 06:38:37.660 [18240] <2> bpduplicate: Received keep alive
20100902.23977670.ADMIN___.00005217 xxxxxxxxxxx______ 06:39:37.670 [18240] <2> bpduplicate: Received keep alive
20100902.24037680.ADMIN___.00005219 xxxxxxxxxxx______ 06:40:37.680 [18240] <2> bpduplicate: Received keep alive
20100902.24097690.ADMIN___.00005221 xxxxxxxxxxx______ 06:41:37.690 [18240] <2> bpduplicate: Received keep alive
20100902.24157700.ADMIN___.00005223 xxxxxxxxxxx______ 06:42:37.700 [18240] <2> bpduplicate: Received keep alive
20100902.24217710.ADMIN___.00005225 xxxxxxxxxxx______ 06:43:37.710 [18240] <2> bpduplicate: Received keep alive
20100902.24277720.ADMIN___.00005229 xxxxxxxxxxx______ 06:44:37.720 [18240] <2> bpduplicate: Received keep alive
20100902.24337730.ADMIN___.00005231 xxxxxxxxxxx______ 06:45:37.730 [18240] <2> bpduplicate: Received keep alive
20100902.24397740.ADMIN___.00005233 xxxxxxxxxxx______ 06:46:37.740 [18240] <2> bpduplicate: Received keep alive
20100902.24457750.ADMIN___.00005235 xxxxxxxxxxx______ 06:47:37.750 [18240] <2> bpduplicate: Received keep alive
20100902.24517760.ADMIN___.00005237 xxxxxxxxxxx______ 06:48:37.760 [18240] <2> bpduplicate: Received keep alive
20100902.24577770.ADMIN___.00005241 xxxxxxxxxxx______ 06:49:37.770 [18240] <2> bpduplicate: Received keep alive
20100902.24637780.ADMIN___.00005243 xxxxxxxxxxx______ 06:50:37.780 [18240] <2> bpduplicate: Received keep alive
20100902.24697790.ADMIN___.00005245 xxxxxxxxxxx______ 06:51:37.790 [18240] <2> bpduplicate: Received keep alive
20100902.24757800.ADMIN___.00005247 xxxxxxxxxxx______ 06:52:37.800 [18240] <2> bpduplicate: Received keep alive
20100902.24817810.ADMIN___.00005249 xxxxxxxxxxx______ 06:53:37.810 [18240] <2> bpduplicate: Received keep alive
20100902.24877820.ADMIN___.00005253 xxxxxxxxxxx______ 06:54:37.820 [18240] <2> bpduplicate: Received keep alive
20100902.24937830.ADMIN___.00005255 xxxxxxxxxxx______ 06:55:37.830 [18240] <2> bpduplicate: Received keep alive
20100902.24997840.ADMIN___.00005257 xxxxxxxxxxx______ 06:56:37.840 [18240] <2> bpduplicate: Received keep alive
20100902.24757800.ADMIN___.00005247 xxxxxxxxxxx______ 06:52:37.800 [18240] <2> bpduplicate: Received keep alive
20100902.24817810.ADMIN___.00005249 xxxxxxxxxxx______ 06:53:37.810 [18240] <2> bpduplicate: Received keep alive
20100902.24877820.ADMIN___.00005253 xxxxxxxxxxx______ 06:54:37.820 [18240] <2> bpduplicate: Received keep alive
20100902.24937830.ADMIN___.00005255 xxxxxxxxxxx______ 06:55:37.830 [18240] <2> bpduplicate: Received keep alive
20100902.24997840.ADMIN___.00005257 xxxxxxxxxxx______ 06:56:37.840 [18240] <2> bpduplicate: Received keep alive
20100902.25057850.ADMIN___.00005259 xxxxxxxxxxx______ 06:57:37.850 [18240] <2> bpduplicate: Received keep alive
20100902.25117860.ADMIN___.00005261 xxxxxxxxxxx______ 06:58:37.860 [18240] <2> bpduplicate: Received keep alive
20100902.25177870.ADMIN___.00005265 xxxxxxxxxxx______ 06:59:37.870 [18240] <2> bpduplicate: Received keep alive
20100902.25237880.ADMIN___.00005267 xxxxxxxxxxx______ 07:00:37.880 [18240] <2> bpduplicate: Received keep alive
20100902.25297890.ADMIN___.00005269 xxxxxxxxxxx______ 07:01:37.890 [18240] <2> bpduplicate: Received keep alive
20100902.25357900.ADMIN___.00005271 xxxxxxxxxxx______ 07:02:37.900 [18240] <2> bpduplicate: Received keep alive
20100902.25417910.ADMIN___.00005273 xxxxxxxxxxx______ 07:03:37.910 [18240] <2> bpduplicate: Received keep alive
20100902.25477920.ADMIN___.00005277 xxxxxxxxxxx______ 07:04:37.920 [18240] <2> bpduplicate: Received keep alive
20100902.25537930.ADMIN___.00005279 xxxxxxxxxxx______ 07:05:37.930 [18240] <2> bpduplicate: Received keep alive
20100902.25597940.ADMIN___.00005281 xxxxxxxxxxx______ 07:06:37.940 [18240] <2> bpduplicate: Received keep alive
20100902.25657950.ADMIN___.00005283 xxxxxxxxxxx______ 07:07:37.950 [18240] <2> bpduplicate: Received keep alive
20100902.25717960.ADMIN___.00005285 xxxxxxxxxxx______ 07:08:37.960 [18240] <2> bpduplicate: Received keep alive
20100902.25777970.ADMIN___.00005289 xxxxxxxxxxx______ 07:09:37.970 [18240] <2> bpduplicate: Received keep alive
20100902.25837980.ADMIN___.00005291 xxxxxxxxxxx______ 07:10:37.980 [18240] <2> bpduplicate: Received keep alive
20100902.25897990.ADMIN___.00005293 xxxxxxxxxxx______ 07:11:37.990 [18240] <2> bpduplicate: Received keep alive
20100902.25958000.ADMIN___.00005295 xxxxxxxxxxx______ 07:12:38.000 [18240] <2> bpduplicate: Received keep alive
20100902.26018010.ADMIN___.00005297 xxxxxxxxxxx______ 07:13:38.010 [18240] <2> bpduplicate: Received keep alive
20100902.26078020.ADMIN___.00005301 xxxxxxxxxxx______ 07:14:38.020 [18240] <2> bpduplicate: Received keep alive
20100902.26138030.ADMIN___.00005303 xxxxxxxxxxx______ 07:15:38.030 [18240] <2> bpduplicate: Received keep alive
20100902.26198040.ADMIN___.00005305 xxxxxxxxxxx______ 07:16:38.040 [18240] <2> bpduplicate: Received keep alive
20100902.26258050.ADMIN___.00005307 xxxxxxxxxxx______ 07:17:38.050 [18240] <2> bpduplicate: Received keep alive
20100902.26318060.ADMIN___.00005309 xxxxxxxxxxx______ 07:18:38.060 [18240] <2> bpduplicate: Received keep alive
20100902.26378070.ADMIN___.00005313 xxxxxxxxxxx______ 07:19:38.070 [18240] <2> bpduplicate: Received keep alive
20100902.26438080.ADMIN___.00005315 xxxxxxxxxxx______ 07:20:38.080 [18240] <2> bpduplicate: Received keep alive
20100902.26498090.ADMIN___.00005317 xxxxxxxxxxx______ 07:21:38.090 [18240] <2> bpduplicate: Received keep alive
20100902.26558100.ADMIN___.00005319 xxxxxxxxxxx______ 07:22:38.100 [18240] <2> bpduplicate: Received keep alive
20100902.26618110.ADMIN___.00005321 xxxxxxxxxxx______ 07:23:38.110 [18240] <2> bpduplicate: Received keep alive
20100902.26621839.ADMIN___.00005322 xxxxxxxxxxx______ 07:23:41.839 [18240] <2> db_error_add_to_file: dberrorq.c:midnite = 1283378400
20100902.26621854.ADMIN___.00005323 xxxxxxxxxxx______ 07:23:41.854 [18240] <16> dupreadline: socket read failed: errno = 131 - Connection reset
 by peer

[Nicolai]

Add a VERBOSE = 5 to bp.conf on the media server and re-run the duplicate. What does the bptm log say when duplicating xxxxxxxxxxx_1283289040 ??

[keyz]

Here is the log. It's another backupid but the symptoms are the same. Everything is fine until the last file positioning (File 375) :

05:34:03.947 [3924828] <2> set_job_details: POSITIONING 1283484843 VB0903 375

05:34:03.947 [3924828] <2> set_job_details: Done
05:34:03.947 [3924828] <2> io_position_for_read: positioning VB0903 to file number 375
05:34:03.947 [3924828] <2> io_read_back_header: drive index 0, reading backup header
05:34:03.953 [3924828] <2> set_job_details: Sending Tfile jobid (691165)
05:34:03.953 [3924828] <2> set_job_details: POSITIONED 1283484843 VB0903

05:34:03.953 [3924828] <2> set_job_details: Done
05:34:03.953 [3924828] <2> io_position_for_read: successfully positioned VB0903 to file number 375
05:34:03.953 [3924828] <2> io_ioctl: command (14)MTBSR 1 from (overwrite.c.771) on drive index 0
05:34:03.957 [3924828] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_DRV-R2-V1-001, from overwrite.c.777
05:34:03.968 [3924828] <2> get_tape_position_for_read: absolute block position prior to reading is 2745264
05:34:03.975 [3924828] <2> io_open: SCSI RESERVE
05:34:03.975 [3924828] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_DRV-R2-V1-001 successfully opened (mode 0)
05:34:03.975 [3924828] <2> io_ioctl: command (13)MTFSR 1 from (overwrite.c.807) on drive index 0
05:34:03.976 [3248578] <2> io_set_recvbuf: setting receive network buffer to 262144 bytes
05:34:03.976 [3248578] <2> io_set_recvbuf: receive network buffer is 262144 bytes
05:34:03.976 [3248578] <2> create_data_socket: tir socket created, fd is 23
05:34:03.987 [3248578] <2> write_data_tir: size of tir data received from read side is 99827 bytes + 0 GB
05:34:03.987 [3924828] <2> read_data_tir: beginning duplicate of TIR information, expected size is 99827 + 0 GB
05:34:03.988 [3248578] <2> write_data_tir: INF - Begin writing True Image Recovery information for copy 2.
05:34:03.988 [3248578] <2> io_ioctl: command (12)MTBSF 1 from (bptm.c.27372) on drive index 10
05:34:04.014 [3924828] <2> read_data_tir: remove rounded, total_bytes_read 100352, extra 525
05:34:04.015 [3924828] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_DRV-R2-V1-001, from bptm.c.17555
05:34:04.020 [3924828] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tpunmount)
05:34:04.020 [3924828] <2> drivename_write: Called with mode 1
05:34:04.020 [3924828] <2> drivename_unlock: unlocked
05:34:04.020 [3924828] <2> drivename_close: Called for file DRV-R2-V1-001
05:34:04.020 [3924828] <2> tpunmount: NOP: MEDIA_DONE 0 691165 0 VB0903 4001938 180 {F0F897BC-B701-11DF-9A34-00093D1357D0}
05:34:04.020 [3924828] <2> notify: executing - /usr/openv/netbackup/bin/restore_notify bptm xxxxxxxxx_1283462012 duplication
05:34:04.108 [3924828] <2> Media_dispatch_signal: calling child_wait (tmcommon.c:3434) delay 0 seconds
05:34:04.109 [3924828] <2> Media_siginfo_print: 0: delay 0 signo SIGCHLD:20 code 9 pid 0
05:34:04.163 [3924828] <2> job_monitoring_exex: ACK disconnect
05:34:04.163 [3924828] <2> job_disconnect: Disconnected
05:34:04.163 [3924828] <2> bptm: Calling tpunmount for media VB0903



Then i have a lot of those until 06:21




05:34:04.163 [3924828] <2> send_MDS_msg: MEDIA_DONE 0 691165 0 VB0903 4001938 180 {F0F897BC-B701-11DF-9A34-00093D1357D0}
05:34:04.163 [3924828] <2> JobInst::sendIrmMsg: starting
05:34:04.164 [3924828] <16> packageBptmResourceDoneMsg: msg (MEDIA_DONE 0 691165 0 VB0903 4001938 180 {F0F897BC-B701-11DF-9A34-00093D1357D0})
05:34:04.164 [3924828] <16> packageBptmResourceDoneMsg: keyword MEDIA_DONE version 0 jobid 691165 copyNum 0 mediaId VB0903 mediaKey 4001938 un
loadDelay 180 allocId {F0F897BC-B701-11DF-9A34-00093D1357D0}
05:34:04.164 [3924828] <16> packageBptmResourceDoneMsg: returns 0
05:34:04.164 [3924828] <2> EndpointSelectorFactory::get_selector: +++ ENTERING +++ : obj = 2046c888 (Endpoint_Selector.cpp:772)
05:34:04.164 [3924828] <2> EndpointSelectorFactory::get_selector: --- EXITING --- : obj = 2046c888 (Endpoint_Selector.cpp:772)
05:34:04.164 [3924828] <2> EndpointSelector::select_endpoint: +++ ENTERING +++ : obj = 2046c8e8 (Endpoint_Selector.cpp:264)
05:34:04.165 [3924828] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 2ff20edc (BpConf.cpp:80)
05:34:04.165 [3924828] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 2ff20edc (BpConf.cpp:80)
05:34:04.165 [3924828] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 2ff20edc (BpConf.cpp:90)
05:34:04.165 [3924828] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 2ff20edc (BpConf.cpp:90)
05:34:04.165 [3924828] <2> EndpointSelector::getPreferredEndpoint: +++ ENTERING +++ : obj = 2046c8e8 (Endpoint_Selector.cpp:658)
05:34:04.168 [3924828] <2> VxSSNetParse::isInServerListFastCheck: +++ ENTERING +++ : obj = 2ff20160 (VxSSNetParse.cpp:166)
05:34:04.168 [3924828] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 2ff1fed0 (BpConf.cpp:80)
05:34:04.168 [3924828] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 2ff1fed0 (BpConf.cpp:80)
05:34:04.183 [3924828] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 2ff1fed0 (BpConf.cpp:90)
05:34:04.183 [3924828] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 2ff1fed0 (BpConf.cpp:90)
05:34:04.183 [3924828] <2> VxSSNetParse::isInServerListFastCheck: --- EXITING --- : obj = 2ff20160 (VxSSNetParse.cpp:166)
05:34:04.183 [3924828] <2> EndpointSelector::getPreferredEndpoint: Found host in connection list, using this endpoint.(Endpoint_Selector.cpp:6
93)
05:34:04.183 [3924828] <2> EndpointSelector::getPreferredEndpoint: --- EXITING --- : obj = 2046c8e8 (Endpoint_Selector.cpp:658)
05:34:04.183 [3924828] <2> EndpointSelector::select_endpoint: There are no endpoints that match server list(Endpoint_Selector.cpp:376)
05:34:04.184 [3924828] <2> EndpointSelector::select_endpoint: invocation->perform_call(...) SUCCESS(Endpoint_Selector.cpp:392)
05:34:04.184 [3924828] <2> EndpointSelector::select_endpoint: --- EXITING --- : obj = 2046c8e8 (Endpoint_Selector.cpp:264)
05:34:04.184 [3924828] <2> EndpointSelector::success: +++ ENTERING +++ : obj = 2046c8e8 (Endpoint_Selector.cpp:484)
05:34:04.184 [3924828] <2> EndpointSelector::success: --- EXITING --- : obj = 2046c8e8 (Endpoint_Selector.cpp:484)
05:34:04.187 [3924828] <2> JobInst::sendIrmMsg: returning
05:34:04.187 [3924828] <2> bptm: EXITING with status 0 <----------
05:34:05.898 [3248578] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_DRV-R3-005, from bptm.c.27379
05:34:05.904 [3248578] <2> write_data_tir: absolute block position prior to writing backup header(s) is 5689283, copy 2
05:34:05.919 [3248578] <2> io_open: SCSI RESERVE
05:34:05.920 [3248578] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_DRV-R3-005 successfully opened (mode 2)
05:34:05.920 [3248578] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.27449) on drive index 10
05:34:07.779 [3248578] <2> write_data_tir: block position check: actual 5689283, expected 5689283
05:34:07.779 [3248578] <2> io_write_back_header: drive index 10, xxxxxxxxx_1283462012, file num = 766, mpx_headers = 0, copy 2
05:34:07.787 [3248578] <2> write_data_tir: writing first TIR block to media, bytes = 100352
05:34:07.788 [3248578] <2> io_terminate_tape: writing empty backup header, drive index 10, copy 2
05:34:07.788 [3248578] <2> io_ioctl: command (10)MTWEOF 1 from (bptm.c.8584) on drive index 10
05:34:09.595 [3248578] <2> io_write_back_header: drive index 10, empty_file, file num = 767, mpx_headers = 0, copy 2
05:34:09.602 [3248578] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_DRV-R3-005, from bptm.c.8702
05:34:11.729 [3248578] <2> io_terminate_tape: absolute block position prior to writing empty header is 5689286, copy 2
05:34:11.729 [3248578] <2> io_terminate_tape: block position check: actual 5689286, expected 5689286
05:34:11.729 [3248578] <2> send_MDS_msg: MEDIADB 1 4097289 RB0165 4000157 *NULL* 20 1283366486 1283480508 1284072961 0 1456055581 765 550 0 8
0 0 1024 0 5689286 0
05:34:11.729 [3248578] <2> EndpointSelectorFactory::get_selector: +++ ENTERING +++ : obj = 2046c8a8 (Endpoint_Selector.cpp:772)
05:34:11.729 [3248578] <2> EndpointSelectorFactory::get_selector: --- EXITING --- : obj = 2046c8a8 (Endpoint_Selector.cpp:772)
05:34:11.729 [3248578] <2> EndpointSelector::select_endpoint: +++ ENTERING +++ : obj = 2046c908 (Endpoint_Selector.cpp:264)


And that's it ! can't find anything about the file read error. On the activity monitor the duplication job failed at 06:21

3 sept. 2010 05:34:03 - positioning VB0903 to file 375
3 sept. 2010 05:34:03 - positioned VB0903; position time: 0:00:00
3 sept. 2010 06:21:27 - Error bpduplicate (pid=8811) socket read failed: errno = 131 - Connection reset by peer
3 sept. 2010 06:21:27 - Error bpduplicate (pid=8811) host xxxxxxxx backup id xxxxxxxx_1283462012 read process failed, file read failed (13).
3 sept. 2010 06:21:29 - Error bpduplicate (pid=8811) Duplicate of backup id xxxxxxxx_1283462012 failed, file read failed (13).
3 sept. 2010 06:21:29 - Error bpduplicate (pid=8811) Status = no images were successfully processed.
3 sept. 2010 06:21:30 - end Duplicate; elapsed time 3:24:04

Thanks in advance

[keyzzzz]

It may be a firewall problem. I have seen on firewall logs some rejects from media server TCP/13724 & TCP/1556 to master server TCP 33809, 33810, 33622, 33514, 34091.

What are those 33xxxx ports  ? Look like random ports.

How can i tell Netbackup to use specific ports ? I have looked in "Port Ranges" and "Firewall" sections but i don't understand very weel.