Synapse: Synapse fails to start with with acme on

Created on 3 Mar 2019 · 9Comments · Source: matrix-org/synapse

Description [please skim through all the comments below, its an error handling issue with several scenarios, each in a separate comment.]

While testing the 0.9 branch on Ubuntu, specifically
matrix-synapse-py3/unknown,now 0.99.2+bionic1 amd64 [installed]
I hit the following TLS/ACME related error

root@kai02-matrix:~# /opt/venvs/matrix-synapse/bin/python -m synapse.app.homeserver --config-path=/etc/matrix-synapse/homeserver.yaml 
2019-03-03 18:15:03,207 - root - 209 - WARNING - None- ***** STARTING SERVER *****
2019-03-03 18:15:03,217 - root - 212 - WARNING - None- Server /opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/app/homeserver.py version 0.99.2
2019-03-03 18:15:03,226 - twisted - 240 - WARNING - None- /opt/venvs/matrix-synapse/lib/python3.6/site-packages/psycopg2/__init__.py:144: builtins.UserWarning: The psycopg2 wheel package will be renamed from release 2.8; in order to keep installing from binary please use "pip install psycopg2-binary" instead. For details see: <http://initd.org/psycopg/docs/install.html#binary-install-from-pypi>.
2019-03-03 18:15:03,856 - twisted - 240 - ERROR - - Error during startup:
2019-03-03 18:15:03,856 - twisted - 240 - ERROR - - Traceback (most recent call last):
2019-03-03 18:15:03,856 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
2019-03-03 18:15:03,856 - twisted - 240 - ERROR - -     current.result = callback(current.result, *args, **kw)
2019-03-03 18:15:03,856 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 1475, in gotResult
2019-03-03 18:15:03,857 - twisted - 240 - ERROR - -     _inlineCallbacks(r, g, status)
2019-03-03 18:15:03,857 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
2019-03-03 18:15:03,857 - twisted - 240 - ERROR - -     result = result.throwExceptionIntoGenerator(g)
2019-03-03 18:15:03,857 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
2019-03-03 18:15:03,857 - twisted - 240 - ERROR - -     return g.throw(self.type, self.value, self.tb)
2019-03-03 18:15:03,857 - twisted - 240 - ERROR - - --- <exception caught here> ---
2019-03-03 18:15:03,857 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/app/homeserver.py", line 429, in start
2019-03-03 18:15:03,858 - twisted - 240 - ERROR - -     yield acme.start_listening()
2019-03-03 18:15:03,858 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
2019-03-03 18:15:03,858 - twisted - 240 - ERROR - -     result = result.throwExceptionIntoGenerator(g)
2019-03-03 18:15:03,858 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
2019-03-03 18:15:03,858 - twisted - 240 - ERROR - -     return g.throw(self.type, self.value, self.tb)
2019-03-03 18:15:03,858 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/handlers/acme.py", line 122, in start_listening
2019-03-03 18:15:03,858 - twisted - 240 - ERROR - -     yield self._issuer._ensure_registered()
2019-03-03 18:15:03,859 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
2019-03-03 18:15:03,859 - twisted - 240 - ERROR - -     current.result = callback(current.result, *args, **kw)
2019-03-03 18:15:03,859 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/txacme/service.py", line 254, in _register
2019-03-03 18:15:03,859 - twisted - 240 - ERROR - -     client.register(regr)
2019-03-03 18:15:03,859 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/txacme/client.py", line 157, in register
2019-03-03 18:15:03,859 - twisted - 240 - ERROR - -     new_reg, uri=self.directory[new_reg]))
2019-03-03 18:15:03,859 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/acme/messages.py", line 235, in __getitem__
2019-03-03 18:15:03,860 - twisted - 240 - ERROR - -     raise KeyError('Directory field not found')
2019-03-03 18:15:03,860 - twisted - 240 - ERROR - - builtins.KeyError: 'Directory field not found'
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.6/logging/handlers.py", line 71, in emit
    if self.shouldRollover(record):
  File "/usr/lib/python3.6/logging/handlers.py", line 185, in shouldRollover
    self.stream = self._open()
  File "/usr/lib/python3.6/logging/__init__.py", line 1061, in _open
    return open(self.baseFilename, self.mode, encoding=self.encoding)
NameError: name 'open' is not defined
Call stack:
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 954, in __del__
    isError=True)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/logger/_logger.py", line 270, in critical
    self.emit(LogLevel.critical, format, **kwargs)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/logger/_logger.py", line 144, in emit
    self.observer(event)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/logger/_observer.py", line 131, in __call__
    observer(event)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/config/logger.py", line 240, in _log
    return observer(event)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/logger/_stdlib.py", line 116, in __call__
    stdlibLevel, StringifiableFromEvent(event), exc_info=excInfo)
Message: <twisted.logger._stdlib.StringifiableFromEvent object at 0x7f0e3365fda0>
Arguments: ()
2019-03-03 18:15:03,903 - twisted - 240 - CRITICAL - - Unhandled error in Deferred:
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.6/logging/handlers.py", line 71, in emit
    if self.shouldRollover(record):
  File "/usr/lib/python3.6/logging/handlers.py", line 185, in shouldRollover
    self.stream = self._open()
  File "/usr/lib/python3.6/logging/__init__.py", line 1061, in _open
    return open(self.baseFilename, self.mode, encoding=self.encoding)
