abraunegg / onedrive

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

Bug: Issues with onedrive 2.5.0-rc1 #2666

Closed gitbls closed 4 months ago

gitbls commented 4 months ago

Describe the bug

I built 2.5.0-rc1 on Debian 12 X64. Did

onedrive --sync --upload-only --dry-run --enable-logging

which took almost 4 hours to complete. (Using the current released version without --dry-run takes 15-20 minutes).

It also reported:

New items to upload to OneDrive: 81278 

which surprised me given that a sync was done a few hours prior and everything in onedrive cloud was up to date.

There were several of these errors:

Skipping uploading this item as a new file, will upload as a modified file (online file already exists): ./Backups/Pictures/RSA/2002Picnic/P9220027.JPG
The local item is out-of-sync with OneDrive, renaming to preserve existing file and prevent local data loss: ./Backups/Pictures/RSA/2002Picnic/P9220027.JPG -> ./Backups/Pictures/RSA/2002Picnic/P9220027-mondo.JPG

and a couple of this error:

ERROR: Microsoft OneDrive API returned an error with the following message:
Error Message:    HTTP request returned status code 502 ()
Error Reason:
Error Code:       UnknownError
Error Timestamp:  2024-03-16T17:51:34
API Request ID:   d1639031-705e-48c3-a866-c0cae6b51e98

Operating System Details

Debian 12 x64
Linux mondo 6.1.0-18-amd64 #1 SMP PREEMPT_DYNAMIC Debian 6.1.76-1 (2024-02-01) x86_64 GNU/Linux
Distributor ID: Debian
Description:    Debian GNU/Linux 12 (bookworm)
Release:        12
Codename:       bookworm

Client Installation Method

From Source

OneDrive Account Type

Personal

What is your OneDrive Application Version

2.5.0-rc1

What is your OneDrive Application Configuration

Reading configuration file: /home/blsodb/.config/onedrive/config
Configuration file successfully loaded
onedrive version                             = onedrive v2.5.0-rc1
Config path                                  = /home/blsodb/.config/onedrive
Config file found in config path             = true
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|~*|*.ini
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 '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.0-rc1
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'                 = 240
Config option 'ip_protocol_version'          = 0
Config option 'threads'                      = 8

Selective sync 'sync_list' configured        = false

Config option 'sync_business_shared_items'   = false
Config option 'Shared Files Directory'       = /home/blsodb/OneDrive/Files Shared With Me

Config option 'webhook_enabled'              = false

What is your 'curl' version

curl 7.88.1 (x86_64-pc-linux-gnu) libcurl/7.88.1 OpenSSL/3.0.11 zlib/1.2.13 brotli/1.0.9 zstd/1.5.4 libidn2/2.3.3 libpsl/0.21.2 (+libidn2/2.3.3) libssh2/1.10.0 nghttp2/1.52.0 librtmp/2.3 OpenLDAP/2.5.13
Release-Date: 2023-02-20, security patched: 7.88.1-10+deb12u5
Protocols: dict file ftp ftps gopher gophers http https imap imaps ldap ldaps mqtt pop3 pop3s rtmp rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS brotli GSS-API HSTS HTTP2 HTTPS-proxy IDN IPv6 Kerberos Largefile libz NTLM NTLM_WB PSL SPNEGO SSL threadsafe TLS-SRP UnixSockets zstd

Where is your 'sync_dir' located

Local

What are all your system 'mount points'

