[FIX] database_cleanup: purge the batch, and say what you are doing

Seventeen minutes with no output looks exactly like an infinite loop. It
was not one: measured on the running process, zero lock waits and queries
changing every sample. It was working, silently, one module every thirty
seconds.

Both halves were mine. Purging line by line — added so one refusal could
not sink a category — calls button_immediate_uninstall() per line, and
that reloads the WHOLE registry: 5984 modules re-read each time. The
batch is now purged in one call, exactly as the OCA wizard intends, and
the per-line isolation only costs when a refusal actually happens.

And the tool captured its child's output, so nothing showed before the
end. It now relays each step as it arrives, with elapsed seconds, and a
timer kills the process group when the deadline passes.

--- FR ---

[FIX] database_cleanup : purger le lot, et dire ce qu'on fait

Dix-sept minutes sans une ligne ressemblent trait pour trait à une boucle
infinie. Ce n'en était pas une : mesuré sur le processus vivant, zéro
verrou en attente et des requêtes qui changeaient à chaque instantané. Il
travaillait, en silence, à raison d'un module toutes les trente secondes.

Les deux moitiés étaient de mon fait. Purger ligne par ligne — ajouté
pour qu'un refus n'emporte pas la catégorie — appelle
button_immediate_uninstall() par ligne, ce qui recharge TOUT le registre :
5984 modules relus à chaque fois. Le lot est désormais purgé en un seul
appel, comme le module OCA le prévoit, et l'isolement ne coûte que
lorsqu'un refus survient vraiment.

Et l'outil capturait la sortie de son enfant : rien avant la fin. Il
relaie maintenant chaque étape, temps écoulé compris.

Assisted-by: Claude Opus 5
This commit is contained in:
Mathieu Benoit 2026-08-17 23:19:04 -04:00
parent eaf70bdebf
commit 58bdd70526
3 changed files with 390 additions and 30 deletions

View file

