--monitor not working as expected #1074

tibmeister · 2020-09-25T01:48:13Z

Bug Report Details

Describe the bug
When making local changes, be it modify, add, or delete of files, change is not reflected in OneDrive online even after waiting for the monitor period, currently set to 60 seconds. Restarting the service (systemd) will pull the deleted files back down instead of deleting them from Online.
No error in logs, runnign with --enable-logging and --verbose from systemd service file.

Application and Operating System Details:

OS: Ubuntu 20.04.1 LTS (Focal Fossa) (kernel 5.4.0-48-generic)
Are you using a headless system (no gui) or with a gui installed? GUI
OneDrive Account Type: Personal
Did you build from source or install from a package? Source
If you installed from source, what is your DMD or LDC compiler version: dmd --version or ldmd2 --version: DMD64 D Compiler v2.090.1
Application configuration: Output of onedrive --display-config

onedrive version                       = v2.4.5-21-g7684c74
Config path                            = /home/jody/.config/onedrive
Config file found in config path       = true
Config option 'check_nosync'           = false
Config option 'sync_dir'               = /home/jody/OneDrive
Config option 'skip_dir'               = 
Config option 'skip_file'              = ~*|.~*|*.tmp
Config option 'skip_dotfiles'          = false
Config option 'skip_symlinks'          = false
Config option 'monitor_interval'       = 60
Config option 'min_notify_changes'     = 1
Config option 'log_dir'                = /var/log/onedrive/
Config option 'classify_as_big_delete' = 1000
Config option 'sync_root_files'        = false
Selective sync 'sync_list' configured  = true
sync_list contents:

Curl Version: Output of curl --version: 7.68.0

Log file filled with:

2020-Sep-24 20:45:51.4294768	Processing 266 OneDrive items to ensure consistent local state due to sync_list being used
2020-Sep-24 20:45:51.4376257	Skipping item - excluded by sync_list config: opti_back
2020-Sep-24 20:45:56.0371465	Processing 263 OneDrive items to ensure consistent local state due to sync_list being used
2020-Sep-24 20:45:56.0448387	Skipping item - excluded by sync_list config: opti_back
2020-Sep-24 20:45:58.9175445	Processing 209 OneDrive items to ensure consistent local state due to sync_list being used
2020-Sep-24 20:45:58.9249836	Skipping item - excluded by sync_list config: opti_back
2020-Sep-24 20:46:01.8453416	Processing 266 OneDrive items to ensure consistent local state due to sync_list being used
2020-Sep-24 20:46:01.8526948	Skipping item - excluded by sync_list config: opti_back
2020-Sep-24 20:46:04.4734091	Processing 250 OneDrive items to ensure consistent local state due to sync_list being used
2020-Sep-24 20:46:04.4808234	Skipping item - excluded by sync_list config: opti_back
2020-Sep-24 20:46:07.5147391	Processing 259 OneDrive items to ensure consistent local state due to sync_list being used
2020-Sep-24 20:46:07.5229097	Skipping item - excluded by sync_list config: opti_back
2020-Sep-24 20:46:11.2459499	Processing 268 OneDrive items to ensure consistent local state due to sync_list being used
2020-Sep-24 20:46:11.2535314	Skipping item - excluded by sync_list config: opti_back
2020-Sep-24 20:46:14.4080581	Processing 280 OneDrive items to ensure consistent local state due to sync_list being used
2020-Sep-24 20:46:14.4155493	Skipping item - excluded by sync_list config: opti_back
2020-Sep-24 20:46:17.2208876	Processing 275 OneDrive items to ensure consistent local state due to sync_list being used
2020-Sep-24 20:46:17.2283162	Skipping item - excluded by sync_list config: opti_back
2020-Sep-24 20:46:24.5085239	Processing 263 OneDrive items to ensure consistent local state due to sync_list being used
2020-Sep-24 20:46:24.5161918	Skipping item - excluded by sync_list config: opti_back
2020-Sep-24 20:46:29.4530798	Processing 269 OneDrive items to ensure consistent local state due to sync_list being used
2020-Sep-24 20:46:29.4606646	Skipping item - excluded by sync_list config: opti_back
2020-Sep-24 20:46:32.4957456	Processing 208 OneDrive items to ensure consistent local state due to sync_list being used
2020-Sep-24 20:46:32.5036579	Skipping item - excluded by sync_list config: opti_back
2020-Sep-24 20:46:35.8913152	Processing 277 OneDrive items to ensure consistent local state due to sync_list being used
2020-Sep-24 20:46:35.8991749	Skipping item - excluded by sync_list config: opti_back
2020-Sep-24 20:46:39.104114	Processing 207 OneDrive items to ensure consistent local state due to sync_list being used
2020-Sep-24 20:46:39.1118329	Skipping item - excluded by sync_list config: opti_back
2020-Sep-24 20:46:41.9972602	Processing 272 OneDrive items to ensure consistent local state due to sync_list being used
2020-Sep-24 20:46:42.0046789	Skipping item - excluded by sync_list config: opti_back
2020-Sep-24 20:46:44.9883803	Processing 274 OneDrive items to ensure consistent local state due to sync_list being used
2020-Sep-24 20:46:44.9958288	Skipping item - excluded by sync_list config: opti_back

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

