🐛 Bug Report: Refreshing OAuth token... forever and stop working

[freedit-dev]

It occurs several times that my instance stop working and the last log is always

INFO redlib::oauth > [⌛] 86279s Elapsed! Refreshing OAuth token...

And restarting redlib always fixed it.

Maybe there should be timeout for refreshing token.

Thanks for your great work.

[sigaloid]

Weird. The refresh code is literally just logging in again, which is what happens at launch.

redlib/src/oauth.rs

Lines 102 to 108 in 6c2579c

	async fn refresh(&mut self) -> Option<()> {
	// Refresh is actually just a subsequent login with the same headers (without the old token
	// or anything). This logic is handled in login, so we just call login again.
	let refresh = self.login().await;
	info!("Refreshing OAuth token... {}", if refresh.is_some() { "success" } else { "failed" });
	refresh
	}

I suppose it could have something to do with the header cache not being cleared.

Can you reproduce this consistently? If so, can you try running off of this branch? https://github.com/redlib-org/redlib/tree/try_fix_oauth_refresh

[extremelyonline]

Not sure if this is the same issue as #81

[freedit-dev]

The latest commit(fix_oauth_ratelimit)

The instance stops responding(no error log) and the last log:

Jun 27 01:41:19 base redlib[4038062]:  ERROR redlib::utils  > Error page rendered: Reddit error 400 "null": "Bad Request"
Jun 27 01:41:57 base redlib[4038062]:  ERROR redlib::utils  > Error page rendered: Reddit error 400 "null": "Bad Request"
Jun 27 01:43:33 base redlib[4038062]:  WARN  redlib::client > Rate limit 9 is low. Spawning force_refresh_token()
Jun 27 01:43:33 base redlib[4038062]:  INFO  redlib::oauth  > [✅] Success - Retrieved token "eyJhbGciOiJSUzI1NiIsImtpZCI6IlNI...", expires in 86399
Jun 27 01:43:33 base redlib[4038062]:  INFO  redlib::oauth  > Refreshing OAuth token... success
Jun 27 01:43:33 base redlib[4038062]:  WARN  redlib::client > Rate limit 8 is low. Spawning force_refresh_token()
Jun 27 01:43:33 base redlib[4038062]:  INFO  redlib::oauth  > [✅] Success - Retrieved token "eyJhbGciOiJSUzI1NiIsImtpZCI6IlNI...", expires in 86399
Jun 27 01:43:33 base redlib[4038062]:  INFO  redlib::oauth  > Refreshing OAuth token... success
Jun 27 01:47:35 base redlib[4038062]:  WARN  redlib::client > Rate limit 9 is low. Spawning force_refresh_token()
Jun 27 01:47:35 base redlib[4038062]:  WARN  redlib::client > Rate limit 8 is low. Spawning force_refresh_token()

I think it needs timeout for token retrieving.

And restarting fixed it.

[sigaloid]

Could be an issue with the atomic/concurrent nature of the token retrieval. Would appreciate if you could test after #158 to see if it has any difference

[freedit-dev]

Wow! Quick fix.

Deployed.

https://uptime.freedit.eu/status/up

[freedit-dev]

@sigaloid hang again

Jun 27 02:39:12 base redlib[4049503]:  TRACE redlib::client > Ratelimit remaining: 11.0
Jun 27 02:39:12 base redlib[4049503]:  TRACE redlib::client > Ratelimit used: 89
Jun 27 02:39:12 base redlib[4049503]:  TRACE redlib::client > Ratelimit reset: 48
Jun 27 02:39:14 base redlib[4049503]:  TRACE redlib::client > Ratelimit remaining: 10.0
Jun 27 02:39:14 base redlib[4049503]:  TRACE redlib::client > Ratelimit used: 90
Jun 27 02:39:14 base redlib[4049503]:  TRACE redlib::client > Ratelimit reset: 45
Jun 27 02:39:18 base redlib[4049503]:  TRACE redlib::client > Ratelimit remaining: 9.0
Jun 27 02:39:18 base redlib[4049503]:  TRACE redlib::client > Ratelimit used: 91
Jun 27 02:39:18 base redlib[4049503]:  TRACE redlib::client > Ratelimit reset: 41
Jun 27 02:39:18 base redlib[4049503]:  WARN  redlib::client > Rate limit 9 is low. Spawning force_refresh_token()
Jun 27 02:39:18 base redlib[4049503]:  TRACE redlib::oauth  > Rolling over refresh token. Current rate limit: 99

[sigaloid]

Hm. Okay, I see.

Side note, really funny that cloudflare's message here uses Redlib's CSS styling.

I'm going to work on trying to reproduce this locally first, some kind of load tester.

[freedit-dev]

Maybe you should not use async rwlock, using std rwlock instead.

[sigaloid]

I don't think it's a synchronization issue. It syncs on mine when I simulate high load.

