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

Crash on startup (1.14.0) #7610

Closed
karthanistyr opened this issue Jun 1, 2020 · 3 comments · Fixed by #7663
Closed

Crash on startup (1.14.0) #7610

karthanistyr opened this issue Jun 1, 2020 · 3 comments · Fixed by #7663
Assignees
@richvdh
Labels
z-bug (Deprecated Label)

Comments

@karthanistyr
Copy link

Description

Restarting synapse runs the risk of crashing.

I run a daily stop-backup-restart routine, but since upgrading to 1.14.0, there have been infrequent occurrences of crashes after attempting to restart (logs attached in gist).

Steps to reproduce

  • stop the server (e.g. stop the docker compose stack, in my case)
  • wait for some time (my backup routine lasts for 45 mins)
  • restart server (restart the docker compose stack)

It's worth noting that using docker-compose, the containers themselves are scrapped when stopped and new ones are spun up on restart, reattaching volumes containing persistent data.

It had been running like this for more than two years (dating back to the 0.27.x series), and it's the first time something like this happens to my server.

It looks like some form of race condition as it is infrequent and I can usually restart the container as would the daily backup script and it starts up fine.

Version information

  • Homeserver: draak.fr
  • Version: 1.14.0
  • Install method: Docker image
  • Platform: debian linux 10.3
  • Hardware: small 4-core 8 GB VPS
@karthanistyr
Copy link
Author

Attaching the logs here too for issue search benefit:

2020-06-01 05:34:30,471 - synapse.storage.data_stores.main.event_push_actions - 503 - INFO - None - Found stream ordering 1 month ago: it's 447264
2020-06-01 05:34:30,472 - synapse.storage.data_stores.main.event_push_actions - 506 - INFO - None - Searching for stream ordering 1 day ago
2020-06-01 05:34:30,575 - synapse.storage.data_stores.main.event_push_actions - 510 - INFO - None - Found stream ordering 1 day ago: it's 480728
2020-06-01 05:34:32,166 - synapse.storage.data_stores - 77 - INFO - None - Starting 'state' data store
2020-06-01 05:34:32,171 - synapse.storage.data_stores - 90 - INFO - None - Database 'master' prepared
2020-06-01 05:34:32,172 - synapse.server - 275 - INFO - None - Finished setting up.
2020-06-01 05:34:32,437 - synapse.app.homeserver - 111 - INFO -  - Running
2020-06-01 05:34:32,438 - synapse.app.homeserver - 30 - INFO -  - Set file limit to: 1048576
2020-06-01 05:34:32,456 - synapse.config.tls - 517 - INFO -  - Loading TLS key from /data/temptest.draak.fr.tls.key
2020-06-01 05:34:32,475 - synapse.config.tls - 494 - INFO -  - Loading TLS certificate from /data/temptest.draak.fr.tls.crt
2020-06-01 05:34:32,714 - twisted - 192 - ERROR -  - Traceback (most recent call last):
2020-06-01 05:34:32,718 - twisted - 192 - ERROR -  -   File "/usr/lib/python3.8/site-packages/synapse/app/_base.py", line 278, in start
2020-06-01 05:34:32,720 - twisted - 192 - ERROR -  -     hs.start_listening(listeners)
2020-06-01 05:34:32,722 - twisted - 192 - ERROR -  -   File "/usr/lib/python3.8/site-packages/synapse/app/homeserver.py", line 292, in start_listening
2020-06-01 05:34:32,724 - twisted - 192 - ERROR -  -     self._listening_services.extend(self._listener_http(config, listener))
2020-06-01 05:34:32,726 - twisted - 192 - ERROR -  -   File "/usr/lib/python3.8/site-packages/synapse/app/homeserver.py", line 106, in _listener_http
2020-06-01 05:34:32,728 - twisted - 192 - ERROR -  -     self._configure_named_resource(name, res.get("compress", False))
2020-06-01 05:34:32,730 - twisted - 192 - ERROR -  -   File "/usr/lib/python3.8/site-packages/synapse/app/homeserver.py", line 182, in _configure_named_resource
2020-06-01 05:34:32,733 - twisted - 192 - ERROR -  -     client_resource = ClientRestResource(self)
2020-06-01 05:34:32,735 - twisted - 192 - ERROR -  -   File "/usr/lib/python3.8/site-packages/synapse/rest/__init__.py", line 73, in __init__
2020-06-01 05:34:32,737 - twisted - 192 - ERROR -  -     self.register_servlets(self, hs)
2020-06-01 05:34:32,739 - twisted - 192 - ERROR -  -   File "/usr/lib/python3.8/site-packages/synapse/rest/__init__.py", line 80, in register_servlets
2020-06-01 05:34:32,741 - twisted - 192 - ERROR -  -     initial_sync.register_servlets(hs, client_resource)
2020-06-01 05:34:32,744 - twisted - 192 - ERROR -  -   File "/usr/lib/python3.8/site-packages/synapse/rest/client/v1/initial_sync.py", line 47, in register_servlets
2020-06-01 05:34:32,746 - twisted - 192 - ERROR -  -     InitialSyncRestServlet(hs).register(http_server)
2020-06-01 05:34:32,748 - twisted - 192 - ERROR -  -   File "/usr/lib/python3.8/site-packages/synapse/rest/client/v1/initial_sync.py", line 28, in __init__
2020-06-01 05:34:32,750 - twisted - 192 - ERROR -  -     self.initial_sync_handler = hs.get_initial_sync_handler()
2020-06-01 05:34:32,752 - twisted - 192 - ERROR -  -   File "/usr/lib/python3.8/site-packages/synapse/server.py", line 622, in _get
2020-06-01 05:34:32,754 - twisted - 192 - ERROR -  -     dep = builder()
2020-06-01 05:34:32,756 - twisted - 192 - ERROR -  -   File "/usr/lib/python3.8/site-packages/synapse/server.py", line 422, in build_initial_sync_handler
2020-06-01 05:34:32,757 - twisted - 192 - ERROR -  -     return InitialSyncHandler(self)
2020-06-01 05:34:32,759 - twisted - 192 - ERROR -  -   File "/usr/lib/python3.8/site-packages/synapse/handlers/initial_sync.py", line 39, in __init__
2020-06-01 05:34:32,761 - twisted - 192 - ERROR -  -     super(InitialSyncHandler, self).__init__(hs)
2020-06-01 05:34:32,763 - twisted - 192 - ERROR -  -   File "/usr/lib/python3.8/site-packages/synapse/handlers/_base.py", line 43, in __init__
2020-06-01 05:34:32,766 - twisted - 192 - ERROR -  -     self.auth = hs.get_auth()
2020-06-01 05:34:32,767 - twisted - 192 - ERROR -  -   File "/usr/lib/python3.8/site-packages/synapse/server.py", line 622, in _get
2020-06-01 05:34:32,769 - twisted - 192 - ERROR -  -     dep = builder()
2020-06-01 05:34:32,771 - twisted - 192 - ERROR -  -   File "/usr/lib/python3.8/site-packages/synapse/server.py", line 339, in build_auth
2020-06-01 05:34:32,773 - twisted - 192 - ERROR -  -     return Auth(self)
2020-06-01 05:34:32,775 - twisted - 192 - ERROR -  -   File "/usr/lib/python3.8/site-packages/synapse/api/auth.py", line 78, in __init__
2020-06-01 05:34:32,777 - twisted - 192 - ERROR -  -     register_cache("cache", "token_cache", self.token_cache)
2020-06-01 05:34:32,778 - twisted - 192 - ERROR -  -   File "/usr/lib/python3.8/site-packages/synapse/util/caches/__init__.py", line 117, in register_cache
2020-06-01 05:34:32,780 - twisted - 192 - ERROR -  -     add_resizable_cache(cache_name, resize_callback)
2020-06-01 05:34:32,782 - twisted - 192 - ERROR -  -   File "/usr/lib/python3.8/site-packages/synapse/config/cache.py", line 76, in add_resizable_cache
2020-06-01 05:34:32,784 - twisted - 192 - ERROR -  -     properties.resize_all_caches_func()
2020-06-01 05:34:32,786 - twisted - 192 - ERROR -  -   File "/usr/lib/python3.8/site-packages/synapse/config/cache.py", line 196, in resize_all_caches
2020-06-01 05:34:32,788 - twisted - 192 - ERROR -  -     for cache_name, callback in _CACHES.items():
2020-06-01 05:34:32,790 - twisted - 192 - ERROR -  - RuntimeError: dictionary changed size during iteration
2020-06-01 05:34:32,912 - twisted - 192 - CRITICAL -  - Unhandled error in Deferred:
2020-06-01 05:34:32,919 - twisted - 192 - CRITICAL -  - 
Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/synapse/app/_base.py", line 278, in start
    hs.start_listening(listeners)
  File "/usr/lib/python3.8/site-packages/synapse/app/homeserver.py", line 292, in start_listening
    self._listening_services.extend(self._listener_http(config, listener))
  File "/usr/lib/python3.8/site-packages/synapse/app/homeserver.py", line 106, in _listener_http
    self._configure_named_resource(name, res.get("compress", False))
  File "/usr/lib/python3.8/site-packages/synapse/app/homeserver.py", line 182, in _configure_named_resource
    client_resource = ClientRestResource(self)
  File "/usr/lib/python3.8/site-packages/synapse/rest/__init__.py", line 73, in __init__
    self.register_servlets(self, hs)
  File "/usr/lib/python3.8/site-packages/synapse/rest/__init__.py", line 80, in register_servlets
    initial_sync.register_servlets(hs, client_resource)
  File "/usr/lib/python3.8/site-packages/synapse/rest/client/v1/initial_sync.py", line 47, in register_servlets
    InitialSyncRestServlet(hs).register(http_server)
  File "/usr/lib/python3.8/site-packages/synapse/rest/client/v1/initial_sync.py", line 28, in __init__
    self.initial_sync_handler = hs.get_initial_sync_handler()
  File "/usr/lib/python3.8/site-packages/synapse/server.py", line 622, in _get
    dep = builder()
  File "/usr/lib/python3.8/site-packages/synapse/server.py", line 422, in build_initial_sync_handler
    return InitialSyncHandler(self)
  File "/usr/lib/python3.8/site-packages/synapse/handlers/initial_sync.py", line 39, in __init__
    super(InitialSyncHandler, self).__init__(hs)
  File "/usr/lib/python3.8/site-packages/synapse/handlers/_base.py", line 43, in __init__
    self.auth = hs.get_auth()
  File "/usr/lib/python3.8/site-packages/synapse/server.py", line 622, in _get
    dep = builder()
  File "/usr/lib/python3.8/site-packages/synapse/server.py", line 339, in build_auth
    return Auth(self)
  File "/usr/lib/python3.8/site-packages/synapse/api/auth.py", line 78, in __init__
    register_cache("cache", "token_cache", self.token_cache)
  File "/usr/lib/python3.8/site-packages/synapse/util/caches/__init__.py", line 117, in register_cache
    add_resizable_cache(cache_name, resize_callback)
  File "/usr/lib/python3.8/site-packages/synapse/config/cache.py", line 76, in add_resizable_cache
    properties.resize_all_caches_func()
  File "/usr/lib/python3.8/site-packages/synapse/config/cache.py", line 196, in resize_all_caches
    for cache_name, callback in _CACHES.items():
