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

"logging error" in logs #8389

Closed
Sursur123 opened this issue Sep 23, 2020 · 6 comments
Closed

"logging error" in logs #8389

Sursur123 opened this issue Sep 23, 2020 · 6 comments

Comments

@Sursur123
Copy link

Sursur123 commented Sep 23, 2020 •
edited
Loading

Description

I cannot join external rooms eg. from matrix.org. I cannot invite external members.
Someone from #synapse:matrix.org told me I should file an issue here.
Federationtester shows Success - No SRV Records

Steps to reproduce

  • Connect to homeserver using Element
  • Click "Explore rooms"
  • Click dropdown "Matrix rooms"
  • Tick matrix.org
  • Error in Element is shown: "No key for hostname.com with ids in ['ed25519:a_rFQL'] (min_validity 1600889737231)"
  • Log (loglevel of "root" set to DEBUG in log.yaml) from homeserver below

Version information

-Logs:

2020-09-23 17:26:32,786 - synapse.access.http.8008 - 290 - INFO - POST-1 - 192.168.1.1 - 8008 - {@user:example.com} Processed request: 0.013sec/-0.000sec (0.004sec, 0.000sec) (0.003sec/0.006sec/3) 42B 200 "POST /_matrix/client/r0/publicRooms HTTP/1.0" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.7 Chrome/83.0.4103.122 Electron/9.1.2 Safari/537.36" [0 dbevts]
2020-09-23 17:26:34,266 - synapse.access.http.8008 - 241 - DEBUG - OPTIONS-2 - 192.168.1.1 - 8008 - Received request: OPTIONS /_matrix/client/r0/publicRooms?server=matrix.org
2020-09-23 17:26:34,266 - synapse.access.http.8008 - 290 - DEBUG - OPTIONS-2 - 192.168.1.1 - 8008 - {None} Processed request: 0.001sec/-0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 0B 204 "OPTIONS /_matrix/client/r0/publicRooms?server=matrix.org HTTP/1.0" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.7 Chrome/83.0.4103.122 Electron/9.1.2 Safari/537.36" [0 dbevts]
2020-09-23 17:26:34,271 - synapse.access.http.8008 - 241 - DEBUG - POST-3 - 192.168.1.1 - 8008 - Received request: POST /_matrix/client/r0/publicRooms?server=matrix.org
2020-09-23 17:26:34,272 - synapse.util.caches.response_cache - 147 - DEBUG - POST-3 - [remote_room_list]: no cached result for [('matrix.org', 20, None, False, None)], calculating new one
2020-09-23 17:26:34,296 - twisted - 231 - ERROR -  - --- Logging error ---
2020-09-23 17:26:34,301 - twisted - 231 - ERROR -  - Traceback (most recent call last):
2020-09-23 17:26:34,301 - twisted - 231 - ERROR -  -   File "/usr/lib/python3.8/logging/__init__.py", line 436, in format
2020-09-23 17:26:34,302 - twisted - 231 - ERROR -  -     return self._format(record)
2020-09-23 17:26:34,302 - twisted - 231 - ERROR -  -   File "/usr/lib/python3.8/logging/__init__.py", line 432, in _format
2020-09-23 17:26:34,302 - twisted - 231 - ERROR -  -     return self._fmt % record.__dict__
2020-09-23 17:26:34,302 - twisted - 231 - ERROR -  - KeyError: 'request'
2020-09-23 17:26:34,302 - twisted - 231 - ERROR -  -
2020-09-23 17:26:34,303 - twisted - 231 - ERROR -  - During handling of the above exception, another exception occurred:
2020-09-23 17:26:34,303 - twisted - 231 - ERROR -  -
2020-09-23 17:26:34,303 - twisted - 231 - ERROR -  - Traceback (most recent call last):
2020-09-23 17:26:34,303 - twisted - 231 - ERROR -  -   File "/usr/lib/python3.8/logging/__init__.py", line 1081, in emit
2020-09-23 17:26:34,303 - twisted - 231 - ERROR -  -     msg = self.format(record)
2020-09-23 17:26:34,303 - twisted - 231 - ERROR -  -   File "/usr/lib/python3.8/logging/__init__.py", line 925, in format
2020-09-23 17:26:34,303 - twisted - 231 - ERROR -  -     return fmt.format(record)
2020-09-23 17:26:34,304 - twisted - 231 - ERROR -  -   File "/usr/lib/python3.8/logging/__init__.py", line 667, in format
2020-09-23 17:26:34,304 - twisted - 231 - ERROR -  -     s = self.formatMessage(record)
2020-09-23 17:26:34,304 - twisted - 231 - ERROR -  -   File "/usr/lib/python3.8/logging/__init__.py", line 636, in formatMessage
2020-09-23 17:26:34,304 - twisted - 231 - ERROR -  -     return self._style.format(record)
2020-09-23 17:26:34,304 - twisted - 231 - ERROR -  -   File "/usr/lib/python3.8/logging/__init__.py", line 438, in format
2020-09-23 17:26:34,304 - twisted - 231 - ERROR -  -     raise ValueError('Formatting field not found in record: %s' % e)
2020-09-23 17:26:34,304 - twisted - 231 - ERROR -  - ValueError: Formatting field not found in record: 'request'
2020-09-23 17:26:34,305 - twisted - 231 - ERROR -  - Call stack:
2020-09-23 17:26:34,309 - twisted - 231 - ERROR -  -   File "/usr/lib/python3.8/runpy.py", line 193, in _run_module_as_main
2020-09-23 17:26:34,309 - twisted - 231 - ERROR -  -     return _run_code(code, main_globals, None,
2020-09-23 17:26:34,309 - twisted - 231 - ERROR -  -   File "/usr/lib/python3.8/runpy.py", line 86, in _run_code
2020-09-23 17:26:34,309 - twisted - 231 - ERROR -  -     exec(code, run_globals)
2020-09-23 17:26:34,310 - twisted - 231 - ERROR -  -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/app/homeserver.py", line 687, in <module>
2020-09-23 17:26:34,310 - twisted - 231 - ERROR -  -     main()
2020-09-23 17:26:34,310 - twisted - 231 - ERROR -  -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/app/homeserver.py", line 683, in main
2020-09-23 17:26:34,310 - twisted - 231 - ERROR -  -     run(hs)
2020-09-23 17:26:34,310 - twisted - 231 - ERROR -  -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/app/homeserver.py", line 667, in run
2020-09-23 17:26:34,310 - twisted - 231 - ERROR -  -     _base.start_reactor(
2020-09-23 17:26:34,310 - twisted - 231 - ERROR -  -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/app/_base.py", line 132, in start_reactor
2020-09-23 17:26:34,310 - twisted - 231 - ERROR -  -     run()
2020-09-23 17:26:34,310 - twisted - 231 - ERROR -  -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/app/_base.py", line 116, in run
2020-09-23 17:26:34,310 - twisted - 231 - ERROR -  -     run_command()
2020-09-23 17:26:34,311 - twisted - 231 - ERROR -  -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/base.py", line 1283, in run
2020-09-23 17:26:34,311 - twisted - 231 - ERROR -  -     self.mainLoop()
2020-09-23 17:26:34,311 - twisted - 231 - ERROR -  -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/base.py", line 1292, in mainLoop
2020-09-23 17:26:34,311 - twisted - 231 - ERROR -  -     self.runUntilCurrent()
2020-09-23 17:26:34,311 - twisted - 231 - ERROR -  -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/metrics/__init__.py", line 517, in f
2020-09-23 17:26:34,311 - twisted - 231 - ERROR -  -     ret = func(*args, **kwargs)
2020-09-23 17:26:34,311 - twisted - 231 - ERROR -  -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/base.py", line 886, in runUntilCurrent
2020-09-23 17:26:34,311 - twisted - 231 - ERROR -  -     f(*a, **kw)
2020-09-23 17:26:34,311 - twisted - 231 - ERROR -  -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 460, in callback
2020-09-23 17:26:34,311 - twisted - 231 - ERROR -  -     self._startRunCallbacks(result)
2020-09-23 17:26:34,312 - twisted - 231 - ERROR -  -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
2020-09-23 17:26:34,312 - twisted - 231 - ERROR -  -     self._runCallbacks()
2020-09-23 17:26:34,312 - twisted - 231 - ERROR -  -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
2020-09-23 17:26:34,312 - twisted - 231 - ERROR -  -     current.result = callback(current.result, *args, **kw)
2020-09-23 17:26:34,312 - twisted - 231 - ERROR -  -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/_resolver.py", line 137, in deliverResults
2020-09-23 17:26:34,312 - twisted - 231 - ERROR -  -     resolutionReceiver.resolutionComplete()
2020-09-23 17:26:34,312 - twisted - 231 - ERROR -  -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/app/_base.py", line 428, in resolutionComplete
2020-09-23 17:26:34,312 - twisted - 231 - ERROR -  -     self._deferred.callback(())
2020-09-23 17:26:34,312 - twisted - 231 - ERROR -  -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 460, in callback
2020-09-23 17:26:34,312 - twisted - 231 - ERROR -  -     self._startRunCallbacks(result)
2020-09-23 17:26:34,312 - twisted - 231 - ERROR -  -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
2020-09-23 17:26:34,312 - twisted - 231 - ERROR -  -     self._runCallbacks()
2020-09-23 17:26:34,313 - twisted - 231 - ERROR -  -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
2020-09-23 17:26:34,313 - twisted - 231 - ERROR -  -     current.result = callback(current.result, *args, **kw)
2020-09-23 17:26:34,313 - twisted - 231 - ERROR -  -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 1475, in gotResult
2020-09-23 17:26:34,313 - twisted - 231 - ERROR -  -     _inlineCallbacks(r, g, status)
2020-09-23 17:26:34,313 - twisted - 231 - ERROR -  -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
2020-09-23 17:26:34,313 - twisted - 231 - ERROR -  -     result = g.send(result)
2020-09-23 17:26:34,313 - twisted - 231 - ERROR -  -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/app/_base.py", line 409, in _resolve
2020-09-23 17:26:34,313 - twisted - 231 - ERROR -  -     yield deferred
2020-09-23 17:26:34,313 - twisted - 231 - ERROR -  -   File "/usr/lib/python3.8/contextlib.py", line 120, in __exit__
2020-09-23 17:26:34,313 - twisted - 231 - ERROR -  -     next(self.gen)
2020-09-23 17:26:34,313 - twisted - 231 - ERROR -  -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/util/async_helpers.py", line 266, in _ctx_manager
2020-09-23 17:26:34,313 - twisted - 231 - ERROR -  -     logger.debug("Releasing linearizer lock %r for key %r", self.name, key)
2020-09-23 17:26:34,314 - twisted - 231 - ERROR -  - Message: "Invoked '%(func_name)s' with args: %(args)s"
2020-09-23 17:26:34,314 - twisted - 231 - ERROR -  - Arguments: {'func_name': 'get_public_rooms', 'args': 'self=<synapse.federation.transport.client.TransportLaye..., remote_server=matrix.org, limit=20, since_token=None, search_filter=None, include_all_networks=False, third_party_instance_id=None'}


2020-09-23 17:26:34,327 - synapse.storage.txn - 415 - DEBUG - GET-6 - [TXN START] {get_rooms_for_user_with_stream_ordering-f}
2020-09-23 17:26:34,328 - synapse.storage.txn - 504 - DEBUG - GET-6 - [TXN END] {get_rooms_for_user_with_stream_ordering-f} 0.000622 sec
2020-09-23 17:26:34,328 - synapse.handlers.sync - 994 - DEBUG - GET-6 - Fetching account data
2020-09-23 17:26:34,328 - synapse.handlers.sync - 1000 - DEBUG - GET-6 - Fetching room data
2020-09-23 17:26:34,329 - synapse.handlers.sync - 1391 - DEBUG - GET-6 - no-oping sync
2020-09-23 17:26:34,329 - synapse.handlers.sync - 1012 - DEBUG - GET-6 - Fetching presence data
2020-09-23 17:26:34,329 - twisted - 231 - ERROR - GET-6 - --- Logging error ---
2020-09-23 17:26:34,329 - twisted - 231 - ERROR - GET-6 - Traceback (most recent call last):
2020-09-23 17:26:34,329 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
2020-09-23 17:26:34,330 - twisted - 231 - ERROR - GET-6 -     result = g.send(result)
2020-09-23 17:26:34,330 - twisted - 231 - ERROR - GET-6 - StopIteration: frozenset({_GetRoomsForUserWithStreamOrdering(room_id='ID:hostname', stream_ordering=3), _GetRoomsForUserWithStreamOrdering(room_id='ID:hostname', stream_ordering=9), _GetRoomsForUserWithStreamOrdering(room_id='ID:hostname', stream_ordering=15)})
2020-09-23 17:26:34,330 - twisted - 231 - ERROR - GET-6 - During handling of the above exception, another exception occurred:
2020-09-23 17:26:34,330 - twisted - 231 - ERROR - GET-6 -
2020-09-23 17:26:34,330 - twisted - 231 - ERROR - GET-6 - Traceback (most recent call last):
2020-09-23 17:26:34,330 - twisted - 231 - ERROR - GET-6 -   File "/usr/lib/python3.8/logging/__init__.py", line 436, in format
2020-09-23 17:26:34,330 - twisted - 231 - ERROR - GET-6 -     return self._format(record)
2020-09-23 17:26:34,330 - twisted - 231 - ERROR - GET-6 -   File "/usr/lib/python3.8/logging/__init__.py", line 432, in _format
2020-09-23 17:26:34,330 - twisted - 231 - ERROR - GET-6 -     return self._fmt % record.__dict__
2020-09-23 17:26:34,330 - twisted - 231 - ERROR - GET-6 - KeyError: 'request'
2020-09-23 17:26:34,330 - twisted - 231 - ERROR - GET-6 -
2020-09-23 17:26:34,330 - twisted - 231 - ERROR - GET-6 - During handling of the above exception, another exception occurred:
2020-09-23 17:26:34,330 - twisted - 231 - ERROR - GET-6 -
2020-09-23 17:26:34,330 - twisted - 231 - ERROR - GET-6 - Traceback (most recent call last):
2020-09-23 17:26:34,330 - twisted - 231 - ERROR - GET-6 -   File "/usr/lib/python3.8/logging/__init__.py", line 1081, in emit
2020-09-23 17:26:34,330 - twisted - 231 - ERROR - GET-6 -     msg = self.format(record)
2020-09-23 17:26:34,331 - twisted - 231 - ERROR - GET-6 -   File "/usr/lib/python3.8/logging/__init__.py", line 925, in format
2020-09-23 17:26:34,331 - twisted - 231 - ERROR - GET-6 -     return fmt.format(record)
2020-09-23 17:26:34,331 - twisted - 231 - ERROR - GET-6 -   File "/usr/lib/python3.8/logging/__init__.py", line 667, in format
2020-09-23 17:26:34,331 - twisted - 231 - ERROR - GET-6 -     s = self.formatMessage(record)
2020-09-23 17:26:34,331 - twisted - 231 - ERROR - GET-6 -   File "/usr/lib/python3.8/logging/__init__.py", line 636, in formatMessage
2020-09-23 17:26:34,331 - twisted - 231 - ERROR - GET-6 -     return self._style.format(record)
2020-09-23 17:26:34,331 - twisted - 231 - ERROR - GET-6 -   File "/usr/lib/python3.8/logging/__init__.py", line 438, in format
2020-09-23 17:26:34,331 - twisted - 231 - ERROR - GET-6 -     raise ValueError('Formatting field not found in record: %s' % e)
2020-09-23 17:26:34,331 - twisted - 231 - ERROR - GET-6 - ValueError: Formatting field not found in record: 'request'
2020-09-23 17:26:34,331 - twisted - 231 - ERROR - GET-6 - Call stack:
2020-09-23 17:26:34,332 - twisted - 231 - ERROR - GET-6 -   File "/usr/lib/python3.8/runpy.py", line 193, in _run_module_as_main
2020-09-23 17:26:34,332 - twisted - 231 - ERROR - GET-6 -     return _run_code(code, main_globals, None,
2020-09-23 17:26:34,332 - twisted - 231 - ERROR - GET-6 -   File "/usr/lib/python3.8/runpy.py", line 86, in _run_code
2020-09-23 17:26:34,332 - twisted - 231 - ERROR - GET-6 -     exec(code, run_globals)
2020-09-23 17:26:34,332 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/app/homeserver.py", line 687, in <module>
2020-09-23 17:26:34,332 - twisted - 231 - ERROR - GET-6 -     main()
2020-09-23 17:26:34,332 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/app/homeserver.py", line 683, in main
2020-09-23 17:26:34,332 - twisted - 231 - ERROR - GET-6 -     run(hs)
2020-09-23 17:26:34,332 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/app/homeserver.py", line 667, in run
2020-09-23 17:26:34,332 - twisted - 231 - ERROR - GET-6 -     _base.start_reactor(
2020-09-23 17:26:34,332 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/app/_base.py", line 132, in start_reactor
2020-09-23 17:26:34,332 - twisted - 231 - ERROR - GET-6 -     run()
2020-09-23 17:26:34,332 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/app/_base.py", line 116, in run
2020-09-23 17:26:34,333 - twisted - 231 - ERROR - GET-6 -     run_command()
2020-09-23 17:26:34,333 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/base.py", line 1283, in run
2020-09-23 17:26:34,333 - twisted - 231 - ERROR - GET-6 -     self.mainLoop()
2020-09-23 17:26:34,333 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/base.py", line 1292, in mainLoop
2020-09-23 17:26:34,333 - twisted - 231 - ERROR - GET-6 -     self.runUntilCurrent()
2020-09-23 17:26:34,333 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/metrics/__init__.py", line 517, in f
2020-09-23 17:26:34,333 - twisted - 231 - ERROR - GET-6 -     ret = func(*args, **kwargs)
2020-09-23 17:26:34,333 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/base.py", line 886, in runUntilCurrent
2020-09-23 17:26:34,333 - twisted - 231 - ERROR - GET-6 -     f(*a, **kw)
2020-09-23 17:26:34,333 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 460, in callback
2020-09-23 17:26:34,333 - twisted - 231 - ERROR - GET-6 -     self._startRunCallbacks(result)
2020-09-23 17:26:34,333 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
2020-09-23 17:26:34,333 - twisted - 231 - ERROR - GET-6 -     self._runCallbacks()
2020-09-23 17:26:34,333 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
2020-09-23 17:26:34,333 - twisted - 231 - ERROR - GET-6 -     current.result = callback(current.result, *args, **kw)
2020-09-23 17:26:34,333 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 1475, in gotResult
2020-09-23 17:26:34,333 - twisted - 231 - ERROR - GET-6 -     _inlineCallbacks(r, g, status)
2020-09-23 17:26:34,333 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 1421, in _inlineCallbacks
2020-09-23 17:26:34,334 - twisted - 231 - ERROR - GET-6 -     status.deferred.callback(getattr(e, "value", None))
2020-09-23 17:26:34,334 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 460, in callback
2020-09-23 17:26:34,334 - twisted - 231 - ERROR - GET-6 -     self._startRunCallbacks(result)
2020-09-23 17:26:34,334 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
2020-09-23 17:26:34,334 - twisted - 231 - ERROR - GET-6 -     self._runCallbacks()
2020-09-23 17:26:34,334 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
2020-09-23 17:26:34,334 - twisted - 231 - ERROR - GET-6 -     current.result = callback(current.result, *args, **kw)
2020-09-23 17:26:34,334 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/util/async_helpers.py", line 67, in callback
2020-09-23 17:26:34,334 - twisted - 231 - ERROR - GET-6 -     self._observers.pop().callback(r)
2020-09-23 17:26:34,334 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 460, in callback
2020-09-23 17:26:34,334 - twisted - 231 - ERROR - GET-6 -     self._startRunCallbacks(result)
2020-09-23 17:26:34,334 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
2020-09-23 17:26:34,334 - twisted - 231 - ERROR - GET-6 -     self._runCallbacks()
2020-09-23 17:26:34,334 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
2020-09-23 17:26:34,334 - twisted - 231 - ERROR - GET-6 -     current.result = callback(current.result, *args, **kw)
2020-09-23 17:26:34,334 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 1475, in gotResult
2020-09-23 17:26:34,334 - twisted - 231 - ERROR - GET-6 -     _inlineCallbacks(r, g, status)
2020-09-23 17:26:34,334 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
2020-09-23 17:26:34,335 - twisted - 231 - ERROR - GET-6 -     result = g.send(result)
2020-09-23 17:26:34,335 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/handlers/sync.py", line 320, in _wait_for_sync_for_user
2020-09-23 17:26:34,335 - twisted - 231 - ERROR - GET-6 -     result = await self.current_sync_for_user(
2020-09-23 17:26:34,335 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/handlers/sync.py", line 352, in current_sync_for_user
2020-09-23 17:26:34,335 - twisted - 231 - ERROR - GET-6 -     return await self.generate_sync_result(sync_config, since_token, full_state)
2020-09-23 17:26:34,335 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/handlers/sync.py", line 1013, in generate_sync_result
2020-09-23 17:26:34,335 - twisted - 231 - ERROR - GET-6 -     await self._generate_sync_entry_for_presence(
2020-09-23 17:26:34,335 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/handlers/sync.py", line 1320, in _generate_sync_entry_for_presence
2020-09-23 17:26:34,335 - twisted - 231 - ERROR - GET-6 -     presence, presence_key = await presence_source.get_new_events(
2020-09-23 17:26:34,335 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/logging/utils.py", line 69, in wrapped
2020-09-23 17:26:34,335 - twisted - 231 - ERROR - GET-6 -     _log_debug_as_f(f, "Invoked '%(func_name)s' with args: %(args)s", msg_args)
2020-09-23 17:26:34,335 - twisted - 231 - ERROR - GET-6 -   File "/opt/venvs/matrix-synapse/lib/python3.8/site-packages/synapse/logging/utils.py", line 42, in _log_debug_as_f
2020-09-23 17:26:34,335 - twisted - 231 - ERROR - GET-6 -     logger.handle(record)
2020-09-23 17:26:34,335 - twisted - 231 - ERROR - GET-6 - Message: "Invoked '%(func_name)s' with args: %(args)s"
2020-09-23 17:26:34,335 - twisted - 231 - ERROR - GET-6 - Arguments: {'func_name': 'get_new_events', 'args': "self=<synapse.handlers.presence.PresenceEventSource obj..., kwargs={'is_guest': False}, user=@user:hostname, from_key=168, include_offline=True, room_ids=None, explicit_room_id=None"}
2020-09-23 17:26:34,336 - synapse.metrics - 543 - DEBUG -  - Collecting gc 0
2020-09-23 17:26:34,398 - synapse.http.federation.well_known_resolver - 186 - INFO - POST-3 - Response from .well-known: {'m.server': 'matrix-federation.matrix.org:443'}
2020-09-23 17:26:34,398 - synapse.http.federation.matrix_federation_agent - 250 - DEBUG - POST-3 - Connecting to matrix-federation.matrix.org:443
2020-09-23 17:26:34,399 - synapse.util.async_helpers - 252 - DEBUG -  - Acquired uncontended linearizer lock 'dns_client_limiter' for key ()
2020-09-23 17:26:34,400 - synapse.util.async_helpers - 266 - DEBUG -  - Releasing linearizer lock 'dns_client_limiter' for key ()
2020-09-23 17:26:34,726 - synapse.http.matrixfederationclient - 500 - INFO - POST-3 - {GET-O-1} [matrix.org] Got response headers: 401 Unauthorized
2020-09-23 17:26:34,727 - synapse.http.matrixfederationclient - 575 - WARNING - POST-3 - {GET-O-1} [matrix.org] Request failed: GET matrix://matrix.org/_matrix/federation/v1/publicRooms?include_all_networks=false&limit=20: HttpResponseException('401: Unauthorized')
2020-09-23 17:26:34,728 - synapse.http.server - 76 - INFO - POST-3 - <XForwardedForRequest at 0x7f3c9fa0af40 method='POST' uri='/_matrix/client/r0/publicRooms?server=matrix.org' clientproto='HTTP/1.0' site=8008> SynapseError: 401 - No key for hostname with ids in ['ed25519:a_rFQL'] (min_validity 1600874794554)
2020-09-23 17:26:34,729 - synapse.access.http.8008 - 290 - INFO - POST-3 - 192.168.1.1 - 8008 - {@user:hostname} Processed request: 0.458sec/-0.000sec (0.009sec, 0.000sec) (0.001sec/0.002sec/1) 132B 401 "POST /_matrix/client/r0/publicRooms?server=matrix.org HTTP/1.0" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.7 Chrome/83.0.4103.122 Electron/9.1.2 Safari/537.36" [0 dbevts]
@richvdh
Copy link
Member

richvdh commented Sep 23, 2020

the interesting thing here is the logging errors. please share your log.yaml file.

@richvdh richvdh changed the title 401 Unauthorized, no federation with matrix.org "logging error" in logs Sep 23, 2020
@Sursur123
Copy link
Author

Sursur123 commented Sep 23, 2020 •
edited
Loading

the interesting thing here is the logging errors. please share your log.yaml file.

I only changed the root loglevel.

#
# This is a YAML file containing a standard Python logging configuration
# dictionary. See [1] for details on the valid settings.
#
# [1]: https://docs.python.org/3.7/library/logging.config.html#configuration-dictionary-schema

version: 1

formatters:
    precise:
        format: '%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - %(request)s - %(message)s'

handlers:
    file:
        class: logging.handlers.TimedRotatingFileHandler
        formatter: precise
        filename: /var/log/matrix-synapse/homeserver.log
        when: midnight
        backupCount: 3  # Does not include the current log file.
        encoding: utf8

    # Default to buffering writes to log file for efficiency. This means that
    # will be a delay for INFO/DEBUG logs to get written, but WARNING/ERROR
    # logs will still be flushed immediately.
    buffer:
        class: logging.handlers.MemoryHandler
        target: file
        # The capacity is the number of log lines that are buffered before
        # being written to disk. Increasing this will lead to better
        # performance, at the expensive of it taking longer for log lines to
        # be written to disk.
        capacity: 10
        flushLevel: 30  # Flush for WARNING logs as well

    # A handler that writes logs to stderr. Unused by default, but can be used
    # instead of "buffer" and "file" in the logger handlers.
    console:
        class: logging.StreamHandler
        formatter: precise

loggers:
    synapse.storage.SQL:
        # beware: increasing this to DEBUG will make synapse log sensitive
        # information such as access tokens.
        level: INFO

    twisted:
        # We send the twisted logging directly to the file handler,
        # to work around https://github.com/matrix-org/synapse/issues/3471
        # when using "buffer" logger. Use "console" to log to stderr instead.
        handlers: [file]
        propagate: false

root:
    level: DEBUG

    # Write logs to the `buffer` handler, which will buffer them together in memory,
    # then write them to a file.
    #
    # Replace "buffer" with "console" to log to stderr instead. (Note that you'll
    # also need to update the configuation for the `twisted` logger above, in
    # this case.)
    #
    handlers: [buffer]

disable_existing_loggers: false

@Sursur123
Copy link
Author

My issue with connection to matrix.org seems to be the same as in #7762.
dig -t SRV _matrix._tcp.hostname gives me SERVFAIL

@richvdh
Copy link
Member

richvdh commented Sep 23, 2020

you'll need to seek help in #synapse:matrix.org for getting federation working. I'll look into the logging errors.

@richvdh
Copy link
Member

richvdh commented Sep 23, 2020

right, sorry, the logging errors are the same problem as are fixed by #8278, which will be in a future release of synapse. In the meantime, I suggest you set the level back to INFO: it's unlikely you'll find much of help in the DEBUG level.

@richvdh richvdh closed this as completed Sep 23, 2020
@richvdh
Copy link
Member

richvdh commented Sep 23, 2020

dig -t SRV _matrix._tcp.hostname gives me SERVFAIL

if this is true, it suggests a problem with your DNS provider which you'll need to get fixed.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@richvdh @Sursur123