Takes an hour or more to upload to the server

[helderdaniel]

Hi,

I have experienced this issue since I installed the application several days ago.

Files take too long to be updated to the server, an hour, some times more. I am not sure if this is expected. From the Readme I noticed that remote changes are delayed:

"While local changes are uploaded right away, remote changes are delayed"

but I assumed that local changes are uploaded right away.

I have a Onedrive Business with 40GB of data.

To reproduce the issue, the service was started and the file "Sample2.txt" was created at the root at 6:11 AM.

hdaniel@Lucas:/storage/OneDrive$ ls -l
(...)
-rwxrwxrwx 1 root root    5 Jan 23 06:11  Sample2.txt
(...)

Logs show that the file was uploaded at 7:10, 59 minutes after being created:

hdaniel@Lucas:~$ journalctl --user-unit onedrive -f 
(...)
Jan 23 05:56:26 Lucas onedrive[2772]: Syncing changes from OneDrive ...
Jan 23 07:10:01 Lucas onedrive[2772]: Uploading file ./Sample2.txt ...
Jan 23 07:10:04 Lucas onedrive[2772]: [314B blob data]
Jan 23 07:10:04 Lucas onedrive[2772]:  done.
Jan 23 07:11:12 Lucas onedrive[2772]: Syncing changes from OneDrive ...

Application and Operating System Details:

• OS: Output of uname -a & provide your OS & version (CentOS 6.x, Ubuntu 18.x etc)

  Linux Lucas 4.15.0-43-generic #46-Ubuntu SMP Thu Dec 6 14:45:28 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

• Are you using a headless system (no gui) or with a gui installed? No GUI, started service with:

systemctl --user start onedrive

and "onedrive.service" is:

hdaniel@Lucas:~$ cat onedrive/onedrive.service
[Unit]
Description=OneDrive Free Client
Documentation=https://github.com/abraunegg/onedrive
After=network-online.target
Wants=network-online.target

[Service]
ExecStart=/usr/local/bin/onedrive --monitor 
Restart=on-failure
RestartSec=3

[Install]
WantedBy=default.target

• OneDrive Account Type Business

• DMD or LDC compiler version dmd --version or ldmd2 --version DMD64 D Compiler v2.084.0 Copyright (C) 1999-2018 by The D Language Foundation, All Rights Reserved written by Walter Bright

• Application configuration: Output of onedrive --display-config

  onedrive version                    = v2.2.4-22-g1d902a5
  Config path                         = /home/hdaniel/.config/onedrive
  Config file found in config path    = true
  Config option 'sync_dir'            = /storage/OneDrive
  Config option 'skip_file'           = ~*
  Config option 'skip_symlinks'       = false
  Config option 'monitor_interval'    = 30
  Config option 'log_dir'             = /var/log/onedrive/
  Selective sync configured           = false

• Curl Version: Output of curl --version

  curl 7.58.0 (x86_64-pc-linux-gnu) libcurl/7.58.0 OpenSSL/1.1.0g zlib/1.2.11 libidn2/2.0.4 libpsl/0.19.1 (+libidn2/2.0.4) nghttp2/1.30.0 librtmp/2.3
  Release-Date: 2018-01-24
  Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtmp rtsp smb smbs smtp smtps telnet tftp 
  Features: AsynchDNS IDN IPv6 Largefile GSS-API Kerberos SPNEGO NTLM NTLM_WB SSL libz TLS-SRP HTTP2 UnixSockets HTTPS-proxy PSL 

Thanks, Helder

[abraunegg]

@helderdaniel

I have a Onedrive Business with 40GB of data.

How many files & folders in the entire tree?

Config option 'monitor_interval' = 30

Why is this set to 30 seconds? Essentially you have a never ending loop checking each database entry and file without any rest. I suspect with a significant number of files this will take a significant amount of time to process. Unless you have SIGNIFICANT rate of change occurring locally & remotely, setting to 30 seconds is way too short - even the application 'default' carried over from 'skilion' version is too short IMHO @ 45 seconds and should be starting at ~300.

To reproduce the issue, the service was started and the file "Sample2.txt" was created at the root at 6:11 AM. Logs show that the file was uploaded at 7:10, 59 minutes after being created

The most likely cause of this is the client was processing through each & every object in the database & was too busy to upload the new file at the point in time when it was created.

