#374 を実装する（スプリント m8d）

CHANGELOG.md

@@ -53,6 +53,10 @@
   `~/.vscode-server/bin` を開発ユーザーが書ける形に揃えます。
 
 ### Fixed
+- **`devbase up` / `devbase scale` の起動の待ちの時間切れの文言が、巡の回数と実際に待った秒数を出すようにしました（#374）。**
+  制限は 1 秒休む巡の回数（60 巡）で数え、docker の呼び出しにかかる時間を含まないため、実際に待つ時間は 60 秒より
+  長くなります。これまでの `timeout (60s) ...` は 60 秒で止まったと読めました。今は
+  `timeout after 60 rounds (73s elapsed) waiting for the entrypoint to complete` の形で出ます。数え方と制限は変わりません。
 - **`devbase env <TAB>` の候補に `token` と `backend` が出るようにしました（#454）。** bash と zsh の補完の
   サブコマンドの一覧に 2 つが無く、名前を手で打たないと使えませんでした。一致テストが `env` のサブコマンドの
   全部を bash と zsh の一覧と比べるようになり、`env` のサブコマンドを足したときの取り残しで落ちます。

docs/specifications/post-start.md

@@ -85,14 +85,16 @@ classDiagram
         +reason: str
         +logs: str
         +timeout: int
+        +elapsed: int
         +describe() str
     }
     DockerError <|-- ContainerStartupError
     ContainerStartupError "1" --> "1..*" StartupFailure
 ```
 
 `ready` と `failures` は番号の昇順で、合わせると待った番号の全部になる。`reason` は `exited`・`not_found`・
-`timeout` のどれかで、`logs` は `exited` のときだけ中身を持つ。
+`timeout` のどれかで、`logs` は `exited` のときだけ中身を持つ。`timeout`（巡の回数の制限）と `elapsed`（待ちを
+始めてから時間切れが決まるまでに実際にかかった秒数）は、`reason` が `timeout` のときだけ意味を持ち、既定は 0 である。
 
 ### 起動の待ち
 
@@ -118,12 +120,14 @@ stateDiagram-v2
 | --- | --- | --- |
 | 終了した（`exited`） | 状態が `exited` か `dead` を含む | `exited unexpectedly` と、続く `Last logs:` とログの末尾（10 行まで。決まったときに 1 回だけ取る） |
 | 見つからない（`not_found`） | 状態を取れない | `container not found` |
-| 時間切れ（`timeout`） | 巡の数が制限に達した時点で、完了の印を確かめられていない | `timeout (<制限>s) waiting for the entrypoint to complete` |
+| 時間切れ（`timeout`） | 巡の数が制限に達した時点で、完了の印を確かめられていない | `timeout after <制限> rounds (<経過>s elapsed) waiting for the entrypoint to complete` |
 
 1 台が起動できなくても、残りの番号は制限まで待つ。番号の小さい 1 台が落ちたときにも、後から起動を終える
 インスタンスへ後処理を届けるためである。そのため 1 台が落ちた `up` / `scale` が終わるまでの時間は、最長で
 制限まで延びる。制限は 1 秒の休みを挟む巡の回数で数えるため、docker の呼び出しにかかる分だけ実際の時間は
-60 秒を超える。
+60 秒を超える。時間切れの文言は、この食い違いを利用者が読めるように、巡の回数（`<制限>`）と、待ちを始めてから
+時間切れが決まるまでに実際にかかった秒数（`<経過>`）の両方を出す。経過は単調な時計（`time.monotonic`）で測り、
+端数を切り捨てた整数の秒で出す。
 
 起動できなかった番号が 1 つ以上あれば `ContainerStartupError` を投げる。引数と成功時の戻り値は変えず、例外は
 `DockerError`（`DevbaseError` の派生）なので、受けない呼び出し元は失敗のまま終わる。内訳を戻り値で返さないのは、
@@ -134,7 +138,7 @@ Container startup failed: 2 of 3 instances did not become ready.
   - dev-2: exited unexpectedly
     Last logs:
     <そのコンテナのログの末尾。10 行まで>
-  - dev-3: timeout (60s) waiting for the entrypoint to complete
+  - dev-3: timeout after 60 rounds (73s elapsed) waiting for the entrypoint to complete
 ```
 
 完了の印（`/tmp/entrypoint-ready`）は、entrypoint が起動のはじめに消し、最後に置く。`docker start` で起こし直した
