OAuth tokens are expiring without being properly regenerated

Describe the bug

OAuth tokens are expiring without being properly regenerated.

How to reproduce

Using the latest release from the custom Fdroid repository, I'm having issues with the OAuth authentication. After a few days, it seems the application token expires silently. The application then fails for every request without an explicit message about authentication, the only way to tell is to watch the HTTP logs server-side.

As the application still thinks is is authenticated, I need to disconnect it, then redo the complete OAuth process to make it work again.

Something also seems to be wrong with the browser cache when I reauthenticate against the Funkwhale server. At first, I end up directly on the permission page without authentication and an error pops up when I try to accept.

What I need to do at this point is close the browser, re-enter the Funkwhale instance name a second time and the login process will then proceed normally.

Expected behavior

The apps keeps a current and working OAuth token without user intervention past the first login.

Actual behavior

The app credentials stop working after a few days.

Screenshots

Environment details

• Device: Pixel 3a XL
• Android version: 11
• App version: 0.1.4-1-fd955bfc-fd955bfc 5a1f80e6f32ba84e8e9c1085cb (104001)

Logs

funkwhale-84d556bd97-tmm8k:api 2021-09-23 12:59:29,092 django.request WARNING  Unauthorized: /api/v1/users/users/me/
funkwhale-84d556bd97-tmm8k:api 2021-09-23 12:59:29,057 django.request WARNING  Bad Request: /api/v1/oauth/token/

Thanks a lot for reporting your experience with Funkwhale! 🐳 A member of the team will have a look at this ticket as soon as possible. Afterwards this ticket will follow our issue workflow. We would really appreciate if you could check back to answer questions. Enjoy!

/cc @funkwhale/steering-commitee

added StatusNeeds triage label

I have a similar experience with Funkwhale Android and Funkwhale in general. I have not yet reported because I was not sure if it's not my setup that causes me to have to re-login frequently. On my system, Funkwhale is shut down daily for backup purposes and then restarted. Maybe this is the reason for me to have to re-login every day but it certainly isn't the case with other software services that I use in the same way and don't have to re-login.

I also get periodically disconnected on the web client. This is only mildly inconvenient since cached components believe they are still authenticated, but a refresh is enough to sort it out, and the process to relogin is a lot simpler on web than Android.

My Funkwhale instance is running 1.1.4, is deployed with the standard container on a Kubernetes cluster, and is running continuously apart from application and cluster node upgrades.

Yes, this is definitely a bug. A maybe fast fix could be a check if the token is still valid on app start or every hour and automatic logout. We already had a discussion in the matrix channel how to fix this problem permanently, I think @ryan_harg has some more insights and will comment here as soon as he finds time.

I'm running into this issue too. I'm using the latest preview build of Funkwhale for Android.

While I haven't run into this using the web UI, every android app I've tried has this issue. Running 1.0.1+git.68bc76bc.

It's a bit of a shame that using the web UI on Android has been the most stable experience, but I ain't complaining.

Just to keep you updated: I'm running into this myself sometimes. There are a few scenarios, where FFA tries to refresh the token, in my usage pattern it works mostly, but not always. I need to find the the scenario (I really think it's only one), where this is not working properly. Any detailed information is appreciated, but as I am still on parental leave, I can not yet work on this, yet.

From what I have seen, it seems to be time-based. Like if I don't use Funkwhale Android for a day or two (so 24+ hours), then it seems to time out.

It actually hasn't happened to me in the last week or so, but I'll see if I can figure out a way to reliably reproduce it.

Sure it's timebased, but there are different scenarios, in which a token gets renewed. For example if you are logged in but the app is closed and you re-open the app, it will check if you have a valid accesstoken - if it is not valid anymore it will try to renew it. There's other scenarios, for example the app is in the background and you bring it to the foreground again and refresh the artists view. The scenarios I have checked seem to work, so I would be interested in contextual information when this happens for you folks.

In my case it's like that:

1. I start listening to music at day 1, 9:10 at the bus
2. I stop music (9:30), close the app and doesn't open it at all this day.
3. I try to play some music at day 2, 9:15
4. App fails to play anything, I need to logout and login and it works again.

I'm running into the same issue, using the latest release of both server: All-in-one docker image (I'll migrate!) & android client: Fairphone 2 running Fairphone Open 21.10.0-rel.2. As I'm having on the same time OpenGL issues on the phone (my fault), the OpenGL crash permits me to get the logs in the settings. I don't know if it's helping, but anyway here are the logs:

