You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
On a LAPI whose decisions table has a large expired backlog, a bouncer that has never completed a pull makes GET /v1/decisions/stream scan the entire expired decision set instead of a delta window. On a production LAPI (~2.2M rows in decisions, ~50k active) a single such request took 26-37 minutes of wall-clock at ~700% CPU, versus 1.5-4.5s for the same request from a bouncer whose last_pull is populated.
bouncers.last_pull is nullable and starts NULL for a newly registered bouncer (pkg/database/ent/schema/bouncer.go):
A non-startup ("delta") stream request derives the bound for its deleted set from it — pkg/apiserver/controllers/v1/decisions.go:339-346:
// Use a 2-second overlap to avoid missing decisions that expired around the last pull timevarexpiredSince*time.TimeifbouncerInfo.LastPull!=nil {
since:=bouncerInfo.LastPull.Add(-2*time.Second)
expiredSince=&since
}
err=writeDeltaDecisions(gctx, now, filters, expiredSince, c.DBClient.QueryExpiredDecisionsSinceWithFilters)
and pkg/database/decisions.go:168-182:
query:=c.Ent.Decision.Query().
Select(...).
Where(decision.UntilLT(now))
ifsince!=nil {
query=query.Where(decision.UntilGT(*since)) // <-- only bounded when since != nil
}
ifv, ok:=filter["dedup"]; !ok||v[0] !="false" {
query=query.Where(longestDecisionForScopeTypeValue)
}
When since is nil the lower bound on until disappears and the query silently changes meaning from "what expired since your last pull" to "everything that ever expired" — every one of those rows then going through the longestDecisionForScopeTypeValue correlated self-anti-join (pkg/database/decisions.go:141-166).
A bouncer with last_pull NULL has, by definition, never received a decision from this LAPI, so its deleted set is empty by construction. The entire result of that query is discarded work.
The generated SQL for the nil case (verbatim, captured by instrumenting the ent driver) is:
SELECT`decisions`.`id`, `decisions`.`until`, `decisions`.`scenario`, `decisions`.`scope`,
`decisions`.`value`, `decisions`.`type`, `decisions`.`origin`, `decisions`.`uuid`FROM`decisions`LEFT JOIN`decisions`AS`t1`ON`t1`.`value`=`decisions`.`value`AND`t1`.`type`=`decisions`.`type`AND`t1`.`scope`=`decisions`.`scope`AND`t1`.`until`>`decisions`.`until`WHERE ((`decisions`.`until`< ? AND`t1`.`until` IS NULL) AND NOT `decisions`.`simulated`)
AND`decisions`.`scope`IN (?, ?)
ORDER BY`decisions`.`id`ASCLIMIT30000
which is byte-identical to the startup=true deleted-set query. With last_pull set, the same statement gains AND decisions.until > ? and is served from the decision_until index.
Note also that LIMIT 30000 bounds output rows, not scanned rows. With ~33.8k rows surviving the anti-join out of ~2.15M candidates, producing one page requires grinding through nearly the whole table, and writeDeltaDecisions paginates by appending AND decisions.id > ?.
Why it persists
last_pull is written only when the whole response succeeded (pkg/apiserver/controllers/v1/decisions.go:386-393), so a bouncer whose HTTP client gives up during the multi-minute response can retry into the same query. In practice the server-side computation usually runs to completion after client disconnect and does write last_pull (UpdateBouncerLastPull deliberately uses context.Background()), so a fleet does self-cure — but at a few bouncers per half hour while the LAPI is CPU-saturated. On the affected deployment, 28 of 35 bouncers were still at last_pull IS NULL.
Measurements
Statements executed directly against the DB file, read-only, outside Go, 120s cap. Two deployments with near-identical data (~2.2M rows in decisions, ~50k active, ~25.5k distinct (value, type, scope), i.e. ~84 rows per value from a recurring blocklist import with flush.max_age: 7d):
statement
host A (Xeon E3-1245v2)
host B (i9-12900K)
delta deleted, since NULL (unbounded), page 1
INTERRUPTED at 120s
30,000 rows in 44.9s
same, with id > 1000000 cursor (page 2)
INTERRUPTED at 120s
30,000 rows in 45.2s
delta deleted, since set (1h window)
2 rows in 1.27s
510 rows in 0.84s
startup "new"
25,504 rows in 5.53s
25,554 rows in 1.37s
EXPLAIN QUERY PLAN is identical on both hosts (SCAN decisions + SEARCH t1 USING INDEX decision_value), and sqlite_stat1 exists on neither — this is not a planner divergence, only the missing lower bound. The ~700% CPU is several of these queries running concurrently for different stuck bouncers.
Regression
Introduced by #3020 (commit 44a2014f, "db: don't set bouncer last_pull until first connection"), first released in v1.6.3. That PR changed since from a value to a pointer and made the predicate conditional in the same commit. Before it:
The same PR did guard the other code path — StreamDecisionNonChunked was given since := time.Time{} and passed &since, so the predicate at least still existed there. When #4413 made chunked transfer the default and removed the non-chunked path in the 1.7 line, the only remaining path became the one that passes a true nil.
What did you expect to happen?
A bouncer that has never completed a pull should not receive a deleted set at all — it holds no decisions, so there is nothing to remove — and the request should not scan the whole decisions table.
How can we reproduce it (as minimally and precisely as possible)?
Run a LAPI with a large expired-decision backlog, e.g. a recurring cscli decisions import of a ~50k-entry blocklist with flush.max_age: 7d, giving ~2M expired rows.
Register a fresh bouncer, so bouncers.last_pull IS NULL:
sqlite3 /var/lib/crowdsec/data/crowdsec.db "select name, last_pull from bouncers;"
Issue a delta pull (note: no startup parameter — DecisionsStreamOpts.Startup is tagged url:"startup,omitempty", so its absence means startup=false):
Observe one core pinned for minutes and a deleted list containing the whole deduplicated expired set. Repeat from a bouncer with a populated last_pull for the fast comparison.
A unit-level reproduction is included in the linked PR (TestStreamDeltaFirstPull in pkg/apiserver/decisions_test.go): insert alert_minibulk.json, expire one of the two decisions, and do a delta pull with a bouncer whose last_pull is still NULL. Before the fix the deleted list is non-empty. Note that every existing stream test uses startup=true, so the delta path currently has no test coverage at all.
Anything else we need to know?
Workaround for operators (no code change, applies today)
The dedup anti-join joins on (value, type, scope) plus a range on until, but the only supporting index is decision_value(value) — so the inner lookup fetches and filters every sibling row sharing a value, and cost grows roughly as SUM(rows_per_value ^ 2). Adding a matching index makes the unbounded query survivable while waiting for a release:
CREATEINDEXIF NOT EXISTS idx_decisions_dedup ON decisions(value, type, scope, until);
ANALYZE;
Measure the improvement with:
EXPLAIN QUERY PLAN <the statement above>;
-- the anti-join probe count, i.e. the actual work:SELECTSUM(c*c) FROM (SELECTCOUNT(*) c FROM decisions GROUP BY value, type, scope);
Three caveats worth knowing before relying on it:
It survives restarts and ordinary upgrades.pkg/database/database.go calls client.Schema.Create(ctx) with no options, and ent's WithDropIndex defaults to false, so ent will not drop an index it does not know about (dialect/sql/schema/atlas.go, skip := DropIndex | DropColumn).
It does NOT survive a table rebuild. On SQLite, a non-alterable schema change (column type, nullability, drop, PK/constraint) makes atlas rebuild the table — ariga.io/atlas/sql/sqlite/migrate.gostate.modifyTable: create new_decisions, copy rows, DROP TABLE decisions, rename, then addIndexes(modify.T, indexes...) recreating only the ent-declared indexes. No DropIndex statement is emitted, so ent's filter never engages and the index disappears silently. Operators should make this an idempotent ensure-task and assert on it: SELECT count(*) FROM sqlite_master WHERE type='index' AND name='idx_decisions_dedup';
It fixes the constant factor, not the shape: the scan is still over every expired row, so cost still grows with flush.max_age.
Lowering flush.max_age also helps superlinearly, since the anti-join cost is roughly quadratic in re-imports per value.
Possible follow-ups (happy to split these out if you'd prefer separate issues)
The missing (value, type, scope, until) index is arguably a defect in its own right, independent of this bug — it would also speed up the ordinary bounded queries. It was not covered by the index audit in db: add some missing indexes #4435.
startup=true runs the same unbounded statement by construction (QueryExpiredDecisionsWithFilters, pkg/database/decisions.go:57, called from decisions.go:316), so a genuinely new bouncer still pays it once on that path. Whether the deleted set is meaningful at all for a client doing a full resync is a client-contract question I did not want to assume.
The two [tainted] markers are missing-postoverflow warnings on whitelist-good-actors; they are unrelated to this report. Nothing here is exercised at runtime, since DISABLE_AGENT=true.
Acquisition config
Details
N/A — LAPI-only deployment (DISABLE_AGENT=true), no acquisition is configured or read.
Config show
Details
Relevant stanzas only; the rest is elided, and org-unit names are redacted.
$ cscli config showLocal API Server: Listen URL: 0.0.0.0:8080 (published as :9921 via docker) mTLS: cert/key/CA under /etc/crowdsec/certs Allowed Agents OU : three org-unit names (redacted) Allowed Bouncers OU: three org-unit names (redacted) Trusted IPs: 127.0.0.1, ::1 Database: Type: sqlite | Path: /var/lib/crowdsec/data/crowdsec.db Max Open Conns: 200 | Decision Bulk Size: 2000 Flush age: 168h0m0s | Flush size: 10000
config.yaml.local additionally sets use_wal: true and prometheus.enabled: false. This file is byte-identical to the one on the unaffected comparison host.
Prometheus metrics
Details
Not available: prometheus.enabled was false during the incident and still is.
$ cscli metricsError: cscli metrics: prometheus is not enabled
Note for anyone reproducing: enabling prometheus also exposes pprof, since cmd/crowdsec/main.go blank-imports net/http/pprof onto http.DefaultServeMux and servePrometheus serves that mux. It works in LAPI-only mode (agentReady is signalled unconditionally when the agent is disabled). It was not needed here — the timings above were taken against the DB file directly.
Related custom configs versions (if applicable) : notification plugins, custom scenarios, parsers etc.
Details
Bouncers: crowdsec-firewall-bouncer v0.0.36, mTLS, ~35 instances.
Decision source: recurring cscli decisions import of a blocklist.de list (~50k entries).
What happened?
On a LAPI whose
decisionstable has a large expired backlog, a bouncer that has never completed a pull makesGET /v1/decisions/streamscan the entire expired decision set instead of a delta window. On a production LAPI (~2.2M rows indecisions, ~50k active) a single such request took 26-37 minutes of wall-clock at ~700% CPU, versus 1.5-4.5s for the same request from a bouncer whoselast_pullis populated.bouncers.last_pullis nullable and starts NULL for a newly registered bouncer (pkg/database/ent/schema/bouncer.go):A non-startup ("delta") stream request derives the bound for its deleted set from it —
pkg/apiserver/controllers/v1/decisions.go:339-346:and
pkg/database/decisions.go:168-182:When
sinceis nil the lower bound onuntildisappears and the query silently changes meaning from "what expired since your last pull" to "everything that ever expired" — every one of those rows then going through thelongestDecisionForScopeTypeValuecorrelated self-anti-join (pkg/database/decisions.go:141-166).A bouncer with
last_pullNULL has, by definition, never received a decision from this LAPI, so its deleted set is empty by construction. The entire result of that query is discarded work.The generated SQL for the nil case (verbatim, captured by instrumenting the ent driver) is:
which is byte-identical to the
startup=truedeleted-set query. Withlast_pullset, the same statement gainsAND decisions.until > ?and is served from thedecision_untilindex.Note also that
LIMIT 30000bounds output rows, not scanned rows. With ~33.8k rows surviving the anti-join out of ~2.15M candidates, producing one page requires grinding through nearly the whole table, andwriteDeltaDecisionspaginates by appendingAND decisions.id > ?.Why it persists
last_pullis written only when the whole response succeeded (pkg/apiserver/controllers/v1/decisions.go:386-393), so a bouncer whose HTTP client gives up during the multi-minute response can retry into the same query. In practice the server-side computation usually runs to completion after client disconnect and does writelast_pull(UpdateBouncerLastPulldeliberately usescontext.Background()), so a fleet does self-cure — but at a few bouncers per half hour while the LAPI is CPU-saturated. On the affected deployment, 28 of 35 bouncers were still atlast_pull IS NULL.Measurements
Statements executed directly against the DB file, read-only, outside Go, 120s cap. Two deployments with near-identical data (~2.2M rows in
decisions, ~50k active, ~25.5k distinct(value, type, scope), i.e. ~84 rows per value from a recurring blocklist import withflush.max_age: 7d):sinceNULL (unbounded), page 1id > 1000000cursor (page 2)sinceset (1h window)EXPLAIN QUERY PLANis identical on both hosts (SCAN decisions+SEARCH t1 USING INDEX decision_value), andsqlite_stat1exists on neither — this is not a planner divergence, only the missing lower bound. The ~700% CPU is several of these queries running concurrently for different stuck bouncers.Regression
Introduced by #3020 (commit
44a2014f, "db: don't set bouncer last_pull until first connection"), first released in v1.6.3. That PR changedsincefrom a value to a pointer and made the predicate conditional in the same commit. Before it:The same PR did guard the other code path —
StreamDecisionNonChunkedwas givensince := time.Time{}and passed&since, so the predicate at least still existed there. When #4413 made chunked transfer the default and removed the non-chunked path in the 1.7 line, the only remaining path became the one that passes a true nil.What did you expect to happen?
A bouncer that has never completed a pull should not receive a deleted set at all — it holds no decisions, so there is nothing to remove — and the request should not scan the whole
decisionstable.How can we reproduce it (as minimally and precisely as possible)?
cscli decisions importof a ~50k-entry blocklist withflush.max_age: 7d, giving ~2M expired rows.bouncers.last_pull IS NULL:startupparameter —DecisionsStreamOpts.Startupis taggedurl:"startup,omitempty", so its absence meansstartup=false):deletedlist containing the whole deduplicated expired set. Repeat from a bouncer with a populatedlast_pullfor the fast comparison.A unit-level reproduction is included in the linked PR (
TestStreamDeltaFirstPullinpkg/apiserver/decisions_test.go): insertalert_minibulk.json, expire one of the two decisions, and do a delta pull with a bouncer whoselast_pullis still NULL. Before the fix thedeletedlist is non-empty. Note that every existing stream test usesstartup=true, so the delta path currently has no test coverage at all.Anything else we need to know?
Workaround for operators (no code change, applies today)
The dedup anti-join joins on
(value, type, scope)plus a range onuntil, but the only supporting index isdecision_value(value)— so the inner lookup fetches and filters every sibling row sharing a value, and cost grows roughly asSUM(rows_per_value ^ 2). Adding a matching index makes the unbounded query survivable while waiting for a release:Measure the improvement with:
Three caveats worth knowing before relying on it:
pkg/database/database.gocallsclient.Schema.Create(ctx)with no options, and ent'sWithDropIndexdefaults to false, so ent will not drop an index it does not know about (dialect/sql/schema/atlas.go,skip := DropIndex | DropColumn).ariga.io/atlas/sql/sqlite/migrate.gostate.modifyTable: createnew_decisions, copy rows,DROP TABLE decisions, rename, thenaddIndexes(modify.T, indexes...)recreating only the ent-declared indexes. NoDropIndexstatement is emitted, so ent's filter never engages and the index disappears silently. Operators should make this an idempotent ensure-task and assert on it:SELECT count(*) FROM sqlite_master WHERE type='index' AND name='idx_decisions_dedup';flush.max_age.Lowering
flush.max_agealso helps superlinearly, since the anti-join cost is roughly quadratic in re-imports per value.Possible follow-ups (happy to split these out if you'd prefer separate issues)
(value, type, scope, until)index is arguably a defect in its own right, independent of this bug — it would also speed up the ordinary bounded queries. It was not covered by the index audit in db: add some missing indexes #4435.startup=trueruns the same unbounded statement by construction (QueryExpiredDecisionsWithFilters,pkg/database/decisions.go:57, called fromdecisions.go:316), so a genuinely new bouncer still pays it once on that path. Whether the deleted set is meaningful at all for a client doing a full resync is a client-contract question I did not want to assume.sqlite3_stepcall). A server-side statement timeout would bound both.Crowdsec version
Details
OS version
Details
Running in docker:
ghcr.io/crowdsecurity/crowdsec:v1.7.8-slim, withDISABLE_AGENT=true(LAPI-only),DISABLE_ONLINE_API=true,USE_TLS=true.Enabled collections and parsers
Details
Stock hub content is present even though the agent is disabled (152 parsers / 767 scenarios / 145 collections available). Enabled items:
The two
[tainted]markers are missing-postoverflow warnings onwhitelist-good-actors; they are unrelated to this report. Nothing here is exercised at runtime, sinceDISABLE_AGENT=true.Acquisition config
Details
N/A — LAPI-only deployment (
DISABLE_AGENT=true), no acquisition is configured or read.Config show
Details
Relevant stanzas only; the rest is elided, and org-unit names are redacted.
config.yaml.localadditionally setsuse_wal: trueandprometheus.enabled: false. This file is byte-identical to the one on the unaffected comparison host.Prometheus metrics
Details
Not available:
prometheus.enabledwasfalseduring the incident and still is.Note for anyone reproducing: enabling prometheus also exposes pprof, since
cmd/crowdsec/main.goblank-importsnet/http/pprofontohttp.DefaultServeMuxandservePrometheusserves that mux. It works in LAPI-only mode (agentReadyis signalled unconditionally when the agent is disabled). It was not needed here — the timings above were taken against the DB file directly.Related custom configs versions (if applicable) : notification plugins, custom scenarios, parsers etc.
Details
Bouncers: crowdsec-firewall-bouncer v0.0.36, mTLS, ~35 instances.
Decision source: recurring
cscli decisions importof a blocklist.de list (~50k entries).