element-hq / element-hq/synapse

Sending SIGHUP to Synapse breaks `TerseJsonFormatting`

Open
#20,091 0 comments 0 reactions 0 assignees View on GitHub
A-Logging
Dominant language
Python
Stars
4.6k
Forks
600
Avg merge
5d 22h
Merged PRs (30d)
51

Description

### Description

When reloading synapse by sending a SIGHUP, synapse breaks the JSON based logging.

The offending part seems to be this, as identified by the "logging during logging" string:
https://github.com/element-hq/synapse/blob/5ed830b3b4c74c89d876cc07756c5d98a100cbed/synapse/config/logger.py#L257-L269

### Steps to reproduce

- Configure synapse to use `TerseJsonFormatter`
- `systemctl restart matrix-synapse.service`
- `systemctl reload matrix-synapse.service`
- `journalctl -xeu matrix-synapse.service` and take a look at the logs before and after the reload

### Homeserver

matrix.uni-paderborn.de

### Synapse Version

1.158.0

### Installation Method

Debian packages from packages.matrix.org

### Database

PostgreSQL, single instance, no portdb, no restore from backup

### Workers

Single process

### Platform

- Debian 13 Trixie
- VM without Container

### Configuration

log.yaml:
```yaml
version: 1

formatters:
structured:
class: synapse.logging.TerseJsonFormatter

handlers:
console:
class: logging.StreamHandler
formatter: structured

loggers:
synapse.storage.SQL:
# beware: increasing this to DEBUG will make synapse log sensitive
# information such as access tokens.
level: INFO

root:
level: INFO

# Write logs to `console` meaning stderr which gets written to journald by systemd.
handlers: [console]

disable_existing_loggers: false
```

### Relevant log output

