abraunegg / onedrive

OneDrive Client for Linux
https://abraunegg.github.io
GNU General Public License v3.0
10.06k stars 859 forks source link

Unable to recursively delete directories in OneDrive Business when Retention Policy is enabled #338

Closed jacklovell closed 4 years ago

jacklovell commented 5 years ago

Bug Report Details

Describe the bug After deleting folders locally, onedrive fails to sync with the remote (O365) server. I get the following error message:

Deleting item from OneDrive: FPGA/Mini-ITX/xillinux-eval-microzed-1.3a
Retry sync count: 1: HTTP request returned status code 403 (Forbidden)
{
    "error": {
        "code": "accessDenied",
        "innerError": {
            "date": "2019-01-10T11:49:11",
            "request-id": "0c850600-9de0-473c-b987-37ada3bd886f"
        },
        "message": "Request was cancelled by event received. If attempting to delete a non-empty folder, it's possible that it's on hold"
    }
}

This is due to onedrive attempting to delete a top level folder before deleting all its contents. My current manual workaround is to delete all of the contents (find . -type f -delete), then synchronize, then loop deleting empty directories (find . -type d -empty -exec rmdir {} +) and synchronize, until there are no more empty directories. For a Onedrive account with many files, this is extremely time consuming.

onedrive should instead delete files and folders starting at the bottom of the hierarchy, which should avoid this problem.

Application and Operating System Details:

To Reproduce Steps to reproduce the behavior if not causing an application crash:

  1. Delete a non-empty folder and its contents
  2. Run onedrive --synchronize
  3. See error

Complete Verbose Log Output A clear and full log of the problem when running the application in the following manner (ie, not in monitor mode):

onedrive --synchronize --verbose <any of your other needed options>

Run the application in a separate terminal window or SSH session and provide the entire application output including the error & crash. When posing the logs, Please format log output to make it easier to read. See https://guides.github.com/features/mastering-markdown/ for more details.

Application Log Output:

Loading config ...
Using Config Dir: /home/jlovell/.config/onedrive
No config file found, using application defaults
Initializing the OneDrive API ...
Opening the item database ...
All operations will be performed in: /home/jlovell/OneDrive
Initializing the Synchronization Engine ...
Account Type: business
Default Drive ID: b!_k4fcUvK40CrbCtGMYxJKlAlr0wl0KBMg7YQ0mhjKM24Zzkqx3LfSZsh6U_sloC3
Default Root ID: 01WBD2A2F6Y2GOVW7725BZO354PWSELRRZ
Remaining Free Space: 1031860031994
Fetching details for OneDrive Root
OneDrive Root exists in the database
Syncing changes from OneDrive ...
Applying changes of Path ID: 01WBD2A2F6Y2GOVW7725BZO354PWSELRRZ
Uploading differences of .
Processing root
The directory has not changed
... (times ~20k)
Processing system
The directory has not changed
Processing pcores
The directory has been deleted locally
Deleting item from OneDrive: FPGA/Mini-ITX/xillinux-eval-microzed-1.3a/vivado-essentials/vivado_system/system/pcores
Retry sync count: 1: HTTP request returned status code 403 (Forbidden)
{
    "error": {
        "code": "accessDenied",
        "innerError": {
            "date": "2019-01-10T14:14:16",
            "request-id": "8e6ad08e-4dfc-4f0f-9e77-b2bff38cac80"
        },
        "message": "Request was cancelled by event received. If attempting to delete a non-empty folder, it's possible that it's on hold"
    }
}
Syncing changes from OneDrive ...
etc...

Bug Report Checklist

jacklovell commented 5 years ago

Also, the following was printed to STDERR (so not included in the log):

