can't set logging to file

[julianuu]

I run synapse on arch linux. If I set handlers: [file] as follows in domain.name.log.config

version: 1
formatters:
  fmt:
    format: '%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - %(request)s- %(message)s'
filters:
  context:
    (): synapse.util.logcontext.LoggingContextFilter
    request: ""
handlers:
  # example output to console
  console:
    class: logging.StreamHandler
    filters: [context]
    level: INFO
  # example output to file - to enable, edit 'root' config below.
  file:
    class: logging.handlers.RotatingFileHandler
    formatter: fmt
    filename: /var/log/synapse/homeserver.log
    maxBytes: 100000000
    backupCount: 10
    filters: [context]
    level: INFO
root:
    handlers: [file] # to use file handler instead, switch to [file]

loggers:
    synapse:
        level: INFO
    synapse.storage.SQL:
        # beware: increasing this to DEBUG will make synapse log sensitive
        # information such as access tokens.
        level: INFO
    # example of enabling debugging for a component:
    #
    # synapse.federation.transport.server:
    #    level: DEBUG

synapse doesn't seem to work, and the log explodes with entries like

Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]     main()
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]   File "/usr/lib/python3.9/site-packages/synapse/app/homeserver.py", line 508, in main
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]     run(hs)
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]   File "/usr/lib/python3.9/site-packages/synapse/app/homeserver.py", line 492, in run
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]     _base.start_reactor(
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]   File "/usr/lib/python3.9/site-packages/synapse/app/_base.py", line 133, in start_reactor
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]     run()
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]   File "/usr/lib/python3.9/site-packages/synapse/app/_base.py", line 117, in run
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]     run_command()
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]   File "/usr/lib/python3.9/site-packages/twisted/internet/base.py", line 1283, in run
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]     self.mainLoop()
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]   File "/usr/lib/python3.9/site-packages/twisted/internet/base.py", line 1292, in mainLoop
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]     self.runUntilCurrent()
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]   File "/usr/lib/python3.9/site-packages/synapse/metrics/__init__.py", line 548, in f
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]     ret = func(*args, **kwargs)
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]   File "/usr/lib/python3.9/site-packages/twisted/internet/base.py", line 886, in runUntilCurrent
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]     f(*a, **kw)
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]   File "/usr/lib/python3.9/site-packages/twisted/internet/defer.py", line 460, in callback
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]     self._startRunCallbacks(result)
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]   File "/usr/lib/python3.9/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]     self._runCallbacks()
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]   File "/usr/lib/python3.9/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]     current.result = callback(current.result, *args, **kw)
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]   File "/usr/lib/python3.9/site-packages/twisted/internet/defer.py", line 1475, in gotResult

Earlier I had suffered from #4240.

[julianuu]

accidentally posted twice