Sftp: "Bad message" (SSH_FX_BAD_MESSAGE)

Help and Support
1

What is the problem you are having with rclone?

Running into an issue when using rclone with SFTP.

Main Error:

2021/01/30 10:47:50 Failed to sync: Update Create failed: sftp: "Bad message" (SSH_FX_BAD_MESSAGE)

2021/01/30 10:44:47 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Errors:                 1 (retrying may help)
Checks:            168103 / 168103, 100%
Elapsed time:       7m0.7s

2021/01/30 10:45:47 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Errors:                 1 (retrying may help)
Checks:            196023 / 196023, 100%
Elapsed time:       8m0.7s

2021/01/30 10:46:47 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Errors:                 1 (retrying may help)
Checks:            216943 / 216943, 100%
Elapsed time:       9m0.7s

2021/01/30 10:47:47 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Errors:                 1 (retrying may help)
Checks:            234084 / 234084, 100%
Elapsed time:      10m0.7s

2021/01/30 10:47:50 ERROR : Encrypted drive 'encrypted:/AppData': not deleting files as there were IO errors
2021/01/30 10:47:50 ERROR : Encrypted drive 'encrypted:/AppData': not deleting directories as there were IO errors
2021/01/30 10:47:50 INFO  : There was nothing to transfer
2021/01/30 10:47:50 ERROR : Attempt 3/3 failed with 1 errors and: Update Create failed: sftp: "Bad message" (SSH_FX_BAD_MESSAGE)
2021/01/30 10:47:50 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Errors:                 1 (retrying may help)
Checks:            234342 / 234342, 100%
Elapsed time:      10m3.8s

2021/01/30 10:47:50 Failed to sync: Update Create failed: sftp: "Bad message" (SSH_FX_BAD_MESSAGE)

Not really sure how to debug it. Seems to work without a hitch locally. Could it be the file length that SFTP isnt liking.

What is your rclone version (output from rclone version)

rclone v1.53.3

  • os/arch: linux/amd64
  • go version: go1.15.5#### Which OS you are using and how many bits (eg Windows 7, 64 bit)

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

SFTP

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

rclone sync $TEMP_SOURCE $RCLONE_REMOTE:/$BACKUP_NAME --bwlimit "08:00,250 22:00,off" --log-level $LOG_LEVEL --log-file=$LOGFILE

The rclone config contents with secrets removed.

[offsite]
type = sftp
host = 192.168.6.2
user = root
port = 22
pass = --removed--
md5sum_command = md5sum
sha1sum_command = sha1sum

[encrypted]
type = crypt
remote = offsite:/mnt/hdd/rclone/encrypted/
filename_encryption = standard
directory_name_encryption = true
password = --removed--
password2 = --removed--

A log from the command with the -vv flag

Log file was 468k lines long so thought it was unnecessary to upload.

