Skip to content

Sending SIGHUP to Synapse breaks TerseJsonFormatting #20091

Description

@LeonWilzer

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:

# this is a workaround to make sure we don't get stack overflows when the
# logging system raises an error which is written to stderr which is redirected
# to the logging system, etc.
if getattr(threadlocal, "active", False):
# write the text of the event, if any, to the *real* stderr (which may
# be redirected to /dev/null, but there's not much we can do)
try:
event_text = eventAsText(event)
print("logging during logging: %s" % event_text, file=sys.__stderr__)
except Exception:
# gah.
pass
return

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:

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

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.

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions