Bug: Item deleted after events of IN_MOVED_FROM & IN_CLOSE_WRITE

[yousong]

Describe the bug

I use vim to edit files stored in onedrive data dir. On save and quit (:wq), vim will do the following

• Move the old file to backupdir
• Open a new file
• Write (open with O_CREAT) and close the file

If vim backupdir is set to a directory unknown to the onedrive app, the app will only receive IN_MOVED_FILE event, no matching IN_MOVED_TO.

The event sequence onedrive app received is like the following as decoded from strace output

IN_MOVED_FROM
IN_CREATE
IN_CLOSE_WRITE

The issue is that onedrive app handles IN_CLOSE_WRITE first (upload), and at the end it assume that the items moved outside the watched directory have been deleted. So I observed the following log.

Uploading new file code/test.md ... done.
Received inotify delete event from operating system .. attempting item deletion as requested
Deleting item from OneDrive: code/test.md

Relevant code in src/monitor.d

onedrive/src/monitor.d

Lines 371 to 388 in 1a88d33

	} else if ((event.mask & IN_CLOSE_WRITE) && !(event.mask & IN_ISDIR)) {
	log.vdebug("event IN_CLOSE_WRITE and ...: ", path);
	if (useCallbacks) onFileChanged(path);
	} else {
	log.vdebug("event unhandled: ", path);
	assert(0);
	}
	skip:
	i += inotify_event.sizeof + event.len;
	}
	// assume that the items moved outside the watched directory have been deleted
	foreach (cookie, path; cookieToPath) {
	log.vdebug("deleting (post loop): ", path);
	if (useCallbacks) onDelete(path);
	remove(path);
	cookieToPath.remove(cookie);
	}

Operating System Details

Run as docker container.  Image `driveone/onedrive:debian`, aka. `driveone/onedrive@sha256:63d45b1f71f882d462299e570a5cfb9c7ce34e065bc779cfd27f94ec04eb2a3c`


PRETTY_NAME="Debian GNU/Linux 12 (bookworm)"
NAME="Debian GNU/Linux"
VERSION_ID="12"
VERSION="12 (bookworm)"
VERSION_CODENAME=bookworm
ID=debian
HOME_URL="https://www.debian.org/"
SUPPORT_URL="https://www.debian.org/support"
BUG_REPORT_URL="https://bugs.debian.org/"

Client Installation Method

From Distribution Package

OneDrive Account Type

Personal

What is your OneDrive Application Version

v2.4.25

What is your OneDrive Application Configuration

onedrive version                             = v2.4.25
Config path                                  = /root/.config/onedrive
Config file found in config path             = false
Config option 'sync_dir'                     = /root/OneDrive
Config option 'enable_logging'               = false
Config option 'log_dir'                      = /var/log/onedrive/
Config option 'disable_notifications'        = false
Config option 'min_notify_changes'           = 5
Config option 'skip_dir'                     =
Config option 'skip_dir_strict_match'        = false
Config option 'skip_file'                    = ~*|.~*|*.tmp
Config option 'skip_dotfiles'                = false
Config option 'skip_symlinks'                = false
Config option 'monitor_interval'             = 300
Config option 'monitor_log_frequency'        = 6
Config option 'monitor_fullscan_frequency'   = 12
Config option 'read_only_auth_scope'         = false
Config option 'dry_run'                      = false
Config option 'upload_only'                  = false
Config option 'download_only'                = false
Config option 'local_first'                  = false
Config option 'check_nosync'                 = false
Config option 'check_nomount'                = false
Config option 'resync'                       = false
Config option 'resync_auth'                  = false
Config option 'cleanup_local_files'          = false
Config option 'classify_as_big_delete'       = 1000
Config option 'disable_upload_validation'    = false
Config option 'bypass_data_preservation'     = false
Config option 'no_remote_delete'             = false
Config option 'remove_source_files'          = false
Config option 'sync_dir_permissions'         = 700
Config option 'sync_file_permissions'        = 600
Config option 'space_reservation'            = 52428800
Config option 'application_id'               =
Config option 'azure_ad_endpoint'            =
Config option 'azure_tenant_id'              = common
Config option 'user_agent'                   =
Config option 'force_http_11'                = false
Config option 'debug_https'                  = false
Config option 'rate_limit'                   = 0
Config option 'operation_timeout'            = 3600
Config option 'dns_timeout'                  = 60
Config option 'connect_timeout'              = 10
Config option 'data_timeout'                 = 600
Config option 'ip_protocol_version'          = 0
Config option 'sync_root_files'              = false
Selective sync 'sync_list' configured        = false
Config option 'sync_business_shared_folders' = false
Business Shared Folders configured           = false
Config option 'webhook_enabled'              = false

