Unexplained no-op entries in `current_state_delta_streams`

[DMRobertson]

To my surprise, there are rows in the current_state_delta_stream table whose event_id and prev_event_id match. This is odd.

matrix=> select stream_id, type, event_id, prev_event_id, instance_name from current_state_delta_stream where event_id = prev_event_id order by stream_id desc limit 20;
 stream_id  │        type         │                   event_id                   │                prev_event_id                 │   instance_name   
════════════╪═════════════════════╪══════════════════════════════════════════════╪══════════════════════════════════════════════╪═══════════════════
 3117777850 │ m.room.join_rules   │ $YOuZdE921TEuO-mf3VVUoFp6lciJ65tqib5LHA9K6w8 │ $YOuZdE921TEuO-mf3VVUoFp6lciJ65tqib5LHA9K6w8 │ event_persister-1
 3107561648 │ m.room.power_levels │ $RSAr3Mw5WvJQLPzcaoyqHVI6I-2unw6JkuPv51UcrWc │ $RSAr3Mw5WvJQLPzcaoyqHVI6I-2unw6JkuPv51UcrWc │ event_persister-2
 3107561648 │ m.room.member       │ $KiF8-dGKk5IxFAUs7mhP5Kzo--4rmFbqG3ewhI-Nzwg │ $KiF8-dGKk5IxFAUs7mhP5Kzo--4rmFbqG3ewhI-Nzwg │ event_persister-2
 3107561648 │ m.room.create       │ $o-TAG0EIQj8AGlNFwqR102vXlOuQ0UpjcO-RMnLiKjU │ $o-TAG0EIQj8AGlNFwqR102vXlOuQ0UpjcO-RMnLiKjU │ event_persister-2
 3102927454 │ m.room.join_rules   │ $-_-Hnj07hlnw2X_xfoxVHVoRX80y-mFC7P83ykNr_NA │ $-_-Hnj07hlnw2X_xfoxVHVoRX80y-mFC7P83ykNr_NA │ event_persister-1
 3086255218 │ m.room.member       │ $pbm-PbXzdN_isbD9aD9amRv5tyMxpKM-qZ0CRQ4k5DQ │ $pbm-PbXzdN_isbD9aD9amRv5tyMxpKM-qZ0CRQ4k5DQ │ event_persister-3
 3086255218 │ m.room.create       │ $cC8biTmTCuoTw9K73R_sTJkaHfvcCHeBlNKVtcxDg2Y │ $cC8biTmTCuoTw9K73R_sTJkaHfvcCHeBlNKVtcxDg2Y │ event_persister-3
 3086255218 │ m.room.power_levels │ $cWPBdTmwb-A5RY61e0RDKKdzI4nfOllQCJJi5hk9BqA │ $cWPBdTmwb-A5RY61e0RDKKdzI4nfOllQCJJi5hk9BqA │ event_persister-3
 3086255218 │ m.room.member       │ $DCt8lOQ7fympotAtpbEOQ18MGdkQvHqTH9rDoWOXsXY │ $DCt8lOQ7fympotAtpbEOQ18MGdkQvHqTH9rDoWOXsXY │ event_persister-3
 3086255218 │ m.room.join_rules   │ $5uKF_F2oEaRih9JJ85cfpQdcKR34RbZOnyxbaXj3KJE │ $5uKF_F2oEaRih9JJ85cfpQdcKR34RbZOnyxbaXj3KJE │ event_persister-3
 3086255218 │ m.room.member       │ $7GEg8Kz0HMNhjwbXidRapEfn2HzRw-bHFnQsnaNkHFU │ $7GEg8Kz0HMNhjwbXidRapEfn2HzRw-bHFnQsnaNkHFU │ event_persister-3
 3080553696 │ m.room.power_levels │ $UC9mVuAlk8r_rqhmpwqf_EVkPaJ5bvMplv0HvbNDzU0 │ $UC9mVuAlk8r_rqhmpwqf_EVkPaJ5bvMplv0HvbNDzU0 │ event_persister-4
 3080553696 │ m.room.member       │ $YJFG3SHK5uLmOin96j4OP3xg5N3qA7cfrKv1qsNirZ4 │ $YJFG3SHK5uLmOin96j4OP3xg5N3qA7cfrKv1qsNirZ4 │ event_persister-4
 3080553696 │ m.room.create       │ $xd40t16UrIqo4_AvnHvYrXbSZAg_RtBUrVyC9IkirD8 │ $xd40t16UrIqo4_AvnHvYrXbSZAg_RtBUrVyC9IkirD8 │ event_persister-4
 3080553696 │ m.room.member       │ $NGpOaLtvQAzsnLZuIZRkBGq-p44y4HuTZtgnHCOL4QY │ $NGpOaLtvQAzsnLZuIZRkBGq-p44y4HuTZtgnHCOL4QY │ event_persister-4
 3080553696 │ m.room.member       │ $Si_FAgxbTfaLlRNro_IA5YwL1oa1Qc1gWiO6wFqU0us │ $Si_FAgxbTfaLlRNro_IA5YwL1oa1Qc1gWiO6wFqU0us │ event_persister-4
 3080553696 │ m.room.member       │ $dxA9R56uqG0yQhdWqdKifQBO0lYfPAaPfAz2pr0ehIg │ $dxA9R56uqG0yQhdWqdKifQBO0lYfPAaPfAz2pr0ehIg │ event_persister-4
 3080553696 │ m.room.member       │ $z2rT8KjiptgFx7T-Jdp5s-4NaBX-L9uaRlQ87xP2t1c │ $z2rT8KjiptgFx7T-Jdp5s-4NaBX-L9uaRlQ87xP2t1c │ event_persister-4
 3080553696 │ m.room.member       │ $XnV2Ci6YumwYQ0e6rMpLsq6SsFwfkH6fO85BLpDgsV0 │ $XnV2Ci6YumwYQ0e6rMpLsq6SsFwfkH6fO85BLpDgsV0 │ event_persister-4
 3080553696 │ m.room.member       │ $9jynwQOW4x3MzPWEjj9rgKEXAN03Yb7P1FQc-pShYpM │ $9jynwQOW4x3MzPWEjj9rgKEXAN03Yb7P1FQc-pShYpM │ event_persister-4