Also with 40GB of files, you are probably also hitting the fs.inotify.max_user_watches for monitor mode.

Do your logs show any warning about fs.inotify.max_user_watches ?

[helderdaniel]

There are 19439 directories and 88599 files.

$> sysctl fs.inotify

shows:

fs.inotify.max_queued_events = 16384
fs.inotify.max_user_instances = 256
fs.inotify.max_user_watches = 200000

I did not found any warning about fs.inotify.max_user_watches in system log

$> dmesg | grep max_user_watches

returns nothing. Also nothing on systemd journal. Both return nothing:

$> journalctl --user | grep max_user $> journalctl --system | grep max_user

By default:

Config option 'monitor_interval' = 45

hdaniel@Lucas:~$ cat onedrive/config 
#Directory where the files will be synced
sync_dir = "~/OneDrive"
#Skip files and directories that match this pattern
skip_file = "~*"
#Wait time (seconds) between sync operations in monitor mode
monitor_interval = "45"

I just change it to 30 to try to speed up upload. But I will test it with 300 seconds.

As you said:

"The most likely cause of this is the client was processing through each & every object in the database & was too busy to upload the new file at the point in time when it was created."

So to get a verbose log, the service was stopped:

onedrive --monitor --enable-logging --verbose

and the application started manually:

onedrive --monitor --enable-logging --verbose

Another file was created, "Sample3.txt", at 16:46 PM

hdaniel@Lucas:~$ ls /storage/OneDrive -l
(...)
-rwxrwxrwx 1 root root    5 Jan 23 06:11  Sample2.txt
-rwxrwxrwx 1 root root    7 Jan 23 16:46  Sample3.txt
(..)

Logs show that this file was uploaded at 18:03 PM, 77 minutes after being created. The application seems to continuosly monitor if there is any change in files and directories, until finally uploads the file.

hdaniel@Lucas:~$ cat /var/log/onedrive/Helder\ Daniel.onedrive.log 
2019-Jan-23 16:42:18.7294659 Initializing the OneDrive API ...
2019-Jan-23 16:42:19.1250425 Opening the item database ...
2019-Jan-23 16:42:19.1302491 All operations will be performed in: /storage/OneDrive
2019-Jan-23 16:42:19.2142386 Initializing the Synchronization Engine ...
2019-Jan-23 16:42:20.661105 Account Type: business
2019-Jan-23 16:42:20.6612384 Default Drive ID: b!nJQI4UfVkkuT3DscKMYwgTdEq3YfLs5MoqnjdcN889m8trHuJL_7To6pfkM0De48
2019-Jan-23 16:42:20.6612994 Default Root ID: 01TUY2TI56Y2GOVW7725BZO354PWSELRRZ
2019-Jan-23 16:42:20.6613565 Remaining Free Space: 1026241150914
2019-Jan-23 16:42:20.6614064 Fetching details for OneDrive Root
2019-Jan-23 16:42:20.9514325 OneDrive Root exists in the database
2019-Jan-23 16:42:20.9830996 Initializing monitor ...
2019-Jan-23 16:42:20.9832563 OneDrive monitor interval (seconds): 30
2019-Jan-23 16:42:20.9836259 Monitor directory: .
2019-Jan-23 16:42:20.9843185 Monitor directory: ./00-FotosVideos
(...)
2019-Jan-23 18:03:29.125695 Processing 5ixCbzOjIXhSOauayBjP3D
2019-Jan-23 18:03:29.1260058 The directory has not changed
2019-Jan-23 18:03:29.3684897 Processing 1DaiiJvyk4EDk4ewUlCH3Q.pdf
2019-Jan-23 18:03:29.3689557 The file has not changed
2019-Jan-23 18:03:29.3689842 Processing data
2019-Jan-23 18:03:29.3691973 The directory has not changed
2019-Jan-23 18:03:29.6114875 Processing config.js
2019-Jan-23 18:03:29.6119197 The file has not changed
2019-Jan-23 18:03:29.6119507 Processing data.js
2019-Jan-23 18:03:29.6122355 The file has not changed
2019-Jan-23 18:03:29.6122652 Processing additional-pages.js
2019-Jan-23 18:03:29.612554 The file has not changed
2019-Jan-23 18:03:29.6125832 Uploading new items of .
2019-Jan-23 18:03:36.2375647 Uploading file ./Sample3.txt ... done.
2019-Jan-23 18:03:36.2437715 Remaining free space: 1026241150907
(...)