--------- beginning of main 
11-12 09:23:37.372 31738 31756 W Adreno-EGL: <qeglDrvAPI_eglGetConfigAttrib:607>: EGL_BAD_ATTRIBUTE 
11-12 09:23:37.389 31738 31756 D vndksupport: Loading /vendor/lib/hw/gralloc.msm8974.so from current namespace instead of sphal namespace. 
11-12 09:23:38.688 31738 31756 W Adreno-EGL: <qeglDrvAPI_eglGetConfigAttrib:607>: EGL_BAD_ATTRIBUTE 
11-12 09:23:38.690 31738 31756 D vndksupport: Loading /vendor/lib/hw/gralloc.msm8974.so from current namespace instead of sphal namespace. 
11-12 09:23:39.474 31738 31759 I HttpUpstream: get() - url: /api/v1/albums/?playable=true&q=spot&page_size=50&page=1&scope=all 
11-12 09:23:39.474 31738 32523 I HttpUpstream: get() - url: /api/v1/artists/?playable=true&q=spot&page_size=50&page=1&scope=all 
11-12 09:23:39.474 31738 32520 I HttpUpstream: get() - url: /api/v1/tracks/?playable=true&q=spot&page_size=50&page=1&scope=all 
11-12 09:23:39.481 31738 32523 I Request.authorize(): Accesstoken expiration: 2021-11-12T10:58:24+0100 
11-12 09:23:39.481 31738 31759 I Request.authorize(): Accesstoken expiration: 2021-11-12T10:58:24+0100 
11-12 09:23:39.481 31738 32520 I Request.authorize(): Accesstoken expiration: 2021-11-12T10:58:24+0100 
11-12 09:23:39.510 31738 32520 I Request.authorize(): Accesstoken not renewed 
11-12 09:23:39.510 31738 32523 I Request.authorize(): Accesstoken not renewed 
11-12 09:23:39.511 31738 31759 I Request.authorize(): Accesstoken not renewed 
11-12 09:23:45.062 31738 32522 I HttpUpstream: get() - url: /api/v1/favorites/tracks/all/?playable=true&page_size=50&page=1&scope=all 
11-12 09:23:45.063 31738 32522 I Request.authorize(): Accesstoken expiration: 2021-11-12T10:58:24+0100 
11-12 09:23:45.078 31738  4053 I Request.authorize(): Accesstoken expiration: 2021-11-12T10:58:24+0100 
11-12 09:23:45.086 31738 32522 I Request.authorize(): Accesstoken not renewed 
11-12 09:23:45.090 31738  4053 I Request.authorize(): Accesstoken not renewed 
11-12 09:23:45.098 31738 31756 W Adreno-EGL: <qeglDrvAPI_eglGetConfigAttrib:607>: EGL_BAD_ATTRIBUTE 
11-12 09:23:45.105 31738 31756 D vndksupport: Loading /vendor/lib/hw/gralloc.msm8974.so from current namespace instead of sphal namespace. 
11-12 09:23:45.157 31738 31738 I ExoPlayerImpl: Init d537b97 [ExoPlayerLib/2.14.2] [FP2, FP2, Fairphone, 28] 
11-12 09:23:45.452 31738 31749 I o.funkwhale.ff: Background concurrent copying GC freed 29215(1731KB) AllocSpace objects, 48(2MB) LOS objects, 50% free, 4MB/9MB, paused 300us total 205.417ms 
11-12 09:23:45.456 31738 31747 W System  : A resource failed to call close. 
11-12 09:23:45.456 31738 31747 I chatty  : uid=10124(audio.funkwhale.ffa) FinalizerDaemon identical 1 line 
11-12 09:23:45.457 31738 31747 W System  : A resource failed to call close. 
11-12 09:23:45.532 31738  4066 W XingSeeker: XING data size mismatch: 12873728, 12873600 
11-12 09:23:45.568 31738  4074 I OMXClient: IOmx service obtained 
11-12 09:23:45.590 31738  4074 I ACodec  : codec does not support config priority (err -2147483648) 
11-12 09:23:45.618 31738  4069 I HttpUpstream: get() - url: /api/v1/favorites/tracks/all/?playable=true&page_size=50&page=1&scope=all 
11-12 09:23:45.619 31738  4069 I Request.authorize(): Accesstoken expiration: 2021-11-12T10:58:24+0100 
11-12 09:23:45.630 31738  4069 I Request.authorize(): Accesstoken not renewed 
11-12 09:23:46.689 31738 31756 W Adreno-EGL: <qeglDrvAPI_eglGetConfigAttrib:607>: EGL_BAD_ATTRIBUTE 
11-12 09:23:46.691 31738 31756 D vndksupport: Loading /vendor/lib/hw/gralloc.msm8974.so from current namespace instead of sphal namespace. 
11-12 09:23:47.425 31738 31738 W ActivityThread: handleWindowVisibility: no activity for token android.os.BinderProxy@b83ecd4 
11-12 09:23:47.679 31738 31756 W Adreno-EGL: <qeglDrvAPI_eglGetConfigAttrib:607>: EGL_BAD_ATTRIBUTE 
11-12 09:23:47.690 31738 31756 D vndksupport: Loading /vendor/lib/hw/gralloc.msm8974.so from current namespace instead of sphal namespace. 
11-12 09:23:49.694 31738 31756 W Adreno-EGL: <qeglDrvAPI_eglGetConfigAttrib:607>: EGL_BAD_ATTRIBUTE 
11-12 09:23:49.699 31738 31756 D vndksupport: Loading /vendor/lib/hw/gralloc.msm8974.so from current namespace instead of sphal namespace. 
11-12 09:23:56.472 31738 31747 W System  : A resource failed to call close. 
11-12 09:23:56.472 31738 31747 W System  : A resource failed to call close. 
11-12 09:24:07.233 31738 31756 W Adreno-EGL: <qeglDrvAPI_eglGetConfigAttrib:607>: EGL_BAD_ATTRIBUTE 
11-12 09:24:07.236 31738 31756 D vndksupport: Loading /vendor/lib/hw/gralloc.msm8974.so from current namespace instead of sphal namespace. 
11-12 09:24:08.247 31738 31756 W Adreno-EGL: <qeglDrvAPI_eglGetConfigAttrib:607>: EGL_BAD_ATTRIBUTE 
11-12 09:24:08.249 31738 31756 D vndksupport: Loading /vendor/lib/hw/gralloc.msm8974.so from current namespace instead of sphal namespace. 
11-12 09:24:09.300 31738 31756 W Adreno-EGL: <qeglDrvAPI_eglGetConfigAttrib:607>: EGL_BAD_ATTRIBUTE 
11-12 09:24:09.303 31738 31756 D vndksupport: Loading /vendor/lib/hw/gralloc.msm8974.so from current namespace instead of sphal namespace. 
11-12 09:24:10.112 31738 31738 E o.funkwhale.ff: Invalid ID 0x00000000. 
11-12 09:24:10.115 31738 31738 I chatty  : uid=10124(audio.funkwhale.ffa) identical 6 lines 
11-12 09:24:10.115 31738 31738 E o.funkwhale.ff: Invalid ID 0x00000000. 
11-12 09:24:18.255 31738 31756 W Adreno-EGL: <qeglDrvAPI_eglGetConfigAttrib:607>: EGL_BAD_ATTRIBUTE 
11-12 09:24:18.263 31738 31756 D vndksupport: Loading /vendor/lib/hw/gralloc.msm8974.so from current namespace instead of sphal namespace. 
11-12 09:24:27.253 31738  4069 I HttpUpstream: get() - url: /api/v1/favorites/tracks/all/?playable=true&page_size=50&page=1&scope=all 
11-12 09:24:27.254 31738  4069 I Request.authorize(): Accesstoken expiration: 2021-11-12T10:58:24+0100 
11-12 09:24:27.256 31738 31759 I Request.authorize(): Accesstoken expiration: 2021-11-12T10:58:24+0100 
11-12 09:24:27.266 31738  4069 I Request.authorize(): Accesstoken not renewed 
11-12 09:24:27.271 31738 31759 I Request.authorize(): Accesstoken not renewed 
11-12 09:24:27.274 31738 32520 I HttpUpstream: get() - url: /api/v1/favorites/tracks/all/?playable=true&page_size=50&page=1&scope=all 
11-12 09:24:27.276 31738 32520 I Request.authorize(): Accesstoken expiration: 2021-11-12T10:58:24+0100 
11-12 09:24:27.281 31738 31756 W Adreno-EGL: <qeglDrvAPI_eglGetConfigAttrib:607>: EGL_BAD_ATTRIBUTE 
11-12 09:24:27.283 31738 32520 I Request.authorize(): Accesstoken not renewed 
11-12 09:24:27.292 31738 31756 D vndksupport: Loading /vendor/lib/hw/gralloc.msm8974.so from current namespace instead of sphal namespace. 
11-12 09:24:33.222 31738 31738 W ActivityThread: handleWindowVisibility: no activity for token android.os.BinderProxy@902977a 
11-12 09:24:33.275 31738 31738 I FFA     : OAuth:31 - isAuthorized(): true 
11-12 09:24:33.275 31738 31738 I SplashActivity: Authorized, redirecting to MainActivity 
11-12 09:24:33.389 31738 31756 W Adreno-EGL: <qeglDrvAPI_eglGetConfigAttrib:607>: EGL_BAD_ATTRIBUTE 
11-12 09:24:33.406 31738 31756 D vndksupport: Loading /vendor/lib/hw/gralloc.msm8974.so from current namespace instead of sphal namespace. 
11-12 09:24:33.412 31738  4065 I HttpUpstream: get() - url: /api/v1/favorites/tracks/all/?playable=true&page_size=50&page=1&scope=all 
11-12 09:24:33.413 31738  4065 I Request.authorize(): Accesstoken expiration: 2021-11-12T10:58:24+0100 
11-12 09:24:33.419 31738  4064 I Request.authorize(): Accesstoken expiration: 2021-11-12T10:58:24+0100 
11-12 09:24:33.425 31738  4065 I Request.authorize(): Accesstoken not renewed 
11-12 09:24:33.450 31738  4064 I Request.authorize(): Accesstoken not renewed 
11-12 09:24:33.458 31738 31756 W Adreno-EGL: <qeglDrvAPI_eglGetConfigAttrib:607>: EGL_BAD_ATTRIBUTE 
11-12 09:24:33.481 31738 31756 D vndksupport: Loading /vendor/lib/hw/gralloc.msm8974.so from current namespace instead of sphal namespace. 
11-12 09:24:33.499 31738 32522 I HttpUpstream: get() - url: /api/v1/favorites/tracks/all/?playable=true&page_size=50&page=1&scope=all 
11-12 09:24:33.500 31738 32522 I Request.authorize(): Accesstoken expiration: 2021-11-12T10:58:24+0100 
11-12 09:24:33.500 31738 31749 I o.funkwhale.ff: NativeAlloc concurrent copying GC freed 13700(742KB) AllocSpace objects, 2(40KB) LOS objects, 49% free, 7MB/15MB, paused 1.153ms total 277.785ms 
11-12 09:24:33.518 31738 32522 I Request.authorize(): Accesstoken not renewed 
11-12 09:24:33.537 31738 31747 W System  : A resource failed to call close. 
11-12 09:24:33.537 31738 31747 W System  : A resource failed to call close. 
11-12 09:24:37.587 31738  4335 I FFA     : OAuth:2 - tryRefreshAccessToken(): true 
11-12 09:24:37.625 31738  4057 I HttpUpstream: get() - url: /api/v1/favorites/tracks/all/?playable=true&page_size=50&page=1&scope=all 
11-12 09:24:37.626 31738  4057 I Request.authorize(): Accesstoken expiration: 2021-11-12T10:58:24+0100 
11-12 09:24:37.638 31738  4057 I Request.authorize(): Accesstoken not renewed 
11-12 09:24:45.605 31738  4335 I FFA     : OAuth:2 - tryRefreshAccessToken(): true 
11-12 09:24:52.917 31738 31738 I ExoPlayerImpl: Release d537b97 [ExoPlayerLib/2.14.2] [FP2, FP2, Fairphone, 28] [goog.exo.core, goog.exo.flac, goog.exo.mediasession] 
11-12 09:24:53.730 31738 31744 I o.funkwhale.ff: Thread[3,tid=31744,WaitingInMainSignalCatcherLoop,Thread*=0xb3184200,peer=0x12e40218,"Signal Catcher"]: reacting to signal 3 
11-12 09:24:53.730 31738 31744 I o.funkwhale.ff: 
11-12 09:24:54.219 31738 31744 I o.funkwhale.ff: Wrote stack traces to '[tombstoned]' 
11-12 09:25:00.763 31738 31738 D AndroidRuntime: Shutting down VM 
--------- beginning of crash 
11-12 09:25:00.764 31738 31738 E AndroidRuntime: FATAL EXCEPTION: main 
11-12 09:25:00.764 31738 31738 E AndroidRuntime: Process: audio.funkwhale.ffa, PID: 31738 
11-12 09:25:00.764 31738 31738 E AndroidRuntime: android.app.RemoteServiceException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{1619e06 u0 audio.funkwhale.ffa/.playback.PlayerService} 
11-12 09:25:00.764 31738 31738 E AndroidRuntime:  at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1737) 
11-12 09:25:00.764 31738 31738 E AndroidRuntime:  at android.os.Handler.dispatchMessage(Handler.java:106) 
11-12 09:25:00.764 31738 31738 E AndroidRuntime:  at android.os.Looper.loop(Looper.java:193) 
11-12 09:25:00.764 31738 31738 E AndroidRuntime:  at android.app.ActivityThread.main(ActivityThread.java:6669) 
11-12 09:25:00.764 31738 31738 E AndroidRuntime:  at java.lang.reflect.Method.invoke(Native Method) 
11-12 09:25:00.764 31738 31738 E AndroidRuntime:  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:493) 
11-12 09:25:00.764 31738 31738 E AndroidRuntime:  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:858) 
android.app.RemoteServiceException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{1619e06 u0 audio.funkwhale.ffa/.playback.PlayerService} 

