[ADD] migration: keep the logs on disk, one file per step

The state screen showed « no tool has run yet » after closing and
reopening. It was reading the progression file, and that file is archived
and reset when a migration restarts — so everything it knew vanished at
the exact moment one wants to understand why the restart was needed.

Each step now has its own log file, appended never overwritten, and the
failures and tool verdicts go to an append-only JSONL beside them. Both
outlive the progression, and the screen reads disk first, memory second,
without counting the overlap twice.

The command output itself is captured where every line already passes,
in the executor's read loop: the terminal still shows it live and nothing
about the run changes. What goes through the real terminal cannot be
captured — a pipe there makes full screens refuse, that lesson is paid —
so those keep at least their command and their exit code.

--- FR ---

[ADD] migration : garder les journaux sur disque, un fichier par étape

L'écran d'état affichait « aucun outil n'a encore tourné » après une
fermeture. Il lisait le fichier de progression, or celui-ci est archivé
puis remis à zéro quand on recommence : tout ce qu'il savait disparaissait
au moment précis où l'on cherche pourquoi il a fallu recommencer.

Chaque étape a désormais son fichier, en ajout et jamais en écrasement, et
les échecs comme les verdicts d'outils vont dans un JSONL à côté. Les deux
survivent à la progression, et l'écran lit le disque d'abord.

La sortie des commandes est captée là où chaque ligne passe déjà, dans la
boucle de lecture de l'exécuteur : le terminal la montre toujours en
direct. Ce qui passe par le vrai terminal n'est pas captable — un tube y
ferait renoncer les pleins écrans — et garde au moins son verdict.

Assisted-by: Claude Opus 5
This commit is contained in:
Mathieu Benoit 2026-08-19 04:32:25 -04:00
parent 566070b4f8
commit 19d807a81e
5 changed files with 448 additions and 7 deletions

View file