[abraunegg]

@helderdaniel

There are 19439 directories and 88599 files.

The sheer volume of files & folders that it needs to process during the 'sync' operation is what is taking the time & consuming CPU / resources to compute as currently the application is single threaded & processes each file in sequence every sync.

But I will test it with 300 seconds.

All this will do is 'delay' the 'sync' process by 300 seconds:

sync -> monitor_interval -> sync -> monitor_interval ......... and repeat until the service is stopped.

A better value is to work out your 'rate of change' - if it is say 3 or 4 local / remote files an hour, there is no reason to be checking (syncing) every 45 seconds - a monitor_interval of 1800 or even 3600 may be better, however:

sync (7200 seconds or however long it takes) -> monitor_interval (3600) -> sync (7200 seconds or however long it takes) -> monitor_interval (3600) -> sync (7200 seconds or however long it takes) -> monitor_interval (3600) .......

This would mean that you could end up with 12 new files over a 3 hour window on OneDrive before they are picked up and synced to your local system.

The other interesting aspect here is that from your log extract - there is no "monitor" event for the new file creation .. or is there in your log?

[abraunegg]

@helderdaniel Can you also clearly articulate:

• The steps you are using to create your test files - are you creating them remotely 'on the box & in the directory'?
• If the files are being created say on an NFS / CIFS / Samba mount - ie - what is the local mount point for your local sync directory

[helderdaniel]

The only events found in the log, tagged as Monitor, are for folders:

(...)
2019-Jan-23 16:42:27.7919415 Monitor directory: ./Works/Proj. Carlos/Graph ISOmorphism/C
2019-Jan-23 16:42:27.7926871 Monitor directory: ./Works/Proj. Carlos/Graph ISOmorphism/IEEE
2019-Jan-23 16:42:27.7929466 Monitor directory: ./Works/Proj. Carlos/Graph ISOmorphism/Matlab
2019-Jan-23 16:42:27.7934354 Monitor directory: ./Works/Proj. Carlos/Graph ISOmorphism/Nauty
(...)

My previous tests were just with files "Sample2.txt" and "Sample3.txt" in the root folder of Onedrive. I am creating the files only on the local sync directory and waiting them to be uploaded to onedrive (to the cloud).

The local sync directory: /storage/onedrive is located on an NTFS partition, mounted on /storage:

from: /etc/fstab:
UUID=7323E5E32CF68623   /storage    ntfs-3g defaults,locale=en_GB.UTF-8 00

hdaniel@Lucas:~$ ls /storage/OneDrive/ -ld
drwxrwxrwx 1 root root 4096 Jan 23 20:28 '/storage/OneDrive/'

[abraunegg]

@helderdaniel OK ... so the inotify are not appearing for new files / folders for you. The reason for this is the userspace use of ntfs-3g as, based on my current understanding and reading (happy to be corrected if wrong), does not support inotify events. This explains why:

• No inotify trigger recorded for new file, thus no immediate upload
• Why the file was uploaded as a "new file" when found as part of the next "sync"

This issue you are seeing is not a bug with onedrive but the manifestation of an issue resulting from the use of ntfs-3g to mount your volume.

The only real fixes for this that I can see are:

• Implement inotify support for ntfs-3g
• Rework how onedrive currently processes elements in the local cache database to validate if any local change has been made, thus quickening the 'scan' process.

[helderdaniel]

ok,

So if the onedrive local folder is stored on another kind of filesystem, say ext4, inotify will trigger an immediate upload.

[abraunegg]

ok,

So if the onedrive local folder is stored on another kind of filesystem, say ext4, inotify will trigger an immediate upload.

Correct

[helderdaniel]

And that is also why remote changes are delayed, right? There is no notification of remote changes to trigger an immediate action.

[abraunegg]

And that is also why remote changes are delayed, right? There is no notification of remote changes to trigger an immediate action.

Correct - remote changes are only detected at the start of a sync process and then processed accordingly

[abraunegg]

Closing issue as this relates to ntfs-3g mounting an external NTFS drive/partition & inotify not supported inside ntfs-3g

[lock[bot]]

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.