Skip to content
This repository has been archived by the owner on Apr 26, 2024. It is now read-only.

Throws notifcation rotation-related error at 30 second interval #14219

Closed
paulvt opened this issue Oct 18, 2022 · 11 comments
Closed

Throws notifcation rotation-related error at 30 second interval #14219

paulvt opened this issue Oct 18, 2022 · 11 comments
Labels
A-Database DB stuff like queries, migrations, new/remove columns, indexes, unexpected entries in the db A-Push Issues related to push/notifications A-Threads Threaded messages T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues. X-Needs-Info This issue is blocked awaiting information from the reporter X-Regression Something broke which worked on a previous release

Comments

@paulvt
Copy link

paulvt commented Oct 18, 2022

Description

Synapse 1.69 throws the following error every 30 seconds:

ERROR: there is no unique or exclusion constraint matching the ON CONFLICT specification

(For log messages/backtrace, see below.)

I do not remember seeing these log messages when I was on Synapse 1.66, where I just upgraded from.

Steps to reproduce

  • Upgrade Synapse to 1.69
  • Tail the log

Homeserver

my own instance

Synapse Version

1.69.0 (on Python 3.9.15)

Installation Method

Docker (matrixdotorg/synapse)

Platform

Installation is based on docker-compose, running on Debian 11 (bullseye).

The installation is not new and thus uses docker.io/postgres:10-alpine as the database image as I had no time to migrate it yet.

Relevant log output

