Synapse OOMs when no loggers use the logcontext filter

[jrick]

I am trying to make synapse only log to stdout/err (which is then collected by a service manager and saved) and remove all of the file logging since it is redundant. I am using 0.19.0 on centos and currently using this for my log config:

version: 1

formatters:
  precise:
   format: '%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - %(request)s- %(message)s'

filters:
  context:
    (): synapse.util.logcontext.LoggingContextFilter
    request: ""

handlers:
  file:
    class: logging.handlers.RotatingFileHandler
    formatter: precise
    filename: /dev/null
    maxBytes: 104857600
    backupCount: 10
    filters: [context]
    level: INFO
  console:
    class: logging.StreamHandler
    formatter: precise
    level: INFO

loggers:
    synapse:
        level: INFO

    synapse.storage.SQL:
        level: INFO

root:
    level: INFO
    handlers: [file, console]

If I remove the file handler from the handlers at the bottom of the config, synapse core dumps on startup after about a 2-3 second delay. I can remove console or even remove both handlers without crashing the program, but if i remove file and only leave console, i see the crash.

As a temporary workaround as you can see I have changed the file logger to log to /dev/null but this is not a great solution.

I'm not sure if the core dump is of any use since symbols are stripped from my python install, otherwise i would provide a backtrace here.

[jrick]

Logs from journalctl:

Feb 05 02:18:14 acff5732-3641-6795-ea9f-ec1b48e22d91 systemd[17292]: Started Matrix Synapse homeserver.
Feb 05 02:18:14 acff5732-3641-6795-ea9f-ec1b48e22d91 systemd[17292]: Starting Matrix Synapse homeserver...
Feb 05 02:18:14 acff5732-3641-6795-ea9f-ec1b48e22d91 polkitd[17445]: Unregistered Authentication Agent for unix-process:20128:16400800 (system bus name :1.134, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8) (disconnected from bus)
Feb 05 02:18:23 acff5732-3641-6795-ea9f-ec1b48e22d91 systemd[17292]: synapse.service: main process exited, code=dumped, status=7/BUS
Feb 05 02:18:23 acff5732-3641-6795-ea9f-ec1b48e22d91 systemd[17292]: Unit synapse.service entered failed state.
Feb 05 02:18:23 acff5732-3641-6795-ea9f-ec1b48e22d91 systemd[17292]: synapse.service failed.

I also failed to mention in the original issue but this is actually a lx branded zone on smartos running a centos image, in case that matters at all (there is no linux kernel, this is all running directly on top of the illumos kernel).

[qbit]

I attempted the same thing on my Debian Jessie box:

Feb 04 19:17:33 vm.bolddaemon.com kernel: Out of memory: Kill process 12133 (python) score 868 or sacrifice child                                                                               
Feb 04 19:17:33 vm.bolddaemon.com kernel: Killed process 12133 (python) total-vm:4737124kB, anon-rss:2888196kB, file-rss:1704kB                                                                 
Feb 04 19:17:33 vm.bolddaemon.com systemd[1]: matrix-synapse.service: main process exited, code=killed, status=9/KILL                                                                           
Feb 04 19:17:34 vm.bolddaemon.com systemd[1]: Unit matrix-synapse.service entered failed state

It started fine initially, but then went into a restart loop with the above messages in the log.

[schnuffle]

I'm using following log config on centos7, which works for me. You need to remove the file handler completly

version: 1

formatters:
  precise:
   format: '%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - %(request)s- %(message)s'

filters:
  context:
    (): synapse.util.logcontext.LoggingContextFilter
    request: ""

handlers:
  console:
    class: logging.StreamHandler
    formatter: precise
    filters: [context]

loggers:
    synapse:
        level: DEBUG

    synapse.storage.SQL:
        level: DEBUG

root:
    level: DEBUG
    handlers: [console]

I remember having had a config, where I only dropped the file handler from the root section but kept it in the handler section. That leaded to synapse eating up all memory.

[jrick]

Thanks for the suggestion. I removed the file section and it was still crashing from OOM. Went back and looked at what might be different between my and your configs, and noticed that yours added the context filter, so I went ahead and added that and it runs fine now.

Leaving this open since it still seems like a bug.

[schnuffle]

Have you tried to delete the context section when not using it?
Like I had to delete the file handler when not using it.

Seemed strange to me as well, already getting into big trouble only by trying to find a good log config.

I would do a quick check but for the moment I'm chasing my own synapse leaking FDs :) and don't want to restart

Reading Python Log Config and Good logging pratice in python seems to indicate that the log config shall only contain definitions that are used.

[lsowen]

I think you can fix this is one of two ways:

1. Add the filters: [context] element to one or more logging handlers (eg the console handler if you remove the file handler); or
2. Change the format to remove the %(request)s field

[Aster-the-Med-Stu]

How about adding instructions on setting logging levels to Readme? Now I have to read multiple issues to figure out how to change Matrix Synapse's log level... Besides, the default setting of Matrix Synapse would flood system's log with tons of synapse's though Matrix Synapse has its separate log file. #3171

[aaronraimist]

@Aster-the-Med-Stu A pull request is always welcome if you have suggested wording.