onedrive.OneDriveException@src/onedrive.d(713): HTTP request returned status code 403 (Forbidden)
{
    "error": {
        "code": "accessDenied",
        "innerError": {
            "date": "2019-01-10T14:28:50",
            "request-id": "b144d7a0-f0db-4027-a7c5-1b02dce79ff7"
        },
        "message": "Request was cancelled by event received. If attempting to delete a non-empty folder, it's possible that it's on hold"
    }
}
----------------
src/onedrive.d:48 void onedrive.OneDriveApi.checkHttpCode(ref const(std.json.JSONValue)) [0x5c1f69]
src/onedrive.d:408 void onedrive.OneDriveApi.del(const(char)[]) [0x5c119f]
src/onedrive.d:222 void onedrive.OneDriveApi.deleteById(const(char)[], const(char)[], const(char)[]) [0x5c00d2]
src/sync.d:1700 void sync.SyncEngine.uploadDeleteItem(itemdb.Item, immutable(char)[]) [0x5d213b]
src/sync.d:1091 void sync.SyncEngine.uploadDirDifferences(itemdb.Item, immutable(char)[]) [0x5cf487]
src/sync.d:1059 void sync.SyncEngine.uploadDifferences(itemdb.Item) [0x5cf219]
src/sync.d:1082 void sync.SyncEngine.uploadDirDifferences(itemdb.Item, immutable(char)[]) [0x5cf409]
src/sync.d:1059 void sync.SyncEngine.uploadDifferences(itemdb.Item) [0x5cf219]
src/sync.d:1082 void sync.SyncEngine.uploadDirDifferences(itemdb.Item, immutable(char)[]) [0x5cf409]
src/sync.d:1059 void sync.SyncEngine.uploadDifferences(itemdb.Item) [0x5cf219]
src/sync.d:1082 void sync.SyncEngine.uploadDirDifferences(itemdb.Item, immutable(char)[]) [0x5cf409]
src/sync.d:1059 void sync.SyncEngine.uploadDifferences(itemdb.Item) [0x5cf219]
src/sync.d:1082 void sync.SyncEngine.uploadDirDifferences(itemdb.Item, immutable(char)[]) [0x5cf409]
src/sync.d:1059 void sync.SyncEngine.uploadDifferences(itemdb.Item) [0x5cf219]
src/sync.d:1082 void sync.SyncEngine.uploadDirDifferences(itemdb.Item, immutable(char)[]) [0x5cf409]
src/sync.d:1059 void sync.SyncEngine.uploadDifferences(itemdb.Item) [0x5cf219]
src/sync.d:1082 void sync.SyncEngine.uploadDirDifferences(itemdb.Item, immutable(char)[]) [0x5cf409]
src/sync.d:1059 void sync.SyncEngine.uploadDifferences(itemdb.Item) [0x5cf219]
src/sync.d:1082 void sync.SyncEngine.uploadDirDifferences(itemdb.Item, immutable(char)[]) [0x5cf409]
src/sync.d:1059 void sync.SyncEngine.uploadDifferences(itemdb.Item) [0x5cf219]
src/sync.d:1016 void sync.SyncEngine.scanForDifferences(immutable(char)[]) [0x5cf001]
src/main.d:661 void main.performSync(sync.SyncEngine, immutable(char)[], bool, bool, bool) [0x5aa430]
src/main.d:482 _Dmain [0x5a9a49]
abraunegg commented 5 years ago

@jacklovell Thanks for the bug report. Currently investigating & attempting to replicate.

abraunegg commented 5 years ago

@jacklovell Unable to reproduce this at all - deleting non-empty sub folders locally and then syncing does not produce an error for me at all.

Consider the following tree:

