Inconsistent Database: Threat List Mismatches

[TimothyBJacobs]

Hello!

We're using the sbserver binary. Over the past 24 hours we've been seeing a series of inconsistent database errors that seem to resolve themselves after a database fetch, but during that 30 minute time window every request generates an error.

Log Excerpt

``` safebrowsing: 2021/01/12 11:16:20 safebrowser.go:419: inconsistent database: safebrowsing: threat list SHA256 mismatch safebrowsing: 2021/01/12 11:16:21 safebrowser.go:419: inconsistent database: safebrowsing: threat list SHA256 mismatch safebrowsing: 2021/01/12 11:16:21 safebrowser.go:419: inconsistent database: safebrowsing: threat list SHA256 mismatch safebrowsing: 2021/01/12 11:16:24 database.go:389: database is now healthy safebrowsing: 2021/01/12 11:16:24 safebrowser.go:563: background threat list updated safebrowsing: 2021/01/12 11:16:24 safebrowser.go:557: Next update in 30m29s /* snipped */ safebrowsing: 2021/01/12 17:49:46 database.go:243: Server requested next update in 29m49.769s safebrowsing: 2021/01/12 17:49:46 database.go:257: update failure: safebrowsing: threat list SHA256 mismatch safebrowsing: 2021/01/12 17:49:46 safebrowser.go:557: Next update in 29m49.769s safebrowsing: 2021/01/12 17:49:46 safebrowser.go:419: inconsistent database: safebrowsing: threat list SHA256 mismatch safebrowsing: 2021/01/12 17:49:46 safebrowser.go:419: inconsistent database: safebrowsing: threat list SHA256 mismatch safebrowsing: 2021/01/12 17:49:46 safebrowser.go:419: inconsistent database: safebrowsing: threat list SHA256 mismatch ```

We also sometimes see this variation.

Log Excerpt

``` safebrowsing: 2021/01/12 18:19:36 safebrowser.go:419: inconsistent database: safebrowsing: threat list SHA256 mismatch safebrowsing: 2021/01/12 18:19:37 safebrowser.go:419: inconsistent database: safebrowsing: threat list SHA256 mismatch safebrowsing: 2021/01/12 18:19:37 database.go:243: Server requested next update in 29m56.277s safebrowsing: 2021/01/12 18:19:37 safebrowser.go:419: inconsistent database: safebrowsing: threat list SHA256 mismatch safebrowsing: 2021/01/12 18:19:37 safebrowser.go:419: inconsistent database: safebrowsing: threat list SHA256 mismatch safebrowsing: 2021/01/12 18:19:38 database.go:389: database is now healthy safebrowsing: 2021/01/12 18:19:39 safebrowser.go:563: background threat list updated safebrowsing: 2021/01/12 18:19:39 safebrowser.go:557: Next update in 29m56.277s safebrowsing: 2021/01/12 18:49:35 database.go:243: Server requested next update in 30m23.724s safebrowsing: 2021/01/12 18:49:38 safebrowser.go:563: background threat list updated safebrowsing: 2021/01/12 18:49:38 safebrowser.go:557: Next update in 30m23.724s safebrowsing: 2021/01/12 19:20:02 database.go:243: Server requested next update in 30m13.773s safebrowsing: 2021/01/12 19:20:02 database.go:248: invalid server response: got 0, want 3 threat lists safebrowsing: 2021/01/12 19:20:02 safebrowser.go:557: Next update in 30m13.773s safebrowsing: 2021/01/12 19:20:02 safebrowser.go:419: inconsistent database: safebrowsing: threat list count mismatch safebrowsing: 2021/01/12 19:20:02 safebrowser.go:419: inconsistent database: safebrowsing: threat list count mismatch ```

This is what is returned from status:

{"Stats":{"QueriesByDatabase":55981296,"QueriesByCache":34,"QueriesByAPI":22829,"QueriesFail":24489,"DatabaseUpdateLag":0},"Error":""}

Do you know what the issue might be? Is there a suggested way to debug this further? The other "inconsistent database" issues I saw looked to be accompanied by unexpected status codes.

[alexwoz]

Thanks for the report! We believe this is associated with a recent server push and will investigate further. Stay tuned for updates.

[TimothyBJacobs]

Thanks for looking into it!

[alexwoz]

Following up here -- it seems we have misalignment with our protocol specification. Specifically, our server does not guarantee returning a list update response for every requested list. We've clarified this in our public documentation and will soon send out a fix to remove this check.

[TimothyBJacobs]

Thank you!

[ladislavr]

Is it any update on the issue ?

[Pod5GS]

Hello! We are seeing the similar issue starting around 9:50am PST 10-27-2021, do you know what issue it might be?

[shlin168]

Also an user who encounter threat list count mismatch several times here, the latest one is on 2021-10-27 which is caused by code below https://github.com/google/safebrowsing/blob/bbf0d20d26b32d99fd21664677fe31ee9f0f66e3/database.go#L246-L251

safebrowsing periodically sends request with listUpdateRequests[] to update different threatType, platformType, etc., and check if it receive same amount of response.

It looks like on 2021-10-27, it sent request with 3 items to update while only received 1 item in listUpdateResponses

{"level":"info","msg":"safebrowsing: 2021/10/27 14:28:49 database.go:248: invalid server response: got 1, want 3 threat lists","time":"2021-10-27T14:28:49.83952Z"}

Based on document, listUpdateResponses[] can be less than listUpdateRequests[]. So we comment out L247 and L250 as below to let it still update local list even receive different amount of response, and only record the mismatch event in log without raising db error.

if len(resp.ListUpdateResponses) != numTypes {
    //db.setError(errors.New("safebrowsing: threat list count mismatch"))
    db.log.Printf("invalid server response: got %d, want %d threat lists",
        len(resp.ListUpdateResponses), numTypes)
    //return nextUpdateWait, false
}