Conversation
jeherve
left a comment
There was a problem hiding this comment.
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 fullREFRESH_LOCK_TTLand 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?
|
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:
The new tests write to the database directly, not through 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? |
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:
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.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:
Testing instructions:
npm run env-test -- --filter=Test_Client_RefreshWP_DEBUG_LOG, connect to Bluesky and leave it running for a week or two.grep "\[atmosphere\]" debug.log | grep -i refreshshould not showRefresh token replayedanymore.Changelog entry
Added manually in
.github/changelog/fix-refresh-lost-on-slow-response.