Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

"optional feature not implemented" with crypt-on-sftp in 1.66 #7673

Closed
uusijani opened this issue Mar 12, 2024 · 9 comments
Closed

"optional feature not implemented" with crypt-on-sftp in 1.66 #7673

uusijani opened this issue Mar 12, 2024 · 9 comments
Labels
bug Point Release Candidate
Milestone
v1.67

Comments

@uusijani
Copy link

What is the problem you are having with rclone?

I'm using a crypt-on-sftp remote, which was working just fine up until v1.65.2. With v1.66, attempts to sync to it now fail with "optional feature not implemented". I've not narrowed down whether it's the crypt or the sftp layer, so I'm just reporting my (failing) test case below.

I did a bisect, and apparently this issue came in at f5f8678 (which was a fix for #6685).

What is your rclone version (output from rclone version)

1.66.0

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

Ubuntu 22.04 (64-bit)

Which cloud storage system are you using? (e.g. Google Drive)

sftp

The command you were trying to run (e.g. rclone copy /tmp remote:tmp)

rclone sync a/ C:

Steps to reproduce

  1. rclone --config test.conf config
  2. set up sftp (44) remote called S
    • for test purposes here I'm using localhost as the underlying remote server
    • set user & password
    • leave everything else at defaults
  3. set up crypt remote C, with
    • "S:ftp" as the underlying remote
    • Very simple filename obfuscation (obfuscate)
    • Encrypt directory names (true)
    • set password, no password2
  4. mkdir -p ftp a/b # on the sftp remote; here I'm using localhost
  5. touch a/test1 # on the sftp remote
  6. rclone --config test.conf sync a/ C: -vv # no problems
  7. touch a/b/test2 # on the sftp remote
  8. rclone --config test.conf sync a/ C: -vv

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

2024/03/12 14:33:36 DEBUG : rclone: Version "v1.66.0" starting with parameters ["rclone" "--config" "test.conf" "sync" "a/" "C:" "-vv"]
2024/03/12 14:33:36 DEBUG : Creating backend with remote "a/"
2024/03/12 14:33:36 DEBUG : Using config file from "/home/jani/test.conf"
2024/03/12 14:33:36 DEBUG : fs cache: renaming cache item "a/" to be canonical "/home/jani/a"
2024/03/12 14:33:36 DEBUG : Creating backend with remote "C:"
2024/03/12 14:33:37 DEBUG : Creating backend with remote "S:ftp"
2024/03/12 14:33:37 DEBUG : sftp://jani@localhost:22/ftp: New connection 127.0.0.1:48814->127.0.0.1:22 to "SSH-2.0-OpenSSH_8.9p1 Ubuntu-3ubuntu0.6"
2024/03/12 14:33:37 DEBUG : sftp://jani@localhost:22/ftp: Shell type "unix" from config
2024/03/12 14:33:37 DEBUG : sftp://jani@localhost:22/ftp: Relative path resolved to "/home/jani/ftp"
2024/03/12 14:33:37 DEBUG : sftp://jani@localhost:22/ftp: Using root directory "/home/jani/ftp"
2024/03/12 14:33:37 DEBUG : test1: Size and modification time the same (differ by -995.288851ms, within tolerance 1s)
2024/03/12 14:33:37 DEBUG : test1: Unchanged skipping
2024/03/12 14:33:37 DEBUG : b/test2: Need to transfer - File not found at Destination
2024/03/12 14:33:37 DEBUG : Encrypted drive 'C:': Waiting for checks to finish
2024/03/12 14:33:37 DEBUG : Encrypted drive 'C:': Waiting for transfers to finish
2024/03/12 14:33:37 DEBUG : sftp://jani@localhost:22/ftp: Shell path "/home/jani/ftp/98.g/149.zkyz4.EACoEuq1.vgxzogr"
2024/03/12 14:33:37 DEBUG : sftp://jani@localhost:22/ftp: Running remote command: md5sum /home/jani/ftp/98.g/149.zkyz4.EACoEuq1.vgxzogr
2024/03/12 14:33:37 DEBUG : sftp://jani@localhost:22/ftp: Remote command result: ac83867dee807f03ee4f8f307cda1257  /home/jani/ftp/98.g/149.zkyz4.EACoEuq1.vgxzogr
2024/03/12 14:33:37 DEBUG : 98.g/149.zkyz4.EACoEuq1.vgxzogr: Parsed hash: ac83867dee807f03ee4f8f307cda1257
2024/03/12 14:33:37 DEBUG : b/test2.yuwiyok9.partial: md5 = ac83867dee807f03ee4f8f307cda1257 OK
2024/03/12 14:33:37 DEBUG : b/test2.yuwiyok9.partial: renamed to: b/test2
2024/03/12 14:33:37 INFO  : b/test2: Copied (new)
2024/03/12 14:33:37 ERROR : Encrypted drive 'C:': not deleting files as there were IO errors
2024/03/12 14:33:37 ERROR : Encrypted drive 'C:': not deleting directories as there were IO errors
2024/03/12 14:33:37 ERROR : Attempt 1/3 failed with 1 errors and: optional feature not implemented
2024/03/12 14:33:37 DEBUG : test1: Size and modification time the same (differ by -995.288851ms, within tolerance 1s)
2024/03/12 14:33:37 DEBUG : test1: Unchanged skipping
2024/03/12 14:33:37 DEBUG : b/test2: Size and modification time the same (differ by -116.891668ms, within tolerance 1s)
2024/03/12 14:33:37 DEBUG : b/test2: Unchanged skipping
2024/03/12 14:33:37 DEBUG : Encrypted drive 'C:': Waiting for checks to finish
2024/03/12 14:33:37 DEBUG : Encrypted drive 'C:': Waiting for transfers to finish
2024/03/12 14:33:37 ERROR : Encrypted drive 'C:': not deleting files as there were IO errors
2024/03/12 14:33:37 ERROR : Encrypted drive 'C:': not deleting directories as there were IO errors
2024/03/12 14:33:37 ERROR : Attempt 2/3 failed with 1 errors and: optional feature not implemented
2024/03/12 14:33:37 DEBUG : test1: Size and modification time the same (differ by -995.288851ms, within tolerance 1s)
2024/03/12 14:33:37 DEBUG : test1: Unchanged skipping
2024/03/12 14:33:37 DEBUG : b/test2: Size and modification time the same (differ by -116.891668ms, within tolerance 1s)
2024/03/12 14:33:37 DEBUG : b/test2: Unchanged skipping
2024/03/12 14:33:37 DEBUG : Encrypted drive 'C:': Waiting for checks to finish
2024/03/12 14:33:37 DEBUG : Encrypted drive 'C:': Waiting for transfers to finish
2024/03/12 14:33:37 ERROR : Encrypted drive 'C:': not deleting files as there were IO errors
2024/03/12 14:33:37 ERROR : Encrypted drive 'C:': not deleting directories as there were IO errors
2024/03/12 14:33:37 ERROR : Attempt 3/3 failed with 1 errors and: optional feature not implemented
2024/03/12 14:33:37 INFO  : 
Transferred:   	         32 B / 32 B, 100%, 0 B/s, ETA -
Errors:                 1 (retrying may help)
Checks:                 5 / 5, 100%
Transferred:            1 / 1, 100%
Elapsed time:         0.3s

2024/03/12 14:33:37 DEBUG : 15 go routines active
2024/03/12 14:33:37 DEBUG : sftp://jani@localhost:22/ftp: Closing 1 unused connections
2024/03/12 14:33:37 Failed to sync: optional feature not implemented

How to use GitHub

  • Please use the 👍 reaction to show that you are affected by the same issue.
  • Please don't comment if you have no relevant information to add. It's just extra noise for everyone subscribed to this issue.
  • Subscribe to receive notifications on status change and new comments.
@jpoggi
Copy link

jpoggi commented Mar 13, 2024

Hi,

I'm having the same issue:

rclone sync /data_01/ remote-encrypt:/data/ --include data/** --progress
2024/03/13 10:50:38 ERROR : Encrypted drive 'remote-encrypt:/data/': not deleting files as there were IO errors
2024/03/13 10:50:38 ERROR : Encrypted drive 'remote-encrypt:/data/': not deleting directories as there were IO errors
2024/03/13 10:50:38 ERROR : Attempt 1/3 failed with 1 errors and: optional feature not implemented

I must add an entra argument to keep the previous behaviour:

--no-update-dir-modtime

It seems that this is related to the remote host capability to modify folders timestamp.

Regards.

@ncw ncw added this to the v1.67 milestone Mar 13, 2024
ncw added a commit that referenced this issue Mar 13, 2024
@ncw
operations: Fix "optional feature not implemented" error with a crypt…
8cb7f28 
…ed sftp

Before this change operations.SetDirModTime could return the error
"optional feature not implemented" when attempting to set modification
times on crypted sftp backends.

This was because crypt wraps the directories using fs.DirWrapper but
these return fs.ErrorNotImplemented for the SetModTime method.

The fix is to recognise that error and fall back to using the
DirSetModTime method on the backend which does work.

Fixes #7673
@ncw
Copy link
Member

ncw commented Mar 13, 2024

I managed to replicate this. It looks easy to fix - can you try this please?

v1.67.0-beta.7775.8cb7f28f8.fix-7673-dir-wrapping on branch fix-7673-dir-wrapping (uploaded in 15-30 mins)

@jpoggi
Copy link

jpoggi commented Mar 13, 2024

@ncw,

With the v1.67.0-beta the copy and sync process is now ok 👍

@drvdijk
Copy link

drvdijk commented Mar 13, 2024

Can confirm, sync passed with v1.67.0-beta, whereas v1.66.0 fails with the optional feature not implemented error.

@uusijani
Copy link
Author

Yup, I can also confirm that v1.67.0-beta.7775.8cb7f28f8.fix-7673-dir-wrapping fixes this!

@drvdijk
Copy link

drvdijk commented Mar 17, 2024 •
edited

Even with the beta I am again encountering optional feature not implemented errors in one specific remote.

Log output with filters and endpoints redacted follows. Filtering the output with: grep -v "DEBUG.*Unchanged skipping" log.2001.txt | grep -v "Size and modification time the same (differ by .*, within tolerance" | grep -v "DEBUG.*@eaDir: Excluded". Filter reasons:

  • Unchanged skipping: none of the files in the run are changed, this is purely a no-op sync run.
  • Size and modification time the same: Didn't want to include file names in this log output, can provide some samples if needed.
  • @eaDir: default exclusion on my side as my NAS creates such files/folders that don't need to end up remotely.

Log output:

2024/03/17 08:04:16 Running rclone
2024/03/17 08:04:16 Checking process lock
2024/03/17 08:04:16 rclone --config /config/rclone.conf sync --exclude-from /config/exclude.txt -vv --stats=5s --checkers=5 --transfers=5 /source/2001 htznr_media_crypt:2001
2024/03/17 08:04:16 DEBUG : Setting --user-agent "drvd/0.1" from environment variable RCLONE_USER_AGENT="drvd/0.1"
2024/03/17 08:04:16 DEBUG : rclone: Version "v1.67.0-beta.7778.7803b4ed6" starting with parameters ["rclone" "--config" "/config/rclone.conf" "sync" "--exclude-from" "/config/exclude.txt" "-vv" "--stats=5s" "--checkers=5" "--transfers=5" "/source/2001" "htznr_media_crypt:2001"]
2024/03/17 08:04:16 DEBUG : Creating backend with remote "/source/2001"
2024/03/17 08:04:16 DEBUG : Using config file from "/config/rclone.conf"
2024/03/17 08:04:16 DEBUG : Creating backend with remote "htznr_media_crypt:2001"
2024/03/17 08:04:16 DEBUG : Creating backend with remote "htznr_media:sync/195.6445"
2024/03/17 08:04:16 DEBUG : sftp://xxx@xxx.xxx/sync/195.6445: New connection x.x.x.x:35152->x.x.x.x:xx to "SSH-2.0-OpenSSH_9.3 FreeBSD-20230719"
2024/03/17 08:04:16 DEBUG : sftp://xxx@xxx.xxx/sync/195.6445: Shell type "unix" from config
2024/03/17 08:04:16 DEBUG : sftp://xxx@xxx.xxx/sync/195.6445: Relative path resolved to "/home/sync/195.6445"
2024/03/17 08:04:16 DEBUG : sftp://xxx@xxx.xxx/sync/195.6445: Using root directory "/home/sync/195.6445"
2024/03/17 08:04:17 DEBUG : sftp://xxx@xxx.xxx/sync/195.6445: New connection x.x.x.x:35154->x.x.x.x:xx to "SSH-2.0-OpenSSH_9.3 FreeBSD-20230719"
2024/03/17 08:04:17 DEBUG : Encrypted drive 'htznr_media_crypt:2001': Waiting for checks to finish
2024/03/17 08:04:17 DEBUG : Encrypted drive 'htznr_media_crypt:2001': Waiting for transfers to finish
2024/03/17 08:04:17 ERROR : Encrypted drive 'htznr_media_crypt:2001': not deleting files as there were IO errors
2024/03/17 08:04:17 ERROR : Encrypted drive 'htznr_media_crypt:2001': not deleting directories as there were IO errors
2024/03/17 08:04:17 ERROR : Attempt 1/3 failed with 1 errors and: optional feature not implemented
2024/03/17 08:04:17 DEBUG : Encrypted drive 'htznr_media_crypt:2001': Waiting for checks to finish
2024/03/17 08:04:17 DEBUG : Encrypted drive 'htznr_media_crypt:2001': Waiting for transfers to finish
2024/03/17 08:04:17 ERROR : Encrypted drive 'htznr_media_crypt:2001': not deleting files as there were IO errors
2024/03/17 08:04:17 ERROR : Encrypted drive 'htznr_media_crypt:2001': not deleting directories as there were IO errors
2024/03/17 08:04:17 ERROR : Attempt 2/3 failed with 1 errors and: optional feature not implemented
2024/03/17 08:04:17 DEBUG : Encrypted drive 'htznr_media_crypt:2001': Waiting for checks to finish
2024/03/17 08:04:17 DEBUG : Encrypted drive 'htznr_media_crypt:2001': Waiting for transfers to finish
2024/03/17 08:04:17 ERROR : Encrypted drive 'htznr_media_crypt:2001': not deleting files as there were IO errors
2024/03/17 08:04:17 ERROR : Encrypted drive 'htznr_media_crypt:2001': not deleting directories as there were IO errors
2024/03/17 08:04:17 ERROR : Attempt 3/3 failed with 1 errors and: optional feature not implemented
2024/03/17 08:04:17 INFO  :
Transferred:              0 B / 0 B, -, 0 B/s, ETA -
Errors:                 1 (retrying may help)
Checks:                66 / 66, 100%
Elapsed time:         1.8s
^M
2024/03/17 08:04:17 DEBUG : 23 go routines active
2024/03/17 08:04:17 DEBUG : sftp://xxx@xxx.xxx/sync/195.6445: Closing 2 unused connections
2024/03/17 08:04:18 Failed to sync: optional feature not implemented

This happens for all folders in the remote htznr_media_crypt as well as running it for the full remote. I have 7 other setups exactly like this (htznr_xxx_crypt backed by htznr_xxx:sync), some of which do encounter the optional feature not implemented, some that don't. I'm unsure what's so special about these remotes, but it does again show the issue.

@kapitainsky
Copy link
Contributor

kapitainsky commented Mar 17, 2024 •
edited

2024/03/17 08:04:16 DEBUG : rclone: Version "v1.67.0-beta.7778.7803b4ed6" starting with parameters ["rclone" "--config" "/config/rclone.conf" "sync" "--exclude-from" "/config/exclude.txt" "-vv" "--stats=5s" "--checkers=5" "--transfers=5" "/source/2001" "htznr_media_crypt:2001"]

You are not using the rclone version that includes the patch for "optional feature not implemented".

You have to use:

v1.67.0-beta.7775.8cb7f28f8.fix-7673-dir-wrapping on branch fix-7673-dir-wrapping

It is separate branch and has not been merged to the main one yet.

@drvdijk
Copy link

drvdijk commented Mar 17, 2024

Thanks for pointing that out @kapitainsky - I was using the beta tag of the rclone docker image which of course at one point did point to the right beta image but right now does not.

Using a custom build of the rcone/rclone docker image pointing at the right version of the fix indeed does get rid of the errors.

@ncw ncw closed this as completed in ff855fe Mar 22, 2024
@ncw
Copy link
Member

ncw commented Mar 22, 2024

Thanks for testing.

I've merged this to master now which means it will be in the latest beta in 15-30 minutes and released in v1.67 and I'll also release it in v1.66.1

@StevenMassaro StevenMassaro mentioned this issue Mar 29, 2024
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Point Release Candidate
Projects
None yet
Milestone
v1.67
Development

No branches or pull requests
5 participants
@ncw @drvdijk @uusijani @kapitainsky @jpoggi