Skip to content

Commit b309c93

Browse files
allanrmartinsallanrmartins
authored
fix(idlewatch): sentinela em thread Python, sem o watchdog em C do faulthandler (#194) (#195)
O job test-macos pendurava dentro de faulthandler.cancel_dump_traceback_later: a thread em C do dump_traceback_later percorre os frames das outras threads sem o GIL e, no macOS arm64, entra em loop infinito em dump_frame quando a thread principal esta executando Python (python/cpython#140815, corrigido so no 3.13/3.14). O cancel seguinte - chamado por todo batimento e pelo desarme da sentinela - esperava por essa thread para sempre. A sentinela passa a ser uma thread daemon em Python (mesmo desenho do watchdog da GUI): batimento = timestamp; passado idle_s sem bater, faulthandler.dump_traceback sincrono, com o GIL. Retratos repetem a cada idle_s parado; suspend/resume viram flags; o desarme so sinaliza e faz join com limite. Perde-se o retrato de um travamento que segure o GIL em C. Validacao no macOS: 200 rodadas do test_idlewatch + 3 suites completas sem travar (o codigo antigo travou 2x em menos de 120 rodadas). Claude-Session: https://claude.ai/code/session_01UBNe1aDCho3ub2JCvAcpWt
1 parent dd45e24 commit b309c93

2 files changed

Lines changed: 135 additions & 88 deletions

File tree

‎scriba/idlewatch.py‎

Lines changed: 76 additions & 58 deletions
Original file line numberDiff line numberDiff line change
@@ -6,20 +6,30 @@
66
vezes na mesma gravação) chegou sem nenhum rastro da causa: o process.log só
77
tem o que foi impresso ANTES da trava.
88
9-
Esta sentinela roda DENTRO do filho: `faulthandler.dump_traceback_later` é uma
10-
thread em C que despeja a pilha de TODAS as threads direto no fd quando o
11-
processo fica `idle_s` sem "bater" - funciona mesmo com o GIL preso num
12-
deadlock, que é exatamente o cenário que interessa. Batimentos: cada escrita no
13-
stdout (as linhas de progresso do process.log), cada mudança de estágio e cada
14-
bloco da diarização. O resumo (espera legítima de rede, sem CPU nem log) fica
15-
SUSPENSO - lá o watchdog do pai já respeita o timeout configurado.
9+
Esta sentinela roda DENTRO do filho: uma thread daemon (o mesmo desenho do
10+
watchdog da GUI, scriba/watchdog.py) confere a cada instante há quanto tempo o
11+
processo não "bate"; passado `idle_s`, despeja a pilha de TODAS as threads com
12+
`faulthandler.dump_traceback`. Batimentos: cada escrita no stdout (as linhas de
13+
progresso do process.log), cada mudança de estágio e cada bloco da diarização.
14+
O resumo (espera legítima de rede, sem CPU nem log) fica SUSPENSO - lá o
15+
watchdog do pai já respeita o timeout configurado.
16+
17+
Por que NÃO `faulthandler.dump_traceback_later` (#194): a thread em C dele
18+
percorre os frames das outras threads SEM o GIL, enquanto elas executam Python.
19+
No macOS arm64 isso trava a própria thread em C dentro do dump (reproduzido em
20+
CI: thread principal em recursão com exceções no instante do dump) e o
21+
`cancel_dump_traceback_later` seguinte - que todo batimento e o desarme
22+
chamavam - espera por ela para sempre, pendurando o processo inteiro. O dump
23+
síncrono roda COM o GIL: nenhuma outra thread mexe em frames enquanto ele lê.
24+
O que se perde é o retrato de um travamento que segure o GIL em código C; esse
25+
caso segue coberto pelo encerramento do pai, só sem as pilhas.
1626
1727
O dump vai para `hang.log` NA PASTA DA REUNIÃO, nunca para o process.log: o
1828
tamanho do process.log é um dos sinais de vida que o pai sonda, e escrever nele
19-
adiaria (ou anularia, com `repeat`) o encerramento do filho travado. Com
20-
`repeat=True` saem dois retratos (8 e 16 min parado) antes do pai agir: pilhas
21-
iguais = travado; diferentes = lentidão extrema. O arquivo só fica na pasta se
22-
houve dump; sem dump ele é removido no desarme.
29+
adiaria (ou anularia) o encerramento do filho travado. Parado de vez, saem
30+
retratos a cada `idle_s` (8 e 16 min) antes do pai agir: pilhas iguais =
31+
travado; diferentes = lentidão extrema. O arquivo só fica na pasta se houve
32+
dump; sem dump ele é removido no desarme.
2333
"""
2434

2535
from __future__ import annotations
@@ -37,12 +47,13 @@
3747

3848
IDLE_S = 8 * 60 # sem batimento por tanto tempo = despeja as pilhas
3949
HANG_LOG = "hang.log" # na pasta da reunião (o do app, em logs/, é o da GUI)
40-
_MIN_REARM_S = 1.0 # cada rearme cria uma thread em C; batidas mais miúdas são coalescidas
50+
_POLL_S = 1.0 # cadência máxima da conferência (mais fina com idle_s curto)
51+
_JOIN_S = 2.0 # quanto o desarme espera a thread da sentinela encerrar
4152

4253

4354
class _State:
4455
__slots__ = ("folder", "path", "file", "idle_s", "header_end", "suspended",
45-
"last_arm", "prev_stdout")
56+
"last_beat", "prev_stdout", "stop", "thread", "retratos")
4657

4758
def __init__(self, folder: Path, path: Path, file, idle_s: float, header_end: int,
4859
prev_stdout) -> None:
@@ -52,8 +63,11 @@ def __init__(self, folder: Path, path: Path, file, idle_s: float, header_end: in
5263
self.idle_s = idle_s
5364
self.header_end = header_end
5465
self.suspended = False
55-
self.last_arm = 0.0
66+
self.last_beat = time.monotonic()
5667
self.prev_stdout = prev_stdout
68+
self.stop = threading.Event()
69+
self.thread: threading.Thread | None = None
70+
self.retratos = 0
5771

5872

5973
_lock = threading.Lock()
@@ -77,9 +91,33 @@ def __getattr__(self, name):
7791
return getattr(self._s, name)
7892

7993

80-
def _schedule(st: _State) -> None:
81-
faulthandler.dump_traceback_later(st.idle_s, repeat=True, file=st.file, exit=False)
82-
st.last_arm = time.monotonic()
94+
def _dump_locked(st: _State, parado_s: float) -> None:
95+
"""(thread da sentinela, com _lock e o GIL) Cabeçalho + pilhas de todas as threads."""
96+
st.retratos += 1
97+
limiar = f"{parado_s / 60:.0f} min" if parado_s >= 60 else f"{parado_s:.1f} s"
98+
st.file.write(f"==== {datetime.now():%d/%m/%Y %H:%M:%S} · {limiar} sem progresso "
99+
f"(retrato {st.retratos}) ====\n")
100+
st.file.flush() # o faulthandler escreve direto no fd: o cabeçalho tem que ir antes
101+
faulthandler.dump_traceback(file=st.file, all_threads=True)
102+
st.file.flush()
103+
104+
105+
def _monitor(st: _State) -> None:
106+
poll = max(0.02, min(_POLL_S, st.idle_s / 4))
107+
while not st.stop.wait(poll):
108+
with _lock:
109+
if _state is not st:
110+
return
111+
if st.suspended:
112+
continue
113+
parado = time.monotonic() - st.last_beat
114+
if parado < st.idle_s:
115+
continue
116+
try:
117+
_dump_locked(st, parado)
118+
except Exception:
119+
log.debug("sentinela: dump falhou", exc_info=True)
120+
st.last_beat = time.monotonic() # próximo retrato só após mais idle_s parado
83121

84122

85123
def arm(folder, idle_s: float | None = None) -> bool:
@@ -93,7 +131,7 @@ def arm(folder, idle_s: float | None = None) -> bool:
93131
with _lock:
94132
if _state is not None:
95133
if _state.folder == folder:
96-
_beat_locked(_state)
134+
_state.last_beat = time.monotonic()
97135
return True
98136
_disarm_locked(None)
99137
try:
@@ -110,7 +148,9 @@ def arm(folder, idle_s: float | None = None) -> bool:
110148
if prev_stdout is not None and not isinstance(prev_stdout, _BeatingStream):
111149
sys.stdout = _BeatingStream(prev_stdout)
112150
st = _State(folder, path, f, float(idle_s), header_end, prev_stdout)
113-
_schedule(st)
151+
st.thread = threading.Thread(target=_monitor, args=(st,), daemon=True,
152+
name="scriba-idlewatch")
153+
st.thread.start()
114154
except Exception:
115155
f.close()
116156
raise
@@ -121,51 +161,28 @@ def arm(folder, idle_s: float | None = None) -> bool:
121161
return True
122162

123163

124-
def _beat_locked(st: _State) -> None:
125-
if st.suspended:
126-
return
127-
if time.monotonic() - st.last_arm < _MIN_REARM_S:
128-
return
129-
try:
130-
_schedule(st)
131-
except Exception:
132-
log.debug("sentinela: rearme falhou", exc_info=True)
133-
134-
135164
def beat() -> None:
136-
"""Sinal de vida (thread-safe, barato quando bate mais de uma vez por segundo)."""
165+
"""Sinal de vida (thread-safe e barato: um timestamp, sem lock nem thread nova)."""
137166
st = _state
138-
if st is None:
139-
return
140-
with _lock:
141-
if _state is st:
142-
_beat_locked(st)
167+
if st is not None:
168+
st.last_beat = time.monotonic()
143169

144170

145171
def suspend() -> None:
146172
"""Pausa a sentinela: espera legítima sem CPU nem log (o resumo via rede/CLI)."""
147173
with _lock:
148174
st = _state
149-
if st is None or st.suspended:
150-
return
151-
st.suspended = True
152-
try:
153-
faulthandler.cancel_dump_traceback_later()
154-
except Exception:
155-
pass
175+
if st is not None:
176+
st.suspended = True
156177

157178

158179
def resume() -> None:
159-
"""Volta a vigiar depois de `suspend()`."""
180+
"""Volta a vigiar depois de `suspend()`; o prazo conta a partir daqui."""
160181
with _lock:
161182
st = _state
162-
if st is None or not st.suspended:
163-
return
164-
st.suspended = False
165-
try:
166-
_schedule(st)
167-
except Exception:
168-
log.debug("sentinela: rearme após suspensão falhou", exc_info=True)
183+
if st is not None and st.suspended:
184+
st.suspended = False
185+
st.last_beat = time.monotonic()
169186

170187

171188
def dumped() -> bool:
@@ -180,16 +197,13 @@ def dumped() -> bool:
180197
return False
181198

182199

183-
def _disarm_locked(note: str | None) -> None:
200+
def _disarm_locked(note: str | None) -> _State | None:
184201
global _state
185202
st = _state
186203
if st is None:
187-
return
204+
return None
188205
_state = None
189-
try:
190-
faulthandler.cancel_dump_traceback_later()
191-
except Exception:
192-
pass
206+
st.stop.set()
193207
if isinstance(sys.stdout, _BeatingStream):
194208
sys.stdout = st.prev_stdout
195209
houve_dump = False
@@ -209,11 +223,15 @@ def _disarm_locked(note: str | None) -> None:
209223
st.path.unlink(missing_ok=True)
210224
except OSError:
211225
pass
226+
return st
212227

213228

214229
def disarm(note: str | None = "o processo seguiu depois do dump: lentidão extrema, "
215230
"não travamento (o pai não precisou encerrá-lo)") -> None:
216231
"""Desliga a sentinela. Sem dump, o hang.log é removido; com dump, `note`
217232
é anexada para o leitor saber que o processo NÃO morreu ali."""
218233
with _lock:
219-
_disarm_locked(note)
234+
st = _disarm_locked(note)
235+
# o join fica FORA do _lock: a thread precisa dele para perceber o desarme
236+
if st is not None and st.thread is not None and st.thread is not threading.current_thread():
237+
st.thread.join(_JOIN_S)

‎tests/test_idlewatch.py‎

Lines changed: 59 additions & 30 deletions
Original file line numberDiff line numberDiff line change
@@ -1,15 +1,17 @@
1-
"""Sentinela de travamento do subprocesso (#188): faulthandler despeja as pilhas em
2-
hang.log na pasta da reunião quando o processo fica sem batimento; batimento
3-
(stdout/estágio/bloco) rearma; o resumo suspende; sem dump o arquivo some."""
1+
"""Sentinela de travamento do subprocesso (#188): a thread da sentinela despeja as
2+
pilhas em hang.log na pasta da reunião quando o processo fica sem batimento;
3+
batimento (stdout/estágio/bloco) adia; o resumo suspende; sem dump o arquivo some.
4+
Desde a #194 não há watchdog em C (faulthandler.dump_traceback_later): o dump é
5+
síncrono, com o GIL, na thread da sentinela."""
46

57
import io
68
import shutil
79
import sys
810
import tempfile
11+
import threading
912
import time
1013
import unittest
1114
from pathlib import Path
12-
from unittest import mock
1315

1416
sys.path.insert(0, str(Path(__file__).resolve().parents[1]))
1517

@@ -28,71 +30,98 @@ def tearDown(self):
2830
sys.stdout = self._stdout
2931
shutil.rmtree(self.tmp, ignore_errors=True)
3032

31-
def _wait_dump(self, path: Path, timeout: float = 5.0) -> str:
33+
def _wait_dump(self, path: Path, *needles: str, timeout: float = 5.0) -> str:
34+
"""Espera o hang.log conter TODOS os `needles` (default: um dump de thread).
35+
O dump é escrito aos poucos: ler o arquivo ao ver o primeiro pedaço e
36+
afirmar sobre o resto era a corrida da #194."""
37+
needles = needles or ("Thread",)
3238
fim = time.monotonic() + timeout
39+
txt = ""
3340
while time.monotonic() < fim:
3441
try:
3542
txt = path.read_text(encoding="utf-8", errors="replace")
3643
except OSError:
3744
txt = ""
38-
if "Thread" in txt or "Timeout" in txt:
45+
if all(n in txt for n in needles):
3946
return txt
4047
time.sleep(0.05)
41-
return path.read_text(encoding="utf-8", errors="replace") if path.exists() else ""
48+
return txt
49+
50+
def _sentinelas(self) -> list[threading.Thread]:
51+
return [t for t in threading.enumerate() if t.name == "scriba-idlewatch"]
4252

4353
def test_sem_batimento_despeja_pilhas_no_hang_log_da_pasta(self):
4454
self.assertTrue(idlewatch.arm(self.folder, idle_s=0.3))
4555
path = self.folder / "hang.log"
4656
self.assertTrue(path.exists())
47-
txt = self._wait_dump(path)
57+
txt = self._wait_dump(path, "Thread", "test_idlewatch", "in _monitor")
4858
self.assertIn("sentinela armada", txt)
49-
self.assertIn("Thread", txt) # o faulthandler despejou as pilhas
50-
self.assertIn("test_idlewatch", txt) # inclusive a desta thread (todas as threads)
59+
self.assertIn("sem progresso", txt) # cabeçalho do retrato
60+
self.assertIn("Thread", txt) # o faulthandler despejou as pilhas
61+
self.assertIn("test_idlewatch", txt) # inclusive a desta thread (todas as threads)
62+
self.assertIn("in _monitor", txt) # o dump sai da thread da sentinela (#194)
5163
self.assertTrue(idlewatch.dumped())
5264
idlewatch.disarm(note="processo seguiu")
5365
txt = path.read_text(encoding="utf-8", errors="replace")
5466
self.assertIn("processo seguiu", txt) # com dump, o arquivo FICA e ganha a nota
5567
self.assertFalse((self.folder / "process.log").exists()) # nunca escreve no process.log
5668

69+
def test_parado_de_vez_repete_o_retrato(self):
70+
idlewatch.arm(self.folder, idle_s=0.3)
71+
path = self.folder / "hang.log"
72+
txt = self._wait_dump(path, "(retrato 2)")
73+
self.assertIn("(retrato 1)", txt)
74+
self.assertIn("(retrato 2)", txt) # 8 e 16 min parado, na vida real
75+
5776
def test_batimentos_seguram_o_dump_e_sem_dump_o_arquivo_some(self):
58-
with mock.patch.object(idlewatch, "_MIN_REARM_S", 0.0): # a batida rearma já
59-
idlewatch.arm(self.folder, idle_s=0.5)
60-
fim = time.monotonic() + 1.5
61-
while time.monotonic() < fim:
62-
idlewatch.beat()
63-
time.sleep(0.1)
64-
self.assertFalse(idlewatch.dumped())
65-
idlewatch.disarm()
77+
idlewatch.arm(self.folder, idle_s=0.5)
78+
fim = time.monotonic() + 1.5
79+
while time.monotonic() < fim:
80+
idlewatch.beat()
81+
time.sleep(0.1)
82+
self.assertFalse(idlewatch.dumped())
83+
idlewatch.disarm()
6684
self.assertFalse((self.folder / "hang.log").exists())
6785

6886
def test_escrita_no_stdout_e_batimento(self):
69-
with mock.patch.object(idlewatch, "_MIN_REARM_S", 0.0):
70-
sys.stdout = io.StringIO()
71-
idlewatch.arm(self.folder, idle_s=0.5)
72-
fim = time.monotonic() + 1.5
73-
while time.monotonic() < fim:
74-
print("34 segmentos") # linha de progresso do process.log
75-
time.sleep(0.1)
76-
self.assertFalse(idlewatch.dumped())
77-
self.assertIn("34 segmentos", sys.stdout.getvalue()) # e a saída passa intacta
78-
idlewatch.disarm()
79-
self.assertIsInstance(sys.stdout, io.StringIO) # stdout restaurado no desarme
87+
sys.stdout = io.StringIO()
88+
idlewatch.arm(self.folder, idle_s=0.5)
89+
fim = time.monotonic() + 1.5
90+
while time.monotonic() < fim:
91+
print("34 segmentos") # linha de progresso do process.log
92+
time.sleep(0.1)
93+
self.assertFalse(idlewatch.dumped())
94+
self.assertIn("34 segmentos", sys.stdout.getvalue()) # e a saída passa intacta
95+
idlewatch.disarm()
96+
self.assertIsInstance(sys.stdout, io.StringIO) # stdout restaurado no desarme
8097

8198
def test_suspender_durante_o_resumo_nao_despeja(self):
8299
idlewatch.arm(self.folder, idle_s=0.3)
83100
idlewatch.suspend()
84101
time.sleep(0.8)
85102
self.assertFalse(idlewatch.dumped())
86103
idlewatch.resume()
87-
txt = self._wait_dump(self.folder / "hang.log")
104+
txt = self._wait_dump(self.folder / "hang.log", "Thread")
88105
self.assertIn("Thread", txt) # depois do resume volta a vigiar
89106

90107
def test_armar_de_novo_na_mesma_pasta_e_idempotente(self):
91108
idlewatch.arm(self.folder, idle_s=5)
92109
self.assertTrue(idlewatch.arm(self.folder, idle_s=5))
93110
self.assertIs(sys.stdout.__class__, idlewatch._BeatingStream) # embrulhado UMA vez
94111
self.assertIsNot(sys.stdout._s.__class__, idlewatch._BeatingStream)
112+
self.assertEqual(len(self._sentinelas()), 1) # e UMA thread
113+
idlewatch.disarm()
114+
115+
def test_desarme_encerra_a_thread_da_sentinela(self):
116+
# #194: nada de thread em C para esperar; o desarme volta na hora e a
117+
# thread da sentinela (Python, daemon) termina junto
118+
idlewatch.arm(self.folder, idle_s=0.3)
119+
self.assertEqual(len(self._sentinelas()), 1)
120+
self._wait_dump(self.folder / "hang.log", "Thread") # desarma NO MEIO da vigilância
121+
t0 = time.monotonic()
95122
idlewatch.disarm()
123+
self.assertLess(time.monotonic() - t0, 2.0)
124+
self.assertEqual(self._sentinelas(), [])
96125

97126
def test_pasta_inexistente_nao_derruba(self):
98127
self.assertFalse(idlewatch.arm(self.tmp / "nao-existe" / "x", idle_s=5))

0 commit comments

Comments
 (0)