2021/01/30 11:12:58 DEBUG : rclone: Version "v1.53.3" starting with parameters ["rcloneorig" "--config" "/boot/config/plugins/rclone/.rclone.conf" "sync" "/mnt/user/backup/AppData/extracted/" "encrypted:/AppData" "--bwlimit" "08:00,250 22:00,off" "--log-level" "DEBUG" "--log-file=/mnt/user/backup/logs/rclone-AppData-2021-01-30.log"]
2021/01/30 11:12:58 DEBUG : Creating backend with remote "/mnt/user/backup/AppData/extracted/"
2021/01/30 11:12:58 DEBUG : Using config file from "/boot/config/plugins/rclone/.rclone.conf"
2021/01/30 11:12:58 INFO  : Starting bandwidth limiter at 250kBytes/s
2021/01/30 11:12:58 DEBUG : Creating backend with remote "encrypted:/AppData"
2021/01/30 11:12:58 DEBUG : Creating backend with remote "offsite:/mnt/hdd/rclone/encrypted/ --removed--"
2021/01/30 11:12:58 DEBUG : sftp://root@192.168.6.2:22//mnt/hdd/rclone/encrypted/ --removed--: New connection 192.168.1.3:35586->192.168.6.2:22 to "SSH-2.0-OpenSSH_8.2p1 Ubuntu-4ubuntu0.1"
2021/01/30 11:12:59 DEBUG : grafana/grafana.db: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/01/30 11:12:59 DEBUG : grafana/grafana.db: Unchanged skipping
2021/01/30 11:12:59 DEBUG : grafana/grafana.ini: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/01/30 11:12:59 DEBUG : grafana/grafana.ini: Unchanged skipping
2021/01/30 11:12:59 DEBUG : sftp://root@192.168.6.2:22//mnt/hdd/rclone/encrypted/ --removed--: New connection 192.168.1.3:35594->192.168.6.2:22 to "SSH-2.0-OpenSSH_8.2p1 Ubuntu-4ubuntu0.1"
2021/01/30 11:12:59 DEBUG : sftp://root@192.168.6.2:22//mnt/hdd/rclone/encrypted/ --removed--: New connection 192.168.1.3:35596->192.168.6.2:22 to "SSH-2.0-OpenSSH_8.2p1 Ubuntu-4ubuntu0.1"
2021/01/30 11:12:59 DEBUG : sftp://root@192.168.6.2:22//mnt/hdd/rclone/encrypted/ --removed--: New connection 192.168.1.3:35598->192.168.6.2:22 to "SSH-2.0-OpenSSH_8.2p1 Ubuntu-4ubuntu0.1"
2021/01/30 11:12:59 DEBUG : sftp://root@192.168.6.2:22//mnt/hdd/rclone/encrypted/ --removed--: New connection 192.168.1.3:35620->192.168.6.2:22 to "SSH-2.0-OpenSSH_8.2p1 Ubuntu-4ubuntu0.1"
2021/01/30 11:12:59 DEBUG : letsencrypt/donoteditthisfile.conf: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/01/30 11:12:59 DEBUG : letsencrypt/donoteditthisfile.conf: Unchanged skipping
2021/01/30 11:12:59 DEBUG : Duplicacy/duplicacy.json: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/01/30 11:12:59 DEBUG : Duplicacy/duplicacy.json: Unchanged skipping
2021/01/30 11:12:59 DEBUG : Duplicacy/machine-id: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/01/30 11:12:59 DEBUG : Duplicacy/machine-id: Unchanged skipping
2021/01/30 11:23:06 DEBUG : nextcloud/www/nextcloud/3rdparty/aws/aws-sdk-php/src/data/workspaces/2015-04-08/smoke.json.php: Unchanged skipping
2021/01/30 11:23:06 DEBUG : nextcloud/www/nextcloud/3rdparty/aws/aws-sdk-php/src/data/xray/2016-04-12/paginators-1.json.php: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/01/30 11:23:06 DEBUG : nextcloud/www/nextcloud/3rdparty/aws/aws-sdk-php/src/data/xray/2016-04-12/paginators-1.json.php: Unchanged skipping
2021/01/30 11:23:06 DEBUG : nextcloud/www/nextcloud/3rdparty/aws/aws-sdk-php/src/data/xray/2016-04-12/api-2.json.php: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/01/30 11:23:06 DEBUG : nextcloud/www/nextcloud/3rdparty/aws/aws-sdk-php/src/data/xray/2016-04-12/api-2.json.php: Unchanged skipping
2021/01/30 11:23:06 DEBUG : Encrypted drive 'encrypted:/AppData': Waiting for checks to finish
2021/01/30 11:23:06 DEBUG : Encrypted drive 'encrypted:/AppData': Waiting for transfers to finish
2021/01/30 11:23:06 ERROR : Encrypted drive 'encrypted:/AppData': not deleting files as there were IO errors
2021/01/30 11:23:06 ERROR : Encrypted drive 'encrypted:/AppData': not deleting directories as there were IO errors
2021/01/30 11:23:06 INFO  : There was nothing to transfer
2021/01/30 11:23:06 ERROR : Attempt 3/3 failed with 1 errors and: Update Create failed: sftp: "Bad message" (SSH_FX_BAD_MESSAGE)
2021/01/30 11:23:06 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Errors:                 1 (retrying may help)
Checks:            234342 / 234342, 100%
Elapsed time:      10m8.1s

