Misc/improve logging

aiidalab_launch/__main__.py

@@ -394,6 +394,7 @@ async def _async_start(
                     echo_logs = asyncio.create_task(instance.echo_logs())
                     await asyncio.wait_for(instance.wait_for_services(), timeout=wait)
                     echo_logs.cancel()
+                    LOGGER.debug("AiiDAlab instance ready.")
             except asyncio.TimeoutError:
                 raise click.ClickException(
                     f"AiiDAlab instance did not start up within the provided wait period ({wait})."
@@ -404,6 +405,7 @@ async def _async_start(
                     "the container output logs by increasing the output "
                     "verbosity with 'aiidalab-launch -vvv start'."
                 )
+            LOGGER.debug("Preparing startup message.")
             msg_startup = (
                 MSG_STARTUP_SSH
                 if (show_ssh_help or not webbrowser_available())

aiidalab_launch/instance.py

@@ -3,13 +3,13 @@
 from __future__ import annotations
 
 import asyncio
-import logging
 from contextlib import contextmanager
 from dataclasses import dataclass
 from enum import Enum, auto
 from pathlib import Path, PurePosixPath
 from secrets import token_hex
 from shutil import rmtree
+from time import time
 from typing import Any, AsyncGenerator, Generator
 
 import docker
@@ -186,17 +186,18 @@ def restart(self) -> None:
 
     def _run_post_start(self) -> None:
         assert self.container is not None
-        logging.debug("Run post-start commands.")
+        LOGGER.debug("Run post-start commands.")
 
-        logging.debug("Ensure ~/.conda directory is owned by the system user.")
+        LOGGER.debug("Ensure ~/.conda directory is owned by the system user.")
         exit_code, _ = self.container.exec_run(
             f"chown -R 1000:1000 /home/{self.profile.system_user}/.conda",
             privileged=True,
         )
         if exit_code != 0:
-            logging.warn(
+            LOGGER.warn(
                 "Failed to ensure ~/.conda directory is owned by the system user."
             )
+        LOGGER.debug("The ~/.conda directory is owned by the system user.")
 
     def stop(self, timeout: float | None = None) -> None:
         self._requires_container()
@@ -217,7 +218,7 @@ def remove(self, conda: bool = False, data: bool = False) -> None:
             try:
                 self.client.volumes.get(self.profile.conda_volume_name()).remove()
             except docker.errors.NotFound:  # already removed
-                logging.debug(
+                LOGGER.debug(
                     f"Failed to remove conda volume '{self.profile.conda_volume_name()}', likely already removed."
                 )
             except Exception as error:  # unexpected error
@@ -269,26 +270,28 @@ async def echo_logs(self) -> None:
     async def _init_scripts_finished(self) -> None:
         assert self.container is not None
         loop = asyncio.get_event_loop()
-        logging.info("Waiting for init services to finish...")
+        LOGGER.debug("Waiting for init services to finish...")
         result = await loop.run_in_executor(
             None, self.container.exec_run, "wait-for-services"
         )
         if result.exit_code != 0:
             raise FailedToWaitForServices(
                 "Failed to check for init processes to complete."
             )
+        LOGGER.debug("Init services finished.")
 
     async def _notebook_service_online(self) -> None:
         assert self.container is not None
         loop = asyncio.get_event_loop()
-        logging.info("Waiting for notebook service to become reachable...")
+        LOGGER.debug("Waiting for notebook service to become reachable...")
         while True:
             result = await loop.run_in_executor(
                 None,
                 self.container.exec_run,
                 "curl --fail-early --fail --silent --max-time 1.0 http://localhost:8888",
             )
             if result.exit_code == 0:
+                LOGGER.debug("Notebook service reachable.")
                 return  # jupyter is online
             elif result.exit_code in (7, 28):
                 await asyncio.sleep(1)  # jupyter not yet reachable
@@ -299,9 +302,11 @@ async def _notebook_service_online(self) -> None:
     async def _host_port_assigned(self) -> None:
         container = self.container
         assert container is not None
+        LOGGER.debug("Waiting for host port to be assigned...")
         while True:
             container.reload()
             if any(_get_host_ports(container)):
+                LOGGER.debug("Host port assigned.")
                 break
             asyncio.sleep(1)
 
@@ -310,11 +315,15 @@ async def wait_for_services(self) -> None:
             raise RuntimeError("Instance was not created.")
 
         LOGGER.info(f"Waiting for services to come up ({self.container.id})...")
+        start = time()
         await asyncio.gather(
             self._init_scripts_finished(),
             self._notebook_service_online(),
             self._host_port_assigned(),
         )
+        LOGGER.info(
+            f"Services came up after {time() - start:.1f} seconds ({self.container.id})."
+        )
 
     async def status(self, timeout: float | None = 5.0) -> AiidaLabInstanceStatus:
         if self.container:

aiidalab_launch/util.py

@@ -1,5 +1,4 @@
 import asyncio
-import logging
 import re
 import webbrowser
 from contextlib import contextmanager
@@ -15,6 +14,8 @@
 from packaging.version import Version, parse
 from requests_cache import CachedSession
 
+from .core import LOGGER
+
 MSG_UNABLE_TO_COMMUNICATE_WITH_CLIENT = (
     "Unable to communicate with docker on this host. This error usually indicates "
     "that Docker is either not installed on this system, that the docker service is "
@@ -143,10 +144,10 @@ def get_latest_version(timeout: float = 0.1) -> Optional[Version]:
         )
         return parse(releases[-1]) if releases else None
     except (requests.exceptions.Timeout, requests.exceptions.ReadTimeout):
-        logging.debug("Timed out while requesting latest version.")
+        LOGGER.debug("Timed out while requesting latest version.")
         return None
     except OSError as error:
-        logging.debug(f"Error while requesting latest version: {error}")
+        LOGGER.debug(f"Error while requesting latest version: {error}")
         return None