Connection gets interrupted, Rclone pretends it didn't happen

Help and Support
1

Hi folks,

I am using Rclone to transfer my local NAS contents to an offsite location. I created a script that launches an Rclone instance and ensures that only one instance is running at any given time. That way I can run the script via a cronjob that fires at least once a day.

The problem at hand arises from the quirks of German (non-corporate) internet connections: once a day the DSL line gets forcefully interrupted and a IP addresses are assigned. The change of IP is not a problem as the target has a dynamic DNS name assigned. What seems to throw Rclone off is the loss of connection: Rclone just stalls and keeps running indefinitely without failing properly. As per the log just keeps the same four files in transfer with further decreasing data rate and ETA, but nothing is noted about the interrupted connection.

Is there any way to properly deal with this? I’ve tried all of Rclone’s parameters for dealing with timeouts / connection loss (--timeout, --retries, --low-level-retries, --contimeout), all of no avail.

2

What happens in the logs when this occurs? Can you run the same item with -vv during the time the connection interrupts?

If you lose internet, it should error out as you’d see a bunch of retries.

3

The log shows, that the SSH connection get dropped, but ironically that does not terminate Rclone. For the below log output I ran Rclone with -vv and forced reconnecting the DSL on the target site at about 15:13. Error appears at 15:16:44

Log Output

2018/08/02 15:11:02 DEBUG : Using config file from "/mnt/alpha/home/janwillhaus/.rclone.conf"
2018/08/02 15:11:02 DEBUG : --min-age 10m0s to 2018-08-02 15:01:02.236608472 +0200 CEST m=-599.992040868
2018/08/02 15:11:02 DEBUG : rclone: Version "v1.38" starting with parameters ["rclone" "sync" "-vv" "--config" "/mnt/alpha/home/janwillhaus/.rclone.conf" "--exclude" ".DS_Store" "--exclude" "._*" "--min-age" "10m" "--low-level-retries" "1" "--retries" "1" "--timeout=30s" "/mnt/alpha/media/music" "schortens:/mnt/volume1/offsite/media/music/"]
2018/08/02 15:11:02 INFO  : sftp://*********@*******************:*****//mnt/volume1/offsite/media/music/: Modify window is 1s
2018/08/02 15:11:02 DEBUG : ._.TemporaryItems: Excluded from sync (and deletion)
2018/08/02 15:11:02 DEBUG : ._Steven Wilson - 2016 - 4 1-2: Excluded from sync (and deletion)
2018/08/02 15:11:03 DEBUG : .apdisk: Size and modification time the same (differ by 0s, within tolerance 1s)
2018/08/02 15:11:03 DEBUG : .apdisk: Unchanged skipping
2018/08/02 15:11:03 DEBUG : convert2opus.sh: Size and modification time the same (differ by 0s, within tolerance 1s)
2018/08/02 15:11:03 DEBUG : convert2opus.sh: Unchanged skipping
2018/08/02 15:11:03 DEBUG : convert2aac_single.sh: Size and modification time the same (differ by 0s, within tolerance 1s)
2018/08/02 15:11:03 DEBUG : convert2aac_single.sh: Unchanged skipping
2018/08/02 15:11:03 DEBUG : convert2mp3.sh: Size and modification time the same (differ by 0s, within tolerance 1s)
2018/08/02 15:11:03 DEBUG : convert2mp3.sh: Unchanged skipping
2018/08/02 15:11:03 DEBUG : .TemporaryItems/._folders.501: Excluded from sync (and deletion)
2018/08/02 15:11:03 DEBUG : The Pineapple Thief/8 Days/._cover.jpg: Excluded from sync (and deletion)
2018/08/02 15:11:41 INFO  : Sara K/Water Falls/01-01 - Chattanooga Choo-Choo.flac: Copied (new)
2018/08/02 15:12:02 INFO  :
Transferred:   58.399 MBytes (986.344 kBytes/s)
Errors:                 0
Checks:                 4
Transferred:            1
Elapsed time:      1m0.6s
Transferring:
 *  Sara K/Water Falls/01-04 - The Painter.flac: 68% done, 207.923 kBytes/s, ETA: 31s
 *  Sara K/Water Falls/01-05 - Water Falls.flac: 26% done, 149.989 kBytes/s, ETA: 1m7s
 * ...r Falls/01-02 - Running Away From You.flac: 73% done, 475.196 kBytes/s, ETA: 15s
 * ...r Falls/01-03 - Turned My Upside Down.flac: 51% done, 194.204 kBytes/s, ETA: 1m6s