2021/01/30 11:23:06 DEBUG : 86 go routines active
2021/01/30 11:23:06 Failed to sync: Update Create failed: sftp: "Bad message" (SSH_FX_BAD_MESSAGE)
2

hello and welcome to the forum,

perhaps this might help
Ssh_fx_bad_message - #5 by ncw

3

I did see that thread and thinking it has something to do with long file names

cat rclone-AppData-2021-01-30.log | grep ERROR 
2021/01/30 11:13:08 ERROR : krusader/xdg/data/Trash/files/Atom Heart Mother (1970)/Pink Floyd - Atom Heart Mother - 01 - Atom Heart Mother- Father’s Shout + Breast Milky + Mother Fore + Funky Dung + Mind Your Throats Please + Remergence.flac: Failed to copy: Update Create failed: sftp: "Bad message" (SSH_FX_BAD_MESSAGE)
2021/01/30 11:16:24 ERROR : Encrypted drive 'encrypted:/AppData': not deleting files as there were IO errors
2021/01/30 11:16:24 ERROR : Encrypted drive 'encrypted:/AppData': not deleting directories as there were IO errors
2021/01/30 11:16:24 ERROR : Attempt 1/3 failed with 1 errors and: Update Create failed: sftp: "Bad message" (SSH_FX_BAD_MESSAGE)
2021/01/30 11:16:33 ERROR : krusader/xdg/data/Trash/files/Atom Heart Mother (1970)/Pink Floyd - Atom Heart Mother - 01 - Atom Heart Mother- Father’s Shout + Breast Milky + Mother Fore + Funky Dung + Mind Your Throats Please + Remergence.flac: Failed to copy: Update Create failed: sftp: "Bad message" (SSH_FX_BAD_MESSAGE)
2021/01/30 11:19:45 ERROR : Encrypted drive 'encrypted:/AppData': not deleting files as there were IO errors
2021/01/30 11:19:45 ERROR : Encrypted drive 'encrypted:/AppData': not deleting directories as there were IO errors
2021/01/30 11:19:45 ERROR : Attempt 2/3 failed with 1 errors and: Update Create failed: sftp: "Bad message" (SSH_FX_BAD_MESSAGE)
2021/01/30 11:19:54 ERROR : krusader/xdg/data/Trash/files/Atom Heart Mother (1970)/Pink Floyd - Atom Heart Mother - 01 - Atom Heart Mother- Father’s Shout + Breast Milky + Mother Fore + Funky Dung + Mind Your Throats Please + Remergence.flac: Failed to copy: Update Create failed: sftp: "Bad message" (SSH_FX_BAD_MESSAGE)
2021/01/30 11:23:06 ERROR : Encrypted drive 'encrypted:/AppData': not deleting files as there were IO errors
2021/01/30 11:23:06 ERROR : Encrypted drive 'encrypted:/AppData': not deleting directories as there were IO errors
2021/01/30 11:23:06 ERROR : Attempt 3/3 failed with 1 errors and: Update Create failed: sftp: "Bad message" (SSH_FX_BAD_MESSAGE)

Ill clean up those files and run it again. Thanks buddy

4

The file that is failing is 185 characters long which when crypted is likely to be > 256 bytes which won't fit in your average filesystem.

So I'd say long files are very likely the problem.

5

I deleted those files last night and ran another backup and it seemed to work without a hitch. Thanks for your feedback :slight_smile: The answer was staring at me the whole time.

1 Like
6

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