Bug 240498

Summary: net-im/py-matrix-synapse: Cannot start service
Product: Ports & Packages Reporter: IPTRACE <arkadiusz.majewski>
Component: Individual Port(s)Assignee: Kubilay Kocak <koobs>
Status: Closed Works As Intended    
Severity: Affects Some People CC: chris, koobs, ports
Priority: --- Flags: koobs: maintainer-feedback+
Version: Latest   
Hardware: amd64   
OS: Any   
See Also: https://github.com/matrix-org/synapse/pull/6284

Description IPTRACE 2019-09-11 10:02:51 UTC 
Hello!

I cannot start the synapse service. Installed using pkg.

pkg install py36-matrix-synapse py36-matrix-synapse-ldap3

FreeBSD 12.0-RELEASE-p10

synapse config file copied from https://github.com/matrix-org/synapse/blob/develop/docs/sample_config.yaml .

user@serv:~ % service synapse start
Starting synapse.

Please opt in or out of reporting anonymized homeserver usage statistics, by
setting the `report_stats` key in your config file to either True or False.

We would really appreciate it if you could help our project out by reporting
anonymized usage statistics from your homeserver. Only very basic aggregate
data (e.g. number of users) will be reported, but it helps us to track the
growth of the Matrix community, and helps us to make Matrix a success, as well
as to convince other networks that they should peer with us.

Thank you.

/usr/local/etc/rc.d/synapse: WARNING: failed to start synapse
user@serv:~ %
Comment 1 Kubilay Kocak freebsd_committer freebsd_triage 2019-09-11 10:07:18 UTC 
@Reporter This appears to be a general/configuration (missing config entry) issue. 

Does the service start when uncommenting "report_stats" in the configuration?

I see that its commented by default:

# Whether or not to report anonymized homeserver usage statistics.
# report_stats: true|false
Comment 2 IPTRACE 2019-09-11 10:12:39 UTC 
Unfortunately not. I've set as follow.

# Whether or not to report anonymized homeserver usage statistics.
report_stats: false
Comment 3 IPTRACE 2019-09-11 12:51:49 UTC 
Little progress. I run the synapse using two below commands as my standard user.

# python3.6 -m synapse.app.homeserver --server-name my.domain --config-path homeserver.yaml --generate-config --report-stats=no
# synctl start

At this moment server had started. So, I've copied generated homeserver.yaml file and other like logs, db and another config file and changed paths in homeserver.yaml file.
Then I've just run the service start command.

# service synapse start

Output is below:

Starting synapse.
2019-09-11 14:43:53,714 - root - 226 - WARNING - None - ***** STARTING SERVER *****
2019-09-11 14:43:53,745 - synapse.util.versionstring - 85 - INFO - None - Failed to check for git repository: [Errno 2] No such file or directory: 'git': 'git'
2019-09-11 14:43:53,746 - root - 227 - WARNING - None - Server /usr/local/lib/python3.6/site-packages/synapse/app/homeserver.py version 1.2.1
2019-09-11 14:43:53,747 - root - 228 - INFO - None - Server hostname: my.domain
2019-09-11 14:43:53,748 - twisted - 254 - INFO - None - Redirected stdout/stderr to logs
2019-09-11 14:43:53,780 - synapse.util.versionstring - 85 - INFO - None - Failed to check for git repository: [Errno 2] No such file or directory: 'git': 'git'
2019-09-11 14:43:53,783 - synapse.app.homeserver - 359 - INFO - None - Preparing database: sqlite3...
2019-09-11 14:43:53,788 - synapse.storage.prepare_database - 242 - INFO - None - Upgrading schema to v55
2019-09-11 14:43:53,790 - synapse.app.homeserver - 377 - INFO - None - Database prepared in sqlite3.
2019-09-11 14:43:53,790 - synapse.server - 233 - INFO - None - Setting up.
2019-09-11 14:43:53,810 - synapse.storage.event_push_actions - 500 - INFO - None - Searching for stream ordering 1 month ago
2019-09-11 14:43:53,810 - synapse.storage.event_push_actions - 505 - INFO - None - Found stream ordering 1 month ago: it's 0
2019-09-11 14:43:53,811 - synapse.storage.event_push_actions - 507 - INFO - None - Searching for stream ordering 1 day ago
2019-09-11 14:43:53,811 - synapse.storage.event_push_actions - 512 - INFO - None - Found stream ordering 1 day ago: it's 0
2019-09-11 14:43:53,814 - synapse.server - 237 - INFO - None - Finished setting up. 

