Twisted log output is discarded

[DataBeaver]

Description

If the database parameters are incorrect such that synapse can't connect to postgresql, it will exit without printing any kind of error message. The log shows "setting up" as the last line.

Steps to reproduce

• Have an incorrect database configuration (in my case I had no matching entry in pg_hba.conf so postgresql was refusing the connection)
• Try to start synapse

I would expect to see some kind of error message pointing me at the database configuration, not a silent exit.

Version information

Synapse 1.12.4, installed from Debian's (unstable/sid) repository.

[richvdh]

are you sure? how did you start synapse?

[DataBeaver]

root@capybara # su -s /bin/sh matrix-synapse -c "/usr/bin/python3 -m synapse.app.homeserver --config-path /etc/matrix-synapse/homeserver.yaml --config-path /etc/matrix-synapse/conf.d/"
2020-05-11 21:03:23,313 - root - 257 - WARNING - None - ***** STARTING SERVER *****
2020-05-11 21:03:23,313 - root - 258 - WARNING - None - Server /usr/lib/python3/dist-packages/synapse/app/homeserver.py version 1.12.4
2020-05-11 21:03:23,313 - root - 259 - INFO - None - Server hostname: (redacted)
2020-05-11 21:03:23,313 - synapse.app.homeserver - 345 - INFO - None - Setting up server
2020-05-11 21:03:23,314 - synapse.server - 240 - INFO - None - Setting up.
root@capybara #

[anoadragon453]

Trying to reproduce this locally, I receive the desired output:

 ❯ su -s /bin/sh user -c "/home/user/code/synapse/env/bin/python -m synapse.app.homeserver --config-path /home/user/code/synapse/homeserver.yaml"
Password: 
This server is configured to use 'matrix.org' as its trusted key server via the
'trusted_key_servers' config option. 'matrix.org' is a good choice for a key
server since it is long-lived, stable and trusted. However, some admins may
wish to use another server for this purpose.

