Bug: Activity occurs out of order #3044

sweharris · 2024-12-12T02:00:40Z

Describe the bug

If I use vim to edit a file then as part of saving it looks like the old file is deleted and the new file is written. But the app performs action in the wrong order and so the result is the file is deleted from OneDrive. On next (timed sync) the file is re-sent.

Dec 11 20:50:46 XXX onedrive[28067]: The operating system sent a deletion notification. Trying to delete the item as requested
Dec 11 20:50:46 XXX onedrive[28067]: Uploading modified file: Android_Sync/Documents/Health/Exercise.txt ... done
Dec 11 20:50:47 XXX onedrive[28067]: The operating system sent a deletion notification. Trying to delete the item as requested
Dec 11 20:50:47 XXX onedrive[28067]: Deleting item from Microsoft OneDrive: Android_Sync/Documents/Health/Exercise.txt

At this point the file is deleted from OneDrive. Some time later a new sync starts

Dec 11 20:51:35 XXX onedrive[28067]: Attempting to contact Microsoft OneDrive Login Service
Dec 11 20:51:35 XXX onedrive[28067]: Successfully reached Microsoft OneDrive Login Service
Dec 11 20:51:35 XXX onedrive[28067]: Starting a sync with Microsoft OneDrive
Dec 11 20:51:35 XXX onedrive[28067]: Syncing changes from Microsoft OneDrive ...
Dec 11 20:51:37 XXX onedrive[28067]: New items to upload to Microsoft OneDrive: 1
Dec 11 20:51:38 XXX onedrive[28067]: Uploading new file: ./Android_Sync/Documents/Health/Exercise.txt ... done
Dec 11 20:51:39 XXX onedrive[28067]: Sync with Microsoft OneDrive is complete

Operating System Details

RedHat 7

Client Installation Method

From Source

OneDrive Account Type

Personal

What is your OneDrive Application Version

onedrive v2.5.3-24-gea7ed66

What is your OneDrive Application Configuration

Application version                          = onedrive v2.5.3-24-gea7ed66
Compiled with                                = DMD 2095
Curl version                                 = libcurl/7.29.0 NSS/3.90 zlib/1.2.11 libidn/1.28 libssh2/1.8.0
User Application Config path                 = /home/sweh/.config/onedrive
System Application Config path               = /etc/onedrive
Applicable Application 'config' location     = /home/sweh/.config/onedrive/config
Configuration file found in config location  = false - using application defaults
Applicable 'sync_list' location              = /home/sweh/.config/onedrive/sync_list
Applicable 'items.sqlite3' location          = /home/sweh/.config/onedrive/items.sqlite3
Config option 'drive_id'                     = 
Config option 'sync_dir'                     = ~/OneDrive
Config option 'enable_logging'               = false
Config option 'log_dir'                      = /var/log/onedrive
Config option 'disable_notifications'        = false
Config option 'skip_dir'                     = 
Config option 'skip_dir_strict_match'        = false
Config option 'skip_file'                    = ~*|.~*|*.tmp|*.swp|*.partial
Config option 'skip_dotfiles'                = false
Config option 'skip_symlinks'                = false
Config option 'monitor_interval'             = 300
Config option 'monitor_log_frequency'        = 12
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 'disable_download_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 'permanent_delete'             = false
Config option 'application_id'               = d50ca740-c83f-4d1b-b616-12c519384f0c
Config option 'azure_ad_endpoint'            = 
Config option 'azure_tenant_id'              = 
Config option 'user_agent'                   = ISV|abraunegg|OneDrive Client for Linux/v2.5.3-24-gea7ed66
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'                 = 60
Config option 'ip_protocol_version'          = 0
Config option 'threads'                      = 8
Config option 'max_curl_idle'                = 120
Compile time option --enable-notifications   = false

Selective sync 'sync_list' configured        = false

Config option 'sync_business_shared_items'   = false

Config option 'webhook_enabled'              = false

What is your 'curl' version

curl 7.29.0 (x86_64-redhat-linux-gnu) libcurl/7.29.0 NSS/3.90 zlib/1.2.7 libidn/1.28 libssh2/1.8.0

Where is your 'sync_dir' located

Local

What are all your system 'mount points'

Relevant directory is that my $HOME is NFS mounted.

server:/FastData on /FastData type nfs (rw,relatime,vers=3,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=10.0.0.134,mountvers=3,mountport=20048,mountproto=udp,local_lock=none,addr=10.0.0.134)

What are all your local file system partition types