RuntimeError: dictionary changed size during iteration

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/usr/lib/python3.8/site-packages/synapse/app/homeserver.py", line 440, in start
    _base.start(hs, config.listeners)
  File "/usr/lib/python3.8/site-packages/synapse/app/_base.py", line 298, in start
    sys.exit(1)
SystemExit: 1
2020-06-01 05:34:33,018 - twisted - 192 - INFO -  - Main loop terminated.

@erikjohnston erikjohnston added z-bug (Deprecated Label) p1 labels Jun 1, 2020
@erikjohnston
Copy link
Member

This also happens during normal operation, e.g. a sytest build on develop saw this:

2020-06-01 14:27:48,359 - synapse.http.server - 110 - ERROR - GET-10 - Failed handle request via 'SyncRestServlet': <SynapseRequest at 0x7fca442aefd0 method='GET' uri='/_matrix/client/r0/sync?set_presence=offline&access_token=<redacted>&timeout=1000' clientproto='HTTP/1.1' site=8832>
Traceback (most recent call last):
  File "/venv/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: ({}, {})

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/venv/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: ({}, {})

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/venv/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/venv/lib/python3.5/site-packages/synapse/handlers/sync.py", line 312, in _wait_for_sync_for_user
    sync_config, since_token, full_state=full_state
  File "/venv/lib/python3.5/site-packages/synapse/handlers/sync.py", line 343, in current_sync_for_user
    return await self.generate_sync_result(sync_config, since_token, full_state)
  File "/venv/lib/python3.5/site-packages/synapse/handlers/sync.py", line 996, in generate_sync_result
    sync_result_builder
  File "/venv/lib/python3.5/site-packages/synapse/handlers/sync.py", line 1267, in _generate_sync_entry_for_account_data
    sync_config.user
  File "/venv/lib/python3.5/site-packages/synapse/handlers/sync.py", line 347, in push_rules_for_user
    rules = await self.store.get_push_rules_for_user(user_id)
  File "/venv/lib/python3.5/site-packages/synapse/util/caches/descriptors.py", line 409, in __get__
    iterable=self.iterable,
  File "/venv/lib/python3.5/site-packages/synapse/util/caches/descriptors.py", line 133, in __init__
    collect_callback=self._metrics_collection_callback,
  File "/venv/lib/python3.5/site-packages/synapse/util/caches/__init__.py", line 117, in register_cache
    add_resizable_cache(cache_name, resize_callback)
  File "/venv/lib/python3.5/site-packages/synapse/config/cache.py", line 76, in add_resizable_cache
    properties.resize_all_caches_func()
  File "/venv/lib/python3.5/site-packages/synapse/config/cache.py", line 196, in resize_all_caches
    for cache_name, callback in _CACHES.items():
RuntimeError: dictionary changed size during iteration

@richvdh richvdh self-assigned this Jun 9, 2020
richvdh added a commit that referenced this issue Jun 9, 2020
@richvdh
Take out a lock before modifying _CACHES
b072d77 
This should fix #7610.
@richvdh
Copy link
Member

richvdh commented Jun 9, 2020

seems to have been introduced by #6391

@richvdh richvdh mentioned this issue Jun 9, 2020
Merged
richvdh added a commit that referenced this issue Jun 10, 2020
@richvdh
Take out a lock before modifying _CACHES (#7663)
0df618f 
This should fix #7610.
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@richvdh richvdh

Labels
z-bug (Deprecated Label)
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Take out a lock before modifying _CACHES matrix-org/synapse
3 participants
@richvdh @karthanistyr @erikjohnston