Unfortunately, server is not up.
Comment 4 IPTRACE 2019-09-11 12:54:58 UTC 
# tail -150 /log/app/matrix-synapse/homeserver.log

2019-09-11 14:52:34,818 - root - 226 - WARNING - None - ***** STARTING SERVER *****
2019-09-11 14:52:34,849 - synapse.util.versionstring - 85 - INFO - None - Failed to check for git repository: [Errno 2] No such file or directory: 'git': 'git'
2019-09-11 14:52:34,851 - root - 227 - WARNING - None - Server /usr/local/lib/python3.6/site-packages/synapse/app/homeserver.py version 1.2.1
2019-09-11 14:52:34,851 - root - 228 - INFO - None - Server hostname: my.domain
2019-09-11 14:52:34,852 - twisted - 254 - INFO - None - Redirected stdout/stderr to logs
2019-09-11 14:52:34,885 - synapse.util.versionstring - 85 - INFO - None - Failed to check for git repository: [Errno 2] No such file or directory: 'git': 'git'
2019-09-11 14:52:34,887 - synapse.app.homeserver - 359 - INFO - None - Preparing database: sqlite3...
2019-09-11 14:52:34,893 - synapse.storage.prepare_database - 242 - INFO - None - Upgrading schema to v55
2019-09-11 14:52:34,894 - synapse.app.homeserver - 377 - INFO - None - Database prepared in sqlite3.
2019-09-11 14:52:34,895 - synapse.server - 233 - INFO - None - Setting up.
2019-09-11 14:52:34,914 - synapse.storage.event_push_actions - 500 - INFO - None - Searching for stream ordering 1 month ago
2019-09-11 14:52:34,915 - synapse.storage.event_push_actions - 505 - INFO - None - Found stream ordering 1 month ago: it's 0
2019-09-11 14:52:34,915 - synapse.storage.event_push_actions - 507 - INFO - None - Searching for stream ordering 1 day ago
2019-09-11 14:52:34,916 - synapse.storage.event_push_actions - 512 - INFO - None - Found stream ordering 1 day ago: it's 0
2019-09-11 14:52:34,919 - synapse.server - 237 - INFO - None - Finished setting up.
2019-09-11 14:52:34,963 - synapse.app.homeserver - 245 - WARNING -  - Starting daemon.
2019-09-11 14:52:34,966 - synapse.app.homeserver - 106 - INFO -  - Running
2019-09-11 14:52:34,966 - synapse.app.homeserver - 30 - INFO -  - Set file limit to: 57870
2019-09-11 14:52:34,981 - synapse.federation.federation_server - 814 - INFO -  - Registering federation query handler for 'profile'
2019-09-11 14:52:34,983 - synapse.push.pusher - 41 - INFO -  - email enable notifs: False
2019-09-11 14:52:34,988 - synapse.federation.federation_server - 814 - INFO -  - Registering federation query handler for 'directory'
2019-09-11 14:52:34,990 - synapse.handlers.auth - 84 - INFO -  - Extra password_providers: []
2019-09-11 14:52:34,992 - synapse.federation.federation_server - 796 - INFO -  - Registering federation EDU handler for 'm.device_list_update'
2019-09-11 14:52:34,992 - synapse.federation.federation_server - 814 - INFO -  - Registering federation query handler for 'user_devices'
2019-09-11 14:52:35,030 - synapse.federation.federation_server - 796 - INFO -  - Registering federation EDU handler for 'm.presence'
2019-09-11 14:52:35,040 - synapse.federation.federation_server - 796 - INFO -  - Registering federation EDU handler for 'm.typing'
2019-09-11 14:52:35,054 - synapse.handlers.deactivate_account - 149 - INFO - user_parter_loop-0 - Starting user parter
2019-09-11 14:52:35,058 - synapse.federation.federation_server - 796 - INFO -  - Registering federation EDU handler for 'm.receipt'
2019-09-11 14:52:35,062 - synapse.federation.federation_server - 814 - INFO -  - Registering federation query handler for 'client_keys'
2019-09-11 14:52:35,065 - synapse.federation.federation_server - 796 - INFO -  - Registering federation EDU handler for 'm.direct_to_device'
2019-09-11 14:52:35,106 - synapse.util.versionstring - 85 - INFO -  - Failed to check for git repository: [Errno 2] No such file or directory: 'git': 'git'
2019-09-11 14:52:35,132 - synapse.util.httpresourcetree - 46 - INFO -  - Attaching <synapse.rest.ClientRestResource object at 0x805deda90> to path b'/_matrix/client/api/v1'
2019-09-11 14:52:35,132 - synapse.util.httpresourcetree - 46 - INFO -  - Attaching <synapse.rest.ClientRestResource object at 0x805deda90> to path b'/_matrix/client/r0'
2019-09-11 14:52:35,133 - synapse.util.httpresourcetree - 46 - INFO -  - Attaching <synapse.rest.ClientRestResource object at 0x805deda90> to path b'/_matrix/client/unstable'
2019-09-11 14:52:35,133 - synapse.util.httpresourcetree - 46 - INFO -  - Attaching <synapse.rest.ClientRestResource object at 0x805deda90> to path b'/_matrix/client/v2_alpha'
2019-09-11 14:52:35,133 - synapse.util.httpresourcetree - 46 - INFO -  - Attaching <synapse.rest.ClientRestResource object at 0x805deda90> to path b'/_matrix/client/versions'
2019-09-11 14:52:35,134 - synapse.util.httpresourcetree - 46 - INFO -  - Attaching <synapse.rest.well_known.WellKnownResource object at 0x805f94588> to path b'/.well-known/matrix/client'
2019-09-11 14:52:35,134 - synapse.util.httpresourcetree - 46 - INFO -  - Attaching <synapse.rest.admin.AdminRestResource object at 0x805f94748> to path b'/_synapse/admin'
2019-09-11 14:52:35,134 - synapse.util.httpresourcetree - 46 - INFO -  - Attaching FilePath('/usr/local/lib/python3.6/site-packages/synapse/static') to path b'/_matrix/static'
2019-09-11 14:52:35,135 - synapse.util.httpresourcetree - 46 - INFO -  - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x805e48d30> to path b'/_matrix/media/r0'
2019-09-11 14:52:35,135 - synapse.util.httpresourcetree - 46 - INFO -  - Attaching <synapse.rest.media.v1.media_repository.MediaRepositoryResource object at 0x805e48d30> to path b'/_matrix/media/v1'
2019-09-11 14:52:35,135 - synapse.util.httpresourcetree - 46 - INFO -  - Attaching <synapse.rest.media.v0.content_repository.ContentRepoResource object at 0x805f94f60> to path b'/_matrix/content'
2019-09-11 14:52:35,136 - synapse.util.httpresourcetree - 46 - INFO -  - Attaching <synapse.federation.transport.server.TransportLayerServer object at 0x805f6dfd0> to path b'/_matrix/federation'
2019-09-11 14:52:35,136 - synapse.util.httpresourcetree - 46 - INFO -  - Attaching <synapse.rest.key.v2.KeyApiV2Resource object at 0x805fa3b00> to path b'/_matrix/key/v2'
2019-09-11 14:52:35,142 - twisted - 254 - ERROR -  - Traceback (most recent call last):
2019-09-11 14:52:35,142 - twisted - 254 - ERROR -  -   File "/usr/local/lib/python3.6/site-packages/twisted/internet/tcp.py", line 1361, in startListening
2019-09-11 14:52:35,143 - twisted - 254 - ERROR -  -     skt.bind(addr)
2019-09-11 14:52:35,143 - twisted - 254 - ERROR -  - PermissionError: [Errno 13] Permission denied
2019-09-11 14:52:35,144 - twisted - 254 - ERROR -  -
2019-09-11 14:52:35,144 - twisted - 254 - ERROR -  - During handling of the above exception, another exception occurred:
2019-09-11 14:52:35,144 - twisted - 254 - ERROR -  -
2019-09-11 14:52:35,145 - twisted - 254 - ERROR -  - Traceback (most recent call last):
2019-09-11 14:52:35,145 - twisted - 254 - ERROR -  -   File "/usr/local/lib/python3.6/site-packages/synapse/app/_base.py", line 259, in start
2019-09-11 14:52:35,145 - twisted - 254 - ERROR -  -     hs.start_listening(listeners)
2019-09-11 14:52:35,146 - twisted - 254 - ERROR -  -   File "/usr/local/lib/python3.6/site-packages/synapse/app/homeserver.py", line 266, in start_listening
2019-09-11 14:52:35,146 - twisted - 254 - ERROR -  -     self._listening_services.extend(self._listener_http(config, listener))
2019-09-11 14:52:35,147 - twisted - 254 - ERROR -  -   File "/usr/local/lib/python3.6/site-packages/synapse/app/homeserver.py", line 152, in _listener_http
2019-09-11 14:52:35,147 - twisted - 254 - ERROR -  -     reactor=self.get_reactor(),
2019-09-11 14:52:35,147 - twisted - 254 - ERROR -  -   File "/usr/local/lib/python3.6/site-packages/synapse/app/_base.py", line 171, in listen_tcp
2019-09-11 14:52:35,148 - twisted - 254 - ERROR -  -     check_bind_error(e, address, bind_addresses)
2019-09-11 14:52:35,148 - twisted - 254 - ERROR -  -   File "/usr/local/lib/python3.6/site-packages/synapse/app/__init__.py", line 49, in check_bind_error
2019-09-11 14:52:35,149 - twisted - 254 - ERROR -  -     raise e
2019-09-11 14:52:35,149 - twisted - 254 - ERROR -  -   File "/usr/local/lib/python3.6/site-packages/synapse/app/_base.py", line 169, in listen_tcp
2019-09-11 14:52:35,149 - twisted - 254 - ERROR -  -     r.append(reactor.listenTCP(port, factory, backlog, address))
2019-09-11 14:52:35,150 - twisted - 254 - ERROR -  -   File "/usr/local/lib/python3.6/site-packages/twisted/internet/posixbase.py", line 495, in listenTCP
2019-09-11 14:52:35,150 - twisted - 254 - ERROR -  -     p.startListening()
2019-09-11 14:52:35,150 - twisted - 254 - ERROR -  -   File "/usr/local/lib/python3.6/site-packages/twisted/internet/tcp.py", line 1363, in startListening
2019-09-11 14:52:35,151 - twisted - 254 - ERROR -  -     raise CannotListenError(self.interface, self.port, le)
2019-09-11 14:52:35,151 - twisted - 254 - ERROR -  - twisted.internet.error.CannotListenError: Couldn't listen on 127.0.0.1:80: [Errno 13] Permission denied.
2019-09-11 14:52:35,154 - synapse.handlers.deactivate_account - 159 - INFO - user_parter_loop-0 - User parter finished: stopping
2019-09-11 14:52:35,157 - synapse.handlers.presence - 236 - INFO - presence.on_shutdown-0 - Performing _on_shutdown. Persisting 0 unpersisted changes
2019-09-11 14:52:35,160 - synapse.handlers.presence - 247 - INFO - presence.on_shutdown-0 - Finished _on_shutdown
2019-09-11 14:52:35,241 - twisted - 254 - CRITICAL -  - Unhandled error in Deferred:
2019-09-11 14:52:35,241 - twisted - 254 - CRITICAL -  -
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/twisted/internet/tcp.py", line 1361, in startListening
    skt.bind(addr)