Oct 18 12:54:59 torus docker-compose[3538837]: db_1      | 2022-10-18 10:54:59.628 UTC [33] ERROR:  there is no unique or exclusion constraint matching the ON CONFLICT specification
Oct 18 12:54:59 torus docker-compose[3538837]: db_1      | 2022-10-18 10:54:59.628 UTC [33] STATEMENT:  INSERT INTO event_push_summary (room_id, user_id, thread_id, notif_count, unread_count, stream_ordering, last_receipt_stream_ordering) VALUES ('!<censored>', '@<censored>', 'main', 0, 0, 1070970, 1070976) ON CONFLICT (room_id, user_id, thread_id)  DO UPDATE SET notif_count=EXCLUDED.notif_count, unread_count=EXCLUDED.unread_count, stream_ordering=EXCLUDED.stream_ordering, last_receipt_stream_ordering=EXCLUDED.last_receipt_stream_ordering
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  | 2022-10-18 10:54:59,633 - synapse.metrics.background_process_metrics - 242 - ERROR - rotate_notifs-20 - Background process 'rotate_notifs' threw an exception
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  | Traceback (most recent call last):
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |   File "/usr/local/lib/python3.9/site-packages/synapse/metrics/background_process_metrics.py", line 240, in run
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |     return await func(*args, **kwargs)
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |   File "/usr/local/lib/python3.9/site-packages/synapse/storage/databases/main/event_push_actions.py", line 1052, in _rotate_notifs
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |     caught_up = await self.db_pool.runInteraction(
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |   File "/usr/local/lib/python3.9/site-packages/synapse/storage/database.py", line 881, in runInteraction
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |     return await delay_cancellation(_runInteraction())
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |   File "/usr/local/lib/python3.9/site-packages/twisted/internet/defer.py", line 1656, in _inlineCallbacks
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |     result = current_context.run(
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |   File "/usr/local/lib/python3.9/site-packages/twisted/python/failure.py", line 514, in throwExceptionIntoGenerator
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |     return g.throw(self.type, self.value, self.tb)
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |   File "/usr/local/lib/python3.9/site-packages/synapse/storage/database.py", line 848, in _runInteraction
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |     result = await self.runWithConnection(
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |   File "/usr/local/lib/python3.9/site-packages/synapse/storage/database.py", line 976, in runWithConnection
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |     return await make_deferred_yieldable(
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |   File "/usr/local/lib/python3.9/site-packages/twisted/python/threadpool.py", line 244, in inContext
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |     result = inContext.theWork()  # type: ignore[attr-defined]
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |   File "/usr/local/lib/python3.9/site-packages/twisted/python/threadpool.py", line 260, in <lambda>
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |     inContext.theWork = lambda: context.call(  # type: ignore[attr-defined]
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |   File "/usr/local/lib/python3.9/site-packages/twisted/python/context.py", line 117, in callWithContext
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |     return self.currentContext().callWithContext(ctx, func, *args, **kw)
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |   File "/usr/local/lib/python3.9/site-packages/twisted/python/context.py", line 82, in callWithContext
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |     return func(*args, **kw)
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |   File "/usr/local/lib/python3.9/site-packages/twisted/enterprise/adbapi.py", line 282, in _runWithConnection
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |     result = func(conn, *args, **kw)
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |   File "/usr/local/lib/python3.9/site-packages/synapse/storage/database.py", line 969, in inner_func
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |     return func(db_conn, *args, **kwargs)
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |   File "/usr/local/lib/python3.9/site-packages/synapse/storage/database.py", line 710, in new_transaction
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |     r = func(cursor, *args, **kwargs)
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |   File "/usr/local/lib/python3.9/site-packages/synapse/storage/databases/main/event_push_actions.py", line 1165, in _handle_new_receipts_for_notifs_txn
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |     self.db_pool.simple_upsert_txn(
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |   File "/usr/local/lib/python3.9/site-packages/synapse/storage/database.py", line 1257, in simple_upsert_txn
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |     return self.simple_upsert_txn_native_upsert(
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |   File "/usr/local/lib/python3.9/site-packages/synapse/storage/database.py", line 1397, in simple_upsert_txn_native_upsert
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |     txn.execute(sql, list(allvalues.values()))
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |   File "/usr/local/lib/python3.9/site-packages/synapse/storage/database.py", line 388, in execute
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |     self._do_execute(self.txn.execute, sql, *args)
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |   File "/usr/local/lib/python3.9/site-packages/synapse/storage/database.py", line 436, in _do_execute
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  |     return func(sql, *args, **kwargs)
Oct 18 12:54:59 torus docker-compose[3538837]: server_1  | psycopg2.errors.InvalidColumnReference: there is no unique or exclusion constraint matching the ON CONFLICT specification

Anything else that would be useful to know?

No response
@DMRobertson
Copy link
Contributor

Odd. Can you connect to the DB and show us what \d event_push_summary prints?

@DMRobertson DMRobertson added A-Push Issues related to push/notifications T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues. X-Regression Something broke which worked on a previous release A-Threads Threaded messages A-Database DB stuff like queries, migrations, new/remove columns, indexes, unexpected entries in the db X-Needs-Info This issue is blocked awaiting information from the reporter labels Oct 18, 2022
@paulvt
Copy link
Author

paulvt commented Oct 18, 2022

Odd. Can you connect to the DB and show us what \d event_push_summary prints?

Of course!

synapse=# \d event_push_summary
                   Table "public.event_push_summary"
            Column            |  Type  | Collation | Nullable | Default 
------------------------------+--------+-----------+----------+---------
 user_id                      | text   |           | not null | 
 room_id                      | text   |           | not null | 
 notif_count                  | bigint |           | not null | 
 stream_ordering              | bigint |           | not null | 
 unread_count                 | bigint |           |          | 
 last_receipt_stream_ordering | bigint |           |          | 
 thread_id                    | text   |           |          | 
Indexes:
    "event_push_summary_unique_index" UNIQUE, btree (user_id, room_id)
    "event_push_summary_unique_index2" UNIQUE, btree (user_id, room_id, thread_id)

@paulvt
Copy link
Author

paulvt commented Oct 18, 2022

On a side note: Given that I'm still getting Matrix notifications, what is of might be the impact of this issue? I could not judge that.

@clokep
Copy link
Member

clokep commented Oct 18, 2022

On a side note: Given that I'm still getting Matrix notifications, what is of might be the impact of this issue? I could not judge that.

The impact is that the code to handle notifications will slow down over time as it processes more and more un-summarized notifications.

@clokep
Copy link
Member

clokep commented Oct 18, 2022

Could you check which background updates are pending?

SELECT * FROM background_updates;

@paulvt
Copy link
Author

paulvt commented Oct 18, 2022 •
edited
Loading

Hmm, surprisingly:

synapse=# SELECT * FROM background_updates;
 update_name | progress_json | depends_on | ordering 
-------------+---------------+------------+----------
(0 rows)

I opened the logs again and the error is no longer happening (since about 1h30 after start).
I'm assuming this can reoccur if more notifications and I shouldn't close this just yet?

@clokep
Copy link
Member

clokep commented Oct 18, 2022

I'm assuming this can reoccur if more notifications and I shouldn't close this just yet?

It should not happen as the needed constraint is now there. If you don't see it for a couple of days I think this is fine to close.

@DMRobertson DMRobertson modified the milestone: Revisit: Next Week Oct 18, 2022
@paulvt
Copy link
Author

paulvt commented Oct 21, 2022

I have not seen this occurring anymore in the past two days, so it seems it resolved itself.
Thanks for looking into this.

@paulvt paulvt closed this as completed Oct 21, 2022
@DMRobertson
Copy link
Contributor

Great news---thanks for following up!

@lsrmg
Copy link

lsrmg commented Nov 14, 2022 •
edited
Loading

I'm getting the same error. I'm not sure, since which version the problem is present in my case. When I'm updating to 1.71.0 the /sync isn't working anymore on the client side.

The background_updates Table is empty.

\d event_push_summary differs ever so slightly from this one:

synapse=# \d event_push_summary
Table "public.event_push_summary"
Column | Type | Collation | Nullable | Default
------------------------------+--------+-----------+----------+---------
user_id | text | | not null |
room_id | text | | not null |
notif_count | bigint | | not null |
stream_ordering | bigint | | not null |
unread_count | bigint | | |
last_receipt_stream_ordering | bigint | | |
thread_id | text | | |
Indexes:
"event_push_summary_thread_id_null" btree (thread_id) WHERE thread_id IS NULL
"event_push_summary_unique_index2" UNIQUE, btree (user_id, room_id, thread_id)

homeserver-Log:

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

@squahtx
Copy link
Contributor

squahtx commented Nov 15, 2022

@lsrmg That looks different to the original report. Can you file a new issue for it?

@lsrmg lsrmg mentioned this issue Nov 15, 2022
Closed
@johansmitsnl johansmitsnl mentioned this issue Nov 16, 2022
Closed
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
A-Database DB stuff like queries, migrations, new/remove columns, indexes, unexpected entries in the db A-Push Issues related to push/notifications A-Threads Threaded messages T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues. X-Needs-Info This issue is blocked awaiting information from the reporter X-Regression Something broke which worked on a previous release
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@clokep @paulvt @squahtx @DMRobertson @lsrmg