Rclone B2 sync - Post Error - method not supported

What is the problem you are having with rclone?

Using rclone to sync to a B2 bucket, I get files that fail with ERROR : Path/To/File.mov: Failed to copy: Post https://pod-000-1113-12.backblaze.com/b2api/v1/b2_upload_file/4759072a79d1bce762ca0a13/c001_v0001113_t0058: file already closed

The same files then retry to sync but seem to keep failing.

What is your rclone version (output from rclone version)

Version 1.49.2

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

Ubuntu - it's a PoC will convert to Fedora when I get to production

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)

rclone sync apple-1:/Volumes/G-SPEED\ Shuttle\ TB3/Client/ b2-rclone:/G-Tech/ -P --transfers 32

A log from the command with the -vv flag (eg output from rclone -vv copy /tmp remote:tmp)

Have to clean up the log so it doesn't contain sensitive info.

Bucket configuration

File Sizes

The files in question vary from small >200M to 10G and there doesn't appear to be any rhyme or reason for the error.

So a bit more of digging it looks as though my Apple workstation is refusing the SSH connection at some point in time - for sporadic files.

2019-09-10 10:23:46 ERROR : sftp://user@ip:22//Volumes/G-SPEED Shuttle TB3/Client/: Discarding closed SSH connection: EOF
2019-09-10 10:23:46 ERROR : sftp://user@ip:22//Volumes/G-SPEED Shuttle TB3/Client/: Discarding closed SSH connection: EOF
2019-09-10 10:23:46 ERROR : sftp://user@ip:22//Volumes/G-SPEED Shuttle TB3/Client/: Discarding closed SSH connection: EOF
2019-09-10 10:23:46 ERROR : sftp://user@ip:22//Volumes/G-SPEED Shuttle TB3/Client/: Discarding closed SSH connection: EOF
2019-09-10 10:23:46 ERROR : sftp://user@ip:22//Volumes/G-SPEED Shuttle TB3/Client/: Discarding closed SSH connection: EOF
2019-09-10 10:23:46 ERROR : sftp://user@ip:22//Volumes/G-SPEED Shuttle TB3/Client/: Discarding closed SSH connection: EOF
2019-09-10 10:23:46 ERROR : sftp://user@ip:22//Volumes/G-SPEED Shuttle TB3/Client/: Discarding closed SSH connection: EOF
2019-09-10 10:23:47 ERROR : Becoming Client/Renders/first4.mov: Failed to copy: failed to open source object: Open: couldn't connect SSH: dial tcp ip:22: connect: connection refused
2019-09-10 10:23:47 ERROR : B2 bucket G-Tech: not deleting files as there were IO errors
2019-09-10 10:23:47 ERROR : B2 bucket G-Tech: not deleting directories as there were IO errors
2019-09-10 10:23:47 ERROR : Attempt 3/3 failed with 3 errors and: failed to open source object: Open: couldn't connect SSH: dial tcp ip:22: connect: connection refused
Transferred:       15.329G / 15.329 GBytes, 100%, 3.126 MBytes/s, ETA 0s
Errors:                 3 (retrying may help)
Checks:               637 / 637, 100%
Transferred:            1 / 1, 100%
Elapsed time:  1h23m41.8s
2019/09/10 10:23:47 Failed to sync with 3 errors: last error was: failed to open source object: Open: couldn't connect SSH: dial tcp ip:22: connect: connection refused

Can anyone confirm if they've seen something like this and is there anyway to improve this?

So the issue may be that my workstation is dropping the SSH connection. I'm going to test by adding ServerAliveInterval 120 to /etc/ssh/ssh_config on the workstation to see if it resolves this issue.

So adjusting the ServerAliveInterval seems to have improved the connection, but this one file is still having issues.

Not sure if there is much else to be done short of using something like Cyberduck to just dump this one file into the directory on B2 in those one off cases. - Would suck to have to do that though.

The file will rclone copy to 100% and just restart for some unlisted reason.

Anyone else have any pointers?

Manually uploading the file with Cyberduck did work, so I'm not sure where to go with this. . .

Hmmm, that file already closed is probably a bug that we haven't tracked down yet.

See this thread

Can you try the beta from that thread and report back what it prints?

Can you try this beta? It should log an ERROR with "Attempted close at" then a backtrace.

Can you paste one of the backtraces (assuming that it does work!)

Thanks

https://beta.rclone.org/branch/v1.49.0-041-g6ade4a26-fix-already-closed-beta/ (uploaded in 15-30 mins)

Testing this now and I'll report back. Removed the file from B2, so we shall see what happens.

Will do.

Just posting it so it's listed. Waiting on this file to upload ~ 22 minutes.

Going to have a beer.

It seemed to restart the file again. What specifically do you need?