sysfs on /sys type sysfs (rw,nosuid,nodev,noexec,relatime)
proc on /proc type proc (rw,nosuid,nodev,noexec,relatime)
udev on /dev type devtmpfs (rw,nosuid,relatime,size=16262452k,nr_inodes=4065613,mode=755,inode64)
devpts on /dev/pts type devpts (rw,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=000)
tmpfs on /run type tmpfs (rw,nosuid,nodev,noexec,relatime,size=3257140k,mode=755,inode64)
/dev/nvme0n1p2 on / type ext4 (rw,relatime,errors=remount-ro)
securityfs on /sys/kernel/security type securityfs (rw,nosuid,nodev,noexec,relatime)
tmpfs on /dev/shm type tmpfs (rw,nosuid,nodev,inode64)
tmpfs on /run/lock type tmpfs (rw,nosuid,nodev,noexec,relatime,size=5120k,inode64)
cgroup2 on /sys/fs/cgroup type cgroup2 (rw,nosuid,nodev,noexec,relatime,nsdelegate,memory_recursiveprot)
pstore on /sys/fs/pstore type pstore (rw,nosuid,nodev,noexec,relatime)
efivarfs on /sys/firmware/efi/efivars type efivarfs (rw,nosuid,nodev,noexec,relatime)
bpf on /sys/fs/bpf type bpf (rw,nosuid,nodev,noexec,relatime,mode=700)
systemd-1 on /proc/sys/fs/binfmt_misc type autofs (rw,relatime,fd=30,pgrp=1,timeout=0,minproto=5,maxproto=5,direct,pipe_ino=23331)
hugetlbfs on /dev/hugepages type hugetlbfs (rw,relatime,pagesize=2M)
mqueue on /dev/mqueue type mqueue (rw,nosuid,nodev,noexec,relatime)
debugfs on /sys/kernel/debug type debugfs (rw,nosuid,nodev,noexec,relatime)
tracefs on /sys/kernel/tracing type tracefs (rw,nosuid,nodev,noexec,relatime)
configfs on /sys/kernel/config type configfs (rw,nosuid,nodev,noexec,relatime)
ramfs on /run/credentials/systemd-sysctl.service type ramfs (ro,nosuid,nodev,noexec,relatime,mode=700)
fusectl on /sys/fs/fuse/connections type fusectl (rw,nosuid,nodev,noexec,relatime)
ramfs on /run/credentials/systemd-sysusers.service type ramfs (ro,nosuid,nodev,noexec,relatime,mode=700)
ramfs on /run/credentials/systemd-tmpfiles-setup-dev.service type ramfs (ro,nosuid,nodev,noexec,relatime,mode=700)
systemd-1 on /ssd type autofs (rw,relatime,fd=51,pgrp=1,timeout=3600,minproto=5,maxproto=5,direct,pipe_ino=23434)
nfsd on /proc/fs/nfsd type nfsd (rw,relatime)
/dev/sda1 on /issd type ext4 (rw,noatime)
/dev/sda1 on /vhd type ext4 (rw,noatime)
/dev/nvme0n1p1 on /boot/efi type vfat (rw,relatime,fmask=0077,dmask=0077,codepage=437,iocharset=ascii,shortname=mixed,utf8,errors=remount-ro)
/dev/sdd1 on /h type ext4 (rw,noatime)
/dev/sdc1 on /g type ext4 (rw,noatime)
/dev/sdb1 on /f type ext4 (rw,noatime)
/dev/sdc1 on /evhd type ext4 (rw,noatime)
/dev/sdb1 on /home type ext4 (rw,noatime)
/dev/sdb1 on /kits type ext4 (rw,noatime)
/dev/sdb1 on /l type ext4 (rw,noatime)
/dev/sdb1 on /music type ext4 (rw,noatime)
/dev/sdb1 on /pictures type ext4 (rw,noatime)
/dev/sdb1 on /rpi type ext4 (rw,noatime)
/dev/sdb1 on /scandocs type ext4 (rw,noatime)
/dev/sdb1 on /videos type ext4 (rw,noatime)
/dev/sdb1 on /home/blsodb/OneDrive/Backups/Music/Albums type ext4 (rw,noatime)
/dev/sdb1 on /f/home/blsodb/OneDrive/Backups/Music/Albums type ext4 (rw,noatime)
/dev/sdb1 on /home/blsodb/OneDrive/Backups/Pictures type ext4 (rw,noatime)
/dev/sdb1 on /f/home/blsodb/OneDrive/Backups/Pictures type ext4 (rw,noatime)
/dev/sdb1 on /home/blsodb/OneDrive/Backups/Scandocs type ext4 (rw,noatime)
/dev/sdb1 on /f/home/blsodb/OneDrive/Backups/Scandocs type ext4 (rw,noatime)
/dev/sdb1 on /home/blsodb/OneDrive/Backups/Videos type ext4 (rw,noatime)
/dev/sdb1 on /f/home/blsodb/OneDrive/Backups/Videos type ext4 (rw,noatime)
ramfs on /run/credentials/systemd-tmpfiles-setup.service type ramfs (ro,nosuid,nodev,noexec,relatime,mode=700)
sunrpc on /run/rpc_pipefs type rpc_pipefs (rw,relatime)
binfmt_misc on /proc/sys/fs/binfmt_misc type binfmt_misc (rw,nosuid,nodev,noexec,relatime)
tmpfs on /run/user/2400 type tmpfs (rw,nosuid,nodev,relatime,size=3257136k,nr_inodes=814284,mode=700,uid=2400,gid=100,inode64)
tmpfs on /run/user/2100 type tmpfs (rw,nosuid,nodev,relatime,size=3257136k,nr_inodes=814284,mode=700,uid=2100,gid=2100,inode64)
tmpfs on /run/user/0 type tmpfs (rw,nosuid,nodev,relatime,size=3257136k,nr_inodes=814284,mode=700,inode64)