abraunegg · 2020-09-25T02:00:02Z

@tibmeister
Your configuration of the application does not align to your log output. Please can you provide a verbose debug log as per the support requirements detailed here: https://github.com/abraunegg/onedrive/wiki/Generate-debug-log-for-support

Secondly, is your /home/jody/OneDrive local, or is it a mount point to a network share?

tibmeister · 2020-09-25T02:33:13Z

Very much local drive. Before stopping the service, locally I created a file in /Lightburn called t.txt with no data. After starting the debug log, that file did not upload, and I created a new file, /Lightburn/t2.txt and put some random text in it. Still, no upload.
debug_output.log.gz

abraunegg · 2020-09-25T02:34:39Z

@tibmeister
Unable to reproduce the issue you are seeing as per below:

alex@ubuntu-20-04-LTS:~/OneDrive$ cat /etc/lsb-release 
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=20.04
DISTRIB_CODENAME=focal
DISTRIB_DESCRIPTION="Ubuntu 20.04.1 LTS"
alex@ubuntu-20-04-LTS:~/OneDrive$

Sync with OneDrive is complete
[M] File changed: ./newfile.txt
Uploading differences of ./newfile.txt
Uploading new items of ./newfile.txt
Uploading new file ./newfile.txt ... 
Uploading 100% |oooooooooooooooooooooooooooooooooooooooo| DONE IN 00:00:01                                                                                                                    
done.
Remaining free space on OneDrive: 1088514694518
[M] Item deleted: ./newfile.txt
Deleting item from OneDrive: ./newfile.txt
[M] File changed: ./newfile.txt
Uploading differences of ./newfile.txt
Uploading new items of ./newfile.txt
Uploading new file ./newfile.txt ... 
Uploading 100% |oooooooooooooooooooooooooooooooooooooooo| DONE IN 00:00:01                                                                                                                    
done.
Remaining free space on OneDrive: 1088514694493
[M] File changed: ./.newfile.txt.swx
Uploading differences of ./.newfile.txt.swx
Uploading new items of ./.newfile.txt.swx
Skipping item - has disappeared: ./.newfile.txt.swx
[M] Item deleted: ./.newfile.txt.swx
Item cannot be deleted from OneDrive because not found in the local database
[M] File changed: ./.newfile.txt.swp
Uploading differences of ./.newfile.txt.swp
Uploading new items of ./.newfile.txt.swp
Uploading new file ./.newfile.txt.swp ... 
Uploading 100% |oooooooooooooooooooooooooooooooooooooooo| DONE IN 00:00:01                                                                                                                    
done.
Remaining free space on OneDrive: 1088514690397
[M] Item deleted: ./.newfile.txt.swp
Deleting item from OneDrive: ./.newfile.txt.swp
[M] File changed: ./newfile.txt~
Uploading differences of ./newfile.txt~
Uploading new items of ./newfile.txt~
Skipping item - has disappeared: ./newfile.txt~
[M] File changed: ./newfile.txt
Uploading differences of ./newfile.txt
Processing newfile.txt
The file last modified time has changed
The file content has changed
Uploading modified file newfile.txt ... 
Uploading 100% |oooooooooooooooooooooooooooooooooooooooo| DONE IN 00:00:01                                                                                                                    
done.
Remaining free space on OneDrive: 1088514690347
Uploading new items of ./newfile.txt
[M] Item deleted: ./newfile.txt~
Item cannot be deleted from OneDrive because not found in the local database
[M] File changed: ./.newfile.txt.swp
Uploading differences of ./.newfile.txt.swp
Uploading new items of ./.newfile.txt.swp
Skipping item - has disappeared: ./.newfile.txt.swp
[M] Item deleted: ./.newfile.txt.swp
Item cannot be deleted from OneDrive because not found in the local database

