Apagar dentro del tiempo que systemd concede - #36
Merged
Merged
Conversation
A restart of a bot that had joined a voice channel timed out, got SIGKILLed and
tripped the OnFailure alert. It happened on the 04:08 deploy and again on the
05:00 unattended-upgrade reboot, both times at exactly 15 seconds:
05:00:00 Stopping loopify-bot.service...
05:00:15 State 'stop-sigterm' timed out. Killing.
The cause is arithmetic, not a race. `Client.close()` disconnects every voice
client, and discord.py reuses the *connect* timeout as the deadline for Discord
to confirm the departure:
# discord/voice_state.py
await asyncio.wait_for(self._disconnected.wait(), timeout=self.timeout)
This bot connects with `timeout=20` and the unit allowed `TimeoutStopSec=15`, so
systemd killed a shutdown that was going to finish, five seconds early. And
because all of it runs inside `async with bot`, the `except KeyboardInterrupt`
handler was never reached — which is why no shutdown line was ever logged, the
detail that made this look like a hang rather than a wait.
A bot that never joined voice has no voice client to wait on. That is why every
other shutdown looked clean, and why an isolated reproduction of the full
playback pipeline — yt-dlp blocked on a full pipe, FFmpeg mid-stream, the
read-ahead thread live — exits instantly: it has no VoiceClient.
Two changes, each covering the other's gap:
- `serve()` releases voice itself, five seconds per client, before `close()` can
wait it out. It also turns SIGINT/SIGTERM into an event rather than leaving
them as a KeyboardInterrupt, so the teardown runs as ordinary code instead of
during exception unwinding, where every further await in a cancelled task
raises immediately and skips the cleanup.
- `TimeoutStopSec` goes to 30, above the connect timeout. Even on a path that
skips the bounded teardown, systemd now waits rather than SIGKILLing — and a
SIGKILL is what skipped the child reaping that killing FFmpeg and yt-dlp
depends on. A clean stop still takes milliseconds; this is only the ceiling.
`tests/test_shutdown.py` enforces the arithmetic that was wrong: it reads
`TimeoutStopSec` out of the deploy script and asserts it exceeds
`VOICE_CONNECT_TIMEOUT`. That test failed with `assert 15.0 > 20.0` before the
unit changed, which is the bug stated as a number.
The signal path is POSIX-only and is the one production actually uses, so it has
its own test rather than being left to the injected-event path the others use.
Verified on the server: a voice client that never confirms is abandoned after 5s
and the process exits at 5.3s, against the 20s that was getting it killed.
Tests: 332, up from 319 — 331 plus the POSIX-only signal test, which skips on Windows.
Closes #35
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Cierra #35.
332 tests (antes 319). Causa raíz confirmada con evidencia de producción: el
fallo se reprodujo solo durante el reinicio de
unattended-upgradesde las05:00, mientras escribía este arreglo.
La causa es aritmética, no una carrera
Client.close()desconecta cada voice client, y discord.py reutiliza eltimeout de conexión como plazo para que Discord confirme la salida:
cogs/music.pyconectaba contimeout=20self.timeoutenVoiceConnectionStateTimeoutStopSecdel unit20 > 15. systemd mataba un apagado que iba a terminar, cinco segundos antes
de tiempo.
Y como todo ocurre dentro del
async with bot, elexcept KeyboardInterruptnunca se alcanzaba — por eso no había línea de apagado en el log, el detalle
que hacía que esto pareciera un cuelgue en vez de una espera.
Por qué costó encontrarlo
Un bot que nunca entró a un canal de voz no tiene voice client que esperar. Eso
explica por qué todos los demás apagados parecían limpios, y descartó tres
hipótesis por el camino:
mientras reproduce, así que "sin logs" no significaba idle.
daemon-reloaddel despliegue — aislado como única variable: apagadolimpio.
servidor (yt-dlp bloqueado sobre tubería llena, FFmpeg a medias, el hilo de
read-ahead vivo, los 5 hilos presentes) y sale al instante. Justamente
porque no tiene
VoiceClient.Esa última falsificación fue la que señaló el sitio correcto.
El arreglo, en dos partes que se cubren mutuamente
1.
serve()libera la voz él mismo, 5 s por cliente, antes de queclose()pueda esperarla sin límite. Además convierte SIGINT/SIGTERM en unevento en vez de dejarlos como
KeyboardInterrupt, para que el teardown corracomo código normal y no durante el desenrollado de una excepción — donde
cualquier
awaitposterior en una tarea cancelada lanza al instante y se saltala limpieza.
2.
TimeoutStopSecpasa a 30, por encima del timeout de conexión. Inclusoen un camino que se salte el teardown acotado, systemd ahora espera en vez de
mandar SIGKILL — y el SIGKILL era justamente lo que se saltaba la cosecha de
hijos de la que dependen los issues #6 y #15. Un apagado limpio sigue tardando
milisegundos; esto es solo el techo.
El test que fija la aritmética
tests/test_shutdown.pyleeTimeoutStopSecdel script de despliegue y afirmaque supera
VOICE_CONNECT_TIMEOUT. Antes de cambiar el unit fallaba así:Es el bug enunciado como un número, y ata el código a la configuración de
despliegue para que no puedan volver a divergir en silencio.
El camino de las señales es POSIX-only y es el que usa producción, así que
tiene su propio test en vez de quedar cubierto solo por el evento inyectado que
usan los demás.
Cómo probarlo
pytest # 332 (331 + el de señales, que se salta en Windows) pytest tests/test_shutdown.pyVerificado en el servidor con un voice client que nunca confirma:
5,31 s frente a los 20 s que lo hacían morir. El SIGTERM no mató el proceso, lo
que prueba que el handler quedó instalado.
Prueba definitiva tras desplegar — hay que estar en un canal de voz, es la
condición que importa:
Aparte
El log de producción destapó además que
!lyricsestá roto y lo estaba desdeantes de todo esto:
lyricsgenius==3.12.2no acepta el argumentoquietque lepasa
services/lyrics_api.py, así que cada búsqueda lanzaTypeError. Solo sevolvió visible al cambiar el
print()porloggingen el #32. Va en su propioissue, no aquí.