NameError: name 'open' is not defined
Call stack:
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 964, in __del__
    debugInfo=debugInfo)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/logger/_logger.py", line 190, in failure
    self.emit(level, format, log_failure=failure, **kwargs)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/logger/_logger.py", line 144, in emit
    self.observer(event)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/logger/_observer.py", line 131, in __call__
    observer(event)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/config/logger.py", line 240, in _log
    return observer(event)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/logger/_stdlib.py", line 116, in __call__
    stdlibLevel, StringifiableFromEvent(event), exc_info=excInfo)
Message: <twisted.logger._stdlib.StringifiableFromEvent object at 0x7f0e3365fda0>
Arguments: ()
2019-03-03 18:15:03,905 - twisted - 240 - CRITICAL - - 
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/acme/messages.py", line 233, in __getitem__
    return self._jobj[self._canon_key(name)]
KeyError: 'new-reg'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/app/homeserver.py", line 429, in start
    yield acme.start_listening()
  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 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/handlers/acme.py", line 122, in start_listening
    yield self._issuer._ensure_registered()
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/txacme/service.py", line 254, in _register
    client.register(regr)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/txacme/client.py", line 157, in register
    new_reg, uri=self.directory[new_reg]))
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/acme/messages.py", line 235, in __getitem__
    raise KeyError('Directory field not found')
KeyError: 'Directory field not found'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  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 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/app/homeserver.py", line 451, in start
    sys.exit(1)
SystemExit: 1

While the start fails, a client.key file gets created

root@kai02-matrix:/etc/matrix-synapse# ls -ahl
total 52K
drwxr-xr-x 1 matrix-synapse nogroup  122 Mar  3 18:15 .
drwxr-xr-x 1 root           root    2.7K Mar  3 01:57 ..
-rwxr-xr-x 1 root           root    1.7K Mar  3 18:15 client.key      <----- THIS ONE
...

so it seems like something goes through to/from ACME, but not all of it. Could it be that the tls_*_path variables get ignored?

Steps to reproduce

The effective config is:

pid_file: "/var/run/matrix-synapse.pid"
soft_file_limit: 0
use_presence: true
listeners:
  - port: 8008
    tls: false
    bind_addresses: ['::1', '127.0.0.1']
    type: http
    x_forwarded: true
    resources:
      - names: [client, federation]
        compress: false
database:
  name: "sqlite3"
  args:
    database: "/var/lib/matrix-synapse/homeserver.db"
event_cache_size: "10K"
log_config: "/etc/matrix-synapse/log.yaml"
rc_messages_per_second: 0.2
rc_message_burst_count: 10.0
federation_rc_window_size: 1000
federation_rc_sleep_limit: 10
federation_rc_sleep_delay: 500
federation_rc_reject_limit: 50
federation_rc_concurrent: 3
media_store_path: "/var/lib/matrix-synapse/media"
uploads_path: "/var/lib/matrix-synapse/uploads"
max_upload_size: "10M"
max_image_pixels: "32M"
dynamic_thumbnails: false
thumbnail_sizes:
- width: 32
  height: 32
  method: crop
- width: 96
  height: 96
  method: crop
- width: 320
  height: 240
  method: scale
- width: 640
  height: 480
  method: scale
- width: 800
  height: 600
  method: scale
url_preview_enabled: False
max_spider_size: "10M"
recaptcha_public_key: "lala"
recaptcha_private_key: "lala"
enable_registration_captcha: False
recaptcha_siteverify_api: "https://www.recaptcha.net/recaptcha/api/siteverify"
turn_user_lifetime: "1h"
turn_allow_guests: True
enable_registration: False
bcrypt_rounds: 12
allow_guest_access: False
trusted_third_party_id_servers:
  - matrix.org
  - vector.im
autocreate_auto_join_rooms: true
enable_metrics: False
room_invite_state_types:
    - "m.room.join_rules"
    - "m.room.canonical_alias"
    - "m.room.avatar"
    - "m.room.encryption"
    - "m.room.name"
app_service_config_files: []
track_appservice_user_ips: False
expire_access_token: False
signing_key_path: "/etc/matrix-synapse/homeserver.signing.key"
key_refresh_interval: "1d" # 1 Day.
perspectives:
  servers:
    "matrix.org":
      verify_keys:
        "ed25519:auto":
          key: "Noi6WqcDj0QmPxCNQqgezwTlBKrfqehY1u2FyWP9uYw"
password_config:
   enabled: true
enable_group_creation: false
server_name: 'matrix.vaizard.xyz'
public_baseurl: 'https://matrix.vaizard.xyz'
web_client: False    
use_presence: True 
federation_domain_whitelist:
 - matrix.vaizard.xyz
listeners:
  - port: 8448 
    bind_addresses:
      - '::'
      - '0.0.0.0'
    type: http
    tls: true
    x_forwarded: false
    resources:
      - names: [client]
        compress: true
      - names: [federation] # Federation APIs
        compress: false
  - port: 8008 
    tls: false
    bind_addresses: ['127.0.0.1']
    type: http
    x_forwarded: true
    resources:
      - names: [client]
        compress: true
      - names: [federation] # Federation APIs
        compress: false
tls_certificate_path: /etc/matrix-synapse/homeserver.tls.crt
tls_private_key_path: /etc/matrix-synapse/homeserver.tls.key
acme:
  enabled: true
  port: 8080
  bind_addresses: [ '127.0.0.1' ]
  url: https://acme-staging-v02.api.letsencrypt.org/directory