The above log shows:

New file creation and upload to OneDrive
Deleting new file from local filesystem and deleting from OneDrive
New file creation and upload to OneDrive
Modify new file and upload changed file to OneDrive

All of this was performed on Ubuntu 20.04.1 LTS

In addition to the debug log, please can you provide:

Entire contents of your 'config' file
The entire file you are using as the systemd service file on your system

tibmeister · 2020-09-25T02:40:19Z

Just double-checked and no upload was performed even though the log says there was, so there's a disconnect somewhere.
config.gz
onedrive@.service.gz

abraunegg · 2020-09-25T02:43:57Z

Very much local drive. Before stopping the service, locally I created a file in /Lightburn called t.txt with no data. After starting the debug log, that file did not upload, and I created a new file, /Lightburn/t2.txt and put some random text in it. Still, no upload.
debug_output.log.gz

Also, in the debug log provided, there is no entry for either t.txt or t2.txt

Please can you generate the debug log whilst replicating the issue.

Below is an example using your config as garnished from your current debug log file - no issue in creating and uploading a file:

Monitor directory: .
Starting a sync with OneDrive
Applying changes of Path ID: 01WIXGO5V6Y2GOVW7725BZO354PWSELRRZ
Updated Remaining Free Space: 1088514687760
Uploading differences of ~/OneDrive
Processing .
The directory has not changed
Processing random_files
Processing random_images
Processing random_videos
Processing newfile.txt
Uploading new items of ~/OneDrive
Skipping item - excluded by sync_list config: ./random_videos
Skipping item - excluded by sync_list config: ./newfile.txt
Skipping item - excluded by sync_list config: ./random_images
Skipping item - excluded by sync_list config: ./random_files
Applying changes of Path ID: 01WIXGO5V6Y2GOVW7725BZO354PWSELRRZ
Updated Remaining Free Space: 1088514687760
Sync with OneDrive is complete
Monitor directory: ./Lightburn
[M] Directory created: ./Lightburn
Uploading differences of ./Lightburn
Uploading new items of ./Lightburn
OneDrive Client requested to create remote path: ./Lightburn
The requested directory to create was not found on OneDrive - creating remote directory: ./Lightburn
Successfully created the remote directory ./Lightburn on OneDrive
[M] File changed: Lightburn/t.txt
Uploading differences of Lightburn/t.txt
Uploading new items of Lightburn/t.txt
Uploading new file Lightburn/t.txt ... 
Uploading 100% |oooooooooooooooooooooooooooooooooooooooo| DONE IN 00:00:01                                                                                                                    
done.
Remaining free space on OneDrive: 1088514687744

tibmeister · 2020-09-25T02:49:12Z

I created t2.txt while the debug log process was running. I am noticing in the regular logs (pasted in original post) that the number of items being processed in the one folder is constantly changing. Is this something you expect to see based on your experience with the Graph API? I have not messed with the Graph API so not very familiar with some of it's potential oddities.

abraunegg · 2020-09-25T02:53:23Z

@tibmeister

I created t2.txt while the debug log process was running.

t2.txt does not appear anywhere within the log file at all. There is no entry in the file provided.

I am noticing in the regular logs (pasted in original post) that the number of items being processed in the one folder is constantly changing. Is this something you expect to see based on your experience with the Graph API? I have not messed with the Graph API so not very familiar with some of it's potential oddities.

This is normal:

Processing 263 OneDrive items ...

The Graph API bundles 'items' on OneDrive into change set, where each changeset can have between 200 and 300 items.

tibmeister · 2020-09-25T02:56:41Z

I was suspecting that, since I know that directory has way more than 300 files. One thing, since that directory is not in my sync_list, why are we processing it at all? Is there something in the config file I am missing?

tibmeister · 2020-09-25T03:02:17Z

I even get this, so somethings wonkey:

onedrive --display-sync-status --verbose
Using 'user' Config Dir: /home/jody/.config/onedrive
Using 'system' Config Dir: /etc/onedrive
Configuration file successfully loaded
Initializing the OneDrive API ...
Configuring Global Azure AD Endpoints
Opening the item database ...
All operations will be performed in: /home/jody/OneDrive
Application version: v2.4.5-21-g7684c74
Account Type: personal
Default Drive ID: bbf6c5fb8d8a889e
Default Root ID: BBF6C5FB8D8A889E!179
Remaining Free Space: 164306529842
Fetching details for OneDrive Root
OneDrive Root exists in the database
Initializing the Synchronization Engine ...
Local directory is out of sync with OneDrive

abraunegg · 2020-09-25T03:04:05Z

@tibmeister

I was suspecting that, since I know that directory has way more than 300 files. One thing, since that directory is not in my sync_list, why are we processing it at all? Is there something in the config file I am missing?

Unfortunately, due to how the Graph API handles objects, all objects returned from OneDrive need to be iterated through to determine a match. It is a gap in the API to provide a more granular way to iterate through folders and items to determine matches.

abraunegg · 2020-09-25T03:09:28Z

@tibmeister

I even get this, so somethings wonkey

onedrive --display-sync-status --verbose

OK .. start from scratch.

Disable all 'systemd' services for the OneDrive client.
Confirm all 'onedrive' processes are stopped
Run a single run of: onedrive --synchronize --verbose --resync
Confirm that things are in-sync: onedrive --display-sync-status --verbose
Run another single sync: onedrive --synchronize --verbose
Confirm that things are in-sync: onedrive --display-sync-status --verbose

If everything is in-sync:

Run monitor sync: onedrive --monitor --verbose
Add a new file to a directory included in your 'sync_list'

tibmeister · 2020-09-25T03:12:08Z

Ok, this will take some time, last count I have somewhere around 300k+ files out there.

Actually, the one directory in the logs above, opti_back, has 460k files itself. So breaking this into 200~300 chunks will take most of the night, if not longer.

abraunegg · 2020-09-25T21:11:05Z

@tibmeister

Ok, this will take some time, last count I have somewhere around 300k+ files out there.

Actually, the one directory in the logs above, opti_back, has 460k files itself. So breaking this into 200~300 chunks will take most of the night, if not longer.

OK .. it also might be worth setting up a 'new' OneDrive personal account to ensure the client is doing what you want, without having to process that volume of files. Need to find out / work out why logs are not showing files being created / moved / deleted or not even showing up in the application debug log file. By not having so many 'read' files to go through will make that a lot simpler.

Further to this, this setting in your current configuration is not correct:

monitor_interval = "60"

What this means is every 60 seconds it is going to query OneDrive for changes. How often is your data being changed on OneDrive - by using Office 365 - surely that data is not changing every 60 seconds? If the process of checking all your files takes several hours, this really pointless to kick it off again so quickly once it completes if your rate of change is very low or all your data changes are local.

The default for this is 300 seconds, and should be 'tuned' based on the rate of data change performed by manipulating data or files on OneDrive itself. I potentially suspect that you might even be better off increasing that value to '43200' to perform a OneDrive check 12 hours after the completion of the previous scan.

norbusan · 2020-09-25T23:36:55Z

Could this be an issue with kernel limits for inotify? It probably depends also on the number of directories, but with this amount of files I guess there kernel infra for watching files and notifying the application might be overloaded.

abraunegg · 2020-09-25T23:59:07Z

Could this be an issue with kernel limits for inotify? It probably depends also on the number of directories, but with this amount of files I guess there kernel infra for watching files and notifying the application might be overloaded.

Could be, however there should be then the warnings generated re inotify not having enough file descriptors .. and in the debug log there is no reference to that nor any inotify events at all.

tibmeister · 2020-09-28T16:45:12Z

Sorry for the delay, got busy over the last few days and got pulled away.

So, after the full sync completed, I was able to perform CRUD operations on files and folders and anything local instantly replicated up, and remote items replicated down according to the schedule (60 seconds).

It seems that while performing a full sync, there is no filesystem notification that occurs, or it get's set into a queue and as long as the full sync finished and the service isn't restarted, the notification is processed. There also is no remote changes replicated. I was able to verify that by starting a full sync, making a change in the middle, and after the sync completed watched the change happen. I repeated the same but interrupted the service in the middle, and the notification never got processed.
Also, I noticed that the service seems to perform a full sync on it's own on some periodic interval that I haven't discerned yet, which means that while the full sync happens, no changes are replicated.

Not sure if the service is a single threaded application or if you could move the sync and ionotify functions into separate threads.

As of now, I would say that things are syncing as expected, as long as I don't make changes during this periodic full sync that occurs. Since I do have a rather large amount of files in my OneDrive, the full sync takes about 3 hours each time it runs.

abraunegg · 2020-09-28T21:50:58Z

@tibmeister

It seems that while performing a full sync, there is no filesystem notification that occurs

