Skip to content

Keep the Bluesky login when a renewal answer is slow - #281

Open
pfefferle wants to merge 3 commits into
trunkfrom
fix/refresh-lost-on-slow-response
Open

pfefferle wants to merge 3 commits into
trunkfrom
fix/refresh-lost-on-slow-response

Conversation

@pfefferle

Copy link
Copy Markdown
Member

Proposed changes:

notiz.blog still lost the Bluesky login about once a week, even with the long-lasting login from #272. The log shows why:

[29-Sep-2026 19:21:22 UTC] [atmosphere] token refresh failed: http_request_failed
[29-Sep-2026 20:21:05 UTC] [atmosphere] refresh rejected permanently (invalid_grant): Refresh token replayed

The refresh request timed out on our side after 15 seconds, but Bluesky had already processed it and rotated the refresh token. The plugin kept the old one, sent it again an hour later, and Bluesky treats a reused refresh token as a replay and deletes the whole session.

The log also has a lot of Token refresh did not complete in time, so refreshes on this host sometimes run longer than the 45 second lock. Then a second worker can take over the lock and send the same refresh token again, with the same result. That probably explains the replay on 26 Sep, which has no failed request before it.

  • Refresh requests wait 30 seconds instead of 15.
  • The refresh lock lives 90 seconds instead of 45 (two 30 second requests plus margin).
  • While the refresh holds the lock, the PHP time limit is raised to at least 90 seconds, so the process is not killed between the answer and saving the new token. It is never lowered, unlimited (WP-CLI) stays unlimited.

A retry does not help here, a retry after a lost answer is exactly what kills the session.

This does not make it impossible. If the connection drops after Bluesky answered, the new token is still lost. It should make it a lot rarer on slow hosts though.

Trade-off: a request that waits for a running refresh (wait_for_token_refresh()) can now block up to 90 seconds instead of 45. unlock() still deletes the lock without checking who owns it, that is unchanged.

Other information:

  • Have you written new tests for your changes, if applicable?

Testing instructions:

  • npm run env-test -- --filter=Test_Client_Refresh
  • On a real site: enable WP_DEBUG_LOG, connect to Bluesky and leave it running for a week or two. grep "\[atmosphere\]" debug.log | grep -i refresh should not show Refresh token replayed anymore.

Changelog entry

Added manually in .github/changelog/fix-refresh-lost-on-slow-response.

@pfefferle pfefferle self-assigned this Sep 29, 2026
@pfefferle
pfefferle requested a review from a team September 29, 2026 23:10
@github-actions github-actions Bot added [Feature] OAuth OAuth flow and authentication [Tests] Includes Tests PR includes test changes labels Sep 29, 2026

@jeherve jeherve left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I threw Claude at this PR, here are its findings.

I think there's an older bug hiding behind part of this though, and it may change what the 45s → 90s bump is fixing.

atmosphere_connection is never re-read from the database

The option is stored with autoload off, so the first get_option() in a process puts it in the options cache, and nothing in the plugin clears that entry afterwards. Every later get_option() in the same process gets the copy it loaded first. Most persistent object cache drop-ins keep their own in-request copy as well, so Redis doesn't save us here.

Two places rely on seeing another worker's write:

  • wait_for_token_refresh() polls every 100ms, but it can't see the new token the lock holder saves, so it always waits the full REFRESH_LOCK_TTL and then returns "Token refresh did not complete in time." If I'm reading this right, those lines in the notiz.blog log don't necessarily mean refreshes run past 45s; we'd see them even when every refresh is quick. With this PR, those requests now block for 90s before failing.
  • The re-read after taking the lock (includes/oauth/class-client.php:1013) returns the same cached row. A process that loaded the connection earlier and renews later (WP-cron running several events in one go, or a long WP-CLI backfill while web cron renews in parallel) would send a refresh token that was already rotated. That could explain the 26 Sep replay with no failed request before it.

A \wp_cache_delete( 'atmosphere_connection', 'options' ) before both reads should cover it, the same way invalidate_lock_option_cache() handles the lock row. The existing waiter tests go through pre_option_atmosphere_connection, which skips the cache, so we'd want a test where the "other worker" writes with a real update_option().

It predates this PR, but since it might be behind one of the two incidents, maybe we could fix it here? Once it's in, we can check whether 90s is still needed. What do you think?

@pfefferle

Copy link
Copy Markdown
Member Author

Thanks @jeherve, you were right. The waiter never saw the new token, and the re-read after the lock returned the same cached row. So the "did not complete in time" lines in the log came from this bug, and don't show that renewals run long.

I fixed it here in 51c22c0, and went a bit further, because the cache was only one part of it:

  • Every read that has to see a write from another process now clears the cache first. That covers the waiter, the re-read after the lock, and the checks that detect a disconnect mid-renewal. Older rows that are still autoloaded are covered too.
  • All writes to atmosphere_connection (refresh, marking reauth, the domain handle sync, disconnect) now go through a compare-and-swap. The row is only written if it still holds what was read. Before, the handle sync could overwrite a freshly rotated refresh token with the old one.
  • The lock knows its owner now. A holder whose lock ran out can't release the lock of the worker that took over, and it doesn't start a token request that could still be running when the lock expires.
  • If the connection changes while a renewal is running, the new tokens get revoked instead of staying valid at the auth server.

The new tests write to the database directly, not through pre_option, as you suggested. All of them fail without the fix.

I kept the 90s for now. The lock still has to cover two 30s requests on the nonce retry. For a waiting publish it doesn't matter much anymore, because it continues as soon as the new token is stored. What do you think?

@pfefferle
pfefferle requested review from a team and jeherve September 30, 2026 16:19
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

[Feature] OAuth OAuth flow and authentication [Tests] Includes Tests PR includes test changes

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants