Failing to upload large file to B2

femaniac14 · June 11, 2020, 1:22am

What is the problem you are having with rclone?

Hi everyone,

I could use some help, since I am constantly having issues to upload these large backups to B2.
Checked the network and already did many tests with rclone, but no success so far.

Much appreciated, regards.

What is your rclone version (output from `rclone version`)

1.52.0

Which OS you are using and how many bits (eg Windows 7, 64 bit)

Windows Svr 2012 R2 64

Which cloud storage system are you using? (eg Google Drive)

Backblaze B2

The command you were trying to run (eg `rclone copy /tmp remote:tmp`)

sync "\\192.168.10.6\f$\BACKUP - AWS FS G - SRVBK03" b2-mcaa:MCAA-Backups/FS-G --b2-chunk-size 250M --b2-upload-cutoff 250M --b2-disable-checksum --fast-list --checkers 70 --low-level-retries 30 --transfers 20 -vv --log-file C:\scripts\Backblaze\Logs\FileServerG.txt

The rclone config contents with secrets removed.

Paste config here

A log from the command with the `-vv` flag

2020/06/10 19:02:01 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Done sending chunk 222
2020/06/10 19:02:04 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Sending chunk 242 length 262144000
2020/06/10 19:02:15 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Error sending chunk 229 (retry=true): Post "https://pod-000-1067-11.backblaze.com/b2api/v1/b2_upload_part/4_z7d014342900f82127b2f0817_f2104115bf648cf36_d20200610_m210851_c000_v0001067_t0041/0045": EOF: &url.Error{Op:"Post", URL:"https://pod-000-1067-11.backblaze.com/b2api/v1/b2_upload_part/4_z7d014342900f82127b2f0817_f2104115bf648cf36_d20200610_m210851_c000_v0001067_t0041/0045", Err:(*errors.errorString)(0xc000088030)}
2020/06/10 19:02:15 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Clearing part upload URL because of error: Post "https://pod-000-1067-11.backblaze.com/b2api/v1/b2_upload_part/4_z7d014342900f82127b2f0817_f2104115bf648cf36_d20200610_m210851_c000_v0001067_t0041/0045": EOF
2020/06/10 19:02:15 DEBUG : pacer: low level retry 1/30 (error Post "https://pod-000-1067-11.backblaze.com/b2api/v1/b2_upload_part/4_z7d014342900f82127b2f0817_f2104115bf648cf36_d20200610_m210851_c000_v0001067_t0041/0045": EOF)
2020/06/10 19:02:15 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2020/06/10 19:02:15 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Sending chunk 229 length 262144000
2020/06/10 19:02:16 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Error sending chunk 227 (retry=true): Post "https://pod-000-1067-11.backblaze.com/b2api/v1/b2_upload_part/4_z7d014342900f82127b2f0817_f2104115bf648cf36_d20200610_m210851_c000_v0001067_t0041/0031": write tcp 192.168.0.208:55368->206.190.213.221:443: wsasend: An existing connection was forcibly closed by the remote host.: &url.Error{Op:"Post", URL:"https://pod-000-1067-11.backblaze.com/b2api/v1/b2_upload_part/4_z7d014342900f82127b2f0817_f2104115bf648cf36_d20200610_m210851_c000_v0001067_t0041/0031", Err:(*net.OpError)(0xc00007c050)}
2020/06/10 19:02:16 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Clearing part upload URL because of error: Post "https://pod-000-1067-11.backblaze.com/b2api/v1/b2_upload_part/4_z7d014342900f82127b2f0817_f2104115bf648cf36_d20200610_m210851_c000_v0001067_t0041/0031": write tcp 192.168.0.208:55368->206.190.213.221:443: wsasend: An existing connection was forcibly closed by the remote host.
2020/06/10 19:02:16 DEBUG : pacer: low level retry 1/30 (error Post "https://pod-000-1067-11.backblaze.com/b2api/v1/b2_upload_part/4_z7d014342900f82127b2f0817_f2104115bf648cf36_d20200610_m210851_c000_v0001067_t0041/0031": write tcp 192.168.0.208:55368->206.190.213.221:443: wsasend: An existing connection was forcibly closed by the remote host.)
2020/06/10 19:02:16 DEBUG : pacer: Rate limited, increasing sleep to 40ms
2020/06/10 19:02:16 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Sending chunk 227 length 262144000
2020/06/10 19:02:16 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Error sending chunk 234 (retry=true): Post "https://pod-000-1067-11.backblaze.com/b2api/v1/b2_upload_part/4_z7d014342900f82127b2f0817_f2104115bf648cf36_d20200610_m210851_c000_v0001067_t0041/0038": write tcp 192.168.0.208:55153->206.190.213.221:443: wsasend: An existing connection was forcibly closed by the remote host.: &url.Error{Op:"Post", URL:"https://pod-000-1067-11.backblaze.com/b2api/v1/b2_upload_part/4_z7d014342900f82127b2f0817_f2104115bf648cf36_d20200610_m210851_c000_v0001067_t0041/0038", Err:(*net.OpError)(0xc000262050)}
2020/06/10 19:02:16 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Clearing part upload URL because of error: Post "https://pod-000-1067-11.backblaze.com/b2api/v1/b2_upload_part/4_z7d014342900f82127b2f0817_f2104115bf648cf36_d20200610_m210851_c000_v0001067_t0041/0038": write tcp 192.168.0.208:55153->206.190.213.221:443: wsasend: An existing connection was forcibly closed by the remote host.
2020/06/10 19:02:16 DEBUG : pacer: low level retry 1/30 (error Post "https://pod-000-1067-11.backblaze.com/b2api/v1/b2_upload_part/4_z7d014342900f82127b2f0817_f2104115bf648cf36_d20200610_m210851_c000_v0001067_t0041/0038": write tcp 192.168.0.208:55153->206.190.213.221:443: wsasend: An existing connection was forcibly closed by the remote host.)
2020/06/10 19:02:16 DEBUG : pacer: Rate limited, increasing sleep to 80ms
2020/06/10 19:02:16 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Sending chunk 234 length 262144000
2020/06/10 19:02:17 DEBUG : pacer: Reducing sleep to 40ms
2020/06/10 19:02:17 DEBUG : pacer: Reducing sleep to 20ms
2020/06/10 19:02:18 DEBUG : pacer: Reducing sleep to 10ms
2020/06/10 19:02:19 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Done sending chunk 223
2020/06/10 19:02:19 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Error sending chunk 227 (retry=false): Post "https://pod-000-1067-11.backblaze.com/b2api/v1/b2_upload_part/4_z7d014342900f82127b2f0817_f2104115bf648cf36_d20200610_m210851_c000_v0001067_t0041/0028": dial tcp 206.190.213.221:443: connectex: No connection could be made because the target machine actively refused it.: &url.Error{Op:"Post", URL:"https://pod-000-1067-11.backblaze.com/b2api/v1/b2_upload_part/4_z7d014342900f82127b2f0817_f2104115bf648cf36_d20200610_m210851_c000_v0001067_t0041/0028", Err:(*net.OpError)(0xc0008be230)}
2020/06/10 19:02:19 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Error sending chunk 229 (retry=false): Post "https://pod-000-1067-11.backblaze.com/b2api/v1/b2_upload_part/4_z7d014342900f82127b2f0817_f2104115bf648cf36_d20200610_m210851_c000_v0001067_t0041/0020": dial tcp 206.190.213.221:443: connectex: No connection could be made because the target machine actively refused it.: &url.Error{Op:"Post", URL:"https://pod-000-1067-11.backblaze.com/b2api/v1/b2_upload_part/4_z7d014342900f82127b2f0817_f2104115bf648cf36_d20200610_m210851_c000_v0001067_t0041/0020", Err:(*net.OpError)(0xc0003f3220)}
2020/06/10 19:02:19 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Error sending chunk 227: Post "https://pod-000-1067-11.backblaze.com/b2api/v1/b2_upload_part/4_z7d014342900f82127b2f0817_f2104115bf648cf36_d20200610_m210851_c000_v0001067_t0041/0028": dial tcp 206.190.213.221:443: connectex: No connection could be made because the target machine actively refused it.
2020/06/10 19:02:19 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Error sending chunk 229: Post "https://pod-000-1067-11.backblaze.com/b2api/v1/b2_upload_part/4_z7d014342900f82127b2f0817_f2104115bf648cf36_d20200610_m210851_c000_v0001067_t0041/0020": dial tcp 206.190.213.221:443: connectex: No connection could be made because the target machine actively refused it.
2020/06/10 19:02:22 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Sending chunk 243 length 262144000
2020/06/10 19:02:26 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Done sending chunk 226
2020/06/10 19:02:26 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Done sending chunk 221
2020/06/10 19:02:45 INFO  : 
Transferred:   	  572.285G / 2.446 TBytes, 23%, 18.226 MBytes/s, ETA 1d6h9m33s
Checks:               100 / 100, 100%
Transferred:            3 / 4, 75%
Elapsed time:   8h55m53.0s
Transferring:
 * BACKUP - FS V - SRVBK0…-05-09T115038_E13C.vbk:  2% /1.944T, 13.878M/s, 39h36m24s

