Duplicate key violation when persisting read markers

[djschilling]

Description

In the homeserver.log i have some requests with error code 500.
Most of them look like that:

2020-05-10 12:10:29,843 - synapse.access.http.8008 - 302 - INFO - POST-1674964 - 84.163.97.55 - 8008 - {@*****:chat.church.tools} Processed request: 0.024sec/0.003sec (0.005sec, 0.000sec) (0.002sec/0.014sec/1) 55B 500 "POST /_matrix/client/r0/rooms/!*****%3Achat.church.tools/read_markers?access_token= HTTP/1.1" "ChurchTools/115 CFNetwork/1125.2 Darwin/19.4.0" [0 dbevts]

One log message is more detailed. I'm not sure if they are related:

2020-05-10 12:10:29,844 - synapse.http.server - 110 - ERROR - POST-1674961 - Failed handle request via 'ReadMarkerRestServlet': 
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/http/server.py", line 78, in wrapped_request_handler
    await h(self, request)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/http/server.py", line 331, in _async_render
    callback_return = await callback_return
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/rest/client/v2_alpha/read_marker.py", line 48, in on_POST
    event_id=read_event_id,
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/handlers/receipts.py", line 121, in received_client_receipt
    is_new = await self._handle_new_receipts([receipt])
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/handlers/receipts.py", line 79, in _handle_new_receipts
    receipt.data,
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/storage/data_stores/main/receipts.py", line 473, in insert_receipt
    stream_id=stream_id,
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/storage/database.py", line 524, in runInteraction
    **kwargs
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/storage/database.py", line 574, in runWithConnection
    self._db_pool.runWithConnection(inner_func, *args, **kwargs)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/python/threadpool.py", line 250, in inContext
    result = inContext.theWork()
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/python/threadpool.py", line 266, in 
    inContext.theWork = lambda: context.call(ctx, func, *args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/python/context.py", line 122, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/python/context.py", line 85, in callWithContext
    return func(*args,**kw)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/enterprise/adbapi.py", line 306, in _runWithConnection
    compat.reraise(excValue, excTraceback)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/python/compat.py", line 464, in reraise
    raise exception.with_traceback(traceback)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/enterprise/adbapi.py", line 297, in _runWithConnection
    result = func(conn, *args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/storage/database.py", line 571, in inner_func
    return func(conn, *args, **kwargs)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/storage/database.py", line 407, in new_transaction
    r = func(cursor, *args, **kwargs)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/storage/data_stores/main/receipts.py", line 413, in insert_linearized_receipt_txn
    "data": json.dumps(data),
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/storage/database.py", line 652, in simple_insert_txn
    txn.execute(sql, vals)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/storage/database.py", line 199, in execute
    self._do_execute(self.txn.execute, sql, *args)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/storage/database.py", line 225, in _do_execute
    return func(sql, *args)
psycopg2.errors.UniqueViolation: duplicate key value violates unique constraint "receipts_linearized_uniqueness"
DETAIL:  Key (room_id, receipt_type, user_id)=(!*****.church.tools, m.read, @*****:chat.church.tools) already exists.

These errors happen sometime but i'm not able to reproduce them by myself.
I guess it's a bug, because it is a 500 internal server error.

Version information

What version of Synapse is running?

• Version: 1.12.3

• Install method: package manager

• Platform: vm

[anoadragon453]

This violation theoretically shouldn't occur normally as the code will delete any rows with matching (room_id, receipt_type, user_id) before attempting to insert:

synapse/synapse/storage/data_stores/main/receipts.py

Lines 394 to 415 in 509e381

	self.db.simple_delete_txn(
	txn,
	table="receipts_linearized",
	keyvalues={
	"room_id": room_id,
	"receipt_type": receipt_type,
	"user_id": user_id,
	},
	)
	self.db.simple_insert_txn(
	txn,
	table="receipts_linearized",
	values={
	"stream_id": stream_id,
	"room_id": room_id,
	"receipt_type": receipt_type,
	"user_id": user_id,
	"event_id": event_id,
	"data": json.dumps(data),
	},
	)

Could I have some more information about your database?

• Are you running with SQLite3 or Postgresql?
• Does Synapse print Database has incorrect collation or Database has incorrect ctype or something to that effect in the logs on startup?

Additionally, for each of these errors, are the room_id/user_id combination always the same? If so, does executing

SELECT * FROM receipts_linearized WHERE room_id = '!******.chuch.tools' AND receipt_type = 'm.read' AND user_id = '@*****:chat.church.tools';

on your database bring up more than one row?

[djschilling]

• I am running Postgresql
• No logs are logged about incorrect collation or ctype
• The more detailed message appears only twice. With the same user/room combination. The database only returns one row for the query.

[richvdh]

it's probably just a race from two requests setting the read marker at once? Possibly that delete and insert should be an upsert?