(20 rows)

Time: 2967.887 ms (00:02.968)
matrix=> select stream_id, type, event_id, prev_event_id, instance_name from current_state_delta_stream where event_id = prev_event_id order by stream_id asc limit 20;
 stream_id │        type         │                         event_id                         │                      prev_event_id                       │ instance_name 
═══════════╪═════════════════════╪══════════════════════════════════════════════════════════╪══════════════════════════════════════════════════════════╪═══════════════
 613456822 │ m.room.power_levels │ $152678187725851JdAFH:matrix.org                         │ $152678187725851JdAFH:matrix.org                         │ ¤
 615758557 │ m.room.power_levels │ $153210549410852MFLuc:matrix.org                         │ $153210549410852MFLuc:matrix.org                         │ ¤
 615758557 │ m.room.member       │ $HtFoyQJArZwUpfAmhY5Aw9W957hXnuok7t2wQjeALJvSQ:zemos.net │ $HtFoyQJArZwUpfAmhY5Aw9W957hXnuok7t2wQjeALJvSQ:zemos.net │ ¤
 615758557 │ m.room.join_rules   │ $1526377987179528VlJZA:matrix.org                        │ $1526377987179528VlJZA:matrix.org                        │ ¤
 615758557 │ m.room.create       │ $1526377907179473iHiAX:matrix.org                        │ $1526377907179473iHiAX:matrix.org                        │ ¤
 643501056 │ m.room.power_levels │ $15178325585557187WShOj:matrix.org                       │ $15178325585557187WShOj:matrix.org                       │ ¤
 643501056 │ m.room.member       │ $DxhpEhQL2fJ6VNLrubEcTEeWKg5Ba7Xf63FPEbwy8Mnu7:zemos.net │ $DxhpEhQL2fJ6VNLrubEcTEeWKg5Ba7Xf63FPEbwy8Mnu7:zemos.net │ ¤
 643501056 │ m.room.join_rules   │ $15174094532469391zCUPQ:matrix.org                       │ $15174094532469391zCUPQ:matrix.org                       │ ¤
 643501056 │ m.room.create       │ $15174092422465585dSMPx:matrix.org                       │ $15174092422465585dSMPx:matrix.org                       │ ¤
 643731588 │ m.room.power_levels │ $15178325585557187WShOj:matrix.org                       │ $15178325585557187WShOj:matrix.org                       │ ¤
 643731588 │ m.room.member       │ $DxhpEhQL2fJ6VNLrubEcTEeWKg5Ba7Xf63FPEbwy8Mnu7:zemos.net │ $DxhpEhQL2fJ6VNLrubEcTEeWKg5Ba7Xf63FPEbwy8Mnu7:zemos.net │ ¤
 643731588 │ m.room.join_rules   │ $15174094532469391zCUPQ:matrix.org                       │ $15174094532469391zCUPQ:matrix.org                       │ ¤
 643731588 │ m.room.create       │ $15174092422465585dSMPx:matrix.org                       │ $15174092422465585dSMPx:matrix.org                       │ ¤
 643749980 │ m.room.power_levels │ $152954036728DGrDM:kamax.io                              │ $152954036728DGrDM:kamax.io                              │ ¤
 643749980 │ m.room.member       │ $JMkGZBAuNZzYdCAwCF5aTzbDg5QqquWbyYnks9w5eLU:zemos.net   │ $JMkGZBAuNZzYdCAwCF5aTzbDg5QqquWbyYnks9w5eLU:zemos.net   │ ¤
 643749980 │ m.room.join_rules   │ $15292480902539NlTLR:kamax.io                            │ $15292480902539NlTLR:kamax.io                            │ ¤
 643749980 │ m.room.create       │ $15292480492528FrGib:kamax.io                            │ $15292480492528FrGib:kamax.io                            │ ¤
 643845277 │ m.room.power_levels │ $15236382578175Bfnzh:matrix.org                          │ $15236382578175Bfnzh:matrix.org                          │ ¤
 643845277 │ m.room.member       │ $9Ammie75D954dviE7Rcqg9kHypgNVXiaPZKSLrfEfGhd:zemos.net  │ $9Ammie75D954dviE7Rcqg9kHypgNVXiaPZKSLrfEfGhd:zemos.net  │ ¤
 643845277 │ m.room.join_rules   │ $15236350597125piIvC:matrix.org                          │ $15236350597125piIvC:matrix.org                          │ ¤