@@ -329,7 +333,7 @@ Deploy failed: Container startup failed: 1 of 2 instances did not become ready.
 - 起動の待ちが、最初の巡で終了した 2 台の名前・理由・ログの末尾を内訳と文言に入れること、制限まで完了の印が無い
   番号を時間切れとして入れること、待った番号が起動できた側とできなかった側のどちらか一方にだけ現れること、
   番号の小さい 1 台が終了しても後から完了した番号を起動できた側へ入れること、1 巡の docker の呼び出しの回数と
-  巡の上限を満たすこと（`tests/utils/test_wait_for_containers.py`）
+  巡の上限を満たすこと、時間切れの文言が巡の回数と、時計を差し替えて進めた実際の経過の秒数（整数）を出すこと（`tests/utils/test_wait_for_containers.py`）
 - `scale`（1 から 3）が `dev-2`・`dev-3` にだけ、実コンテナ名で始まる窓のタイトルを設定し、`DEVBASE_WINDOW_TITLE=off`
   で設定しないこと、増やしたインスタンスの不足リポジトリを `up` と同じ文言で報告し、揃っていれば何も出さないこと、
   処理の順が `up` と同じであること（`tests/commands/test_container_post_start.py`・`tests/commands/test_container_scale_order.py`）

lib/devbase/utils/docker.py

@@ -166,19 +166,23 @@ class StartupFailure:
     """起動の待ちで起動できなかった 1 インスタンス。
 
     ``reason`` は ``exited``・``not_found``・``timeout`` のどれかで、``logs`` は
-    ``exited`` のときだけ中身を持つ (ログの末尾。取れなければ空)。
+    ``exited`` のときだけ中身を持つ (ログの末尾。取れなければ空)。``timeout`` は巡の回数の
+    制限で、``elapsed`` は待ちを始めてから時間切れが決まるまでに実際にかかった秒数 (整数)。
+    どちらも ``timeout`` のときだけ意味を持つ。
     """
 
     index: int
     service: str
     reason: str
     logs: str = ''
     timeout: int = 0
+    elapsed: int = 0
 
     def describe(self) -> str:
         """利用者へ出す 1 インスタンス分の文言 (ログの末尾を含む)。"""
         if self.reason == 'timeout':
-            text = f"timeout ({self.timeout}s) waiting for the entrypoint to complete"
+            text = (f"timeout after {self.timeout} rounds ({self.elapsed}s elapsed) "
+                    "waiting for the entrypoint to complete")
         else:
             text = _STARTUP_REASON_TEXT.get(self.reason, self.reason)
         lines = [f"  - {self.service}: {text}"]