I don't know what exactly the problem is - you're saying it's hanging precisely after the line "TRACE redlib::oauth > Rolling over refresh token. Current rate limit: 99"? Nothing else?

If so, it sounds like you cannot retrieve new tokens for some reason, by method of an automatic refresh. Which makes no sense - it's generating one every time you start it, and a refresh should be no different than restarting the program.

[sigaloid]

here's an example of my log output:

 TRACE redlib::client > Ratelimit remaining: 9.0
 TRACE redlib::client > Ratelimit used: 91
 TRACE redlib::client > Ratelimit reset: 103
 WARN  redlib::client > Rate limit 9 is low. Spawning force_refresh_token()
 TRACE redlib::oauth  > Rolling over refresh token. Current rate limit: 99
 INFO  redlib::oauth  > [✅] Success - Retrieved token "eyJhbGciOiJSUzI1NiIsImtpZCI6IlNI...", expires in 86399
 INFO  redlib::oauth  > Refreshing OAuth token... success
 TRACE redlib::client > Ratelimit remaining: 8.0
 TRACE redlib::client > Ratelimit used: 92
 TRACE redlib::client > Ratelimit reset: 102
 TRACE redlib::client > Ratelimit remaining: 5.0
 TRACE redlib::client > Ratelimit used: 95
 TRACE redlib::client > Ratelimit reset: 102
 TRACE redlib::client > Ratelimit remaining: 7.0
 TRACE redlib::client > Ratelimit used: 93
 TRACE redlib::client > Ratelimit reset: 102
 TRACE redlib::client > Ratelimit remaining: 6.0
 TRACE redlib::client > Ratelimit used: 94
 TRACE redlib::client > Ratelimit reset: 102
 WARN  redlib::client > Rate limit 6 is low. Spawning force_refresh_token()
 TRACE redlib::oauth  > Rolling over refresh token. Current rate limit: 99
 INFO  redlib::oauth  > [✅] Success - Retrieved token "eyJhbGciOiJSUzI1NiIsImtpZCI6IlNI...", expires in 86399
 INFO  redlib::oauth  > Refreshing OAuth token... success
 TRACE redlib::client > Ratelimit remaining: 3.0

Besides the occasional fact that a response may take longer to retrieve and the really small rate limits right before a refresh might accidentally overwrite the rate limit, my refreshing works just fine.

[freedit-dev]

Yes, it's occasional. And it hang exactly TRACE redlib::oauth > Rolling over refresh token. Current rate limit: 99, nothing else. And restarting always fixed it.

Jun 27 03:36:31 base redlib[4054219]:  WARN  redlib::client > Rate limit 8 is low. Spawning force_refresh_token()
Jun 27 03:36:31 base redlib[4054219]:  TRACE redlib::oauth  > Rolling over refresh token. Current rate limit: 99
Jun 27 03:36:31 base redlib[4054219]:  INFO  redlib::oauth  > [✅] Success - Retrieved token "eyJhbGciOiJSUzI1NiIsImtpZCI6IlNI...", expires in 86399
Jun 27 03:36:31 base redlib[4054219]:  INFO  redlib::oauth  > Refreshing OAuth token... success
Jun 27 03:36:31 base redlib[4054219]:  TRACE redlib::client > Ratelimit remaining: 7.0
Jun 27 03:36:31 base redlib[4054219]:  TRACE redlib::client > Ratelimit used: 93
Jun 27 03:36:31 base redlib[4054219]:  TRACE redlib::client > Ratelimit reset: 208
Jun 27 03:36:34 base redlib[4054219]:  WARN  redlib::client > Rate limit 7 is low. Spawning force_refresh_token()
Jun 27 03:36:34 base redlib[4054219]:  TRACE redlib::oauth  > Rolling over refresh token. Current rate limit: 99
Jun 27 03:36:34 base redlib[4054219]:  INFO  redlib::oauth  > [✅] Success - Retrieved token "eyJhbGciOiJSUzI1NiIsImtpZCI6IlNI...", expires in 86399
Jun 27 03:36:34 base redlib[4054219]:  INFO  redlib::oauth  > Refreshing OAuth token... success
Jun 27 03:36:34 base redlib[4054219]:  TRACE redlib::client > Ratelimit remaining: 99.0
Jun 27 03:36:34 base redlib[4054219]:  TRACE redlib::client > Ratelimit used: 1
Jun 27 03:36:34 base redlib[4054219]:  TRACE redlib::client > Ratelimit reset: 205
Jun 27 03:36:39 base redlib[4054219]:  TRACE redlib::client > Ratelimit remaining: 99.0

I just wanted to say that maybe we should have better logs to diagnose whether it is caused by "async rwlock" or "token retriving timeout".

[freedit-dev]

I just add more log and it stuck here

redlib/src/oauth.rs

Line 74 in 3bd8b51

let resp = client.request(request).await.ok()?;

And restarting fixed it.