database:
  name: "psycopg2"
  args:
    user: "synapse"
    password: "pwpwpwpwpwpwpw"
    database: "synapse"
    host: "127.0.0.1"
    cp_min: 5
    cp_max: 10
max_upload_size: '32M'
url_preview_enabled: True
url_preview_ip_range_blacklist:
 - '127.0.0.0/8'
 - '10.0.0.0/8'
 - '172.16.0.0/12'
 - '192.168.0.0/16'
 - '100.64.0.0/10'
 - '169.254.0.0/16'
 - '::1/128'
 - 'fe80::/64'
 - 'fc00::/7'
url_preview_url_blacklist:
 - scheme: 'http' # blacklist all plain HTTP URLs
recaptcha_private_key: 'fdfdfd'
recaptcha_public_key: 'fdfdfdfd'
turn_uris: [ "turn:matrix.vaizard.xyz:3478?transport=udp", "turn:matrix.vaizard.xyz:3478?transport=tcp" ]
turn_shared_secret: ffdfdfdfdfdfdfd
enable_registration: 'True'
registration_shared_secret: 'dfdfdsfdsdf'
enable_registration_captcha: 'False'
allow_guest_access: "True"
report_stats: True
macaroon_secret_key: 'dfdfdsfdsdf'
push:
   include_content: true
alias_creation_rules:
  - user_id: "*"
    alias: "*"
    action: allow

then start synapse.

Version information

Homeserver: matrix.vaizard.xyz
matrix-synapse-py3/unknown,now 0.99.2+bionic1
ubuntu, inside an LXD container

bug

Source

killua-eu

All 9 comments

I verified that the http://matrix.vaizard.xyz:8080 is well reachable (reconfigured a webserver to listen on 8080 and got perfectly normal responses) ...

killua-eu on 3 Mar 2019

Oh this is a fun one. I managed to get several different errors, some of them cryptic, some easy to figure out. the first one is the following:

Failed to listen on 0.0.0.0, continuing because listening on [::]

2019-03-03 23:44:14,975 - root - 209 - WARNING - None- ***** STARTING SERVER *****
2019-03-03 23:44:14,984 - root - 212 - WARNING - None- Server /opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/app/homeserver.py version 0.99.2
2019-03-03 23:44:14,985 - root - 214 - INFO - None- Server hostname: matrix.vaizard.xyz
2019-03-03 23:44:14,985 - twisted - 240 - INFO - None- Redirected stdout/stderr to logs
2019-03-03 23:44:14,993 - twisted - 240 - WARNING - None- /opt/venvs/matrix-synapse/lib/python3.6/site-packages/psycopg2/__init__.py:144: builtins.UserWarning: The psycopg2 wheel package will be renamed from release 2.8; in order to keep installing from binary please use "pip install psycopg2-binary" instead. For details see: <http://initd.org/psycopg/docs/install.html#binary-install-from-pypi>.
2019-03-03 23:44:15,004 - synapse.app.homeserver - 358 - INFO - None- Preparing database: psycopg2...
2019-03-03 23:44:15,008 - synapse.storage.prepare_database - 223 - INFO - None- Upgrading schema to v53
2019-03-03 23:44:15,009 - synapse.app.homeserver - 376 - INFO - None- Database prepared in psycopg2.
2019-03-03 23:44:15,009 - synapse.server - 217 - INFO - None- Setting up.
2019-03-03 23:44:15,021 - synapse.storage.event_push_actions - 471 - INFO - None- Searching for stream ordering 1 month ago
2019-03-03 23:44:15,022 - synapse.storage.event_push_actions - 477 - INFO - None- Found stream ordering 1 month ago: it's 0
2019-03-03 23:44:15,022 - synapse.storage.event_push_actions - 479 - INFO - None- Searching for stream ordering 1 day ago
2019-03-03 23:44:15,022 - synapse.storage.event_push_actions - 485 - INFO - None- Found stream ordering 1 day ago: it's 0
2019-03-03 23:44:15,023 - synapse.server - 221 - INFO - None- Finished setting up.
2019-03-03 23:44:15,024 - synapse.app.homeserver - 628 - INFO - None- Scheduling stats reporting for 3 hour intervals
2019-03-03 23:44:15,024 - synapse.app.homeserver - 105 - INFO - - Running
2019-03-03 23:44:15,024 - synapse.app.homeserver - 30 - INFO - - Set file limit to: 1048576
2019-03-03 23:44:15,094 - synapse.handlers.acme - 106 - INFO - - Listening for ACME requests on :::8080
2019-03-03 23:44:15,094 - twisted - 240 - INFO - - Site starting on 8080
2019-03-03 23:44:15,094 - synapse.handlers.acme - 106 - INFO - - Listening for ACME requests on 0.0.0.0:8080
2019-03-03 23:44:15,094 - synapse.app - 47 - WARNING - - Failed to listen on 0.0.0.0, continuing because listening on [::]
2019-03-03 23:44:15,139 - synapse.app.homeserver - 577 - INFO - - report_stats can use psutil
2019-03-03 23:44:15,139 - synapse.metrics - 372 - INFO - - Collecting gc 0
2019-03-03 23:44:15,407 - synapse.metrics - 372 - INFO - - Collecting gc 0
2019-03-03 23:44:16,103 - synapse.metrics - 372 - INFO - - Collecting gc 0
2019-03-03 23:44:16,295 - synapse.handlers.acme - 127 - WARNING - - Reprovisioning matrix.vaizard.xyz
2019-03-03 23:44:16,564 - twisted - 240 - INFO - - Requesting a certificate for 'matrix.vaizard.xyz'.
2019-03-03 23:44:16,850 - synapse.metrics - 372 - INFO - - Collecting gc 0
2019-03-03 23:44:16,853 - synapse.metrics - 372 - INFO - - Collecting gc 1

