Events based cache issues in SPIRE 1.11

[sorindumitru]

We’ve seen some issues over the weekend with the events based cache. Instances that have restarted have taken a lot of time to populate the cache and become available:

{"file":"authorized_entryfetcher.go:40","func":"[github.com/spiffe/spire/pkg/server/endpoints.NewAuthorizedEntryFetcherWithEventsBasedCache](https://github.com/spiffe/spire/pkg/server/endpoints.NewAuthorizedEntryFetcherWithEventsBasedCache)","level":"info","msg":"Building event-based in-memory entry cache","subsystem_name":"endpoints","time":"2025-01-11T14:13:56Z"}
{"file":"authorized_entryfetcher.go:45","func":"[github.com/spiffe/spire/pkg/server/endpoints.NewAuthorizedEntryFetcherWithEventsBasedCache](https://github.com/spiffe/spire/pkg/server/endpoints.NewAuthorizedEntryFetcherWithEventsBasedCache)","level":"info","msg":"Completed building event-based in-memory entry cache","subsystem_name":"endpoints","time":"2025-01-11T14:41:02Z"}

From the metrics I can tell this it spent this time fetching registration entries. Hydrating the cache seems to now:

1. Read all entries from the datastore
2. Read all events from the datastore
3. Read all entries associated with those events

In this case we had a large number of events, maybe ~500k, which meant the server was stuck here for ~30 minutes. Looking through the past logs I can see it taking multiple seconds or minutes before.

Additionally, we mark the fetched events as processed in

spire/pkg/server/endpoints/authorized_entryfetcher_registration_entries.go

Line 138 in a49eaad

a.lastEvent = event.EventID

, but later on we might completely bail on processing the entries associated with them due to the datastore returning an error in

spire/pkg/server/endpoints/authorized_entryfetcher_registration_entries.go

Line 230 in a49eaad

return err

. Since we then only fetch changed events from the last processed one, we might skip some entry updates.

The version of the events based cache we had in 1.10.4 doesn’t seem to have these issues. It would be worth considering reverting the latest changes to the cache since they only improve a small edge case (de-duplicating entries that might be created due to long running transactions started before the cache was hydrated; I can’t imagine there being more than a couple and usually 0 of these). #5509 is the change that would need to be reverted.

@amoore877, @stevend-uber tagging you here since I know you were also using the events based cache.

• Version: >= 1.11.0
• Platform: any
• Subsystem: server, agent

[stevend-uber]

@sorindumitru Unfortunately right now we are using the 1.10 version of SPIRE-Server and don't currently see that. We did very thorough testing of this exact scenario during the performance evaluation of the feature and confirm that this wasn't an issue in anything in prior to or including the 1.10 version of the events-based cache.

[sorindumitru]

@stevend-uber I believe this is only an issue starting with 1.11.0. That's where #5509 was included.

[faisal-memon]

Please assign this to me, Ill take a look

[faisal-memon]

Started looking into this. Prior to #5509 we had a workflow that did this at startup:

1. Got the last event id
2. Full read of all registration entries to load the cche
3. Start polling every 5 seconds for all events after the last event id at startup

Seems like #5509 inadvertently removed that first step so it just steps though all the stale events at startup.

[sorindumitru]

Seems like #5509 inadvertently removed that first step so it just steps though all the stale events at startup.

Yes, I think if we bring back that initial read of skipped events and last event id it should be ok from that regard. We likely also wouldn't need the "updateCache" call during the initial cache hydration.

There's also the return in

spire/pkg/server/endpoints/authorized_entryfetcher_registration_entries.go

Line 230 in a49eaad

return err

which makes it possible to not apply some updates. I think we could fix that by not clearing the map of entries to fetch at the beginning of the refresh (

spire/pkg/server/endpoints/authorized_entryfetcher_registration_entries.go

Line 44 in a49eaad

a.fetchEntries = make(map[string]struct{})

) and manually removing the entries that are succesfully fetched (which we already do in

spire/pkg/server/endpoints/authorized_entryfetcher_registration_entries.go

Line 248 in a49eaad

delete(a.fetchEntries, entryId)

). That would mean that failed entries will be retried on the next refresh.

[faisal-memon]

Thanks @sorindumitru for confirming my suspicions. Ill get started on a fix for the initial cache hydration.

Will look into the issues with refresh next.