`synapse.logging.RemoteHandler` stops logging after a few seconds due to `_connection_waiter = deferred`

[haarp]

Description

Hello!

On a mostly fresh install of Matrix synapse, when a logging handler is set up with class: synapse.logging.RemoteHandler, it stops sending logs from that handler a few seconds after starting. I can verify with tcpdump that no more packets are being sent.

After the startup log lines, I usually see one or two requests being processed, and then nothing forever.

Other handlers continue to log just fine.

Experimenting with Synapse's logger, I could trace this down to self._connection_waiter = deferred in synapse/logging/_remote.py. Commenting this line fixes the behavior, and logs arrive continuously.

Steps to reproduce

• Set up logging as shown in config
• Set up log receiver: nc -l -p 12401 -vv
• (Also set up package dump: tcpdump -i $interface port 12401)
• Start Synapse
• Observe a few seconds of logs, then silence

Homeserver

private

Synapse Version

1.111.0

Installation Method

Debian packages from packages.matrix.org

Database

PostgreSQL, single server, fresh with no porting or backup restores

Workers

I don't know

Platform

Running on Debian 12. Issue was observed with 1.95.1 from Debian's pkg repo aswell as 1.111.0 from packages.matrix.org's repo

Configuration

log.yaml:

version: 1
formatters:
  precise:
    format: '%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - %(request)s- %(message)s'
  journal_fmt:
    format: '%(name)s: [%(request)s] %(message)s'
  structured:
    class: synapse.logging.TerseJsonFormatter
filters:
  context:
    (): synapse.util.logcontext.LoggingContextFilter
    request: ""
handlers:
  file:
    class: logging.handlers.WatchedFileHandler
    formatter: precise
    filename: /var/log/matrix-synapse/homeserver.log
    filters: [context]
    level: DEBUG
    encoding: utf8
  console:
    class: logging.StreamHandler
    formatter: precise
    level: WARN
  journal:
    class: systemd.journal.JournalHandler
    formatter: journal_fmt
    filters: [context]
    level: WARN
    SYSLOG_IDENTIFIER: synapse
  graylog:
    class: synapse.logging.RemoteHandler
    formatter: structured
    filters: [context]
    level: DEBUG
    host: server.domain.tld
    port: 12401
loggers:
    twisted:
        level: WARN
    synapse:
        level: INFO
    synapse.metrics:
        level: WARN
    synapse.http.federation.well_known_resolver:
        level: WARN
    synapse.storage.TIME:
        level: WARN
    synapse.http.matrixfederationclient:
        level: WARN
root:
    level: INFO
    handlers: [file, journal, graylog]

Relevant log output

Nothing. Not even with `DEBUG` do the other log handlers mention anything about the RemoteHandler.

Anything else that would be useful to know?

Thanks!

[devonh]

Thank you for reporting this. Also - thank you for the very thorough and precise reproduction information. I was able to reproduce this very easily using the setup you described.

[devonh]

This seems like a more specific and more problematic occurrence of #16851. With the setup described in this issue all log lines are dropped after a few seconds whereas the other issues only reports some dropped log lines.