@ -178,12 +178,22 @@ class Execute:
env=my_env,
)
sink = getattr(self, "log_sink", None)
while True:
line = process.stdout.readline()
if not line:
break
if not quiet:
print(line, end="")
if sink:
# Chaque ligne passe DÉJÀ ici : c'est le seul endroit où
# journaliser sans rien changer à ce que le terminal
# montre. Une erreur d'écriture ne doit jamais faire
# échouer la commande qu'on est en train de suivre.
try:
sink.write(line)
except Exception:
sink = None
if (
return_status_and_output
or return_status_and_output_and_command

View file

@ -36,6 +36,9 @@ except Exception: # pragma: no cover - repli si i18n indisponible
DEFAULT_PATH = ".venv.erplibre/odoo_database_migration_log.json"
PATH_MIGRATION_PRIVATE = os.path.join("private", "odoo", "migration")
STEP_LOG_DIR = "step_log"
EVENT_FILE = "events.jsonl"
# Les codes de sortie que TOUS les outils de migration partagent. Les
# traduire ici plutôt qu'à l'affichage évite qu'un « 1 » passe pour une
@ -48,12 +51,112 @@ VERDICT = {
def read(path=DEFAULT_PATH):
"""La progression, telle qu'écrite. {} si elle n'existe pas encore."""
"""La progression, complétée par ce qui a été écrit SUR DISQUE.
Le fichier de progression est archivé puis remis à zéro quand on
recommence une migration : tout ce qu'il contenait disparaissait alors
de cet écran. Le journal permanent, lui, ne fait que s'allonger — et
c'est justement en revenant après une interruption qu'on a besoin de
ce qui s'est passé avant.
"""
try:
with open(path, "r", encoding="utf-8") as handle:
return json.load(handle)
dct = json.load(handle)
except (OSError, ValueError):
return {}
dct["lst_event"] = merge_events(dct)
return dct
def log_dir(dct):
"""Le répertoire des journaux de cette migration, ou None."""
database = (dct or {}).get("config_database_name")
if not database:
return None
chemin = os.path.join(PATH_MIGRATION_PRIVATE, database, STEP_LOG_DIR)
return chemin if os.path.isdir(chemin) else None
def read_event_file(dct):
"""Les événements du journal permanent, en ignorant les lignes cassées.
Une écriture interrompue laisse une ligne tronquée ; la refuser en bloc
perdrait tout le reste du fichier pour une seule ligne.
"""
chemin = log_dir(dct)
if not chemin:
return []
lst = []
try:
with open(
os.path.join(chemin, EVENT_FILE), "r", encoding="utf-8"
) as handle:
for ligne in handle:
ligne = ligne.strip()
if not ligne:
continue
try:
lst.append(json.loads(ligne))
except ValueError:
continue
except OSError:
return []
return lst
def merge_events(dct):
"""Le disque d'abord, la mémoire ensuite, sans doublon.
Les deux sources se recouvrent : ce qui vient d'être enregistré est aux
deux endroits. On dédoublonne sur (horodatage, nom, type) — trois
champs qu'un même événement porte à l'identique dans les deux.
"""
vus = set()
fusion = []
for item in read_event_file(dct) + list(dct.get("lst_event") or []):
cle = (item.get("at"), item.get("name"), item.get("kind"))
if cle in vus:
continue
vus.add(cle)
fusion.append(item)
return fusion
def step_log_path(dct, step):
"""Le fichier de journal d'une étape, s'il existe."""
chemin = log_dir(dct)
if not chemin or not step:
return None
fichier = os.path.join(chemin, f"{step_slug(step)}.log")
return fichier if os.path.isfile(fichier) else None
def step_slug(msg):
"""Le même nom que celui écrit par la migration. Un seul calcul.
Deux formules séparées dériveraient, et l'écran chercherait alors un
fichier que personne n'écrit — sans rien signaler, puisqu'un fichier
absent se lit comme une étape sans journal.
"""
import re
prefix, sep, label = (msg or "").partition(" - ")
propre = re.sub(r"[^A-Za-z0-9._-]+", "-", (label or prefix)).strip("-")
tete = re.sub(r"[^A-Za-z0-9._-]+", "-", prefix).strip("-") if sep else ""
nom = f"{tete}_{propre}" if tete else propre
return (nom or "step")[:80].lower()
def step_log_tail(dct, step, lines=200):
"""Les dernières lignes du journal de cette étape."""
chemin = step_log_path(dct, step)
if not chemin:
return []
try:
with open(chemin, "r", encoding="utf-8", errors="replace") as handle:
return handle.read().splitlines()[-lines:]
except OSError:
return []
def journal_by_step(dct):
@ -189,7 +292,8 @@ def render_text(dct, limit_cmd=12):
lignes.append(f"\n🔷 {t('What was done, step by step')}")
for section in journal_by_step(dct):
lst_cmd = section["lst_cmd"]
lignes.append(f" {section['step']} ({len(lst_cmd)})")
journal = " 📄" if step_log_path(dct, section["step"]) else ""
lignes.append(f" {section['step']} ({len(lst_cmd)}){journal}")
for cmd in lst_cmd[:limit_cmd]:
lignes.append(f" {cmd[:120]}")
if len(lst_cmd) > limit_cmd:

View file

@ -111,10 +111,18 @@ def pane_text(dct, row):
for item in lst_failure:
lignes.append(f" {item.get('name')}")
lignes.append("")
if not section["lst_cmd"]:
lignes.append(t("No tool has run yet."))
for cmd in section["lst_cmd"]:
lignes.append(f"· {cmd}")
# La SORTIE des commandes, relue sur disque. C'est ce qui manquait :
# la liste des commandes dit ce qui a été lancé, jamais ce que cela a
# répondu — et c'est la réponse qu'on vient chercher.
tail = status.step_log_tail(dct, section["step"])
if tail:
lignes.append("")
lignes.append(f"── {t('server log')} ──")
lignes.extend(tail)
elif not section["lst_cmd"]:
lignes.append(t("No tool has run yet."))
return "\n".join(lignes)

View file

@ -14,7 +14,11 @@ import zipfile
from uuid import uuid4
from script.todo import auto_ask, todo_file_browser
from script.todo import (
auto_ask,
migration_status,
todo_file_browser,
)
from script.todo.version_manager import get_odoo_version
try:
@ -59,6 +63,10 @@ LOCAL_MANIFEST = os.path.join(
# be dropped depends on the database, so that choice is never versioned.
PATH_MIGRATION_GLOBAL = os.path.join("script", "odoo", "migration")
PATH_MIGRATION_PRIVATE = os.path.join("private", "odoo", "migration")
# Le journal permanent des échecs et des verdicts, hors du fichier de
# progression : celui-ci est remis à zéro quand on recommence.
STEP_LOG_DIR = "step_log"
EVENT_FILE = "events.jsonl"
# Steps of the migration, in order. What each one owns is declared just below,
# by GLOBAL_PROGRESSION_KEY and STEP_OWNED_KEY — not by the prefix alone, which
# lies on some keys and is missing on others. Rewinding to a step drops
@ -2932,6 +2940,7 @@ class TodoUpgrade:
# Retenu pour l'écran d'état : un événement sans étape oblige à
# relire tout le journal pour savoir OÙ il s'est produit.
self.current_step = msg
self.open_step_log(msg)
print(f"🔷 {prefix}{sep}{t(label)}" if sep else f"🔷 {t(msg)}")
def installed_theme(self, database_name):
@ -3191,7 +3200,10 @@ class TodoUpgrade:
self.write_config()
print(f"\n🏠 ⬇ {t('Execute command')} :\n")
print(cmd)
return subprocess.call(cmd, shell=True, executable="/bin/bash")
self.note_step_log(f"$ {cmd}")
status = subprocess.call(cmd, shell=True, executable="/bin/bash")
self.note_step_log(f" -> {status}")
return status
def prompt_cow_prediction(self, database_name, next_version):
"""Que faire des copies COW annoncées, dès l'étape 2.
@ -3896,6 +3908,76 @@ class TodoUpgrade:
MAX_EVENT = 200
# Le nom de fichier d'une étape est calculé PAR L'ÉCRAN D'ÉTAT, et
# importé ici. Deux formules dériveraient, et l'écran chercherait alors
# un fichier que personne n'écrit — sans rien signaler, puisqu'un
# fichier absent se lit comme une étape sans journal.
step_slug = staticmethod(migration_status.step_slug)
def log_dir(self):
"""Où vivent les journaux de CETTE migration. Créé à la demande.
Sous le nom de la base, comme les archives et les instantanés COW :
deux migrations menées de front ne doivent pas écrire dans le même
fichier, et l'on veut pouvoir tout emporter d'un seul répertoire.
"""
database = (getattr(self, "dct_progression", None) or {}).get(
"config_database_name"
) or "sans-nom"
chemin = os.path.join(PATH_MIGRATION_PRIVATE, database, STEP_LOG_DIR)
try:
os.makedirs(chemin, exist_ok=True)
except OSError:
return None
return chemin
def open_step_log(self, msg):
"""Rediriger la sortie des commandes vers le journal de cette étape.
En AJOUT, jamais en écrasement : une étape rejouée après un retour
en arrière doit s'ajouter à ce qu'on savait d'elle, pas l'effacer.
C'est précisément l'historique qu'on vient relire.
"""
self.close_step_log()
chemin = self.log_dir()
if not chemin:
return
fichier = os.path.join(chemin, f"{self.step_slug(msg)}.log")
try:
handle = open(fichier, "a", encoding="utf-8", buffering=1)
except OSError:
return
handle.write(f"\n===== {datetime.datetime.now()} — {msg} =====\n")
self.step_log = handle
if getattr(self, "execute", None) is not None:
self.execute.log_sink = handle
def close_step_log(self):
handle = getattr(self, "step_log", None)
if handle:
try:
handle.close()
except Exception:
pass
self.step_log = None
if getattr(self, "execute", None) is not None:
self.execute.log_sink = None
def note_step_log(self, texte):
"""Écrire une ligne dans le journal de l'étape en cours.
Ce qui passe par `run_on_terminal` n'a PAS de sortie capturable —
un tube y ferait renoncer les pleins écrans, la leçon a été payée.
On garde donc au moins la commande et son verdict.
"""
handle = getattr(self, "step_log", None)
if not handle:
return
try:
handle.write(f"[{datetime.datetime.now()}] {texte}\n")
except Exception:
pass
def record_event(self, kind, name, status, detail=""):
"""Garder ce qui s'est MAL passé, et ce que les outils ont conclu.
@ -3922,6 +4004,32 @@ class TodoUpgrade:
)
self.dct_progression["lst_event"] = lst[-self.MAX_EVENT :]
self.write_config()
# ET sur disque, en AJOUT, hors du fichier de progression. Celui-ci
# est archivé puis remis à zéro quand on recommence une migration :
# tout ce qu'on y avait mis disparaissait alors de l'écran d'état,
# au moment précis où l'on cherchait à comprendre pourquoi il avait
# fallu recommencer.
self.append_event_file(lst[-1])
self.note_step_log(f"[{kind}] {name} -> {status}")
def append_event_file(self, event):
"""Ajouter l'événement au journal permanent, une ligne de JSON.
JSONL et non JSON : un fichier qu'on complète ligne à ligne
survit à une interruption au milieu d'une écriture, là où un
tableau JSON réécrit en entier ne laisserait qu'un fichier
tronqué — donc illisible, donc perdu en totalité.
"""
chemin = self.log_dir()
if not chemin:
return
try:
with open(
os.path.join(chemin, EVENT_FILE), "a", encoding="utf-8"
) as handle:
handle.write(json.dumps(event, ensure_ascii=False) + "\n")
except OSError:
pass
def run_tool(self, name, cmd):
"""Lancer un outil de migration et RETENIR sa conclusion.

View file

@ -22,6 +22,7 @@ Deux choses se vérifient ici, et la seconde est la moins évidente :
import io
import os
import shutil
import unittest
from contextlib import redirect_stdout
@ -353,6 +354,216 @@ class TestLookingIsNotAnswering(Base):
self.assertNotIn("self.run_on_terminal(", source)
class DiskCase(Base):
"""Un répertoire jetable : les chemins de journal sont RELATIFS."""
def setUp(self):
super().setUp()
import tempfile
self.dossier = tempfile.mkdtemp(prefix="erplibre_essai_")
avant = os.getcwd()
os.chdir(self.dossier)
self.addCleanup(shutil.rmtree, self.dossier, True)
self.addCleanup(os.chdir, avant)
def upgrade(self, database="essai_db"):
obj = TodoUpgrade.__new__(TodoUpgrade)
obj.dct_progression = {"config_database_name": database}
obj.lst_command_executed = []
obj.write_config = lambda: None
return obj
class TestWhatSurvivesClosingTheTool(DiskCase):
"""Le fichier de progression est ARCHIVÉ puis remis à zéro.
Recommencer une migration effaçait donc tout ce que l'écran d'état
savait — au moment précis où l'on cherche à comprendre pourquoi il a
fallu recommencer. Le journal permanent, lui, ne fait que s'allonger.
"""
def test_events_are_found_again_with_nothing_in_memory(self):
obj = self.upgrade()
obj.print_step("4.2.I - Migrate database")
obj.record_event("command", "update_addons_all.sh", 1)
obj.record_event("test", "smoke_public_url", 0)
obj.close_step_log()
# Une progression NEUVE : c'est l'état après réouverture.
neuf = {"config_database_name": "essai_db"}
lst = status.merge_events(neuf)
self.assertEqual(len(lst), 2)
self.assertEqual(lst[0]["name"], "update_addons_all.sh")
def test_the_step_survives_with_them(self):
# Un événement sans étape oblige à relire tout le journal pour
# savoir OÙ il s'est produit.
obj = self.upgrade()
obj.print_step("4.2.I - Migrate database")
obj.record_event("test", "database_cleanup", 1)
obj.close_step_log()
lst = status.merge_events({"config_database_name": "essai_db"})
self.assertEqual(lst[0]["step"], "4.2.I - Migrate database")
def test_memory_and_disk_are_not_counted_twice(self):
obj = self.upgrade()
obj.print_step("2 - Succeed update all addons")
obj.record_event("test", "smoke_public_url", 0)
obj.close_step_log()
# `obj.dct_progression` porte DÉJÀ l'événement : les deux sources se
# recouvrent, et les additionner le montrerait en double.
self.assertEqual(len(status.merge_events(obj.dct_progression)), 1)
def test_a_truncated_line_does_not_lose_the_others(self):
# Une écriture interrompue laisse une ligne tronquée ; refuser le
# fichier en bloc perdrait tout pour une seule ligne.
obj = self.upgrade()
obj.print_step("1 - Import database from zip")
obj.record_event("test", "premier", 0)
obj.close_step_log()
chemin = os.path.join(
"private",
"odoo",
"migration",
"essai_db",
"step_log",
"events.jsonl",
)
with open(chemin, "a") as handle:
handle.write('{"at": "x", "name": "coup\n')
obj.record_event("test", "dernier", 0)
noms = [
x["name"]
for x in status.merge_events({"config_database_name": "essai_db"})
]
self.assertIn("premier", noms)
self.assertIn("dernier", noms)
def test_a_migration_without_a_database_writes_nowhere(self):
obj = self.upgrade(database=None)
obj.dct_progression = {}
obj.print_step("0 - Inspect zip")
obj.record_event("test", "x", 0)
obj.close_step_log()
# Rien ne doit planter, et rien ne doit se perdre ailleurs.
self.assertEqual(len(obj.dct_progression["lst_event"]), 1)
class TestTheStepLogs(DiskCase):
def test_each_step_gets_its_own_file(self):
obj = self.upgrade()
for etape in ("0 - Inspect zip", "4.2.C - Install module"):
obj.print_step(etape)
obj.note_step_log("quelque chose")
obj.close_step_log()
dossier = os.path.join(
"private", "odoo", "migration", "essai_db", "step_log"
)
self.assertEqual(
sorted(x for x in os.listdir(dossier) if x.endswith(".log")),
["0_inspect-zip.log", "4.2.c_install-module.log"],
)
def test_the_numbered_prefix_keeps_them_in_order(self):
# Un `ls` trié est la première chose qu'on fait dans ce répertoire.
self.assertTrue(
status.step_slug("4.2.C - Install module").startswith("4.2.c")
)
def test_replaying_a_step_ADDS_to_what_was_known(self):
# Une étape rejouée après un retour en arrière ne doit pas effacer
# l'historique : c'est justement ce qu'on vient relire.
obj = self.upgrade()
obj.print_step("2 - Succeed update all addons")
obj.note_step_log("premier passage")
obj.close_step_log()
obj.print_step("2 - Succeed update all addons")
obj.note_step_log("second passage")
obj.close_step_log()
tail = status.step_log_tail(
{"config_database_name": "essai_db"},
"2 - Succeed update all addons",
)
texte = "\n".join(tail)
self.assertIn("premier passage", texte)
self.assertIn("second passage", texte)
def test_the_command_and_its_verdict_are_kept(self):
# `run_on_terminal` n'a PAS de sortie capturable — un tube y ferait
# renoncer les pleins écrans. On garde au moins ces deux-là.
obj = self.upgrade()
obj.print_step("3 - Clean up database")
obj.run_on_terminal("true")
obj.close_step_log()
texte = "\n".join(
status.step_log_tail(
{"config_database_name": "essai_db"}, "3 - Clean up database"
)
)
self.assertIn("$ true", texte)
self.assertIn("-> 0", texte)
def test_a_step_never_run_has_no_file(self):
self.assertIsNone(
status.step_log_path(
{"config_database_name": "essai_db"}, "9 - jamais"
)
)
def test_the_name_is_computed_in_ONE_place(self):
# Deux formules dériveraient, et l'écran chercherait un fichier que
# personne n'écrit — sans rien signaler, puisqu'un fichier absent
# se lit comme une étape sans journal.
self.assertIs(TodoUpgrade.step_slug, status.step_slug)
class TestTheCommandOutputItself(DiskCase):
"""Ce qui manquait vraiment : ce que les commandes ont RÉPONDU."""
def test_the_lines_land_in_the_step_log(self):
from script.execute import execute as ex
obj = self.upgrade()
obj.execute = ex.Execute()
obj.print_step("2 - Succeed update all addons")
with redirect_stdout(io.StringIO()):
obj.todo_upgrade_execute(
"echo première && echo seconde >&2", wait_at_error=False
)
obj.close_step_log()
texte = "\n".join(
status.step_log_tail(
{"config_database_name": "essai_db"},
"2 - Succeed update all addons",
)
)
self.assertIn("première", texte)
# stderr aussi : c'est là que les erreurs d'Odoo se trouvent.
self.assertIn("seconde", texte)
def test_a_broken_sink_never_breaks_the_command(self):
# Journaliser est un service rendu, pas une condition de marche.
from script.execute import execute as ex
class PuitsCasse:
def write(self, texte):
raise OSError("disque plein")
moteur = ex.Execute()
moteur.log_sink = PuitsCasse()
with redirect_stdout(io.StringIO()):
status_code = moteur.exec_command_live(
"echo bonjour", source_erplibre=False, quiet=True
)
self.assertEqual(status_code, 0)
def test_nothing_is_logged_without_a_step(self):
from script.execute import execute as ex
moteur = ex.Execute()
self.assertIsNone(getattr(moteur, "log_sink", None))
class TestTheStatisticsScreenOffersIt(Base):
"""L'écran de statistiques répond « qu'a-t-on supprimé, et pourquoi ».