User Logged Out error triggered on each relaunch of app

nzpei commented 8 months ago

Steps to reproduce:

Log in to an Invidious account and grant access at the consent screen
Use Playlet as per normal
Close the Playlet app on Roku
Immediately relaunch the Playlet app on Roku
Error message "User Logged Out" with the following is displayed:

It looks like you are logged in to Invidious, but your access token does not have the required permissions. For that reason, we have logged you out. Please log in again. This can happen when Playlet is updated with new features. We apologize for the inconvenience.

Very early on in the logs, it shows the following: [INFO][HttpClient.bs:309] Sending POST https://invidious.fdn.fr/api/v1/auth/tokens/unregister which suggests that something failed and caused an explicit logout() to occur in the code.

The best I can trace through the source code is it appears https://github.com/iBicha/playlet/blob/80d3d24e3988d539be64c67c326a1cbce2675cb0/playlet-lib/src/components/Services/Invidious/InvidiousService.bs#L505 is failing this test: if tokenObject = invalid or if not IsArray(tokenObject.scopes) for some reason and returning false - but I'm not entirely sure why without being able to debug further.

State after freshly logging in successfully: {"app":{"app_git_commit_hash":"9df1b70e49d7cd67f85fe8ed1dc9f355b84e2429","app_version":"0.19.0","id":"693751","lib_git_commit_hash":"1172a82a26ad53bc5deb2d886136323c2268e67f","lib_url":"https://github.com/iBicha/playlet/releases/latest/download/playlet-lib.zip","lib_url_type":"github","lib_version":"0.19.1","lib_version_latest":"0.19.1"},"device":{"display_aspect_ratio":"16x9","display_mode":"720p","display_size":{"h":720,"w":1280},"display_type":"HDTV","friendly_name":"Streaming Stick 4K","graphics_platform":"opengl","internet_status":true,"model":"3820X","model_details":{"Manufacturer":"Roku","ModelNumber":"3820CA","VendorName":"Roku","VendorUSBName":"Roku"},"model_display_name":"Streaming Stick 4K","model_type":"STB","os_version":{"build":"4174","major":"12","minor":"5","revision":"5"},"ui_resolution":{"height":1080,"name":"FHD","width":1920},"user_country_code":"<obfuscated>","video_mode":"2160p60b10"},"invidious":{"auth_url":"http://invidious.fdn.fr/authorize_token?scopes=GET%3Afeed%2CGET%3Aplaylists*%2CPOST%3Atokens%2F*%2C%3Ahistory*%2C%3Asubscriptions*&callback_url=http%3A%2F%2F<obfuscated>%3A8888%2Finvidious%2Ftoken_callback%3Fref%3Dhttps%3A%2F%2Finvidious.fdn.fr&expire=1769989470","current_instance":"https://invidious.fdn.fr","logged_in":true,"logged_in_instance":"https://invidious.fdn.fr","logged_in_username":"<obfuscated>"},"preferences":{"__version":1,"invidious.instance":"https://invidious.fdn.fr","invidious.proxy_videos":"if_needed","misc.home_screen_layout":[{"enabled":true,"id":"subscriptions"},{"enabled":true,"id":"trending"},{"enabled":true,"id":"trending_music"},{"enabled":true,"id":"trending_gaming"},{"enabled":true,"id":"trending_movies"},{"enabled":true,"id":"popular"},{"enabled":true,"id":"playlists"},{"enabled":true,"id":"watch_history"}],"misc.queue_notifications":true,"playback.autoplay":true,"playback.preferred_quality":"auto","search_history.enabled":true,"sponsorblock.enabled":true,"sponsorblock.show_notifications":true}}

State after relaunching app and error displayed on screen: {"app":{"app_git_commit_hash":"9df1b70e49d7cd67f85fe8ed1dc9f355b84e2429","app_version":"0.19.0","id":"693751","lib_git_commit_hash":"1172a82a26ad53bc5deb2d886136323c2268e67f","lib_url":"https://github.com/iBicha/playlet/releases/latest/download/playlet-lib.zip","lib_url_type":"github","lib_version":"0.19.1","lib_version_latest":"0.19.1"},"device":{"display_aspect_ratio":"16x9","display_mode":"720p","display_size":{"h":720,"w":1280},"display_type":"HDTV","friendly_name":"Streaming Stick 4K","graphics_platform":"opengl","internet_status":true,"model":"3820X","model_details":{"Manufacturer":"Roku","ModelNumber":"3820CA","VendorName":"Roku","VendorUSBName":"Roku"},"model_display_name":"Streaming Stick 4K","model_type":"STB","os_version":{"build":"4174","major":"12","minor":"5","revision":"5"},"ui_resolution":{"height":1080,"name":"FHD","width":1920},"user_country_code":"<obfuscated>","video_mode":"2160p60b10"},"invidious":{"auth_url":"http://invidious.fdn.fr/authorize_token?scopes=GET%3Afeed%2CGET%3Aplaylists*%2CPOST%3Atokens%2F*%2C%3Ahistory*%2C%3Asubscriptions*&callback_url=http%3A%2F%2F<obfuscated>%3A8888%2Finvidious%2Ftoken_callback%3Fref%3Dhttps%3A%2F%2Finvidious.fdn.fr&expire=1769988190","current_instance":"https://invidious.fdn.fr","logged_in":false,"logged_in_instance":null,"logged_in_username":null},"preferences":{"__version":1,"invidious.instance":"https://invidious.fdn.fr","invidious.proxy_videos":"if_needed","misc.home_screen_layout":[{"enabled":true,"id":"subscriptions"},{"enabled":true,"id":"trending"},{"enabled":true,"id":"trending_music"},{"enabled":true,"id":"trending_gaming"},{"enabled":true,"id":"trending_movies"},{"enabled":true,"id":"popular"},{"enabled":true,"id":"playlists"},{"enabled":true,"id":"watch_history"}],"misc.queue_notifications":true,"playback.autoplay":true,"playback.preferred_quality":"auto","search_history.enabled":true,"sponsorblock.enabled":true,"sponsorblock.show_notifications":true}}