.
├── Architecture\ Layres
├── Cisco\ VDI\ Whitepaper
├── Copy\ 1
│   ├── Architecture\ Layres
│   ├── Cisco\ VDI\ Whitepaper
│   ├── CP704
│   │   ├── Sample\ Exam
│   │   ├── Week\ 1
│   │   ├── Week\ 10
│   │   ├── Week\ 11
│   │   ├── Week\ 12
│   │   ├── Week\ 2
│   │   ├── Week\ 3
│   │   ├── Week\ 4
│   │   ├── Week\ 5
│   │   ├── Week\ 6
│   │   ├── Week\ 7
│   │   ├── Week\ 8
│   │   └── Week\ 9
│   ├── Desktop\ Crap
│   ├── Desktop\ Crap\ #2
│   ├── Desktop\ Crap\ #3
│   ├── Exchange_Visio_Stencil_and_Template
│   ├── Hans-The\ Silva\ Method
│   ├── MyNAS
│   │   ├── Anaconda\ Code\ Help
│   │   ├── Blank\ NDA's
│   │   ├── EULA\ HTML\ Version
│   │   ├── Install\ Guide\ Graphics
│   │   │   └── PSD
│   │   ├── Install\ Guide\ Graphics\ -\ JPG
│   │   ├── MyNAS\ Install\ Guide
│   │   ├── Tick\ and\ Cross
│   │   └── WebUI\ Errors
│   ├── MYOB\ Hours
│   ├── MYOB\ Work
│   └── SMPP
├── Copy\ 2
│   ├── Architecture\ Layres
│   ├── Cisco\ VDI\ Whitepaper
│   ├── CP704
│   │   ├── Sample\ Exam
│   │   ├── Week\ 1
│   │   ├── Week\ 10
│   │   ├── Week\ 11
│   │   ├── Week\ 12
│   │   ├── Week\ 2
│   │   ├── Week\ 3
│   │   ├── Week\ 4
│   │   ├── Week\ 5
│   │   ├── Week\ 6
│   │   ├── Week\ 7
│   │   ├── Week\ 8
│   │   └── Week\ 9
│   ├── Desktop\ Crap
│   ├── Desktop\ Crap\ #2
│   ├── Desktop\ Crap\ #3
│   ├── Exchange_Visio_Stencil_and_Template
│   ├── Hans-The\ Silva\ Method
│   ├── MyNAS
│   │   ├── Anaconda\ Code\ Help
│   │   ├── Blank\ NDA's
│   │   ├── EULA\ HTML\ Version
│   │   ├── Install\ Guide\ Graphics
│   │   │   └── PSD
│   │   ├── Install\ Guide\ Graphics\ -\ JPG
│   │   ├── MyNAS\ Install\ Guide
│   │   ├── Tick\ and\ Cross
│   │   └── WebUI\ Errors
│   ├── MYOB\ Hours
│   ├── MYOB\ Work
│   └── SMPP
├── CP704
│   ├── Sample\ Exam
│   ├── Week\ 1
│   ├── Week\ 10
│   ├── Week\ 11
│   ├── Week\ 12
│   ├── Week\ 2
│   ├── Week\ 3
│   ├── Week\ 4
│   ├── Week\ 5
│   ├── Week\ 6
│   ├── Week\ 7
│   ├── Week\ 8
│   └── Week\ 9
├── Desktop\ Crap
├── Desktop\ Crap\ #2
├── Desktop\ Crap\ #3
├── ecryptfs
│   └── trunk
│       ├── debian
│       │   ├── local
│       │   ├── patches
│       │   ├── po
│       │   └── source
│       ├── doc
│       │   ├── beginners_guide
│       │   ├── call_graph
│       │   ├── design_doc
│       │   └── manpage
│       ├── img
│       │   └── old
│       ├── lintian
│       ├── m4
│       ├── po
│       ├── rpm
│       ├── scripts
│       ├── src
│       │   ├── daemon
│       │   ├── desktop
│       │   ├── include
│       │   ├── key_mod
│       │   ├── libecryptfs
│       │   ├── libecryptfs-swig
│       │   ├── pam_ecryptfs
│       │   ├── python
│       │   └── utils
│       └── tests
│           ├── kernel
│           │   ├── directory-concurrent
│           │   ├── enospc
│           │   ├── extend-file-random
│           │   ├── file-concurrent
│           │   ├── inode-race-stat
│           │   ├── inotify
│           │   ├── llseek
│           │   ├── lp-509180
│           │   ├── lp-524919
│           │   ├── lp-870326
│           │   ├── lp-994247
│           │   ├── miscdev-bad-count
│           │   ├── mmap-bmap
│           │   ├── mmap-close
│           │   ├── mmap-dir
│           │   ├── read-dir
│           │   ├── trunc-file
│           │   └── xattr
│           ├── lib
│           └── userspace
│               ├── lfs
│               ├── verify-passphrase-sig
│               └── wrap-unwrap
├── ODS
│   ├── Architecture\ Layres
│   ├── Cisco\ VDI\ Whitepaper
│   ├── CP704
│   │   ├── Sample\ Exam
│   │   ├── Week\ 1
│   │   ├── Week\ 10
│   │   ├── Week\ 11
│   │   ├── Week\ 12
│   │   ├── Week\ 2
│   │   ├── Week\ 3
│   │   ├── Week\ 4
│   │   ├── Week\ 5
│   │   ├── Week\ 6
│   │   ├── Week\ 7
│   │   ├── Week\ 8
│   │   └── Week\ 9
│   ├── eakbas
│   ├── Images
│   │   ├── JPG
│   │   └── PNG
│   │       ├── Screen\ Shots\ v1.0.0
│   │       ├── Screen\ Shots\ v1.1.0
│   │       │   ├── Admin\ Guide
│   │       │   └── Install\ Guide
│   │       ├── Screen\ Shots\ v1.2.0
│   │       │   ├── Admin\ Guide
│   │       │   └── Install\ Guide
│   │       ├── Screen\ Shots\ v1.3.0
│   │       │   ├── Admin\ Guide
│   │       │   └── Install\ Guide
│   │       ├── Screen\ Shots\ v1.4.0
│   │       │   ├── Admin\ Guide
│   │       │   ├── Install\ Guide
│   │       │   └── Other
│   │       └── Screen\ Shots\ v2.0.0
│   ├── MyNAS
│   │   ├── Anaconda\ Code\ Help
│   │   ├── Blank\ NDA's
│   │   ├── EULA\ HTML\ Version
│   │   ├── Install\ Guide\ Graphics
│   │   │   └── PSD
│   │   ├── Install\ Guide\ Graphics\ -\ JPG
│   │   ├── MyNAS\ Install\ Guide
│   │   ├── Tick\ and\ Cross
│   │   └── WebUI\ Errors
│   ├── MYOB\ Hours
│   ├── MYOB\ Work
│   └── SMPP
└── SMPP