PermissionError: [Errno 13] Permission denied

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/synapse/app/_base.py", line 259, in start
    hs.start_listening(listeners)
  File "/usr/local/lib/python3.6/site-packages/synapse/app/homeserver.py", line 266, in start_listening
    self._listening_services.extend(self._listener_http(config, listener))
  File "/usr/local/lib/python3.6/site-packages/synapse/app/homeserver.py", line 152, in _listener_http
    reactor=self.get_reactor(),
  File "/usr/local/lib/python3.6/site-packages/synapse/app/_base.py", line 171, in listen_tcp
    check_bind_error(e, address, bind_addresses)
  File "/usr/local/lib/python3.6/site-packages/synapse/app/__init__.py", line 49, in check_bind_error
    raise e
  File "/usr/local/lib/python3.6/site-packages/synapse/app/_base.py", line 169, in listen_tcp
    r.append(reactor.listenTCP(port, factory, backlog, address))
  File "/usr/local/lib/python3.6/site-packages/twisted/internet/posixbase.py", line 495, in listenTCP
    p.startListening()
  File "/usr/local/lib/python3.6/site-packages/twisted/internet/tcp.py", line 1363, in startListening
    raise CannotListenError(self.interface, self.port, le)
twisted.internet.error.CannotListenError: Couldn't listen on 127.0.0.1:80: [Errno 13] Permission denied.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/usr/local/lib/python3.6/site-packages/synapse/app/homeserver.py", line 435, in start
    _base.start(hs, config.listeners)
  File "/usr/local/lib/python3.6/site-packages/synapse/app/_base.py", line 268, in start
    sys.exit(1)
