diff --git a/script/execute/execute.py b/script/execute/execute.py index cfb9ff3..dcb360f 100644 --- a/script/execute/execute.py +++ b/script/execute/execute.py @@ -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 diff --git a/script/todo/migration_status.py b/script/todo/migration_status.py index 6cd506d..d59eecb 100755 --- a/script/todo/migration_status.py +++ b/script/todo/migration_status.py @@ -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: diff --git a/script/todo/migration_status_tui.py b/script/todo/migration_status_tui.py index 0777a78..d19486b 100644 --- a/script/todo/migration_status_tui.py +++ b/script/todo/migration_status_tui.py @@ -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) diff --git a/script/todo/todo_upgrade.py b/script/todo/todo_upgrade.py index fa69554..96b4c42 100755 --- a/script/todo/todo_upgrade.py +++ b/script/todo/todo_upgrade.py @@ -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. diff --git a/test/test_migration_status.py b/test/test_migration_status.py index 7e91c53..a3689f1 100644 --- a/test/test_migration_status.py +++ b/test/test_migration_status.py @@ -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 ».