added TypeBug label

removed StatusNeeds triage label

added StatusNeeds triage label

removed StatusNeeds triage label

added StatusNeeds reproduction label

I am currently investingating on this issue. It may actually be a backend problem. Or rather, I suspect a reverse-proxy issue. Here are the logs I get on the server when the app is trying to renew the token:

POST /api/v1/oauth/token/ HTTP/1.1" 400

from the reverse-proxy (Apache here, multiple services exeposed in addition to Funkwhale),

django.request WARNING  Bad Request: /api/v1/oauth/token/

from Funkwhale itself. I'm trying to debug further but it is complex since I can only reproduce on production. If anyone has an idea to help me increase the logs on the request, I take it.

@georgkrause has implemented a way to decrease the validity time of access tokens by means of configuration. Do you know about that? It helps reducing the roundtrip time. I have been able to reproduce it with a local setup, too. If not, look at the .env.dev file and add something like this:

ACCESS_TOKEN_EXPIRE_SECONDS=120

Oh nice. That'll help me reproduce without having to mess with the Android code.

I did some examination a while back, but due to personal issues at home I have very limited resources currently to follow up. I really appreciate you folks looking in on this as well.

@christophehenry That URL looks almost incomplete, like there should be a token on the end of it?

But I can also grab logs from my server and see if I'm seeing the same thing. I do still run into this occasionally.