SystemExit: 1
2019-09-11 14:52:35,258 - twisted - 254 - INFO -  - Main loop terminated.
2019-09-11 14:52:35,259 - synapse.app.homeserver - 70 - WARNING -  - Stopping daemon.
Comment 5 IPTRACE 2019-09-11 13:06:56 UTC 
More progress. I've just changed line in /usr/local/etc/rc.d/synapse .

from
: ${synapse_user:=synapse}
to
: ${synapse_user:=root}

It looks like running "service synapse start" even as root does not give proper permissions to create socket?
Comment 6 Christopher May-Townsend 2019-09-20 21:08:17 UTC 
The other issue you have I managed to get around by installing git (it seems to check if theres a tag or something in the repo)

At this rate, we should add git as a dependency (unless the warning for this is a red herring and would work anyway)
Comment 7 Sascha Biberhofer 2019-11-28 15:35:11 UTC 
I completely missed this bug, sorry for chiming in this late. 

As far as the git error is concerned: This is indeed a red herring and can safely be ignored. It's also tracked by upstream in [1] and should be fixed in recent releases.

As far as listening on port 80 is concerned: I think that if you want synapse to listen on ports <1024 then you need to run it as root. The general recommendation is not to do this at all and instead use a reverse proxy to handle this. By default, synapse shouldn't use port 80 unless you've enabled the acme listener, which isn't supported by the port as we don't have the necessary python packages in ports for this. 

It might be better not to copy the sample config from the repo, but instead generate the configuration locally, which should avoid this problem. In any case, you may need to edit the configuration accordingly.

Is there's any action we should take for our port/package? 

Cheers,
Sascha

[1] https://github.com/matrix-org/synapse/pull/6284
Comment 8 Kubilay Kocak freebsd_committer freebsd_triage 2020-03-17 02:28:45 UTC 
This issue needs issue isolate and a change proposal to progress
Comment 9 Kubilay Kocak freebsd_committer freebsd_triage 2020-04-27 07:49:58 UTC 
^Triage: 

- Maintainer confirmed that the config sample is not intended to be a complete configuration, but rather a reference. More precisely via IRC: " Neither the upstream nor a generated config can be used without editing."

- Further, reporter used an upstream configuration file, which, all else being equal, would not be a supported (freebsd port) configuration.

- To the extent that any integration or out of box experience for the matrix port can or should be improved, that ought to happen independently from the issue 'as reported' here.