FreeNAS + BackBlaze B2 "Archiving" restarts/hangs

[KieranR]

Hi All,

Been using FreeNAS for what seems like forever - since when it effectively forked the GUI from m0n0Wall.

Recently upgraded to 11.0 u4 - to use the S3 and BackBlaze b2 offering.

So far, mostly going great, however, large files - those that are in excess of 100GB are constantly restarting - they'll get to near as 100% - and then next thing I see is either the job failed - or the number of bytes transferred is back to close 0%

Any ideas on how I can get around this ?

I've had a whole 1.3TB sync up - but that was based on files around the 20-50MB mark, and other files up to the 20GB mark.

Cheers

Kieran

 

[dlavigne]

Anything related in /var/log/messages?

 

[KieranR]

No there hasn't been.
Somethings in the /var/log/middleware.log.* - but -by the time the darn things fail, and I notice - hours have gone past :-(

I started a manual rclone off, and at the moment there are two large files in the area I am trying to sync...

Error received was:

Code:

2018/05/17 15:46:47 DEBUG : Old-drive.img.gz: Clearing part upload URL because of error: Not enough members for write of 4_zc83b64250d73c9fc612f0
21a_f318334d8baf0ef67_d20180517_m152447_c000_v0001059_t0027: neighbor_down; class org.apache.http.conn.ConnectTimeoutException - Connect to member-05.vault:8180 [member
-05.vault/192.168.243.15] failed: connect timed out (http://member-05.vault:8180/api/put_shard?sguid=4_zc83b64250d73c9fc612f021a_f318334d8baf0ef67_d20180517_m152447_c00
0_v0001059_t0027_s05&is_first=false&is_last=false&is_speed_test=false&upload_id=b35651c02de323f1357a5&shard_size=5921568&offset=1638400&reason=UPLOAD_PART) (500 interna
l_error)
2018/05/17 15:46:47 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2018/05/17 15:46:47 DEBUG : pacer: low level retry 1/20 (error Not enough members for write of 4_zc83b64250d73c9fc612f021a_f318334d8baf0ef67_d20180517_m152447_c000_v000
1059_t0027: neighbor_down; class org.apache.http.conn.ConnectTimeoutException - Connect to member-05.vault:8180 [member-05.vault/192.168.243.15] failed: connect timed o
ut (http://member-05.vault:8180/api/put_shard?sguid=4_zc83b64250d73c9fc612f021a_f318334d8baf0ef67_d20180517_m152447_c000_v0001059_t0027_s05&is_first=false&is_last=false
&is_speed_test=false&upload_id=b35651c02de323f1357a5&shard_size=5921568&offset=1638400&reason=UPLOAD_PART) (500 internal_error))
2018/05/17 15:46:47 DEBUG : Old-drive.img.gz: Sending chunk 240 length 100663296
2018/05/17 15:46:49 DEBUG : pacer: Reducing sleep to 10ms
2018/05/17 15:46:49 DEBUG : Old-drive.img.gz: Error sending chunk 240: Post https://pod-000-1059-02.backblaze.com/b2api/v1/b2_upload_part/4_zc83b
64250d73c9fc612f021a_f201d4de874a7153a_d20180517_m094123_c000_v0001059_t0006/0058: http: ContentLength=100663336 with Body length 0
2018/05/17 15:46:49 DEBUG : OId-drive.img.gz: Sending chunk 254 length 100663296
2018/05/17 15:46:49 DEBUG : disk-images/rdisk0s2.img.gz: Done sending chunk 205
2018/05/17 15:46:50 DEBUG : disk-images/rdisk0s2.img.gz: Sending chunk 222 length 100663296
2018/05/17 15:47:47 INFO  :
Transferred:   106.749 GBytes (1.809 MBytes/s)

Then a little later:

Code:

2018/05/17 16:17:58 DEBUG : disk-images/rdisk0s2.img.gz: Done sending chunk 223
2018/05/17 16:17:58 DEBUG : disk-images/rdisk0s2.img.gz: Sending chunk 257 length 100663296
2018/05/17 16:18:07 DEBUG : disk-images/rdisk0s2.img.gz: Done sending chunk 235
2018/05/17 16:18:07 DEBUG : disk-images/rdisk0s2.img.gz: Sending chunk 258 length 100663296
2018/05/17 16:18:10 DEBUG : Old-drive.img.gz: Done sending chunk 254
2018/05/17 16:18:10 DEBUG : Old-drive.img.gz: Cancelling large file upload due to error: Post https://pod-000-1059-02.backblaze.com/b2api/v1/b2_upload_part/4_zc83b64250d73c9fc612f021a_f201d4de874a7153a_d20180517_m094123_c000_v0001059_t0006/0058: http: ContentLength=100663336 with Body length 0
2018/05/17 16:18:11 DEBUG : disk-images/rdisk0s2.img.gz: Sending chunk 259 length 100663296
2018/05/17 16:18:23 ERROR : Old-drive.img.gz: Failed to copy: Post https://pod-000-1059-02.backblaze.com/b2api/v1/b2_upload_part/4_zc83b64250d73c9fc612f021a_f201d4de874a7153a_d20180517_m094123_c000_v0001059_t0006/0058: http: ContentLength=100663336 with Body length 0
2018/05/17 16:18:34 DEBUG : disk-images/rdisk0s2.img.gz: Done sending chunk 232
2018/05/17 16:18:34 DEBUG : disk-images/rdisk0s2.img.gz: Sending chunk 260 length 100663296
2018/05/17 16:18:35 DEBUG : disk-images/rdisk0s2.img.gz: Done sending chunk 228
2018/05/17 16:18:36 DEBUG : disk-images/rdisk0s2.img.gz: Sending chunk 261 length 100663296

So - I've tried to troubleshoot this by finding information from other sources (such as github comments for rclone itself, which is notable that the version in FreeNAS 11.0-u4 is *not* the latest version) - and finding a command that might give more info.

The command that set this off was:

Code:

clone --config /tmp/moo sync /mnt/data/Old-Imac/ remote:BBnas-Archive/Old-iMac -vv --retries=15 --transfers 32 --low-level-retries=20 --b2-upload-cutoff=200M

The file /tmp/moo is just the config and user details.

Any help would be most appreciated.

TIA

K

 

[dlavigne]

Might be worth reporting at bugs.freenas.org. If you do, post the issue number here.