Not relevant

How do you use 'onedrive'

Local onedrive agent sync'ing to personal Onedrive; $HOME/OneDrive is a subdirectory $HOME, which is mounted from NFS

Agent is running from systemd as myself.

/usr/local/bin/onedrive -m --disable-notifications --monitor-interval 30 --monitor-fullscan-frequency 120 --monitor-log-frequency 999 --skip-dot-files --check-for-nosync

Steps to reproduce the behaviour

% rpm -qf /usr/bin/vi
vim-minimal-7.4.629-8.el7_9.x86_64

vi ~/OneDrive/a_test_file

Make changes.

:wq to save and exit

Complete Verbose Log Output

Dec 11 20:50:46 XXX onedrive[28067]: The operating system sent a deletion notification. Trying to delete the item as requested
Dec 11 20:50:46 XXX onedrive[28067]: Uploading modified file: Android_Sync/Documents/Health/Exercise.txt ... done
Dec 11 20:50:47 XXX onedrive[28067]: The operating system sent a deletion notification. Trying to delete the item as requested
Dec 11 20:50:47 XXX onedrive[28067]: Deleting item from Microsoft OneDrive: Android_Sync/Documents/Health/Exercise.txt

At this point the file is deleted from OneDrive. Some time later a new sync starts

Dec 11 20:51:35 XXX onedrive[28067]: Attempting to contact Microsoft OneDrive Login Service
Dec 11 20:51:35 XXX onedrive[28067]: Successfully reached Microsoft OneDrive Login Service
Dec 11 20:51:35 XXX onedrive[28067]: Starting a sync with Microsoft OneDrive
Dec 11 20:51:35 XXX onedrive[28067]: Syncing changes from Microsoft OneDrive ...
Dec 11 20:51:37 XXX onedrive[28067]: New items to upload to Microsoft OneDrive: 1
Dec 11 20:51:38 XXX onedrive[28067]: Uploading new file: ./Android_Sync/Documents/Health/Exercise.txt ... done
Dec 11 20:51:39 XXX onedrive[28067]: Sync with Microsoft OneDrive is complete

Screenshots

No response

Other Log Information or Details

No response

Additional context

No response

The text was updated successfully, but these errors were encountered:

abraunegg · 2024-12-12T07:52:25Z

@sweharris
First a couple of points:

/usr/local/bin/onedrive -m --disable-notifications --monitor-interval 30 --monitor-fullscan-frequency 120 --monitor-log-frequency 999 --skip-dot-files --check-for-nosync

--monitor-interval 30 will be ignored. Please read:
- https://github.com/abraunegg/onedrive/blob/master/docs/application-config-options.md#monitor_interval
- Lowering Monitoring Mode Interval #3043

Relevant directory is that my $HOME is NFS mounted.

NFS mounted directories can cause issues with inotify - typically inotify does not support them, so it is interesting that this is even working for you ... Please read https://github.com/abraunegg/onedrive/blob/master/docs/usage.md#how-to-change-where-my-data-from-microsoft-onedrive-is-stored

I will try and reproduce this on RHEL 7, however on Fedora, when actually using verbose logging (your output above is not verbose logging):

[M] Local item deleted: vim_test/.test_file.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: vim_test/test_file
New items to upload to Microsoft OneDrive: 1
Total New Data to Upload:        5 Bytes
Uploading new file: vim_test/test_file ... done
[M] Total number of local file(s) added or changed: 1

Exact same test without --verbose:

The operating system sent a deletion notification. Trying to delete the item as requested
The operating system sent a deletion notification. Trying to delete the item as requested
Moving vim_test/test_file to vim_test/test_file~
The operating system sent a deletion notification. Trying to delete the item as requested
Uploading modified file: vim_test/test_file ... done
Attempting to contact Microsoft OneDrive Login Service
Successfully reached Microsoft OneDrive Login Service  <----- 300 seconds later
Starting a sync with Microsoft OneDrive
Syncing changes from Microsoft OneDrive ...
Sync with Microsoft OneDrive is complete

So at this stage nothing is being sent out-of-order ......... and the correct file is being uploaded to Microsoft OneDrive when it changed, and, nothing is uploaded on the next sync cycle.

So for the moment I am marking this as unable to reproduce.

If I am unable to reproduce on RHEL7 (I will use RHEL 7.9, with and without an NFS mounted $HOME path) - I will mark this as a local environment issue and will not be solving/bug fixing this.

