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

Trying to debug server issues - However overflow of errors #8495

Closed
melroy89 opened this issue Oct 7, 2020 · 1 comment
Closed

Trying to debug server issues - However overflow of errors #8495

melroy89 opened this issue Oct 7, 2020 · 1 comment

Comments

@melroy89
Copy link

melroy89 commented Oct 7, 2020 •
edited
Loading

Description

Hi backend team. Where to start, so I'm hosting my own Synapse homeserver. Which should be made easier, more stable and better performing. I think we all agree on that.

Personally, I'm facing quite a variety of issues on my homeserver (with just 2 users). To name a few:

  • Issues with joining rooms (~2000 people)
  • Issues with signature checking and decrypting keys
  • Other connection issues causing stability issues, ...

Trying to debug via the logging is very problematic to say the least. Therefore my approach would be the clear-up most of the error message --> low-hanging fruit. Which are basically spamming the logs (unnecessary).

Spamming the logs is not only problematic for debugging but also for the performance as well. The default log level of Synapse (DEBUG) can therefore cause a lot of disk I/O (which is very slow, slowing down the server in general). Especially the long trackback calls! I hope you agree.

Bottom-line; before I can provide you more useful information that would be easier to pin-pointing the root cause; I hope some of the following errors can be relativity easily solved (making it easier to find the actual errors).

Errors

Download all (compressed): log_files.tar.gz

Without further ado, lets see what I mean.

Stdout traceback with PUT-4809

{"log":"2020-10-07 21:51:05,017 - twisted - 231 - ERROR - PUT-4809 - --- Logging error ---\n","stream":"stderr","time":"2020-10-07T21:51:05.017612052Z"}
{"log":"2020-10-07 21:51:05,017 - twisted - 231 - ERROR - PUT-4809 - Traceback (most recent call last):\n","stream":"stderr","time":"2020-10-07T21:51:05.017925241Z"}
{"log":"2020-10-07 21:51:05,017 - twisted - 231 - ERROR - PUT-4809 -   File \"/usr/local/lib/python3.7/logging/__init__.py\", line 1025, in emit\n","stream":"stderr","time":"2020-10-07T21:51:05.018147809Z"}
{"log":"2020-10-07 21:51:05,018 - twisted - 231 - ERROR - PUT-4809 -     msg = self.format(record)\n","stream":"stderr","time":"2020-10-07T21:51:05.018297186Z"}
{"log":"2020-10-07 21:51:05,018 - twisted - 231 - ERROR - PUT-4809 -   File \"/usr/local/lib/python3.7/logging/__init__.py\", line 869, in format\n","stream":"stderr","time":"2020-10-07T21:51:05.018461161Z"}
{"log":"2020-10-07 21:51:05,018 - twisted - 231 - ERROR - PUT-4809 -     return fmt.format(record)\n","stream":"stderr","time":"2020-10-07T21:51:05.01860364Z"}
{"log":"2020-10-07 21:51:05,018 - twisted - 231 - ERROR - PUT-4809 -   File \"/usr/local/lib/python3.7/logging/__init__.py\", line 611, in format\n","stream":"stderr","time":"2020-10-07T21:51:05.018759498Z"}
{"log":"2020-10-07 21:51:05,018 - twisted - 231 - ERROR - PUT-4809 -     s = self.formatMessage(record)\n","stream":"stderr","time":"2020-10-07T21:51:05.018902597Z"}
{"log":"2020-10-07 21:51:05,018 - twisted - 231 - ERROR - PUT-4809 -   File \"/usr/local/lib/python3.7/logging/__init__.py\", line 580, in formatMessage\n","stream":"stderr","time":"2020-10-07T21:51:05.019091656Z"}
{"log":"2020-10-07 21:51:05,019 - twisted - 231 - ERROR - PUT-4809 -     return self._style.format(record)\n","stream":"stderr","time":"2020-10-07T21:51:05.019247053Z"}
{"log":"2020-10-07 21:51:05,019 - twisted - 231 - ERROR - PUT-4809 -   File \"/usr/local/lib/python3.7/logging/__init__.py\", line 422, in format\n","stream":"stderr","time":"2020-10-07T21:51:05.019407853Z"}
{"log":"2020-10-07 21:51:05,019 - twisted - 231 - ERROR - PUT-4809 -     return self._fmt % record.__dict__\n","stream":"stderr","time":"2020-10-07T21:51:05.019552361Z"}
{"log":"2020-10-07 21:51:05,019 - twisted - 231 - ERROR - PUT-4809 - KeyError: 'request'\n","stream":"stderr","time":"2020-10-07T21:51:05.01972942Z"}
{"log":"2020-10-07 21:51:05,019 - twisted - 231 - ERROR - PUT-4809 - Call stack:\n","stream":"stderr","time":"2020-10-07T21:51:05.019907892Z"}
{"log":"2020-10-07 21:51:05,020 - twisted - 231 - ERROR - PUT-4809 -   File \"/usr/local/lib/python3.7/runpy.py\", line 193, in _run_module_as_main\n","stream":"stderr","time":"2020-10-07T21:51:05.021270969Z"}
{"log":"2020-10-07 21:51:05,021 - twisted - 231 - ERROR - PUT-4809 -     \"__main__\", mod_spec)\n","stream":"stderr","time":"2020-10-07T21:51:05.021413606Z"}
{"log":"2020-10-07 21:51:05,021 - twisted - 231 - ERROR - PUT-4809 -   File \"/usr/local/lib/python3.7/runpy.py\", line 85, in _run_code\n","stream":"stderr","time":"2020-10-07T21:51:05.021544054Z"}
{"log":"2020-10-07 21:51:05,021 - twisted - 231 - ERROR - PUT-4809 -     exec(code, run_globals)\n","stream":"stderr","time":"2020-10-07T21:51:05.021713686Z"}
{"log":"2020-10-07 21:51:05,021 - twisted - 231 - ERROR - PUT-4809 -   File \"/usr/local/lib/python3.7/site-packages/synapse/app/homeserver.py\", line 687, in \u003cmodule\u003e\n","stream":"stderr","time":"2020-10-07T21:51:05.022078021Z"}
{"log":"2020-10-07 21:51:05,021 - twisted - 231 - ERROR - PUT-4809 -     main()\n","stream":"stderr","time":"2020-10-07T21:51:05.022107161Z"}
{"log":"2020-10-07 21:51:05,022 - twisted - 231 - ERROR - PUT-4809 -   File \"/usr/local/lib/python3.7/site-packages/synapse/app/homeserver.py\", line 683, in main\n","stream":"stderr","time":"2020-10-07T21:51:05.022220525Z"}
{"log":"2020-10-07 21:51:05,022 - twisted - 231 - ERROR - PUT-4809 -     run(hs)\n","stream":"stderr","time":"2020-10-07T21:51:05.022380961Z"}
{"log":"2020-10-07 21:51:05,022 - twisted - 231 - ERROR - PUT-4809 -   File \"/usr/local/lib/python3.7/site-packages/synapse/app/homeserver.py\", line 674, in run\n","stream":"stderr","time":"2020-10-07T21:51:05.022535926Z"}
{"log":"2020-10-07 21:51:05,022 - twisted - 231 - ERROR - PUT-4809 -     logger=logger,\n","stream":"stderr","time":"2020-10-07T21:51:05.022678323Z"}
{"log":"2020-10-07 21:51:05,022 - twisted - 231 - ERROR - PUT-4809 -   File \"/usr/local/lib/python3.7/site-packages/synapse/app/_base.py\", line 132, in start_reactor\n","stream":"stderr","time":"2020-10-07T21:51:05.02283373Z"}
{"log":"2020-10-07 21:51:05,022 - twisted - 231 - ERROR - PUT-4809 -     run()\n","stream":"stderr","time":"2020-10-07T21:51:05.022977Z"}
{"log":"2020-10-07 21:51:05,022 - twisted - 231 - ERROR - PUT-4809 -   File \"/usr/local/lib/python3.7/site-packages/synapse/app/_base.py\", line 116, in run\n","stream":"stderr","time":"2020-10-07T21:51:05.023132399Z"}
{"log":"2020-10-07 21:51:05,023 - twisted - 231 - ERROR - PUT-4809 -     run_command()\n","stream":"stderr","time":"2020-10-07T21:51:05.023273353Z"}
{"log":"2020-10-07 21:51:05,023 - twisted - 231 - ERROR - PUT-4809 -   File \"/usr/local/lib/python3.7/site-packages/twisted/internet/base.py\", line 1283, in run\n","stream":"stderr","time":"2020-10-07T21:51:05.023429902Z"}
{"log":"2020-10-07 21:51:05,023 - twisted - 231 - ERROR - PUT-4809 -     self.mainLoop()\n","stream":"stderr","time":"2020-10-07T21:51:05.023573415Z"}

And another example with federation_transaction_transmission_loop:

{"log":"2020-10-07 21:54:14,063 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 - --- Logging error ---\n","stream":"stderr","time":"2020-10-07T21:54:14.065152879Z"}
{"log":"2020-10-07 21:54:14,063 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 - Traceback (most recent call last):\n","stream":"stderr","time":"2020-10-07T21:54:14.065159009Z"}
{"log":"2020-10-07 21:54:14,063 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/logging/__init__.py\", line 1025, in emit\n","stream":"stderr","time":"2020-10-07T21:54:14.065165474Z"}
{"log":"2020-10-07 21:54:14,063 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     msg = self.format(record)\n","stream":"stderr","time":"2020-10-07T21:54:14.065172028Z"}
{"log":"2020-10-07 21:54:14,064 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/logging/__init__.py\", line 869, in format\n","stream":"stderr","time":"2020-10-07T21:54:14.065178235Z"}
{"log":"2020-10-07 21:54:14,064 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     return fmt.format(record)\n","stream":"stderr","time":"2020-10-07T21:54:14.065184782Z"}
{"log":"2020-10-07 21:54:14,064 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/logging/__init__.py\", line 611, in format\n","stream":"stderr","time":"2020-10-07T21:54:14.06519093Z"}
{"log":"2020-10-07 21:54:14,064 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     s = self.formatMessage(record)\n","stream":"stderr","time":"2020-10-07T21:54:14.065197429Z"}
{"log":"2020-10-07 21:54:14,064 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/logging/__init__.py\", line 580, in formatMessage\n","stream":"stderr","time":"2020-10-07T21:54:14.065203947Z"}
{"log":"2020-10-07 21:54:14,064 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     return self._style.format(record)\n","stream":"stderr","time":"2020-10-07T21:54:14.06523502Z"}
{"log":"2020-10-07 21:54:14,064 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/logging/__init__.py\", line 422, in format\n","stream":"stderr","time":"2020-10-07T21:54:14.065259361Z"}
{"log":"2020-10-07 21:54:14,064 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     return self._fmt % record.__dict__\n","stream":"stderr","time":"2020-10-07T21:54:14.065274542Z"}
{"log":"2020-10-07 21:54:14,065 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 - KeyError: 'request'\n","stream":"stderr","time":"2020-10-07T21:54:14.065441084Z"}
{"log":"2020-10-07 21:54:14,065 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 - Call stack:\n","stream":"stderr","time":"2020-10-07T21:54:14.065521794Z"}
{"log":"2020-10-07 21:54:14,066 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/runpy.py\", line 193, in _run_module_as_main\n","stream":"stderr","time":"2020-10-07T21:54:14.066520444Z"}
{"log":"2020-10-07 21:54:14,066 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     \"__main__\", mod_spec)\n","stream":"stderr","time":"2020-10-07T21:54:14.066741873Z"}
{"log":"2020-10-07 21:54:14,066 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/runpy.py\", line 85, in _run_code\n","stream":"stderr","time":"2020-10-07T21:54:14.066880683Z"}
{"log":"2020-10-07 21:54:14,066 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     exec(code, run_globals)\n","stream":"stderr","time":"2020-10-07T21:54:14.066950714Z"}
{"log":"2020-10-07 21:54:14,066 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/app/homeserver.py\", line 687, in \u003cmodule\u003e\n","stream":"stderr","time":"2020-10-07T21:54:14.067014112Z"}
{"log":"2020-10-07 21:54:14,066 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     main()\n","stream":"stderr","time":"2020-10-07T21:54:14.067189745Z"}
{"log":"2020-10-07 21:54:14,067 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/app/homeserver.py\", line 683, in main\n","stream":"stderr","time":"2020-10-07T21:54:14.067413252Z"}
{"log":"2020-10-07 21:54:14,067 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     run(hs)\n","stream":"stderr","time":"2020-10-07T21:54:14.067547963Z"}
{"log":"2020-10-07 21:54:14,067 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/app/homeserver.py\", line 674, in run\n","stream":"stderr","time":"2020-10-07T21:54:14.067702Z"}
{"log":"2020-10-07 21:54:14,067 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     logger=logger,\n","stream":"stderr","time":"2020-10-07T21:54:14.067895508Z"}
{"log":"2020-10-07 21:54:14,067 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/app/_base.py\", line 132, in start_reactor\n","stream":"stderr","time":"2020-10-07T21:54:14.068045004Z"}
{"log":"2020-10-07 21:54:14,068 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     run()\n","stream":"stderr","time":"2020-10-07T21:54:14.068212176Z"}
{"log":"2020-10-07 21:54:14,068 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/app/_base.py\", line 116, in run\n","stream":"stderr","time":"2020-10-07T21:54:14.068419425Z"}
{"log":"2020-10-07 21:54:14,068 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     run_command()\n","stream":"stderr","time":"2020-10-07T21:54:14.068576303Z"}
{"log":"2020-10-07 21:54:14,068 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/twisted/internet/base.py\", line 1283, in run\n","stream":"stderr","time":"2020-10-07T21:54:14.068765912Z"}
{"log":"2020-10-07 21:54:14,068 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     self.mainLoop()\n","stream":"stderr","time":"2020-10-07T21:54:14.068936977Z"}
{"log":"2020-10-07 21:54:14,068 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/twisted/internet/base.py\", line 1292, in mainLoop\n","stream":"stderr","time":"2020-10-07T21:54:14.06916887Z"}
{"log":"2020-10-07 21:54:14,069 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     self.runUntilCurrent()\n","stream":"stderr","time":"2020-10-07T21:54:14.069355333Z"}
{"log":"2020-10-07 21:54:14,069 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/metrics/__init__.py\", line 517, in f\n","stream":"stderr","time":"2020-10-07T21:54:14.069536293Z"}
{"log":"2020-10-07 21:54:14,069 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     ret = func(*args, **kwargs)\n","stream":"stderr","time":"2020-10-07T21:54:14.069718662Z"}
{"log":"2020-10-07 21:54:14,069 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/twisted/internet/base.py\", line 886, in runUntilCurrent\n","stream":"stderr","time":"2020-10-07T21:54:14.069851126Z"}
{"log":"2020-10-07 21:54:14,069 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     f(*a, **kw)\n","stream":"stderr","time":"2020-10-07T21:54:14.069992324Z"}
{"log":"2020-10-07 21:54:14,069 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py\", line 460, in callback\n","stream":"stderr","time":"2020-10-07T21:54:14.070155702Z"}
{"log":"2020-10-07 21:54:14,070 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     self._startRunCallbacks(result)\n","stream":"stderr","time":"2020-10-07T21:54:14.07033731Z"}
{"log":"2020-10-07 21:54:14,070 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py\", line 568, in _startRunCallbacks\n","stream":"stderr","time":"2020-10-07T21:54:14.070575304Z"}
{"log":"2020-10-07 21:54:14,070 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     self._runCallbacks()\n","stream":"stderr","time":"2020-10-07T21:54:14.07067615Z"}
{"log":"2020-10-07 21:54:14,070 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py\", line 654, in _runCallbacks\n","stream":"stderr","time":"2020-10-07T21:54:14.070817127Z"}
{"log":"2020-10-07 21:54:14,070 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     current.result = callback(current.result, *args, **kw)\n","stream":"stderr","time":"2020-10-07T21:54:14.070918865Z"}
{"log":"2020-10-07 21:54:14,070 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py\", line 1475, in gotResult\n","stream":"stderr","time":"2020-10-07T21:54:14.071123182Z"}
{"log":"2020-10-07 21:54:14,071 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     _inlineCallbacks(r, g, status)\n","stream":"stderr","time":"2020-10-07T21:54:14.071270041Z"}
{"log":"2020-10-07 21:54:14,071 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py\", line 1418, in _inlineCallbacks\n","stream":"stderr","time":"2020-10-07T21:54:14.071438035Z"}
{"log":"2020-10-07 21:54:14,071 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     result = g.send(result)\n","stream":"stderr","time":"2020-10-07T21:54:14.071853651Z"}
{"log":"2020-10-07 21:54:14,071 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/http/server.py\", line 170, in wrapped_async_request_handler\n","stream":"stderr","time":"2020-10-07T21:54:14.07219088Z"}
{"log":"2020-10-07 21:54:14,072 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     await h(self, request)\n","stream":"stderr","time":"2020-10-07T21:54:14.072479932Z"}
{"log":"2020-10-07 21:54:14,072 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/http/server.py\", line 230, in _async_render_wrapper\n","stream":"stderr","time":"2020-10-07T21:54:14.072837673Z"}
{"log":"2020-10-07 21:54:14,072 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     callback_return = await self._async_render(request)\n","stream":"stderr","time":"2020-10-07T21:54:14.0731462Z"}
{"log":"2020-10-07 21:54:14,073 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/http/server.py\", line 407, in _async_render\n","stream":"stderr","time":"2020-10-07T21:54:14.073513779Z"}
{"log":"2020-10-07 21:54:14,073 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     callback_return = await raw_callback_return\n","stream":"stderr","time":"2020-10-07T21:54:14.073676934Z"}
{"log":"2020-10-07 21:54:14,073 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/rest/client/v2_alpha/read_marker.py\", line 38, in on_POST\n","stream":"stderr","time":"2020-10-07T21:54:14.073806793Z"}
{"log":"2020-10-07 21:54:14,073 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     await self.presence_handler.bump_presence_active_time(requester.user)\n","stream":"stderr","time":"2020-10-07T21:54:14.074015118Z"}
{"log":"2020-10-07 21:54:14,074 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/handlers/presence.py\", line 491, in bump_presence_active_time\n","stream":"stderr","time":"2020-10-07T21:54:14.074219532Z"}
{"log":"2020-10-07 21:54:14,074 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     await self._update_states([prev_state.copy_and_replace(**new_fields)])\n","stream":"stderr","time":"2020-10-07T21:54:14.074353413Z"}
{"log":"2020-10-07 21:54:14,074 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/handlers/presence.py\", line 406, in _update_states\n","stream":"stderr","time":"2020-10-07T21:54:14.074492957Z"}
{"log":"2020-10-07 21:54:14,074 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     await self._persist_and_notify(list(to_notify.values()))\n","stream":"stderr","time":"2020-10-07T21:54:14.074715685Z"}
{"log":"2020-10-07 21:54:14,074 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/handlers/presence.py\", line 660, in _persist_and_notify\n","stream":"stderr","time":"2020-10-07T21:54:14.074884469Z"}
{"log":"2020-10-07 21:54:14,074 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     self._push_to_remotes(states)\n","stream":"stderr","time":"2020-10-07T21:54:14.075010496Z"}
{"log":"2020-10-07 21:54:14,075 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/handlers/presence.py\", line 679, in _push_to_remotes\n","stream":"stderr","time":"2020-10-07T21:54:14.075144127Z"}
{"log":"2020-10-07 21:54:14,075 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     self.federation.send_presence(states)\n","stream":"stderr","time":"2020-10-07T21:54:14.075331903Z"}
{"log":"2020-10-07 21:54:14,075 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/logging/context.py\", line 668, in g\n","stream":"stderr","time":"2020-10-07T21:54:14.075486667Z"}
{"log":"2020-10-07 21:54:14,075 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     return run_in_background(f, *args, **kwargs)\n","stream":"stderr","time":"2020-10-07T21:54:14.075607362Z"}
{"log":"2020-10-07 21:54:14,075 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/logging/context.py\", line 699, in run_in_background\n","stream":"stderr","time":"2020-10-07T21:54:14.075842047Z"}
{"log":"2020-10-07 21:54:14,075 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     res = defer.ensureDeferred(res)\n","stream":"stderr","time":"2020-10-07T21:54:14.075994818Z"}
{"log":"2020-10-07 21:54:14,076 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py\", line 911, in ensureDeferred\n","stream":"stderr","time":"2020-10-07T21:54:14.076135781Z"}
{"log":"2020-10-07 21:54:14,076 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     return _cancellableInlineCallbacks(coro)\n","stream":"stderr","time":"2020-10-07T21:54:14.076267257Z"}
{"log":"2020-10-07 21:54:14,076 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py\", line 1529, in _cancellableInlineCallbacks\n","stream":"stderr","time":"2020-10-07T21:54:14.076474452Z"}
{"log":"2020-10-07 21:54:14,076 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     _inlineCallbacks(None, g, status)\n","stream":"stderr","time":"2020-10-07T21:54:14.076683008Z"}
{"log":"2020-10-07 21:54:14,076 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py\", line 1418, in _inlineCallbacks\n","stream":"stderr","time":"2020-10-07T21:54:14.076823651Z"}
{"log":"2020-10-07 21:54:14,076 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     result = g.send(result)\n","stream":"stderr","time":"2020-10-07T21:54:14.076958536Z"}
{"log":"2020-10-07 21:54:14,077 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/federation/sender/__init__.py\", line 417, in send_presence\n","stream":"stderr","time":"2020-10-07T21:54:14.07721244Z"}
{"log":"2020-10-07 21:54:14,077 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     await self._process_presence_inner(list(states_map.values()))\n","stream":"stderr","time":"2020-10-07T21:54:14.077366452Z"}
{"log":"2020-10-07 21:54:14,077 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/util/metrics.py\", line 88, in measured_func\n","stream":"stderr","time":"2020-10-07T21:54:14.077524882Z"}
{"log":"2020-10-07 21:54:14,077 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     r = await func(self, *args, **kwargs)\n","stream":"stderr","time":"2020-10-07T21:54:14.077740491Z"}
{"log":"2020-10-07 21:54:14,077 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/federation/sender/__init__.py\", line 460, in _process_presence_inner\n","stream":"stderr","time":"2020-10-07T21:54:14.077909073Z"}
{"log":"2020-10-07 21:54:14,077 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     self._get_per_destination_queue(destination).send_presence(states)\n","stream":"stderr","time":"2020-10-07T21:54:14.078039711Z"}
{"log":"2020-10-07 21:54:14,078 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/federation/sender/per_destination_queue.py\", line 151, in send_presence\n","stream":"stderr","time":"2020-10-07T21:54:14.078195225Z"}
{"log":"2020-10-07 21:54:14,078 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     self.attempt_new_transaction()\n","stream":"stderr","time":"2020-10-07T21:54:14.078381651Z"}
{"log":"2020-10-07 21:54:14,078 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/federation/sender/per_destination_queue.py\", line 208, in attempt_new_transaction\n","stream":"stderr","time":"2020-10-07T21:54:14.078575403Z"}
{"log":"2020-10-07 21:54:14,078 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     self._transaction_transmission_loop,\n","stream":"stderr","time":"2020-10-07T21:54:14.078723325Z"}
{"log":"2020-10-07 21:54:14,078 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/metrics/background_process_metrics.py\", line 218, in run_as_background_process\n","stream":"stderr","time":"2020-10-07T21:54:14.0789244Z"}
{"log":"2020-10-07 21:54:14,078 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     return defer.ensureDeferred(run())\n","stream":"stderr","time":"2020-10-07T21:54:14.079074556Z"}
{"log":"2020-10-07 21:54:14,079 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py\", line 911, in ensureDeferred\n","stream":"stderr","time":"2020-10-07T21:54:14.079259192Z"}
{"log":"2020-10-07 21:54:14,079 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     return _cancellableInlineCallbacks(coro)\n","stream":"stderr","time":"2020-10-07T21:54:14.079410967Z"}
{"log":"2020-10-07 21:54:14,079 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py\", line 1529, in _cancellableInlineCallbacks\n","stream":"stderr","time":"2020-10-07T21:54:14.079587393Z"}
{"log":"2020-10-07 21:54:14,079 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     _inlineCallbacks(None, g, status)\n","stream":"stderr","time":"2020-10-07T21:54:14.079742513Z"}
{"log":"2020-10-07 21:54:14,079 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py\", line 1418, in _inlineCallbacks\n","stream":"stderr","time":"2020-10-07T21:54:14.079928951Z"}
{"log":"2020-10-07 21:54:14,079 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     result = g.send(result)\n","stream":"stderr","time":"2020-10-07T21:54:14.080078543Z"}
{"log":"2020-10-07 21:54:14,080 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/metrics/background_process_metrics.py\", line 205, in run\n","stream":"stderr","time":"2020-10-07T21:54:14.080263518Z"}
{"log":"2020-10-07 21:54:14,080 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     result = await result\n","stream":"stderr","time":"2020-10-07T21:54:14.080421399Z"}
{"log":"2020-10-07 21:54:14,080 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/federation/sender/per_destination_queue.py\", line 303, in _transaction_transmission_loop\n","stream":"stderr","time":"2020-10-07T21:54:14.080602754Z"}
{"log":"2020-10-07 21:54:14,080 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     self._destination, pending_pdus, pending_edus\n","stream":"stderr","time":"2020-10-07T21:54:14.08075718Z"}
{"log":"2020-10-07 21:54:14,080 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/util/metrics.py\", line 88, in measured_func\n","stream":"stderr","time":"2020-10-07T21:54:14.080940322Z"}
{"log":"2020-10-07 21:54:14,080 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     r = await func(self, *args, **kwargs)\n","stream":"stderr","time":"2020-10-07T21:54:14.081150888Z"}
{"log":"2020-10-07 21:54:14,081 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/federation/sender/transaction_manager.py\", line 135, in send_new_transaction\n","stream":"stderr","time":"2020-10-07T21:54:14.081373291Z"}
{"log":"2020-10-07 21:54:14,081 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     transaction, json_data_cb\n","stream":"stderr","time":"2020-10-07T21:54:14.081514713Z"}
{"log":"2020-10-07 21:54:14,081 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/logging/utils.py\", line 69, in wrapped\n","stream":"stderr","time":"2020-10-07T21:54:14.081653395Z"}
{"log":"2020-10-07 21:54:14,081 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     _log_debug_as_f(f, \"Invoked '%(func_name)s' with args: %(args)s\", msg_args)\n","stream":"stderr","time":"2020-10-07T21:54:14.081849942Z"}
{"log":"2020-10-07 21:54:14,081 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -   File \"/usr/local/lib/python3.7/site-packages/synapse/logging/utils.py\", line 42, in _log_debug_as_f\n","stream":"stderr","time":"2020-10-07T21:54:14.082040249Z"}
{"log":"2020-10-07 21:54:14,082 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 -     logger.handle(record)\n","stream":"stderr","time":"2020-10-07T21:54:14.082179933Z"}
{"log":"2020-10-07 21:54:14,082 - twisted - 231 - ERROR - federation_transaction_transmission_loop-4031 - Message: \"Invoked '%(func_name)s' with args: %(args)s\"\n","stream":"stderr","time":"2020-10-07T21:54:14.082395176Z"}

