PneumaticTube icon indicating copy to clipboard operation
PneumaticTube copied to clipboard

Access token keeps expiring

Open david-navigator opened this issue 2 years ago • 22 comments

Running PT on about 10 machines without a problem. Installed on the 11th and it works for a while (a couple of hours I guess, maybe fewer) and then throws an expired_access_token error. Have recreated the token several times and the issue keeps occuring. I'm wondering if this could possibly be something to do with the machine having a CET time zone but my DB account being GMT ? (all the machines that work are GMT, this is the first machine I tried where the time zone differs)

An error occurred and your file was not uploaded. An authentication error occurred: Dropbox.Api.AuthException: expired_access_token/ at Dropbox.Api.DropboxRequestHandler.<RequestJsonString>d__2d.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Dropbox.Api.DropboxRequestHandler.<RequestJsonStringWithRetry>d__1a.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Dropbox.Api.DropboxRequestHandler.<Dropbox.Api.Stone.ITransport.SendUploadRequestAsync>d__d`3.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at PneumaticTube.DropboxClientExtensions.<Upload>d__3.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at PneumaticTube.Program.<Upload>d__3.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at PneumaticTube.Program.<Upload>d__2.MoveNext(); Request Id: 0a52c5b95b174d258b7931fe93c43f17

david-navigator avatar Mar 11 '22 11:03 david-navigator

I think this is due to DropBox dropping support for old TLS versions; the current version of PT is using an old DropBox SDK that's probably not selecting the correct version.

I'm working on updating all the SDKs that PT depends on and releasing a new version - I believe that will fix the issue.

hartez avatar Mar 16 '22 17:03 hartez

@david-navigator Can you give version 1.5 a try? https://github.com/hartez/PneumaticTube/releases/tag/v1.5

I'll try to get it published to Chocolatey later this week.

hartez avatar Mar 16 '22 18:03 hartez

Hi @hartez

Sadly no difference. Please let me know what I can do to help to diagnose this issue.

An error occurred and your file was not uploaded. An authentication error occurred: Dropbox.Api.AuthException: expired_access_token/. at Dropbox.Api.DropboxRequestHandler.<RequestJsonString>d__20.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Dropbox.Api.DropboxRequestHandler.<RequestJsonStringWithRetry>d__18.MoveNext() --- End of stack trace from previous location where exception was thrown --- at Dropbox.Api.DropboxRequestHandler.<RequestJsonStringWithRetry>d__18.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Dropbox.Api.DropboxRequestHandler.<Dropbox-Api-Stone-ITransport-SendUploadRequestAsync>d__13`3.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at PneumaticTube.DropboxClientExtensions.<Upload>d__3.MoveNext() in C:\Users\hartez\source\repos\PneumaticTube\DropboxClientExtensions.cs:line 32 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at PneumaticTube.Program.<Upload>d__4.MoveNext() in C:\Users\hartez\source\repos\PneumaticTube\Program.cs:line 154 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at PneumaticTube.Program.<Upload>d__3.MoveNext() in C:\Users\hartez\source\repos\PneumaticTube\Program.cs:line 115; Request Id: 1ad987672bbd4d068daf40cff1b23fb5

david-navigator avatar Mar 20 '22 16:03 david-navigator

Hi @hartez

Could be related to this https://dropbox.tech/developers/migrating-app-permissions-and-access-tokens ? All my machines that work were installed and authenticated prior to Sept 21.

david-navigator avatar Mar 20 '22 17:03 david-navigator

Hi @hartez

I've run up a new machine, set with the same time zone as all the other working machines and this too raises an expired_access_token after a couple of hours. So at least it proved it's not my specific computer nor the time zone setting that's causing the issue.

david-navigator avatar Mar 20 '22 21:03 david-navigator

@david-navigator Okay, I've been able to reproduce your error locally, and I think I've properly updated things to use the new short-lived tokens and refresh tokens. I'll do a little more testing in the morning and if it's still working correctly, I'll put out a release.

hartez avatar Mar 28 '22 05:03 hartez

@david-navigator Okay, I've been able to reproduce your error locally, and I think I've properly updated things to use the new short-lived tokens and refresh tokens. I'll do a little more testing in the morning and if it's still working correctly, I'll put out a release.

Brilliant. Thanks, I look forward to it

david-navigator avatar Mar 28 '22 09:03 david-navigator

