Mass db flooding after upgrade to 1.7.3

[Dryusdan]

Hi

Description

After upgrade on 1.7.2 and 1.7.3 yesterday, the size of my DB increase (+45Go in 24h).
When I look PostgreSQL, I have this log :

2020-01-01 14:04:05.358 CET [17809] synapse@synapse STATEMENT:  INSERT INTO current_state_delta_stream (stream_id, room_id, type, state_key, event_id, prev_event_id) SELECT 2420301, '!BbUcoMPQhtUNJexFlJ:matrix.org', 'm.room.member', '@freenode_DerRidda:matrix.org', NULL, ( SELECT event_id FROM current_state_events WHERE room_id = '!BbUcoMPQhtUNJexFlJ:matrix.org' AND type = 'm.room.member' AND state_key = '@freenode_DerRidda:matrix.org' )
2020-01-01 14:04:06.943 CET [1003] prometheus@postgres LOG:  using stale statistics instead of current ones because stats collector is not responding
2020-01-01 14:04:06.943 CET [1003] prometheus@postgres STATEMENT:  SELECT * FROM pg_stat_bgwriter;
2020-01-01 14:04:08.842 CET [17813] synapse@synapse ERROR:  more than one row returned by a subquery used as an expression
2020-01-01 14:04:08.842 CET [17813] synapse@synapse STATEMENT:  INSERT INTO current_state_delta_stream (stream_id, room_id, type, state_key, event_id, prev_event_id) SELECT 2420307, '!BbUcoMPQhtUNJexFlJ:matrix.org', 'm.room.member', '@freenode_DerRidda:matrix.org', NULL, ( SELECT event_id FROM current_state_events WHERE room_id = '!BbUcoMPQhtUNJexFlJ:matrix.org' AND type = 'm.room.member' AND state_key = '@freenode_DerRidda:matrix.org' )
2020-01-01 14:04:10.930 CET [17834] synapse@synapse ERROR:  more than one row returned by a subquery used as an expression
2020-01-01 14:04:10.930 CET [17834] synapse@synapse STATEMENT:  INSERT INTO current_state_delta_stream (stream_id, room_id, type, state_key, event_id, prev_event_id) SELECT 2420309, '!BbUcoMPQhtUNJexFlJ:matrix.org', 'm.room.member', '@freenode_DerRidda:matrix.org', NULL, ( SELECT event_id FROM current_state_events WHERE room_id = '!BbUcoMPQhtUNJexFlJ:matrix.org' AND type = 'm.room.member' AND state_key = '@freenode_DerRidda:matrix.org' )
2020-01-01 14:04:12.445 CET [17830] synapse@synapse ERROR:  more than one row returned by a subquery used as an expression
2020-01-01 14:04:12.445 CET [17830] synapse@synapse STATEMENT:  INSERT INTO current_state_delta_stream (stream_id, room_id, type, state_key, event_id, prev_event_id) SELECT 2420310, '!BbUcoMPQhtUNJexFlJ:matrix.org', 'm.room.member', '@freenode_DerRidda:matrix.org', NULL, ( SELECT event_id FROM current_state_events WHERE room_id = '!BbUcoMPQhtUNJexFlJ:matrix.org' AND type = 'm.room.member' AND state_key = '@freenode_DerRidda:matrix.org' )
2020-01-01 14:04:13.749 CET [17817] synapse@synapse ERROR:  more than one row returned by a subquery used as an expression
2020-01-01 14:04:13.749 CET [17817] synapse@synapse STATEMENT:  INSERT INTO current_state_delta_stream (stream_id, room_id, type, state_key, event_id, prev_event_id) SELECT 2420311, '!BbUcoMPQhtUNJexFlJ:matrix.org', 'm.room.member', '@freenode_DerRidda:matrix.org', NULL, ( SELECT event_id FROM current_state_events WHERE room_id = '!BbUcoMPQhtUNJexFlJ:matrix.org' AND type = 'm.room.member' AND state_key = '@freenode_DerRidda:matrix.org' )

And on homeserver.log :

2020-01-01 14:04:00,871 - synapse.handlers.federation - 2250 - ERROR - PUT-6-$1577880425457241muJEu:matrix.org-$1577880182456181zQTvR:matrix.org-$1577880178456166AGyoI:matrix.org-$1577658883892428oSbvC:matrix.org-$1577627735689024sKqol:matrix.org-$1577617260635687aplFx:matrix.org-$1577531125183665SRzKE:matrix.org-$1577526720163394OXfRz:matrix.org-$157750217458595fuZbl:matrix.org-$157749386313173RfdBz:matrix.org-$15774216112286987mrSFk:matrix.org-$1577401872983855CUbVa:matrix.org-$1577383552920168sQjaE:matrix.org-$1577378305903094eoePc:matrix.org-$1577375047893341hFFwg:matrix.org-$1577370956881491Ibxnr:matrix.org- Failed to get auth chain
Traceback (most recent call last):
  File "/opt/matrix/synapse/env/lib/python3.7/site-packages/synapse/handlers/federation.py", line 2242, in _update_auth_events_and_context_for_auth
    yield self._handle_new_event(origin, e, auth_events=auth)