### What is your 'curl' version

```shell
N/A

Where is your 'sync_dir' located

Local

What are all your system 'mount points'

Not relevant

What are all your local file system partition types

N/A

How do you use 'onedrive'

Not relevant

Steps to reproduce the behaviour

1. Configure vim with let &backupdir = $HOME . "/.vim.tmp.d"
2. Edit a file with vim
3. Write then close (:wq) the file

Complete Verbose Log Output

Not relevant

Screenshots

No response

Other Log Information or Details

No response

Additional context

No response

[yousong]

IN_MOVED_FROM
IN_CREATE
IN_CLOSE_WRITE

It's worth noting that the Monitor received the 3 events in one read.

Actually it's 6 events in one read. The other 3 is about a file named 4913. It's a vim specific thing and can be safely ignored.

read(10, "\253\0\0\0\0\1\0\0\0\0\0\0\20\0\0\0004913\0\0\0\0\0\0\0\0\0\0\0\0\253\0\0\0\10\0\0\0\0\0\0\0\20\0\0\0004913\0\0\0\0\0\0\0\0\0\0\0\0\253\0\0\0\0\2\0\0\0\0\0\0\20\0\0\0004913\0\0\0\0\0\0\0\0\0\0\0\0\253\0\0\0@\0\0\0h\234\27\0\20\0\0\0test.md\0\0\0\0\0\0\0\0\0\253\0\0\0\0\1\0\0\0\0\0\0\20\0\0\0test.md\0\0\0\0\0\0\0\0\0\253\0\0\0\10\0\0\0\0\0\0\0\20\0\0\0test.md\0\0\0\0\0\0\0\0\0", 4096)

[abraunegg]

@yousong
The issue is with vim.

It is sending a delete file request with the incorrect item due to '4913' file .. which is a vim issue.

You need to add '4913' to your skip_file configuration.

[yousong]

@abraunegg It's not 4913 file. Please read the issue description again. Any program that moves a file out from onedrive data dir then create a new file with the same name can trigger the bug.

[abraunegg]

@yousong
'vim' is the culprit here - not this client.

'vim' is generating the events including the delete. This client is handling these events, in order, as required for normal client operations.

This is not a bug with this client, but is an issue with 'vim'.

Your options are:

• Configure 'vim' so that this does not occur
• Log a bug report with 'vim'
• Don't use 'vim'

[yousong]

@abraunegg Here is a simple python script for reproducing the issue.

import os

os.rename('test.md', '/tmp/test.md')
with open('test.md', 'w') as fout:
    fout.write('hello')

Save it as $HOME/a.py

Run the following shell command

( touch $HOME/onedrive/test.md; cd $HOME/onedrive ; python3 $HOME/a.py; )

[yousong]

@abraunegg Note that Vim is NOT involved in the reproduction steps here.

[abraunegg]

@yousong
Correct .. but your process which is the same as what vim does - is the issue ..

You are moving a file out which is a DELETE event .. you are creating the DELETE event.

Reproduction or not - you are causing the issue.

[yousong]

'vim' is generating the events including the delete. This client is handling these events, in order, as required for normal client operations.

Yes. vim or whatever program is generating the events.

BUT, the onedrive client is NOT handling these events, in order. It handles the close_write first then the moved_from event. Whereas the event order is moved_from , then close_write

[yousong]

The current behavior of the client is very flawed I may say. It will delete the file on the remote side, the moment after user updates content with programs like vim.

[abraunegg]

@yousong

@abraunegg Here is a simple python script for reproducing the issue.

import os

os.rename('test.md', '/tmp/test.md')
with open('test.md', 'w') as fout:
    fout.write('hello')

Save it as $HOME/a.py

Run the following shell command

( touch $HOME/onedrive/test.md; cd $HOME/onedrive ; python3 $HOME/a.py; )

test.md

FYI your proof python script also fails:

[alex@onedrive-client-dev OneDrive]$ touch ~/OneDrive/test.md; cd ~/OneDrive ; python3 ~/vim_python_bug_proof.py   
Traceback (most recent call last):
  File "/home/alex/vim_python_bug_proof.py", line 3, in <module>
    os.rename('test.md', '/tmp/test.md')
OSError: [Errno 18] Invalid cross-device link: 'test.md' -> '/tmp/test.md'

[alex@onedrive-client-dev ~]$ cat vim_python_bug_proof.py 
import os

os.rename('test.md', '/tmp/test.md')
with open('test.md', 'w') as fout:
        fout.write('hello')
[alex@onedrive-client-dev ~]$ 

No issue, as current user, copying the file to /tmp:

[alex@onedrive-client-dev ~]$ cp ~/OneDrive/test.md /tmp/test.md
[alex@onedrive-client-dev ~]$ mv ~/OneDrive/test.md /tmp/test.md 
[alex@onedrive-client-dev ~]$ 

The current behavior of the client is very flawed I may say. It will delete the file on the remote side, the moment after user updates content with programs like vim.

Now .. in testing your claim:

onedrive client version v2.4.x

[M] Local file changed: ./.newfile.swpx
Cannot upload file changes/creation: ./.newfile.swpx: No such file or directory
Received inotify delete event from operating system .. attempting item deletion as requested
[M] Local item deleted: ./.newfile.swpx
Item cannot be deleted from OneDrive because it was not found in the local database
[M] Local file changed: ./.newfile.swp
Skipping item - .file or .folder: ./.newfile.swp
Received inotify delete event from operating system .. attempting item deletion as requested
[M] Local item deleted: ./.newfile.swp
Item cannot be deleted from OneDrive because it was not found in the local database
[M] Local file changed: ./4913
Cannot upload file changes/creation: ./4913: No such file or directory
Received inotify delete event from operating system .. attempting item deletion as requested
[M] Local item deleted: ./4913
Item cannot be deleted from OneDrive because it was not found in the local database
[M] Local file changed: ./newfile
Processing newfile
The file last modified time has changed
The file content has changed
Uploading modified file newfile ... done.
Remaining free space on OneDrive: 4187593023
[M] Local file changed: ./.newfile.swp
Cannot upload file changes/creation: ./.newfile.swp: No such file or directory
Received inotify delete event from operating system .. attempting item deletion as requested
[M] Local item deleted: ./.newfile.swp
Item cannot be deleted from OneDrive because it was not found in the local database
Received inotify delete event from operating system .. attempting item deletion as requested
[M] Local item deleted: ./newfile
Deleting item from OneDrive: ./newfile

This demonstrates the issue you are claiming.

onedrive client version v2.5.x - 'alpha-5'

[M] New local file added: ./.newfile.swpx
Cannot upload file changes/creation: ./.newfile.swpx: No such file or directory
[M] Local item deleted: ./.newfile.swpx
The operating system sent a deletion notification. Trying to delete the item as requested
Item cannot be deleted from Microsoft OneDrive because it was not found in the local database
[M] New local file added: ./4913
Cannot upload file changes/creation: ./4913: No such file or directory
[M] Local item deleted: ./4913
The operating system sent a deletion notification. Trying to delete the item as requested
Item cannot be deleted from Microsoft OneDrive because it was not found in the local database
[M] Local item deleted: ./newfile
The operating system sent a deletion notification. Trying to delete the item as requested
Deleting item from OneDrive: ./newfile
[M] New local file added: ./newfile
New items to upload to OneDrive: 1
Total New Data to Upload:        33 Bytes
Uploading new file ./newfile ... done.

Contents online

The current 'inotify' handling in 'alpha-5' is the same as v2.4.x ... so I cannot detail why there is a difference in order handling at this stage - and I am not going to diagnose this further as there is no issue identified in v2.5.x codebase.

The net result here:

• Confirmed issue in v2.4.x as per your bug report
• No issue found with v2.5.x which has been under active development since June 2023 (point of last release) - no bug exists

[yousong]

FYI your proof python script also fails:

[alex@onedrive-client-dev OneDrive]$ touch ~/OneDrive/test.md; cd ~/OneDrive ; python3 ~/vim_python_bug_proof.py   
Traceback (most recent call last):
  File "/home/alex/vim_python_bug_proof.py", line 3, in <module>
    os.rename('test.md', '/tmp/test.md')
OSError: [Errno 18] Invalid cross-device link: 'test.md' -> '/tmp/test.md'

FYI, likely your test.md is located on a different file system as /tmp (likely tmpfs). mv works because it's a superset of python os.rename(). the rename syscall "does not work across different mount points, even if the same filesystem is mounted on both"

The important thing is how the onedrive program handles the 3 events coming in a single read call.

The current 'inotify' handling in 'alpha-5' is the same as v2.4.x ... so I cannot detail why there is a difference in order handling at this stage - and I am not going to diagnose this further as there is no issue identified in v2.5.x codebase.

Glad that no issue with v2.5.x. Thank you for your time and efforts. For now I am going to stick with v2.4.25 with a minor local temp fix Fix path got deleted in handling of move & close_write event

[abraunegg]

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