What are all your local file system partition types

NAME        FSTYPE FSVER LABEL UUID                                 FSAVAIL FSUSE% MOUNTPOINTS
sda                                                                                
└─sda1      ext4   1.0         3a22e794-ff5d-47d8-997c-3a08624a1a97  424.9G    49% /vhd
                                                                                   /issd
sdb                                                                                
└─sdb1      ext4   1.0         a99d207e-0a52-4f85-afdc-eb4f11fda4e4    2.1T    36% /f/home/blsodb/OneDrive/Backups/Videos
                                                                                   /home/blsodb/OneDrive/Backups/Videos
                                                                                   /f/home/blsodb/OneDrive/Backups/Scandocs
                                                                                   /home/blsodb/OneDrive/Backups/Scandocs
                                                                                   /f/home/blsodb/OneDrive/Backups/Pictures
                                                                                   /home/blsodb/OneDrive/Backups/Pictures
                                                                                   /f/home/blsodb/OneDrive/Backups/Music/Albums
                                                                                   /home/blsodb/OneDrive/Backups/Music/Albums
                                                                                   /videos
                                                                                   /scandocs
                                                                                   /rpi
                                                                                   /pictures
                                                                                   /music
                                                                                   /l
                                                                                   /kits
                                                                                   /home
                                                                                   /f
sdc                                                                                
└─sdc1      ext4   1.0         b3b7295e-69b9-435b-8433-80af30f0c0e7    1.4T    55% /evhd
                                                                                   /g
sdd                                                                                
└─sdd1      ext4   1.0         256faf0e-b7e4-42d6-b23f-4939c8adaf97    719G    56% /h
sde                                                                                
nvme0n1                                                                            
├─nvme0n1p1 vfat   FAT32       FA37-0573                             505.2M     1% /boot/efi
├─nvme0n1p2 ext4   1.0         678df82e-5fe1-4b95-a263-e8ee908e2e6d  427.3G     1% /
└─nvme0n1p3 swap   1           684706e8-94c9-497a-8e38-3e430d0eac00                [SWAP]

How do you use 'onedrive'

onedrive is run in a systemd timer-enabled script nightly. The script does the command:

onedrive --sync --upload-only --dry-run --enable-logging 

Steps to reproduce the behaviour

I'm sure I can easily reproduce it here by switching to the new verison of onedrive with the above command.

Complete Verbose Log Output

I could provide this by doing another run, but there is a huge amount of personal information that I would need to redact (directory names, file names, etc).

Please let me know if you need this after you've reviewed the above information.

Screenshots

No response

Other Log Information or Details

No response

Additional context

No response

abraunegg commented 4 months ago

@gitbls Thanks for raising these questions and testing RC1.

I built 2.5.0-rc1 on Debian 12 X64. Did

onedrive --sync --upload-only --dry-run --enable-logging

Firstly, when enabling logging I would always also include --verbose so you have a more accurate log of what is actually occurring. Without using --verbose output is really limited and is not going to be informative or helpful.

which took almost 4 hours to complete. (Using the current released version without --dry-run takes 15-20 minutes).

This will be 100% correct for a first run with v2.5.0 as there has been lots that has changed, including the DB schema which is not backwards compatible. This is essentially also the same as doing a --resync. Once v2.5.0 has been fully synced that first time, the process should be much faster than v2.4.x series.

You can redo this test with either dropping back to v2.4.25 (the DB schema will be incompatible, and perform a full scan) - to which you can then also determine the time difference between v2.5.0 and v2.4.25 for that --resync scenario.

IMPORTANT POINT: Because you are also using --dry-run ... your resulting sync state will also never be saved - which will make it difficult to then accurately determine the performance benefit of v2.5.0 as the resulting DB is not saved.

So this is not a bug or issue.

It also reported:

New items to upload to OneDrive: 81278 

which surprised me given that a sync was done a few hours prior and everything in onedrive cloud was up to date.

This is 100% correct because it has no record of these as being stored online at this point in time - because of the DB Schema change which is the same as doing a --resync ... and if you do a --resync with v2.4.25 you will have a similar exercise occur, but you wont know exactly what is being checked as needed to be uploaded .....

So this is not a bug or issue, but is one of the application output changes.

There were several of these errors:

Skipping uploading this item as a new file, will upload as a modified file (online file already exists): ./Backups/Pictures/RSA/2002Picnic/P9220027.JPG
The local item is out-of-sync with OneDrive, renaming to preserve existing file and prevent local data loss: ./Backups/Pictures/RSA/2002Picnic/P9220027.JPG -> ./Backups/Pictures/RSA/2002Picnic/P9220027-mondo.JPG

OK .. this essentially means that the file already exists online. Due to you not using --verbose you are missing why the backup action is being taken - is the size different, is the hash different, is the timestamp different .....

If the size or hash (meaning the content of the file online does not match) is different that is when the local file is backed up so that you can then determine what is the correct file ... maybe you edited or cropped the file locally ... who knows ... but a difference was detected between online and local and action was taken to preserve your data.

So this is not a bug or issue.

To assist with your understanding all of the above 3 items, please read the Client Architecture Documentation and potentially change your usage to include / add --verbose

and a couple of this error:

ERROR: Microsoft OneDrive API returned an error with the following message:
Error Message:    HTTP request returned status code 502 ()
Error Reason:
Error Code:       UnknownError
Error Timestamp:  2024-03-16T17:51:34
API Request ID:   d1639031-705e-48c3-a866-c0cae6b51e98

This is a genuine error, but without any context as to where this is occurring or why.

A HTTP Status Code 502 is a standard HTTP response status code that indicates a gateway or proxy server received an invalid response from an upstream server. In the context of calling an API, this usually means that the OneDrive service is acting as a gateway or proxy and attempted to forward your request to another server but received a bad response from that server. A 502 error is usually indicative of issues on the server side or with the network, not with the API requests the 'onedrive' application is making.

To dig into this actual error, a full debug log would be required to dig into where and how this is being generated and what the 'onedrive' application did when this was encountered - was the request retried correctly .. ??

Please read: https://github.com/abraunegg/onedrive/wiki/Generate-debug-log-for-support to generate a debug log.

Once you have got this log available, please generate password protected archive and email the debug logfile through.

If you are concerned about data sensitivity, please read:

gitbls commented 4 months ago

Thanks @abraunegg for the detailed response. I'll read through the links you've provided and run another test as suggested. ETA Sunday US west coast time.

abraunegg commented 4 months ago

Thanks @abraunegg for the detailed response. I'll read through the links you've provided and run another test as suggested. ETA Sunday US west coast time.

Please also remember - any use of --dry-run is going to skew your time to complete as this is not going to be a representative comparison with v2.4.25.

abraunegg commented 4 months ago

@gitbls When running your tests, please rebuild your v2.5.0-rc1 client so that you are using onedrive v2.5.0-rc1-10-g8493ea8 or greater.

gitbls commented 4 months ago

@gitbls When running your tests, please rebuild your v2.5.0-rc1 client so that you are using onedrive v2.5.0-rc1-10-g8493ea8 or greater.

Sadly, I'm not exactly clear how to do this. What's the most efficient way to pull down that version?

I've been wrestling with a problematic upload of one file, just got a log with --debug-https and starting to review the log. Will update to latest client and rerun once I have it in hand.

Thx

EDIT: can I just download the zip file from https://github.com/abraunegg/onedrive/tree/onedrive-v2.5.0-release-candidate-1?

abraunegg commented 4 months ago

@gitbls

Sadly, I'm not exactly clear how to do this. What's the most efficient way to pull down that version?

I use a script titled clone_pr.sh with the following contents:

#!/bin/bash

PR=2661

rm -rf ./onedrive-pr${PR}
git clone https://github.com/abraunegg/onedrive.git onedrive-pr${PR}
cd onedrive-pr${PR}
git fetch origin pull/${PR}/head:pr${PR}
git checkout pr${PR}

Depending on how you have installed the compiler (you are using Debian 12, so you could just add ldc using the Debian 12 repositories):

cd /onedrive-pr2661
./configure; make clean; make;

EDIT: can I just download the zip file from https://github.com/abraunegg/onedrive/tree/onedrive-v2.5.0-release-candidate-1?

No .. as that is the initial code drop for RC1 .. not where the PR is now with documentation fixes, a couple of other items, your spelling error catch etc.

gitbls commented 4 months ago

@gitbls When running your tests, please rebuild your v2.5.0-rc1 client so that you are using onedrive v2.5.0-rc1-10-g8493ea8 or greater.

Sadly, I'm not a git wizard. Whats the best

@gitbls