The token is sent as part of the request body, not the url.

Ack, I realised that later. I'm not used to seeing URLs that just end with a /. My apps don't do that.

I don't think I have all the data here. I'm searching for a way to extensively log the network requests on my server (Fedora 35). So far, my DDG-fu has failed me.

Edit: I managed to get more infos on the request using django-request-viewer. Here is the request that was performed:

{
    "path": "/api/v1/oauth/token/",
    "files": {},
    "method": "POST",
    "params": {
      "client_id": [
        "[RETRACTED]"
      ],
      "grant_type": [
        "refresh_token"
      ],
      "client_secret": [
        "[RETRACTED]"
      ],
      "refresh_token": [
        "[RETRACTED]"
      ]
    },
    "headers": {
      "Via": "1.1 [RETRACTED]",
      "Host": "[RETRACTED]",
      "Accept": "application/json",
      "Connection": "Keep-Alive",
      "User-Agent": "[RETRACTED]",
      "Content-Type": "application/x-www-form-urlencoded",
      "Content-Length": "263",
      "Accept-Encoding": "gzip",
      "X-Forwarded-For": "[RETRACTED]",
      "X-Forwarded-Host": "[RETRACTED]",
      "X-Forwarded-Proto": "https",
      "X-Forwarded-Server": "[RETRACTED]"
    },
    "message": "{\"error\": \"invalid_grant\"}",
    "status_code": 400,
    "time_length": 0.025525,
    "content_type": "utf-8",
    "status_message": "Bad Request",
    "request_timestamp": "01 Mar 2022 20:53:43.028336",
    "response_timestamp": "01 Mar 2022 20:53:43.053861"
  },

Nothing looks wrong to me 🤔