feat(upgrade): report the run in three buckets

README.md

@@ -147,6 +147,10 @@ To update all instances:
 
 1. **Update Environment Files**: `alakazam example.com.yml config` to refresh .env files. It's a good practice to keep these files under version control (e.g., in a Git repository at `~/.abra/example.com`) and review changes with `git diff` before proceeding.
 2. **Upgrade Applications**: `alakazam example.com.yml upgrade` to update all applications.
+    - an app that abra refuses and an app that does not become healthy both end the run non-zero,
+      the apps beside them are still upgraded and still get their hooks
+    - a failing upgrade hook is reported but does not end the run, so that the hooks can be fixed
+      one at a time
 
 ### Rotate Secrets
 
@@ -262,6 +266,13 @@ For each app/recipe the following `<app_configurations>` can be used:
     - this is useful for env variables that are used multiple times like `COMPOSE_FILE`
 - **`env`**: Sets values for environment variables.
 - **`*-hooks`**: Specifies `abra.sh` commands or local scripts to run at specific stages.
+    - **`pre-upgrade-hooks`**: commands that should be run before each upgrade, while the old
+      containers are still running
+        - they are a precondition rather than an addition, so unlike every other kind they run
+          without `--execute-hooks`; `--skip-pre-upgrade-hooks` leaves them out
+        - a failing one costs that app its upgrade and nothing else, the run then ends non-zero
+        - the command comes from the recipe version the configuration asks for, so it has to exist
+          there and has to work against the app that is still running the old one
     - **`initial-hooks`**: commands for initialisation
     - **`deploy-hooks`**: commands that should be run after each deployment
     - **`upgrade-hooks`**: commands that should be run after each upgrade

alakazam.py

@@ -61,8 +61,14 @@ GROUP_PATH = None  # path this run was invoked with, either an instance file or
 HIDE_SECRETS = False  # keep secret values out of the output, for runs whose logs are archived
 ABRA_DIR = None  # path to the abra data directory
 FETCH_MAX_AGE = 3600 # seconds; recipe repos are refetched at most once per hour
-ABRA_RETRIES = 6 # number of attempts per abra command that failed to reach the server
+ABRA_RETRIES = 8 # number of attempts per abra command that failed for a reason worth retrying
 ABRA_RETRY_DELAY = 2 # seconds before the first retry, doubled for every further one
