Commit e4a8dbca1ac5
tarball3 files changed+169-52
@@ -14,7 +14,7 @@
1414
1515
use std::{1616
future::Future,17
- sync::{Arc, atomic::AtomicU64},17
+ sync::{Arc, Mutex as StdMutex, PoisonError, atomic::AtomicU64},1818
time::Duration,1919
};2020
@@ -103,6 +103,21 @@ where
103103
}104104
}105105
106
+/// The step a room's cache creation is on, so a creation that never finishes says where.107
+#[derive(Default)]108
+pub(super) struct CreationStep(StdMutex<&'static str>);109
+110
+impl CreationStep {111
+ pub(super) fn at(&self, room_id: &RoomId, step: &'static str) {112
+ debug!(%room_id, step, "room caches creation step");113
+ *self.0.lock().unwrap_or_else(PoisonError::into_inner) = step;114
+ }115
+116
+ pub(super) fn current(&self) -> &'static str {117
+ *self.0.lock().unwrap_or_else(PoisonError::into_inner)118
+ }119
+}120
+106121
/// A type to hold all the caches for a given room.107122
#[derive(Debug)]108123
pub(super) struct Caches {@@ -111,6 +126,7 @@ pub(super) struct Caches {
111126
112127
impl Caches {113128
/// Create a new [`Caches`].129
+ #[allow(clippy::too_many_arguments)]114130
pub async fn new(115131
weak_client: &WeakClient,116132
room_id: &RoomId,@@ -119,6 +135,7 @@ impl Caches {
119135
auto_shrink_sender: mpsc::Sender<OwnedRoomId>,120136
store: EventCacheStoreLock,121137
automatic_pagination: Option<AutomaticPagination>,138
+ step: &CreationStep,122139
) -> Result<Self> {123140
let Some(client) = weak_client.get() else {124141
return Err(EventCacheError::ClientDropped);@@ -156,9 +173,11 @@ impl Caches {
156173
pagination_status.clone(),157174
generation.clone(),158175
automatic_pagination,176
+ step,159177
)160178
.await?;161179
180
+ step.at(room_id, "reading the loaded state");162181
let timeline_is_not_empty =163182
room_state.read().await?.room_linked_chunk().revents().next().is_some();164183
@@ -323,7 +323,9 @@ impl LockedRoomEventCacheState {
323323
pagination_status: SharedObservable<SharedPaginationStatus>,324324
generation: Arc<AtomicU64>,325325
automatic_pagination: Option<AutomaticPagination>,326
+ step: &super::super::CreationStep,326327
) -> Result<Self, EventCacheError> {328
+ step.at(&room_id, "taking the store lock");327329
let store_guard = match store.lock().await? {328330
// Lock is clean: all good!329331
EventCacheStoreLockState::Clean(guard) => guard,@@ -345,6 +347,7 @@ impl LockedRoomEventCacheState {
345347
// indicates that at some point, there's some malformed data.346348
// a storage error can be transient (an IndexedDB transaction aborted under us), and the347349
// clear below throws away the room's whole history, so read once more before trusting it350
+ step.at(&room_id, "loading the linked chunk metadata");348351
let metadata = match super::super::read_store("linked chunk metadata", || {349352
load_linked_chunk_metadata(&store_guard, linked_chunk_id)350353
})@@ -362,6 +365,7 @@ impl LockedRoomEventCacheState {
362365
error!("error when loading a linked chunk's metadata from the store: {err}");363366
364367
// Try to clear storage for this room.368
+ step.at(&room_id, "clearing a malformed linked chunk");365369
store_guard366370
.handle_linked_chunk_updates(linked_chunk_id, vec![Update::Clear])367371
.await?;@@ -371,6 +375,7 @@ impl LockedRoomEventCacheState {
371375
}372376
};373377
378
+ step.at(&room_id, "loading the latest chunk");374379
let last_chunk = match super::super::read_store("latest chunk", || {375380
store_guard.load_last_chunk(linked_chunk_id)376381
})@@ -393,6 +398,7 @@ impl LockedRoomEventCacheState {
393398
error!("error when loading a linked chunk's latest chunk from the store: {err}");394399
395400
// Try to clear storage for this room.401
+ step.at(&room_id, "clearing an unreadable linked chunk");396402
store_guard397403
.handle_linked_chunk_updates(linked_chunk_id, vec![Update::Clear])398404
.await?;@@ -30,7 +30,11 @@
3030
use std::{3131
collections::HashMap,3232
fmt,33
- sync::{Arc, OnceLock, RwLock as StdRwLock, RwLockReadGuard, RwLockWriteGuard},33
+ sync::{34
+ Arc, Mutex as StdMutex, OnceLock, PoisonError, RwLock as StdRwLock, RwLockReadGuard,35
+ RwLockWriteGuard,36
+ atomic::{AtomicBool, AtomicU64, Ordering},37
+ },3438
time::Duration,3539
};3640
@@ -50,7 +54,7 @@ use tokio::sync::{
5054
broadcast::{Receiver, Sender, channel},5155
mpsc, watch,5256
};53
-use tracing::{debug, error, instrument, trace};57
+use tracing::{debug, error, instrument, trace, warn};5458
5559
use crate::{5660
Client,@@ -148,8 +152,20 @@ pub enum EventCacheError {
148152
/// was cancelled by a runtime shutdown.149153
#[error("the event cache task did not complete: {0}")]150154
TaskInterrupted(String),155
+156
+ /// A room's caches were not created in time, twice.157
+ #[error("the caches of room {room_id} were not created in time, stuck {step}")]158
+ RoomCachesNotCreated {159
+ /// The room whose caches were not created.160
+ room_id: OwnedRoomId,161
+ /// The creation step the last attempt was on.162
+ step: &'static str,163
+ },151164
}152165
166
+/// How long creating one room's caches may take before the attempt is abandoned.167
+const CREATION_WAIT: Duration = Duration::from_secs(10);168
+153169
/// A result using the [`EventCacheError`].154170
pub type Result<T> = std::result::Result<T, EventCacheError>;155171
@@ -228,6 +244,9 @@ impl EventCache {
228244
config: StdRwLock::new(EventCacheConfig::default()),229245
store: event_cache_store,230246
multiple_room_updates_lock: Default::default(),247
+ creation_gates: Default::default(),248
+ clears: Default::default(),249
+ dropped_room_updates: Default::default(),231250
room_updates_handled: watch::Sender::new(0),232251
by_room: Default::default(),233252
drop_handles: Default::default(),@@ -374,6 +393,9 @@ impl EventCache {
374393
if !self.has_subscribed() {375394
return true;376395
}396
+ if self.inner.dropped_room_updates.load(Ordering::SeqCst) {397
+ return false;398
+ }377399
let target = client.room_updates_sent();378400
let mut handled = self.inner.room_updates_handled.subscribe();379401
let waited = timeout(handled.wait_for(|handled| *handled >= target), limit).await;@@ -510,6 +532,16 @@ struct EventCacheInner {
510532
// TODO: that's the place to add a cross-process lock!511533
multiple_room_updates_lock: Mutex<()>,512534
535
+ /// One creation at a time per room, see [`EventCacheInner::all_caches_for_room`].536
+ creation_gates: StdMutex<HashMap<OwnedRoomId, Arc<Mutex<()>>>>,537
+538
+ /// How many times every room has been cleared.539
+ clears: AtomicU64,540
+541
+ /// Whether a room update was dropped because the room's caches couldn't be542
+ /// created, after which nothing counts as handled until a restart.543
+ dropped_room_updates: AtomicBool,544
+513545
/// How many of the client's [`RoomUpdates`] have been handled, counted in514546
/// the client's `room_updates_sent` terms.515547
room_updates_handled: watch::Sender<u64>,@@ -615,6 +647,7 @@ impl EventCacheInner {
615647
// will take turn to acquire it.616648
617649
let mut all_caches = self.by_room.write().await;650
+ self.clears.fetch_add(1, Ordering::SeqCst);618651
619652
// Prepare to reset all the caches: it ensures nobody is accessing or mutating620653
// them.@@ -652,9 +685,12 @@ impl EventCacheInner {
652685
653686
// Left rooms.654687
for (room_id, left_room_update) in updates.left {655
- let Ok(caches) = self.all_caches_for_room(&room_id).await else {656
- error!(?room_id, "Room must exist");657
- continue;688
+ let caches = match self.all_caches_for_room(&room_id).await {689
+ Ok(caches) => caches,690
+ Err(err) => {691
+ self.drop_room_update(&room_id, err);692
+ continue;693
+ }658694
};659695
660696
if let Err(err) = caches.handle_left_room_update(left_room_update).await {@@ -667,9 +703,12 @@ impl EventCacheInner {
667703
for (room_id, joined_room_update) in updates.joined {668704
trace!(?room_id, "Handling a `JoinedRoomUpdate`");669705
670
- let Ok(caches) = self.all_caches_for_room(&room_id).await else {671
- error!(?room_id, "Room must exist");672
- continue;706
+ let caches = match self.all_caches_for_room(&room_id).await {707
+ Ok(caches) => caches,708
+ Err(err) => {709
+ self.drop_room_update(&room_id, err);710
+ continue;711
+ }673712
};674713
675714
if let Err(err) = caches.handle_joined_room_update(joined_room_update).await {@@ -691,52 +730,105 @@ impl EventCacheInner {
691730
) -> Result<OwnedRwLockReadGuard<CachesByRoom, Caches>> {692731
// Fast path: the entry exists; let's acquire a read lock, it's cheaper than a693732
// write lock.694
- match OwnedRwLockReadGuard::try_map(self.by_room.clone().read_owned().await, |by_room| {733
+ if let Some(caches) = self.loaded_caches(room_id).await {734
+ return Ok(caches);735
+ }736
+737
+ // Slow-path: one creation per room at a time, run outside the room caches lock, so a738
+ // creation that never finishes holds up its own room only.739
+ let gate = self740
+ .creation_gates741
+ .lock()742
+ .unwrap_or_else(PoisonError::into_inner)743
+ .entry(room_id.to_owned())744
+ .or_default()745
+ .clone();746
+ debug!(%room_id, "waiting to create a room's caches");747
+ let _creating = gate.lock().await;748
+749
+ // In the meanwhile, some other caller might have done the same, so check for750
+ // existence again.751
+ if let Some(caches) = self.loaded_caches(room_id).await {752
+ return Ok(caches);753
+ }754
+755
+ let created = loop {756
+ let clears = self.clears.load(Ordering::SeqCst);757
+ let caches = match self.create_caches(room_id).await {758
+ Ok(caches) => caches,759
+ Err(err) => {760
+ self.creation_gates761
+ .lock()762
+ .unwrap_or_else(PoisonError::into_inner)763
+ .remove(room_id);764
+ return Err(err);765
+ }766
+ };767
+ let mut by_room = self.by_room.clone().write_owned().await;768
+ // a clear of every room that ran meanwhile wiped the store these caches were769
+ // loaded from770
+ if self.clears.load(Ordering::SeqCst) != clears {771
+ continue;772
+ }773
+ by_room.insert(room_id.to_owned(), caches);774
+ break by_room;775
+ };776
+ self.creation_gates.lock().unwrap_or_else(PoisonError::into_inner).remove(room_id);777
+ debug!(%room_id, "created a room's caches");778
+779
+ Ok(OwnedRwLockWriteGuard::try_downgrade_map(created, |by_room| by_room.get(room_id))780
+ .expect("`Caches` has just been inserted"))781
+ }782
+783
+ fn drop_room_update(&self, room_id: &RoomId, err: EventCacheError) {784
+ if matches!(err, EventCacheError::RoomCachesNotCreated { .. }) {785
+ // the update is gone, so no later `pos` may claim it was stored786
+ self.dropped_room_updates.store(true, Ordering::SeqCst);787
+ }788
+ error!(%room_id, "dropping a room update, its caches are unavailable: {err}");789
+ }790
+791
+ async fn loaded_caches(792
+ &self,793
+ room_id: &RoomId,794
+ ) -> Option<OwnedRwLockReadGuard<CachesByRoom, Caches>> {795
+ OwnedRwLockReadGuard::try_map(self.by_room.clone().read_owned().await, |by_room| {695796
by_room.get(room_id)696
- }) {697
- Ok(caches) => Ok(caches),698
-699
- Err(by_room_guard) => {700
- // Slow-path: the entry doesn't exist; let's acquire a write lock.701
- drop(by_room_guard);702
- debug!(%room_id, "waiting for the room caches lock to create a room's caches");703
- let by_room_guard = self.by_room.clone().write_owned().await;704
-705
- // In the meanwhile, some other caller might have obtained write access and done706
- // the same, so check for existence again.707
- let mut by_room_guard =708
- match OwnedRwLockWriteGuard::try_downgrade_map(by_room_guard, |by_room| {709
- by_room.get(room_id)710
- }) {711
- Ok(caches) => return Ok(caches),712
- Err(by_room_guard) => by_room_guard,713
- };714
-715
- debug!(%room_id, "creating a room's caches");716
- let caches = Caches::new(717
- &self.client,718
- room_id,719
- self.generic_update_sender.clone(),720
- self.linked_chunk_update_sender.clone(),721
- // SAFETY: we must have subscribed before reaching this code, otherwise722
- // something is very wrong.723
- self.auto_shrink_sender.get().cloned().expect(724
- "we must have called `EventCache::subscribe()` before calling here.",725
- ),726
- self.store.clone(),727
- self.automatic_pagination.get().cloned(),728
- )729
- .await?;730
- debug!(%room_id, "created a room's caches");731
-732
- by_room_guard.insert(room_id.to_owned(), caches);733
-734
- Ok(OwnedRwLockWriteGuard::try_downgrade_map(by_room_guard, |by_room| {735
- by_room.get(room_id)736
- })737
- .expect("`Caches` has just been inserted"))797
+ })798
+ .ok()799
+ }800
+801
+ /// Create a room's caches, abandoning an attempt that runs past [`CREATION_WAIT`] and802
+ /// trying once more.803
+ async fn create_caches(&self, room_id: &RoomId) -> Result<Caches> {804
+ let mut stuck = "";805
+ for attempt in 1..=2 {806
+ debug!(%room_id, attempt, "creating a room's caches");807
+ let step = caches::CreationStep::default();808
+ let creation = Caches::new(809
+ &self.client,810
+ room_id,811
+ self.generic_update_sender.clone(),812
+ self.linked_chunk_update_sender.clone(),813
+ // SAFETY: we must have subscribed before reaching this code, otherwise814
+ // something is very wrong.815
+ self.auto_shrink_sender816
+ .get()817
+ .cloned()818
+ .expect("we must have called `EventCache::subscribe()` before calling here."),819
+ self.store.clone(),820
+ self.automatic_pagination.get().cloned(),821
+ &step,822
+ );823
+ match timeout(creation, CREATION_WAIT).await {824
+ Ok(created) => return created,825
+ Err(_) => {826
+ stuck = step.current();827
+ warn!(%room_id, attempt, step = stuck, "a room's caches weren't created in time");828
+ }738829
}739830
}831
+ Err(EventCacheError::RoomCachesNotCreated { room_id: room_id.to_owned(), step: stuck })740832
}741833
}