Error instead of warning in logs when sending SIGTERM since v21

[feliixx]

Hi @benoitc,

Thanks a lot for all the work you've done on Gunicorn!

We recently upgraded from version 20.1.0 to 21.2.0 and noticed in our logs when restarting our application that a warning has been replaced by an error when sending SIGTERM to a worker:

version 20.1.0:

systemd: Stopping App...
app: gunicorn WARNING Worker with pid 2542594 was terminated due to signal 15
app: gunicorn INFO Handling signal: term
app: gunicorn INFO Worker exiting (pid: 2542537)
app: gunicorn INFO Worker exiting (pid: 2542545)
app: gunicorn INFO Shutting down: Master
systemd: Stopped App.
systemd: Started App.

version 21.2.0:

systemd: Stopping App...
app: gunicorn ERROR Worker (pid:1340527) was sent SIGTERM!
app: gunicorn INFO Handling signal: term
app: gunicorn INFO Worker exiting (pid: 1340420)
app: gunicorn INFO Worker exiting (pid: 1340424)
app: gunicorn INFO Shutting down: Master
systemd: Stopped App.
systemd: Started App.

This is a bit annoying for us as we carefully monitor any error sent by our app, and this seems to be a false positive.

The commits introducing this change are 76f8da2 and 28df992, however it's not clear from the commit messages why the log level was changed. The documentation about signals does say that sending SIGTERM is the proper way to do a graceful shutdown.

Is it possible to change the log level back to warning, at least for SIGTERM? We'll be happy to send a PR if you agree.

[Venture200]

Hello, any update on this ?

[pauljeannot]

Hello, also effected by this issue. Any update on this ?

[feliixx]

For other people affected by this: we've managed to sidestep the issue by using KillMode=mixed in our systemd service config:

[Service]
KillMode=mixed
...

We've been using this config in production for over a year with Gunicorn 21.2.0 and above without issues.

[pauljeannot]

For my understanding, using KillMode=mixed means that while the master process receives SIGTERM for a graceful shutdown, the workers are immediately sent a SIGKILL, which prevents them from completing any pending tasks or writing logs (so no false positive in your monitoring).

Am I right?

[feliixx]

For my understanding, using KillMode=mixed means that while the master process receives SIGTERM for a graceful shutdown, the workers are immediately sent a SIGKILL, which prevents them from completing any pending tasks or writing logs

Exactly. As you noted, that's not ideal as the worker won't shutdown gracefully but instead are immediately killed, so it might be problematic in some cases.

[benoitc]

the log level is indeed wrong. This will be fixed in coming release

[pauljeannot]

@benoitc Thanks! I just opened a PR for it, if it can help.

[sylt]

I'm gonna go against the stream here, but I honestly don't think the log level is wrong. Instead, I think we should ask: Why do we even hit this trace/code path from the beginning? If SIGTERM is caught by the worker as a mean of doing a graceful shutdown (meaning the worker should exit normally with exit code 0), why are we executing a code path for handling workers terminated by a signal? I would argue that if the worker exited normally, we shouldn't even be in that code path.

I've tried to address what I consider to be the root cause in #3312. It's more intricate than changing the log level of course, but I think it's more correct. The benefit of keeping the log level as is would be that other signals (such as e.g. SIGSEGV and SIGKILL) are logged as errors.