+# lower case markers in the abra output for an app whose replaced container has not gone away yet,
+# which leaves abra unable to tell which one a command is meant for
+AMBIGUOUS_CONTAINER_ERRORS = (
+    "ambiguous container list",
+    "expected 1 container but found",
+)
 # lower case markers in the abra output that indicate an unreachable server instead of a failed operation
 CONNECTION_ERRORS = (
     "error during connect",
@@ -706,6 +712,27 @@ def is_connection_error(output: str) -> bool:
     return any(error in output.lower() for error in CONNECTION_ERRORS)
 
 
+def get_retry_reason(output: str) -> Optional[str]:
+    """
+    Names the transient condition an abra output shows, or nothing when the failure is a real one.
+
+    Both conditions leave the server untouched: an unreachable server never ran the command, and an
+    ambiguous container list is decided before the command is handed over. Retrying is therefore
+    safe even for a command that would not survive being run twice.
+
+    Args:
+        output (str): The combined stdout and stderr of the abra command
+
+    Returns:
+        str: What went wrong, phrased for the retry message, or None if it is worth no retry
+    """
+    if is_connection_error(output):
+        return "failed to reach the server"
+    if any(error in output.lower() for error in AMBIGUOUS_CONTAINER_ERRORS):
+        return "found more than one container, the replaced one has not gone away yet"
+    return None
+
+
 def run_streamed(command: List[str]) -> subprocess.CompletedProcess:
     """
     Runs a command and echoes its output line by line while it is still running.
@@ -764,12 +791,13 @@ def abra(*args: str, machine_output: bool = False, ignore_error: bool = False, s
         process = run_streamed(command) if stream else subprocess.run(command, capture_output=True)
         if not process.returncode or attempt == ABRA_RETRIES:
             break
-        if not is_connection_error(process.stdout.decode() + process.stderr.decode()):
+        reason = get_retry_reason(process.stdout.decode() + process.stderr.decode())
+        if not reason:
             break
         # back off exponentially: a server that drops connections during the ssh handshake is
         # usually throttling, and retrying every couple of seconds keeps it throttling
         delay = ABRA_RETRY_DELAY * 2 ** (attempt - 1)
-        logging.warning(f"attempt {attempt}/{ABRA_RETRIES} of '{' '.join(command)}' failed to reach the server, retry in {delay}s")
+        logging.warning(f"attempt {attempt}/{ABRA_RETRIES} of '{' '.join(command)}' {reason}, retry in {delay}s")
         sleep(delay)
     if process.stderr and ignore_error and not quiet:
         logging.warning(process.stderr.decode())
@@ -1441,7 +1469,7 @@ def insert_secrets_from_conf(domain: str, app_config: Dict[str, Any]) -> None:
                 insert_secret(domain, secret_name, secret)
 
 
-def run_local_script(tokens: List[str], app_domain: str, server: str, instance_domain: str, dry_run: bool = False, strict: bool = False) -> None:
+def run_local_script(tokens: List[str], app_domain: str, server: str, instance_domain: str, dry_run: bool = False, strict: bool = False) -> Optional[str]:
     """
     Run a local script hook. Relative paths are resolved against ROOT_PATH for execution. Logs an error and returns early if the script is not executable.
 
@@ -1453,6 +1481,9 @@ def run_local_script(tokens: List[str], app_domain: str, server: str, instance_d
         dry_run (bool): If True, prints the command but does not execute it.
         strict (bool): Abort on a non-executable script or a non-zero exit code instead of only logging it.
 
+    Returns:
+        str: Why the script failed, or None when it ran through
+
     Raises:
         click.ClickException: If the script is not executable or exits non-zero and strict is set
     """
@@ -1466,16 +1497,18 @@ def run_local_script(tokens: List[str], app_domain: str, server: str, instance_d
         if strict:
             raise click.ClickException(f"script '{cmd_display}' failed for {app_domain}: {message}")
         logging.error(message)
-        return
+        return message
     if dry_run:
-        return
+        return None
     # the script may print a secret it just created, so its output is captured and dropped
     result = subprocess.run([str(script_path)] + args, env=env, capture_output=HIDE_SECRETS)
     if result.returncode != 0:
         message = f"Script '{cmd_display}' exited with code {result.returncode}"
         if strict:
             raise click.ClickException(f"script '{cmd_display}' failed for {app_domain}: {message}")
-        logging.warning(message)
+        logging.error(message)
+        return message
+    return None
 
 
 def run_secret_hooks(domain: str, app_config: Dict[str, Any], instance_domain: str = "", strict: bool = False) -> None:
@@ -1731,7 +1764,7 @@ def run_readiness_hooks(domain: str, app_config: Dict[str, Any]) -> None:
         run_readiness_hook(domain, hook)
 
 
-def execute_cmds(app_config: Dict[str, Any], commands: Tuple[str] = tuple(), initial: bool = False, deploy: bool = False, upgrade: bool = False, dry_run: bool = False, chaos: bool = False, strict: bool = False, instance_domain: str = "") -> None:
+def execute_cmds(app_config: Dict[str, Any], commands: Tuple[str] = tuple(), pre_upgrade: bool = False, initial: bool = False, deploy: bool = False, upgrade: bool = False, dry_run: bool = False, chaos: bool = False, strict: bool = False, instance_domain: str = "") -> List[str]:
     """
     Execute post-deployment commands for an application based on the provided configuration.
     This can include running scripts or commands inside the application's environment.
@@ -1740,6 +1773,7 @@ def execute_cmds(app_config: Dict[str, Any], commands: Tuple[str] = tuple(), ini
         app_config (dict): A dictionary containing the deployment configuration and commands for an application.
         commands (list): A list of commands that should be executed in the following format:
             '<container_name> <abra.sh command> <optional arguments>'
+        pre_upgrade (bool): execute pre-upgrade-hooks, which run while the old containers still do
         initial (bool): execute initial-hooks
         deploy (bool): execute deploy-hooks
         upgrade (bool): execute upgrade-hooks
@@ -1748,38 +1782,55 @@ def execute_cmds(app_config: Dict[str, Any], commands: Tuple[str] = tuple(), ini
         instance_domain (str): The instance domain, used to set ALAKAZAM_INSTANCE_DOMAIN for script hooks.
 
     Returns:
-        None
+        list: The commands that failed, empty when all of them ran through. Always empty with
+            strict, which ends on the first failure instead of collecting it.
 
     Raises:
         click.ClickException: If a command fails and strict is set
     """
     domain = app_config['app_domain']
     server = app_config['server']
-    all_cmds = []
+    # kept grouped by kind rather than flattened, so that a dry run can say which kind it shows
+    groups = []
+    if pre_upgrade and (pre_upgrade_hooks:= app_config.get('pre-upgrade-hooks')):
+        groups.append(('pre-upgrade-hooks', pre_upgrade_hooks))
     if initial and (initial_hooks:= app_config.get('initial-hooks')):
-        all_cmds = all_cmds + initial_hooks
+        groups.append(('initial-hooks', initial_hooks))
     if deploy and (deploy_hooks:= app_config.get('deploy-hooks')):
-        all_cmds = all_cmds + deploy_hooks
+        groups.append(('deploy-hooks', deploy_hooks))
     if upgrade and (upgrade_hooks:= app_config.get('upgrade-hooks')):
-        all_cmds = all_cmds + upgrade_hooks
+        groups.append(('upgrade-hooks', upgrade_hooks))
     if commands:
-        all_cmds = all_cmds + list(commands)
+        groups.append(('--command', list(commands)))
     chaos_flag = ""
     if chaos:
         chaos_flag = "-C"
-    for cmd in all_cmds:
-        tokens = cmd.split()
-        container = tokens[0]
-        if container == "script" and len(tokens) >= 2 and resolve_path(tokens[1]).exists():
-            run_local_script(tokens, domain, server, instance_domain, dry_run, strict)
-            continue
-        print(f"Run '{cmd}' in {domain}:{container}", flush=True)
+    failed = []
+    for kind, cmds in groups:
+        # a real run has the deployment output between the kinds to tell them apart, a dry run
+        # prints them back to back and needs saying which side of the deployment each one is on
         if dry_run:
-            continue
-        try:
-            abra(*build_app_cmd(domain, cmd, chaos_flag), ignore_error=not strict, stream=True)
-        except RuntimeError as e:
-            raise click.ClickException(f"command '{cmd}' failed for {domain}: {e}")
+            print(f"{kind} for {domain}:")
+        for cmd in cmds:
+            tokens = cmd.split()
+            container = tokens[0]
+            if container == "script" and len(tokens) >= 2 and resolve_path(tokens[1]).exists():
+                if reason := run_local_script(tokens, domain, server, instance_domain, dry_run, strict):
+                    failed.append(cmd)
+                continue
+            print(f"Run '{cmd}' in {domain}:{container}", flush=True)
+            if dry_run:
+                continue
+            try:
+                # the error is raised here even without strict, so that a failure can be reported
+                # rather than only showing up in the streamed output
+                abra(*build_app_cmd(domain, cmd, chaos_flag), stream=True)
+            except RuntimeError as e:
+                if strict:
+                    raise click.ClickException(f"command '{cmd}' failed for {domain}: {e}")
+                logging.error(f"command '{cmd}' failed for {domain}: {e}")
+                failed.append(cmd)
+    return failed
 
 
 @click.group(context_settings={"help_option_names": ['-h', '--help']})
@@ -2054,9 +2105,71 @@ def deploy_apps(instance_apps: Dict[str, List[List]], execute_hooks: bool = Fals
             execute_cmds(app_config, deploy=True, instance_domain=instance)
 
 
+def run_upgrade_hooks(upgraded: List[Tuple[str, Dict[str, Any], str]], unhealthy: List[str]) -> List[Tuple[str, str]]:
+    """
+    Runs the upgrade hooks of every app that came back healthy and collects the ones that failed.
+
+    An app that never became healthy is left out: its hook would reach a container that is not
+    there, and the failure would say nothing beyond what the health check already said. A failing
+    hook is collected rather than raised, so that the apps behind it still get theirs.
+
+    Args:
+        upgraded (list): Tuples of app name, app configuration and instance domain
+        unhealthy (list): App domains whose services did not become healthy
+
+    Returns:
+        list: Tuples of app domain and the hook command that failed
+    """
+    failures = []
+    for app, app_config, instance_domain in upgraded:
+        domain = app_config.get('app_domain')
+        if domain in unhealthy:
+            logging.warning(f"{domain} is not healthy, its upgrade hooks are left out")
+            continue
+        logging.info(f"execute commands for {domain}")
+        failures += [(domain, cmd) for cmd in
+                     execute_cmds(app_config, upgrade=True, instance_domain=instance_domain)]
+    return failures
+
+
+def report_upgrade_run(total: int, failed: List[str], unhealthy: List[str],
+                       hook_failures: List[Tuple[str, str]]) -> None:
+    """
+    Reports what an upgrade run could not finish, and ends it when something needs a person.
+
+    An app that was refused and an app that never became healthy both leave the environment in a
+    state nobody asked for, so they end the run non-zero. A failing hook is reported only: hooks
+    still fail for reasons that are not failures, such as mariadb-upgrade refusing an already
+    upgraded database, and a verdict on them has to wait until those are sorted out.
+
+    Args:
+        total (int): How many apps the run set out to upgrade
+        failed (list): App domains abra refused to upgrade
+        unhealthy (list): App domains whose services did not become healthy
+        hook_failures (list): Tuples of app domain and the hook command that failed
+
+    Raises:
+        click.ClickException: If any app failed to upgrade or never became healthy
+    """
+    if hook_failures:
+        listed = ", ".join(f"{domain} '{cmd}'" for domain, cmd in hook_failures)
+        logging.error(f"{len(hook_failures)} upgrade hook(s) failed, "
+                      f"which does not end this run: {listed}")
+    problems = []
+    if failed:
+        problems.append(f"{len(failed)} of {total} app(s) failed to upgrade: {', '.join(failed)}")
+    if unhealthy:
+        problems.append(f"{len(unhealthy)} of {total} app(s) did not become healthy: "
+                        f"{', '.join(unhealthy)}")
+    if problems:
+        raise click.ClickException("\n".join(problems))
+
+
 @cli.command()
 @click.option('recipes', '-r', '--recipe', multiple=True, metavar='<RecipeName>', help='Filter for selcted recipes, this option can be specified multiple times.')
 @click.option('-e', '--execute-hooks', is_flag=True, help='run post-upgrade commands.')
+@click.option('skip_pre_upgrade_hooks', '--skip-pre-upgrade-hooks', is_flag=True,
+              help='leave out the pre-upgrade-hooks, which run unasked otherwise.')
 @click.option('-d', '--dry-run', is_flag=True, help="don't execute the upgrade process")
 @click.option('-rd', '--redeploy', is_flag=True, help="use undeploy and deploy for the updating process")
 @click.option('--redeploy-wait', type=int, default=20, metavar='<SECONDS>',
@@ -2065,12 +2178,14 @@ def deploy_apps(instance_apps: Dict[str, List[List]], execute_hooks: bool = Fals
 @click.option('--timeout', default=PS_WAIT_TIMEOUT, show_default=True, metavar='<Seconds>', help='how long to wait for all services to become healthy.')
 @click.option('--settle', default=PS_WAIT_SETTLE, show_default=True, metavar='<Seconds>', help='how long to give the replaced services to be taken down before their health is read.')
 @click.option('noninteractive', '-n', '--non-interactive', is_flag=True, help='Run this command non-interactively')
-def upgrade(recipes: Tuple[str], execute_hooks: bool, dry_run: bool, redeploy: bool,
-            converge_checks: bool, timeout: int, settle: int, noninteractive: bool, redeploy_wait: int) -> None:
+def upgrade(recipes: Tuple[str], execute_hooks: bool, skip_pre_upgrade_hooks: bool, dry_run: bool,
+            redeploy: bool, converge_checks: bool, timeout: int, settle: int, noninteractive: bool,
+            redeploy_wait: int) -> None:
     """
     Upgrades specified applications by executing the upgrade commands via the 'abra' command-line interface.
     It checks the current deployment status of the apps and performs upgrades only where necessary, with options to execute additional commands or perform a dry run. It either took the target version from the configuration or it uses the latest available version.
     The apps are upgraded without waiting for each other, then the run blocks until every service of them is healthy, and only then the upgrade hooks are executed.
+    A pre-upgrade hook runs before an app is replaced, while its old containers are still up. It is a precondition rather than an addition, so it needs no --execute-hooks and a failing one costs its app the upgrade.
     """
     deployed_instance_apps = get_apps_by_deployment(recipes, deployed=True)
     upgrade_cmds = []
@@ -2126,8 +2241,13 @@ def upgrade(recipes: Tuple[str], execute_hooks: bool, dry_run: bool, redeploy: b
         print(app)
         print(note)
     if dry_run:
+        # shown instead of run, so that a dry run answers what the hooks would have done. The
+        # pre-upgrade ones are not behind --execute-hooks and are therefore always listed
+        if not skip_pre_upgrade_hooks:
+            for _, app_config, _, instance_domain in upgrade_cmds:
+                execute_cmds(app_config, pre_upgrade=True, dry_run=True,
+                             instance_domain=instance_domain)
         if execute_hooks:
-            # shown instead of run, so that a dry run also answers what the -e would have done
             for _, app_config, _, instance_domain in upgrade_cmds:
                 execute_cmds(app_config, upgrade=True, dry_run=True, instance_domain=instance_domain)
         return
@@ -2141,6 +2261,10 @@ def upgrade(recipes: Tuple[str], execute_hooks: bool, dry_run: bool, redeploy: b
                 if missing := get_missing_secrets(app_domain):
                     print(f"{app_domain} is missing {len(missing)} secret(s): {', '.join(sorted(missing))}")
                     create_secrets((app,), instances=(instance_domain,))
+                if not skip_pre_upgrade_hooks:
+                    # before the undeploy below, which would leave the hook nothing to act on
+                    execute_cmds(app_config, pre_upgrade=True, strict=True,
+                                 instance_domain=instance_domain)
                 if redeploy:
                     upgrade_cmd.pop(0)
                     upgrade_cmd.insert(0, 'deploy')
@@ -2150,32 +2274,31 @@ def upgrade(recipes: Tuple[str], execute_hooks: bool, dry_run: bool, redeploy: b
                     sleep(redeploy_wait)
                 print(f'deploy {app_domain}')
                 print(abra("app", *upgrade_cmd))
-            except RuntimeError as error:
+            except (RuntimeError, click.ClickException) as error:
                 # the apps behind this one do not depend on it, so they are still upgraded and the
                 # run ends on the failure instead of dropping everything where it stands
                 logging.error(f"upgrade of {app_domain} failed: {error}")
                 failed.append(app_domain)
                 continue
             upgraded.append((app, app_config, instance_domain))
-        problems = []
-        if failed:
-            problems.append(
-                f"{len(failed)} of {len(upgrade_cmds)} app(s) failed to upgrade: {', '.join(failed)}")
+        unhealthy, hook_failures = [], []
         if upgraded:
             try:
                 # the deployments were started without waiting for each other, so the services are
                 # still settling here and a hook would reach a container that is not up again yet
-                wait_for_healthy_apps(tuple({app for app, *_ in upgraded}), timeout, settle=settle)
+                pending = get_unhealthy_apps(tuple({app for app, *_ in upgraded}), timeout,
+                                             settle=settle)
+                unhealthy = sorted({domain for domain, _ in pending})
+                if pending:
+                    logging.error(f"{len(pending)} service(s) still not healthy after {timeout}s:"
+                                  f"\n{format_pending_containers(pending)}")
             except click.ClickException as error:
-                # collected rather than raised, so that it cannot hide the apps that failed before
-                problems.append(error.message)
-            else:
-                if execute_hooks:
-                    for app, app_config, instance_domain in upgraded:
-                        logging.info(f"execute commands for {app_config.get('app_domain')}")
-                        execute_cmds(app_config, upgrade=True, instance_domain=instance_domain)
-        if problems:
-            raise click.ClickException("\n".join(problems))
+                # with nothing to read the health off, no app can be told apart from another
+                logging.error(error.message)
+                unhealthy = sorted(config.get('app_domain') for _, config, _ in upgraded)
+            if execute_hooks:
+                hook_failures = run_upgrade_hooks(upgraded, unhealthy)
+        report_upgrade_run(len(upgrade_cmds), failed, unhealthy, hook_failures)
 
 
 @cli.command()
@@ -2211,12 +2334,13 @@ def undeploy_apps(instance_apps: Dict[str, List[List]]) -> None:
 @cli.command()
 @click.option('recipes', '-r', '--recipe', multiple=True, metavar='<RecipeName>', help='Filter for selcted recipes, this option can be specified multiple times.')
 @click.option('commands', '-c', '--command', multiple=True, metavar="'<container_name> <abra.sh command> <optional arguments>'", help='commands that should be executed')
+@click.option('pre_upgrade', '-p', '--pre-upgrade', is_flag=True, help='execute pre-upgrade-hooks from config')
 @click.option('-i', '--initial', is_flag=True, help='execute initial-hooks from config')
 @click.option('-d', '--deploy', is_flag=True, help='execute deploy-hooks from config')
 @click.option('-u', '--upgrade', is_flag=True, help='execute upgrade-hooks from config')
 @click.option('-l', '--list-cmds', is_flag=True, help="only show cmds, don't execute them")
 @click.option('-C', '--chaos', is_flag=True, help="execute in chaos mode")
-def cmd(recipes: Tuple[str], commands: Tuple[str], initial: bool, deploy: bool, upgrade: bool, list_cmds: bool = False, chaos: bool = False) -> None:
+def cmd(recipes: Tuple[str], commands: Tuple[str], pre_upgrade: bool, initial: bool, deploy: bool, upgrade: bool, list_cmds: bool = False, chaos: bool = False) -> None:
     """
     Execute commands for all specified applications based on the provided configuration.
     """
@@ -2233,7 +2357,7 @@ def cmd(recipes: Tuple[str], commands: Tuple[str], initial: bool, deploy: bool,
                 print(f"{domain} is not deployed")
                 continue
             logging.info(f'execute commands for {domain}')
-            execute_cmds(app_config, commands=commands, initial=initial, deploy=deploy, upgrade=upgrade, dry_run=list_cmds, chaos=chaos, instance_domain=instance_domain)
+            execute_cmds(app_config, commands=commands, pre_upgrade=pre_upgrade, initial=initial, deploy=deploy, upgrade=upgrade, dry_run=list_cmds, chaos=chaos, instance_domain=instance_domain)
 
 
 @cli.command()
@@ -2725,13 +2849,13 @@ def print_containers(containers: List[Tuple[str, Dict[str, Any]]], verbose: bool
     print(tabulate(rows, 'firstrow', 'rounded_outline'), flush=True)
 
 
-def wait_for_healthy_apps(recipes: Tuple[str], timeout: int, verbose: bool = False, settle: int = 0) -> None:
+def get_unhealthy_apps(recipes: Tuple[str], timeout: int, verbose: bool = False, settle: int = 0) -> List[Tuple[str, Dict[str, Any]]]:
     """
-    Blocks until no service of the selected apps is starting, unknown or unhealthy any more.
+    Waits for the services of the selected apps to settle and reports the ones that never did.
 
     The status is checked after the settle delay and then every PS_WAIT_INTERVAL seconds until the
-    timeout is reached. Having nothing deployed is a failure rather than an early success: waiting
-    for the health of an environment that does not exist would report a broken deployment as green.
+    timeout is reached. Having nothing deployed is a failure rather than an early success: reading
+    the health of an environment that does not exist would report a broken deployment as green.
 
     The delay matters wherever apps are being replaced: such a service keeps reporting its old
     container for a moment, and that one is healthy, it has been running all along. Reading the
@@ -2739,13 +2863,17 @@ def wait_for_healthy_apps(recipes: Tuple[str], timeout: int, verbose: bool = Fal
     built from scratch has nothing to replace and leaves the delay at zero.
 
     Args:
-        recipes (tuple): Recipes to wait for, all of them if empty
+        recipes (tuple): Recipes to read, all of them if empty
         timeout (int): Seconds to wait before giving up
         verbose (bool): Add the chaos, state and image columns to the final table
         settle (int): Seconds to give replaced services to be taken down before the first check
 
+    Returns:
+        list: Tuples of app domain and container for every service that is still not healthy,
+            empty when all of them are
+
     Raises:
-        click.ClickException: If nothing is deployed, or if services are still not healthy when the timeout is reached
+        click.ClickException: If nothing is deployed
     """
     if settle:
         print(f"waiting {settle}s for the replaced services to be taken down", flush=True)
@@ -2760,15 +2888,49 @@ def wait_for_healthy_apps(recipes: Tuple[str], timeout: int, verbose: bool = Fal
         if not pending:
             print_containers(containers, verbose)
             print("All services are healthy")
-            return
+            return []
         if time() >= deadline:
             break
         waiting = ", ".join(f"{domain} {container['service']} ({container['status']})" for domain, container in pending)
         print(f"{len(pending)} service(s) not healthy yet, check again in {PS_WAIT_INTERVAL}s: {waiting}", flush=True)
         sleep(PS_WAIT_INTERVAL)
     print_containers(containers, verbose)
-    report = "\n".join(f"  {domain} {container['service']}: {container['status']}" for domain, container in pending)
-    raise click.ClickException(f"{len(pending)} service(s) still not healthy after {timeout}s:\n{report}")
+    return pending
+
+
+def format_pending_containers(pending: List[Tuple[str, Dict[str, Any]]]) -> str:
+    """
+    Renders the services that never became healthy as one indented line each.
+
+    Args:
+        pending (list): Tuples of app domain and container information
+
+    Returns:
+        str: One line per service, naming its app and its status
+    """
+    return "\n".join(f"  {domain} {container['service']}: {container['status']}"
+                     for domain, container in pending)
+
+
+def wait_for_healthy_apps(recipes: Tuple[str], timeout: int, verbose: bool = False, settle: int = 0) -> None:
+    """
+    Blocks until no service of the selected apps is starting, unknown or unhealthy any more.
+
+    For a caller that has something left to do for the apps that did come back, get_unhealthy_apps()
+    reports them instead of ending the run.
+
+    Args:
+        recipes (tuple): Recipes to wait for, all of them if empty
+        timeout (int): Seconds to wait before giving up
+        verbose (bool): Add the chaos, state and image columns to the final table
+        settle (int): Seconds to give replaced services to be taken down before the first check
+
+    Raises:
+        click.ClickException: If nothing is deployed, or if services are still not healthy when the timeout is reached
+    """
+    if pending := get_unhealthy_apps(recipes, timeout, verbose, settle):
+        raise click.ClickException(f"{len(pending)} service(s) still not healthy after {timeout}s:"
+                                   f"\n{format_pending_containers(pending)}")
 
 
 def get_deployment_traces(recipes: Tuple[str]) -> List[str]:

tests/test_retry.py

@@ -1,5 +1,6 @@
 """Tests for which abra failures may be retried."""
 
+import logging
 import os
 import sys
 
@@ -9,7 +10,7 @@ import pytest
 sys.path.insert(0, os.path.dirname(os.path.dirname(os.path.abspath(__file__))))
 
 import alakazam
-from alakazam import abra, is_connection_error
+from alakazam import abra, get_retry_reason, is_connection_error
 
 
 class FakeProcess:
@@ -21,19 +22,22 @@ class FakeProcess:
 
 UNREACHABLE = b"FATA error during connect: kex_exchange_identification: Connection closed by remote host"
 REJECTED = b"FATA login.a.org is still deployed"
+AMBIGUOUS = (b"WARN ambiguous container list received, prompting for input\n"
+             b"? which container are you looking for?\nFATA EOF")
+
+
+@pytest.fixture
+def runs(monkeypatch):
+    """Hands out a prepared result per abra call and records what was slept between them."""
+    calls = {"results": [], "slept": []}
+    monkeypatch.setattr(alakazam, "sleep", calls["slept"].append)
+    monkeypatch.setattr(alakazam.subprocess, "run", lambda cmd, capture_output: calls["results"].pop(0))
+    return calls
 
 
 class TestRetryLoop:
     """A server that drops the ssh handshake is usually throttling, so the retries have to spread out."""
 
-    @pytest.fixture
-    def runs(self, monkeypatch):
-        calls = {"results": [], "slept": []}
-        monkeypatch.setattr(alakazam, "sleep", calls["slept"].append)
-        monkeypatch.setattr(alakazam.subprocess, "run",
-                            lambda cmd, capture_output: calls["results"].pop(0))
-        return calls
-
     def test_a_successful_command_does_not_retry(self, runs):
         runs["results"] = [FakeProcess(0)]
         abra("app", "ls")
@@ -83,3 +87,35 @@ class TestConnectionErrors:
     ])
     def test_operational_failures_are_not_retried(self, output):
         assert not is_connection_error(output)
+
+
+class TestAmbiguousContainer:
+    """
+    An app that was just updated keeps its replaced container for a while, and abra then cannot
+    tell which of the two a command is meant for. It asks, and a run without a terminal ends on EOF.
+    """
+
+    @pytest.mark.parametrize("output", [
+        "WARN ambiguous container list received, prompting for input\nFATA EOF",
+        "FATA expected 1 container but found 2: files_app.1.pxo3 (created About a minute ago)",
+    ])
+    def test_it_is_worth_another_attempt(self, output):
+        assert get_retry_reason(output) == ("found more than one container, "
+                                            "the replaced one has not gone away yet")
+
+    def test_an_unreachable_server_keeps_its_own_reason(self):
+        assert get_retry_reason("kex_exchange_identification") == "failed to reach the server"
+
+    def test_a_rejected_operation_is_worth_none(self):
+        assert get_retry_reason("FATA login.a.org is still deployed") is None
+
+    def test_the_command_is_repeated_until_one_container_is_left(self, runs):
+        runs["results"] = [FakeProcess(1, AMBIGUOUS), FakeProcess(1, AMBIGUOUS), FakeProcess(0)]
+        abra("app", "cmd", "-T", "files.a.org", "app", "--", "run_occ", "upgrade")
+        assert runs["slept"] == [alakazam.ABRA_RETRY_DELAY, alakazam.ABRA_RETRY_DELAY * 2]
+
+    def test_the_reason_is_reported(self, runs, caplog):
+        runs["results"] = [FakeProcess(1, AMBIGUOUS), FakeProcess(0)]
+        with caplog.at_level(logging.WARNING):
+            abra("app", "cmd", "-T", "files.a.org", "app", "--", "run_occ", "upgrade")
+        assert "the replaced one has not gone away yet" in caplog.text

tests/test_upgrade_hooks.py

@@ -12,10 +12,14 @@ sys.path.insert(0, os.path.dirname(os.path.dirname(os.path.abspath(__file__))))
 
 import alakazam
 
+# only nextcloud carries a pre-upgrade hook, so that "not configured" is distinguishable from
+# "configured but not run"
 CONFIG = {"a.org": {
     "nextcloud": {"app_domain": "cloud.a.org", "server": "a.org", "version": "2.0.0",
+                  "pre-upgrade-hooks": ["db update_mongo_version"],
                   "upgrade-hooks": ["app occ upgrade"]},
-    "wekan": {"app_domain": "boards.a.org", "server": "a.org", "version": "2.0.0"},
+    "wekan": {"app_domain": "boards.a.org", "server": "a.org", "version": "2.0.0",
+              "upgrade-hooks": ["app ready"]},
 }}
 
 # kept before any fixture replaces it, for the tests that check what a dry run actually prints
@@ -35,9 +39,19 @@ def steps(monkeypatch, versions):
     monkeypatch.setattr(alakazam, "INSTANCE_CONFIGS", CONFIG)
     monkeypatch.setattr(alakazam, "sleep", lambda seconds: steps.append(f"sleep:{seconds}"))
     monkeypatch.setattr(alakazam, "get_missing_secrets", lambda domain: [])
-    # a dry run reaches the same function, so the two have to be told apart here
-    monkeypatch.setattr(alakazam, "execute_cmds", lambda config, dry_run=False, **kw: steps.append(
-        f"{'show' if dry_run else 'hook'}:{config['app_domain']}"))
+    def execute_cmds(config, dry_run=False, **kw):
+        """
+        Labels a hook call by kind, and keeps quiet for an app that configures none of that kind.
+
+        selected() matches on a prefix, so the pre-upgrade label needs one of its own rather than a
+        suffix: "hook:pre:..." would be picked up by every assertion on "hook:".
+        """
+        kind, key = ("pre-hook", "pre-upgrade-hooks") if kw.get("pre_upgrade") else ("hook", "upgrade-hooks")
+        if config.get(key):
+            steps.append(f"{'show:' if dry_run else ''}{kind}:{config['app_domain']}")
+        return []   # the commands that failed, which execute_cmds reports back
+
+    monkeypatch.setattr(alakazam, "execute_cmds", execute_cmds)
 
     # the recipe filter has to be honoured here, it is what the wait narrows itself down with
     def apps_by_deployment(recipes, deployed=True):
@@ -59,6 +73,11 @@ def steps(monkeypatch, versions):
     return steps
 
 
+def unhealthy(*domains):
+    """What get_unhealthy_apps() reports for services that never settled."""
+    return [(domain, {"service": "app", "status": "starting"}) for domain in domains]
+
+
 def selected(steps, prefix):
     return [step for step in steps if step.startswith(prefix)]
 
@@ -164,8 +183,10 @@ class TestDryRun:
 
     def test_a_shown_hook_is_not_executed(self, steps):
         run(["--dry-run", "-e"], input="\n")
-        assert selected(steps, "show:") == ["show:cloud.a.org", "show:boards.a.org"]
+        assert selected(steps, "show:") == ["show:pre-hook:cloud.a.org",
+                                            "show:hook:cloud.a.org", "show:hook:boards.a.org"]
         assert selected(steps, "hook:") == []
+        assert selected(steps, "pre-hook:") == []
 
 
 class TestSettleOption:
@@ -234,16 +255,213 @@ class TestAFailingApp:
         assert "2 of 2 app(s) failed" in result.exception.message
         assert selected(steps, "ps:") == []
 
-    def test_a_failing_wait_does_not_hide_the_failing_app(self, failing, monkeypatch):
+    def test_an_unhealthy_app_does_not_hide_the_failing_one(self, failing, monkeypatch):
         """One failure covering up another is how a broken app slips through a green pipeline."""
-        monkeypatch.setattr(alakazam, "wait_for_healthy_apps", lambda *a, **k: (_ for _ in ()).throw(
-            click.ClickException("1 service(s) still not healthy after 900s")))
+        monkeypatch.setattr(alakazam, "get_unhealthy_apps", lambda *a, **k: unhealthy("boards.a.org"))
         message = self.invoke(["-e"]).exception.message
-        assert "cloud.a.org" in message
-        assert "still not healthy" in message
+        assert "failed to upgrade: cloud.a.org" in message
+        assert "did not become healthy: boards.a.org" in message
 
-    def test_the_hooks_stay_out_when_the_wait_failed(self, failing, monkeypatch):
-        monkeypatch.setattr(alakazam, "wait_for_healthy_apps", lambda *a, **k: (_ for _ in ()).throw(
-            click.ClickException("1 service(s) still not healthy after 900s")))
+
+class TestPreUpgradeHooks:
+    """
+    A pre-upgrade hook prepares an app while its old containers still run, which is the only moment
+    some migrations have: mongo refuses to start on data whose feature compatibility version is two
+    majors behind the binary, so the version has to be raised before the binary is replaced.
+    """
+
+    def test_it_runs_before_that_app_is_deployed(self, steps):
+        run(["-n"])
+        upgrade = next(s for s in steps if "app upgrade" in s and "cloud.a.org" in s)
+        assert steps.index("pre-hook:cloud.a.org") < steps.index(upgrade)
+
+    def test_it_runs_before_the_undeploy_of_a_redeploy(self, steps):
+        """After an undeploy there is nothing left for the hook to read or change."""
+        run(["-n", "--redeploy"])
+        undeploy = next(s for s in steps if "app undeploy" in s and "cloud.a.org" in s)
+        assert steps.index("pre-hook:cloud.a.org") < steps.index(undeploy)
+
+    def test_it_runs_without_execute_hooks(self, steps):
+        """Unlike the other kinds: skipping a precondition does not skip work, it breaks the app."""
+        run(["-n"])
+        assert selected(steps, "pre-hook:") == ["pre-hook:cloud.a.org"]
+        assert selected(steps, "hook:") == []
+
+    def test_an_app_that_configures_none_gets_none(self, steps):
+        run(["-n"])
+        assert "pre-hook:boards.a.org" not in steps
+
+    def test_an_app_already_at_its_version_gets_none(self, steps, versions):
+        versions["nextcloud"] = "2.0.0"
+        run(["-n"])
+        assert selected(steps, "pre-hook:") == []
+
+    def test_the_flag_leaves_them_out(self, steps):
+        run(["-n", "--skip-pre-upgrade-hooks"])
+        assert selected(steps, "pre-hook:") == []
+        assert any("app upgrade" in s for s in steps)
+
+    def test_a_dry_run_shows_them_and_runs_nothing(self, steps):
+        run(["--dry-run"], input="\n")
+        assert selected(steps, "show:") == ["show:pre-hook:cloud.a.org"]
+        assert selected(steps, "pre-hook:") == []
+        assert not any("app upgrade" in s and "-r" not in s for s in steps)
+
+    def test_a_dry_run_honours_the_skip(self, steps):
+        run(["--dry-run", "--skip-pre-upgrade-hooks"], input="\n")
+        assert selected(steps, "show:") == []
+
+
+class TestAFailingPreUpgradeHook:
+    """It is a precondition, so it costs its own app the upgrade and no other app anything."""
+
+    @pytest.fixture
+    def failing(self, monkeypatch, steps):
+        def execute_cmds(config, dry_run=False, **kw):
+            if kw.get("pre_upgrade"):
+                if not config.get("pre-upgrade-hooks"):
+                    return
+                # what execute_cmds(strict=True) raises for a command the recipe does not have
+                raise click.ClickException(
+                    "command 'db update_mongo_version' failed for cloud.a.org: "
+                    "FATA no db function in abra.sh")
+            steps.append(f"hook:{config['app_domain']}")
+            return []
+
+        monkeypatch.setattr(alakazam, "execute_cmds", execute_cmds)
+        return steps
+
+    def invoke(self, args):
+        return CliRunner().invoke(alakazam.upgrade, ["-n"] + args, standalone_mode=False)
+
+    def test_that_app_is_not_upgraded(self, failing):
+        self.invoke([])
+        assert not any("app upgrade" in s and "cloud.a.org" in s for s in failing)
+
+    def test_the_other_app_still_is(self, failing):
+        self.invoke([])
+        assert any("app upgrade" in s and "boards.a.org" in s for s in failing)
+
+    def test_the_run_ends_naming_the_app(self, failing):
+        result = self.invoke([])
+        assert isinstance(result.exception, click.ClickException)
+        assert "1 of 2 app(s) failed to upgrade: cloud.a.org" in result.exception.message
+
+    def test_the_failing_app_is_neither_waited_for_nor_hooked(self, failing):
         self.invoke(["-e"])
-        assert selected(failing, "hook:") == []
+        assert selected(failing, "ps:") == ["ps:boards.a.org"]
+        assert selected(failing, "hook:") == ["hook:boards.a.org"]
+
+    def test_the_reason_is_reported(self, failing, caplog):
+        with caplog.at_level(logging.ERROR):
+            self.invoke([])
+        assert "no db function in abra.sh" in caplog.text
+
+
+class TestDryRunNamesTheHookKind:
+    """
+    A real run has "deploy <domain>" between the kinds; a dry run prints them back to back, so the
+    kind has to be named or a pre-upgrade hook is indistinguishable from an identical later one.
+    """
+
+    @pytest.fixture
+    def output(self, steps, monkeypatch):
+        monkeypatch.setattr(alakazam, "execute_cmds", REAL_EXECUTE_CMDS)
+        return run(["--dry-run", "-e"], input="\n").output
+
+    def test_both_kinds_are_named(self, output):
+        assert "pre-upgrade-hooks for cloud.a.org:" in output
+        assert "upgrade-hooks for cloud.a.org:" in output
+
+    def test_the_pre_upgrade_kind_comes_first(self, output):
+        assert output.index("pre-upgrade-hooks for cloud.a.org:") < output.index("upgrade-hooks for")
+
+    def test_an_app_without_the_kind_does_not_announce_it(self, output):
+        assert "pre-upgrade-hooks for boards.a.org:" not in output
+
+    def test_a_real_run_names_no_kind(self, steps, monkeypatch):
+        """There the deployment output separates them, and the label would only be noise."""
+        monkeypatch.setattr(alakazam, "execute_cmds", REAL_EXECUTE_CMDS)
+        output = run(["-n", "-e"]).output
+        assert "upgrade-hooks for" not in output
+        assert "Run 'db update_mongo_version' in cloud.a.org:db" in output
+
+
+class TestAnUnhealthyApp:
+    """
+    An app that does not come back must not cost the apps that did their hooks: a run over twenty
+    apps would otherwise leave nineteen of them half migrated because of one.
+    """
+
+    @pytest.fixture
+    def sick(self, monkeypatch, steps):
+        monkeypatch.setattr(alakazam, "get_unhealthy_apps", lambda *a, **k: unhealthy("cloud.a.org"))
+        return steps
+
+    def invoke(self, args):
+        return CliRunner().invoke(alakazam.upgrade, ["-n"] + args, standalone_mode=False)
+
+    def test_the_healthy_app_still_gets_its_hooks(self, sick):
+        self.invoke(["-e"])
+        assert selected(sick, "hook:") == ["hook:boards.a.org"]
+
+    def test_the_unhealthy_app_does_not(self, sick):
+        """Its hook would reach a container that is not there."""
+        self.invoke(["-e"])
+        assert "hook:cloud.a.org" not in sick
+
+    def test_it_is_reported_and_ends_the_run(self, sick):
+        result = self.invoke(["-e"])
+        assert isinstance(result.exception, click.ClickException)
+        assert "1 of 2 app(s) did not become healthy: cloud.a.org" in result.exception.message
+
+    def test_a_health_check_that_reads_nothing_distrusts_every_app(self, steps, monkeypatch):
+        """Without a status for any of them, none of them can be told apart from a broken one."""
+        monkeypatch.setattr(alakazam, "get_unhealthy_apps", lambda *a, **k: (_ for _ in ()).throw(
+            click.ClickException("no apps are deployed, there is nothing to wait for")))
+        result = self.invoke(["-e"])
+        assert selected(steps, "hook:") == []
+        assert "boards.a.org" in result.exception.message
+        assert "cloud.a.org" in result.exception.message
+
+
+class TestAFailingUpgradeHook:
+    """
+    Reported but not a verdict: hooks still fail for reasons that are not failures, so they are
+    collected until those are sorted out and only then become something the run ends on.
+    """
+
+    @pytest.fixture
+    def broken(self, monkeypatch, steps):
+        def execute_cmds(config, dry_run=False, **kw):
+            if kw.get("pre_upgrade"):
+                return []
+            steps.append(f"hook:{config['app_domain']}")
+            return ["app occ upgrade"] if config["app_domain"] == "cloud.a.org" else []
+
+        monkeypatch.setattr(alakazam, "execute_cmds", execute_cmds)
+        return steps
+
+    def invoke(self, args):
+        return CliRunner().invoke(alakazam.upgrade, ["-n"] + args, standalone_mode=False)
+
+    def test_the_run_still_succeeds(self, broken):
+        result = self.invoke(["-e"])
+        assert result.exit_code == 0, result.exception
+
+    def test_it_is_reported(self, broken, caplog):
+        with caplog.at_level(logging.ERROR):
+            self.invoke(["-e"])
+        assert "1 upgrade hook(s) failed" in caplog.text
+        assert "cloud.a.org 'app occ upgrade'" in caplog.text
+
+    def test_the_other_apps_keep_their_hooks(self, broken):
+        self.invoke(["-e"])
+        assert selected(broken, "hook:") == ["hook:cloud.a.org", "hook:boards.a.org"]
+
+    def test_it_is_reported_next_to_a_failure_that_does_end_the_run(self, broken, monkeypatch, caplog):
+        monkeypatch.setattr(alakazam, "get_unhealthy_apps", lambda *a, **k: unhealthy("boards.a.org"))
+        with caplog.at_level(logging.ERROR):
+            result = self.invoke(["-e"])
+        assert "upgrade hook(s) failed" in caplog.text
+        assert "did not become healthy: boards.a.org" in result.exception.message