```shell
Aug 11 16:25:29 upb-matrix-trixie matrix-synapse[1074379]: {"log":"SynapseSite starting on 8008","namespace":"twisted","level":"INFO","time":1786458329.67,"server_name":"upb-well-known.dev.cs.uni-paderborn.de","request":"call_when_running"}
Aug 11 16:25:29 upb-matrix-trixie matrix-synapse[1074379]: {"log":"SynapseSite starting on 8008","namespace":"twisted","level":"INFO","time":1786458329.68,"server_name":"upb-well-known.dev.cs.uni-paderborn.de","request":"call_when_running"}
Aug 11 16:25:29 upb-matrix-trixie matrix-synapse[1074379]: {"log":"Synapse now listening on TCP port 8008","namespace":"synapse.app._base","level":"INFO","time":1786458329.68,"server_name":"upb-well-known.dev.cs.uni-paderborn.de","request":"call_when_running"}
Aug 11 16:25:29 upb-matrix-trixie systemd[1]: Started matrix-synapse.service - Synapse Matrix homeserver.
░░ Subject: A start job for unit matrix-synapse.service has finished successfully
░░ Defined-By: systemd
░░ Support: https://www.debian.org/support
░░
░░ A start job for unit matrix-synapse.service has finished successfully.
░░
░░ The job identifier is 672271.
Aug 11 16:25:29 upb-matrix-trixie matrix-synapse[1074379]: {"log":"garbage collector: Freezing all allocated objects in the hopes that (almost) everything currently allocated are things that will be used by the homeserver for the rest of time. Doing so means less work each GC (hopefully).","namespace":"synapse.app._base","level":"INFO","time":1786458329.68,"server_name":"upb-well-known.dev.cs.uni-paderborn.de","request":"call_when_running"}
Aug 11 16:25:29 upb-matrix-trixie matrix-synapse[1074379]: {"log":"Starting background schema updates for database master","namespace":"synapse.storage.background_updates","level":"INFO","time":1786458329.73,"server_name":"upb-well-known.dev.cs.uni-paderborn.de","request":"background_updates-0"}
Aug 11 16:25:29 upb-matrix-trixie matrix-synapse[1074379]: {"log":"User parter finished: stopping","namespace":"synapse.handlers.deactivate_account","level":"INFO","time":1786458329.73,"server_name":"upb-well-known.dev.cs.uni-paderborn.de","request":"user_parter_loop-0"}
Aug 11 16:25:29 upb-matrix-trixie matrix-synapse[1074379]: {"log":"Started pushers","namespace":"synapse.push.pusherpool","level":"INFO","time":1786458329.73,"server_name":"upb-well-known.dev.cs.uni-paderborn.de","request":"start_pushers-0"}
Aug 11 16:25:29 upb-matrix-trixie matrix-synapse[1074379]: {"log":"No more background updates to do. Unscheduling background update task.","namespace":"synapse.storage.background_updates","level":"INFO","time":1786458329.74,"server_name":"upb-well-known.dev.cs.uni-paderborn.de","request":"background_updates-0"}
Aug 11 16:25:36 upb-matrix-trixie systemd[1]: Reloading matrix-synapse.service - Synapse Matrix homeserver...
░░ Subject: A reload job for unit matrix-synapse.service has begun execution
░░ Defined-By: systemd
░░ Support: https://www.debian.org/support
░░
░░ A reload job for unit matrix-synapse.service has begun execution.
░░
░░ The job identifier is 672395.
Aug 11 16:25:36 upb-matrix-trixie matrix-synapse[1074379]: logging during logging: 2026-08-11T16:25:36+0200 [stderr#error] {"log":"{\"log\":\"Reloaded log config from /etc/matrix-synapse/log.yaml due to SIGHUP\",\"namespace\":\"synapse.config.logger\",\"level\":\"INFO\",\"time\":1786458336.37,\"server_name\":\"upb-well-known.dev.cs.uni-paderborn.de\",\"request\":\"sighup\"}","namespace":"twisted","level":"ERROR","time":1786458336.37,"server_name":"upb-well-known.dev.cs.uni-paderborn.de","request":"sighup"}
Aug 11 16:25:36 upb-matrix-trixie matrix-synapse[1074379]: logging during logging: 2026-08-11T16:25:36+0200 [stderr#error] {"log":"{\"log\":\"Reloading config section 'caches'\",\"namespace\":\"synapse.config._base\",\"level\":\"INFO\",\"time\":1786458336.37,\"server_name\":\"upb-well-known.dev.cs.uni-paderborn.de\",\"request\":\"sighup\"}","namespace":"twisted","level":"ERROR","time":1786458336.37,"server_name":"upb-well-known.dev.cs.uni-paderborn.de","request":"sighup"}
Aug 11 16:25:36 upb-matrix-trixie systemd[1]: Reloaded matrix-synapse.service - Synapse Matrix homeserver.
░░ Subject: A reload job for unit matrix-synapse.service has finished
░░ Defined-By: systemd
░░ Support: https://www.debian.org/support
░░
░░ A reload job for unit matrix-synapse.service has finished.
░░
░░ The job identifier is 672395 and the job result is done.
Aug 11 16:25:59 upb-matrix-trixie matrix-synapse[1074379]: logging during logging: 2026-08-11T16:25:59+0200 [stderr#error] {"log":"{\"log\":\"Rotating notifications\",\"namespace\":\"synapse.storage.databases.main.event_push_actions\",\"level\":\"INFO\",\"time\":1786458359.62,\"server_name\":\"upb-well-known.dev.cs.uni-paderborn.de\",\"request\":\"rotate_notifs-0\"}","namespace":"twisted","level":"ERROR","time":1786458359.62,"server_name":"upb-well-known.dev.cs.uni-paderborn.de","request":"rotate_notifs-0"}
Aug 11 16:25:59 upb-matrix-trixie matrix-synapse[1074379]: logging during logging: 2026-08-11T16:25:59+0200 [stderr#error] {"log":"{\"log\":\"Rotating notifications up to: 14\",\"namespace\":\"synapse.storage.databases.main.event_push_actions\",\"level\":\"INFO\",\"time\":1786458359.62,\"server_name\":\"upb-well-known.dev.cs.uni-paderborn.de\",\"request\":\"rotate_notifs-0\"}","namespace":"twisted","level":"ERROR","time":1786458359.62,"server_name":"upb-well-known.dev.cs.uni-paderborn.de","request":"rotate_notifs-0"}
Aug 11 16:25:59 upb-matrix-trixie matrix-synapse[1074379]: logging during logging: 2026-08-11T16:25:59+0200 [stderr#error] {"log":"{\"log\":\"Rotating notifications, handling 0 rows\",\"namespace\":\"synapse.storage.databases.main.event_push_actions\",\"level\":\"INFO\",\"time\":1786458359.62,\"server_name\":\"upb-well-known.dev.cs.uni-paderborn.de\",\"request\":\"rotate_notifs-0\"}","namespace":"twisted","level":"ERROR","time":1786458359.62,"server_name":"upb-well-known.dev.cs.uni-paderborn.de","request":"rotate_notifs-0"}
```

### Anything else that would be useful to know?

I have only tested out the `TerseJsonFormatter`, but I bet the other JSON based formatters are also affected.

Contributor guide

Open the contributing guide

Research direction

Start in synapse/config/logger.py at the linked lines 257-269 and reproduce the issue with TerseJsonFormatter, systemctl reload, and journalctl. Trace what changes during SIGHUP and verify that logs remain JSON-formatted afterward without the "logging during logging" wrapper; check whether the other JSON formatters show the same behavior.

Written by the indexing model from the issue text.

Assessment

Tech stack
python
Domain
observability
Issue type
Bug
Difficulty
3/5
Estimated time
1-2 days
Activity status
Quiet
Clarity
Mostly clear
Newbie friendliness
68/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.