Additionally, RHEL7 reached its end of maintenance support 2 phase June 30th 2024. Unless you can confirm you have valid ELS that supports through to June 30 2028, I wont be able to support any further as this is a end of support platform.

sweharris · 2024-12-12T12:15:03Z

The NFS/inotify issue you're thinking of occurs if I make changes to the tree on a machine other than where the daemon is running; eg if the daemon runs on clientA and I make changes on clientB then clientA does not get an inotify message and so the daemon doesn't wake up. If a change is made on clientA then it all works properly.

I wonder if my vim config is causing a difference in behaviour; in ~/.vimrc I have:

set backupdir=~/.vim/backup/
set directory=~/.vim/backup/

abraunegg · 2024-12-12T18:58:11Z

@sweharris
Whilst I am waiting on my RHEL 7.9 system to update, I have created a PR to assist with what is actually going on by adding the path to the deletion logging - for example:

The operating system sent a deletion notification. Trying to delete this item as requested: vim_test/.test_file.swpx
New items to upload to Microsoft OneDrive: 1
Uploading new file: vim_test/test_file ... done
The operating system sent a deletion notification. Trying to delete this item as requested: vim_test/.test_file.swpx
The operating system sent a deletion notification. Trying to delete this item as requested: vim_test/4913
Moving vim_test/test_file to vim_test/test_file~
Moved local item was not in-sync with local database - uploading as new item
Skipping path - path has disappeared: vim_test/test_file~
The operating system sent a deletion notification. Trying to delete this item as requested: vim_test/test_file~
New items to upload to Microsoft OneDrive: 1
WARNING: Online file integrity failure for: vim_test/test_file
To disable the integrity checking of uploaded files use --disable-upload-validation
Skipping uploading this item as a new file, will upload as a modified file (online file already exists): vim_test/test_file
Uploading modified file: vim_test/test_file ... done

This shows the sequence, using vi doing the following actions:

create a new file
modify existing file

sweharris · 2024-12-12T19:12:20Z

So this time I edited existing file ~/OneDrive/tmp/test-card-numbers. The log showed

Dec 12 14:05:51 XXX onedrive[8253]: The operating system sent a deletion notification. Trying to delete this item as requested: tmp/4913
Dec 12 14:05:52 XXX onedrive[8253]: Uploading modified file: tmp/test-card-numbers.txt ... done
Dec 12 14:05:53 XXX onedrive[8253]: The operating system sent a deletion notification. Trying to delete this item as requested: tmp/test-card-numbers.txt
Dec 12 14:05:53 XXX onedrive[8253]: Deleting item from Microsoft OneDrive: tmp/test-card-numbers.txt

OK, I've got a Rocky 9 machine that I configured the same way. Note that if I just installed "vim-minimal" then I see different behaviour. If I install the full "vim" then I see this.

Rocky 9, vim-minimal:

The operating system sent a deletion notification. Trying to delete this item as requested: tmp/.test-card-numbers.txt.swx
The operating system sent a deletion notification. Trying to delete this item as requested: tmp/4913
Moving tmp/test-card-numbers.txt to tmp/test-card-numbers.txt~
The operating system sent a deletion notification. Trying to delete this item as requested: tmp/test-card-numbers.txt~
Uploading modified file: tmp/test-card-numbers.txt ... done

No error there. But once full "vim" has been installed ("sudo dnf install vim") then I see

The operating system sent a deletion notification. Trying to delete this item as requested: tmp/4913
Uploading modified file: tmp/test-card-numbers.txt ... done
The operating system sent a deletion notification. Trying to delete this item as requested: tmp/test-card-numbers.txt
Deleting item from Microsoft OneDrive: tmp/test-card-numbers.txt

So I can replicate on Rocky9 but it needs full vim.

% rpm -qa | grep vim
vim-minimal-8.2.2637-21.el9.x86_64
vim-filesystem-8.2.2637-21.el9.noarch
vim-common-8.2.2637-21.el9.x86_64
vim-enhanced-8.2.2637-21.el9.x86_64

abraunegg · 2024-12-12T19:17:58Z

@sweharris
So is this a 'vim' bug in how it writes out files as compared to 'vi' ?

The 'application' is what is reading / writing / issuing the delete. The operating system via inotify is processing these events in the order that they are received.

sweharris · 2024-12-12T19:23:32Z

The file remains on the local filesystem, so it's not a vim bug. I just think vim-minimal may not be honouring the vimrc directives (you can see it created the backup file with a ~ in the same directory, but with vim-enhanced the vimrc directives told it to store it in a different place).