Give this release a try: https://github.com/hartez/PneumaticTube/releases/tag/v1.5.1

You'll need to re-authorize it the first time; after that, it should automatically refresh authorization without human intervention. Let me know if you run into problems.

hartez avatar Mar 28 '22 15:03 hartez

@hartez Thanks. Seems to be running but it's very slow. Not sure if something's changed in this build or something else is throttling the upload. My 600MB file is just 50% complete after an hour.

david-navigator avatar Mar 29 '22 10:03 david-navigator

@hartez looks like chunked uploading is broken. 145 MB file (not chunked uploading) uploads instantly, 290 MB file (chunked uploading) 25 minutes

david-navigator avatar Mar 29 '22 11:03 david-navigator

I'll take a look this weekend.

hartez avatar Apr 01 '22 02:04 hartez

@david-navigator Give https://github.com/hartez/PneumaticTube/releases/tag/v1.6-pre at try.

I'm seeing the same issue you are - large chunked uploads are agonizingly slow. Nothing in the actual uploading code was changed when fixing the auth issues, so I'm guessing either something has changed in the underlying C# SDK or in the Dropbox backend.

That said, up to this point PT has had a hard-coded chunk size for chunked uploads of 128kB. This version 1.6 release bumps the default chunk size up to 1MB; using a larger chunk size made a big difference in the total upload time in my testing (which stand reasons; fewer round trips).

This version also adds a new command line option -k to configure the chunk size. It's specified in kB, so

 .\PneumaticTube.exe -f .\test.dat -c -k 8192

would upload the file in 8MB chunks. So you can play around with that parameter and figure out what chunk size makes sense for your connection speed.

I'm curious whether you'll see the same behavior - faster chunked uploads when using larger chunk sizes. Assuming that helps, I'll merge that feature into the main branch and push out a full 1.6 release.

hartez avatar Apr 03 '22 23:04 hartez

@hartez Seems much better. I found some docs from Dropbox that suggest a 4MB chunk size is optimum for large files, but my tests show this for a 300MB file 1MB chunk 4m 20s 4MB chunk 1m 23s 8MB chunk 1m 1s 16MB chunk 0m 36s 32 MB chunk 0m 26s

david-navigator avatar Apr 05 '22 08:04 david-navigator

@hartez seems to be an issue with files around 130MB - smaller and larger files seem to work OK, but I have a file here which always results in the same error. Tried different chunk sizes, but makes no difference. [Later: found a similar, but different sized file, that creates the file error. One is 123 MB (129,118,208 bytes) the other is 123 MB (129,593,344 bytes) - sizes as reported by Windows properties]

This is the error. Will do some more diagnosing unless you want a copy of the problematic file to test yourself ?

An error occurred and your file was not uploaded. System.AggregateException: One or more errors occurred. ---> System.Threading.Tasks.TaskCanceledException: A task was canceled. --- End of inner exception stack trace --- at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions) at System.Threading.Tasks.Task.Wait(Int32 millisecondsTimeout, CancellationToken cancellationToken) at PneumaticTube.Program.RunAndReturnExitCode(UploadOptions options) in C:\Users\hartez\source\repos\PneumaticTube\Program.cs:line 0 ---> (Inner Exception #0) System.Threading.Tasks.TaskCanceledException: A task was canceled.<---

david-navigator avatar Apr 21 '22 18:04 david-navigator

I'm out of town this weekend, but I try to look at this next week when I get back.

hartez avatar Apr 22 '22 23:04 hartez

@david-navigator I've tried to reproduce this with artificially created files with those sizes, but I'm not running into any problems. I can't imagine that the actual content of the file should make any difference, but if you want to post one of the problem files somewhere I can grab it and try to reproduce the issue.

Could the TaskCanceledException be happening because the connection is timing out?

hartez avatar May 08 '22 20:05 hartez

@hartez Oddly, two machines which have been running fine for months, suddenly threw this error today

C:\Program Files\Navigator Systems\NX SQL Server\DropboxUpload>pneumatictube -f "C:\ProgramData\Navigator Systems\backups\Tuesday\SNSStaging.zip" -p "/Everyone/Cloud_backups/SNS/Tuesday/SNSStaging"  -k 16384 
Uploading SNSStaging.zip to /Everyone/Cloud_backups/SNS/Tuesday/SNSStaging
Ctrl-C to cancel
An error occurred and your file was not uploaded.
System.AggregateException: One or more errors occurred. ---> System.Threading.Tasks.TaskCanceledException: A task was canceled.
   --- End of inner exception stack trace ---
   at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)
   at System.Threading.Tasks.Task.Wait(Int32 millisecondsTimeout, CancellationToken cancellationToken)
   at PneumaticTube.Program.RunAndReturnExitCode(UploadOptions options) in C:\Users\hartez\source\repos\PneumaticTube\Program.cs:line 0