a file is generated nontheless, but with the name client.key, where I was expecting the names according to tls_*_paths. I also get only the key, but not the cert. Not sure if my expectation is off, but this doesn't seem right.

killua-eu on 4 Mar 2019

The other error was ERROR - - builtins.PermissionError: [Errno 13] Permission denied: b'/etc/matrix-synapse/conf.d/8Awdo28fHcXjlhPeclient.key.new'

2019-03-03 22:56:29,277 - root - 209 - WARNING - None- ***** STARTING SERVER *****
2019-03-03 22:56:29,287 - root - 212 - WARNING - None- Server /opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/app/homeserver.py version 0.99.2
2019-03-03 22:56:29,287 - root - 214 - INFO - None- Server hostname: matrix.vaizard.xyz
2019-03-03 22:56:29,288 - twisted - 240 - INFO - None- Redirected stdout/stderr to logs
2019-03-03 22:56:29,297 - twisted - 240 - WARNING - None- /opt/venvs/matrix-synapse/lib/python3.6/site-packages/psycopg2/__init__.py:144: builtins.UserWarning: The psycopg2 wheel package will be renamed from release 2.8; in order to keep installing from binary please use "pip install psycopg2-binary" instead. For details see: <http://initd.org/psycopg/docs/install.html#binary-install-from-pypi>.
2019-03-03 22:56:29,307 - synapse.app.homeserver - 358 - INFO - None- Preparing database: psycopg2...
2019-03-03 22:56:29,312 - synapse.storage.prepare_database - 223 - INFO - None- Upgrading schema to v53
2019-03-03 22:56:29,313 - synapse.app.homeserver - 376 - INFO - None- Database prepared in psycopg2.
2019-03-03 22:56:29,313 - synapse.server - 217 - INFO - None- Setting up.
2019-03-03 22:56:29,324 - synapse.storage.event_push_actions - 471 - INFO - None- Searching for stream ordering 1 month ago
2019-03-03 22:56:29,325 - synapse.storage.event_push_actions - 477 - INFO - None- Found stream ordering 1 month ago: it's 0
2019-03-03 22:56:29,325 - synapse.storage.event_push_actions - 479 - INFO - None- Searching for stream ordering 1 day ago
2019-03-03 22:56:29,325 - synapse.storage.event_push_actions - 485 - INFO - None- Found stream ordering 1 day ago: it's 0
2019-03-03 22:56:29,326 - synapse.server - 221 - INFO - None- Finished setting up.
2019-03-03 22:56:29,327 - synapse.app.homeserver - 628 - INFO - None- Scheduling stats reporting for 3 hour intervals
2019-03-03 22:56:29,327 - synapse.app.homeserver - 105 - INFO - - Running
2019-03-03 22:56:29,327 - synapse.app.homeserver - 30 - INFO - - Set file limit to: 1048576
2019-03-03 22:56:29,407 - synapse.handlers.acme - 106 - INFO - - Listening for ACME requests on :::8080
2019-03-03 22:56:29,408 - twisted - 240 - INFO - - Site starting on 8080
2019-03-03 22:56:29,408 - synapse.handlers.acme - 106 - INFO - - Listening for ACME requests on 0.0.0.0:8080
2019-03-03 22:56:29,408 - synapse.app - 47 - WARNING - - Failed to listen on 0.0.0.0, continuing because listening on [::]
2019-03-03 22:56:29,444 - twisted - 240 - ERROR - - Error during startup:
2019-03-03 22:56:29,444 - twisted - 240 - ERROR - - Traceback (most recent call last):
2019-03-03 22:56:29,444 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
2019-03-03 22:56:29,445 - twisted - 240 - ERROR - -     result = g.send(result)
2019-03-03 22:56:29,445 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/app/homeserver.py", line 429, in start
2019-03-03 22:56:29,445 - twisted - 240 - ERROR - -     yield acme.start_listening()
2019-03-03 22:56:29,445 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 1613, in unwindGenerator
2019-03-03 22:56:29,445 - twisted - 240 - ERROR - -     return _cancellableInlineCallbacks(gen)
2019-03-03 22:56:29,445 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 1529, in _cancellableInlineCallbacks
2019-03-03 22:56:29,446 - twisted - 240 - ERROR - -     _inlineCallbacks(None, g, status)
2019-03-03 22:56:29,446 - twisted - 240 - ERROR - - --- <exception caught here> ---
2019-03-03 22:56:29,446 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/app/homeserver.py", line 429, in start
2019-03-03 22:56:29,446 - twisted - 240 - ERROR - -     yield acme.start_listening()
2019-03-03 22:56:29,446 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
2019-03-03 22:56:29,446 - twisted - 240 - ERROR - -     result = g.send(result)
2019-03-03 22:56:29,446 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/handlers/acme.py", line 122, in start_listening
2019-03-03 22:56:29,446 - twisted - 240 - ERROR - -     yield self._issuer._ensure_registered()
2019-03-03 22:56:29,446 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/txacme/service.py", line 243, in _ensure_registered
2019-03-03 22:56:29,447 - twisted - 240 - ERROR - -     return self._with_client(self._register)
2019-03-03 22:56:29,447 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/txacme/service.py", line 184, in _with_client
2019-03-03 22:56:29,447 - twisted - 240 - ERROR - -     return self._client_creator().addCallback(f, *a, **kw)
2019-03-03 22:56:29,447 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/handlers/acme.py", line 86, in <lambda>
2019-03-03 22:56:29,447 - twisted - 240 - ERROR - -     FilePath(self.hs.config.config_dir_path)
2019-03-03 22:56:29,447 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/txacme/endpoint.py", line 153, in load_or_create_client_key
2019-03-03 22:56:29,447 - twisted - 240 - ERROR - -     encryption_algorithm=serialization.NoEncryption()))
2019-03-03 22:56:29,448 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/python/filepath.py", line 1538, in setContent
2019-03-03 22:56:29,448 - twisted - 240 - ERROR - -     with sib.open('w') as f:
2019-03-03 22:56:29,448 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/python/filepath.py", line 1008, in open
2019-03-03 22:56:29,448 - twisted - 240 - ERROR - -     return self.create()
2019-03-03 22:56:29,448 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/python/filepath.py", line 1581, in create
2019-03-03 22:56:29,448 - twisted - 240 - ERROR - -     fdint = os.open(self.path, _CREATE_FLAGS)
2019-03-03 22:56:29,448 - twisted - 240 - ERROR - - builtins.PermissionError: [Errno 13] Permission denied: b'/etc/matrix-synapse/conf.d/8Awdo28fHcXjlhPeclient.key.new'
2019-03-03 22:56:29,450 - synapse.app.homeserver - 577 - INFO - - report_stats can use psutil
2019-03-03 22:56:29,450 - synapse.metrics - 372 - INFO - - Collecting gc 0
2019-03-03 22:56:29,469 - twisted - 240 - CRITICAL - - Unhandled error in Deferred:
2019-03-03 22:56:29,469 - twisted - 240 - CRITICAL - - 
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/app/homeserver.py", line 429, in start
    yield acme.start_listening()
