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

Logging loop after SIGHUP when a StreamHandler is configured #6550

Open
richvdh opened this issue Dec 14, 2019 · 5 comments
Open

Logging loop after SIGHUP when a StreamHandler is configured #6550

richvdh opened this issue Dec 14, 2019 · 5 comments
Labels
A-Logging Synapse's logs (structured or otherwise). Not metrics. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues.

Comments

@richvdh
Copy link
Member

richvdh commented Dec 14, 2019

If you use the default logging config, which has a StreamHandler pointing at sys.stderr, and do not set --no-redirect-stdio, then when you send synapse a SIGHUP, it will stack overflow and abort.

The problem appears to be that when you SIGHUP it, the streamhandler gets repointed at the redirected stderr, which goes back into a logger: so as soon as anything is logged, we get an infinite loop.

@richvdh
Copy link
Member Author

richvdh commented Dec 14, 2019

I thought this used to work, but I just tried the same thing on v0.20.0 (the version that introduced reloading the log config on SIGHUP) and it did the same.

@richvdh
Copy link
Member Author

richvdh commented Dec 14, 2019

This seems like yet another reason that redirecting stdio is a terrible idea, and we should implement #1539 (comment).

@neilisfragile neilisfragile added z-bug (Deprecated Label) z-p2 (Deprecated Label) A-Logging Synapse's logs (structured or otherwise). Not metrics. labels Dec 17, 2019
@richvdh richvdh changed the title Stack overflow on SIGHUP with default logging config Stack overflow on SIGHUP when a StreamHandler is configured Jan 8, 2020
@richvdh
Copy link
Member Author

richvdh commented Jan 8, 2021

(the default logging config no longer has a StreamHandler pointing at sys.stderr, but plenty of peoples' logging configs do have that setup)

@richvdh
Copy link
Member Author

richvdh commented Jun 10, 2021

as of #8268, you no longer get a stack overflow, but you do get logging that looks like this:

logging during logging: 2021-06-10T14:34:07+0100 [stderr#error] 2021-06-10 14:34:07,796 - twisted - 258 - ERROR - sentinel - 2021-06-10 14:34:07,796 - synapse.metrics - 596 - DEBUG - sentinel - Collecting gc 0

It's worth noting that this (logs-to-stderr plus redirect-stdio-to-logs) is the default configuration for the docker image.

@richvdh richvdh changed the title Stack overflow on SIGHUP when a StreamHandler is configured Logging loop after SIGHUP when a StreamHandler is configured Jun 10, 2021
@richvdh
Copy link
Member Author

richvdh commented Jun 10, 2021

(a StreamHandler is no longer the default for the non-docker case as of #8040)

@richvdh richvdh added T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues. and removed z-bug (Deprecated Label) z-p2 (Deprecated Label) labels Jun 10, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
A-Logging Synapse's logs (structured or otherwise). Not metrics. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues.
Projects
None yet
Development

No branches or pull requests

2 participants