2019-09-10 17:45:51 INFO  : B2 bucket G-Tech: Waiting for transfers to finish
Transferred:        3.910G / 3.910 GBytes, 100%, 1.655 MBytes/s, ETA 0s
Transferred:        3.910G / 3.910 GBytes, 100%, 1.655 MBytes/s, ETA 0s
2019-09-10 18:26:11 DEBUG : Becoming client/Renders/first4.mov: Clearing upload URL because of error: incident id 60ce486519b1-a1a01ba2efa2 (500 internal_error)
2019-09-10 18:26:11 DEBUG : pacer: low level retry 1/1 (error incident id 60ce486519b1-a1a01ba2efa2 (500 internal_error))
2019-09-10 18:26:11 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2019-09-10 18:26:11 DEBUG : Becoming client/Renders/first4.mov: Received error: incident id 60ce486519b1-a1a01ba2efa2 (500 internal_error) - low level retry 1/10
2019-09-10 18:26:11 DEBUG : pacer: Reducing sleep to 10ms
2019-09-10 18:26:11 ERROR : Becoming client/Renders/first4.mov: Failed to copy: Post https://pod-000-1044-15.backblaze.com/b2api/v1/b2_upload_file/4759072a79d1bce762ca0a13/c001_v0001044_t0044: file already closed
2019-09-10 18:26:11 ERROR : Attempt 1/3 failed with 3 errors and: Post https://pod-000-1044-15.backblaze.com/b2api/v1/b2_upload_file/4759072a79d1bce762ca0a13/c001_v0001044_t0044: file already closed
2019-09-10 18:26:12 DEBUG : .DS_Store: Size of src and dst objects identical
2019-09-10 18:26:12 DEBUG : .DS_Store: Unchanged skipping

I can't post the complete stack trace, character limits and all, but the important bits seem to be posted.

Let me know if you need something else and I'd be happy to find/post what's needed.

I'm running this copy operation again this morning to see if something has magically changed. Will update in a bit if there is any progress.

Yeah no change, it's still repeating the file over and over for some reason.

Here's the errors from the console.

2019-09-11 08:07:28 INFO  : B2 bucket G-Tech: Waiting for transfers to finish
2019-09-11 08:53:44 DEBUG : Becoming client/Renders/first4.mov: Clearing upload URL because of error: incident id 60ce486519b1-6405a0aa3075 (500 internal_error)
2019-09-11 08:53:44 DEBUG : pacer: low level retry 1/1 (error incident id 60ce486519b1-6405a0aa3075 (500 internal_error))
2019-09-11 08:53:44 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2019-09-11 08:53:44 DEBUG : Becoming client/Renders/first4.mov: Received error: incident id 60ce486519b1-6405a0aa3075 (500 internal_error) - low level retry 1/10
2019-09-11 08:53:44 DEBUG : pacer: Reducing sleep to 10ms
2019-09-11 08:53:45 ERROR : Becoming client/Renders/first4.mov: Failed to copy: Post https://pod-000-1104-08.backblaze.com/b2api/v1/b2_upload_file/4759072a79d1bce762ca0a13/c001_v0001104_t0034: file already closed
2019-09-11 08:53:45 ERROR : Attempt 1/3 failed with 3 errors and: Post https://pod-000-1104-08.backblaze.com/b2api/v1/b2_upload_file/4759072a79d1bce762ca0a13/c001_v0001104_t0034: file already closed
2019-09-11 08:53:45 DEBUG : .DS_Store: Size and modification time the same (differ by 0s, within tolerance 1s)
2019-09-11 08:53:45 DEBUG : .DS_Store: Unchanged skipping

2019-09-11 08:53:46 INFO  : B2 bucket G-Tech: Waiting for transfers to finish
2019-09-11 09:45:20 DEBUG : Becoming client/Renders/first4.mov: Clearing upload URL because of error: incident id 60ce486519b1-a6e81ee36deb (500 internal_error)
2019-09-11 09:45:20 DEBUG : pacer: low level retry 1/1 (error incident id 60ce486519b1-a6e81ee36deb (500 internal_error))
2019-09-11 09:45:20 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2019-09-11 09:45:20 DEBUG : Becoming client/Renders/first4.mov: Received error: incident id 60ce486519b1-a6e81ee36deb (500 internal_error) - low level retry 1/10
2019-09-11 09:45:21 DEBUG : pacer: Reducing sleep to 10ms
2019-09-11 09:45:21 ERROR : Becoming client/Renders/first4.mov: Failed to copy: Post https://pod-000-1120-02.backblaze.com/b2api/v1/b2_upload_file/4759072a79d1bce762ca0a13/c001_v0001120_t0036: file already closed
2019-09-11 09:45:21 ERROR : Attempt 2/3 failed with 3 errors and: Post https://pod-000-1120-02.backblaze.com/b2api/v1/b2_upload_file/4759072a79d1bce762ca0a13/c001_v0001120_t0036: file already closed
2019-09-11 09:45:21 DEBUG : .DS_Store: Size and modification time the same (differ by 0s, within tolerance 1s)
2019-09-11 09:45:21 DEBUG : .DS_Store: Unchanged skipping

@ncw anything else you want me to look into to try and troubleshoot this?

I've managed to replicate this bug locally.

I need a bit if quiet time to work out exactly what is going on as it isn't obvious to me at the moment!

1 Like

I think I've fixed the "already closed" messages here - can you have a go please?

https://beta.rclone.org/branch/v1.49.0-042-gaf097d7a-fix-already-closed-beta/ (uploaded in 15-30 mins)

I would need a linux version, everything there is freebsd etc.

Sorry, messed up the build, try this one

https://beta.rclone.org/branch/v1.49.0-042-g89fda14a-fix-already-closed-beta/ (uploaded in 15-30 mins)

Getting a 404 with that link.

It is building, it will be there in 15-30 mins :slight_smile:

1 Like

Testing this version now. Will update in a bit.

1 Like