Correct. This is due to the OneDrive API and how events are currently handled. These local events however are queued and handled post syncing the data from OneDrive.

This is why it is very important to set the monitor_interval option to a relevant value. Setting this to '60' as per your original configuration is a really bad idea. This is also the reason why it is set to 300 seconds, and really, should be much greater if you have a lot of data on OneDrive to process. In your specific instance, having something process for ~3hrs, wait 60 seconds and then re-perform that same step is overkill. Unless your 'remote' rate of data change really is that frequent, fine, but I seriously would change 'monitor_interval' to 43200 (12 hours) in your scenario or even greater. Even if it is that frequent, changes made online during that sync, will not be picked up until after the completion of the current sync & when then next one actually starts.

Please also note, Microsoft OneDrive has performance limitations if you have > 300K files stored on OneDrive. This is something that I cannot fix. Microsoft has acknowledged in the past that this performance degradation starts at the 100K file stored level.

Not sure if the service is a single threaded application or if you could move the sync and ionotify functions into separate threads.

Refer to #232 for further details

Closing issue as not a bug or issue

tibmeister · 2020-09-29T03:37:27Z

Can multiple —single-directory arguments be passed on the command line? I think this may be the better approach. I was hoping the sync_list would only look at the folders entered for sync, or if there could be a way to run in a mode to exclude everything except explicitly defined sync_list. Kinda like doing selective sync on the Windows client. This would take the load of the service my not scanning everything but rather just saying “give me folder x” and “give me folder y”.
As for the file count, on Windows the on-demand helps since I only have a very small subset of the files actually downloaded, and on my Mac I use selective sync so the others are ignored. So I haven’t had any real issues with the file limit since I don’t have 1TB laying around to sync my entire OneDrive to.

github-actions · 2021-05-27T23:29:04Z

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.

abraunegg added More Information Needed Waiting on Response labels Sep 25, 2020

abraunegg added the Unable to reproduce label Sep 25, 2020

abraunegg closed this as completed Sep 28, 2020

abraunegg added Not a bug and removed More Information Needed Waiting on Response labels Sep 28, 2020

github-actions bot locked as resolved and limited conversation to collaborators May 27, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

--monitor not working as expected #1074

--monitor not working as expected #1074

tibmeister commented Sep 25, 2020 •

edited by abraunegg

Loading

abraunegg commented Sep 25, 2020

tibmeister commented Sep 25, 2020

abraunegg commented Sep 25, 2020

tibmeister commented Sep 25, 2020

abraunegg commented Sep 25, 2020

tibmeister commented Sep 25, 2020

abraunegg commented Sep 25, 2020 •

edited

Loading

tibmeister commented Sep 25, 2020

tibmeister commented Sep 25, 2020 •

edited by abraunegg

Loading

abraunegg commented Sep 25, 2020

abraunegg commented Sep 25, 2020

tibmeister commented Sep 25, 2020 •

edited

Loading

abraunegg commented Sep 25, 2020

norbusan commented Sep 25, 2020

abraunegg commented Sep 25, 2020

tibmeister commented Sep 28, 2020

abraunegg commented Sep 28, 2020

tibmeister commented Sep 29, 2020

github-actions bot commented May 27, 2021

--monitor not working as expected #1074

--monitor not working as expected #1074

Comments

tibmeister commented Sep 25, 2020 • edited by abraunegg Loading

Bug Report Details

abraunegg commented Sep 25, 2020

tibmeister commented Sep 25, 2020

abraunegg commented Sep 25, 2020

tibmeister commented Sep 25, 2020

abraunegg commented Sep 25, 2020

tibmeister commented Sep 25, 2020

abraunegg commented Sep 25, 2020 • edited Loading

tibmeister commented Sep 25, 2020

tibmeister commented Sep 25, 2020 • edited by abraunegg Loading

abraunegg commented Sep 25, 2020

abraunegg commented Sep 25, 2020

tibmeister commented Sep 25, 2020 • edited Loading

abraunegg commented Sep 25, 2020

norbusan commented Sep 25, 2020

abraunegg commented Sep 25, 2020

tibmeister commented Sep 28, 2020

abraunegg commented Sep 28, 2020

tibmeister commented Sep 29, 2020

github-actions bot commented May 27, 2021

tibmeister commented Sep 25, 2020 •

edited by abraunegg

Loading

abraunegg commented Sep 25, 2020 •

edited

Loading

tibmeister commented Sep 25, 2020 •

edited by abraunegg

Loading

tibmeister commented Sep 25, 2020 •

edited

Loading