@@ -247,7 +251,9 @@ def wait_for_containers_ready(
     1 から ``scale`` までの番号を巡ごとに確かめる。1 巡では、まだ決まっていない番号ごとに
     状態を 1 回、動いていれば完了の印を 1 回確かめる。決まった番号 (起動できた・終了した・
     見つからない) へは、その後の巡で問い合わせない。1 台が起動できなくても、残りの番号は
-    制限まで待つ。巡の数は ``timeout`` を超えない (1 巡ごとに 1 秒休む)。
+    制限まで待つ。巡の数は ``timeout`` を超えない (1 巡ごとに 1 秒休む)。制限は巡の回数で
+    数え、docker の呼び出しにかかる時間は含まない。時間切れの文言には、巡の回数と、単調な
+    時計で測った実際の経過の秒数を出す。
 
     Args:
         container_prefix: Container name prefix (e.g., "dev")
@@ -268,6 +274,7 @@ def wait_for_containers_ready(
     pending = list(range(1, scale + 1))
     ready: List[int] = []
     failures: List[StartupFailure] = []
+    started = time.monotonic()
     rounds = 0
     while pending and rounds < timeout:
         still_pending = []
@@ -293,8 +300,10 @@ def wait_for_containers_ready(
         time.sleep(1)
         rounds += 1
 
+    elapsed = int(time.monotonic() - started)
     failures.extend(
-        StartupFailure(i, f"{container_prefix}-{i}", 'timeout', timeout=timeout)
+        StartupFailure(i, f"{container_prefix}-{i}", 'timeout', timeout=timeout,
+                       elapsed=elapsed)
         for i in pending)
     if failures:
         raise ContainerStartupError(ready, failures)

tests/utils/test_wait_for_containers.py

@@ -3,6 +3,7 @@
 1 台が起動できなくても残りを制限まで待ち、起動できた番号と、起動できなかった番号ごとの
 理由 (終了した・見つからない・時間切れ) を例外で返す。実 docker には触れない。
 ``docker_compose`` を差し替え、巡 (``time.sleep`` の回数) ごとの状態を台本で返す。
+時計 (``time.monotonic``) も差し替え、休みと docker の呼び出しにかかる秒数を台本で進める。
 """
 
 from __future__ import annotations
@@ -22,21 +23,28 @@ class Script:
     ``states[n](round)`` は ``(状態, 完了の印があるか)``。状態が ``None`` なら見つからない。
     """
 
-    def __init__(self, states, logs=None):
+    def __init__(self, states, logs=None, call_seconds=0.0):
         self.states = states
         self.logs = logs or {}
+        self.call_seconds = call_seconds
+        self.clock = 1000.0
         self.round = 0
         self.calls: list = []
 
-    def sleep(self, _seconds):
+    def sleep(self, seconds):
+        self.clock += seconds
         self.round += 1
 
+    def monotonic(self):
+        return self.clock
+
     def __call__(self, command, compose_file=None, check=True, capture_output=False,
                  silent_error=False):
         command = list(command)
         service = command[-1] if command[0] in ('ps', 'logs') else command[2]
         index = int(service.rsplit('-', 1)[1])
         self.calls.append((self.round, command[0], index))
+        self.clock += self.call_seconds
         state, ready = self.states[index](self.round)
         if command[0] == 'ps':
             stdout = '' if state is None else json.dumps({'State': state})
@@ -68,10 +76,11 @@ def missing(_r):
 
 @pytest.fixture
 def run(monkeypatch):
-    def _run(states, scale=None, timeout=60, logs=None):
-        script = Script(states, logs)
+    def _run(states, scale=None, timeout=60, logs=None, call_seconds=0.0):
+        script = Script(states, logs, call_seconds)
         monkeypatch.setattr(docker, 'docker_compose', script)
         monkeypatch.setattr(docker.time, 'sleep', script.sleep)
+        monkeypatch.setattr(docker.time, 'monotonic', script.monotonic)
         scale = scale or len(states)
         try:
             result = docker.wait_for_containers_ready('dev', scale, timeout=timeout)
@@ -121,10 +130,34 @@ def test_timeout_names_the_instances_not_ready(run):
     assert error.ready == (1,)
     (failure,) = error.failures
     assert (failure.index, failure.reason) == (2, 'timeout')
-    assert '  - dev-2: timeout (5s) waiting for the entrypoint to complete' in str(error)
+    assert ('  - dev-2: timeout after 5 rounds (5s elapsed) '
+            'waiting for the entrypoint to complete') in str(error)
     assert script.round == 5
 
 
+def test_timeout_reports_rounds_and_real_elapsed_seconds(run):
+    """#374: 時間切れの文言は巡の回数と、docker の呼び出しを含む実際の経過の秒数 (整数) を出す"""
+    # 1 巡に ps と exec が 1 回ずつ、各 0.65 秒。60 巡で 60 + 60 * 1.3 = 138 秒
+    script, error = run({1: never_ready}, call_seconds=0.65)
+
+    assert script.round == 60
+    (failure,) = error.failures
+    assert (failure.timeout, failure.elapsed) == (60, 138)
+    assert ('  - dev-1: timeout after 60 rounds (138s elapsed) '
+            'waiting for the entrypoint to complete') in str(error)
+    assert 'timeout (60s)' not in str(error)
+
+
+def test_elapsed_seconds_are_truncated_to_an_integer(run):
+    """#374: 経過の秒数は整数の秒で出す (端数は切り捨てる)"""
+    # 3 巡 + 3 巡 * (ps + exec) * 0.3 = 3 + 1.8 = 4.8 秒
+    _script, error = run({1: never_ready}, timeout=3, call_seconds=0.3)
+
+    (failure,) = error.failures
+    assert failure.elapsed == 4
+    assert 'timeout after 3 rounds (4s elapsed)' in str(error)
+
+
 def test_missing_container_is_not_found(run):
     _script, error = run({1: missing, 2: ready_at(0)})