(20 rows)

From the source code, it doesn't look this should be possible in the logic which inserts rows to this table, unless a) Synapse's in-memory caches are out of date, or b) the current state events table has changed beneath us.

However: the recently removed weird corner (#12943) was known to create dodgy state groups and I can't help but wonder if that was the cause.

At the time of writing, stream ID 3117777850 was the last time we saw this on matrix.org.

matrix=> select distinct stream_id from current_state_delta_stream where event_id = prev_event_id ORDER BY stream_id DESC limit 5;
 stream_id  
════════════
 3117777850
 3107561648
 3102927454
 3086255218
 3080553696
matrix=> select max(stream_id) from current_state_delta_stream;
    max     
════════════
 3153891551
(1 row)

[reivilibre]

Even if we can't figure out why this happened, we could possibly make some effort to add a CHECK constraint to the table to ensure this doesn't happen again — and crucially it would give us an exception when this happened.

I don't see any recent examples of this issue in our database, but it's a large table so I haven't exactly scanned backwards through it all.

[H-Shay]

I did a little digging in the db and found that stream ID 3117777850 appears to still be the last time we saw this on matrix.org (by running the same query as above: select stream_id, type, event_id, prev_event_id, instance_name from current_state_delta_stream where event_id = prev_event_id order by stream_id desc limit 20;), the first result was:

stream_id   3117777850
type   m.room.join_rules
event_id   $YOuZdE921TEuO-mf3VVUoFp6lciJ65tqib5LHA9K6w8
prev_event_id  $YOuZdE921TEuO-mf3VVUoFp6lciJ65tqib5LHA9K6w8
instance_name event_persister-1

select max(stream_id) from current_state_delta_stream is now 4123332416, and this issue was raised almost a year ago, which seems to lend credence to the idea that this might be attributed to the "weird corner" being fixed? At any rate, it doesn't seem to have recurred in the last year. I am going to add a warning/logging flagging this condition when we insert to both the current_state_delta_stream table and current_state_events but I am wondering what other investigation makes sense here.

[H-Shay]

Looks like adding logging is also not as stragihtforward as it seems. At least some of the places that we insert into current_state_delta_stream the selection from current_state_events and insertion is done entirely in SQL:

synapse/synapse/storage/databases/main/events.py

Lines 1129 to 1153 in 5e82b07

	sql = """
	INSERT INTO current_state_delta_stream
	(stream_id, instance_name, room_id, type, state_key, event_id, prev_event_id)
	SELECT ?, ?, ?, ?, ?, ?, (
	SELECT event_id FROM current_state_events
	WHERE room_id = ? AND type = ? AND state_key = ?
	)
	"""
	txn.execute_batch(
	sql,
	(
	(
	stream_id,
	self._instance_name,
	room_id,
	etype,
	state_key,
	to_insert.get((etype, state_key)),
	room_id,
	etype,
	state_key,
	)
	for etype, state_key in itertools.chain(to_delete, to_insert)
	),
	)

Which means that in order to log when the prev event == current event it seems like I'd have to break the SQL into two transactions (one to select so I can check the result and log in python, and one to insert) which presumably would add a performance penalty (especially in a hot path like here, not to mention it would make it harder? impossible? to take advantage of the batching mechanism shown in the above code clip).

Given this I'm wondering if it still makes sense to do this and add the logging given the fact that we haven't seen a recurrence of the issue in a year (and there is a plausible mechanism for it having been fixed)?

[DMRobertson]

Given what you say in #13436 (comment) and our time constraints, I think it makes sense to chalk this up to the weird corner and close this. Worst-case scenario we can reopen.

(Though I wouldn't object to a CHECK constraint as Olivier suggests.)

Which means that in order to log when the prev event == current event it seems like I'd have to break the SQL into two transactions (one to select so I can check the result and log in python, and one to insert)

I think you might mean that you'd have to break the SQL up into two queries (which both run in the same transaction)? That aside, we can ask the DB to give us back columns (more generally, expressions) from an INSERT statement with a RETURNING clause (INSERT INTO ... RETURNING expr1, expr2, ...;). See e.g. https://www.postgresql.org/docs/current/dml-returning.html and https://www.sqlite.org/lang_returning.html for gory details.

But as I say, let's assume this is dealt with by us having sanded away the weird corner.

[H-Shay]

Oh thanks for sharing that about RETURNING, that looks like exactly what I'd like to use here. FTR I did open a PR to add the check constraint, but it is blocked due to the fact that the dummy data for the port_db script has data which triggers the condition: #15849

We discussed this in a meeting and it was pointed out that if the dummy data has this condition, it means it exists in the wild and we should put some energy into tracking it down (but that was before I ascertained that this condition hasn't recurred for about a year now on m.org). I think it probably makes sense to drop it but thought I should add that context.