2018/08/02 15:12:14 INFO  : Sara K/Water Falls/01-02 - Running Away From You.flac: Copied (new)
2018/08/02 15:12:40 INFO  : Sara K/Water Falls/01-04 - The Painter.flac: Copied (new)
2018/08/02 15:12:57 INFO  : Sara K/Water Falls/01-05 - Water Falls.flac: Copied (new)
2018/08/02 15:13:02 INFO  :
Transferred:   120.169 MBytes (1020.108 kBytes/s)
Errors:                 0
Checks:                 4
Transferred:            4
Elapsed time:      2m0.6s
Transferring:
 *  Sara K/Water Falls/01-08 - Destination.flac:  3% done, 88.281 kBytes/s, ETA: 3m59s
 * ...ls/01-06 - (Would You) Break My Heart.flac: 76% done, 310.827 kBytes/s, ETA: 17s
 * ...r Falls/01-03 - Turned My Upside Down.flac: 96% done, 226.763 kBytes/s, ETA: 4s
 * Sara K/Water Falls/01-07 - Step on Mine.flac: 43% done, 367.004 kBytes/s, ETA: 32s

2018/08/02 15:13:08 INFO  : Sara K/Water Falls/01-03 - Turned My Upside Down.flac: Copied (new)
2018/08/02 15:14:02 INFO  :
Transferred:   130.839 MBytes (741.742 kBytes/s)
Errors:                 0
Checks:                 4
Transferred:            5
Elapsed time:      3m0.6s
Transferring:
 *  Sara K/Water Falls/01-08 - Destination.flac: 17% done, 7.282 kBytes/s, ETA: 41m11s
 * ...- All Your Love (Turned Into Passion).flac:  1% done, 1.028 kBytes/s, ETA: 8h26m13s
 * ...ls/01-06 - (Would You) Break My Heart.flac: 88% done, 10.725 kBytes/s, ETA: 4m8s
 * Sara K/Water Falls/01-07 - Step on Mine.flac: 61% done, 13.840 kBytes/s, ETA: 9m49s

2018/08/02 15:15:02 INFO  :
Transferred:   130.870 MBytes (556.926 kBytes/s)
Errors:                 0
Checks:                 4
Transferred:            5
Elapsed time:      4m0.6s
Transferring:
 *  Sara K/Water Falls/01-08 - Destination.flac: 17% done, 136 Bytes/s, ETA: 37h32m7s
 * ...- All Your Love (Turned Into Passion).flac:  1% done, 19 Bytes/s, ETA: 461h19m53s
 * ...ls/01-06 - (Would You) Break My Heart.flac: 88% done, 200 Bytes/s, ETA: 3h46m11s
 * Sara K/Water Falls/01-07 - Step on Mine.flac: 61% done, 585 Bytes/s, ETA: 3h57m8s

2018/08/02 15:16:02 INFO  :
Transferred:   130.870 MBytes (445.771 kBytes/s)
Errors:                 0
Checks:                 4
Transferred:            5
Elapsed time:      5m0.6s
Transferring:
 *  Sara K/Water Falls/01-08 - Destination.flac: 17% done, 2 Bytes/s, ETA: 2052h23m51s
 * ...- All Your Love (Turned Into Passion).flac:  1% done, 0 Bytes/s, ETA: 25225h12m31s
 * ...ls/01-06 - (Would You) Break My Heart.flac: 88% done, 3 Bytes/s, ETA: 206h7m36s
 * Sara K/Water Falls/01-07 - Step on Mine.flac: 61% done, 10 Bytes/s, ETA: 216h6m19s

2018/08/02 15:16:44 ERROR : sftp://*********@*******************:*****//mnt/volume1/offsite/media/music/: Discarding closed SSH connection: read tcp 10.10.10.2:15222->***.***.***.***:*****: read: operation timed out
2018/08/02 15:17:02 INFO  :
Transferred:   131.276 MBytes (372.759 kBytes/s)
Errors:                 0
Checks:                 4
Transferred:            5
Elapsed time:      6m0.6s
Transferring:
 *  Sara K/Water Falls/01-08 - Destination.flac: 17% done, 0 Bytes/s, ETA: 112223h21m56s
 * ...- All Your Love (Turned Into Passion).flac:  2% done, 7.342 kBytes/s, ETA: 1h10m3s
 * ...ls/01-06 - (Would You) Break My Heart.flac: 88% done, 679 Bytes/s, ETA: 1h6m0s
 * Sara K/Water Falls/01-07 - Step on Mine.flac: 61% done, 0 Bytes/s, ETA: 11816h27m15s

