From 6bb033ecda9e213d0c46e4431384c7dd4ae3c5e0 Mon Sep 17 00:00:00 2001 From: Joshua Li Date: Fri, 17 Apr 2026 15:19:15 -0700 Subject: [PATCH] feat: timestamps and health logs --- devservices/commands/logs.py | 60 ++++++++++++++--- devservices/utils/console.py | 9 ++- devservices/utils/docker.py | 46 +++++++++++++ tests/commands/test_logs.py | 123 ++++++++++++++++++++++++++++++++--- tests/utils/test_docker.py | 110 +++++++++++++++++++++++++++++++ 5 files changed, 328 insertions(+), 20 deletions(-) diff --git a/devservices/commands/logs.py b/devservices/commands/logs.py index 84ebf3d..75d61b1 100644 --- a/devservices/commands/logs.py +++ b/devservices/commands/logs.py @@ -26,6 +26,9 @@ from devservices.utils.console import Console from devservices.utils.dependencies import InstalledRemoteDependency from devservices.utils.dependencies import install_and_verify_dependencies +from devservices.utils.docker import get_container_health +from devservices.utils.docker_compose import DockerComposeCommand +from devservices.utils.docker_compose import get_container_names_for_project from devservices.utils.docker_compose import get_docker_compose_commands_to_run from devservices.utils.docker_compose import run_cmd from devservices.utils.services import Service @@ -103,7 +106,9 @@ def logs(args: Namespace) -> None: ) exit(1) try: - logs_output = _logs(service, remote_dependencies, list(mode_dependencies)) + logs_output, docker_compose_commands = _logs( + service, list(remote_dependencies), list(mode_dependencies) + ) except DockerComposeError as dce: capture_exception(dce, level="info") console.failure(f"Failed to get logs for {service.name}: {dce.stderr}") @@ -129,12 +134,14 @@ def logs(args: Namespace) -> None: console.info(f"=== Logs for supervisor program: {program_name} ===") console.info(log_content) + _print_health_logs(console, docker_compose_commands) + def _logs( service: Service, - remote_dependencies: set[InstalledRemoteDependency], + remote_dependencies: list[InstalledRemoteDependency], mode_dependencies: list[str], -) -> list[subprocess.CompletedProcess[str]]: +) -> tuple[list[subprocess.CompletedProcess[str]], list[DockerComposeCommand]]: relative_local_dependency_directory = os.path.relpath( os.path.join(DEVSERVICES_DEPENDENCIES_CACHE_DIR, DEPENDENCY_CONFIG_VERSION), service.repo_path, @@ -142,23 +149,20 @@ def _logs( service_config_file_path = os.path.join( service.repo_path, DEVSERVICES_DIR_NAME, CONFIG_FILE_NAME ) - # Set the environment variable for the local dependencies directory to be used by docker compose current_env = os.environ.copy() current_env[DEVSERVICES_DEPENDENCIES_CACHE_DIR_KEY] = ( relative_local_dependency_directory ) docker_compose_commands = get_docker_compose_commands_to_run( service=service, - remote_dependencies=list(remote_dependencies), + remote_dependencies=remote_dependencies, current_env=current_env, command="logs", - options=["-n", MAX_LOG_LINES], + options=["--timestamps", "-n", MAX_LOG_LINES], service_config_file_path=service_config_file_path, mode_dependencies=mode_dependencies, ) - cmd_outputs = [] - with concurrent.futures.ThreadPoolExecutor() as executor: futures = [ executor.submit(run_cmd, cmd.full_command, current_env) @@ -166,8 +170,46 @@ def _logs( ] for future in concurrent.futures.as_completed(futures): cmd_outputs.append(future.result()) + return cmd_outputs, docker_compose_commands + + +def _print_health_logs( + console: Console, docker_compose_commands: list[DockerComposeCommand] +) -> None: + container_names: list[str] = [] + for cmd in docker_compose_commands: + try: + container_names += [ + c.name + for c in get_container_names_for_project( + cmd.project_name, cmd.config_path, cmd.services + ) + ] + except Exception: + continue + + if not container_names: + return + + health_results = get_container_health(container_names) + if not health_results: + return - return cmd_outputs + console.info("=== Container health ===") + for h in health_results: + if h.status == "healthy": + console.success(f" {h.name}: {h.status}") + elif h.status in ("unhealthy", "starting"): + console.warning(f" {h.name}: {h.status}") + else: + console.info(f" {h.name}: no healthcheck") + + for h in health_results: + if not h.log or h.status == "healthy": + continue + console.info(f"\n--- {h.name} health check log ---") + for entry in h.log: + console.info(f" exit={entry.exit_code} {entry.output}") def _supervisor_logs( diff --git a/devservices/utils/console.py b/devservices/utils/console.py index af3a66f..781acc7 100644 --- a/devservices/utils/console.py +++ b/devservices/utils/console.py @@ -20,10 +20,13 @@ def __new__(cls) -> Console: cls._instance = super(Console, cls).__new__(cls) return cls._instance - def print(self, message: str, color: str = "", bold: bool = False) -> None: + def print( + self, message: str, color: str = "", bold: bool = False, cr: bool = False + ) -> None: color = color + (Color.BOLD if bold else "") end = Color.RESET if color != "" or bold else "" - sys.stdout.write(color + message + end + "\n") + prefix = "\r" if cr else "" + sys.stdout.write(prefix + color + message + end + "\n") sys.stdout.flush() def success(self, message: str, bold: bool = False) -> None: @@ -60,7 +63,7 @@ def __init__( self.console = Console() def print(self, message: str, color: str = "", bold: bool = False) -> None: - self.console.print("\r" + message, color=color, bold=bold) + self.console.print(message, color=color, bold=bold, cr=True) def success(self, message: str, bold: bool = False) -> None: self.print(message=message, color=Color.GREEN, bold=bold) diff --git a/devservices/utils/docker.py b/devservices/utils/docker.py index b2725d0..6992dfd 100644 --- a/devservices/utils/docker.py +++ b/devservices/utils/docker.py @@ -1,8 +1,11 @@ from __future__ import annotations import concurrent.futures +import json import subprocess import time +from dataclasses import dataclass +from dataclasses import field from typing import NamedTuple from devservices.constants import HEALTHCHECK_INTERVAL @@ -96,6 +99,49 @@ def wait_for_healthy(container: ContainerNames, status: Status) -> None: raise ContainerHealthcheckFailedError(container.short_name, HEALTHCHECK_TIMEOUT) +@dataclass +class HealthCheckEntry: + exit_code: int + output: str + + +@dataclass +class ContainerHealth: + name: str + status: str # "healthy", "unhealthy", "starting", or "none" + log: list[HealthCheckEntry] = field(default_factory=list) + + +def get_container_health(container_names: list[str]) -> list[ContainerHealth]: + """Return health check status and last log entries for each container.""" + if not container_names: + return [] + try: + raw = subprocess.check_output( + ["docker", "inspect", *container_names], + text=True, + stderr=subprocess.DEVNULL, + ) + except subprocess.CalledProcessError: + return [] + + results = [] + for c in json.loads(raw): + name = c["Name"].lstrip("/") + health = c["State"].get("Health") + if health is None: + results.append(ContainerHealth(name=name, status="none")) + else: + entries = [ + HealthCheckEntry(exit_code=e["ExitCode"], output=e["Output"].strip()) + for e in health.get("Log", []) + ] + results.append( + ContainerHealth(name=name, status=health["Status"], log=entries) + ) + return results + + def get_matching_containers(labels: list[str]) -> list[str]: """ Returns a list of container names with the given label diff --git a/tests/commands/test_logs.py b/tests/commands/test_logs.py index 1583579..b336084 100644 --- a/tests/commands/test_logs.py +++ b/tests/commands/test_logs.py @@ -8,6 +8,7 @@ import pytest +from devservices.commands.logs import _print_health_logs from devservices.commands.logs import _supervisor_logs from devservices.commands.logs import logs from devservices.configs.service_config import load_service_config_from_file @@ -17,6 +18,10 @@ from devservices.exceptions import DependencyError from devservices.exceptions import DockerComposeError from devservices.exceptions import SupervisorError +from devservices.utils.console import Console +from devservices.utils.docker import ContainerHealth +from devservices.utils.docker import HealthCheckEntry +from devservices.utils.docker_compose import DockerComposeCommand from devservices.utils.services import Service from devservices.utils.state import StateTables from testing.utils import create_config_file @@ -153,6 +158,7 @@ def test_logs_no_specified_service_success( "logs", "clickhouse", "redis", + "--timestamps", "-n", "100", ], @@ -184,6 +190,7 @@ def test_logs_no_specified_service_success( "logs", "clickhouse", "redis", + "--timestamps", "-n", "100", ], @@ -422,13 +429,16 @@ def test_logs_with_supervisor_dependencies( args = Namespace(service_name="test-service") mock_get_service_entries.return_value = ["test-service"] mock_install_and_verify_dependencies.return_value = set() - mock_logs.return_value = [ - subprocess.CompletedProcess( - args=["docker", "compose", "logs"], - returncode=0, - stdout="docker logs output", - ) - ] + mock_logs.return_value = ( + [ + subprocess.CompletedProcess( + args=["docker", "compose", "logs"], + returncode=0, + stdout="docker logs output", + ) + ], + [], + ) mock_supervisor_logs.return_value = {"worker": "supervisor worker logs output"} logs(args) @@ -610,7 +620,7 @@ def test_logs_with_active_modes( [], # started modes ] mock_install_and_verify_dependencies.return_value = set() - mock_logs.return_value = [] + mock_logs.return_value = ([], []) logs(args) @@ -720,3 +730,100 @@ def test_supervisor_logs_supervisor_error( "test-service", str(config_file_path) ) mock_manager.get_program_logs.assert_called_once_with("worker") + + +@mock.patch("devservices.commands.logs.get_container_health") +@mock.patch("devservices.commands.logs.get_container_names_for_project") +def test_print_health_logs_no_containers( + mock_get_container_names: mock.Mock, + mock_get_container_health: mock.Mock, + capsys: pytest.CaptureFixture[str], +) -> None: + mock_get_container_names.return_value = [] + console = Console() + _print_health_logs(console, [DockerComposeCommand([], "proj", "/path", [])]) + mock_get_container_health.assert_not_called() + assert capsys.readouterr().out == "" + + +@mock.patch("devservices.commands.logs.get_container_health") +@mock.patch("devservices.commands.logs.get_container_names_for_project") +def test_print_health_logs_all_healthy( + mock_get_container_names: mock.Mock, + mock_get_container_health: mock.Mock, + capsys: pytest.CaptureFixture[str], +) -> None: + from devservices.utils.docker import ContainerNames + + mock_get_container_names.return_value = [ + ContainerNames(name="proj-redis-1", short_name="redis") + ] + mock_get_container_health.return_value = [ + ContainerHealth(name="proj-redis-1", status="healthy", log=[]) + ] + console = Console() + _print_health_logs(console, [DockerComposeCommand([], "proj", "/path", ["redis"])]) + out = capsys.readouterr().out + assert "=== Container health ===" in out + assert "proj-redis-1: healthy" in out + + +@mock.patch("devservices.commands.logs.get_container_health") +@mock.patch("devservices.commands.logs.get_container_names_for_project") +def test_print_health_logs_unhealthy_with_log( + mock_get_container_names: mock.Mock, + mock_get_container_health: mock.Mock, + capsys: pytest.CaptureFixture[str], +) -> None: + from devservices.utils.docker import ContainerNames + + mock_get_container_names.return_value = [ + ContainerNames(name="proj-redis-1", short_name="redis") + ] + mock_get_container_health.return_value = [ + ContainerHealth( + name="proj-redis-1", + status="unhealthy", + log=[HealthCheckEntry(exit_code=1, output="connection refused")], + ) + ] + console = Console() + _print_health_logs(console, [DockerComposeCommand([], "proj", "/path", ["redis"])]) + out = capsys.readouterr().out + assert "proj-redis-1: unhealthy" in out + assert "proj-redis-1 health check log" in out + assert "exit=1" in out + assert "connection refused" in out + + +@mock.patch("devservices.commands.logs.get_container_health") +@mock.patch("devservices.commands.logs.get_container_names_for_project") +def test_print_health_logs_no_healthcheck( + mock_get_container_names: mock.Mock, + mock_get_container_health: mock.Mock, + capsys: pytest.CaptureFixture[str], +) -> None: + from devservices.utils.docker import ContainerNames + + mock_get_container_names.return_value = [ + ContainerNames(name="proj-redis-1", short_name="redis") + ] + mock_get_container_health.return_value = [ + ContainerHealth(name="proj-redis-1", status="none", log=[]) + ] + console = Console() + _print_health_logs(console, [DockerComposeCommand([], "proj", "/path", ["redis"])]) + out = capsys.readouterr().out + assert "proj-redis-1: no healthcheck" in out + assert "health check log" not in out + + +@mock.patch("devservices.commands.logs.get_container_names_for_project") +def test_print_health_logs_inspect_exception_ignored( + mock_get_container_names: mock.Mock, + capsys: pytest.CaptureFixture[str], +) -> None: + mock_get_container_names.side_effect = Exception("docker error") + console = Console() + _print_health_logs(console, [DockerComposeCommand([], "proj", "/path", ["redis"])]) + assert capsys.readouterr().out == "" diff --git a/tests/utils/test_docker.py b/tests/utils/test_docker.py index 06f8729..938a288 100644 --- a/tests/utils/test_docker.py +++ b/tests/utils/test_docker.py @@ -15,9 +15,12 @@ from devservices.exceptions import ContainerHealthcheckFailedError from devservices.exceptions import DockerDaemonNotRunningError from devservices.exceptions import DockerError +from devservices.utils.docker import ContainerHealth from devservices.utils.docker import ContainerNames +from devservices.utils.docker import HealthCheckEntry from devservices.utils.docker import check_all_containers_healthy from devservices.utils.docker import check_docker_daemon_running +from devservices.utils.docker import get_container_health from devservices.utils.docker import get_matching_containers from devservices.utils.docker import get_matching_networks from devservices.utils.docker import get_volumes_for_containers @@ -539,6 +542,113 @@ def test_check_all_containers_healthy_success( ) +def test_get_container_health_empty() -> None: + assert get_container_health([]) == [] + + +@mock.patch("subprocess.check_output") +def test_get_container_health_docker_error(mock_check_output: mock.Mock) -> None: + mock_check_output.side_effect = subprocess.CalledProcessError(1, "docker inspect") + assert get_container_health(["container1"]) == [] + + +@mock.patch("subprocess.check_output") +def test_get_container_health_healthy(mock_check_output: mock.Mock) -> None: + mock_check_output.return_value = """[ + { + "Name": "/my-container", + "State": { + "Health": { + "Status": "healthy", + "Log": [ + {"ExitCode": 0, "Output": "OK\\n"} + ] + } + } + } + ]""" + result = get_container_health(["my-container"]) + assert result == [ + ContainerHealth( + name="my-container", + status="healthy", + log=[HealthCheckEntry(exit_code=0, output="OK")], + ) + ] + mock_check_output.assert_called_once_with( + ["docker", "inspect", "my-container"], + text=True, + stderr=subprocess.DEVNULL, + ) + + +@mock.patch("subprocess.check_output") +def test_get_container_health_unhealthy(mock_check_output: mock.Mock) -> None: + mock_check_output.return_value = """[ + { + "Name": "/bad-container", + "State": { + "Health": { + "Status": "unhealthy", + "Log": [ + {"ExitCode": 1, "Output": "connection refused\\n"}, + {"ExitCode": 1, "Output": "connection refused\\n"} + ] + } + } + } + ]""" + result = get_container_health(["bad-container"]) + assert result == [ + ContainerHealth( + name="bad-container", + status="unhealthy", + log=[ + HealthCheckEntry(exit_code=1, output="connection refused"), + HealthCheckEntry(exit_code=1, output="connection refused"), + ], + ) + ] + + +@mock.patch("subprocess.check_output") +def test_get_container_health_no_healthcheck(mock_check_output: mock.Mock) -> None: + mock_check_output.return_value = """[ + { + "Name": "/plain-container", + "State": {} + } + ]""" + result = get_container_health(["plain-container"]) + assert result == [ContainerHealth(name="plain-container", status="none", log=[])] + + +@mock.patch("subprocess.check_output") +def test_get_container_health_multiple(mock_check_output: mock.Mock) -> None: + mock_check_output.return_value = """[ + { + "Name": "/c1", + "State": { + "Health": {"Status": "healthy", "Log": []} + } + }, + { + "Name": "/c2", + "State": {} + } + ]""" + result = get_container_health(["c1", "c2"]) + assert result == [ + ContainerHealth(name="c1", status="healthy", log=[]), + ContainerHealth(name="c2", status="none", log=[]), + ] + mock_check_output.assert_called_once_with( + ["docker", "inspect", "c1", "c2"], + text=True, + stderr=subprocess.DEVNULL, + ) + + @mock.patch("devservices.utils.docker.wait_for_healthy") def test_check_all_containers_healthy_failure( mock_wait_for_healthy: mock.Mock,