Repository navigation
fix(search): log bleve's background errors - #3782
junkerderprovinz wants to merge 2 commits into
Conversation
The bleve index was opened without an async error callback, so errors from scorch's merger and persister were dropped. A corrupt segment then kept the merger rewriting the index with nothing in the logs. Log them, at most once a minute, since a failing merge retries several times a second. The retry loop itself stays until bleve backs off (blevesearch/bleve#2402). Fixes opencloud-eu#3594 Co-authored-by: Marosh <175698736+sykoramaros@users.noreply.github.com>
Not up to standards ⛔🔴 Issues
|
| Category | Results |
|---|---|
| Security | 1 critical |
🟢 Metrics 27 complexity
Metric Results Complexity 27
NEW Get contextual insights on your PRs based on Codacy's metrics, along with PR and Jira context, without leaving GitHub. Enable AI reviewer
TIP This summary will be updated as you push new changes.
dschmidt
left a comment
dschmidt
left a comment
There was a problem hiding this comment.
Thanks, this is the right fix for the silent half of #3594 and the maps.Clone reasoning checks out against bleve's newIndexUsing. Three things before merge:
1. Register the callback in init(), not on every NewIndex
scorch documents RegistryAsyncErrorCallbacks as read-only after process init, and NewScorch reads it without a lock. runtimeConfig writes it on every call, so a second concurrent NewIndex would race, and the function name hides the side effect. Suggestion: register once in the package's init() with a closure that reads the logger from a package-level atomic.Pointer[log.Logger] (or a small mutex-guarded struct), and let NewIndex only set that pointer. runtimeConfig then becomes a plain map again, and the repeated calls in the test suite stop rewriting the registry.
2. Sample per source and error type, never sample panics
One BurstSampler{Burst: 1, Period: 1m} is shared by everything, so a persister error (disk full, EIO) or a goroutine panic arriving within a minute of the looping merger error is dropped without a trace. The ScorchError you get already carries Source (merger, persister, introducer) and ErrType (persist, cleanup, async panic). Key the sampler on those two (bounded, at most nine keys, lazily created behind a mutex), log ErrAsyncPanic unsampled, and emit source and err_type as log fields. Each distinct failure then shows up immediately and only the identical retry loop is throttled.
3. Fixes vs Refs
The issue also asks for a metric or health signal. The metric half is cheap once you are inside the callback: a counter opencloud_search_bleve_async_errors_total{source, err_type} in services/search/pkg/metrics (same promauto pattern as the existing ones), incremented unsampled next to the sampled log line. If you add that, "Fixes" is fine for the log and metric part and I'll open a separate issue for the "mark unhealthy" question, which needs a policy decision (unready would take the whole search service out although queries still work). If you'd rather keep this PR to logging only, please change it to "Refs #3594".
scorch reads its callback registry without a lock when an index opens,
so the callback is registered once in init() and NewIndex only sets the
logger. A single sampler for all errors let the looping merger hide a
persister error or a panic, so sampling is now per source and error
type, and panics are never sampled. Every error also increments
opencloud_search_bleve_async_errors_total{source, err_type}.
|
Thanks for the careful review, all three points are in f377b4d. The callback is registered once in init(), and NewIndex only stores the logger in an atomic.Pointer, so nothing writes the registry after init. Sampling is keyed on source and error type, panics are never sampled, and every error increments opencloud_search_bleve_async_errors_total{source, err_type}. With the counter in place I kept "Fixes #3594"; the unhealthy question can go to your separate issue. |
Description
The search service opened its bleve index without an async error callback, so errors from scorch's merger, persister and introducer were dropped. The callback is registered once in the package's init(), because scorch reads its callback registry without a lock whenever an index opens; NewIndex only hands it the logger.
Errors are logged at error level with source, err_type and the index path. Logging is sampled to one line per minute for each source and error type, since a failing merge retries several times a second and that loop shouldn't hide a persister error. Panics are never sampled. Every error also increments
opencloud_search_bleve_async_errors_total{source, err_type}.The callback name is passed on every open, including creation (
bleve.Newbecamebleve.NewUsing), so a new index also stores it inindex_meta.json.Related Issue
This makes the problem visible but doesn't stop it: with a corrupt segment the merger still loops until bleve backs off (blevesearch/bleve#2402). Whether a failing index should mark the service unhealthy is left for the separate issue @dschmidt offered to open.
Motivation and Context
Thanks @sykoramaros for the thorough analysis and for pinning down the missing callback. This covers the logging and the metric you proposed.
How Has This Been Tested?
go test ./services/search/...andgo test -raceon the bleve, mapping, search and query packagesindex_meta.json; NewIndex leaves the registry alone; two indexes open at the same time without a race; a repeating error logs once while a different source or type logs right away; panics always log; the counter goes up per source and error typeTypes of changes
Checklist:
Claude Code helped with the investigation, the reproduction and the fix. I reviewed the change and take responsibility for it.
Assisted-by: Claude Code:claude-opus-5-5