To suppress this warning and continue using 'matrix.org', admins should set
'suppress_key_server_warning' to 'true' in homeserver.yaml.
--------------------------------------------------------------------------------
2020-05-11 20:19:25,758 - twisted - 192 - INFO - None - Redirected stdout/stderr to logs
2020-05-11 20:19:25,759 - root - 257 - WARNING - None - ***** STARTING SERVER *****
2020-05-11 20:19:25,759 - root - 258 - WARNING - None - Server /home/user/code/synapse/synapse/app/homeserver.py version 1.13.0rc1 (b=anoa/fix_broken_communities,622137815)
2020-05-11 20:19:25,759 - root - 259 - INFO - None - Server hostname: localhost
2020-05-11 20:19:25,759 - synapse.app.homeserver - 366 - INFO - None - Setting up server
2020-05-11 20:19:25,759 - synapse.server - 270 - INFO - None - Setting up.
2020-05-11 20:19:25,799 - twisted - 192 - ERROR -  - Traceback (most recent call last):
2020-05-11 20:19:25,801 - twisted - 192 - ERROR -  -   File "/usr/lib64/python3.8/runpy.py", line 193, in _run_module_as_main
2020-05-11 20:19:25,802 - twisted - 192 - ERROR -  -     return _run_code(code, main_globals, None,
2020-05-11 20:19:25,802 - twisted - 192 - ERROR -  -   File "/usr/lib64/python3.8/runpy.py", line 86, in _run_code
2020-05-11 20:19:25,802 - twisted - 192 - ERROR -  -     exec(code, run_globals)
2020-05-11 20:19:25,803 - twisted - 192 - ERROR -  -   File "/home/user/code/synapse/synapse/app/homeserver.py", line 679, in <module>
2020-05-11 20:19:25,804 - twisted - 192 - ERROR -  -     main()
2020-05-11 20:19:25,805 - twisted - 192 - ERROR -  -   File "/home/user/code/synapse/synapse/app/homeserver.py", line 674, in main
2020-05-11 20:19:25,807 - twisted - 192 - ERROR -  -     hs = setup(sys.argv[1:])
2020-05-11 20:19:25,807 - twisted - 192 - ERROR -  -   File "/home/user/code/synapse/synapse/app/homeserver.py", line 369, in setup
2020-05-11 20:19:25,807 - twisted - 192 - ERROR -  -     hs.setup()
2020-05-11 20:19:25,808 - twisted - 192 - ERROR -  -   File "/home/user/code/synapse/synapse/server.py", line 272, in setup
2020-05-11 20:19:25,808 - twisted - 192 - ERROR -  -     self.datastores = DataStores(self.DATASTORE_CLASS, self)
2020-05-11 20:19:25,808 - twisted - 192 - ERROR -  -   File "/home/user/code/synapse/synapse/storage/data_stores/__init__.py", line 47, in __init__
2020-05-11 20:19:25,809 - twisted - 192 - ERROR -  -     with make_conn(database_config, engine) as db_conn:
2020-05-11 20:19:25,809 - twisted - 192 - ERROR -  -   File "/home/user/code/synapse/synapse/storage/database.py", line 114, in make_conn
2020-05-11 20:19:25,809 - twisted - 192 - ERROR -  -     db_conn = engine.module.connect(**db_params)
2020-05-11 20:19:25,810 - twisted - 192 - ERROR -  -   File "/home/user/code/synapse/env/lib/python3.8/site-packages/psycopg2/__init__.py", line 126, in connect
2020-05-11 20:19:25,810 - twisted - 192 - ERROR -  -     conn = _connect(dsn, connection_factory=connection_factory, **kwasync)
2020-05-11 20:19:25,810 - twisted - 192 - ERROR -  - psycopg2.OperationalError: FATAL:  role "synapse_blabla_incorrect" does not exist
2020-05-11 20:19:25,810 - twisted - 192 - ERROR -  - 
❯  

You wouldn't happen to have the no_redirect_stdio config option set to true in any of your homeserver configuration files?

[DataBeaver]

Grepping for stdio in /etc/matrix-synapse produces no results. I've tried with both the logging config supplied with the Debian package and the one generated by synapse itself with the --generate-config switch. The log file does not get the error either.

[richvdh]

do you have daemonize set in the config?

[DataBeaver]

Nope, no daemonize set either.

If I do set no_redirect_stdio to true, then the database error is printed directly to stderr and appears on the terminal. So twisted is eating stderr as it should, but then it just ends up going nowhere. I've yet to figure out what causes it to disappear.

[richvdh]

@DataBeaver: is this still a problem? is the error appearing in the logfile?

somewhat related: #4641

[DataBeaver]

Yes, this still occurs with Synapse 1.20.1. Version of twisted is 18.9.0 if that matters. It would be acceptable if the error was only in the log and not the terminal I tried to start synapse from, but it doesn't go into the log either.

[richvdh]

weird. can you share your log config?

[richvdh]

also, can you share anything you do see in your logs?

[DataBeaver]

https://gist.github.com/DataBeaver/443bccea5e10fb99792b2c05e27c9081

2020-10-07 14:55:30,307 - root - 296 - WARNING - None - ***** STARTING SERVER *****
2020-10-07 14:55:30,307 - root - 297 - WARNING - None - Server /usr/lib/python3/dist-packages/synapse/app/homeserver.py version 1.20.1
2020-10-07 14:55:30,308 - root - 298 - INFO - None - Server hostname: tdb.fi
2020-10-07 14:55:30,308 - root - 299 - INFO - None - Instance name: master
2020-10-07 14:55:30,308 - synapse.app.homeserver - 375 - INFO - None - Setting up server
2020-10-07 14:55:30,308 - synapse.server - 249 - INFO - None - Setting up.

[richvdh]

Well, that should work. Can you try two things for me:

• remove the specific configuration for the twisted logger: that should result in a log line as follows:

  2020-10-07 13:36:13,141 - twisted - 250 - INFO - None - Redirected stdout/stderr to logs
  

• add disable_existing_loggers: false to your log config, as per https://github.com/matrix-org/synapse/blob/master/docs/sample_log_config.yaml#L67.

[DataBeaver]

Neither of those things, separately or together, causes anything new to appear in the log.

[richvdh]

it seems like twisted's logging system is not correctly being connected to the python stdlib logger. I have no idea what could cause this :/.