Skip to content

Apagar dentro del tiempo que systemd concede - #36

Merged
Isma-L154 merged 1 commit into
mainfrom
arreglo-apagado-issue-35
Sep 12, 2026
Merged

Isma-L154 merged 1 commit into
mainfrom
arreglo-apagado-issue-35

Conversation

@Isma-L154

Copy link
Copy Markdown
Owner

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-upgrades de las
05:00, mientras escribía este arreglo.

La causa es aritmética, no una carrera

05:00:00  Stopping loopify-bot.service...
05:00:15  State 'stop-sigterm' timed out. Killing.     <- 15 s exactos
05:00:15  Main process exited, code=killed, status=9/KILL
05:00:15  Triggering OnFailure= dependencies.

Client.close() desconecta cada voice client, y discord.py reutiliza el
timeout de conexión como plazo para que Discord confirme la salida
:

# discord/voice_state.py:544
await asyncio.wait_for(self._disconnected.wait(), timeout=self.timeout)
cogs/music.py conectaba con timeout=20
self.timeout en VoiceConnectionState 20 s
TimeoutStopSec del unit 15 s

20 > 15. systemd mataba un apagado que iba a terminar, cinco segundos antes
de tiempo.

Y como todo ocurre dentro del async with bot, el except KeyboardInterrupt
nunca 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:

  • Trabajo en vuelo en el executor — no había; el bot no registra nada
    mientras reproduce, así que "sin logs" no significaba idle.
  • El daemon-reload del despliegue — aislado como única variable: apagado
    limpio.
  • El estado de reproducción completo — reproducido fielmente en el propio
    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 que
close() pueda esperarla sin límite. Además convierte SIGINT/SIGTERM en un
evento en vez de dejarlos como KeyboardInterrupt, para que el teardown corra
como código normal y no durante el desenrollado de una excepción — donde
cualquier await posterior en una tarea cancelada lanza al instante y se salta
la limpieza.

2. TimeoutStopSec pasa a 30, por encima del timeout de conexión. Incluso
en 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.py lee TimeoutStopSec del script de despliegue y afirma
que supera VOICE_CONNECT_TIMEOUT. Antes de cambiar el unit fallaba así:

assert unit_setting("TimeoutStopSec") > VOICE_CONNECT_TIMEOUT
AssertionError: assert 15.0 > 20.0

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.py

Verificado en el servidor con un voice client que nunca confirma:

[ 0.30s] --- SIGTERM (lo que manda systemd) ---
[ 0.30s]   voice.disconnect() llamado -> se cuelga para siempre
         Voice disconnect did not confirm in 5s; abandoning it
[ 5.31s] serve() retorno. voice.forced=True
[ 5.31s] PROCESO SALIENDO

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:

# En Discord: !play <algo>, dejarlo sonando
sudo systemctl restart loopify-bot
journalctl -u loopify-bot -n 15 --no-pager
# debe aparecer "Shutting down (KeyboardInterrupt)" y "Deactivated successfully",
# NO "result 'timeout'" ni status=9/KILL

Aparte

El log de producción destapó además que !lyrics está roto y lo estaba desde
antes de todo esto: lyricsgenius==3.12.2 no acepta el argumento quiet que le
pasa services/lyrics_api.py, así que cada búsqueda lanza TypeError. Solo se
volvió visible al cambiar el print() por logging en el #32. Va en su propio
issue, no aquí.

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
@Isma-L154
Isma-L154 merged commit a816547 into main Sep 12, 2026
3 checks passed
@Isma-L154
Isma-L154 deleted the arreglo-apagado-issue-35 branch September 12, 2026 05:08
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant