fix: warn when feedback arrives with no step state (and a falsified hypothesis)

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
 

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.

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.

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: 
+<plugrl_server.common.checkpoint_manager.CheckpointManager object at 0x000001ECA5B27A10> 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: 
+<plugrl_server.algorithm.fpo.fpo.FPOAlgorithm object at 0x000001ECA5AA0A10>
+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.