---> (Inner Exception #0) System.Threading.Tasks.TaskCanceledException: A task was canceled.<---

and if I expand my log file slightly, just a few seconds earlier a smaller file was uploaded without a problem

C:\Program Files\Navigator Systems\NX SQL Server\DropboxUpload>pneumatictube -f "C:\ProgramData\Navigator Systems\backups\Tuesday\Thinfinity.zip" -p "/Everyone/Cloud_backups/WindyCity/Tuesday/Thinfinity"  -k 16384 
Uploading Thinfinity.zip to /Everyone/Cloud_backups/WindyCity/Tuesday/Thinfinity
Ctrl-C to cancel
Whoosh...
Uploaded Thinfinity.zip to /Everyone/Cloud_backups/WindyCity/Tuesday/Thinfinity/Thinfinity.zip; Revision 5e6e9018853a401ae73e9

C:\Program Files\Navigator Systems\NX SQL Server\DropboxUpload>IF 0 NEQ 0 EXIT 1 

C:\Program Files\Navigator Systems\NX SQL Server\DropboxUpload>cd C:\Program Files\Navigator Systems\NX SQL Server\DropBoxUpload 

C:\Program Files\Navigator Systems\NX SQL Server\DropboxUpload>pneumatictube -f "C:\ProgramData\Navigator Systems\backups\Tuesday\WindyCity.zip" -p "/Everyone/Cloud_backups/WindyCity/Tuesday/WindyCity"  -k 16384 
Uploading WindyCity.zip to /Everyone/Cloud_backups/WindyCity/Tuesday/WindyCity
Ctrl-C to cancel
An error occurred and your file was not uploaded.
System.AggregateException: One or more errors occurred. ---> System.Threading.Tasks.TaskCanceledException: A task was canceled.
   --- End of inner exception stack trace ---
   at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)
   at System.Threading.Tasks.Task.Wait(Int32 millisecondsTimeout, CancellationToken cancellationToken)
   at PneumaticTube.Program.RunAndReturnExitCode(UploadOptions options) in C:\Users\hartez\source\repos\PneumaticTube\Program.cs:line 0
---> (Inner Exception #0) System.Threading.Tasks.TaskCanceledException: A task was canceled.<---

david-navigator avatar Aug 23 '22 14:08 david-navigator

I wonder if I can extract more helpful error messages from the API.

hartez avatar Aug 23 '22 15:08 hartez

That would be great if you can.

Thx

David

⁣Get BlueMail for Android ​

On 23 Aug 2022, 16:09, at 16:09, "E.Z. Hart" @.***> wrote:

I wonder if I can extract more helpful error messages from the API.

-- Reply to this email directly or view it on GitHub: https://github.com/hartez/PneumaticTube/issues/32#issuecomment-1224211198 You are receiving this because you were mentioned.

Message ID: @.***>

david-navigator avatar Aug 23 '22 16:08 david-navigator

@hartez very weird, those two machines are now behaving (the file size being uploaded has changed too). I don't think it was a connection issue as I have 10 virtual machines on one bare metal machine and 8 were fine and 2 were not. Some time later the 2 that were not working started working (after the file size had grown)

david-navigator avatar Aug 23 '22 17:08 david-navigator

@david-navigator Give release 1.7 a try; the error reporting for this scenario should be a bit better.

Likely what's happening is the HTTP connection timing out, probably due to some hiccup in between you and Dropbox (which is why it's intermittent). 1.7 also adds an option (-t) to specify the connection timeout; if this starts to happen more often, it may help to bump up the timeout (which defaults to 100 seconds).

hartez avatar Sep 02 '22 02:09 hartez

@hartez Sorry I didn't comment earlier, but since your latest release (1.7) we haven't had any upload issues :)

david-navigator avatar Mar 30 '23 15:03 david-navigator