PermissionError: [Errno 13] Permission denied: b'/etc/matrix-synapse/conf.d/8Awdo28fHcXjlhPeclient.key.new'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  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 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/app/homeserver.py", line 451, in start
    sys.exit(1)
SystemExit: 1
2019-03-03 22:56:29,471 - twisted - 240 - INFO - - (TCP Port 8080 Closed)
2019-03-03 22:56:29,472 - twisted - 240 - INFO - - Main loop terminated.


The problem is in the debian package here. To reproduce install do: `apt install matrix-synapse-py3`. The unit file

cat /etc/systemd/system/multi-user.target.wants/matrix-synapse.service
[Unit]
Description=Synapse Matrix homeserver

[Service]
Type=simple
User=matrix-synapse
WorkingDirectory=/var/lib/matrix-synapse
EnvironmentFile=/etc/default/matrix-synapse
ExecStartPre=/opt/venvs/matrix-synapse/bin/python -m synapse.app.homeserver --config-path=/etc/matrix-synapse/homeserver.yaml --config-path=/etc/matrix-synapse/conf.d/ --generate-keys
ExecStart=/opt/venvs/matrix-synapse/bin/python -m synapse.app.homeserver --config-path=/etc/matrix-synapse/homeserver.yaml --config-path=/etc/matrix-synapse/conf.d/
ExecReload=/bin/kill -HUP $MAINPID
Restart=always
RestartSec=3

[Install]
WantedBy=multi-user.target


says `--config-path=/etc/matrix-synapse/conf.d/` but while /etc/matrix-synapse belongs to the matrix-synapse user, the conf.d does not (root is the owner)

