apiserver: don't query expired decisions for a bouncer that never pulled

[nikosch86]

Fixes #4613

What

A bouncer that has never completed a pull has bouncers.last_pull = NULL. In the delta branch of the decision stream, expiredSince is then left nil, and QueryExpiredDecisionsSinceWithFilters skips its until lower bound entirely:

if since != nil {
    query = query.Where(decision.UntilGT(*since))
}

so the query degrades from "what expired since your last pull" to "everything that ever expired", with every row passing through the longestDecisionForScopeTypeValue self-anti-join.

Such a bouncer holds no decision from this LAPI, so its deleted set is empty by construction — the whole result is discarded work. This skips the query instead of running it.

Impact

On a production LAPI with ~2.2M rows in decisions (~50k active, ~25.5k distinct (value, type, scope)), a single delta pull from a bouncer with last_pull IS NULL took 26-37 minutes at ~700% CPU, against 1.5-4.5s for the same request from a bouncer with last_pull populated. Run directly against the DB file, one 30,000-row page of the unbounded statement takes ~45s on an i9-12900K and over 120s on a Xeon E3-1245v2, while the bounded form returns in ~1s. EXPLAIN QUERY PLAN is identical in both cases and sqlite_stat1 is absent, so this is the missing predicate rather than a planner divergence.

It is also somewhat self-sustaining: last_pull is only written on a fully successful response, so a bouncer whose client times out during the multi-minute response can retry into the same query.

Regression

Introduced by #3020 (44a2014f), released in v1.6.3, which turned since into a pointer and made the predicate conditional in the same commit. That PR did guard the other path — StreamDecisionNonChunked passed &time.Time{} rather than nil — but #4413 later removed that path, leaving only the one that passes nil.

Test

Adds TestStreamDeltaFirstPull. Every existing stream test uses startup=true, so the delta path had no coverage at all; this covers both the first-pull case and the ordinary delta that follows it.

The test is red on master and green with the fix:

--- FAIL: TestStreamDeltaFirstPull (0.37s)
        Error: Should be empty, but was [0x31cdd7d91b00]

Locally: go test ./pkg/apiserver/... ./pkg/database/... passes, go vet and gofmt are clean. I was not able to run golangci-lint (not installed on this machine), so CI is the first full lint pass.

Not in scope

Two related things I deliberately left out, both noted in the issue:

• startup=true runs the same unbounded statement by construction (QueryExpiredDecisionsWithFilters has no since parameter). Whether a client doing a full resync needs a deleted set at all is a contract question I did not want to assume.
• The anti-join joins on (value, type, scope) + a range on until while the only supporting index is (value). Adding index.Fields("value", "type", "scope", "until") speeds up every stream query including the bounded ones — applied as a manual index on the affected host it took the unbounded statement from >120s to 12.74s per page, and the end-to-end first sync from 26-37 min to 71s. It is an independent change and belongs in its own PR — happy to open it if you want it.

[github-actions]

@nikosch86: There are no 'kind' label on this PR. You need a 'kind' label to generate the release automatically.

• /kind feature
• /kind enhancement
• /kind refactoring
• /kind fix
• /kind chore
• /kind dependencies

Details

I am a bot created to help the crowdsecurity developers manage community feedback and contributions. You can check out my manifest file to understand my behavior and what I can do. If you want to use this for your project, you can check out the BirthdayResearch/oss-governance-bot repository.

[github-actions]

@nikosch86: There are no area labels on this PR. You can add as many areas as you see fit.

• /area agent
• /area local-api
• /area cscli
• /area appsec
• /area security
• /area configuration

Details

I am a bot created to help the crowdsecurity developers manage community feedback and contributions. You can check out my manifest file to understand my behavior and what I can do. If you want to use this for your project, you can check out the BirthdayResearch/oss-governance-bot repository.

[nikosch86]

/kind fix

[nikosch86]

/area local-api

[codecov]

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 64.27%. Comparing base (f1bc9db) to head (172956f).
⚠️ Report is 3 commits behind head on master.

Additional details and impacted files

@@            Coverage Diff             @@
##           master    #4614      +/-   ##
==========================================
+ Coverage   64.21%   64.27%   +0.06%     
==========================================
  Files         520      520              
  Lines       39657    39655       -2     
==========================================
+ Hits        25465    25490      +25     
+ Misses      11805    11786      -19     
+ Partials     2387     2379       -8     

Flag	Coverage Δ
bats	41.37% <28.57%> (+<0.01%)	⬆️
unit-linux	41.31% <100.00%> (+0.18%)	⬆️
unit-windows	29.89% <100.00%> (+0.19%)	⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Harness.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:

• ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

[blotus]

/kind fix
/area local-api

[buixor]

Hello @nikosch86 ! Thanks for the PR and the idea is relevant. However :

startup=true runs the same unbounded statement by construction (QueryExpiredDecisionsWithFilters has no since parameter). Whether a client doing a full resync needs a deleted set at all is a contract question I did not want to assume.

As any bouncer first's request will have a startup=true, you will always hit this path first, I'm afraid the patch wouldn't do what you hope for.

Did you have a chance to test it in real life ? I think as-is what would happen is:

• first pull has startup=true, goes to the expensive codepath, sets a last_pull
• further pulls have non-nil last_pull

One thing to consider is how to avoid breaking behavior for k8s and similar environments, where a bouncer changing IP would get a new entry in the database (bouncer@IP) and end up with a nil last_pull.

I don't have a ideal solution to suggest right now, this might needs further thinking/iteration.

PS: Please let's keep the conversation between humans to limit verbosity 😃
PPS: The cpu cycles / time spent you mention seems off the charts, something else might be wrong in your setup.

[nikosch86]

Hi @buixor

I reviewed everything again (by hand, not with some AI).
First of all, yes, all reproduced on production with our cluster, fixes tested on the cluster live.

I found an issue that is basically the corner stone of why we ran into this, our blocklist import was not differential, so 25k new lines have been added and 25k old lines expired every cycle, that leads to a big delta of blocks that need to be expired when a bouncer connects on the expensive code path and has no last_pull set (because the LAPI DB does not know it yet).
So while this is still a problem, we would not have ran into this if it wasn't for the way the blocklists are imported.

To clarify the intention of the fix: when last_pull is null, skip the deleted decisions query, the bouncer has not been seen before, so it has nothing to delete.

A different approach that I tested on the cluster would be to not skip the deleted decisions but introduce a time window, eg until > now - W so the scan is cheaper.

Apart from code changes I also tried adding an index:

  func (Decision) Indexes() []ent.Index {
        return []ent.Index{
                index.Fields("start_ip", "end_ip"),
                index.Fields("value"),
                index.Fields("until"),
                index.Fields("alert_decisions"),
                index.Fields("value", "type", "scope", "until"),   // <- new
        }
  }

baseline first pull: 446s
with cheap path: 13s
No fix but added index: 69s
windowed approach: 14s
fix with index: 2.46s

[blotus]

Hello,

I've opened #4619 to add the index you mentioned (plus another one, and a small optimisation to compensate for the write slowdown due to the new index).

I'm still trying to understand how this PR had any impact in your environment: in the linked issue, you mention using the firewall bouncer, which will always send startup=true on the 1st request.

Do those bouncers change IP when they query LAPI (proxy, network change at runtime, ...) ?
A bouncer using a never-seen-before IP is considered a new one and gets a new database entry with
a nil last_pull. Same if the entry was removed by cscli bouncers prune or bouncers_autodelete and then recreated.

Could you check in the LAPI logs if you have any entries matching Creating bouncer .... or unable to update bouncer ... ?