Skip to content
This repository has been archived by the owner on Apr 26, 2024. It is now read-only.

cant set logging to file #9100

Closed
julianuu opened this issue Jan 13, 2021 · 5 comments
Closed

cant set logging to file #9100

julianuu opened this issue Jan 13, 2021 · 5 comments

Comments

@julianuu
Copy link

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.
@richvdh
Copy link
Member

richvdh commented Jan 13, 2021

can you include more context from the log output? you've missed out the actual error message.

@julianuu
Copy link
Author

oh, sorry.

Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error] --- Logging error ---
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error] Traceback (most recent call last):
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 1418, in _inlineCallbacks
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]     result = g.send(result)
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error] StopIteration
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging:
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error] During handling of the above exception, another exception occurred:
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging:
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error] Traceback (most recent call last):
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/logging/handlers.py", line 74, in emit
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]     self.doRollover()
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/logging/handlers.py", line 172, in doRollover
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]     os.remove(dfn)
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error] PermissionError: [Errno 13] Permission denied: '/var/log/synapse/homeserver.log.10'
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging:
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error] During handling of the above exception, another exception occurred:
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging:
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error] Traceback (most recent call last):
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/logging/handlers.py", line 74, in emit
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]     self.doRollover()
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/logging/handlers.py", line 172, in doRollover
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]     os.remove(dfn)
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error] PermissionError: [Errno 13] Permission denied: '/var/log/synapse/homeserver.log.10'
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error] Call stack:
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/runpy.py", line 197, in _run_module_as_main
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]     return _run_code(code, main_globals, None,
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/runpy.py", line 87, in _run_code
Jan 13 15:35:44 wg-server synapse[82816]: logging during logging: 2021-01-13T15:35:44+0100 [stderr#error]     exec(code, run_globals)
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 512, in <module>
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

There is much more above still

@julianuu
Copy link
Author 

[wg@wg-server ~]$ ls -la /var/log/synapse/
total 1126452
drwxr-xr-x  2 root    root         4096 Jan 16  2020 .
drwxr-xr-x 15 root    root         4096 Jan  1 00:00 ..
-rw-r--r--  1 synapse synapse 104857589 Jan 16  2020 homeserver.log
-rw-r--r--  1 synapse synapse 104857580 Jan 10  2020 homeserver.log.1
-rw-r--r--  1 synapse synapse 104857563 Nov 14  2019 homeserver.log.10
-rw-r--r--  1 synapse synapse 104857447 Jan  6  2020 homeserver.log.2
-rw-r--r--  1 synapse synapse 104857266 Dec 26  2019 homeserver.log.3
-rw-r--r--  1 synapse synapse 104857412 Dec 20  2019 homeserver.log.4
-rw-r--r--  1 synapse synapse 104857445 Dec 15  2019 homeserver.log.5
-rw-r--r--  1 synapse synapse 104857397 Dec 10  2019 homeserver.log.6
-rw-r--r--  1 synapse synapse 104857573 Dec  3  2019 homeserver.log.7
-rw-r--r--  1 synapse synapse 104857411 Nov 27  2019 homeserver.log.8
-rw-r--r--  1 synapse synapse 104857455 Nov 21  2019 homeserver.log.9

@richvdh
Copy link
Member

richvdh commented Jan 13, 2021 •
edited

looks like the synapse user doesn't have permission to write to that directory, so can't rotate the files. try chown synapse /var/log/synapse.

@julianuu
Copy link
Author

You are right, it works. Sorry about that.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@richvdh @julianuu