193 directories

Then I issue:

rm -rf ./ODS/Architecture\ Layres/

Then I perform a new sync:

./onedrive --confdir '~/.config/onedrive-business' --synchronize --verbose
Loading config ...
Using Config Dir: /home/alex/.config/onedrive-business
No config file found, using application defaults
Initializing the OneDrive API ...
Opening the item database ...
All operations will be performed in: /home/alex/OneDrive
Initializing the Synchronization Engine ...
Account Type: business
Default Drive ID: b!xA9hqR7mT0OL6Gku8YbuzTJ8oZmRnQZJu6-yDL49Zc5MccrHbuT0R4QUwIzUvbJY
Default Root ID: 01D6JQORV6Y2GOVW7725BZO354PWSELRRZ
Remaining Free Space: 1099003921953
Fetching details for OneDrive Root
OneDrive Root exists in the database
Syncing changes from OneDrive ...
Applying changes of Path ID: 01D6JQORV6Y2GOVW7725BZO354PWSELRRZ
Uploading differences of .
Processing root
The directory has not changed
Processing SMPP
The directory has not changed
Processing SMPP-IF-SPEC_v3_3-24858.pdf
The file has not changed
Processing SMPP_v3_4_Issue1_2-24857.pdf
The file has not changed
Processing ecryptfs
The directory has not changed
Processing trunk
The directory has not changed
Processing CONTRIBUTING
The file has not changed
Processing NEWS
...
The file has not changed
Processing cp704_quallec_6_six sigma.ppt
The file has not changed
Processing tutorial10.doc
The file has not changed
Processing ODS
The directory has not changed
Processing Architecture Layres                           <- REMOVED CORRECTLY
The directory has been deleted locally                   <- REMOVED CORRECTLY
Deleting item from OneDrive: ODS/Architecture Layres     <- REMOVED CORRECTLY
Processing CP704
The directory has not changed
Processing Week 4
The directory has not changed
Processing cp704_lecture_7_framework.ppt
The file has not changed
Processing Tutorial04.doc
...
Processing Getting_Started_w_View_40_RC.pdf
The file has not changed
Processing Architecture Layres
The directory has not changed
Processing architecture layers v0.4 - AB.vsd
The file has not changed
Processing MYOB Work
The directory has not changed
Processing MYOB System Audit.docx
The file has not changed
Processing MYOB 2012.6 Performance Testing - AV Software.zip
The file has not changed
Processing MYOB 2012.6 Performance Testing - AV Software.docx
The file has not changed
Uploading new items of .
Applying changes of Path ID: 01D6JQORV6Y2GOVW7725BZO354PWSELRRZ

Please can you provide more detailed reproduction steps that can trigger this issue 100% of the time.

abraunegg commented 5 years ago