2020/06/10 19:02:50 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Done sending chunk 230
2020/06/10 19:03:02 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Done sending chunk 228
2020/06/10 19:03:03 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Done sending chunk 225
2020/06/10 19:03:31 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Done sending chunk 231
2020/06/10 19:03:45 INFO  : 
Transferred:   	  573.090G / 2.446 TBytes, 23%, 18.218 MBytes/s, ETA 1d6h9m38s
Checks:               100 / 100, 100%
Transferred:            3 / 4, 75%
Elapsed time:   8h56m53.1s
Transferring:
 * BACKUP - FS V - SRVBK0…-05-09T115038_E13C.vbk:  2% /1.944T, 12.309M/s, 44h38m13s

2020/06/10 19:04:07 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Done sending chunk 240
2020/06/10 19:04:19 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Done sending chunk 233
2020/06/10 19:04:33 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Done sending chunk 232
2020/06/10 19:04:39 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Done sending chunk 235
2020/06/10 19:04:45 INFO  : 
Transferred:   	  573.938G / 2.446 TBytes, 23%, 18.211 MBytes/s, ETA 1d6h9m31s
Checks:               100 / 100, 100%
Transferred:            3 / 4, 75%
Elapsed time:   8h57m53.0s
Transferring:
 * BACKUP - FS V - SRVBK0…-05-09T115038_E13C.vbk:  2% /1.944T, 12.240M/s, 44h52m10s