@ -30,8 +30,11 @@ Exit codes: 0 nothing left, 1 leftovers remain, 2 the tool failed.
import argparse
import json
import os
import signal
import subprocess
import sys
import threading
import time
sys.path.append(
os.path.normpath(os.path.join(os.path.dirname(__file__), "..", "..", ".."))
@ -74,6 +77,7 @@ LABEL = {
"properties": "obsolete properties",
}
STEP = "ERPLIBRE_CLEANUP_STEP"
START = "ERPLIBRE_CLEANUP_START"
END = "ERPLIBRE_CLEANUP_END"
@ -90,6 +94,7 @@ ORDER = %(order)r
MAX_ROUND = %(max_round)d
DRY_RUN = %(dry_run)s
t_all = "%(all_label)s"
report = {"rounds": [], "missing": [], "failed": []}
@ -97,6 +102,14 @@ def note(label, name, exc):
report["failed"].append([label, name, str(exc)[:200]])
def step(label, name, index=0, total=0):
# Dire ce qu'on fait PENDANT qu'on le fait. Sans cela l'outil se taisait
# jusqu'au rapport final : mesuré, dix-sept minutes de silence complet
# sur une base de 5984 modules, impossible à distinguer d'un blocage.
detail = f" {index}/{total}" if total else ""
print(f"%(step)s {label}{detail} {name}", flush=True)
def recover():
# Rendre la transaction utilisable, quoi qu'il vienne de se passer.
#
@ -118,6 +131,7 @@ try:
for index in range(MAX_ROUND):
this_round = []
purged_this_round = 0
step("pass", str(index + 1), index + 1, MAX_ROUND)
for label, model in ORDER:
if model not in env:
if label not in report["missing"]:
@ -153,19 +167,40 @@ try:
env.cr.commit()
except Exception:
recover()
for line, name in todo:
if DRY_RUN:
would.append(name)
continue
if DRY_RUN:
would = [name for _line, name in todo]
elif todo:
# LE LOT D'ABORD, et ce n'est pas une optimisation de
# confort. `purge()` d'un module appelle
# button_immediate_uninstall(), qui RECHARGE LE REGISTRE
# ENTIER — 5984 modules à relire. En purgeant ligne par
# ligne j'en faisais un rechargement PAR MODULE : mesuré,
# dix secondes chacun, dix-sept minutes pour neuf modules.
# Le module OCA purge le lot en un seul appel, donc un seul
# rechargement.
#
# L'isolement ligne à ligne garde tout son sens — un refus
# ne doit pas emporter la catégorie — mais il ne coûte que
# lorsqu'il sert vraiment, c'est-à-dire après un échec.
step(label, t_all, 0, len(todo))
try:
line.purge()
# Valider ENTRÉE PAR ENTRÉE : un refus plus loin ne doit
# pas emporter ce qui vient d'être réparé.
wizard.purge_line_ids.purge()
env.cr.commit()
ok += 1
except Exception as exc:
ok = len(todo)
except Exception:
recover()
errors.append([name, str(exc)[:160]])
for index, (line, name) in enumerate(todo, start=1):
step(label, name, index, len(todo))
try:
line.purge()
# Valider ENTRÉE PAR ENTRÉE : un refus plus loin
# ne doit pas emporter ce qui vient d'être
# réparé.
env.cr.commit()
ok += 1
except Exception as exc:
recover()
errors.append([name, str(exc)[:160]])
purged_this_round += ok
this_round.append({"kind": label, "purged": ok,
"errors": errors, "would": would})
@ -201,6 +236,8 @@ def build_script(max_round, dry_run):
"dry_run": "True" if dry_run else "False",
"start": START,
"end": END,
"step": STEP,
"all_label": "the whole batch",
}
@ -302,14 +339,46 @@ def install_module(database, module="database_cleanup", timeout=1800):
return done.returncode, done.stdout + done.stderr
def run_shell(database, config_path, script, timeout=3600):
def kill_group(process):
"""Tuer le GROUPE : « ./odoo_bin.sh » est un script bash.
Un terminate() sur lui tue le script et laisse odoo-bin vivant, sur la
base, avec ses verrous. La leçon a déjà été payée une fois par six
serveurs orphelins.
"""
try:
group = os.getpgid(process.pid)
except OSError:
group = None
for signal_number in (signal.SIGTERM, signal.SIGKILL):
if group is None:
break
try:
os.killpg(group, signal_number)
except OSError:
break
try:
process.wait(timeout=20)
return
except subprocess.TimeoutExpired:
continue
def run_shell(database, config_path, script, timeout=3600, echo=None):
"""Pousser le script dans « odoo-bin shell » et rendre son rapport.
On LIT au fil de l'eau plutôt que de tout capturer : ce nettoyage dure
des minutes — dix-sept, mesurées, sur une base de 5984 modules — et la
version précédente n'affichait rien avant la fin. Un travail qui avance
et un blocage se ressemblent alors trait pour trait, et c'est ainsi
qu'on interrompt une réparation à moitié faite.
Les journaux d'Odoo se mêlent à la sortie, d'où les sentinelles : on ne
lit que ce qui est entre elles. Leur absence est une erreur franche, pas
un rapport vide qu'on prendrait pour « rien à faire ».
lit comme rapport que ce qui est entre elles. Leur absence est une
erreur franche, pas un rapport vide qu'on prendrait pour « rien à
faire ».
"""
done = subprocess.run(
process = subprocess.Popen(
[
"./odoo_bin.sh",
"shell",
@ -319,12 +388,43 @@ def run_shell(database, config_path, script, timeout=3600):
database,
"--log-level=warn",
],
input=script,
capture_output=True,
stdin=subprocess.PIPE,
stdout=subprocess.PIPE,
stderr=subprocess.STDOUT,
text=True,
timeout=timeout,
start_new_session=True,
)
output = done.stdout + done.stderr
# Le délai ne peut pas vivre dans la boucle de lecture : celle-ci BLOQUE
# tant qu'aucune ligne n'arrive, et c'est exactement le cas qu'il faut
# couvrir. Un minuteur à part, donc.
expire = {"fired": False}
def couper():
expire["fired"] = True
kill_group(process)
minuteur = threading.Timer(timeout, couper)
minuteur.daemon = True
minuteur.start()
lst_line = []
try:
process.stdin.write(script)
process.stdin.close()
for line in process.stdout:
lst_line.append(line)
if echo and line.startswith(STEP):
echo(line[len(STEP) :].strip())
process.wait()
finally:
minuteur.cancel()
if process.poll() is None:
kill_group(process)
output = "".join(lst_line)
if expire["fired"]:
raise RuntimeError(
f"{t('The cleanup was still running after')} {timeout}"
f" {t('seconds and was stopped.')}"
)
if START not in output or END not in output:
raise RuntimeError(
f"{t('The cleanup produced no report.')}\n{output.strip()[-1500:]}"
@ -336,6 +436,30 @@ def run_shell(database, config_path, script, timeout=3600):
raise RuntimeError(f"{t('Unreadable report')} : {exc}")
def make_echo(depart):
"""Relayer la progression du script poussé, horodatée.
Le temps écoulé n'est pas décoratif : c'est lui qui distingue « ça
avance lentement » de « ça ne bouge plus », et c'est précisément la
question qu'on se pose devant un écran muet.
"""
def echo(ligne):
morceaux = ligne.split(" ", 1)
etiquette = morceaux[0]
reste = morceaux[1] if len(morceaux) > 1 else ""
secondes = int(time.monotonic() - depart)
if etiquette == "pass":
print(f" [{secondes:>4}s] {t('pass')} {reste}")
else:
print(
f" [{secondes:>4}s] {t(LABEL.get(etiquette, etiquette))}"
f" — {t(reste) if reste == 'the whole batch' else reste}"
)
return echo
def leftovers(report):
"""[(kind, name, message)] de ce que la DERNIÈRE passe n'a pas pu purger."""
if not report.get("rounds"):
@ -457,17 +581,24 @@ def main(argv=None):
return 2
print(f"⧖ {t('Cleaning')} '{config.database}'…")
print(
f" {t('Purging modules reloads the whole registry: on a big')}"
f" {t('addons path this takes minutes, not seconds.')}"
)
depart = time.monotonic()
try:
report = run_shell(
config.database,
config.config,
build_script(config.max_round, config.dry_run),
timeout=config.timeout,
echo=make_echo(depart),
)
except (RuntimeError, subprocess.SubprocessError, OSError) as exc:
print(f"❌ {exc}")
return 2
print(render(report, config.database))
print(f"⌛ {t('Took')} {int(time.monotonic() - depart)} {t('seconds.')}")
return 1 if leftovers(report) else 0

View file

@ -5430,6 +5430,38 @@ TRANSLATIONS = {
"fr": "journal du serveur",
"en": "server log",
},
"Purging modules reloads the whole registry: on a big": {
"fr": "Purger les modules recharge tout le registre : sur un grand",
"en": "Purging modules reloads the whole registry: on a big",
},
"addons path this takes minutes, not seconds.": {
"fr": "addons path cela prend des minutes, pas des secondes.",
"en": "addons path this takes minutes, not seconds.",
},
"Took": {
"fr": "Durée :",
"en": "Took",
},
"seconds.": {
"fr": "secondes.",
"en": "seconds.",
},
"pass": {
"fr": "passe",
"en": "pass",
},
"The cleanup was still running after": {
"fr": "Le nettoyage tournait encore après",
"en": "The cleanup was still running after",
},
"seconds and was stopped.": {
"fr": "secondes et a été arrêté.",
"en": "seconds and was stopped.",
},
"the whole batch": {
"fr": "le lot entier",
"en": "the whole batch",
},
"Clean the database before testing the pages?": {
"fr": "Nettoyer la base avant de tester les pages ?",
"en": "Clean the database before testing the pages?",

View file

@ -34,17 +34,45 @@ class FakeLine:
self.id = abs(hash(name)) % 10000
self.fails = fails # nombre de refus avant de céder
self.journal = journal if journal is not None else []
self.purged = False
def purge(self):
# Comme le vrai : une ligne déjà purgée ne l'est pas deux fois.
# `purge()` d'OCA filtre sur `not x.purged`, et sans cela le repli
# ligne à ligne recompterait ce que le lot avait déjà fait.
if self.purged:
return True
self.journal.append(("purge", self.name))
if self.fails > 0:
self.fails -= 1
raise RuntimeError(f"refus sur {self.name}")
self.purged = True
return True
class FakeRecordset(list):
"""Un `purge_line_ids` qui se purge EN LOT, comme le vrai.
C'est TOUT l'enjeu du correctif : `purge()` d'un module appelle
button_immediate_uninstall(), qui recharge le registre entier. Un appel
par ligne en faisait un rechargement par module — mesuré, dix secondes
chacun. Un seul appel sur le lot, c'est un seul rechargement.
"""
def __init__(self, lines, journal=None):
super().__init__(lines)
self.journal = journal if journal is not None else []
def purge(self):
self.journal.append(("purge_batch", len(self)))
for line in self:
line.purge()
return True
class FakeWizard:
def __init__(self, lines):
self.purge_line_ids = lines
def __init__(self, lines, journal=None):
self.purge_line_ids = FakeRecordset(lines, journal)
class FakeModel:
@ -56,7 +84,9 @@ class FakeModel:
if self._raise:
raise RuntimeError(self._raise)
# Les lignes déjà purgées ne reviennent pas : find() les recalcule.
return FakeWizard([ln for ln in self._lines if ln.fails >= 0])
reste = [ln for ln in self._lines if ln.fails >= 0 and not ln.purged]
journal = reste[0].journal if reste else None
return FakeWizard(reste, journal)
class FakeCursor:
@ -208,9 +238,25 @@ class TestTheOrder(unittest.TestCase):
class TestOneEntryCannotSinkThePass(unittest.TestCase):
def test_each_entry_is_committed_on_its_own(self):
# Sans cela, le premier refus emporterait tout ce que la passe avait
# déjà réparé — et un rollback, ici, remonte jusqu'au début.
def test_a_healthy_category_is_purged_in_ONE_call(self):
# LE point du correctif. `purge()` d'un module appelle
# button_immediate_uninstall(), qui recharge le registre ENTIER —
# 5984 modules à relire. En purgeant ligne par ligne j'en faisais
# un rechargement PAR MODULE : mesuré, dix secondes chacun,
# dix-sept minutes pour neuf modules, sans rien afficher.
journal = []
lines = [
FakeLine("a", journal=journal),
FakeLine("b", journal=journal),
FakeLine("c", journal=journal),
]
models = {cleanup.ORDER[0][1]: FakeModel(lines)}
report, _got = run_script(models, max_round=1)
# `journal` est celui des LIGNES : c'est là qu'atterrit la purge.
self.assertEqual(journal.count(("purge_batch", 3)), 1)
self.assertEqual(report["rounds"][0][0]["purged"], 3)
def test_the_healthy_case_commits_once_for_the_batch(self):
journal = []
lines = [
FakeLine("a", journal=journal),
@ -218,9 +264,9 @@ class TestOneEntryCannotSinkThePass(unittest.TestCase):
]
models = {cleanup.ORDER[0][1]: FakeModel(lines)}
_report, got = run_script(models, max_round=1)
# Une validation par entrée, PLUS une après la création : `find()`
# peut avoir purgé de lui-même, et ce travail-là doit tenir.
self.assertEqual(got.count(("commit", None)), 3)
# Une validation après la création — `find()` peut avoir purgé de
# lui-même — et une pour le lot. Pas une par ligne.
self.assertEqual(got.count(("commit", None)), 2)
def test_a_refusal_gives_up_only_its_own(self):
journal = []
@ -234,9 +280,25 @@ class TestOneEntryCannotSinkThePass(unittest.TestCase):
entry = report["rounds"][0][0]
self.assertEqual(entry["purged"], 2)
self.assertEqual([name for name, _msg in entry["errors"]], ["bad"])
self.assertEqual(got.count(("rollback", None)), 1)
# Deux entrées purgées + la création : trois validations.
self.assertEqual(got.count(("commit", None)), 3)
# Le lot a été tenté, a échoué, et SEULEMENT alors on isole. Le
# coût du ligne-à-ligne n'est payé que là où il sert.
self.assertEqual(journal.count(("purge_batch", 3)), 1)
self.assertGreaterEqual(got.count(("rollback", None)), 1)
def test_the_isolation_only_happens_after_a_refusal(self):
# Une catégorie saine ne doit JAMAIS passer par le repli : c'est
# lui qui coûtait dix secondes par module.
journal = []
models = {
cleanup.ORDER[0][1]: FakeModel(
[
FakeLine("a", journal=journal),
FakeLine("b", journal=journal),
]
)
}
_report, got = run_script(models, max_round=1)
self.assertEqual(got.count(("rollback", None)), 0)
def test_the_script_never_takes_a_savepoint(self):
# L'invariant du correctif, dit une fois pour toutes : le module OCA
@ -303,6 +365,141 @@ class TestTheReportSurvivesAnything(unittest.TestCase):
self.assertIn("miettes", report["failed"][0][2])
class TestTheSilenceThatLookedLikeAHang(unittest.TestCase):
"""Dix-sept minutes sans une ligne, et l'on croit à une boucle infinie.
Vécu, sur test_neutralize_upgrade_16 : l'outil affichait « ⧖ Nettoyage
de … » puis PLUS RIEN. Le processus travaillait — zéro verrou en
attente, des requêtes qui changeaient à chaque instantané — mais un
travail qui avance et un blocage se ressemblent trait pour trait quand
aucun des deux ne parle. On interrompt alors une réparation à moitié
faite, ce qui est le pire des deux mondes.
"""
def test_the_pushed_script_announces_what_it_does(self):
source = cleanup.build_script(1, False)
self.assertIn(cleanup.STEP, source)
self.assertIn("flush=True", source)
def test_it_announces_each_pass(self):
source = cleanup.build_script(1, False)
self.assertIn('step("pass"', source)
def test_the_parent_relays_each_line_AS_IT_ARRIVES(self):
"""Le test comportemental, et non plus un mot cherché dans le code.
`capture_output=True` ne rend la main qu'à la fin : c'était la cause
du silence, pas la lenteur elle-même. On vérifie donc qu'une ligne
de progression ressort AVANT que le processus n'ait fini de parler.
"""
import io
lignes = [
f"{cleanup.STEP} modules 1/3 vieux_module\n",
"un journal Odoo sans rapport\n",
f"{cleanup.STEP} columns 2/3 res_partner.x\n",
f"{cleanup.START}\n",
'{"rounds": [], "missing": [], "failed": []}\n',
f"{cleanup.END}\n",
]
vu = []
class FauxProcessus:
def __init__(self, lst):
self.stdin = io.StringIO()
self.pid = -1
self._lst = lst
@property
def stdout(self):
# Un générateur : chaque ligne n'existe qu'au moment où on
# la lit, comme un vrai tube. Rendre la liste entière
# laisserait passer une lecture en bloc.
for rang, ligne in enumerate(self._lst):
vu.append(("lu", rang))
yield ligne
def wait(self, timeout=None):
return 0
def poll(self):
return 0
original = cleanup.subprocess.Popen
cleanup.subprocess.Popen = lambda *a, **kw: FauxProcessus(lignes)
self.addCleanup(setattr, cleanup.subprocess, "Popen", original)
report = cleanup.run_shell(
"db",
"./config.conf",
"script",
echo=lambda ligne: vu.append(("relayé", ligne)),
)
self.assertEqual(report["rounds"], [])
relayes = [x for x in vu if x[0] == "relayé"]
self.assertEqual(
[x[1] for x in relayes],
["modules 1/3 vieux_module", "columns 2/3 res_partner.x"],
)
# ET au fil de l'eau : le relais suit IMMÉDIATEMENT la lecture de
# sa ligne. « quelque part avant la fin » ne suffirait pas — une
# lecture en bloc suivie d'une boucle de relais passerait aussi.
self.assertEqual(vu[vu.index(("lu", 0)) + 1], relayes[0])
self.assertEqual(vu[vu.index(("lu", 2)) + 1], relayes[1])
def test_the_relay_shows_the_elapsed_time(self):
# Ce qui distingue « ça avance lentement » de « ça ne bouge plus ».
import io
from contextlib import redirect_stdout
import time as _time
echo = cleanup.make_echo(_time.monotonic() - 42)
out = io.StringIO()
with redirect_stdout(out):
echo("modules 2/9 stock_deposit")
self.assertIn("42", out.getvalue())
self.assertIn("stock_deposit", out.getvalue())
def test_the_slowness_is_announced_up_front(self):
import inspect
source = inspect.getsource(cleanup.main)
self.assertIn("reloads the whole registry", source)
def test_the_timeout_cannot_be_starved_by_silence(self):
# Un délai vérifié DANS la boucle de lecture ne se déclencherait
# jamais : cette boucle bloque tant qu'aucune ligne n'arrive, et
# c'est exactement le cas qu'il faut couvrir.
import inspect
source = inspect.getsource(cleanup.run_shell)
self.assertIn("threading.Timer", source)
def test_stopping_kills_the_whole_group(self):
# « ./odoo_bin.sh » est un script bash : un terminate() sur lui tue
# le script et laisse odoo-bin vivant, sur la base, avec ses
# verrous. La leçon a déjà été payée en serveurs orphelins.
import inspect
source = inspect.getsource(cleanup.kill_group)
self.assertIn("killpg", source)
self.assertIn(
"start_new_session", inspect.getsource(cleanup.run_shell)
)
def test_a_timeout_is_reported_as_such(self):
# Sans cela, un arrêt à l'expiration se lisait « le nettoyage n'a
# produit aucun rapport » — un diagnostic faux.
import inspect
source = inspect.getsource(cleanup.run_shell)
self.assertIn("was still running after", source)
self.assertLess(
source.index("was still running after"),
source.index("produced no report"),
)
class TestTheCascadeThatKilledEverything(unittest.TestCase):
"""Vécu, sur test_neutralize_upgrade_13 : sept catégories mortes d'une.