"Skipping undecryptable file name" should be an ERROR

asdffdsa · October 23, 2021, 4:12pm

"Skipping undecryptable file name" is logged as DEBUG.

imho, that should be

logged as an ERROR
generate a non-zero exit code.
when rclone sync, should prevent rclone from deleting files.

as a result, the python script that i wrote to orchestrate rclone has to regex that text and add that to the summary email i am sent.

for other rcloners, who debug logs are large and complex to read, would not know that rclone failed to complete the command as intended.

2021/10/23 11:44:06 DEBUG : rclone: Version "v1.56.0" starting with parameters ["C:\\data\\rclone\\scripts\\rclone.exe" "sync" "b:\\mount\\rcloner\\keepass_files_onedrivevb_crypt_20211023.114405\\data\\keepass" "onedrivevb_crypt:en07keepass/rclone/backup" "--backup-dir=onedrivevb_crypt:en07keepass/rclone/archive/20211023.114405" "--stats=0" "--fast-list" "--log-level=DEBUG" "--log-file=C:\\data\\rclone\\logs\\keepass_files_onedrivevb_crypt\\20211023.114405\\rclone.log" "--config=C:\\data\\rclone\\scripts\\onedrive.conf" "--ask-password"]
2021/10/23 11:44:06 DEBUG : Creating backend with remote "b:\\mount\\rcloner\\keepass_files_onedrivevb_crypt_20211023.114405\\data\\keepass"
2021/10/23 11:44:06 DEBUG : Using config file from "C:\\data\\rclone\\scripts\\onedrive.conf"
2021/10/23 11:44:06 DEBUG : fs cache: renaming cache item "b:\\mount\\rcloner\\keepass_files_onedrivevb_crypt_20211023.114405\\data\\keepass" to be canonical "//?/b:/mount/rcloner/keepass_files_onedrivevb_crypt_20211023.114405/data/keepass"
2021/10/23 11:44:06 DEBUG : Creating backend with remote "onedrivevb_crypt:en07keepass/rclone/backup"
2021/10/23 11:44:07 DEBUG : Creating backend with remote "onedrivevb:crypt01/83jmcan84pcee32d1p7890mmlo/vplun6pmri0mr96fadebs0mm0s/ebue23o4ems817a5kdmjh5ureg"
2021/10/23 11:44:08 DEBUG : Creating backend with remote "onedrivevb_crypt:en07keepass/rclone/archive/20211023.114405"
2021/10/23 11:44:08 DEBUG : Creating backend with remote "onedrivevb:crypt01/83jmcan84pcee32d1p7890mmlo/vplun6pmri0mr96fadebs0mm0s/liigm7fdonh9ek3p5g2bvri3q0/6est3fpf9v21ns1um1tm7cnh54"
2021/10/23 11:44:13 DEBUG : AutoHotkeyU64.exe: Size and modification time the same (differ by -741.1696ms, within tolerance 1s)
2021/10/23 11:44:13 DEBUG : AutoHotkeyU64.exe: Unchanged skipping
2021/10/23 11:44:13 DEBUG : KeePass.chm: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:13 DEBUG : KeePass.chm: Unchanged skipping
2021/10/23 11:44:13 DEBUG : KeePass.exe: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:13 DEBUG : KeePass.exe: Unchanged skipping
2021/10/23 11:44:13 DEBUG : KeePass.config.xml: Size and modification time the same (differ by -635.5729ms, within tolerance 1s)
2021/10/23 11:44:13 DEBUG : KeePass.exe.config: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:13 DEBUG : KeePass.exe.config: Unchanged skipping
2021/10/23 11:44:13 DEBUG : KeePass.config.xml: Unchanged skipping
2021/10/23 11:44:13 DEBUG : KeePassLibC32.dll: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:13 DEBUG : KeePassLibC32.dll: Unchanged skipping
2021/10/23 11:44:13 DEBUG : KeePass.XmlSerializers.dll: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:13 DEBUG : KeePass.XmlSerializers.dll: Unchanged skipping
2021/10/23 11:44:13 DEBUG : KeePassLibC64.dll: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:13 DEBUG : KeePassLibC64.dll: Unchanged skipping
2021/10/23 11:44:13 DEBUG : file.txt: Unchanged skipping
2021/10/23 11:44:13 DEBUG : ShInstUtil.exe: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:13 DEBUG : ShInstUtil.exe: Unchanged skipping
2021/10/23 11:44:14 DEBUG : database/01.kdbx: Size and modification time the same (differ by -78.7563ms, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : database/01.kdbx: Unchanged skipping
2021/10/23 11:44:14 DEBUG : scripts/a2e.cmd: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : scripts/a2e.cmd: Unchanged skipping
2021/10/23 11:44:14 DEBUG : scripts/doit.cmdkey.add.cmd: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : scripts/doit.cmdkey.add.cmd: Unchanged skipping
2021/10/23 11:44:14 DEBUG : scripts/kpu.ahk: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : scripts/rdp.ahk: Size and modification time the same (differ by -555.4618ms, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : scripts/rdp.ahk: Unchanged skipping
2021/10/23 11:44:14 DEBUG : scripts/rdp.ru.2fa.ahk: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : scripts/rdp.ru.2fa.ahk: Unchanged skipping
2021/10/23 11:44:14 DEBUG : scripts/doit.cmdkey.delete.cmd: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : scripts/doit.cmdkey.delete.cmd: Unchanged skipping
2021/10/23 11:44:14 DEBUG : scripts/kpu.ahk: Unchanged skipping
2021/10/23 11:44:14 DEBUG : scripts/ru.cmd: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : scripts/ru.cmd: Unchanged skipping
2021/10/23 11:44:14 DEBUG : scripts/sch_kdbx_quick.backup.cmd: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : scripts/nircmdc.exe: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : scripts/nircmdc.exe: Unchanged skipping
2021/10/23 11:44:14 DEBUG : scripts/vbar.console.ahk: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : scripts/vbar.console.ahk: Unchanged skipping
2021/10/23 11:44:14 DEBUG : scripts/viscosity.test.ahk: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : scripts/viscosity.test.ahk: Unchanged skipping
2021/10/23 11:44:14 DEBUG : scripts/quick.backup.cmd: Size and modification time the same (differ by -564.6546ms, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : scripts/quick.backup.cmd: Unchanged skipping
2021/10/23 11:44:14 DEBUG : scripts/back.cmd: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : scripts/back.cmd: Unchanged skipping
2021/10/23 11:44:14 DEBUG : scripts/rclone.rdp.py: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : scripts/rclone.rdp.py: Unchanged skipping
2021/10/23 11:44:14 DEBUG : scripts/rdp.ru.ahk: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : scripts/rdp.ru.ahk: Unchanged skipping
2021/10/23 11:44:14 DEBUG : scripts/doit.py.cmd: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : scripts/doit.py.cmd: Unchanged skipping
2021/10/23 11:44:14 DEBUG : scripts/sch_kdbx_quick.backup.cmd: Unchanged skipping
2021/10/23 11:44:14 DEBUG : scripts/viscosity.ahk: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : scripts/viscosity.ahk: Unchanged skipping
2021/10/23 11:44:14 DEBUG : key/01.key: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : key/01.key: Unchanged skipping
2021/10/23 11:44:14 DEBUG : qkla6d84saeepjt9a8fphrvivk/~tmp2F_e8r7nf8ge88uspuaid7912ea796pktenj1ciut56shf7pcl04ns0: Skipping undecryptable file name: illegal base32 data at input byte 0
2021/10/23 11:44:14 DEBUG : XSL/KDBX_Common.xsl: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : XSL/KDBX_Common.xsl: Unchanged skipping
2021/10/23 11:44:14 DEBUG : XSL/KDBX_DetailsFull_HTML.xsl: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : XSL/KDBX_DetailsFull_HTML.xsl: Unchanged skipping
2021/10/23 11:44:14 DEBUG : XSL/KDBX_DetailsLight_HTML.xsl: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : XSL/KDBX_DetailsLight_HTML.xsl: Unchanged skipping
2021/10/23 11:44:14 DEBUG : XSL/KDBX_PasswordsOnly_TXT.xsl: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : XSL/KDBX_PasswordsOnly_TXT.xsl: Unchanged skipping
2021/10/23 11:44:14 DEBUG : XSL/KDBX_Tabular_HTML.xsl: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : XSL/KDBX_Tabular_HTML.xsl: Unchanged skipping
2021/10/23 11:44:14 DEBUG : Plugins/KeePassOTP/KeePassOTP.plgx: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : Plugins/KeePassOTP/KeePassOTP.plgx: Unchanged skipping
2021/10/23 11:44:14 DEBUG : Plugins/KPEnhancedEntryView-v2.4.1/KPEnhancedEntryView-v2.4.1.zip: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : Plugins/KPEnhancedEntryView-v2.4.1/KPEnhancedEntryView-v2.4.1.zip: Unchanged skipping
2021/10/23 11:44:14 DEBUG : Plugins/KPEnhancedEntryView-v2.4.1/Readme.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : Plugins/KPEnhancedEntryView-v2.4.1/Readme.txt: Unchanged skipping
2021/10/23 11:44:14 DEBUG : Plugins/KPEnhancedEntryView-v2.4.1/COPYING: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : Plugins/KPEnhancedEntryView-v2.4.1/COPYING: Unchanged skipping
2021/10/23 11:44:14 DEBUG : Plugins/KPEnhancedEntryView-v2.4.1/KPEnhancedEntryView.plgx: Size and modification time the same (differ by 0s, within tolerance 1s)
2021/10/23 11:44:14 DEBUG : Plugins/KPEnhancedEntryView-v2.4.1/KPEnhancedEntryView.plgx: Unchanged skipping
2021/10/23 11:44:14 DEBUG : Encrypted drive 'onedrivevb_crypt:en07keepass/rclone/backup': Waiting for checks to finish
2021/10/23 11:44:14 DEBUG : Encrypted drive 'onedrivevb_crypt:en07keepass/rclone/backup': Waiting for transfers to finish
2021/10/23 11:44:14 DEBUG : Waiting for deletions to finish
2021/10/23 11:44:19 DEBUG : Encrypted drive 'onedrivevb_crypt:en07keepass/rclone/backup': deleted 1 directories
2021/10/23 11:44:19 INFO  : There was nothing to transfer
2021/10/23 11:44:19 DEBUG : 7 go routines active

ncw · October 23, 2021, 10:02pm

Unfortunately people mix crypt and non crypt stuff in the same directory and this would drive them wild with lots of ERROR messages.

asdffdsa · October 23, 2021, 10:34pm

hi,

yes, people might mix crypt and non-crypt.
i would be surprised to find a rcloner that intentionally does that.
as per the docs:
"To avoid issues it is best to configure a dedicated path for encrypted content, and access it exclusively through a crypt remote."

i had a 2MB log. sometimes i manually scan the logs and got lucky that i noticed it.

in the end, it is your call and now i have added that log entry to the set of regex that my script scans for.

tho i do worry about people who have not yet transitioned to a fellow rcloner.
for them, this would be an ERROR and they would want to know.

Ole · October 24, 2021, 7:01am

I find

"DEBUG skipping" too quiet about a possible data corruption/mess up.
"ERROR failed" too hard because it prohibits sync until the issue has been addressed and this isn’t necessary because the offending file is ignored (it is not deleted by the sync).
"NOTICE Warning, skipping" too noisy/verbose for users with a bit of mess in their folder structure.
"INFO Warning, skipping" strikes the right balance.

asdffdsa · October 25, 2021, 2:17pm

i see your logic

my concern is for newbies and most users, who would not be mixing crypted and decrypted.

rclone should have at least have one message as NOTICE as most newbies do not use -v
"One or more files were skipped - using undecryptable file name(s). use a debug log to get a complete list"

Ole · October 25, 2021, 4:34pm

I appreciate your concern and recognize that you are often first in line when bad things happen to newbies.

My findings were based on a comparison to a similar situation without encryption. That is rclone sync source: targetCrypt: should have similar behavior as rclone sync source: target: when the target contains files from other sources or files where the file names have been changed/corrupted.

The correct behavior based on this analogy would be “INFO deleting”, but I find this too drastic - especially given the current behavior.

The analogy also shows that a natural consequence of a “NOTICE warning skipping” would be to introduce a “NOTICE warning deleting” on all jobs deleting (potentially unexpected) files in the (unencrypted) target.

The NOTICE road could therefore easily lead to a longer and more heated discussion than a proposal to change a single fs.Debugf(...) to fs.Infof(...) in the crypt backend.

ncw · October 30, 2021, 12:59pm

So raising the log from DEBUG to NOTICE would be OK by me.

We could also have an additional flag for crypt - say strict_names which raises an error if it gets any names like this. This would suit @asdffdsa original purpose I think?

asdffdsa · October 30, 2021, 2:42pm

NOTICE + strict_names, that suits me fine

thanks,

ncw · November 5, 2021, 12:57pm

Do you want to open a new issue on Github about this? With a link to this forum thread?

asdffdsa · November 5, 2021, 2:03pm

thanks,

"Skipping undecryptable file name" is logged as NOTICE + add new flag strict_names · Issue #5787 · rclone/rclone · GitHub

system · January 5, 2022, 10:03am

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