`synapse.api.errors.StoreError: 404: No row found` during background process `rotate_notifs`

[LRSHRS]

Description

For some versions of matrix-synapse we're getting the following error in our homeserver-logs. We didn't noticed any issues while using the service at all, everythin was running fine except for the presence-status since the introduction of incremental /sync requests some versions ago.

With the new synapse version 1.71.0 the /sync requests from all clients keep failing with the message "No row found".
It seems to me that there are some null-values in the database where they not ment to be.

Steps to reproduce

• Updating to matrix-synapse-py3 1.71.0

Homeserver

on-premise/local network

Synapse Version

1.71.0

Installation Method

Debian packages from packages.matrix.org

Platform

Debian 11

Relevant log output

2022-11-11 20:15:50,596 - synapse.metrics.background_process_metrics - 242 - ERROR - rotate_notifs-18 - Background process 'rotate_notifs' threw an exception
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/metrics/background_process_metrics.py", line 240, in run
    return await func(*args, **kwargs)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/databases/main/event_push_actions.py", line 1052, in _rotate_notifs
    caught_up = await self.db_pool.runInteraction(
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/database.py", line 881, in runInteraction
    return await delay_cancellation(_runInteraction())
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/internet/defer.py", line 1656, in _inlineCallbacks
    result = current_context.run(
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/python/failure.py", line 514, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/database.py", line 848, in _runInteraction
    result = await self.runWithConnection(
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/database.py", line 976, in runWithConnection
    return await make_deferred_yieldable(
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/python/threadpool.py", line 244, in inContext
    result = inContext.theWork()  # type: ignore[attr-defined]
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/python/threadpool.py", line 260, in <lambda>
    inContext.theWork = lambda: context.call(  # type: ignore[attr-defined]
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/python/context.py", line 117, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/python/context.py", line 82, in callWithContext
    return func(*args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/enterprise/adbapi.py", line 282, in _runWithConnection
    result = func(conn, *args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/database.py", line 969, in inner_func
    return func(db_conn, *args, **kwargs)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/database.py", line 710, in new_transaction
    r = func(cursor, *args, **kwargs)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/databases/main/event_push_actions.py", line 1097, in _handle_new_receipts_for_notifs_txn
    old_rotate_stream_ordering = self.db_pool.simple_select_one_onecol_txn(
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/database.py", line 1718, in simple_select_one_onecol_txn
    raise StoreError(404, "No row found")
synapse.api.errors.StoreError: 404: No row found

Anything else that would be useful to know?

There are two issues like this in #14219 and #14300.

[clokep]

Do you have purging enabled on your homeserver?

[LRSHRS]

No, I don't have retention/purging enabled.

[erikjohnston]

@lsrmg that stack trace doesn't seem to match v1.71.0, in that the line numbers don't line up. Is it possible the running synapse was different from the one that was installed?

Secondly, that stack trace is for a background process, which while not ideal shouldn't cause problems with /sync. Could you post some logs (or send them to me at @erikj:jki.re) for the time period that /sync was 404ing for please?

[LRSHRS]

Thank you for you quick answer! I send you the full logs to @erikj:jki.re.

You're right, I restored the working state and must have copied the wron snipped.

Today I installed 1.71.0 and secured the right log:

2022-11-16 20:54:59,691 - synapse.metrics.background_process_metrics - 244 - ERROR - rotate_notifs-3 - Background process 'rotate_notifs' threw an exception
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/metrics/background_process_metrics.py", line 242, in run
    return await func(*args, **kwargs)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/databases/main/event_push_actions.py", line 1296, in _rotate_notifs
    caught_up = await self.db_pool.runInteraction(
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/database.py", line 881, in runInteraction
    return await delay_cancellation(_runInteraction())
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/internet/defer.py", line 1692, in _inlineCallbacks
    result = context.run(
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/python/failure.py", line 518, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/database.py", line 848, in _runInteraction
    result = await self.runWithConnection(
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/database.py", line 976, in runWithConnection
    return await make_deferred_yieldable(
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/python/threadpool.py", line 244, in inContext
    result = inContext.theWork()  # type: ignore[attr-defined]
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/python/threadpool.py", line 260, in <lambda>
    inContext.theWork = lambda: context.call(  # type: ignore[attr-defined]
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/python/context.py", line 117, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/python/context.py", line 82, in callWithContext
    return func(*args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/twisted/enterprise/adbapi.py", line 282, in _runWithConnection
    result = func(conn, *args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/database.py", line 969, in inner_func
    return func(db_conn, *args, **kwargs)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/database.py", line 710, in new_transaction
    r = func(cursor, *args, **kwargs)
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/databases/main/event_push_actions.py", line 1341, in _handle_new_receipts_for_notifs_txn
    old_rotate_stream_ordering = self.db_pool.simple_select_one_onecol_txn(
  File "/opt/venvs/matrix-synapse/lib/python3.9/site-packages/synapse/storage/database.py", line 1718, in simple_select_one_onecol_txn
    raise StoreError(404, "No row found")
synapse.api.errors.StoreError: 404: No row found

And the error on the client-side (Element 1.11.14):
request: /_matrix/client/r0/sync?filter=0&timeout=0&since=s7426708_211201868_0_11098700_23391459_11895_341941_195689_0
answer: {"errcode":"M_UNKNOWN","error":"No row found"}

[LRSHRS]

Same issue present in synapse 1.72 for me

[H-Shay]

@lsrmg do you have logs?

[LRSHRS]

@lsrmg do you have logs?

@H-Shay sorry, but I only have the logs provided above.

[H-Shay]

I took a look at the logs you sent my teammate and while I do see the error from the background process, I am not seeing anything related to /sync. Can you provide logs for the time that you send a few requests to /sync and see them fail? If possible, if you could provide logs with the logging level set to debug that would help immensely. Feel free to send them to @shayshay:matrix.org.

[H-Shay]

Looking at the debug logs provided, I do see /sync requests failing:

2022-12-02 00:32:39,162 - synapse.access.http.8008 - 460 - INFO - GET-564 - **anon-IP** - 8008 - {@xxxx:xxxxx-xxxxx} Processed request: 0.003sec/0.001sec (0.002sec, 0.000sec) (0.000sec/0.000sec/0) 46B 404 "GET /_matrix/client/r0/sync?filter=2&timeout=0&since=s7583202_215985817_237228_11477561_23942297_12075_355636_197795_0 HTTP/1.0" "browser" [0 dbevts]

Looking closer, it looks like /sync calls unread_notifs_for_room_id which calls get_unread_event_push_actions_by_room_for_user, and one of the queries contained within is failing.

It appears that the query that is failing is

2022-12-02 00:32:38,434 - synapse.storage.SQL - 416 - DEBUG - GET-534 - [SQL] {get_unread_event_push_actions_by_room-286} SELECT stream_ordering FROM event_push_summary_stream_ordering

with the message

2022-12-02 00:32:38,450 - synapse.storage.txn - 786 - DEBUG - GET-534 - [TXN FAIL] {get_unread_event_push_actions_by_room-286} 404: No row found

which afaict originates from this chunk of code here:

# The (inclusive) event stream ordering that was previously summarised.
        rotated_upto_stream_ordering = self.db_pool.simple_select_one_onecol_txn(
            txn,
            table="event_push_summary_stream_ordering",
            keyvalues={},
            retcol="stream_ordering",
        )

which seems to have been added in #13877. @clokep, I think this is part of the threading work? You are more familiar with it than I, do you have any thoughts on what might be the issue?

[H-Shay]

Also just noting that the debug logs I looked at were from Synapse v1.72.0, not 1.71.0.

[clokep]

I think this is part of the threading work?

It was not part of threading -- this process existed earlier. (Threading just made it a bit more complicated!)

do you have any thoughts on what might be the issue?

I've only seen this be an issue when message retention is enabled. I'm not sure beyond that.