2020/06/10 19:04:46 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Done sending chunk 237
2020/06/10 19:04:58 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Done sending chunk 234
2020/06/10 19:04:59 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Done sending chunk 241
2020/06/10 19:05:06 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Done sending chunk 236
2020/06/10 19:05:10 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Done sending chunk 243
2020/06/10 19:05:13 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Done sending chunk 239
2020/06/10 19:05:27 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Done sending chunk 238
2020/06/10 19:05:30 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Done sending chunk 242
2020/06/10 19:05:30 DEBUG : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Cancelling large file upload due to error: Post "https://pod-000-1067-11.backblaze.com/b2api/v1/b2_upload_part/4_z7d014342900f82127b2f0817_f2104115bf648cf36_d20200610_m210851_c000_v0001067_t0041/0028": dial tcp 206.190.213.221:443: connectex: No connection could be made because the target machine actively refused it.
2020/06/10 19:05:41 ERROR : BACKUP - FS V - SRVBK03/BACKUP - FS V - SRVBK03D2020-05-09T115038_E13C.vbk: Failed to copy: Post "https://pod-000-1067-11.backblaze.com/b2api/v1/b2_upload_part/4_z7d014342900f82127b2f0817_f2104115bf648cf36_d20200610_m210851_c000_v0001067_t0041/0028": dial tcp 206.190.213.221:443: connectex: No connection could be made because the target machine actively refused it.
2020/06/10 19:05:42 ERROR : B2 bucket MCAA-Backups path FS-V: not deleting files as there were IO errors
2020/06/10 19:05:42 ERROR : B2 bucket MCAA-Backups path FS-V: not deleting directories as there were IO errors
2020/06/10 19:05:42 ERROR : Attempt 3/3 failed with 1 errors and: Post "https://pod-000-1067-11.backblaze.com/b2api/v1/b2_upload_part/4_z7d014342900f82127b2f0817_f2104115bf648cf36_d20200610_m210851_c000_v0001067_t0041/0028": dial tcp 206.190.213.221:443: connectex: No connection could be made because the target machine actively refused it.
2020/06/10 19:05:42 INFO  : 
Transferred:   	  574.135G / 574.135 GBytes, 100%, 18.185 MBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Checks:               100 / 100, 100%
Transferred:            3 / 3, 100%
Elapsed time:   8h58m49.1s

2020/06/10 19:05:42 DEBUG : 4 go routines active
2020/06/10 19:05:43 Failed to sync: Post "https://pod-000-1067-11.backblaze.com/b2api/v1/b2_upload_part/4_z7d014342900f82127b2f0817_f2104115bf648cf36_d20200610_m210851_c000_v0001067_t0041/0028": dial tcp 206.190.213.221:443: connectex: No connection could be made because the target machine actively refused it.

ncw · June 11, 2020, 7:11pm

It looks like rclone isn't retrying this error which it should be

No connection could be made because the target machine actively refused it.

Can you try this which should hopefully fix the problem?

https://beta.rclone.org/branch/v1.52.1-058-ga163527a-fix-b2-retries-beta/ (uploaded in 15-30 mins)

femaniac14 · June 11, 2020, 8:04pm

Sure Nick, thanks for the quick response.

I'll report the results as soon as I can. Thanks !

femaniac14 · June 16, 2020, 5:00pm

Nick, the results were great.

I haven't seen the same error occur again in many attemps of very large files (>2Tb), which is awesome.

Appreciate your support, as usual !

Regards,

ncw · June 17, 2020, 9:47am

Thanks for testing

I've merged this to master now which means it will be in the latest beta in 15-30 mins and released in v1.52.2

system · August 17, 2020, 5:47am

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.