@jacklovell If you can provide some file & folder statistics (# of files, # of sub folders, file size etc) for the folders you are attempting to delete that would also be greatly appreciated.

abraunegg commented 5 years ago

@jacklovell I have created a PR to capture some additional debugging to help identify what is going on. Please can you capture some logs using this version in addition to:

git clone https://github.com/abraunegg/onedrive.git
cd onedrive
git fetch origin pull/341/head:pr341
git checkout pr341
make

Please can you run the above PR with the following command:

onedrive --synchronize --verbose --verbose <+ any others you need> --debug-https > debug_output.log 2>&1

Sanitise your logfile using:

sed -i '/^Authorization:\ bearer\ /d' debug_output.log

Depending on the 'volume' of files / sub folders, this could be an API issue where 'files / folders' with > than X number of entries take a while to delete, thus it would seem like it is attempting to delete non empty items for you.

abraunegg commented 5 years ago

@jacklovell Potentially related issue: https://github.com/OneDrive/onedrive-api-docs/issues/933

jacklovell commented 5 years ago

@abraunegg Thanks for looking into this. It seems to be an issue with the way OneDrive Business's retention policy is configured: see for example https://office365.uservoice.com/forums/289138-office-365-security-compliance/suggestions/19799911-onedrive-for-business-unable-to-perform-delete-fol.

I also encounter this issue when I try to delete a non-empty folder in the OneDrive web interface (in my case, https://onedrive.com redirects to https://\<employer name>-my.sharepoint.com/../onedrive.aspx). I get the following notification when the delete fails: onedrive_delete

It seems that onedrive is matching the behaviour of Microsoft's web interface here. So if you can successfully delete a non-empty directory in the web interface, that would explain why you can't reproduce the problem.

I'm currently removing loads of files from my Onedrive, and it's taking a very long time to sync. Once I'm down to a more manageable amount of files, I'll checkout your PR above and provide some more detailed logs, if these are still useful.

abraunegg commented 5 years ago

@abraunegg Thanks for looking into this. It seems to be an issue with the way OneDrive Business's retention policy is configured: see for example https://office365.uservoice.com/forums/289138-office-365-security-compliance/suggestions/19799911-onedrive-for-business-unable-to-perform-delete-fol.

I also encounter this issue when I try to delete a non-empty folder in the OneDrive web interface (in my case, https://onedrive.com redirects to https://-my.sharepoint.com/../onedrive.aspx). I get the following notification when the delete fails: onedrive_delete

It seems that onedrive is matching the behaviour of Microsoft's web interface here. So if you can successfully delete a non-empty directory in the web interface, that would explain why you can't reproduce the problem.

I'm currently removing loads of files from my Onedrive, and it's taking a very long time to sync. Once I'm down to a more manageable amount of files, I'll checkout your PR above and provide some more detailed logs, if these are still useful.

@jacklovell Thanks - at least the 'cause' of this issue has been identified. The 'onedrive' client still will crash when it encounters this issue, thus that still needs to be fixed. I can successfully delete non-empty folders via the web interface.

Do you know how to 'enable' this feature on OneDrive Business / SharePoint? I have looked around 'Site Settings' for a SharePoint Library and nothing stands out as being obvious.

jacklovell commented 5 years ago

I'm afraid I don't know much more about this feature. As I understand it, eDiscovery holds need to be in place, but this requires an administrator to change. I think this is the relevant documentation, but I don't have admin rights and so can't see the Security & Compiliance Centre options: https://docs.microsoft.com/en-gb/Office365/SecurityCompliance/ediscovery-cases?redirectSourcePath=%252fen-us%252farticle%252fmanage-ediscovery-cases-in-the-security--compliance-center-9a00b9ea-33fd-4772-8ea6-9d3c65e829e6.

abraunegg commented 5 years ago

@jacklovell Thanks - will try to see how I can activate this so that the issue can be replicated. If I cant replicate, I will need to work with you and through various code changes so that the 'right' experience for this situation occurs.

The current PR will start with providing what is the OneDrive response when a 'Retention Policy' is enabled. If you can run that PR against some test tree / test folder / test account that is affected that would be greatly appreciated.

jacklovell commented 5 years ago

Attached is the log output of onedrive --synchronize --verbose --verbose --debug-https > debug_output.log 2>&1 when trying to delete a folder called test with a single file, file.test, inside it. I've removed most of the "processing \nThe directory has not changed" lines, to make it easier to find the relative log entries. This is using a local checkout of pr341:

jlovell@jlovell-thinkpad ~ $ onedrive --version
onedrive v2.2.4-23-g9832702

debug_output.log

abraunegg commented 5 years ago

@jacklovell Thanks - this gives me a direction to update the PR to handle this situation

abraunegg commented 5 years ago

@jacklovell Can you retest with the latest PR #341 ?

The response from OneDrive should now be correctly captured & a warning message printed as to why the remote folder could not be deleted.

Currently working through the right way on how to recursively delete files remotely when this situation occurs & currently have no way to test either.

jacklovell commented 5 years ago

I've tested again this morning. Looks good: the error message and suggested workaround appear in both verbose (onedrive --synchronize --verbose --verbose --debug-https) and standard (onedrive --synchronize) modes. Logs attached.

jlovell@jlovell-thinkpad ~ $ onedrive --version
onedrive v2.2.5-3-gdcc582f

debug_output.log debug_nonverbose.log

abraunegg commented 5 years ago

@jacklovell PR #341 merged

Workaround: Client will print the following when this issue is encountered:

ERROR: Unable to delete the requested remote path from OneDrive: <dir>
ERROR: This error is due to OneDrive Business Retention Policy being applied
WORKAROUND: Manually delete all files and folders from the above path as per Business Retention Policy

A future version of onedrive will attempt to resolve this automatically.

asnowfix commented 4 years ago

I belive I am getting this error too:

[...]
ERROR: Unable to delete the requested remote path from OneDrive: Dropbox/Personal/2019/2019 - air france
ERROR: This error is due to OneDrive Business Retention Policy being applied
WORKAROUND: Manually delete all files and folders from the above path as per Business Retention Policy

ERROR: Current directory has a 'case-insensitive match' to an existing directory on OneDrive
ERROR: To resolve, rename this local directory: /home/fkowalski/OneDrive/./Dropbox/Personal/2019/2019 - Air France
ERROR: Remote OneDrive directory: 2019 - air france
[...]

My concern is that onedrive seems to exit upon this error. Being a background process (that I do not monitor), I would rather expect it to skip over it, even if the file is not synchronized & the client hits the error again & again.

abraunegg commented 4 years ago

@asnowfix

My concern is that onedrive seems to exit upon this error

Which error is the client exiting as you have listed 2 different errors ?

Whilst the first is logged as an "error" this is not a client error or issue - this is due OneDrive Business Retention Policy being applied to your OneDrive account and this causes this error.

The second, again, whilst logged as an "error" this occurs because you have 2 folders with the same name according to the Microsoft naming conventions - the only way to solve this one is for you to rename your directories to be compliant.

asnowfix commented 4 years ago

You are right: I am not absolutely sure that the error I mentioned is causing onedrive to exit at that point. Given that every few days I find onedrive stopped, I am trying to capture why it exited (or was killed).

Note that I am getting these error on stderr rather than in the log file: you may want to fix it.

 ERROR: Unable to delete the requested remote path from OneDrive: Dropbox/Personal/2019/2019 - air france (Case Conflict 56)
ERROR: This error is due to OneDrive Business Retention Policy being applied
WORKAROUND: Manually delete all files and folders from the above path as per Business Retention Policy

I just reproduced the issue, but I do not find one drive exiting, so this might not be the actual issue I am facing.

abraunegg commented 4 years ago

@asnowfix

Given that every few days I find onedrive stopped, I am trying to capture why it exited (or was killed).

Most likely some sort of transient network access issue.

It would be advisable to run the client in debug & https debug mode to determine further how and why the client is exiting as per https://github.com/abraunegg/onedrive/wiki/Generate-https-debug-log-for-support

Note that I am getting these error on stderr rather than in the log file: you may want to fix it.

Noted - however all of these are log.error - which goes to stderr .. so this is not a bug. Please raise a new issue for a change as this is not a bug, but would be treated as an enhancement.

As your running as a service (given it is a background process) - if your running systemd, these errors as per stderr 'should' be logged to the systemd log file, thus logged.

lock[bot] commented 4 years ago

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.