NoneType object errors

For example:

2020-10-07 12:20:57,369 - synapse.http.server - 616 - WARNING - GET-12739 - Not sending response to request <XForwardedForRequest at 0x7f7603d3e890 method='GET' uri='/_matrix/media/r0/download/tedomum.net/nMHNmjgeSZvIXWzrOWILkkFM' clientproto='HTTP/1.0' site=8008>, already disconnected.
2020-10-07 12:22:28,999 - synapse.rest.media.v1._base - 229 - WARNING - GET-12795 - Failed to write to consumer: <class 'AttributeError'> 'NoneType' object has no attribute 'registerProducer'
2020-10-07 12:22:29,000 - synapse.http.server - 85 - ERROR - GET-12795 - Failed handle request via 'DownloadResource': <XForwardedForRequest at 0x7f76187c4290 method='GET' uri='/_matrix/media/r0/download/tedomum.net/nMHNmjgeSZvIXWzrOWILkkFM' clientproto='HTTP/1.0' site=8008>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/synapse/rest/media/v1/_base.py", line 224, in respond_with_responder
    await responder.write_to_consumer(request)
  File "/usr/local/lib/python3.7/site-packages/synapse/rest/media/v1/media_storage.py", line 257, in write_to_consumer
    FileSender().beginFileTransfer(self.open_file, consumer)
  File "/usr/local/lib/python3.7/site-packages/twisted/protocols/basic.py", line 923, in beginFileTransfer
    self.consumer.registerProducer(self, False)
  File "/usr/local/lib/python3.7/site-packages/twisted/web/http.py", line 987, in registerProducer
    self.channel.registerProducer(producer, streaming)
AttributeError: 'NoneType' object has no attribute 'registerProducer'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/synapse/http/server.py", line 230, in _async_render_wrapper
    callback_return = await self._async_render(request)
  File "/usr/local/lib/python3.7/site-packages/synapse/http/server.py", line 258, in _async_render
    callback_return = await raw_callback_return
  File "/usr/local/lib/python3.7/site-packages/synapse/rest/media/v1/download_resource.py", line 64, in _async_render_GET
    await self.media_repo.get_remote_media(request, server_name, media_id, name)
  File "/usr/local/lib/python3.7/site-packages/synapse/rest/media/v1/media_repository.py", line 251, in get_remote_media
    request, responder, media_type, media_length, upload_name
  File "/usr/local/lib/python3.7/site-packages/synapse/rest/media/v1/_base.py", line 233, in respond_with_responder
    request.unregisterProducer()
  File "/usr/local/lib/python3.7/site-packages/twisted/web/http.py", line 993, in unregisterProducer
    self.channel.unregisterProducer()

Steps to reproduce

  • Setup Synapse
  • Join a room and try to talk to others (from other federations) - so the basics

Version information

  • Homeserver: matrix.melroy.org (with melroy.org/.well-known/matrix/server & melroy.org/.well-known/matrix/client)

If not matrix.org:

  • Version: 1.20.1 (python 3.7.9)
  • Install method: Docker
  • Platform: Docker container on Debian
@richvdh
Copy link
Member

richvdh commented Oct 13, 2020 •
edited
Loading

These errors are duplicates of existing issues.

The errors from the logging system (which end with Message: \"Invoked '%(func_name)s' with args: %(args)s\"\n") are fixed in synapse 1.21 by #8278.

The registerProducer error should be fixed by #8465, which missed 1.21 but will be in 1.22.

The default log level of Synapse (DEBUG)

This is incorrect. Synapse has no default log level, but the log level in the log config file which is generated by --generate-config is INFO.

If you see other errors in the logs, please open separate issues for them.

@richvdh richvdh closed this as completed Oct 13, 2020
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
@melroy89 @richvdh