So it may require vim-enhanced and the ~/.vimrc file to generate the right (bad) sequence of events.

abraunegg · 2024-12-12T19:36:54Z

@sweharris
This might be the same issue as #2586

In the PR, I have added the suggested fix (I was unable to reproduce at the time)

Please can you test PR #3045 running client version onedrive v2.5.3-28-g0e4721e

I am still getting my RHEL 7.9 system workable.

abraunegg · 2024-12-12T19:43:12Z

@sweharris
On Fedora, using the PR:

Sync with Microsoft OneDrive is complete
New items to upload to Microsoft OneDrive: 1
Uploading new file: vim_test/test_file ... done
The operating system sent a deletion notification. Trying to delete this item as requested: vim_test/4913
New items to upload to Microsoft OneDrive: 1
WARNING: Online file integrity failure for: vim_test/test_file
To disable the integrity checking of uploaded files use --disable-upload-validation
Skipping uploading this item as a new file, will upload as a modified file (online file already exists): vim_test/test_file
Uploading modified file: vim_test/test_file ... done

alex@fedora:~/OneDrive/vim_test$ rpm -qa | grep vim
vim-data-9.1.906-1.fc40.noarch
vim-filesystem-9.1.906-1.fc40.noarch
vim-common-9.1.906-1.fc40.x86_64
vim-enhanced-9.1.906-1.fc40.x86_64
vim-minimal-9.1.906-1.fc40.x86_64
alex@fedora:~/OneDrive/vim_test$

sweharris · 2024-12-12T19:58:51Z

Hmm, that looks a lot better. On Rocky9 I now see

The operating system sent a deletion notification. Trying to delete this item as requested: tmp/4913
Uploading modified file: tmp/test-card-numbers.txt ... done

And on RedHat 7 via systemd it also looks good

Dec 12 14:56:54 XXX onedrive[13937]: The operating system sent a deletion notification. Trying to delete this item as requested: tmp/4913
Dec 12 14:56:55 XXX onedrive[13937]: Uploading modified file: tmp/test-card-numbers.txt ... done

That's with

% onedrive --version
onedrive v2.5.3-28-g0e4721e

So I think this is good!

(FWIW, I don't think you need to build 7.9 machine anymore since I could replicate on 9, and demonstrated the fix works for both)

abraunegg · 2024-12-12T20:02:34Z

My testing on RHEL 7.9

[alex@rhel-7-9 vim_test]$ rpm -qa | grep vim
vim-common-7.4.629-8.el7_9.x86_64
vim-enhanced-7.4.629-8.el7_9.x86_64
vim-minimal-7.4.629-8.el7_9.x86_64
vim-filesystem-7.4.629-8.el7_9.x86_64
[alex@rhel-7-9 vim_test]$ cat /etc/redhat-release 
Red Hat Enterprise Linux Server release 7.9 (Maipo)
[alex@rhel-7-9 vim_test]$

RHEL 7.9 'master'

[M] New local file added: vim_test/test_file
New items to upload to Microsoft OneDrive: 1
Total New Data to Upload:        25 Bytes
Uploading new file: vim_test/test_file ... done
[M] Total number of local file(s) added or changed: 1
[M] Local item deleted: vim_test/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] New local file added: vim_test/test_file
New items to upload to Microsoft OneDrive: 1
Total New Data to Upload:        45 Bytes
The file we are attempting to upload as a new file already exists on Microsoft OneDrive: vim_test/test_file
WARNING: Online file integrity failure for: vim_test/test_file
WARNING: Online file integrity failure - Size Mismatch
WARNING: Online file integrity failure - Hash Mismatch
CAUTION: When you upload files to Microsoft OneDrive that uses SharePoint as its backend, Microsoft OneDrive will alter your files post upload.
CAUTION: This will lead to technical differences between the version stored online and your local original file, potentially causing issues with the accuracy or consistency of your data.
CAUTION: Please refer to https://github.com/OneDrive/onedrive-api-docs/issues/935 for further details.
To disable the integrity checking of uploaded files use --disable-upload-validation
Skipping uploading this item as a new file, will upload as a modified file (online file already exists): vim_test/test_file
Uploading modified file: vim_test/test_file ... done
[M] Total number of local file(s) added or changed: 1
[M] Local item deleted: vim_test/test_file
The operating system sent a deletion notification. Trying to delete the item as requested
Deleting item from Microsoft OneDrive: vim_test/test_file