Sadly, I'm not exactly clear how to do this. What's the most efficient way to pull down that version?

I use a script titled clone_pr.sh with the following contents:

#!/bin/bash

PR=2661

rm -rf ./onedrive-pr${PR}
git clone https://github.com/abraunegg/onedrive.git onedrive-pr${PR}
cd onedrive-pr${PR}
git fetch origin pull/${PR}/head:pr${PR}
git checkout pr${PR}

Depending on how you have installed the compiler (you are using Debian 12, so you could just add ldc using the Debian 12 repositories):

cd /onedrive-pr2661
./configure; make clean; make;

EDIT: can I just download the zip file from https://github.com/abraunegg/onedrive/tree/onedrive-v2.5.0-release-candidate-1?

No .. as that is the initial code drop for RC1 .. not where the PR is now with documentation fixes, a couple of other items, your spelling error catch etc.

Thx! So just to confirm...PR 2661 is what I want, or do I want 2668?

abraunegg commented 4 months ago

Thx! So just to confirm...PR 2661 is what I want, or do I want 2668?

PR 2661 is correct: https://github.com/abraunegg/onedrive/pull/2661

gitbls commented 4 months ago

Running test now. Thx!

gitbls commented 4 months ago

OK, here's where I'm at. Using the latest onedrive, syncing upload of the whole tree fails to upload HomeV3.QDF. I've attached that log (log9.1), which i trimmed down to the relevant stuff.

However, if I do a single directory (the one that contains HomeV3.QDF,) it worked fine, Well, it worked twice in a row. (log11) On the released version (v2.4.25-1+np1 installed via apt from download.opensuse.org) it failed more frequently, but then, I didn't have the ip_protocol_version setting (see below)

Also, when I started seeing the error as demonstrated in log9.1, a couple of other things:

Thx! (edited to remove non-redacted logs)

abraunegg commented 4 months ago

@gitbls Rather curious .... given that --single-directory is successful but without it is not .... as the code is the same - performing a session upload for a file > 4Mb.

As the log indicates, using 'ip_protocol_version = 1' in your config file is the right approach. This option is available in v2.4.25 as well: https://github.com/abraunegg/onedrive/blob/master/docs/USAGE.md#ip_protocol_version

This option was put in as it has been proven beyond all doubt that libcurl itself gets hung up with some IPv6 stuff, which is why forcing it to use IPv4 only stops this resolution snafu from occurring. This is a libcurl bug unfortunately that it will flip/flop between IPv4 and IPv6 for resolution if not explicitly told to use IPv4. Additionally, you are using Debian - thus are locked into using old packages - your version of libcurl was released in February 20 2023 and there are a number of resolution IPv4/IPv6 fixes post then.

I would attempt to use --single-directory a number of times in a row - or make multiple copies of your file in the same directory to see if you can trigger the same error with that option - as you should be able to, but because of how that option works, libcurl is not being stressed enough to generate the internal error.

Also - non of your logs are showing all the actual HTTPS Debug logs either. The actual libcurl parts will only display to the console (for data sensitivity reasons), which is why the logging when using that option is slightly different. Please read: https://github.com/abraunegg/onedrive/wiki/Generate-https-debug-log-for-support

When you review your console generated debug log, you will see then all the HTTPS parts, and see where libcurl is trying to resolve against IPv6 .. and this is where it then fails - hence why then IPv4 should be used to exclude IPv6 resolution.

Now .. you mention you changed the IP handling and it didnt resolve the issue ... if you add --display-running-config to you command line this will then also print your active applicable configuration as part of your logfile, so that you can validate that this is being correctly set when running the application.

gitbls commented 4 months ago

@gitbls Rather curious .... given that --single-directory is successful but without it is not .... as the code is the same - performing a session upload for a file > 4Mb.

As the log indicates, using 'ip_protocol_version = 1' in your config file is the right approach. This option is available in v2.4.25 as well: https://github.com/abraunegg/onedrive/blob/master/docs/USAGE.md#ip_protocol_version

Yep, I was today day's old when I discovered that

This option was put in as it has been proven beyond all doubt that libcurl itself gets hung up with some IPv6 stuff, which is why forcing it to use IPv4 only stops this resolution snafu from occurring. This is a libcurl bug unfortunately that it will flip/flop between IPv4 and IPv6 for resolution if not explicitly told to use IPv4. Additionally, you are using Debian - thus are locked into using old packages - your version of libcurl was released in February 20 2023 and there are a number of resolution IPv4/IPv6 fixes post then.

But using ip_protocol_version=1 should prevent these curl problems?