twisted.internet.defer.FirstError: FirstError[#0, [Failure instance: Traceback: <class 'psycopg2.errors.CardinalityViolation'>: more than one row returned by a subquery used as an expression

/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/internet/defer.py:654:_runCallbacks
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/internet/defer.py:1475:gotResult
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
--- <exception caught here> ---
/opt/matrix/synapse/env/lib/python3.7/site-packages/synapse/storage/persist_events.py:147:handle_queue_loop
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/opt/matrix/synapse/env/lib/python3.7/site-packages/synapse/storage/persist_events.py:257:persisting_queue
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/opt/matrix/synapse/env/lib/python3.7/site-packages/synapse/storage/persist_events.py:412:_persist_events
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/opt/matrix/synapse/env/lib/python3.7/site-packages/synapse/storage/data_stores/main/events.py:85:f
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/opt/matrix/synapse/env/lib/python3.7/site-packages/synapse/storage/data_stores/main/events.py:215:_persist_events_and_state_updates
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/opt/matrix/synapse/env/lib/python3.7/site-packages/synapse/storage/database.py:456:runInteraction
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/opt/matrix/synapse/env/lib/python3.7/site-packages/synapse/storage/database.py:504:runWithConnection
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/python/threadpool.py:250:inContext
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/python/threadpool.py:266:<lambda>
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/python/context.py:122:callWithContext
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/python/context.py:85:callWithContext
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/enterprise/adbapi.py:306:_runWithConnection
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/python/compat.py:464:reraise
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/enterprise/adbapi.py:297:_runWithConnection
/opt/matrix/synapse/env/lib/python3.7/site-packages/synapse/storage/database.py:501:inner_func
/opt/matrix/synapse/env/lib/python3.7/site-packages/synapse/storage/database.py:339:new_transaction
/opt/matrix/synapse/env/lib/python3.7/site-packages/synapse/logging/utils.py:79:wrapped
/opt/matrix/synapse/env/lib/python3.7/site-packages/synapse/storage/data_stores/main/events.py:465:_persist_events_txn
/opt/matrix/synapse/env/lib/python3.7/site-packages/synapse/storage/data_stores/main/events.py:503:_update_current_state_txn
/opt/matrix/synapse/env/lib/python3.7/site-packages/synapse/storage/database.py:145:executemany
/opt/matrix/synapse/env/lib/python3.7/site-packages/synapse/storage/database.py:168:_do_execute
]]

Or

77401872983855CUbVa:matrix.org-$1577383552920168sQjaE:matrix.org-$1577378305903094eoePc:matrix.org-$1577375047893341hFFwg:matrix.org-$1577370956881491Ibxnr:matrix.org- Failed to get auth chain
Traceback (most recent call last):
  File "/opt/matrix/synapse/env/lib/python3.7/site-packages/synapse/handlers/federation.py", line 2242, in _update_auth_events_and_context_for_auth
    yield self._handle_new_event(origin, e, auth_events=auth)
twisted.internet.defer.FirstError: FirstError[#0, [Failure instance: Traceback: <class 'RuntimeError'>: Attempt to access state_group of rejected event
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/internet/defer.py:1418:_inlineCallbacks
/opt/matrix/synapse/env/lib/python3.7/site-packages/synapse/storage/persist_events.py:381:_persist_events
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/internet/defer.py:1613:unwindGenerator
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/internet/defer.py:1529:_cancellableInlineCallbacks
--- <exception caught here> ---
/opt/matrix/synapse/env/lib/python3.7/site-packages/synapse/storage/persist_events.py:147:handle_queue_loop
/opt/matrix/synapse/env/lib/python3.7/site-packages/synapse/storage/persist_events.py:257:persisting_queue
/opt/matrix/synapse/env/lib/python3.7/site-packages/synapse/storage/persist_events.py:381:_persist_events
/opt/matrix/synapse/env/lib/python3.7/site-packages/twisted/internet/defer.py:1418:_inlineCallbacks
/opt/matrix/synapse/env/lib/python3.7/site-packages/synapse/storage/persist_events.py:505:_get_new_state_after_events
/opt/matrix/synapse/env/lib/python3.7/site-packages/synapse/events/snapshot.py:214:state_group
]]

Problem disapear when I rollback onto 1.7.1.

Steps to reproduce

• list the steps
• that reproduce the bug
• using hyphens as bullet points

Version information

• Homeserver:

If not matrix.org: matrix.drycat.fr

What version of Synapse is running?

{
    "python_version": "3.7.3",
    "server_version": "1.7.1"
}

• Version: 1.7.2, 1.7.3

• Install method:

• Platform: package manager and pip (I reinstall my synapse on other server because the first upgrade on debian 10 (dist upgrade)

[richvdh]

I'd be very surprised if the changes between 1.7.1 and 1.7.2 caused this, so I suspect it's a coincidence.

I suggest we start with the CardinalityViolation. It sounds like there are duplicate rows in the current_state_events with the same (room_id, type, state_key) values. This can be caused by an incorrect collation setting on the postgres database as per #6696 (comment), so check that.

Also check that the unique index is actually in place on that table.

Otherwise I suggest dumping that table and re-importing it, and checking for duplicates.

[Dryusdan]

Yes, the problem for this table is a colate problem.
When I dumping db and reimport in new colate, this is work fine.
I have only problem on #6808 but I opened a new issue.

I closing this.
Thank for your answer.