2018/08/02 15:18:02 INFO  :
Transferred:   131.370 MBytes (319.814 kBytes/s)
Errors:                 0
Checks:                 4
Transferred:            5
Elapsed time:      7m0.6s
Transferring:
 *  Sara K/Water Falls/01-08 - Destination.flac: 18% done, 1.738 kBytes/s, ETA: 2h51m32s
 * ...- All Your Love (Turned Into Passion).flac:  2% done, 137 Bytes/s, ETA: 63h50m32s
 * ...ls/01-06 - (Would You) Break My Heart.flac: 88% done, 12 Bytes/s, ETA: 60h9m17s
 * Sara K/Water Falls/01-07 - Step on Mine.flac: 61% done, 0 Bytes/s, ETA: 646113h40m22s

2018/08/02 15:19:02 INFO  :
Transferred:   131.370 MBytes (279.890 kBytes/s)
Errors:                 0
Checks:                 4
Transferred:            5
Elapsed time:      8m0.6s
Transferring:
 *  Sara K/Water Falls/01-08 - Destination.flac: 18% done, 32 Bytes/s, ETA: 156h19m28s
 * ...- All Your Love (Turned Into Passion).flac:  2% done, 2 Bytes/s, ETA: 3490h51m1s
 * ...ls/01-06 - (Would You) Break My Heart.flac: 88% done, 0 Bytes/s, ETA: 3289h12m35s
 * Sara K/Water Falls/01-07 - Step on Mine.flac: 61% done, 0 Bytes/s, ETA: 0s

2018/08/02 15:20:02 INFO  :
Transferred:   131.370 MBytes (248.827 kBytes/s)
Errors:                 0
Checks:                 4
Transferred:            5
Elapsed time:      9m0.6s
Transferring:
 *  Sara K/Water Falls/01-08 - Destination.flac: 18% done, 0 Bytes/s, ETA: 8547h42m0s
 * ...- All Your Love (Turned Into Passion).flac:  2% done, 0 Bytes/s, ETA: 190876h44m4s
 * ...ls/01-06 - (Would You) Break My Heart.flac: 88% done, 0 Bytes/s, ETA: 179851h12m25s
 * Sara K/Water Falls/01-07 - Step on Mine.flac: 61% done, 0 Bytes/s, ETA: 0s

2018/08/02 15:21:02 INFO  :
Transferred:   131.370 MBytes (223.971 kBytes/s)
Errors:                 0
Checks:                 4
Transferred:            5
Elapsed time:     10m0.6s
Transferring:
 *  Sara K/Water Falls/01-08 - Destination.flac: 18% done, 0 Bytes/s, ETA: 467380h58m25s
 * ...- All Your Love (Turned Into Passion).flac:  2% done, 0 Bytes/s, ETA: 188786h28m45.580896768s
 * ...ls/01-06 - (Would You) Break My Heart.flac: 88% done, 0 Bytes/s, ETA: 0s
 * Sara K/Water Falls/01-07 - Step on Mine.flac: 61% done, 0 Bytes/s, ETA: 0s

2018/08/02 15:22:02 INFO  :
Transferred:   131.370 MBytes (203.629 kBytes/s)
Errors:                 0
Checks:                 4
Transferred:            5
Elapsed time:     11m0.6s
Transferring:
 *  Sara K/Water Falls/01-08 - Destination.flac: 18% done, 0 Bytes/s, ETA: 0s
 * ...- All Your Love (Turned Into Passion).flac:  2% done, 0 Bytes/s, ETA: 1910458h19m34.239770624s
 * ...ls/01-06 - (Would You) Break My Heart.flac: 88% done, 0 Bytes/s, ETA: 0s
 * Sara K/Water Falls/01-07 - Step on Mine.flac: 61% done, 0 Bytes/s, ETA: 1348223h9m24.572438528s

The regular stats output will continue indefinitely (I’ve tested this with run times > 2days).

I find it confusing that

2018/08/02 15:16:44 ERROR : sftp://*********@*******************:*****//mnt/volume1/offsite/media/music/: Discarding closed SSH connection: read tcp 10.10.10.2:15222->***.***.***.***:*****: read: operation timed out

does not cause Rclone to completely exit. After all, I have set low-level-retries to 1, so it should not try again, as the IP address will not match anymore (changes with the reconnection).

4

I wonder if it has to do with the SSH backend? I’ve routinely lost link and rclone definitely dies after the proper time out/retries but I’m using GD as a backend.

@ncw - thoughts?

5

The SSH backend does not use the same timeout handling as the http based remotes (like drive etc). It does respect --conn-timeout though.

I think this is probably a bug in the sftp library rclone uses or in rclone…

Can you put the above log in a new issue on github and we can work on fixing it - thanks.