I would attempt to use --single-directory a number of times in a row - or make multiple copies of your file in the same directory to see if you can trigger the same error with that option - as you should be able to, but because of how that option works, libcurl is not being stressed enough to generate the internal error.

I'll do that.

Also - non of your logs are showing all the actual HTTPS Debug logs either. The actual libcurl parts will only display to the console (for data sensitivity reasons), which is why the logging when using that option is slightly different. Please read: https://github.com/abraunegg/onedrive/wiki/Generate-https-debug-log-for-support

That's weird. The only thing that I did differently than that page was leaving off the 2>&1. But for completeness, will do taht as well.

When you review your console generated debug log, you will see then all the HTTPS parts, and see where libcurl is trying to resolve against IPv6 .. and this is where it then fails - hence why then IPv4 should be used to exclude IPv6 resolution.

Now .. you mention you changed the IP handling and it didnt resolve the issue ... if you add --display-running-config to you command line this will then also print your active applicable configuration as part of your logfile, so that you can validate that this is being correctly set when running the application.

I added the ip_protocol_version = "1" long before these last 2 runs. I mistakenly left the quotes off and noticed that it wasn't being set.

Will add --display-running-config to the test script

gitbls commented 4 months ago

Here's the log output for --display-running-config. Seems to have both debug-https set and ip_protocol_version=1

2024-03-17 16:36:36 DEBUG: --------------- Application Runtime Configuration ---------------
2024-03-17 16:36:36 DEBUG: onedrive version                             = onedrive v2.5.0-rc1-11-g235fbf7
2024-03-17 16:36:36 DEBUG: Config path                                  = /home/blsodb/.config/onedrive
2024-03-17 16:36:36 DEBUG: Config file found in config path             = true
2024-03-17 16:36:36 DEBUG: Config option 'drive_id'                     =
2024-03-17 16:36:36 DEBUG: Config option 'sync_dir'                     = ~/OneDrive
2024-03-17 16:36:36 DEBUG: Config option 'enable_logging'               = true
2024-03-17 16:36:36 DEBUG: Config option 'log_dir'                      = /var/log/onedrive
2024-03-17 16:36:36 DEBUG: Config option 'disable_notifications'        = false
2024-03-17 16:36:36 DEBUG: Config option 'skip_dir'                     =
2024-03-17 16:36:36 DEBUG: Config option 'skip_dir_strict_match'        = false
2024-03-17 16:36:36 DEBUG: Config option 'skip_file'                    = ~*|.~*|*.tmp|*.swp|*.partial|~*|*.ini
2024-03-17 16:36:36 DEBUG: Config option 'skip_dotfiles'                = false
2024-03-17 16:36:36 DEBUG: Config option 'skip_symlinks'                = false
2024-03-17 16:36:36 DEBUG: Config option 'monitor_interval'             = 300
2024-03-17 16:36:36 DEBUG: Config option 'monitor_log_frequency'        = 12
2024-03-17 16:36:36 DEBUG: Config option 'monitor_fullscan_frequency'   = 12
2024-03-17 16:36:36 DEBUG: Config option 'read_only_auth_scope'         = false
2024-03-17 16:36:36 DEBUG: Config option 'dry_run'                      = false
2024-03-17 16:36:36 DEBUG: Config option 'upload_only'                  = true
2024-03-17 16:36:36 DEBUG: Config option 'download_only'                = false
2024-03-17 16:36:36 DEBUG: Config option 'local_first'                  = false
2024-03-17 16:36:36 DEBUG: Config option 'check_nosync'                 = false
2024-03-17 16:36:36 DEBUG: Config option 'check_nomount'                = false
2024-03-17 16:36:36 DEBUG: Config option 'resync'                       = false
2024-03-17 16:36:36 DEBUG: Config option 'resync_auth'                  = false
2024-03-17 16:36:36 DEBUG: Config option 'cleanup_local_files'          = false
2024-03-17 16:36:36 DEBUG: Config option 'classify_as_big_delete'       = 1000
2024-03-17 16:36:36 DEBUG: Config option 'disable_upload_validation'    = false
2024-03-17 16:36:36 DEBUG: Config option 'disable_download_validation'  = false
2024-03-17 16:36:36 DEBUG: Config option 'bypass_data_preservation'     = false
2024-03-17 16:36:36 DEBUG: Config option 'no_remote_delete'             = false
2024-03-17 16:36:36 DEBUG: Config option 'remove_source_files'          = false
2024-03-17 16:36:36 DEBUG: Config option 'sync_dir_permissions'         = 700
2024-03-17 16:36:36 DEBUG: Config option 'sync_file_permissions'        = 600
2024-03-17 16:36:36 DEBUG: Config option 'space_reservation'            = 52428800
2024-03-17 16:36:36 DEBUG: Config option 'application_id'               = d50ca740-c83f-4d1b-b616-12c519384f0c
2024-03-17 16:36:36 DEBUG: Config option 'azure_ad_endpoint'            =
2024-03-17 16:36:36 DEBUG: Config option 'azure_tenant_id'              =
2024-03-17 16:36:36 DEBUG: Config option 'user_agent'                   = ISV|abraunegg|OneDrive Client for Linux/v2.5.0-rc1-11-g235fbf7
2024-03-17 16:36:36 DEBUG: Config option 'force_http_11'                = false
2024-03-17 16:36:36 DEBUG: Config option 'debug_https'                  = true
2024-03-17 16:36:36 DEBUG: Config option 'rate_limit'                   = 0
2024-03-17 16:36:36 DEBUG: Config option 'operation_timeout'            = 3600
2024-03-17 16:36:36 DEBUG: Config option 'dns_timeout'                  = 60
2024-03-17 16:36:36 DEBUG: Config option 'connect_timeout'              = 10
2024-03-17 16:36:36 DEBUG: Config option 'data_timeout'                 = 240
2024-03-17 16:36:36 DEBUG: Config option 'ip_protocol_version'          = 1
2024-03-17 16:36:36 DEBUG: Config option 'threads'                      = 8
2024-03-17 16:36:36 DEBUG:
2024-03-17 16:36:36 DEBUG: Selective sync 'sync_list' configured        = false
2024-03-17 16:36:37 DEBUG: Updating refreshToken on disk
2024-03-17 16:36:37 DEBUG: Setting file permissions for: /home/blsodb/.config/onedrive/refresh_token
2024-03-17 16:36:36 DEBUG: Config option 'classify_as_big_delete'       = 1000
2024-03-17 16:36:36 DEBUG: Config option 'disable_upload_validation'    = false
2024-03-17 16:36:36 DEBUG: Config option 'disable_download_validation'  = false
abraunegg commented 4 months ago

