search

abraunegg / onedrive

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

Onedrive not honoring retry timer from HTTP 429 response #815

Closed tjbonzo closed 4 years ago

tjbonzo commented 4 years ago

Bug Report Details

Describe the bug Microsoft will occasionally throttle traffic to their servers. When this condition exists they return a HTTP 429 message that should contain a retry timer. Onedrive client should honor that timer. It appears that currently onedrive-client uses a hard-coded 'int backoffInterval = 2'. We are seeing retry timers of 120 - which seems excessively long but we don't control the MS server.

Application and Operating System Details:

Note: Please generate a full debug log as per https://github.com/abraunegg/onedrive/wiki/Generate-debug-log-for-support and email to support@mynas.com.au This condition only happens occasionally. I will generate a full debug the next time it happens. For now this is some of the info:

To Reproduce Steps to reproduce the behavior if not causing an application crash:

  1. Wait for Microsoft to start throttling traffic
  2. Attempt a onedrive sync (onedrive -vvv --download-only --synchronize --debug-https)
  3. Note the HTTP 429 response.

Complete Verbose Log Output A clear and full log of the problem when running the application in the following manner (ie, not in monitor mode):

< HTTP/1.1 429 
< Cache-Control: private
< Content-Type: application/json
< request-id: e75ef48a-3879-46d9-8d11-6e8908517c87
< client-request-id: e75ef48a-3879-46d9-8d11-6e8908517c87
< x-ms-ags-diagnostic: {"ServerInfo":{"DataCenter":"East US","Slice":"SliceC","Ring":"5","ScaleUnit":"000","RoleInstance":"AGSFE_IN_71"}}
< Strict-Transport-Security: max-age=31536000
< Date: Thu, 05 Mar 2020 18:04:22 GMT
< Content-Length: 233
< 
OneDrive HTTP Server Response: 429
* Connection #1 to host 10.15.100.3 left intact
* Found bundle for host graph.microsoft.com: 0x5559ef352fe0 [can pipeline]
* Re-using existing connection! (#1) with proxy 10.15.100.3
* Connected to 10.15.100.3 (10.15.100.3) port 8080 (#1)
> GET /v1.0/me/drive/root HTTP/1.1
Host: graph.microsoft.com
User-Agent: OneDrive Client for Linux v2.3.13-8-g8c7f664
Accept: */*
Authorization: bearer eyJ0eXAiOiJKV1QiLCJub25jZSI6InRqTEJ6Uk...

< HTTP/1.1 429 
< Cache-Control: private
< Content-Type: application/json
< request-id: 6bf74159-052c-4184-896f-666f36a3cdcd
< client-request-id: 6bf74159-052c-4184-896f-666f36a3cdcd
< x-ms-ags-diagnostic: {"ServerInfo":{"DataCenter":"East US","Slice":"SliceC","Ring":"5","ScaleUnit":"000","RoleInstance":"AGSFE_IN_71"}}
< Strict-Transport-Security: max-age=31536000
< Date: Thu, 05 Mar 2020 18:04:22 GMT
< Content-Length: 233
< 
OneDrive HTTP Server Response: 429
* Connection #1 to host 10.15.100.3 left intact
ERROR: Unable to query OneDrive to initialize application

Run the application in a separate terminal window or SSH session and provide the entire application output including the error & crash. When posing the logs, Please format log output to make it easier to read. See https://guides.github.com/features/mastering-markdown/ for more details.

Application Log Output:

Screenshots If applicable, add screenshots to help explain your problem.

Additional context Add any other context about the problem here.

Bug Report Checklist

abraunegg commented 4 years ago

@tjbonzo Please can you provide via email the full HTTPS debug log as per https://github.com/abraunegg/onedrive/wiki/Generate-https-debug-log-for-support

abraunegg commented 4 years ago

@tjbonzo In order to 'fix' this issue, given you are experiencing the 429 at the moment - timing is critical to ensure the right fix is performed, as I am unable to trigger a 429 response from OneDrive myself.

tjbonzo commented 4 years ago

The 429 response is sporadic - as soon as it happens again I will grab a full debug.

kmonchamp commented 4 years ago

I am also having the same issue with error code 429 throttling. I was able to capture a debug log for you. I followed your logging instructions and emailed it over.

uname -a
Linux sorairo 5.5.8-arch1-1 #1 SMP PREEMPT Fri, 06 Mar 2020 00:57:33 +0000 x86_64 GNU/Linux

dmd --version
DMD64 D Compiler v2.090.1

onedrive --display-config --confdir ~/.config/onedrive/Music 
onedrive version                    = v2.3.13
Config path                         = /home/kevin/.config/onedrive/Music
Config file found in config path    = true
Config option 'check_nosync'        = true
Config option 'sync_dir'            = /storage
Config option 'skip_dir'            = 
Config option 'skip_file'           = ~*|.~*|*.tmp
Config option 'skip_dotfiles'       = false
Config option 'skip_symlinks'       = false
Config option 'monitor_interval'    = 45
Config option 'min_notify_changes'  = 5
Config option 'log_dir'             = /var/log/onedrive/Music/
Config option 'sync_root_files'     = false
Selective sync configured           = true
sync_list contents:
Music

curl --version
curl 7.69.0 (x86_64-pc-linux-gnu) libcurl/7.69.0 OpenSSL/1.1.1d zlib/1.2.11 libidn2/2.3.0 libpsl/0.21.0 (+libidn2/2.2.0) libssh2/1.9.0 nghttp2/1.39.2
Release-Date: 2020-03-04
Protocols: dict file ftp ftps gopher http https imap imaps pop3 pop3s rtsp scp sftp smb smbs smtp smtps telnet tftp 
Features: AsynchDNS GSS-API HTTP2 HTTPS-proxy IDN IPv6 Kerberos Largefile libz NTLM NTLM_WB PSL SPNEGO SSL TLS-SRP UnixSockets
abraunegg commented 4 years ago

@kmonchamp Thanks for the debug log.

Whilst you are getting the 429 error - can you please run the following PR - hopefully this will provide more debugging that will assist.

git clone https://github.com/abraunegg/onedrive.git
cd onedrive
git fetch origin pull/816/head:pr816
git checkout pr816
./configure; make clean; make;

The PR version of the client should be onedrive v2.3.13-25-g67aa069

tjbonzo commented 4 years ago

Debug log with PR version has been emailed (although the version is 13-26 not 13-25): $ ./onedrive --version onedrive v2.3.13-26-gbd1d563

https://github.com/microsoftgraph/microsoft-graph-docs/blob/master/concepts/best-practices-concept.md Has information about throttling and 429 handling (which you are likely already aware).

tjbonzo commented 4 years ago

Note that when getting a 429, the last output is: "Remove your '/home/vlab/.config/onedrive/items.sqlite3' file and try to sync again", which I believe is coming from this segment of sync.d.

sync.d:
 851                                if (e.httpStatusCode == 504) {
 852                                        // HTTP request returned status code 504 (Gateway Timeout)
 853                                        // Retry by calling applyDifferences() again
 854                                        log.vlog("OneDrive returned a 'HTTP 504 - Gateway Timeout' - gracefully handling error");
 855                                        applyDifferences(driveId, idToQuery, performFullItemScan);
 856                                } else {
 857                                        // Default operation if not 404, 410, 500, 504 errors
 858                                        // display what the error is
 859                                        displayOneDriveErrorMessage(e.msg);
 860                                        log.log("\nRemove your '", cfg.databaseFilePath, "' file and try to sync again\n");
 861                                        return;
 862                                }

It appears we never get into the backoff section of 429 handling:

1595                        } catch (OneDriveException e) {
1596                                if ((e.httpStatusCode == 429) || (e.httpStatusCode == 408)) {
1597                                        // HTTP request returned status code 429 (Too Many Requests)
1598                                        // https://github.com/abraunegg/onedrive/issues/133
1599                                        // or 408 request timeout
1600                                        // https://github.com/abraunegg/onedrive/issues/694
1601                                        // Back off & retry with incremental delay
1602                                        int retryCount = 10;
1603                                        int retryAttempts = 1;
1604                                        int backoffInterval = 2;

1604 int backoffInterval = 2; // Shouldn't this be the Retry value?

abraunegg commented 4 years ago

Note that when getting a 429, the last output is: "Remove your '/home/vlab/.config/onedrive/items.sqlite3' file and try to sync again", which I believe is coming from this segment of sync.d.

sync.d:
 851                                if (e.httpStatusCode == 504) {
 852                                        // HTTP request returned status code 504 (Gateway Timeout)
 853                                        // Retry by calling applyDifferences() again
 854                                        log.vlog("OneDrive returned a 'HTTP 504 - Gateway Timeout' - gracefully handling error");
 855                                        applyDifferences(driveId, idToQuery, performFullItemScan);
 856                                } else {
 857                                        // Default operation if not 404, 410, 500, 504 errors
 858                                        // display what the error is
 859                                        displayOneDriveErrorMessage(e.msg);
 860                                        log.log("\nRemove your '", cfg.databaseFilePath, "' file and try to sync again\n");
 861                                        return;
 862                                }

It appears we never get into the backoff section of 429 handling:

1595                        } catch (OneDriveException e) {
1596                                if ((e.httpStatusCode == 429) || (e.httpStatusCode == 408)) {
1597                                        // HTTP request returned status code 429 (Too Many Requests)
1598                                        // https://github.com/abraunegg/onedrive/issues/133
1599                                        // or 408 request timeout
1600                                        // https://github.com/abraunegg/onedrive/issues/694
1601                                        // Back off & retry with incremental delay
1602                                        int retryCount = 10;
1603                                        int retryAttempts = 1;
1604                                        int backoffInterval = 2;

1604 int backoffInterval = 2; // Shouldn't this be the Retry value?

Correct - however I need the correct full debug log to work on this to fix this correctly.

Still waiting for a debug log that can provide the data. I am working on the fix.

abraunegg commented 4 years ago

Updated the PR with some more debugging and handling

Please use the updated PR when trying to capture the correct HTTPS debug log please. The version that should be in-use should be:

onedrive v2.3.13-27-ge73116a

or higher

abraunegg commented 4 years ago

Finally able to trigger this in part, by hammering the service - however the current PR is not handling this the way I was expecting (using the retry-value), but it is sleeping correctly for some operations:

[DEBUG] onedrive.perform() => OneDrive HTTP Server Response: 404
* Connection #2 to host graph.microsoft.com left intact
[DEBUG] onedrive.perform() => HTTP Response Headers: ["strict-transport-security":"max-age=31536000", "x-ms-ags-diagnostic":"{\"ServerInfo\":{\"DataCenter\":\"Australia Southeast\",\"Slice\":\"SliceC\",\"Ring\":\"4\",\"ScaleUnit\":\"002\",\"RoleInstance\":\"AGSFE_IN_0\"}}", "date":"Sat, 07 Mar 2020 22:57:18 GMT", "client-request-id":"b539b9ee-caff-4cbf-b63e-b13d2ef7fd5f", "content-length":"230", "request-id":"b539b9ee-caff-4cbf-b63e-b13d2ef7fd5f", "cache-control":"private", "content-type":"application/json"]
Uploading new file ./more_files/xQLutqKXPN95DbBrYinOHwvTClHy6Zrd/file16.data ... 
* Found bundle for host graph.microsoft.com: 0xe7a800
* Re-using existing connection! (#2) with host graph.microsoft.com
* Connected to graph.microsoft.com (20.190.142.179) port 443 (#2)
> POST /v1.0/drives/b!bO8V7s9SSk6r7mWHpIjURotN33W1W2tEv3OXV_oFIdQimEdOHR-1So7CqeT1MfHA/items/01WIXGO5WBPVZPL322JJA2KOEO4DX2CJUC:/file16.data:/createUploadSession HTTP/1.1
User-Agent: OneDrive Client for Linux v2.3.13-27-ge73116a
Host: graph.microsoft.com
Accept: */*
Content-Type: application/json
Content-Length: 110

< HTTP/1.1 429 
< Cache-Control: private
< Content-Type: application/json
< Retry-After: 120
< request-id: 57dc0e42-f1b6-4320-80f5-ed5581e3ed8b
< client-request-id: 57dc0e42-f1b6-4320-80f5-ed5581e3ed8b
< x-ms-ags-diagnostic: {"ServerInfo":{"DataCenter":"Australia Southeast","Slice":"SliceC","Ring":"4","ScaleUnit":"002","RoleInstance":"AGSFE_IN_0"}}
< Strict-Transport-Security: max-age=31536000
< Date: Sat, 07 Mar 2020 22:57:19 GMT
< Content-Length: 236
* HTTP error before end of send, stop sending
< 
[DEBUG] onedrive.perform() => OneDrive HTTP Server Response: 429
* Closing connection 2
[DEBUG] onedrive.perform() => HTTP Response Headers: ["strict-transport-security":"max-age=31536000", "x-ms-ags-diagnostic":"{\"ServerInfo\":{\"DataCenter\":\"Australia Southeast\",\"Slice\":\"SliceC\",\"Ring\":\"4\",\"ScaleUnit\":\"002\",\"RoleInstance\":\"AGSFE_IN_0\"}}", "retry-after":"120", "date":"Sat, 07 Mar 2020 22:57:19 GMT", "client-request-id":"57dc0e42-f1b6-4320-80f5-ed5581e3ed8b", "content-length":"236", "request-id":"57dc0e42-f1b6-4320-80f5-ed5581e3ed8b", "cache-control":"private", "content-type":"application/json"]
skipped.
ERROR: OneDrive returned an error with the following message:
  Error Message: HTTP request returned status code 429 ()
  Error Reason:  The request has been throttled
[DEBUG] Checking file: ./more_files/xQLutqKXPN95DbBrYinOHwvTClHy6Zrd/file17.data
* About to connect() to graph.microsoft.com port 443 (#8)
*   Trying 20.190.142.179...
* Connected to graph.microsoft.com (20.190.142.179) port 443 (#8)
*   CAfile: /etc/pki/tls/certs/ca-bundle.crt
  CApath: none
* SSL connection using TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
* Server certificate:
*       subject: CN=graph.microsoft.com
*       start date: Jan 21 03:42:40 2019 GMT
*       expire date: Jan 21 03:42:40 2021 GMT
*       common name: graph.microsoft.com
*       issuer: CN=Microsoft IT TLS CA 4,OU=Microsoft IT,O=Microsoft Corporation,L=Redmond,ST=Washington,C=US
> GET /v1.0/me/drive/root:/.%2Fmore_files%2FxQLutqKXPN95DbBrYinOHwvTClHy6Zrd%2Ffile17.data:/?select=id,name,eTag,cTag,deleted,file,folder,root,fileSystemInfo,remoteItem,parentReference,size HTTP/1.1
User-Agent: OneDrive Client for Linux v2.3.13-27-ge73116a
Host: graph.microsoft.com
Accept: */*

< HTTP/1.1 429 
< Cache-Control: private
< Content-Type: application/json
< Retry-After: 120
< request-id: eeca496b-7dd8-4087-8c89-ccf3983ab9b1
< client-request-id: eeca496b-7dd8-4087-8c89-ccf3983ab9b1
< x-ms-ags-diagnostic: {"ServerInfo":{"DataCenter":"Australia Southeast","Slice":"SliceC","Ring":"4","ScaleUnit":"002","RoleInstance":"AGSFE_IN_6"}}
< Strict-Transport-Security: max-age=31536000
< Date: Sat, 07 Mar 2020 22:57:19 GMT
< Content-Length: 236
< 
[DEBUG] onedrive.perform() => OneDrive HTTP Server Response: 429
* Connection #8 to host graph.microsoft.com left intact
[DEBUG] onedrive.perform() => HTTP Response Headers: ["strict-transport-security":"max-age=31536000", "x-ms-ags-diagnostic":"{\"ServerInfo\":{\"DataCenter\":\"Australia Southeast\",\"Slice\":\"SliceC\",\"Ring\":\"4\",\"ScaleUnit\":\"002\",\"RoleInstance\":\"AGSFE_IN_6\"}}", "retry-after":"120", "date":"Sat, 07 Mar 2020 22:57:19 GMT", "client-request-id":"eeca496b-7dd8-4087-8c89-ccf3983ab9b1", "content-length":"236", "request-id":"eeca496b-7dd8-4087-8c89-ccf3983ab9b1", "cache-control":"private", "content-type":"application/json"]
[DEBUG] Using Retry-After Value = 0
Thread sleeping due to 'HTTP request returned status code 429' - The request has been throttled
Sleeping for 300 seconds
abraunegg commented 4 years ago

Updated the PR, correct handling and using the 'Retry-After' header response value:

[DEBUG] Fragment: 1 of 1
Uploading 100% |oooooooooooooooooooooooooooooooooooooooo|   ETA   --:--:--:* Found bundle for host mynasau3-my.sharepoint.com: 0x1ac30e0
* Re-using existing connection! (#3) with host mynasau3-my.sharepoint.com
* Connected to mynasau3-my.sharepoint.com (40.108.249.53) port 443 (#3)
> PUT /personal/alex_braunegg_mynasau3_onmicrosoft_com/_api/v2.0/drives/b!bO8V7s9SSk6r7mWHpIjURotN33W1W2tEv3OXV_oFIdQimEdOHR-1So7CqeT1MfHA/items/01WIXGO5TM56VNA63OT5E262AAA2SG3ZH6/uploadSession?guid='2d83d4a3-ce4a-4d1f-9679-5ffcb62b007b'&path='~tmp57_file0.data'&overwrite=True&rename=False&dc=0&tempauth=eyJ0eXAiOiJKV1QiLCJhbGciOiJub25lIn0.eyJhdWQiOiIwMDAwMDAwMy0wMDAwLTBmZjEtY2UwMC0wMDAwMDAwMDAwMDAvbXluYXNhdTMtbXkuc2hhcmVwb2ludC5jb21AMWQ1MzMwYWYtYTg3NS00NWNmLTllNTYtNDM0MzMzMTU3ZGVmIiwiaXNzIjoiMDAwMDAwMDMtMDAwMC0wZmYxLWNlMDAtMDAwMDAwMDAwMDAwIiwibmJmIjoiMTU4MzYyNTEyNiIsImV4cCI6IjE1ODM3MTE1MjYiLCJlbmRwb2ludHVybCI6IkRWbm0xTTNBeU5kd1ZnV283RXJjTFg4d040M3hyR1kwWnMzNFlOUytaSzg9IiwiZW5kcG9pbnR1cmxMZW5ndGgiOiIzMjMiLCJpc2xvb3BiYWNrIjoiVHJ1ZSIsImNpZCI6Ik1HSXpOVFUxWlRJdFpEQXdOaTAwTlRNekxXRmxOek10TmpnM01qQmlPREkyWW1KbSIsInZlciI6Imhhc2hlZHByb29mdG9rZW4iLCJzaXRlaWQiOiJaV1V4TldWbU5tTXROVEpqWmkwMFpUUmhMV0ZpWldVdE5qVTROMkUwT0Roa05EUTIiLCJhcHBfZGlzcGxheW5hbWUiOiJPbmVEcml2ZSBGcmVlIENsaWVudCIsImdpdmVuX25hbWUiOiJBbGV4IiwiZmFtaWx5X25hbWUiOiJCcmF1bmVnZyIsImFwcGlkIjoiMjJjNDlhMGQtZDIxYy00NzkyLWFlZDEtOGYxNjNjOTgyNTQ2IiwidGlkIjoiMWQ1MzMwYWYtYTg3NS00NWNmLTllNTYtNDM0MzMzMTU3ZGVmIiwidXBuIjoiYWxleC5icmF1bmVnZ0BteW5hc2F1My5vbm1pY3Jvc29mdC5jb20iLCJwdWlkIjoiMTAwMzIwMDA5MTUwQ0MyNiIsImNhY2hla2V5IjoiMGguZnxtZW1iZXJzaGlwfDEwMDMyMDAwOTE1MGNjMjZAbGl2ZS5jb20iLCJzY3AiOiJteWZpbGVzLndyaXRlIGFsbGZpbGVzLndyaXRlIGFsbHNpdGVzLndyaXRlIiwidHQiOiIyIiwidXNlUGVyc2lzdGVudENvb2tpZSI6bnVsbH0.cUkxZ1FBa2IxRUxLbTRsV2FacnpVNlR0ZzZRMU9SSjEvajRmTXpLa0dXMD0 HTTP/1.1
User-Agent: OneDrive Client for Linux v2.3.13-27-ge73116a
Host: mynasau3-my.sharepoint.com
Accept: */*
Content-Range: bytes 0-1420415/1420416
Content-Length: 1420416
Expect: 100-continue

< HTTP/1.1 429 Too Many Requests
< Content-Type: application/json; charset=utf-8
< Retry-After: 120
< Server: Microsoft-IIS/10.0
< SPRequestGuid: 69993c9f-10c1-0000-4611-35c073429891
< request-id: 69993c9f-10c1-0000-4611-35c073429891
< MS-CV: nzyZacEQAABGETXAc0KYkQ.0
< Strict-Transport-Security: max-age=31536000
< SPRequestDuration: 24
< SPIisLatency: 1
< X-Powered-By: ASP.NET
< MicrosoftSharePointTeamServices: 16.0.0.19819
< X-Content-Type-Options: nosniff
< X-MS-InvokeApp: 1; RequireReadOnly
< P3P: CP="ALL IND DSP COR ADM CONo CUR CUSo IVAo IVDo PSA PSD TAI TELo OUR SAMo CNT COM INT NAV ONL PHY PRE PUR UNI"
< Date: Sat, 07 Mar 2020 23:52:06 GMT
< Content-Length: 149
* HTTP error before end of send, stop sending
< 
[DEBUG] onedrive.perform() => OneDrive HTTP Server Response: 429
* Closing connection 3
[DEBUG] onedrive.perform() => HTTP Response Headers: ["strict-transport-security":"max-age=31536000", "microsoftsharepointteamservices":"16.0.0.19819", "p3p":"CP=\"ALL IND DSP COR ADM CONo CUR CUSo IVAo IVDo PSA PSD TAI TELo OUR SAMo CNT COM INT NAV ONL PHY PRE PUR UNI\"", "sprequestguid":"69993c9f-10c1-0000-4611-35c073429891", "retry-after":"120", "date":"Sat, 07 Mar 2020 23:52:06 GMT", "sprequestduration":"24", "server":"Microsoft-IIS/10.0", "spiislatency":"1", "x-content-type-options":"nosniff", "request-id":"69993c9f-10c1-0000-4611-35c073429891", "content-length":"149", "x-ms-invokeapp":"1; RequireReadOnly", "ms-cv":"nzyZacEQAABGETXAc0KYkQ.0", "x-powered-by":"ASP.NET", "content-type":"application/json; charset=utf-8"]
[DEBUG] onedrive.perform() => Received HTTP 429 Retry-After Header Response: 120
[DEBUG] onedrive.perform() => Setting retryAfterValue to: 120
[DEBUG] 
Fragment upload failed - received throttle request response from OneDrive
[DEBUG] Using Retry-After Value = 120
Thread sleeping due to 'HTTP request returned status code 429' - The request has been throttled
Sleeping for 120 seconds
Retrying fragment upload
* About to connect() to mynasau3-my.sharepoint.com port 443 (#4)
*   Trying 40.108.249.53...
* Connected to mynasau3-my.sharepoint.com (40.108.249.53) port 443 (#4)
*   CAfile: /etc/pki/tls/certs/ca-bundle.crt
  CApath: none
* SSL connection using TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
* Server certificate:
*       subject: CN=*.sharepoint.com,OU=Microsoft Corporation,O=Microsoft Corporation,L=Redmond,ST=WA,C=US
*       start date: Aug 07 22:36:15 2019 GMT
*       expire date: Aug 07 22:36:15 2021 GMT
*       common name: *.sharepoint.com
*       issuer: CN=Microsoft IT TLS CA 2,OU=Microsoft IT,O=Microsoft Corporation,L=Redmond,ST=Washington,C=US
> PUT /personal/alex_braunegg_mynasau3_onmicrosoft_com/_api/v2.0/drives/b!bO8V7s9SSk6r7mWHpIjURotN33W1W2tEv3OXV_oFIdQimEdOHR-1So7CqeT1MfHA/items/01WIXGO5TM56VNA63OT5E262AAA2SG3ZH6/uploadSession?guid='2d83d4a3-ce4a-4d1f-9679-5ffcb62b007b'&path='~tmp57_file0.data'&overwrite=True&rename=False&dc=0&tempauth=eyJ0eXAiOiJKV1QiLCJhbGciOiJub25lIn0.eyJhdWQiOiIwMDAwMDAwMy0wMDAwLTBmZjEtY2UwMC0wMDAwMDAwMDAwMDAvbXluYXNhdTMtbXkuc2hhcmVwb2ludC5jb21AMWQ1MzMwYWYtYTg3NS00NWNmLTllNTYtNDM0MzMzMTU3ZGVmIiwiaXNzIjoiMDAwMDAwMDMtMDAwMC0wZmYxLWNlMDAtMDAwMDAwMDAwMDAwIiwibmJmIjoiMTU4MzYyNTEyNiIsImV4cCI6IjE1ODM3MTE1MjYiLCJlbmRwb2ludHVybCI6IkRWbm0xTTNBeU5kd1ZnV283RXJjTFg4d040M3hyR1kwWnMzNFlOUytaSzg9IiwiZW5kcG9pbnR1cmxMZW5ndGgiOiIzMjMiLCJpc2xvb3BiYWNrIjoiVHJ1ZSIsImNpZCI6Ik1HSXpOVFUxWlRJdFpEQXdOaTAwTlRNekxXRmxOek10TmpnM01qQmlPREkyWW1KbSIsInZlciI6Imhhc2hlZHByb29mdG9rZW4iLCJzaXRlaWQiOiJaV1V4TldWbU5tTXROVEpqWmkwMFpUUmhMV0ZpWldVdE5qVTROMkUwT0Roa05EUTIiLCJhcHBfZGlzcGxheW5hbWUiOiJPbmVEcml2ZSBGcmVlIENsaWVudCIsImdpdmVuX25hbWUiOiJBbGV4IiwiZmFtaWx5X25hbWUiOiJCcmF1bmVnZyIsImFwcGlkIjoiMjJjNDlhMGQtZDIxYy00NzkyLWFlZDEtOGYxNjNjOTgyNTQ2IiwidGlkIjoiMWQ1MzMwYWYtYTg3NS00NWNmLTllNTYtNDM0MzMzMTU3ZGVmIiwidXBuIjoiYWxleC5icmF1bmVnZ0BteW5hc2F1My5vbm1pY3Jvc29mdC5jb20iLCJwdWlkIjoiMTAwMzIwMDA5MTUwQ0MyNiIsImNhY2hla2V5IjoiMGguZnxtZW1iZXJzaGlwfDEwMDMyMDAwOTE1MGNjMjZAbGl2ZS5jb20iLCJzY3AiOiJteWZpbGVzLndyaXRlIGFsbGZpbGVzLndyaXRlIGFsbHNpdGVzLndyaXRlIiwidHQiOiIyIiwidXNlUGVyc2lzdGVudENvb2tpZSI6bnVsbH0.cUkxZ1FBa2IxRUxLbTRsV2FacnpVNlR0ZzZRMU9SSjEvajRmTXpLa0dXMD0 HTTP/1.1
User-Agent: OneDrive Client for Linux v2.3.13-27-ge73116a
Host: mynasau3-my.sharepoint.com
Accept: */*
Content-Range: bytes 0-1420415/1420416
Content-Length: 1420416
Expect: 100-continue
tjbonzo commented 4 years ago

Sent new debug based on v2.3.13-28-g9711f38 (although looks like you can recreate the issue now).

abraunegg commented 4 years ago

@tjbonzo Thanks for the log file - it helps ensure that this is being detected in the right places.

Please can you rebuild your client so that you are running onedrive v2.3.13-31-g5ac11e2 - this now uses the correct value rather than the 300 default if the value is not being set.

tjbonzo commented 4 years ago

Looks to work now - although it appears to loop in order to trigger the 429 error (perhaps by design for this debug PR). It now waits 120 seconds then tries again. (Why MS feels 120 second timeout jail is appropriate is beyond me)

On Sat, Mar 7, 2020 at 6:05 PM abraunegg notifications@github.com wrote:

@tjbonzo https://github.com/tjbonzo Thanks for the log file - it helps ensure that this is being detected in the right places.

Please can you rebuild your client so that you are running onedrive v2.3.13-31-g5ac11e2 - this now uses the correct value rather than the 300 default if the value is not being set.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/abraunegg/onedrive/issues/815?email_source=notifications&email_token=AAFYKKFNC7R6IOTU42D6X6LRGLONXA5CNFSM4LDJSTQ2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEOEIRUA#issuecomment-596150480, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAFYKKCYM6566YT3SN3ZLKLRGLONXANCNFSM4LDJSTQQ .

-- Tim Jedlicka, Network Entomologist bonzo@galifree.com, http://www.galifree.com

abraunegg commented 4 years ago

@tjbonzo

Looks to work now - although it appears to loop in order to trigger the 429 error (perhaps by design for this debug PR).

What should be happening is this:

If you have the debug log and you can show what you mean by 'loop' in order to trigger that would be greatly appreciated.

tjbonzo commented 4 years ago

sent full debug log to: support@mynas.com.au This is the highlight - note that it is looping in "* We are completely uploaded and fine"

vlab@burp5:~/onedrive/private/816/onedrive$ egrep "completely|Date|Retry" debug_output.log 
* We are completely uploaded and fine
< Date: Sun, 08 Mar 2020 00:22:00 GMT
< Date: Sun, 08 Mar 2020 00:22:01 GMT
[DEBUG] OneDrive API Response: {"@odata.context":"https:\/\/graph.microsoft.com\/v1.0\/$metadata#drives\/$entity","createdBy":{"user":{"displayName":"System Account"}},"createdDateTime":"2016-09-30T17:42:34Z","description":"","driveType":"business","id":"b!b2m8bw8d1E6xnWwvQ9_ZYRli0LRCoV9MvlVT90y5gMfQh35oqNBITI-UFPDGchLF","lastModifiedBy":{"user":{"displayName":"Jedlicka, Tim (Acme - US\/Naperville)","email":"tim.jedlicka@acme.com","id":"08da4466-4a95-4ed0-839d-a9338395e4ff"}},"lastModifiedDateTime":"2020-01-02T19:24:14Z","name":"OneDrive","owner":{"user":{"displayName":"Jedlicka, Tim (Acme - US\/Naperville)","email":"tim.jedlicka@acme.com","id":"08da4466-4a95-4ed0-839d-a9338395e4ff"}},"quota":{"deleted":131434562,"remaining":1098374812579,"state":"normal","total":1099511627776,"used":70028837},"webUrl":"https:\/\/acmenam-my.sharepoint.com\/personal\/tim_jedlicka_acme_com\/Documents"}
< Date: Sun, 08 Mar 2020 00:22:01 GMT
[DEBUG] OneDrive API Response: {"@odata.context":"https:\/\/graph.microsoft.com\/v1.0\/$metadata#users('08da4466-4a95-4ed0-839d-a9338395e4ff')\/drive\/root\/$entity","createdDateTime":"2016-09-30T17:42:34Z","fileSystemInfo":{"createdDateTime":"2016-09-30T17:42:34Z","lastModifiedDateTime":"2020-03-08T00:21:53Z"},"folder":{"childCount":17},"id":"01ZZFXACN6Y2GOVW7725BZO354PWSELRRZ","lastModifiedDateTime":"2020-03-08T00:21:53Z","name":"root","parentReference":{"driveId":"b!b2m8bw8d1E6xnWwvQ9_ZYRli0LRCoV9MvlVT90y5gMfQh35oqNBITI-UFPDGchLF","driveType":"business"},"root":{},"size":70028837,"webUrl":"https:\/\/acmenam-my.sharepoint.com\/personal\/tim_jedlicka_acme_com\/Documents"}
[DEBUG] OneDrive Account Details:      {"@odata.context":"https:\/\/graph.microsoft.com\/v1.0\/$metadata#drives\/$entity","createdBy":{"user":{"displayName":"System Account"}},"createdDateTime":"2016-09-30T17:42:34Z","description":"","driveType":"business","id":"b!b2m8bw8d1E6xnWwvQ9_ZYRli0LRCoV9MvlVT90y5gMfQh35oqNBITI-UFPDGchLF","lastModifiedBy":{"user":{"displayName":"Jedlicka, Tim (Acme - US\/Naperville)","email":"tim.jedlicka@acme.com","id":"08da4466-4a95-4ed0-839d-a9338395e4ff"}},"lastModifiedDateTime":"2020-01-02T19:24:14Z","name":"OneDrive","owner":{"user":{"displayName":"Jedlicka, Tim (Acme - US\/Naperville)","email":"tim.jedlicka@acme.com","id":"08da4466-4a95-4ed0-839d-a9338395e4ff"}},"quota":{"deleted":131434562,"remaining":1098374812579,"state":"normal","total":1099511627776,"used":70028837},"webUrl":"https:\/\/acmenam-my.sharepoint.com\/personal\/tim_jedlicka_acme_com\/Documents"}
[DEBUG] OneDrive Account Root Details: {"@odata.context":"https:\/\/graph.microsoft.com\/v1.0\/$metadata#users('08da4466-4a95-4ed0-839d-a9338395e4ff')\/drive\/root\/$entity","createdDateTime":"2016-09-30T17:42:34Z","fileSystemInfo":{"createdDateTime":"2016-09-30T17:42:34Z","lastModifiedDateTime":"2020-03-08T00:21:53Z"},"folder":{"childCount":17},"id":"01ZZFXACN6Y2GOVW7725BZO354PWSELRRZ","lastModifiedDateTime":"2020-03-08T00:21:53Z","name":"root","parentReference":{"driveId":"b!b2m8bw8d1E6xnWwvQ9_ZYRli0LRCoV9MvlVT90y5gMfQh35oqNBITI-UFPDGchLF","driveType":"business"},"root":{},"size":70028837,"webUrl":"https:\/\/acmenam-my.sharepoint.com\/personal\/tim_jedlicka_acme_com\/Documents"}
< Date: Sun, 08 Mar 2020 00:22:01 GMT
[DEBUG] OneDrive API Response: {"@odata.context":"https:\/\/graph.microsoft.com\/v1.0\/$metadata#users('08da4466-4a95-4ed0-839d-a9338395e4ff')\/drive\/root\/$entity","createdDateTime":"2016-09-30T17:42:34Z","fileSystemInfo":{"createdDateTime":"2016-09-30T17:42:34Z","lastModifiedDateTime":"2020-03-08T00:21:53Z"},"folder":{"childCount":17},"id":"01ZZFXACN6Y2GOVW7725BZO354PWSELRRZ","lastModifiedDateTime":"2020-03-08T00:21:53Z","name":"root","parentReference":{"driveId":"b!b2m8bw8d1E6xnWwvQ9_ZYRli0LRCoV9MvlVT90y5gMfQh35oqNBITI-UFPDGchLF","driveType":"business"},"root":{},"size":70028837,"webUrl":"https:\/\/acmenam-my.sharepoint.com\/personal\/tim_jedlicka_acme_com\/Documents"}
< Date: Sun, 08 Mar 2020 00:22:01 GMT
[DEBUG] OneDrive API Response: {"@odata.context":"https:\/\/graph.microsoft.com\/v1.0\/$metadata#drives('b%21b2m8bw8d1E6xnWwvQ9_ZYRli0LRCoV9MvlVT90y5gMfQh35oqNBITI-UFPDGchLF')\/items\/$entity","fileSystemInfo":{"createdDateTime":"2016-09-30T17:42:34Z","lastModifiedDateTime":"2020-03-08T00:21:53Z"},"folder":{"childCount":17},"id":"01ZZFXACN6Y2GOVW7725BZO354PWSELRRZ","name":"root","parentReference":{"driveId":"b!b2m8bw8d1E6xnWwvQ9_ZYRli0LRCoV9MvlVT90y5gMfQh35oqNBITI-UFPDGchLF","driveType":"business"},"root":{},"size":70028837}
[DEBUG] OneDrive Path Details: {"@odata.context":"https:\/\/graph.microsoft.com\/v1.0\/$metadata#drives('b%21b2m8bw8d1E6xnWwvQ9_ZYRli0LRCoV9MvlVT90y5gMfQh35oqNBITI-UFPDGchLF')\/items\/$entity","fileSystemInfo":{"createdDateTime":"2016-09-30T17:42:34Z","lastModifiedDateTime":"2020-03-08T00:21:53Z"},"folder":{"childCount":17},"id":"01ZZFXACN6Y2GOVW7725BZO354PWSELRRZ","name":"root","parentReference":{"driveId":"b!b2m8bw8d1E6xnWwvQ9_ZYRli0LRCoV9MvlVT90y5gMfQh35oqNBITI-UFPDGchLF","driveType":"business"},"root":{},"size":70028837}
< Date: Sun, 08 Mar 2020 00:22:01 GMT
< Date: Sun, 08 Mar 2020 00:22:01 GMT
< Date: Sun, 08 Mar 2020 00:22:02 GMT
* We are completely uploaded and fine
< Date: Sun, 08 Mar 2020 00:22:03 GMT
* We are completely uploaded and fine
< Date: Sun, 08 Mar 2020 00:22:04 GMT
< Date: Sun, 08 Mar 2020 00:22:04 GMT
* We are completely uploaded and fine
< Date: Sun, 08 Mar 2020 00:22:05 GMT

... many many more of these edited out for brevity. 

* We are completely uploaded and fine
< Date: Sun, 08 Mar 2020 00:23:56 GMT
< Date: Sun, 08 Mar 2020 00:23:55 GMT
* We are completely uploaded and fine
< Date: Sun, 08 Mar 2020 00:23:56 GMT
* We are completely uploaded and fine
< Date: Sun, 08 Mar 2020 00:23:57 GMT
< Date: Sun, 08 Mar 2020 00:23:57 GMT
* We are completely uploaded and fine
< Date: Sun, 08 Mar 2020 00:23:58 GMT
< Retry-After: 120
< Date: Sun, 08 Mar 2020 00:23:58 GMT
[DEBUG] onedrive.perform() => Received HTTP 429 Retry-After Header Response: 120
[DEBUG] Using Retry-After Value = 120
Retrying fragment upload
* We are completely uploaded and fine
< Date: Sun, 08 Mar 2020 00:26:01 GMT
< Date: Sun, 08 Mar 2020 00:26:00 GMT
* We are completely uploaded and fine
< Date: Sun, 08 Mar 2020 00:26:01 GMT
* We are completely uploaded and fine
< Date: Sun, 08 Mar 2020 00:26:02 GMT
< Date: Sun, 08 Mar 2020 00:26:02 GMT
* We are completely uploaded and fine
< Date: Sun, 08 Mar 2020 00:26:03 GMT
* We are completely uploaded and fine
abraunegg commented 4 years ago

@tjbonzo Without the HTTPS debug logging - this is potentially clearer:

Remaining free space on OneDrive: 1097745278756
Uploading new file ./random_files/YJ03MkkQxjxIAtsKDG26cVt1e8e9hSid/file4.data ... 
Uploading 100% |oooooooooooooooooooooooooooooooooooooooo|   ETA   --:--:--:     
done.
Remaining free space on OneDrive: 1097743784612
Uploading new file ./random_files/YJ03MkkQxjxIAtsKDG26cVt1e8e9hSid/file5.data ... 
Uploading 100% |oooooooooooooooooooooooooooooooooooooooo|   ETA   --:--:--:
Thread sleeping due to 'HTTP request returned status code 429' - The request has been throttled
Sleeping for 120 seconds
Retrying fragment upload
Uploading 100% |oooooooooooooooooooooooooooooooooooooooo|   ETA   --:--:--:     
done.
Remaining free space on OneDrive: 1097741997540
Uploading new file ./random_files/YJ03MkkQxjxIAtsKDG26cVt1e8e9hSid/file6.data ... 
Uploading 100% |oooooooooooooooooooooooooooooooooooooooo|   ETA   --:--:--:     
done.
  1. The last fragment was uploaded - We are completely uploaded and fine
  2. Next fragment generated a 429 - Thread sleeping due to 'HTTP request returned status code 429' - The request has been throttled
  3. This fragment is re-tried after 120 seconds and successfully uploaded

The line:

* We are completely uploaded and fine

This actually comes from Curl - I have no control over this messaging as this is the output Curl provides when performing debug operations.

tjbonzo commented 4 years ago

Same fix needs to be applied for "--display-sync-status", getting a 300 second timeout rather than 120. Full debug - sync_status.log sent via email.

< HTTP/1.1 429 ^M
< Cache-Control: private^M
< Content-Type: application/json^M
< request-id: ce661108-e651-44ad-996b-cc75067917e3^M
< client-request-id: ce661108-e651-44ad-996b-cc75067917e3^M
< x-ms-ags-diagnostic: {"ServerInfo":{"DataCenter":"West US","Slice":"SliceC","Ring":"5","ScaleUnit":"001","RoleInstance":"AGSFE_IN_20"}}^M
< Strict-Transport-Security: max-age=31536000^M
< Date: Sun, 08 Mar 2020 19:53:09 GMT^M
< Content-Length: 233^M
< ^M
[DEBUG] onedrive.perform() => OneDrive HTTP Server Response: 429
* Connection #1 to host 10.158.100.3 left intact
[DEBUG] onedrive.perform() => HTTP Response Headers: ["strict-transport-security":"max-age=31536000", "x-ms-ags-diagnostic":"{\"ServerInfo\":{\"DataCenter\":\"West US\",\"\
Slice\":\"SliceC\",\"Ring\":\"5\",\"ScaleUnit\":\"001\",\"RoleInstance\":\"AGSFE_IN_20\"}}", "date":"Sun, 08 Mar 2020 19:53:09 GMT", "client-request-id":"ce661108-e651-44a\
d-996b-cc75067917e3", "content-length":"233", "request-id":"ce661108-e651-44ad-996b-cc75067917e3", "cache-control":"private", "content-type":"application/json"]
[DEBUG] Using Retry-After Value = 0
Thread sleeping due to 'HTTP request returned status code 429' - The request has been throttled
Sleeping for 300 seconds
* Connection 0 seems to be dead!
abraunegg commented 4 years ago

@tjbonzo Actually this is operating 100% correct for the following reasons:

Other notes:

abraunegg commented 4 years ago

@tjbonzo Can you please rebuild your client to use the latest PR version and re-test. The version should be onedrive v2.3.13-35-ga1f905c

This has the handling now as per above.

tjbonzo commented 4 years ago

For --display-sync-status I was occasionally getting 404 errors (with 3 different versions of onedrive). I removed my items.sqlite3 db (don't know if that impacted the results or if this is an intermittent problem). I then got a 404 error, and all subsequent attempts have been successful (see logs below). Working on getting put in the 429 jail (throttled) again, but at the moment I can't cause a throttle (nor any more 404's). (pure speculation - a load balancer is sometimes sending me to a mis-behaving onedrive server). If I can get another 429 I'll capture the --display-sync-status with a 429.

13-35 debug - 404 error

$ cat debug.01
[DEBUG] homePath: HOME environment variable set
[DEBUG] homePath: /home/vlab
[DEBUG] configDirBase: WARNING - no XDG_CONFIG_HOME environment variable set
[DEBUG] configDirBase: /home/vlab/.config
[DEBUG] configDirName: Configuring application to use default config path
Using Config Dir: /home/vlab/.config/onedrive
[DEBUG] sync_dir: Getting syncDir from config value sync_dir
[DEBUG] sync_dir: A '~' was found in configured sync_dir, automatically expanding as SHELL and USER environment variable is set
[DEBUG] syncDir: /home/vlab/OneDrive
Initializing the OneDrive API ...
[DEBUG] Downgrading all HTTP operations to HTTP/1.1 by default
Opening the item database ...
[DEBUG] Using database file: /home/vlab/.config/onedrive/items.sqlite3
All operations will be performed in: /home/vlab/OneDrive
[DEBUG] Loading user configured sync_list file ...
[DEBUG] sync_list: vlab
[DEBUG] sync_list: USA_IP_DATABASE.xlsx
[DEBUG] sync_list: vlab-provider-network-assignments.xlsx
[DEBUG] Configuring skip_dir ...
[DEBUG] skip_dir: .*|Music|Movies/FullHD
[DEBUG] Configuring skip_file ...
[DEBUG] skip_file: ~*|thumbs.db|Games/*.iso
[DEBUG] OneDrive Account Details:      {"@odata.context":"https:\/\/graph.microsoft.com\/v1.0\/$metadata#drives\/$entity","createdBy":{"user":{"displayName":"System Account"}},"createdDateTime":"2016-09-30T17:42:34Z","description":"","driveType":"business","id":"b!b2m8bw8d1E6xnWwvQ9_ZYRli0LRCoV9MvlVT90y5gMfQh35oqNBITI-UFPDGchLF","lastModifiedBy":{"user":{"displayName":"Jedlicka, Tim (Acme - US\/Naperville)","email":"tim.jedlicka@acme.com","id":"08da4466-4a95-4ed0-839d-a9338395e4ff"}},"lastModifiedDateTime":"2020-03-08T19:13:00Z","name":"OneDrive","owner":{"user":{"displayName":"Jedlicka, Tim (Acme - US\/Naperville)","email":"tim.jedlicka@acme.com","id":"08da4466-4a95-4ed0-839d-a9338395e4ff"}},"quota":{"deleted":539548034,"remaining":1098097492440,"state":"normal","total":1099511627776,"used":12775006},"webUrl":"https:\/\/acmenam-my.sharepoint.com\/personal\/tim_jedlicka_acme_com\/Documents"}
[DEBUG] OneDrive Account Root Details: {"@odata.context":"https:\/\/graph.microsoft.com\/v1.0\/$metadata#users('08da4466-4a95-4ed0-839d-a9338395e4ff')\/drive\/root\/$entity","createdDateTime":"2016-09-30T17:42:34Z","fileSystemInfo":{"createdDateTime":"2016-09-30T17:42:34Z","lastModifiedDateTime":"2020-03-11T00:18:52Z"},"folder":{"childCount":17},"id":"01ZZFXACN6Y2GOVW7725BZO354PWSELRRZ","lastModifiedDateTime":"2020-03-11T00:18:52Z","name":"root","parentReference":{"driveId":"b!b2m8bw8d1E6xnWwvQ9_ZYRli0LRCoV9MvlVT90y5gMfQh35oqNBITI-UFPDGchLF","driveType":"business"},"root":{},"size":12775006,"webUrl":"https:\/\/acmenam-my.sharepoint.com\/personal\/tim_jedlicka_acme_com\/Documents"}
Application version: v2.3.13-35-ga1f905c
Account Type: business
Default Drive ID: b!b2m8bw8d1E6xnWwvQ9_ZYRli0LRCoV9MvlVT90y5gMfQh35oqNBITI-UFPDGchLF
Default Root ID: 01ZZFXACN6Y2GOVW7725BZO354PWSELRRZ
Remaining Free Space: 1098097492440
Fetching details for OneDrive Root
OneDrive Root does not exist in the database. We need to add it.
[DEBUG] Handing a OneDrive 'root' change
[DEBUG] Update/Insert local database with item details
[DEBUG] item details: Item("b!b2m8bw8d1E6xnWwvQ9_ZYRli0LRCoV9MvlVT90y5gMfQh35oqNBITI-UFPDGchLF", "01ZZFXACN6Y2GOVW7725BZO354PWSELRRZ", "root", dir, "", "", 2020-Mar-11 00:18:52Z, "", "", "", "", "", "")
Added OneDrive Root to the local database
Initializing the Synchronization Engine ...
ERROR: OneDrive returned an error with the following message:
  Error Message: HTTP request returned status code 404 (Not Found)
  Error Reason:  The resource could not be found.
onedrive v2.3.13-35-ga1f905c

Successful status


$ cat  cat debug.46
[DEBUG] homePath: HOME environment variable set
[DEBUG] homePath: /home/vlab
[DEBUG] configDirBase: WARNING - no XDG_CONFIG_HOME environment variable set
[DEBUG] configDirBase: /home/vlab/.config
[DEBUG] configDirName: Configuring application to use default config path
Using Config Dir: /home/vlab/.config/onedrive
[DEBUG] sync_dir: Getting syncDir from config value sync_dir
[DEBUG] sync_dir: A '~' was found in configured sync_dir, automatically expanding as SHELL and USER environment variable is set
[DEBUG] syncDir: /home/vlab/OneDrive
Initializing the OneDrive API ...
[DEBUG] Downgrading all HTTP operations to HTTP/1.1 by default
Opening the item database ...
[DEBUG] Using database file: /home/vlab/.config/onedrive/items.sqlite3
All operations will be performed in: /home/vlab/OneDrive
[DEBUG] Loading user configured sync_list file ...
[DEBUG] sync_list: vlab
[DEBUG] sync_list: USA_IP_DATABASE.xlsx
[DEBUG] sync_list: vlab-provider-network-assignments.xlsx
[DEBUG] Configuring skip_dir ...
[DEBUG] skip_dir: .*|Music|Movies/FullHD
[DEBUG] Configuring skip_file ...
[DEBUG] skip_file: ~*|thumbs.db|Games/*.iso
[DEBUG] OneDrive Account Details:      {"@odata.context":"https:\/\/graph.microsoft.com\/v1.0\/$metadata#drives\/$entity","createdBy":{"user":{"displayName":"System Account"}},"createdDateTime":"2016-09-30T17:42:34Z","description":"","driveType":"business","id":"b!b2m8bw8d1E6xnWwvQ9_ZYRli0LRCoV9MvlVT90y5gMfQh35oqNBITI-UFPDGchLF","lastModifiedBy":{"user":{"displayName":"Jedlicka, Tim (Acme - US\/Naperville)","email":"tim.jedlicka@acme.com","id":"08da4466-4a95-4ed0-839d-a9338395e4ff"}},"lastModifiedDateTime":"2020-03-08T19:13:00Z","name":"OneDrive","owner":{"user":{"displayName":"Jedlicka, Tim (Acme - US\/Naperville)","email":"tim.jedlicka@acme.com","id":"08da4466-4a95-4ed0-839d-a9338395e4ff"}},"quota":{"deleted":539548034,"remaining":1098097112019,"state":"normal","total":1099511627776,"used":12775006},"webUrl":"https:\/\/acmenam-my.sharepoint.com\/personal\/tim_jedlicka_acme_com\/Documents"}
[DEBUG] OneDrive Account Root Details: {"@odata.context":"https:\/\/graph.microsoft.com\/v1.0\/$metadata#users('08da4466-4a95-4ed0-839d-a9338395e4ff')\/drive\/root\/$entity","createdDateTime":"2016-09-30T17:42:34Z","fileSystemInfo":{"createdDateTime":"2016-09-30T17:42:34Z","lastModifiedDateTime":"2020-03-11T01:18:52Z"},"folder":{"childCount":17},"id":"01ZZFXACN6Y2GOVW7725BZO354PWSELRRZ","lastModifiedDateTime":"2020-03-11T01:18:52Z","name":"root","parentReference":{"driveId":"b!b2m8bw8d1E6xnWwvQ9_ZYRli0LRCoV9MvlVT90y5gMfQh35oqNBITI-UFPDGchLF","driveType":"business"},"root":{},"size":12775006,"webUrl":"https:\/\/acmenam-my.sharepoint.com\/personal\/tim_jedlicka_acme_com\/Documents"}
Application version: v2.3.13-35-ga1f905c
Account Type: business
Default Drive ID: b!b2m8bw8d1E6xnWwvQ9_ZYRli0LRCoV9MvlVT90y5gMfQh35oqNBITI-UFPDGchLF
Default Root ID: 01ZZFXACN6Y2GOVW7725BZO354PWSELRRZ
Remaining Free Space: 1098097112019
Fetching details for OneDrive Root
OneDrive Root exists in the database
Initializing the Synchronization Engine ...
Local directory is out of sync with OneDrive
Approximate data to transfer: 12775 KB
onedrive v2.3.13-35-ga1f905c
abraunegg commented 4 years ago

@tjbonzo I have updated the PR with additional debug output where relevant for when an exception is raised & where a 429 is handled & what call is being re-tried. It will also output the call that generated the exception, to help identify why, in your case above - a 404 is being thrown.

Specifically, I think for the 404, it was being generated by this call onedrive.viewChangesById - but without the prior debug logging being available, it would have been unclear as to 'why' this was failing. Usually this will be because the id to query or the driveId to query would have been blank - but why would have been blank .. unsure.

Also - it could have been because of some sort of internal bad handing on the Microsoft end - but most likely the 'data' was not present in the values needed to get a successful response - this at least is now going to be visible due to the added debug log output.

tjbonzo commented 4 years ago

For reference (which you may be aware), some information from Microsoft on throttling. Specifically it appears the client is "undecorated". https://docs.microsoft.com/en-us/sharepoint/dev/general-development/how-to-avoid-getting-throttled-or-blocked-in-sharepoint-online?redirectedfrom=MSDN

Well-decorated traffic will be prioritized over traffic, which isn't properly decorated. Traffic is undecorated if there's no AppID/AppTitle and User Agent string in CSOM or REST API call to SharePoint Online. The User Agent string should be in a specific format as described below.

I tested with "onedrive v2.3.13-36-g1764a8f" last night, but could not trigger a 429 - leading me to believe that there are other factors/users causing the 429. Currently the server is returning a 503 so waiting for the server to be fixed.

abraunegg commented 4 years ago

@tjbonzo The decoration currently in use has the appropriate user agent set - you can see this in the HTTPS debug logs. If you have something else to set it to, you can test via setting this in the config file.

abraunegg commented 4 years ago

@tjbonzo Can you update your client to the latest PR version, as I have updated the User Agent to be even more compliant with the required decoration requirements. It now will appear as:

ISV|abraunegg|OneDrive_Client_for_Linux/v%version_string%

If you can stress test this updated version that would be greatly appreciated.

tjbonzo commented 4 years ago

Earlier tried a User-Agent via config of: user_agent = "NONISV|Acme|OneDrive/v2.3.13-36-g1764a8f" That did not help with the 503 blocking.

Just updated to 13-37, User-Agent: ISV|abraunegg|OneDrive_Client_for_Linux/v2.3.13-37-g4dac0f8 however MS is still returning a "503 Server Overload". My IT dept is working with them to unblock us and when that happens I will try to test more.

Re-reading the throttling documentation sited earlier, changing the User-Agent should have broken me out of the 429/503 jail, but that did not work, making me question if User-Agent alone is considered "decorated" or if AppID/AppTitle is REQUIRED.

Traffic is undecorated if there's no AppID/AppTitle and User Agent string in CSOM or REST API call to SharePoint Online.

There are several versions of Linux-Onedrive running within my company. I speculate that some are mis-behaving by not honoring the retry timer - which escalates/extends the retry interval. I believe that has now escalated to a 503 blocking condition. Once we get unblocked, it will take some time while the other clients overload the server then I might start to see 429's again. i.e. it might take some time before I see the sporadic 429's again.

abraunegg commented 4 years ago

@tjbonzo

There are several versions of Linux-Onedrive running within my company. I speculate that some are mis-behaving by not honoring the retry timer - which escalates/extends the retry interval.

Never a good situation - plus, there is a good chance of potentially older 'skilion' versions also in use.

In your company situation - can you ask your firewall / proxy team to look / collect all the current user agents they are seeing? Potential entries are:

The issue here is that currently the application is still using the 'skilion' application ID, thus no idea what the AppTitle used was.

An option here is to update the clientId to a new AppID (as per #770) where I have control over what the AppTitle is.

This would mean that the User Agent String would need to be updated as per following:

ISV|abraunegg|%AppTitle%/v2.3.13-37-g4dac0f8

abraunegg commented 4 years ago

@tjbonzo Re the 503 errors - if you are still getting those - can you do a debug log with this PR, and tell me, when you are getting the 503 response, is the code responding citing that a Retry-After Header Response was received?

tjbonzo commented 4 years ago

No retry header with my current 503's. Log sent via email.

We (my sharepoint admins) have been informed of the block and it will take manual intervention to release the block. The 503 is apparently an escalation of the 429 throttling. Since clearing 503 takes manual intervention it makes sense that there would be no retry timer in a 503. I don't know if that is the spec, but that appears to be the way things are behaving.

We will be registering a new ClientID (aka AppID) in our sharepoint tenant and testing with your PR (hopefully sometime this weekend). If that works it likely will make sense to implement the #770 change in concert with this 429 fix since a mis-behaving client can eventually block any app using the same ID.

abraunegg commented 4 years ago

@tjbonzo Any update here on your testing ?

abraunegg commented 4 years ago

@tjbonzo Any update here on your testing ?

tjbonzo commented 4 years ago

My IT guy has "disappeared" - waiting to get a new AppID/ClientID. I suspect he is swamped with networking issues as most of us are working from home now. I'm still bugging folks as best I can.

On Tue, Mar 17, 2020 at 4:44 PM abraunegg notifications@github.com wrote:

@tjbonzo https://github.com/tjbonzo Any update here on your testing ?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/abraunegg/onedrive/issues/815#issuecomment-600315929, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAFYKKEBYG7JRTYM6ASBOIDRH7VMDANCNFSM4LDJSTQQ .

-- Tim Jedlicka, Network Entomologist bonzo@galifree.com, http://www.galifree.com

abraunegg commented 4 years ago

@tjbonzo Manually apply the changes as per #770 to a local copy - this is a new AppID / ClientID and will be the base when v2.4.0 is rolled out.

abraunegg commented 4 years ago

@tjbonzo I am thinking of pushing this PR into master given all your testing on this issue. Will most likely do this in the morning.

abraunegg commented 4 years ago

Closing issue as PR #816 merged into master

lock[bot] commented 4 years ago

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.