De-duplicate and parameterize exit error logging. #3057
Conversation
The signal log message had the PID and signal in the message format string, which makes each message unique. This is awkward in log processing with for example Sentry, where you want to see similar messages grouped together. The exit message was emitted twice, from the "if exitcode != 0" and the "if exitcode > 0" clause. You would be seeing things like: [2023-08-17 09:50:10 +0200] [66450] [ERROR] Worker (pid:66451) exited with code 1 [2023-08-17 09:50:10 +0200] [66450] [ERROR] Worker (pid:66451) exited with code 1.
|
I like this change. Are we abble to create a test for it? |
Something like a logging class in dummy application in test_arbiter.py that captures log messages? I was assuming that arbiter.stop() hits these changes, but instead only reap_workers() hits this. |
|
There's also PR 3094. #3094, which is related and prevents "operator confusion" so to say. |
| if exitcode != 0: | ||
| self.log.error('Worker (pid:%s) exited with code %s', wpid, exitcode) | ||
| self.log.error("Child exited with code %s (pid: %s)", |
There was a problem hiding this comment.
we should use "Worker" instead of "Child" here. This is more meaningful in the context of Gunicorn arbitration.
There was a problem hiding this comment.
Hi Benoit,
Sorry, I totally missed that I committed to this open PR! That was not my intention. I'll have a look what happened before and what I want from these changes. My intent was to lower the log level on the regular reload/sigterms. And the two raises in between the log statements were irksome to me.
What I find confusing that both master and worker are logging the same event, with the same wording. In the logs it's not clear which process is which.
| # 0: as seen from macos/py311 from reload on workers | ||
| # where workers from SIGTERM but waitpid/nohang gives | ||
| # me 0. | ||
| self.log.info("Child terminated (pid: %s)", wpid) |
| @@ -522,37 +522,40 @@ def reap_workers(self): | |||
| # A worker was terminated. If the termination reason was | |||
| # that it could not boot, we'll shut it down to avoid | |||
| # infinite start/stop cycles. | |||
| exitcode = status >> 8 | |||
|
|
|||
| exitcode = os.WEXITSTATUS(status) \ | |||
There was a problem hiding this comment.
I was trying to find out why I was/am seeing 0 on worker reload, where I was expecting to see 15 for SIGTERM. I was hoping that this might give me more, but clearly 0 stays 0.
| wpid, sig_name) | ||
|
|
||
| # Additional hint for SIGKILL | ||
| if status == signal.SIGKILL: |
There was a problem hiding this comment.
we miss this extra hint in the change. Could you add it?
There was a problem hiding this comment.
You miss the hint? I thought it was misleading because it never is a memory issue whenever we get to see these error logs.
The signal log message had the PID and signal in the message format string, which makes each message unique. This is awkward in log processing with for example Sentry, where you want to see similar messages grouped together.
The exit message was emitted twice, from the "if exitcode != 0" and the "if exitcode > 0" clause. You would be seeing things like:
See issue #3056