root@c5:~# ls -ahl /etc/matrix-synapse
total 52K
drwxr-xr-x 3 matrix-synapse nogroup 4.0K Mar 3 23:37 .
drwxr-xr-x 93 root root 4.0K Mar 3 23:37 ..
drwxr-xr-x 2 root root 4.0K Mar 3 23:37 conf.d
-rw-r--r-- 1 matrix-synapse nogroup 59 Mar 3 23:37 homeserver.signing.key
-rw-r--r-- 1 root root 32K Mar 1 11:08 homeserver.yaml
-rw-r--r-- 1 root root 672 Dec 20 16:47 log.yaml
```

So here the deb package just needs to set the correct owner of the conf.d directory.

killua-eu on 4 Mar 2019

Wrong direcory? With reference to the the comment just above, the cert gets downloaded to /etc/matrix-synapse/conf.d even though

tls_certificate_path: /etc/matrix-synapse/homeserver.tls.crt
tls_private_key_path: /etc/matrix-synapse/homeserver.tls.key

Or is there an argument to pass to install the LE cert somewhere else?

killua-eu on 4 Mar 2019

Rate-limited

2019-03-04 00:01:52,458 - root - 209 - WARNING - None- ***** STARTING SERVER *****
2019-03-04 00:01:52,468 - root - 212 - WARNING - None- Server /opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/app/homeserver.py version 0.99.2
2019-03-04 00:01:52,468 - root - 214 - INFO - None- Server hostname: matrix.vaizard.xyz
2019-03-04 00:01:52,469 - twisted - 240 - INFO - None- Redirected stdout/stderr to logs
2019-03-04 00:01:52,477 - twisted - 240 - WARNING - None- /opt/venvs/matrix-synapse/lib/python3.6/site-packages/psycopg2/__init__.py:144: builtins.UserWarning: The psycopg2 wheel package will be renamed from release 2.8; in order to keep installing from binary please use "pip install psycopg2-binary" instead. For details see: <http://initd.org/psycopg/docs/install.html#binary-install-from-pypi>.
2019-03-04 00:01:52,488 - synapse.app.homeserver - 358 - INFO - None- Preparing database: psycopg2...
2019-03-04 00:01:52,491 - synapse.storage.prepare_database - 223 - INFO - None- Upgrading schema to v53
2019-03-04 00:01:52,493 - synapse.app.homeserver - 376 - INFO - None- Database prepared in psycopg2.
2019-03-04 00:01:52,493 - synapse.server - 217 - INFO - None- Setting up.
2019-03-04 00:01:52,504 - synapse.storage.event_push_actions - 471 - INFO - None- Searching for stream ordering 1 month ago
2019-03-04 00:01:52,505 - synapse.storage.event_push_actions - 477 - INFO - None- Found stream ordering 1 month ago: it's 0
2019-03-04 00:01:52,505 - synapse.storage.event_push_actions - 479 - INFO - None- Searching for stream ordering 1 day ago
2019-03-04 00:01:52,505 - synapse.storage.event_push_actions - 485 - INFO - None- Found stream ordering 1 day ago: it's 0
2019-03-04 00:01:52,507 - synapse.server - 221 - INFO - None- Finished setting up.
2019-03-04 00:01:52,507 - synapse.app.homeserver - 628 - INFO - None- Scheduling stats reporting for 3 hour intervals
2019-03-04 00:01:52,507 - synapse.app.homeserver - 105 - INFO - - Running
2019-03-04 00:01:52,507 - synapse.app.homeserver - 30 - INFO - - Set file limit to: 1048576
2019-03-04 00:01:52,577 - synapse.handlers.acme - 106 - INFO - - Listening for ACME requests on :::8080
2019-03-04 00:01:52,578 - twisted - 240 - INFO - - Site starting on 8080
2019-03-04 00:01:52,578 - synapse.handlers.acme - 106 - INFO - - Listening for ACME requests on 0.0.0.0:8080
2019-03-04 00:01:52,578 - synapse.app - 47 - WARNING - - Failed to listen on 0.0.0.0, continuing because listening on [::]
2019-03-04 00:01:52,623 - synapse.app.homeserver - 577 - INFO - - report_stats can use psutil
2019-03-04 00:01:52,623 - synapse.metrics - 372 - INFO - - Collecting gc 0
2019-03-04 00:01:52,897 - synapse.metrics - 372 - INFO - - Collecting gc 0
2019-03-04 00:01:53,594 - synapse.metrics - 372 - INFO - - Collecting gc 0
2019-03-04 00:01:53,780 - synapse.handlers.acme - 127 - WARNING - - Reprovisioning matrix.vaizard.xyz
2019-03-04 00:01:54,033 - twisted - 240 - INFO - - Requesting a certificate for 'matrix.vaizard.xyz'.
2019-03-04 00:01:54,322 - synapse.metrics - 372 - INFO - - Collecting gc 0
2019-03-04 00:01:54,325 - synapse.metrics - 372 - INFO - - Collecting gc 1
2019-03-04 00:01:54,518 - synapse.handlers.acme - 132 - ERROR - - Fail!
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/handlers/acme.py", line 130, in provision_certificate
    yield self._issuer.issue_cert(self._acme_domain)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/eliot/twisted.py", line 83, in callbackWithContext
    return self._action.run(callback, *args, **kwargs)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/eliot/_action.py", line 402, in run
    return f(*args, **kwargs)
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/txacme/client.py", line 724, in _got_json
    messages.Error.from_json(jobj), response)
txacme.client.ServerError: (Error(typ='urn:acme:error:rateLimited', title=None, detail='Error creating new authz :: too many failed authorizations recently: see https://letsencrypt.org/docs/rate-limits/'), <treq.response._Response 429 'application/problem+json' 189 bytes>)
2019-03-04 00:01:54,521 - twisted - 240 - ERROR - - Error during startup:
2019-03-04 00:01:54,521 - twisted - 240 - ERROR - - Traceback (most recent call last):
2019-03-04 00:01:54,522 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
2019-03-04 00:01:54,522 - twisted - 240 - ERROR - -     current.result = callback(current.result, *args, **kw)
2019-03-04 00:01:54,523 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 1475, in gotResult
2019-03-04 00:01:54,523 - twisted - 240 - ERROR - -     _inlineCallbacks(r, g, status)
2019-03-04 00:01:54,524 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
2019-03-04 00:01:54,524 - twisted - 240 - ERROR - -     result = result.throwExceptionIntoGenerator(g)
2019-03-04 00:01:54,525 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
2019-03-04 00:01:54,525 - twisted - 240 - ERROR - -     return g.throw(self.type, self.value, self.tb)
2019-03-04 00:01:54,526 - twisted - 240 - ERROR - - --- <exception caught here> ---
2019-03-04 00:01:54,526 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/app/homeserver.py", line 430, in start
2019-03-04 00:01:54,527 - twisted - 240 - ERROR - -     yield do_acme()
2019-03-04 00:01:54,528 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
2019-03-04 00:01:54,528 - twisted - 240 - ERROR - -     result = result.throwExceptionIntoGenerator(g)
2019-03-04 00:01:54,529 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
2019-03-04 00:01:54,529 - twisted - 240 - ERROR - -     return g.throw(self.type, self.value, self.tb)
2019-03-04 00:01:54,529 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/app/homeserver.py", line 407, in do_acme
2019-03-04 00:01:54,530 - twisted - 240 - ERROR - -     yield acme.provision_certificate()
2019-03-04 00:01:54,530 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
2019-03-04 00:01:54,531 - twisted - 240 - ERROR - -     result = result.throwExceptionIntoGenerator(g)
2019-03-04 00:01:54,531 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
2019-03-04 00:01:54,531 - twisted - 240 - ERROR - -     return g.throw(self.type, self.value, self.tb)
2019-03-04 00:01:54,532 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/handlers/acme.py", line 130, in provision_certificate
2019-03-04 00:01:54,532 - twisted - 240 - ERROR - -     yield self._issuer.issue_cert(self._acme_domain)
2019-03-04 00:01:54,533 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
2019-03-04 00:01:54,533 - twisted - 240 - ERROR - -     current.result = callback(current.result, *args, **kw)
2019-03-04 00:01:54,533 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/eliot/twisted.py", line 83, in callbackWithContext
2019-03-04 00:01:54,534 - twisted - 240 - ERROR - -     return self._action.run(callback, *args, **kwargs)
2019-03-04 00:01:54,534 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/eliot/_action.py", line 402, in run
2019-03-04 00:01:54,535 - twisted - 240 - ERROR - -     return f(*args, **kwargs)
2019-03-04 00:01:54,535 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/txacme/client.py", line 724, in _got_json
2019-03-04 00:01:54,535 - twisted - 240 - ERROR - -     messages.Error.from_json(jobj), response)
2019-03-04 00:01:54,536 - twisted - 240 - ERROR - - txacme.client.ServerError: (Error(typ='urn:acme:error:rateLimited', title=None, detail='Error creating new authz :: too many failed authorizations recently: see https://letsencrypt.org/docs/rate-limits/'), <treq.response._Response 429 'application/problem+json' 189 bytes>)
2019-03-04 00:01:54,545 - twisted - 240 - INFO - - (TCP Port 8080 Closed)
2019-03-04 00:01:54,548 - twisted - 240 - INFO - - Main loop terminated.

While evaluating the problem, i did more cert requests then the Letsencrypt api allows to. I can imagine a franctic admin working under pressure to required to restart synapse several times, locking himself up, at first for a few minutes, then for a day. Without much ability to start the server. So it would be probably nice, to print big fat warnings to use the staging api url if things don't work right away

killua-eu on 4 Mar 2019

I hope the devs will agree with me to keep all the above scenarios under a single issue. Better error handling could probably save a day or two. Since the whole thing is a pain to test (twisted serves the well-known only during startup), it might be useful to have a config option to keep serving the well-known longer, so that one can debug i.e. issues on wrong network/reverse proxy/firewall/... settings that might interfere with the ACME facility.

killua-eu on 4 Mar 2019

Not respecting the acme port

To work around the Failed to listen on 0.0.0.0, continuing because listening on [::], i limited the listening to 127.0.0.1 or the internal ip address of the container. I got

2019-03-03 23:32:40,477 - root - 209 - WARNING - None- ***** STARTING SERVER *****
2019-03-03 23:32:40,487 - root - 212 - WARNING - None- Server /opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/app/homeserver.py version 0.99.2
2019-03-03 23:32:40,487 - root - 214 - INFO - None- Server hostname: matrix.vaizard.xyz
2019-03-03 23:32:40,488 - twisted - 240 - INFO - None- Redirected stdout/stderr to logs
2019-03-03 23:32:40,496 - twisted - 240 - WARNING - None- /opt/venvs/matrix-synapse/lib/python3.6/site-packages/psycopg2/__init__.py:144: builtins.UserWarning: The psycopg2 wheel package will be renamed from release 2.8; in order to keep installing from binary please use "pip install psycopg2-binary" instead. For details see: <http://initd.org/psycopg/docs/install.html#binary-install-from-pypi>.
2019-03-03 23:32:40,506 - synapse.app.homeserver - 358 - INFO - None- Preparing database: psycopg2...
2019-03-03 23:32:40,510 - synapse.storage.prepare_database - 223 - INFO - None- Upgrading schema to v53
2019-03-03 23:32:40,511 - synapse.app.homeserver - 376 - INFO - None- Database prepared in psycopg2.
2019-03-03 23:32:40,512 - synapse.server - 217 - INFO - None- Setting up.
2019-03-03 23:32:40,523 - synapse.storage.event_push_actions - 471 - INFO - None- Searching for stream ordering 1 month ago
2019-03-03 23:32:40,523 - synapse.storage.event_push_actions - 477 - INFO - None- Found stream ordering 1 month ago: it's 0
2019-03-03 23:32:40,524 - synapse.storage.event_push_actions - 479 - INFO - None- Searching for stream ordering 1 day ago
2019-03-03 23:32:40,524 - synapse.storage.event_push_actions - 485 - INFO - None- Found stream ordering 1 day ago: it's 0
2019-03-03 23:32:40,525 - synapse.server - 221 - INFO - None- Finished setting up.
2019-03-03 23:32:40,526 - synapse.app.homeserver - 628 - INFO - None- Scheduling stats reporting for 3 hour intervals
2019-03-03 23:32:40,526 - synapse.app.homeserver - 105 - INFO - - Running
2019-03-03 23:32:40,526 - synapse.app.homeserver - 30 - INFO - - Set file limit to: 1048576
2019-03-03 23:32:40,596 - synapse.handlers.acme - 106 - INFO - - Listening for ACME requests on :::8080
2019-03-03 23:32:40,597 - twisted - 240 - INFO - - Site starting on 8080
2019-03-03 23:32:40,597 - synapse.handlers.acme - 106 - INFO - - Listening for ACME requests on 0.0.0.0:8080
2019-03-03 23:32:40,597 - synapse.app - 47 - WARNING - - Failed to listen on 0.0.0.0, continuing because listening on [::]
2019-03-03 23:32:40,641 - synapse.app.homeserver - 577 - INFO - - report_stats can use psutil
2019-03-03 23:32:40,642 - synapse.metrics - 372 - INFO - - Collecting gc 0
2019-03-03 23:32:40,914 - synapse.metrics - 372 - INFO - - Collecting gc 0
2019-03-03 23:32:41,624 - synapse.metrics - 372 - INFO - - Collecting gc 0
2019-03-03 23:32:41,819 - synapse.handlers.acme - 127 - WARNING - - Reprovisioning matrix.vaizard.xyz
2019-03-03 23:32:42,164 - twisted - 240 - INFO - - Requesting a certificate for 'matrix.vaizard.xyz'.
2019-03-03 23:32:42,473 - synapse.metrics - 372 - INFO - - Collecting gc 0
2019-03-03 23:32:42,475 - synapse.metrics - 372 - INFO - - Collecting gc 1
2019-03-03 23:32:48,124 - synapse.metrics - 372 - INFO - - Collecting gc 0
2019-03-03 23:32:48,318 - synapse.handlers.acme - 132 - ERROR - - Fail!
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/handlers/acme.py", line 130, in provision_certificate
    yield self._issuer.issue_cert(self._acme_domain)
txacme.client.AuthorizationFailed: AuthorizationFailed(<Status(invalid) Identifier(typ=IdentifierType(dns), value='matrix.vaizard.xyz') [Error(typ='urn:acme:error:unauthorized', title=None, detail='Invalid response from http://matrix.vaizard.xyz/.well-known/acme-challenge/EX1PyXaHXYlPEqTFgrE09u7uFurcGZeTngKKMzGDsQ0 [78.44.255.11]: 503')]>)
2019-03-03 23:32:48,319 - twisted - 240 - ERROR - - Error during startup:
2019-03-03 23:32:48,320 - twisted - 240 - ERROR - - Traceback (most recent call last):
2019-03-03 23:32:48,321 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/treq/client.py", line 80, in _deliverWaiting
2019-03-03 23:32:48,322 - twisted - 240 - ERROR - -     waiter.connectionLost(reason)
2019-03-03 23:32:48,322 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/treq/content.py", line 39, in connectionLost
2019-03-03 23:32:48,323 - twisted - 240 - ERROR - -     self.finished.callback(None)
2019-03-03 23:32:48,324 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 460, in callback
2019-03-03 23:32:48,325 - twisted - 240 - ERROR - -     self._startRunCallbacks(result)
2019-03-03 23:32:48,326 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
2019-03-03 23:32:48,326 - twisted - 240 - ERROR - -     self._runCallbacks()
2019-03-03 23:32:48,327 - twisted - 240 - ERROR - - --- <exception caught here> ---
2019-03-03 23:32:48,327 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/app/homeserver.py", line 430, in start
2019-03-03 23:32:48,328 - twisted - 240 - ERROR - -     yield do_acme()
2019-03-03 23:32:48,329 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/app/homeserver.py", line 407, in do_acme
2019-03-03 23:32:48,329 - twisted - 240 - ERROR - -     yield acme.provision_certificate()
2019-03-03 23:32:48,330 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/synapse/handlers/acme.py", line 130, in provision_certificate
2019-03-03 23:32:48,331 - twisted - 240 - ERROR - -     yield self._issuer.issue_cert(self._acme_domain)
2019-03-03 23:32:48,331 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
2019-03-03 23:32:48,332 - twisted - 240 - ERROR - -     current.result = callback(current.result, *args, **kw)
2019-03-03 23:32:48,332 - twisted - 240 - ERROR - -   File "/opt/venvs/matrix-synapse/lib/python3.6/site-packages/txacme/client.py", line 599, in repoll
2019-03-03 23:32:48,333 - twisted - 240 - ERROR - -     raise AuthorizationFailed(authzr)

So, [Error(typ='urn:acme:error:unauthorized', title=None, detail='Invalid response from http://matrix.vaizard.xyz/.well-known/acme-challenge/EX1PyXaHXYlPEqTFgrE09u7uFurcGZeTngKKMzGDsQ0 [78.44.255.11]: 503')]>) goes to http://matrix.vaizard.xyz instead of http://matrix.vaizard.xyz:8080as I request per configuration. As i have a proxy hogging por 80, this will I guess, be the root of my problem.

killua-eu on 4 Mar 2019

This is a bit of a grab-bag, and it's hard to see what's going on in any of it. I don't agree that it should all be treated as one bug; there are various different things going on here with different solutions.

Here's one that caught my eye in the noise:

Failed to listen on 0.0.0.0, continuing because listening on [::]

Note that this is a harmless warning. There's something to be said for the fact that the default config shouldn't generate warnings, but still: it's clearly a separate issue.

In other words: I suggest filing more granular issues.