But using ip_protocol_version=1 should prevent these curl problems?

Correct - it should work around the IPv6 issues

2024-03-17 16:36:36 DEBUG: --------------- Application Runtime Configuration ---------------

Great .. so it is being set and used .. thus, libcurl should not be using IPv6 for all operations (DNS, API access etc)

gitbls commented 4 months ago

Just ran the single directory 4 times and it worked every time. I did see this fail more frequently with the released version (even doing a single directory) so this is an improvement.

Will add some additional files to the directory to see if that helps stimulate the error.

If that doesn't do it, I'll try it a few times without all the logging, perhaps that is slowing things down enough such that it doesn't fail?

Also, you mentioned there was no debug-https output. What should that look like (so I can ensure that I'm getting it going forward)?

Thanks for your help with this!

abraunegg commented 4 months ago

@gitbls When you are running 'debug' (-v -v) + --debug-https your console output should have the following similar content:

* Found bundle for host graph.microsoft.com: 0x2b0a4a0 [can pipeline]
* Re-using existing connection! (#1) with host graph.microsoft.com
* Connected to graph.microsoft.com (20.190.142.169) port 443 (#1)
> GET /v1.0/drives/b!bO8V7s9SSk6r7mWHpIjURotN33W1W2tEv3OXV_oFIdQimEdOHR-1So7CqeT1MfHA/items/01WIXGO5V6Y2GOVW7725BZO354PWSELRRZ/delta?token=NDslMjM0OyUyMzE7Mzs0ZTQ3OTgyMi0xZjFkLTRhYjUtOGVjMi1hOWU0ZjUzMWYxYzA7NjM4NDYzMDM3NDcyMjAwMDAwOzIyNDcxNjI2MzslMjM7JTIzOyUyMzA7JTIz HTTP/1.1
Host: graph.microsoft.com
User-Agent: ISV|abraunegg|OneDrive Client for Linux/v2.5.0-rc1-3-g86b4cd3
Accept: */*
Authorization: bearer <redacted>
.........
< HTTP/1.1 200 OK
< Cache-Control: no-store, no-cache
< Transfer-Encoding: chunked
< Content-Type: application/json;odata.metadata=minimal;odata.streaming=true;IEEE754Compatible=false;charset=utf-8
< Strict-Transport-Security: max-age=31536000
< request-id: 20e67acd-2d71-44ec-bff7-0af8c3a0b776
< client-request-id: 20e67acd-2d71-44ec-bff7-0af8c3a0b776
< x-ms-ags-diagnostic: {"ServerInfo":{"DataCenter":"Australia Southeast","Slice":"E","Ring":"4","ScaleUnit":"001","RoleInstance":"ML1PEPF000058B8"}}
< OData-Version: 4.0
< Date: Sun, 17 Mar 2024 23:56:02 GMT
< 
DEBUG: onedrive.performHTTPOperation() => OneDrive HTTP Server Response: 200
* Connection #1 to host graph.microsoft.com left intact

and so on.

This sort of logging is only sent to the console / ssh session which is why redirection of console using > debug_output.log 2>&1 is important when using --debug-https

For your testing at the moment I would remove ip_protocol_version = "1" from your config file - so that you can consistently generate the error, see the error in the HTTPS Debug, then work forwards from that point.

When onedrive got the curl/libcurl error, the CPU utilization of onedrive hit 100%

Looking back at the prior comment .. this also stands out. HTTP/2 introduces a binary framing layer at its core, which is a departure from the newline-delimited text format of HTTP/1.x. This binary framing layer is designed to improve performance over HTTP/1.x by allowing multiplexing of requests and responses, stream prioritisation, and more efficient use of network resources. If the CPU is peaking, it means something is not working right in libcurl.

As a result. the next piece of advice I have is that you drop down to using pure HTTP/1.1 rather than HTTP/2 + some potential HTTP/1.1 communication streams.

Use either --force-http-11 or add force_http_11 = "true" to your config file.

Your resulting end up configuration might be:

ip_protocol_version = "1"
force_http_11 = "true"

And this will be down to the fact of Debian using a old curl version .......

gitbls commented 4 months ago

Giving it a total of 4 QDFs each about 200MB or so causes it to fail in single-directory mode. Here's the latest log:

log17.zip

abraunegg commented 4 months ago

Giving it a total of 4 QDFs each about 200MB or so causes it to fail in single-directory mode. Here's the latest log:

log17.zip

Great .. so this confirms somthing odd going on with libcurl

gitbls commented 4 months ago

Yep, and I forgot to mention: if you look at log-17, search for 17:04:28, and notice that the previous timestamp is four minutes earlier. I think I mentioned this previously. Also, onedrive was consuming 300% CPU during that period. NUC fan was really humming!

abraunegg commented 4 months ago

Yep, and I forgot to mention: if you look at log-17, search for 17:04:28, and notice that the previous timestamp is four minutes earlier. I think I mentioned this previously. Also, onedrive was consuming 300% CPU during that period. NUC fan was really humming!

Yes - however as the logfile provided has all the dates - this is the '--enable-logging' log .. not the console log, which is missing the other curl outputs ....

Also this is all HTTP/2 failures.

Suggest you try:

ip_protocol_version = "1"
force_http_11 = "true"

and go from there.

gitbls commented 4 months ago

Using force_http_11="true" in the config file works for all 3 files. 🥂

Is this relatively "safe" to use as a workaround while I putz around to see if I can update curl and company?

abraunegg commented 4 months ago

Using force_http_11="true" is 100% safe ... there is no issue here. The issue is that without this, your distribution (Debian) has curl bugs when dealing with HTTP/2 connections.

As this client 100% relies on curl/libcurl to operate - having a relative bug free curl/libcurl version is key to having 'onedrive' operate smoothly.

Now that you know the cause, this issue can be potentially resolved as your issue is with libcurl and HTTP/2 and not 'onedrive'

gitbls commented 4 months ago

Indeed. I'll sort curl out, and I need to get back to project, sdm. (RasPi tool) I have some cool features just waiting for me to test them.

Not a onedrive bug, thanks for your help in sorting this out!

abraunegg commented 4 months ago

Closing issue as this is not an issue with 'onedrive'

abraunegg commented 4 months ago

@gitbls FYI - curl 8.5.x is available for Debian 12 via backports: https://packages.debian.org/source/bookworm-backports/curl

gitbls commented 4 months ago

Thx!

gitbls commented 4 months ago

@abraunegg Thanks again for your help in sleuthing this out. I haven't yet installed the libcurl backport, but it's on my todo list.

I wanted to mention that this new version is most definitely faster! My nightly backup used to take about 13-15 minutes, and now takes less than 2 minutes for a similar update (running through the whole directory tree and uploading a single 200+MB file that changed.

abraunegg commented 3 months ago

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.