Traceback in synapse.metrics.background_process_metrics

[MayeulC]

Description

I am having issues federating with matrix.org. Inbound federation works, but matrix.org users can only receive my messages trough another server. My logs are spammed multiple times per second with the following traceback (I don't even have metrics enabled, as far as I can tell):

sept. 15 15:01:47 services.mayeul.net python[18942]: 2020-09-15 15:01:47,616 - synapse.http.matrixfederationclient - 507 - WARNING - federation_transaction_transmission_loop-42640- {PUT-O-26322} [rclb.dev] Request failed: PUT matrix://rclb.dev/_matrix/federation/v1/send/1600166541646: TimeoutError('')
sept. 15 15:01:48 services.mayeul.net python[18942]: 2020-09-15 15:01:48,391 - synapse.metrics.background_process_metrics - 222 - ERROR - user_directory.notify_new_event-16258- Background process 'user_directory.notify_new_event' threw an exception
sept. 15 15:01:48 services.mayeul.net python[18942]: Traceback (most recent call last):
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/synapse/metrics/background_process_metrics.py", line 214, in run
sept. 15 15:01:48 services.mayeul.net python[18942]:     return (yield result)
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
sept. 15 15:01:48 services.mayeul.net python[18942]:     result = result.throwExceptionIntoGenerator(g)
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
sept. 15 15:01:48 services.mayeul.net python[18942]:     return g.throw(self.type, self.value, self.tb)
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/synapse/handlers/user_directory.py", line 103, in process
sept. 15 15:01:48 services.mayeul.net python[18942]:     await self._unsafe_process()
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/synapse/handlers/user_directory.py", line 154, in _unsafe_process
sept. 15 15:01:48 services.mayeul.net python[18942]:     await self._handle_deltas(deltas)
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/synapse/handlers/user_directory.py", line 217, in _handle_deltas
sept. 15 15:01:48 services.mayeul.net python[18942]:     state_key, room_id, prev_event_id, event_id
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/synapse/handlers/user_directory.py", line 396, in _handle_profile_change
sept. 15 15:01:48 services.mayeul.net python[18942]:     await self.store.update_profile_in_user_dir(user_id, new_name, new_avatar)
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
sept. 15 15:01:48 services.mayeul.net python[18942]:     result = result.throwExceptionIntoGenerator(g)
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
sept. 15 15:01:48 services.mayeul.net python[18942]:     return g.throw(self.type, self.value, self.tb)
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py", line 525, in runInteraction
sept. 15 15:01:48 services.mayeul.net python[18942]:     **kwargs
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
sept. 15 15:01:48 services.mayeul.net python[18942]:     result = result.throwExceptionIntoGenerator(g)
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
sept. 15 15:01:48 services.mayeul.net python[18942]:     return g.throw(self.type, self.value, self.tb)
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py", line 573, in runWithConnection
sept. 15 15:01:48 services.mayeul.net python[18942]:     self._db_pool.runWithConnection(inner_func, *args, **kwargs)
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/twisted/python/threadpool.py", line 250, in inContext
sept. 15 15:01:48 services.mayeul.net python[18942]:     result = inContext.theWork()
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/twisted/python/threadpool.py", line 266, in <lambda>
sept. 15 15:01:48 services.mayeul.net python[18942]:     inContext.theWork = lambda: context.call(ctx, func, *args, **kw)
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/twisted/python/context.py", line 122, in callWithContext
sept. 15 15:01:48 services.mayeul.net python[18942]:     return self.currentContext().callWithContext(ctx, func, *args, **kw)
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/twisted/python/context.py", line 85, in callWithContext
sept. 15 15:01:48 services.mayeul.net python[18942]:     return func(*args,**kw)
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/twisted/enterprise/adbapi.py", line 306, in _runWithConnection
sept. 15 15:01:48 services.mayeul.net python[18942]:     compat.reraise(excValue, excTraceback)
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/twisted/python/compat.py", line 464, in reraise
sept. 15 15:01:48 services.mayeul.net python[18942]:     raise exception.with_traceback(traceback)
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/twisted/enterprise/adbapi.py", line 297, in _runWithConnection
sept. 15 15:01:48 services.mayeul.net python[18942]:     result = func(conn, *args, **kw)
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py", line 570, in inner_func
sept. 15 15:01:48 services.mayeul.net python[18942]:     return func(conn, *args, **kwargs)
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py", line 416, in new_transaction
sept. 15 15:01:48 services.mayeul.net python[18942]:     r = func(cursor, *args, **kwargs)
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/synapse/storage/data_stores/main/user_directory.py", line 400, in _update_profile_in_user_dir_txn
sept. 15 15:01:48 services.mayeul.net python[18942]:     display_name,
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py", line 208, in execute
sept. 15 15:01:48 services.mayeul.net python[18942]:     self._do_execute(self.txn.execute, sql, *args)
sept. 15 15:01:48 services.mayeul.net python[18942]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/synapse/storage/database.py", line 234, in _do_execute
sept. 15 15:01:48 services.mayeul.net python[18942]:     return func(sql, *args)
sept. 15 15:01:48 services.mayeul.net python[18942]: psycopg2.errors.InvalidTextRepresentation: ERREUR:  tableau litéral mal formé : «  »
sept. 15 15:01:48 services.mayeul.net python[18942]: LINE 1: ...t(to_tsvector('english', COALESCE(ARRAY['tulir'], '')), 'B')...
sept. 15 15:01:48 services.mayeul.net python[18942]:                                                              ^
sept. 15 15:01:48 services.mayeul.net python[18942]: DETAIL:  La valeur du tableau doit commencer par « { » ou avec l'information de la
sept. 15 15:01:48 services.mayeul.net python[18942]: dimension.

Roughly translating the last error, that gives:

ERROR:malformed array literal: " "
DETAIL: array value must start with "{" or with dimension information

Steps to reproduce

• start synapse

Unfortunately, I don't really know which specific configuration could help reproducing the issue. I can add more verbose logging to the python scripts if you tell me what is needed.

Version information

• Homeserver: mayeul.net

If not matrix.org:

• Version: 1.18.0 (also reproduces on 1.19.0 and 1.19.1).

• Install method: yunohost app

• Platform: yunohost

[clokep]

I think this is a duplicate of #8220, which will be fixed in Synapse v1.20.0.

[MayeulC]

Thanks a lot for pointing this out, that looked a lot like a duplicate, and it seems like this is fixed now that I use 1.20.0rc3.

[clokep]

Thanks for confirming that it is fixed in the upcoming upgrade! 👍

[MayeulC]

Though I still do not federate with matrix.org 👀

The only noteworthy things in my logs are the following:

Similar to #4727 :

sept. 15 19:30:18 services.mayeul.net python[20879]: 2020-09-15 19:30:18,529 - twisted - 231 - CRITICAL - - Unhandled Error
sept. 15 19:30:18 services.mayeul.net python[20879]: Traceback (most recent call last):
sept. 15 19:30:18 services.mayeul.net python[20879]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/twisted/python/log.py", line 103, in callWithLogger
sept. 15 19:30:18 services.mayeul.net python[20879]:     return callWithContext({"system": lp}, func, *args, **kw)
sept. 15 19:30:18 services.mayeul.net python[20879]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/twisted/python/log.py", line 86, in callWithContext
sept. 15 19:30:18 services.mayeul.net python[20879]:     return context.call({ILogContext: newCtx}, func, *args, **kw) 
sept. 15 19:30:18 services.mayeul.net python[20879]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/twisted/python/context.py", line 122, in callWithContext
sept. 15 19:30:18 services.mayeul.net python[20879]:     return self.currentContext().callWithContext(ctx, func, *args, **kw)
sept. 15 19:30:18 services.mayeul.net python[20879]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/twisted/python/context.py", line 85, in callWithContext
sept. 15 19:30:18 services.mayeul.net python[20879]:     return func(*args,**kw)
sept. 15 19:30:18 services.mayeul.net python[20879]: --- <exception caught here> ---
sept. 15 19:30:18 services.mayeul.net python[20879]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/twisted/internet/posixbase.py", line 619, in _doReadOrWrite
sept. 15 19:30:18 services.mayeul.net python[20879]:     why = selectable.doWrite()
sept. 15 19:30:18 services.mayeul.net python[20879]:   File "/opt/yunohost/matrix-synapse/lib/python3.7/site-packages/twisted/internet/base.py", line 1208, in doWrite
sept. 15 19:30:18 services.mayeul.net python[20879]:     "doWrite called on a %s" % reflect.qual(self.__class__))
sept. 15 19:30:18 services.mayeul.net python[20879]: builtins.RuntimeError: doWrite called on a twisted.internet.udp.Port

Similar to #5604 and #8118 (I might have a slight case of the latter, as I had DNS lookup errors, which didn't subside when I added matrix-federation.matrix.org to /etc/hosts).

sept. 15 19:30:50 services.mayeul.net python[20879]: 2020-09-15 19:30:50,764 - synapse.logging.context - 351 - WARNING - federation_transaction_transmission_loop-2801- Expected logging context federation_transaction_transmission_loop-2801 was lost
sept. 15 19:30:51 services.mayeul.net python[20879]: 2020-09-15 19:30:51,413 - synapse.logging.context - 396 - WARNING - federation_transaction_transmission_loop-2801- Re-starting finished log context federation_transaction_transmission_loop-2801
sept. 15 19:30:51 services.mayeul.net python[20879]: 2020-09-15 19:30:51,413 - synapse.logging.context - 396 - WARNING - federation_transaction_transmission_loop-2801- Re-starting finished log context federation_transaction_transmission_loop-2801
(...)
sept. 15 19:32:14 services.mayeul.net python[20879]: 2020-09-15 19:32:14,689 - synapse.logging.context - 596 - WARNING - federation_transaction_transmission_loop-2801- Expected logging context sentinel but found federation_transaction_transmission_loop-2854

Interesting to me is that these errors started to happen on an otherwise long-running server (Synapse has been up for more than a year, not without some hiccups). I just happened to perform some postgresql DB maintenance lately, that's the only related thing I can see. I'll reboot the server just to see.

---

Edit: solved by increasing timeout, filled #8338