Latest Logs after relaunch with the error being displayed


[APP] Loading Playlet lib from https://github.com/iBicha/playlet/releases/latest/download/playlet-lib.zip
[APP] Playlet lib loaded from https://github.com/iBicha/playlet/releases/latest/download/playlet-lib.zip in 3501 ms
*********** End Startup Logs ***********
[INFO][EcpArgs.bs:17] LaunchArgumentsReceived {splashTime: 932, source: homescreen, instant_on_run_mode: foreground, lastExitOrTerminationReason: EXIT_UNKNOWN}
[INFO][VideoRowList.bs:286] Loading row content: Subscriptions
[INFO][VideoRowList.bs:286] Loading row content: Trending
[INFO][VideoRowList.bs:286] Loading row content: Trending - Music
[INFO][VideoRowList.bs:286] Loading row content: Trending - Gaming
[INFO][HttpClient.bs:309] Sending POST https://invidious.fdn.fr/api/v1/auth/tokens/unregister ID: <obfuscated>
[INFO][HttpServer.bs:75] listening on 0.0.0.0:8888
[INFO][HttpClient.bs:290] Cache hit GET https://invidious.fdn.fr/api/v1/trending?fields=title,videoId,videoThumbnails,lengthSeconds,viewCount,author,authorId,publishedText,liveNow,isUpcoming,premiereTimestamp&region=<obfuscated>&type=Music
[INFO][HttpClient.bs:290] Cache hit GET https://invidious.fdn.fr/api/v1/trending?region=<obfuscated>&fields=title,videoId,videoThumbnails,lengthSeconds,viewCount,author,authorId,publishedText,liveNow,isUpcoming,premiereTimestamp
[INFO][HttpClient.bs:290] Cache hit GET https://invidious.fdn.fr/api/v1/trending?fields=title,videoId,videoThumbnails,lengthSeconds,viewCount,author,authorId,publishedText,liveNow,isUpcoming,premiereTimestamp&region=<obfuscated>&type=Gaming
[INFO][HttpClient.bs:451] Finished ID: <obfuscated>
<subsequent log lines truncated>```

iBicha commented 8 months ago

Thanks a lot for the detailed report. I've been trying to reproduce this for a while, but I couldn't reproduce. I saw the issue only once. The only explanation that comes to mind is that the token was not saved to registry correctly. I added some logs to the verify function to help clarify the issue, when it happens.

Can you confirm this happens consistently every time?

nzpei commented 8 months ago

Thanks for the quick reply. Yes I can consistently reproduce it, 100% of the time, across two separate Roku devices (the streaming stick which these logs are from, and a second TV that has built-in Roku functionality).

I'll capture logs of it happening with the new version and will let you know.

iBicha commented 8 months ago

Thank you, please try https://github.com/iBicha/playlet/releases/tag/canary and let me know (it contains the additional logs https://github.com/iBicha/playlet/pull/279/files)

nzpei commented 8 months ago

[WARN][InvidiousService.bs:520] Token scopes do not match expected scopes. Expected: "GET:feed,GET:playlists*,POST:tokens/*,:history*,:subscriptions*", got: "GET:feed,GET:playlists,POST:tokens/,:history,:subscriptions"

iBicha commented 8 months ago

[WARN][InvidiousService.bs:520] Token scopes do not match expected scopes. Expected: "GET:feed,GET:playlists*,POST:tokens/*,:history*,:subscriptions*", got: "GET:feed,GET:playlists,POST:tokens/,:history,:subscriptions"

~~Dang, are you by chance using Safari to login?~~

Edit: ok I think I'm able to reproduce the issue. This happens when you are logged out of both Playlet and Invidious, and then you try to login. In the process, since the scope is encoded in the url, the * gets lost when decoded back later. Even Invidious does not show it correctly.

I will investigate further see where the decoding bug happen

nzpei commented 8 months ago

~~Nope. I can repro it with:~~ ~~- Firefox on Desktop-~~ ~~- Chromium on Desktop~~ ~~- Brave on Android~~

Interesting - thanks - I'll try seeing what happens when I'm logged into Invidious already

iBicha commented 8 months ago

Ok so I implemented a fix in https://github.com/iv-org/invidious/pull/4418 and it seems to work. What happens next is

We wait for the PR to be merged
Wait for different instance maintainers (in this case https://invidious.fdn.fr) to update
That should be it

nzpei commented 8 months ago

Thanks for the quick fix, and all of your hard work on this project!

The more I've dug into the code, the more impressed I am at the level of insightful thought and consideration that you've put into the architecture and technical design of Playlet. Amazing stuff.

iBicha commented 7 months ago

The fix has been merged https://github.com/iv-org/invidious/pull/4348

For people using their own instances: update your instance
For people using public instances: the fix will be applied once instance maintainers update

Thanks

iBicha / playlet

User Logged Out error triggered on each relaunch of app #277