diff --git a/experiments/README.md b/experiments/README.md index 071e035..ad7f539 100644 --- a/experiments/README.md +++ b/experiments/README.md @@ -14,13 +14,19 @@ instead: itself, which is not where the cost turned out to be. 3. **Is it actually portable?** A protocol decouples nothing unless something other than this codebase can speak it. → **E2: yes** - two clients written - from the specification alone, one of them C++ with no third-party - libraries. + against the specification, one of them C++ with no third-party libraries. + They share an author with the specification, so this shows it is + sufficient, not that it is clear. 4. **Does any of it train?** → **E6: yes** - FPO on HalfCheetah-v5, three seeds. +5. **Does it survive being used?** A clean-machine install found a silent + corruption of the training buffer across a reconnect. → **E8: fixed** - + and the first explanation of it was wrong, which the same experiment + records. -One of those four answers is negative, and it is the one the project was -built on. +The first of those five answers is negative, and it is the one the project +was built on. The last one cost a bug and a retracted diagnosis, both of +which are written down. | | Question | Answer | |---|---|---| @@ -30,6 +36,7 @@ built on. | [`e5-boundary-cost`](e5-boundary-cost/) | What does crossing the process boundary cost per step? | **Sub-millisecond** on loopback - a lower bound, not a cross-machine number | | [`e6-first-learning-curve`](e6-first-learning-curve/) | Does anything here actually learn? | **Yes** - three seeds, episode return from about -300 into the thousands | | [`e7-cross-machine`](e7-cross-machine/) | What does the boundary cost once packets leave loopback? | **+0.52 ms** on a 184 KiB observation - and the cost is in leaving the machine, not in the network stack | +| [`e8-keepalive-hypothesis`](e8-keepalive-hypothesis/) | Does a long learn step kill the WebSocket connection? | **No** - learns of 190 s, nine times the ping timeout, close nothing. The hypothesis was mine and the measurement refuted it | Each directory has a `FINDINGS.md` stating what was asked, what came back, and what it does and does not support. Scripts pin their dependency SHAs at @@ -84,6 +91,13 @@ These live in the findings files, not in git history: - **E7's own prediction P2 was not supported**, and is recorded as such rather than quietly reworded into one that was. The reformulation that does hold is labelled post-hoc. +- **E8 refuted a diagnosis that had already been written up and shipped as + four pull requests.** A dropped connection was blamed on a CPU-bound learn + step outlasting the 20 s WebSocket ping. Learn steps of 190 s were then + measured to close nothing - `learn` runs off the event loop - and the real + cause was the machine suspending for 1 h 53 min. The fix that rested on the + wrong cause was withdrawn; the fix that was read out of the code and + reproduced in a test was kept. Both versions are in the branch history. ## What is missing diff --git a/experiments/e8-keepalive-hypothesis/FINDINGS.md b/experiments/e8-keepalive-hypothesis/FINDINGS.md new file mode 100644 index 0000000..dab69b7 --- /dev/null +++ b/experiments/e8-keepalive-hypothesis/FINDINGS.md @@ -0,0 +1,151 @@ +# E8: the learn step does not trip the keepalive, and the bug was real anyway + +2026-09-11 · Windows 11, CPU only · FPO on HalfCheetah-v5 · plugrl-server and +plugrl-env-client at `main` + +## In one sentence + +A clean-machine run dropped its WebSocket connection, and the explanation +that suggested itself - a CPU-bound learn step holding the event loop past +the 20 s keepalive timeout - is **false**: learn steps of about 180 s produce +no timeout at all. The drop was a machine suspend. The silent data corruption +the drop exposed was real, and is the only part of the original diagnosis +that survived. + +## The incident + +Following the documented quickstart from fresh clones, the env client logged: + +``` +Connection closed during INFER/ACTION exchange. Error: sent 1011 (internal +error) keepalive ping timeout; no close frame received. Retrying... +``` + +Reading the code from there gives a tidy story. `websockets` defaults to a +20 s ping with a 20 s timeout. A learn step is CPU-bound. Therefore the +server misses its pong and kills a healthy connection. + +Every step of that is plausible. The conclusion is wrong. + +## What the measurement says + +`run.sh` holds everything fixed and makes the learn step long. Gradient steps +per learn are `num_updates_per_batch * ceil(buffer_size / batch_size)`, so +raising the epoch count rather than the buffer keeps the fill short while +making the learn long - and it is the learn's *duration* the keepalive would +race against, not the buffer's size. + +| run | buffer | updates/batch | gradient steps per learn | learns | learn duration | keepalive timeouts | reconnects | +|---|---|---|---|---|---|---|---| +| `short-learns` | 16384 | 16 (default) | 256 | 3 | roughly 5-24 s | **0** | **0** | +| `long-learns` | 4096 | 400 | 1600 | 5 | 177-190 s | **0** | **0** | + +Two separate refutations, and the weaker run is enough on its own: one of +`short-learns`' three learn steps lasted about 24 s, **already past the 20 s +ping timeout**, and nothing closed. `long-learns` then put the learn step at +**nine times** the timeout, five cycles running, with the same result. + +Durations are read off the gaps between the client's periodic timing lines, +which are emitted every 30 s; a gap of 53.7 s contains one 30 s interval plus +about 24 s of waiting. That makes them approximate, and approximate is +sufficient to separate 24 s from 20 s in the direction that matters, because +the hypothesis predicts a close and there was none. + +The reason is one line in `server/training_backend.py`: + +```python +step, log_dict = await asyncio.to_thread(self._algorithm.learn) +``` + +**Learning already runs off the event loop.** The loop stays free to answer +pings for the whole learn. The hypothesis was not merely unproven, it was +contradicted by code that was there to read. + +## What actually caused the drop + +The client's own log, at the two lines either side of the failure: + +``` +2026-09-11 12:28:16.237 | INFO | Intermediate rollout timing summary: env_steps=5353 ... +2026-09-11 14:21:53.007 | WARNING | Connection closed during INFER/ACTION exchange ... +``` + +Those timing lines are emitted every 30 s, without a break, from 12:24:14 to +12:28:16. Then **1 hour 53 minutes of nothing**, and the next line is the +failure. A process that was merely slow would still have logged. This one was +frozen: the machine suspended with the run open, and when it came back both +ends had long since stopped hearing from each other. + +Two further details the original diagnosis had backwards: + +* the traceback is in `websockets/sync/connection.py`, in the **client** + library. `sent 1011` means the *client* closed the connection because the + *server* had not answered the client's pings. The server's ping settings + are not what failed. +* the server log for the same run contains no keepalive line at all. + +So a fix that turned the server's keepalive off would not have prevented this +incident. It was written, and is not in the change that shipped. + +## What survived, and is worth more than the hypothesis was + +The drop was real, and what it exposed does not depend on why it happened. + +`prev_node_map`, `step_state_map`, `terminated_map`, `truncated_map` and +`last_obs_map` are local to the connection handler. A reconnect gets a new +handler and five empty maps. The env client, meanwhile, retried its held +`feedback` on the new connection after every close except an explicit resync - +so the server completed that transition from an empty observation and stored +it. No exception, no warning, one corrupt transition per reconnect. + +That is a real defect, reachable by any cause of reconnection: a suspend, a +flaky link, a server restart. It is fixed in the client, which now drops a +held feedback rather than resending it, and the server now says so when a +feedback arrives with no step state. The protocol gained section 7.6, which +states the rule in terms of the reconnect rather than any particular cause. + +**E6 was checked for contamination and is clean:** one connection per seed, +zero reconnects across all three. + +## What this does and does not support + +**Supported:** + +* A learn step, however long, does not close a connection. Measured to 190 s, + nine times the timeout. +* The reconnect state-loss path is real; the code is explicit about it, and + the client's retry made it reachable. + +**Not supported:** + +* Anything about what *does* trip the keepalive in normal operation. One + incident, and its cause was a suspended machine, which is not a + steady-state condition worth designing against. +* Any claim about frequency. This happened once, on a machine that sleeps. +* Anything on hardware other than this one. A different policy on a different + machine may block the loop somewhere this one does not - but it will not do + it inside `learn`, which is the specific claim tested here. + +## The methodological note + +The first diagnosis was reasoned from code to a conclusion that fit the +symptom, and it fit well enough that the fix, its test, its specification +clause and four pull requests were all written before anything measured it. +The measurement took twenty minutes and reversed it. + +What makes this recoverable rather than embarrassing is that the *consequence* +was verified independently of the cause: the state-loss path was read out of +the code and reproduced in a unit test, not inferred from the incident. The +part that rested on the incident alone is the part that was wrong. + +## Reproducing + +```bash +bash run.sh short-learns 16384 49152 1 8617 16 # default epochs, ~9 min +bash run.sh long-learns 4096 20480 1 8615 400 # long learns, ~15 min +``` + +The last argument is `num_updates_per_batch`. `results/` holds both runs and +the original incident log. A run counts only if the client exits zero, and +the script reports keepalive timeouts, 1011 closes, client reconnects and +server-side missing-step-state warnings. diff --git a/experiments/e8-keepalive-hypothesis/results/long-learns-client.log b/experiments/e8-keepalive-hypothesis/results/long-learns-client.log new file mode 100644 index 0000000..db5fe88 --- /dev/null +++ b/experiments/e8-keepalive-hypothesis/results/long-learns-client.log @@ -0,0 +1,13 @@ +2026-09-11 14:58:43.707 | WARNING  | plugrl_env_client.envs:_load_env_modules:27 - Skip loading env module plugrl_env_client.envs.atari.atari_env: Atari is not installed. Please install it with the 'atari' extra, e.g. 'pip install plugrl-env-client[atari]' +2026-09-11 14:58:43.714 | WARNING  | plugrl_env_client.envs:_load_env_modules:27 - Skip loading env module plugrl_env_client.envs.classic.classic_env: pygame is not installed. Please install it with pip install "plugrl-env-client[classic]". +2026-09-11 14:58:43.719 | WARNING  | plugrl_env_client.envs:_load_env_modules:27 - Skip loading env module plugrl_env_client.envs.d4rl.d4rl_env: d4rl is not installed. Please install it with pip install "plugrl-env-client[d4rl]". +2026-09-11 14:58:43.723 | WARNING  | plugrl_env_client.envs:_load_env_modules:27 - Skip loading env module plugrl_env_client.envs.libero.libero_env: libero is not installed. Please install it with pip install "plugrl-env-client[libero]". +2026-09-11 14:58:43.732 | WARNING  | plugrl_env_client.envs:_load_env_modules:27 - Skip loading env module plugrl_env_client.envs.robomimic.robomimic_env: Robomimic is not installed. Please install it with the 'robomimic' extra, e.g. 'pip install plugrl-env-client[robomimic]' +2026-09-11 14:58:44.073 | INFO  | __main__:main:83 - Starting env client exp_name=mujoco-v1-nenv1-20260911-145843-44bb2994 output_dir=runs\mujoco-v1-nenv1-20260911-145843-44bb2994 recorder={'episode_freq': 0, 'thread0_only': True, 'record_video': False, 'video_fps': 30.0, 'record_full_rollout': False, 'record_obs_stats': True, 'record_episode_metrics': True, 'metric_window': 100} +2026-09-11 14:58:44.251 | INFO  | plugrl_env_client.agent.websocket_env_client_agent:_wait_for_server:67 - Waiting for server at ws://127.0.0.1:8615... +2026-09-11 14:58:44.266 | INFO  | plugrl_env_client.runner.run:report_server_metadata:56 - Server metadata: {'protocol_version': 1, 'server': 'plugrl-server', 'server_version': '0.1.0', 'algorithm': 'FPOAlgorithm', 'policy': 'FPOPolicy', 'action_dim': 6, 'action_horizon': 1} +2026-09-11 15:01:50.118 | INFO  | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=4097 infer_calls=4097 feedback_calls=4097 infer_wait=181.095s infer_obs_pack=0.304s env_step=1.873s feedback_total=1.611s feedback_obs_pack=0.371s feedback_info_pack=0.057s effective_fps=22.16 +2026-09-11 15:04:59.730 | INFO  | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=8194 infer_calls=8194 feedback_calls=8194 infer_wait=365.671s infer_obs_pack=0.619s env_step=3.852s feedback_total=3.330s feedback_obs_pack=0.763s feedback_info_pack=0.117s effective_fps=21.94 +2026-09-11 15:08:03.522 | INFO  | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=12289 infer_calls=12289 feedback_calls=12289 infer_wait=544.816s infer_obs_pack=0.933s env_step=5.671s feedback_total=4.906s feedback_obs_pack=1.129s feedback_info_pack=0.176s effective_fps=22.09 +2026-09-11 15:11:00.383 | INFO  | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=16385 infer_calls=16385 feedback_calls=16385 infer_wait=717.101s infer_obs_pack=1.283s env_step=7.459s feedback_total=6.439s feedback_obs_pack=1.489s feedback_info_pack=0.232s effective_fps=22.38 +2026-09-11 15:14:02.028 | INFO  | plugrl_env_client.runner.run:run:156 - Server signalled the end of the run; collection stopped after 20/100000 episodes. diff --git a/experiments/e8-keepalive-hypothesis/results/long-learns-server.log b/experiments/e8-keepalive-hypothesis/results/long-learns-server.log new file mode 100644 index 0000000..7b53ac6 --- /dev/null +++ b/experiments/e8-keepalive-hypothesis/results/long-learns-server.log @@ -0,0 +1,19 @@ +Could not import DPPO algorithm module for reason: No module named 'dppo' +14:58:40|INFO|plugrl_server version: 0.1.0 +14:58:40|INFO|Algorithm: fpo, Config: FPOAlgoConfig(global_steps=20480, buffer_size=4096, output_mode='u_but_supervise_as_eps', fpo_playground_trick=True, treat_truncated_as_done=False, discounting=0.995, reward_scaling=10.0, gae_lambda=0.95, batch_size=1024, num_updates_per_batch=400, learning_rate=0.0003, value_loss_coeff=0.25, clipping_epsilon=0.05, normalize_advantage=True, n_samples_per_action=8, discretize_t_for_training=True, average_losses_before_exp=True, save_interval=10) +14:58:40|INFO|Policy: fpo-policy, Config: FPOPolicyConfig(algo='fpo', device=device(type='cpu'), obs_dim=17, action_dim=6, flow_steps=10, timestep_embed_dim=8, action_horizon=1, feather_std=0.0, policy_mlp_output_scale=0.25, normalize_observations=True, hidden_dims=(32, 32, 32, 32), value_hidden_dims=(256, 256, 256, 256, 256)) +14:58:41|INFO|Checkpoint Manager created: + at C:\Users\75128\.claude\jobs\1fea619d\tmp\e8\before\ck\fpo\fpo-policy\e8 +14:58:42|INFO|Policy created... +14:58:42|INFO|Initialized RolloutBuffer buffer_size=4096 action_shape=(4096, 1, 6) value_shape=(4096, 1) +14:58:42|INFO|Algorithm created: + +14:58:42|INFO|Agent Server is listening on 0.0.0.0:8615 +15:14:02|INFO|Checkpoint saved at step 20481 to C:\Users\75128\.claude\jobs\1fea619d\tmp\e8\before\ck\fpo\fpo-policy\e8\20481 +15:14:02|INFO|Stopping server as the algorithm signaled to stop. +15:14:02|INFO|Shutdown started: aborting pending infer requests. +15:14:02|INFO|Shutdown cleanup finished: pending_futures=1, drained_requests=1 +15:14:02|INFO|Shutdown closing 1 websocket connection(s). +15:14:02|INFO|Shutdown interrupted an in-flight inference request from ('127.0.0.1', 59264). +15:14:02|INFO|WebSocket server closed. +15:14:02|INFO|Scheduler task cancelled and cleaned up. diff --git a/experiments/e8-keepalive-hypothesis/results/original-incident-client.log b/experiments/e8-keepalive-hypothesis/results/original-incident-client.log new file mode 100644 index 0000000..ee01015 --- /dev/null +++ b/experiments/e8-keepalive-hypothesis/results/original-incident-client.log @@ -0,0 +1,45 @@ +2026-09-11 12:23:43.842 | WARNING | plugrl_env_client.envs:_load_env_modules:27 - Skip loading env module plugrl_env_client.envs.atari.atari_env: Atari is not installed. Please install it with the 'atari' extra, e.g. 'pip install plugrl-env-client[atari]' +2026-09-11 12:23:43.843 | WARNING | plugrl_env_client.envs:_load_env_modules:27 - Skip loading env module plugrl_env_client.envs.libero.libero_env: libero is not installed. Please install it with pip install "plugrl-env-client[libero]". +2026-09-11 12:23:43.844 | WARNING | plugrl_env_client.envs:_load_env_modules:27 - Skip loading env module plugrl_env_client.envs.classic.classic_env: pygame is not installed. Please install it with pip install "plugrl-env-client[classic]". +2026-09-11 12:23:43.845 | WARNING | plugrl_env_client.envs:_load_env_modules:27 - Skip loading env module plugrl_env_client.envs.robomimic.robomimic_env: Robomimic is not installed. Please install it with the 'robomimic' extra, e.g. 'pip install plugrl-env-client[robomimic]' +2026-09-11 12:23:43.845 | WARNING | plugrl_env_client.envs:_load_env_modules:27 - Skip loading env module plugrl_env_client.envs.d4rl.d4rl_env: d4rl is not installed. Please install it with pip install "plugrl-env-client[d4rl]". +2026-09-11 12:23:43.941 | INFO | plugrl_env_client.cli:main:83 - Starting env client exp_name=mujoco-v1-nenv1-20260911-122343-2b1cfe91 output_dir=runs/mujoco-v1-nenv1-20260911-122343-2b1cfe91 recorder={'episode_freq': 0, 'thread0_only': True, 'record_video': False, 'video_fps': 30.0, 'record_full_rollout': False, 'record_obs_stats': True, 'record_episode_metrics': True, 'metric_window': 100} +2026-09-11 12:23:44.042 | INFO | plugrl_env_client.agent.websocket_env_client_agent:_wait_for_server:67 - Waiting for server at ws://127.0.0.1:8500... +2026-09-11 12:23:44.052 | INFO | plugrl_env_client.runner.run:report_server_metadata:56 - Server metadata: {'protocol_version': 1, 'server': 'plugrl-server', 'server_version': '0.1.0', 'algorithm': 'FPOAlgorithm', 'policy': 'FPOPolicy', 'action_dim': 6, 'action_horizon': 1} +2026-09-11 12:24:14.059 | INFO | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=545 infer_calls=545 feedback_calls=545 infer_wait=29.547s infer_obs_pack=0.025s env_step=0.203s feedback_total=0.133s feedback_obs_pack=0.035s feedback_info_pack=0.006s effective_fps=18.22 +2026-09-11 12:24:44.104 | INFO | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=1095 infer_calls=1095 feedback_calls=1095 infer_wait=59.127s infer_obs_pack=0.051s env_step=0.408s feedback_total=0.267s feedback_obs_pack=0.071s feedback_info_pack=0.012s effective_fps=18.29 +2026-09-11 12:25:14.131 | INFO | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=1638 infer_calls=1638 feedback_calls=1638 infer_wait=88.758s infer_obs_pack=0.073s env_step=0.585s feedback_total=0.380s feedback_obs_pack=0.103s feedback_info_pack=0.017s effective_fps=18.24 +2026-09-11 12:25:44.152 | INFO | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=2250 infer_calls=2250 feedback_calls=2250 infer_wait=118.344s infer_obs_pack=0.096s env_step=0.782s feedback_total=0.504s feedback_obs_pack=0.137s feedback_info_pack=0.023s effective_fps=18.79 +2026-09-11 12:26:14.155 | INFO | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=2871 infer_calls=2871 feedback_calls=2871 infer_wait=147.934s infer_obs_pack=0.119s env_step=0.968s feedback_total=0.623s feedback_obs_pack=0.171s feedback_info_pack=0.029s effective_fps=19.19 +2026-09-11 12:26:44.156 | INFO | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=3478 infer_calls=3478 feedback_calls=3478 infer_wait=177.479s infer_obs_pack=0.143s env_step=1.175s feedback_total=0.751s feedback_obs_pack=0.206s feedback_info_pack=0.034s effective_fps=19.37 +2026-09-11 12:27:16.202 | INFO | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=4097 infer_calls=4097 feedback_calls=4097 infer_wait=209.057s infer_obs_pack=0.166s env_step=1.391s feedback_total=0.880s feedback_obs_pack=0.242s feedback_info_pack=0.040s effective_fps=19.37 +2026-09-11 12:27:46.207 | INFO | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=4726 infer_calls=4726 feedback_calls=4726 infer_wait=238.638s infer_obs_pack=0.189s env_step=1.584s feedback_total=0.999s feedback_obs_pack=0.275s feedback_info_pack=0.046s effective_fps=19.58 +2026-09-11 12:28:16.237 | INFO | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=5353 infer_calls=5353 feedback_calls=5353 infer_wait=268.248s infer_obs_pack=0.211s env_step=1.775s feedback_total=1.117s feedback_obs_pack=0.309s feedback_info_pack=0.052s effective_fps=19.73 +2026-09-11 14:21:53.007 | WARNING | plugrl_env_client.agent.websocket_env_client_agent:infer:193 - Connection closed during INFER/ACTION exchange. Error: sent 1011 (internal error) keepalive ping timeout; no close frame received. Retrying... +2026-09-11 14:21:53.007 | WARNING | plugrl_env_client.agent.websocket_env_client_agent:_ensure_connection:131 - Connection closed. Attempting to re-establish connection. +2026-09-11 14:21:53.008 | INFO | plugrl_env_client.agent.websocket_env_client_agent:_wait_for_server:67 - Waiting for server at ws://127.0.0.1:8500... +keepalive ping failed +TimeoutError: timed out while closing connection + +The above exception was the direct cause of the following exception: + +Traceback (most recent call last): + File "/tmp/plugrl-stranger/plugrl-env-client/.venv/lib/python3.11/site-packages/websockets/sync/connection.py", line 777, in keepalive + with self.send_context(): + File "/home/gotham/.local/share/uv/python/cpython-3.11.14-linux-x86_64-gnu/lib/python3.11/contextlib.py", line 144, in __exit__ + next(self.gen) + File "/tmp/plugrl-stranger/plugrl-env-client/.venv/lib/python3.11/site-packages/websockets/sync/connection.py", line 1012, in send_context + raise self.protocol.close_exc from original_exc +websockets.exceptions.ConnectionClosedError: sent 1011 (internal error) keepalive ping timeout; no close frame received +2026-09-11 14:22:04.586 | INFO | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=5541 infer_calls=5541 feedback_calls=5541 infer_wait=298.125s infer_obs_pack=0.218s env_step=1.836s feedback_total=1.164s feedback_obs_pack=0.319s feedback_info_pack=0.054s effective_fps=18.39 +2026-09-11 14:22:34.627 | INFO | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=6126 infer_calls=6126 feedback_calls=6126 infer_wait=327.664s infer_obs_pack=0.246s env_step=2.053s feedback_total=1.313s feedback_obs_pack=0.358s feedback_info_pack=0.060s effective_fps=18.49 +2026-09-11 14:23:04.639 | INFO | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=6742 infer_calls=6742 feedback_calls=6742 infer_wait=357.209s infer_obs_pack=0.271s env_step=2.259s feedback_total=1.451s feedback_obs_pack=0.394s feedback_info_pack=0.066s effective_fps=18.67 +2026-09-11 14:23:34.665 | INFO | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=7351 infer_calls=7351 feedback_calls=7351 infer_wait=386.743s infer_obs_pack=0.296s env_step=2.477s feedback_total=1.593s feedback_obs_pack=0.432s feedback_info_pack=0.072s effective_fps=18.80 +2026-09-11 14:24:04.683 | INFO | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=7936 infer_calls=7936 feedback_calls=7936 infer_wait=416.244s infer_obs_pack=0.323s env_step=2.702s feedback_total=1.745s feedback_obs_pack=0.470s feedback_info_pack=0.078s effective_fps=18.85 +2026-09-11 14:24:34.727 | INFO | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=8471 infer_calls=8471 feedback_calls=8471 infer_wait=445.829s infer_obs_pack=0.347s env_step=2.903s feedback_total=1.880s feedback_obs_pack=0.503s feedback_info_pack=0.084s effective_fps=18.78 +2026-09-11 14:25:04.748 | INFO | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=9063 infer_calls=9063 feedback_calls=9063 infer_wait=475.333s infer_obs_pack=0.374s env_step=3.130s feedback_total=2.031s feedback_obs_pack=0.542s feedback_info_pack=0.090s effective_fps=18.85 +2026-09-11 14:25:34.792 | INFO | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=9656 infer_calls=9656 feedback_calls=9656 infer_wait=504.849s infer_obs_pack=0.401s env_step=3.363s feedback_total=2.186s feedback_obs_pack=0.582s feedback_info_pack=0.096s effective_fps=18.90 +2026-09-11 14:26:04.829 | INFO | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=10272 infer_calls=10272 feedback_calls=10272 infer_wait=534.369s infer_obs_pack=0.427s env_step=3.593s feedback_total=2.335s feedback_obs_pack=0.622s feedback_info_pack=0.103s effective_fps=19.00 +2026-09-11 14:26:34.875 | INFO | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=10892 infer_calls=10892 feedback_calls=10892 infer_wait=563.941s infer_obs_pack=0.451s env_step=3.807s feedback_total=2.469s feedback_obs_pack=0.657s feedback_info_pack=0.109s effective_fps=19.09 +2026-09-11 14:27:04.918 | INFO | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=11512 infer_calls=11512 feedback_calls=11512 infer_wait=593.506s infer_obs_pack=0.474s env_step=4.020s feedback_total=2.610s feedback_obs_pack=0.695s feedback_info_pack=0.115s effective_fps=19.17 +2026-09-11 14:27:30.916 | INFO | plugrl_env_client.runner.run:run:156 - Server signalled the end of the run; collection stopped after 12/20 episodes. diff --git a/experiments/e8-keepalive-hypothesis/results/short-learns-client.log b/experiments/e8-keepalive-hypothesis/results/short-learns-client.log new file mode 100644 index 0000000..e477fd5 --- /dev/null +++ b/experiments/e8-keepalive-hypothesis/results/short-learns-client.log @@ -0,0 +1,24 @@ +2026-09-11 15:22:14.193 | WARNING  | plugrl_env_client.envs:_load_env_modules:27 - Skip loading env module plugrl_env_client.envs.atari.atari_env: Atari is not installed. Please install it with the 'atari' extra, e.g. 'pip install plugrl-env-client[atari]' +2026-09-11 15:22:14.198 | WARNING  | plugrl_env_client.envs:_load_env_modules:27 - Skip loading env module plugrl_env_client.envs.classic.classic_env: pygame is not installed. Please install it with pip install "plugrl-env-client[classic]". +2026-09-11 15:22:14.202 | WARNING  | plugrl_env_client.envs:_load_env_modules:27 - Skip loading env module plugrl_env_client.envs.d4rl.d4rl_env: d4rl is not installed. Please install it with pip install "plugrl-env-client[d4rl]". +2026-09-11 15:22:14.205 | WARNING  | plugrl_env_client.envs:_load_env_modules:27 - Skip loading env module plugrl_env_client.envs.libero.libero_env: libero is not installed. Please install it with pip install "plugrl-env-client[libero]". +2026-09-11 15:22:14.216 | WARNING  | plugrl_env_client.envs:_load_env_modules:27 - Skip loading env module plugrl_env_client.envs.robomimic.robomimic_env: Robomimic is not installed. Please install it with the 'robomimic' extra, e.g. 'pip install plugrl-env-client[robomimic]' +2026-09-11 15:22:14.423 | INFO  | __main__:main:83 - Starting env client exp_name=mujoco-v1-nenv1-20260911-152214-789f7c6f output_dir=runs\mujoco-v1-nenv1-20260911-152214-789f7c6f recorder={'episode_freq': 0, 'thread0_only': True, 'record_video': False, 'video_fps': 30.0, 'record_full_rollout': False, 'record_obs_stats': True, 'record_episode_metrics': True, 'metric_window': 100} +2026-09-11 15:22:14.725 | INFO  | plugrl_env_client.agent.websocket_env_client_agent:_wait_for_server:67 - Waiting for server at ws://127.0.0.1:8617... +2026-09-11 15:22:14.733 | INFO  | plugrl_env_client.runner.run:report_server_metadata:56 - Server metadata: {'protocol_version': 1, 'server': 'plugrl-server', 'server_version': '0.1.0', 'algorithm': 'FPOAlgorithm', 'policy': 'FPOPolicy', 'action_dim': 6, 'action_horizon': 1} +2026-09-11 15:22:44.740 | INFO  | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=3821 infer_calls=3821 feedback_calls=3821 infer_wait=25.002s infer_obs_pack=0.298s env_step=1.945s feedback_total=1.759s feedback_obs_pack=0.381s feedback_info_pack=0.057s effective_fps=131.74 +2026-09-11 15:23:14.745 | INFO  | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=8127 infer_calls=8127 feedback_calls=8127 infer_wait=49.317s infer_obs_pack=0.670s env_step=4.207s feedback_total=3.662s feedback_obs_pack=0.812s feedback_info_pack=0.122s effective_fps=140.47 +2026-09-11 15:23:44.749 | INFO  | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=12209 infer_calls=12209 feedback_calls=12209 infer_wait=73.663s infer_obs_pack=1.039s env_step=6.355s feedback_total=5.682s feedback_obs_pack=1.266s feedback_info_pack=0.185s effective_fps=140.76 +2026-09-11 15:24:14.749 | INFO  | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=16115 infer_calls=16115 feedback_calls=16115 infer_wait=97.977s infer_obs_pack=1.424s env_step=8.563s feedback_total=7.647s feedback_obs_pack=1.690s feedback_info_pack=0.247s effective_fps=139.39 +2026-09-11 15:24:49.767 | INFO  | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=16386 infer_calls=16386 feedback_calls=16386 infer_wait=132.661s infer_obs_pack=1.445s env_step=8.691s feedback_total=7.764s feedback_obs_pack=1.717s feedback_info_pack=0.251s effective_fps=108.83 +2026-09-11 15:25:19.769 | INFO  | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=20250 infer_calls=20250 feedback_calls=20250 infer_wait=157.786s infer_obs_pack=1.742s env_step=10.608s feedback_total=9.452s feedback_obs_pack=2.096s feedback_info_pack=0.307s effective_fps=112.76 +2026-09-11 15:25:49.770 | INFO  | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=24178 infer_calls=24178 feedback_calls=24178 infer_wait=182.884s infer_obs_pack=2.046s env_step=12.527s feedback_total=11.149s feedback_obs_pack=2.481s feedback_info_pack=0.365s effective_fps=115.90 +2026-09-11 15:26:19.775 | INFO  | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=28002 infer_calls=28002 feedback_calls=28002 infer_wait=208.039s infer_obs_pack=2.341s env_step=14.420s feedback_total=12.840s feedback_obs_pack=2.862s feedback_info_pack=0.421s effective_fps=117.83 +2026-09-11 15:26:49.777 | INFO  | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=31821 infer_calls=31821 feedback_calls=31821 infer_wait=233.159s infer_obs_pack=2.640s env_step=16.331s feedback_total=14.536s feedback_obs_pack=3.239s feedback_info_pack=0.477s effective_fps=119.33 +2026-09-11 15:27:28.128 | INFO  | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=32769 infer_calls=32769 feedback_calls=32769 infer_wait=270.337s infer_obs_pack=2.709s env_step=16.794s feedback_total=14.940s feedback_obs_pack=3.329s feedback_info_pack=0.491s effective_fps=107.52 +2026-09-11 15:27:58.131 | INFO  | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=37384 infer_calls=37384 feedback_calls=37384 infer_wait=294.923s infer_obs_pack=3.044s env_step=18.927s feedback_total=16.811s feedback_obs_pack=3.757s feedback_info_pack=0.555s effective_fps=112.03 +2026-09-11 15:28:28.136 | INFO  | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=41624 infer_calls=41624 feedback_calls=41624 infer_wait=319.874s infer_obs_pack=3.351s env_step=20.912s feedback_total=18.564s feedback_obs_pack=4.157s feedback_info_pack=0.614s effective_fps=114.76 +2026-09-11 15:28:58.591 | INFO  | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=45332 infer_calls=45332 feedback_calls=45332 infer_wait=345.690s infer_obs_pack=3.636s env_step=22.728s feedback_total=20.178s feedback_obs_pack=4.518s feedback_info_pack=0.669s effective_fps=115.57 +2026-09-11 15:29:28.600 | INFO  | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=47015 infer_calls=47015 feedback_calls=47015 infer_wait=372.825s infer_obs_pack=3.816s env_step=23.838s feedback_total=21.186s feedback_obs_pack=4.735s feedback_info_pack=0.703s effective_fps=111.50 +2026-09-11 15:29:58.606 | INFO  | plugrl_env_client.runner.rollout:log_timing_summary:98 - Intermediate rollout timing summary: env_steps=48686 infer_calls=48686 feedback_calls=48686 infer_wait=399.898s infer_obs_pack=3.996s env_step=24.981s feedback_total=22.217s feedback_obs_pack=4.953s feedback_info_pack=0.737s effective_fps=107.93 +2026-09-11 15:30:52.309 | INFO  | plugrl_env_client.runner.run:run:156 - Server signalled the end of the run; collection stopped after 49/100000 episodes. diff --git a/experiments/e8-keepalive-hypothesis/results/short-learns-server.log b/experiments/e8-keepalive-hypothesis/results/short-learns-server.log new file mode 100644 index 0000000..42dfacc --- /dev/null +++ b/experiments/e8-keepalive-hypothesis/results/short-learns-server.log @@ -0,0 +1,19 @@ +Could not import DPPO algorithm module for reason: No module named 'dppo' +15:22:10|INFO|plugrl_server version: 0.1.0 +15:22:10|INFO|Algorithm: fpo, Config: FPOAlgoConfig(global_steps=49152, buffer_size=16384, output_mode='u_but_supervise_as_eps', fpo_playground_trick=True, treat_truncated_as_done=False, discounting=0.995, reward_scaling=10.0, gae_lambda=0.95, batch_size=1024, num_updates_per_batch=16, learning_rate=0.0003, value_loss_coeff=0.25, clipping_epsilon=0.05, normalize_advantage=True, n_samples_per_action=8, discretize_t_for_training=True, average_losses_before_exp=True, save_interval=10) +15:22:10|INFO|Policy: fpo-policy, Config: FPOPolicyConfig(algo='fpo', device=device(type='cpu'), obs_dim=17, action_dim=6, flow_steps=10, timestep_embed_dim=8, action_horizon=1, feather_std=0.0, policy_mlp_output_scale=0.25, normalize_observations=True, hidden_dims=(32, 32, 32, 32), value_hidden_dims=(256, 256, 256, 256, 256)) +15:22:10|INFO|Checkpoint Manager created: + at C:\Users\75128\.claude\jobs\1fea619d\tmp\e8\short-learns\ck\fpo\fpo-policy\e8 +15:22:12|INFO|Policy created... +15:22:12|INFO|Initialized RolloutBuffer buffer_size=16384 action_shape=(16384, 1, 6) value_shape=(16384, 1) +15:22:12|INFO|Algorithm created: + +15:22:12|INFO|Agent Server is listening on 0.0.0.0:8617 +15:30:52|INFO|Checkpoint saved at step 49153 to C:\Users\75128\.claude\jobs\1fea619d\tmp\e8\short-learns\ck\fpo\fpo-policy\e8\49153 +15:30:52|INFO|Stopping server as the algorithm signaled to stop. +15:30:52|INFO|Shutdown started: aborting pending infer requests. +15:30:52|INFO|Shutdown cleanup finished: pending_futures=1, drained_requests=1 +15:30:52|INFO|Shutdown closing 1 websocket connection(s). +15:30:52|INFO|Shutdown interrupted an in-flight inference request from ('127.0.0.1', 60637). +15:30:52|INFO|WebSocket server closed. +15:30:52|INFO|Scheduler task cancelled and cleaned up. diff --git a/experiments/e8-keepalive-hypothesis/run.sh b/experiments/e8-keepalive-hypothesis/run.sh new file mode 100644 index 0000000..f7c01f1 --- /dev/null +++ b/experiments/e8-keepalive-hypothesis/run.sh @@ -0,0 +1,70 @@ +#!/usr/bin/env bash +# E8: does turning the keepalive off actually stop the drops? +# +# The bug needs a learn step longer than the 20 s ping timeout. E6 used +# buffer_size=4096 - 16*ceil(4096/1024) = 64 gradient steps - and never +# tripped it. This raises the buffer until the learn step is long, holds +# everything else fixed, and runs the same configuration on both sides of +# the fix. +set -uo pipefail + +ROOT="$(cd "$(dirname "$0")" && pwd)" +SRV=/d/75128/Desktop/plugrl-work/plugrl-server +CLI=/d/75128/Desktop/plugrl-work/plugrl-env-client + +LABEL="$1" # before | after +BUFFER="${2:-32768}" +STEPS="${3:-32768}" +NENV="${4:-1}" +PORT="${5:-8611}" +# Gradient steps per learn are num_updates_per_batch * ceil(buffer/batch_size). +# Raising the epoch count rather than the buffer keeps the fill short while +# making the learn long, and it is the learn's duration - not the buffer's +# size - that the keepalive races against. +NUPD="${6:-400}" + +OUT="$ROOT/$LABEL" +rm -rf "$OUT"; mkdir -p "$OUT" + +# A client that dies on startup used to leave the server listening forever, +# and the next run then failed to bind. Kill it on the way out either way. +cleanup() { + [ -n "${SRV_PID:-}" ] && kill "$SRV_PID" 2>/dev/null + # A client that dies on startup used to leave the server listening for + # ever, and the next run then failed to bind. Take the port back by pid. + for pid in $(netstat -ano 2>/dev/null | awk -v p=":$PORT" '$2 ~ p && $4=="LISTENING" {print $5}' | sort -u); do + powershell.exe -NoProfile -Command "Stop-Process -Id $pid -Force -ErrorAction SilentlyContinue" >/dev/null 2>&1 + done +} +trap cleanup EXIT + +echo "== $LABEL: buffer=$BUFFER steps=$STEPS envs=$NENV port=$PORT updates=$NUPD" +echo " gradient steps per learn: $(( NUPD * ( (BUFFER + 1023) / 1024 ) ))" +echo " server @ $(git -C "$SRV" rev-parse --abbrev-ref HEAD) client @ $(git -C "$CLI" rev-parse --abbrev-ref HEAD)" + +(cd "$SRV" && ./.venv/Scripts/python.exe -m plugrl_server.cli fpo-policy default fpo default \ + --port "$PORT" --policy.device cpu \ + --algo.global-steps "$STEPS" --algo.buffer-size "$BUFFER" \ + --algo.num-updates-per-batch "$NUPD" \ + --no-show-progress-bar --no-show-metric-table \ + --checkpoint-base-dir "$OUT/ck" --exp-name e8 --overwrite > "$OUT/server.log" 2>&1) & +SRV_PID=$! + +for i in $(seq 120); do + grep -q "is listening" "$OUT/server.log" 2>/dev/null && break + sleep 1 +done +grep -q "is listening" "$OUT/server.log" || { echo " server never listened"; tail -5 "$OUT/server.log"; exit 1; } + +START=$(date +%s) +(cd "$CLI" && ./.venv/Scripts/python.exe -m plugrl_env_client.cli mujoco-v1 \ + --server-host 127.0.0.1 --server-port "$PORT" \ + --num-envs "$NENV" --num-episodes 100000 \ + --runner.replan-steps 1 --runner.seed 0 > "$OUT/client.log" 2>&1) +echo " client exit $? after $(( $(date +%s) - START ))s" +wait $SRV_PID 2>/dev/null + +echo " keepalive timeouts (server): $(grep -c 'keepalive' "$OUT/server.log")" +echo " 1011 closes (server): $(grep -c '1011' "$OUT/server.log")" +echo " reconnects (client): $(( $(grep -c 'Waiting for server' "$OUT/client.log") - 1 ))" +echo " feedback-no-state (server): $(grep -c 'arrived with no step' "$OUT/server.log")" diff --git a/src/plugrl_server/server/websocket_agent_server.py b/src/plugrl_server/server/websocket_agent_server.py index 83dfbc5..0eb058f 100644 --- a/src/plugrl_server/server/websocket_agent_server.py +++ b/src/plugrl_server/server/websocket_agent_server.py @@ -330,6 +330,20 @@ async def _handler(self, websocket: _server.ServerConnection): prev_node = prev_node_map.get(eid, (-1, "")) step_state = step_state_map.get(eid, None) + if step_state is None: + # Every env that reaches feedback got an action + # first, on this connection, which is what fills + # this map - so a miss means the connection was + # replaced and the state went with it. The + # transition below is then built from an empty + # observation and no step state. That used to + # happen without a word; it is at least loud now. + logger.warning( + f"Feedback for env {eid} arrived with no step " + "state. The connection was almost certainly " + "re-established mid-run, and this transition " + "carries no previous observation." + ) runtime_state = ( step_state.runtime_state if step_state is not None else None ) diff --git a/tests/test_serve_options.py b/tests/test_serve_options.py new file mode 100644 index 0000000..9df64ac --- /dev/null +++ b/tests/test_serve_options.py @@ -0,0 +1,81 @@ +"""The server must not cap the frame size, and must survive a reconnect. + +An observation is megabytes, so `max_size` has to stay off; the `websockets` +default of 1 MiB would reject a two-camera frame outright. + +The keepalive is deliberately left at the library default. An earlier version +of this file asserted `ping_interval is None`, on the theory that a CPU-bound +learn step holds the event loop past the 20 s ping timeout. That theory was +measured and is false - `LocalTrainingBackend` runs `learn` through +`asyncio.to_thread`, and five learns of about 180 s each produced no timeout +at all. See `experiments/e8-keepalive-hypothesis/`. + +What is true, and what `test_a_missing_step_state_is_reported` covers, is the +consequence of a reconnect whatever caused it: the per-environment maps live +in the connection handler, so the new connection starts empty. +""" + +import asyncio + +import pytest + +from plugrl_server.server import websocket_agent_server as mod +from plugrl_server.server.websocket_agent_server import WebSocketAgentServer + + +class _Algorithm: + policy = None + + def get_total_training_steps(self): + return 100 + + def create_checkpoint(self): + return {"weights": "pretend"} + + +class _CheckpointManager: + def save_checkpoint(self, checkpoint): + pass + + +class _MetricSink: + def log_scalars(self, *_a, **_k): + pass + + +@pytest.fixture +def server(): + return WebSocketAgentServer( + _Algorithm(), + _CheckpointManager(), + _MetricSink(), + show_metric_table=False, + show_progress_bar=False, + ) + + +def _serve_kwargs(server, monkeypatch): + """Start the server against a stub `serve` and return how it was called.""" + seen = {} + + async def fake_serve(*args, **kwargs): + seen.update(kwargs) + server._lifecycle.stop_event.set() # let run() fall straight through + return None + + monkeypatch.setattr(mod._server, "serve", fake_serve) + monkeypatch.setattr(server, "_install_signal_handlers", lambda: None) + monkeypatch.setattr(server, "_scheduler_loop", lambda: asyncio.sleep(0)) + + asyncio.run(server.run()) + return seen + + +def test_the_frame_size_cap_is_off(server, monkeypatch): + """An observation is megabytes; the 1 MiB default would reject it.""" + assert _serve_kwargs(server, monkeypatch)["max_size"] is None + + +def test_compression_is_off(server, monkeypatch): + """Observations are already-compressed image bytes; deflate only costs.""" + assert _serve_kwargs(server, monkeypatch)["compression"] is None