RHEL 7.9 using PR

[M] New local file added: vim_test/test_file
New items to upload to Microsoft OneDrive: 1
Total New Data to Upload:        37 Bytes
Uploading new file: vim_test/test_file ... done
[M] Total number of local file(s) added or changed: 1
[M] Local item deleted: vim_test/4913
The operating system sent a deletion notification. Trying to delete this item as requested: vim_test/4913
Item cannot be deleted from Microsoft OneDrive because it was not found in the local database
[M] New local file added: vim_test/test_file
New items to upload to Microsoft OneDrive: 1
Total New Data to Upload:        65 Bytes
The file we are attempting to upload as a new file already exists on Microsoft OneDrive: vim_test/test_file
WARNING: Online file integrity failure for: vim_test/test_file
WARNING: Online file integrity failure - Size Mismatch
WARNING: Online file integrity failure - Hash Mismatch
CAUTION: When you upload files to Microsoft OneDrive that uses SharePoint as its backend, Microsoft OneDrive will alter your files post upload.
CAUTION: This will lead to technical differences between the version stored online and your local original file, potentially causing issues with the accuracy or consistency of your data.
CAUTION: Please refer to https://github.com/OneDrive/onedrive-api-docs/issues/935 for further details.
To disable the integrity checking of uploaded files use --disable-upload-validation
Skipping uploading this item as a new file, will upload as a modified file (online file already exists): vim_test/test_file
Uploading modified file: vim_test/test_file ... done
[M] Total number of local file(s) added or changed: 1

abraunegg · 2024-12-12T20:03:06Z

@sweharris
Thanks for the confirmation of PR, will mark this as fixed and merge this into 'master'

abraunegg · 2024-12-20T01:55:21Z

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.

sweharris added the Bug Something isn't working label Dec 12, 2024

abraunegg added Investigating More Information Needed Unable to reproduce labels Dec 12, 2024

abraunegg added Fixed and removed Investigating More Information Needed Unable to reproduce labels Dec 12, 2024

abraunegg added this to the v2.5.4 milestone Dec 12, 2024

abraunegg linked a pull request Dec 12, 2024 that will close this issue

Fix that item deleted after events of IN_MOVED_FROM & IN_CLOSE_WRITE #3045

Merged

abraunegg closed this as completed in #3045 Dec 12, 2024

Repository owner locked as resolved and limited conversation to collaborators Dec 20, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Bug: Activity occurs out of order #3044

Bug: Activity occurs out of order #3044

sweharris commented Dec 12, 2024 •

edited by abraunegg

Loading

abraunegg commented Dec 12, 2024

sweharris commented Dec 12, 2024 •

edited

Loading

abraunegg commented Dec 12, 2024

sweharris commented Dec 12, 2024

abraunegg commented Dec 12, 2024

sweharris commented Dec 12, 2024

abraunegg commented Dec 12, 2024

abraunegg commented Dec 12, 2024

sweharris commented Dec 12, 2024 •

edited

Loading

abraunegg commented Dec 12, 2024

abraunegg commented Dec 12, 2024

abraunegg commented Dec 20, 2024

Bug: Activity occurs out of order #3044

Bug: Activity occurs out of order #3044

Comments

sweharris commented Dec 12, 2024 • edited by abraunegg Loading

Describe the bug

Operating System Details

Client Installation Method

OneDrive Account Type

What is your OneDrive Application Version

What is your OneDrive Application Configuration

What is your 'curl' version

Where is your 'sync_dir' located

What are all your system 'mount points'

What are all your local file system partition types

How do you use 'onedrive'

Steps to reproduce the behaviour

Complete Verbose Log Output

Screenshots

Other Log Information or Details

Additional context

abraunegg commented Dec 12, 2024

sweharris commented Dec 12, 2024 • edited Loading

abraunegg commented Dec 12, 2024

sweharris commented Dec 12, 2024

abraunegg commented Dec 12, 2024

sweharris commented Dec 12, 2024

abraunegg commented Dec 12, 2024

abraunegg commented Dec 12, 2024

sweharris commented Dec 12, 2024 • edited Loading

abraunegg commented Dec 12, 2024

RHEL 7.9 'master'

RHEL 7.9 using PR

abraunegg commented Dec 12, 2024

abraunegg commented Dec 20, 2024

sweharris commented Dec 12, 2024 •

edited by abraunegg

Loading

sweharris commented Dec 12, 2024 •

edited

Loading

sweharris commented Dec 12, 2024 •

edited

Loading