From 6fcf13188811ff72a0b5c3ae2480597038105392 Mon Sep 17 00:00:00 2001 From: Gotham-Zolio <18781106300@163.com> Date: Fri, 11 Sep 2026 14:31:10 -0400 Subject: [PATCH 1/4] fix: stop keepalive pings from silently corrupting training data A clean-machine run of the documented quickstart dropped its connection twice in six minutes: ConnectionClosedError: sent 1011 (internal error) keepalive ping timeout; no close frame received The cause is not the network. `websockets` defaults to a 20 s ping with a 20 s timeout, and a learn step is CPU-bound Python that holds the GIL for longer than that on a slow machine. The event loop never gets to read the pong, so the server closes a connection whose client is perfectly healthy. The disconnect itself is survivable - the env client reconnects. What is not survivable is what the reconnect loses. `prev_node_map`, `step_state_map`, `terminated_map`, `truncated_map` and `last_obs_map` are local to `_handler`, so a new connection starts with all five empty. The first feedback after a reconnect then reaches the algorithm with `last_obs={}`, `step_state=None` and `terminated=False`, and is stored as a transition. No exception, no warning: a corrupt transition in the buffer, and more of them the slower the machine. It only triggers under load, which is why it has never shown up in a fast-machine run. Two changes: * `ping_interval=None` on `serve`. The protocol already has its own liveness mechanism - a server that waits FEEDBACK_WAIT_TIMEOUT for feedback and gives up - so the ping adds no detection the server did not already have, and costs this. * a warning when feedback arrives for an environment with no step state. Every environment that reaches feedback was given an action first on the same connection, so a miss means exactly one thing, and it should say so rather than quietly feed the learner an empty observation. Regression test asserts both `ping_interval` and `max_size` are None at the `serve` call, verified to fail when the keyword is removed. Co-Authored-By: Claude Opus 5 (1M context) --- .../server/websocket_agent_server.py | 34 +++++++- tests/test_keepalive.py | 79 +++++++++++++++++++ 2 files changed, 112 insertions(+), 1 deletion(-) create mode 100644 tests/test_keepalive.py diff --git a/src/plugrl_server/server/websocket_agent_server.py b/src/plugrl_server/server/websocket_agent_server.py index 83dfbc5..b9107c2 100644 --- a/src/plugrl_server/server/websocket_agent_server.py +++ b/src/plugrl_server/server/websocket_agent_server.py @@ -185,7 +185,25 @@ async def run(self): self._install_signal_handlers() try: self._server = await _server.serve( - self._handler, self._host, self._port, compression=None, max_size=None + self._handler, + self._host, + self._port, + compression=None, + max_size=None, + # websockets defaults to a 20 s ping with a 20 s timeout, and + # a learn step is CPU-bound work that can hold the GIL past + # that. On a slow machine the server then closes the + # connection with 1011 for a client that is perfectly + # healthy - and because the per-environment maps live in the + # connection handler, the reconnect starts with empty ones + # and the next feedback reaches the algorithm with no + # previous observation and no step state. Silent, and worse + # than the disconnect it came from. + # + # This protocol has its own liveness mechanism already: + # FEEDBACK_WAIT_TIMEOUT. Keepalive pings on top of it buy + # nothing and cost that. + ping_interval=None, ) logger.info(f"Agent Server is listening on {self._host}:{self._port}") await self._lifecycle.stop_event.wait() @@ -330,6 +348,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_keepalive.py b/tests/test_keepalive.py new file mode 100644 index 0000000..411268d --- /dev/null +++ b/tests/test_keepalive.py @@ -0,0 +1,79 @@ +"""The server must not ping its clients to death. + +`websockets` defaults to a 20 s keepalive ping with a 20 s timeout. A learn +step is CPU-bound Python: it holds the GIL, the event loop does not run, the +pong is not read, and the server closes a perfectly healthy connection with +1011. That is bad on its own, and worse than it looks: the per-environment +maps that carry the previous observation live inside the connection handler, +so the reconnect starts with empty ones and the next feedback reaches the +algorithm with nothing behind it. No error, just a corrupt transition. + +The protocol already has its own liveness check - FEEDBACK_WAIT_TIMEOUT - so +the ping buys nothing. These tests pin that down, because the setting is one +keyword away from coming back by accident. +""" + +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_keepalive_pings_are_off(server, monkeypatch): + """A learn step can outlast any ping interval, so there is no safe one.""" + assert _serve_kwargs(server, monkeypatch)["ping_interval"] is None + + +def test_the_frame_size_cap_is_still_off(server, monkeypatch): + """An observation is megabytes; the 1 MiB default would reject it.""" + assert _serve_kwargs(server, monkeypatch)["max_size"] is None From 6320bd0b817ad3a4ed11cd78eddfa0b4323819a5 Mon Sep 17 00:00:00 2001 From: Gotham-Zolio <18781106300@163.com> Date: Fri, 11 Sep 2026 14:41:00 -0400 Subject: [PATCH 2/4] docs: say what turning the keepalive off gives up The comment justified the change and stopped there, which made it read as free. It is not: the feedback timeout bounds the wait between an action and its feedback, and the recv that waits for the next infer is unbounded, so a peer that dies without closing its socket now parks a coroutine until TCP gives up rather than being noticed in 20 s. Also records why a long ping timeout was rejected instead of chosen, since that is the obvious next question and the answer - the value would have to exceed a learn step of 16 x ceil(buffer_size / 1024) gradient steps on unknown hardware - is not obvious. Co-Authored-By: Claude Opus 5 (1M context) --- .../server/websocket_agent_server.py | 20 ++++++++++++++++++- 1 file changed, 19 insertions(+), 1 deletion(-) diff --git a/src/plugrl_server/server/websocket_agent_server.py b/src/plugrl_server/server/websocket_agent_server.py index b9107c2..4b46f5b 100644 --- a/src/plugrl_server/server/websocket_agent_server.py +++ b/src/plugrl_server/server/websocket_agent_server.py @@ -202,7 +202,25 @@ async def run(self): # # This protocol has its own liveness mechanism already: # FEEDBACK_WAIT_TIMEOUT. Keepalive pings on top of it buy - # nothing and cost that. + # almost nothing and cost that. + # + # Almost, and not nothing: the feedback timeout covers the + # wait between an action and its feedback, and the recv above + # that waits for the next infer is unbounded. A peer that dies + # without closing its socket - power cut, cable out - leaves + # that recv parked until the operating system gives up on the + # TCP connection, where before it would have been noticed in + # 20 s. It costs one idle coroutine and one socket, and the + # run was going to stall regardless, because a dead client + # sends no more observations either way. + # + # A long ping timeout instead of none would close that gap, + # and was rejected: the value would have to exceed the + # longest learn step, which is 16 x ceil(buffer_size / 1024) + # gradient steps of whatever policy the user brought, on + # whatever hardware they have. Any number here is a guess + # about someone else's machine, and being wrong about it + # costs real transitions. ping_interval=None, ) logger.info(f"Agent Server is listening on {self._host}:{self._port}") From b2895e24f49f5e2654e57560fc128720ec800778 Mon Sep 17 00:00:00 2001 From: Gotham-Zolio <18781106300@163.com> Date: Fri, 11 Sep 2026 15:22:46 -0400 Subject: [PATCH 3/4] fix: drop the keepalive change, measurement says the premise was false The earlier commits on this branch turned the server's keepalive off, on the reasoning that a CPU-bound learn step holds the event loop past the 20 s ping timeout and kills a healthy connection. That was measured and it is not what happens. LocalTrainingBackend runs learn through asyncio.to_thread, so the loop is free throughout, and five learn steps of 177-190 s each - nine times the timeout - produced no close at all. Two runs, default and inflated epoch counts, in experiments/e8-keepalive-hypothesis. The incident that started this was a machine suspending for one hour and fifty-three minutes mid-run, visible as a gap in a log that is otherwise written every thirty seconds. The timeout that fired came from the client library, not the server's, so turning the server's keepalive off would not have prevented it either. So ping_interval goes back to the library default and the test that pinned it is gone. What stays is the warning when feedback arrives for an environment with no step state, which was read out of the handler rather than inferred from the incident, and is true whatever caused the reconnect. The test file keeps the two assertions that are still real - compression and max_size - and records the falsified hypothesis so nobody re-derives it. Co-Authored-By: Claude Opus 5 (1M context) --- .../e8-keepalive-hypothesis/FINDINGS.md | 145 ++++++++++++++++++ .../results/long-learns-client.log | 13 ++ .../results/long-learns-server.log | 19 +++ .../results/original-incident-client.log | 45 ++++++ experiments/e8-keepalive-hypothesis/run.sh | 70 +++++++++ .../server/websocket_agent_server.py | 38 +---- ...est_keepalive.py => test_serve_options.py} | 40 ++--- 7 files changed, 314 insertions(+), 56 deletions(-) create mode 100644 experiments/e8-keepalive-hypothesis/FINDINGS.md create mode 100644 experiments/e8-keepalive-hypothesis/results/long-learns-client.log create mode 100644 experiments/e8-keepalive-hypothesis/results/long-learns-server.log create mode 100644 experiments/e8-keepalive-hypothesis/results/original-incident-client.log create mode 100644 experiments/e8-keepalive-hypothesis/run.sh rename tests/{test_keepalive.py => test_serve_options.py} (56%) diff --git a/experiments/e8-keepalive-hypothesis/FINDINGS.md b/experiments/e8-keepalive-hypothesis/FINDINGS.md new file mode 100644 index 0000000..1bf0988 --- /dev/null +++ b/experiments/e8-keepalive-hypothesis/FINDINGS.md @@ -0,0 +1,145 @@ +# 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 | +|---|---|---|---|---|---|---| +| 1 | 16384 | 16 (default) | 256 | 3 | 7-11 s | **0** | +| 2 | 4096 | 400 | 1600 | 5 | 177-190 s | **0** | + +Run 2's learn step is **nine times** the 20 s ping timeout, on every one of +five cycles, and nothing closed. The durations are measured as gaps between +the client's 30 s periodic timing lines, so they include only what the client +waited. + +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 before 16384 49152 1 8613 16 # default epochs: short learns +bash run.sh before 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/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 4b46f5b..0eb058f 100644 --- a/src/plugrl_server/server/websocket_agent_server.py +++ b/src/plugrl_server/server/websocket_agent_server.py @@ -185,43 +185,7 @@ async def run(self): self._install_signal_handlers() try: self._server = await _server.serve( - self._handler, - self._host, - self._port, - compression=None, - max_size=None, - # websockets defaults to a 20 s ping with a 20 s timeout, and - # a learn step is CPU-bound work that can hold the GIL past - # that. On a slow machine the server then closes the - # connection with 1011 for a client that is perfectly - # healthy - and because the per-environment maps live in the - # connection handler, the reconnect starts with empty ones - # and the next feedback reaches the algorithm with no - # previous observation and no step state. Silent, and worse - # than the disconnect it came from. - # - # This protocol has its own liveness mechanism already: - # FEEDBACK_WAIT_TIMEOUT. Keepalive pings on top of it buy - # almost nothing and cost that. - # - # Almost, and not nothing: the feedback timeout covers the - # wait between an action and its feedback, and the recv above - # that waits for the next infer is unbounded. A peer that dies - # without closing its socket - power cut, cable out - leaves - # that recv parked until the operating system gives up on the - # TCP connection, where before it would have been noticed in - # 20 s. It costs one idle coroutine and one socket, and the - # run was going to stall regardless, because a dead client - # sends no more observations either way. - # - # A long ping timeout instead of none would close that gap, - # and was rejected: the value would have to exceed the - # longest learn step, which is 16 x ceil(buffer_size / 1024) - # gradient steps of whatever policy the user brought, on - # whatever hardware they have. Any number here is a guess - # about someone else's machine, and being wrong about it - # costs real transitions. - ping_interval=None, + self._handler, self._host, self._port, compression=None, max_size=None ) logger.info(f"Agent Server is listening on {self._host}:{self._port}") await self._lifecycle.stop_event.wait() diff --git a/tests/test_keepalive.py b/tests/test_serve_options.py similarity index 56% rename from tests/test_keepalive.py rename to tests/test_serve_options.py index 411268d..9df64ac 100644 --- a/tests/test_keepalive.py +++ b/tests/test_serve_options.py @@ -1,16 +1,18 @@ -"""The server must not ping its clients to death. - -`websockets` defaults to a 20 s keepalive ping with a 20 s timeout. A learn -step is CPU-bound Python: it holds the GIL, the event loop does not run, the -pong is not read, and the server closes a perfectly healthy connection with -1011. That is bad on its own, and worse than it looks: the per-environment -maps that carry the previous observation live inside the connection handler, -so the reconnect starts with empty ones and the next feedback reaches the -algorithm with nothing behind it. No error, just a corrupt transition. - -The protocol already has its own liveness check - FEEDBACK_WAIT_TIMEOUT - so -the ping buys nothing. These tests pin that down, because the setting is one -keyword away from coming back by accident. +"""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 @@ -69,11 +71,11 @@ async def fake_serve(*args, **kwargs): return seen -def test_keepalive_pings_are_off(server, monkeypatch): - """A learn step can outlast any ping interval, so there is no safe one.""" - assert _serve_kwargs(server, monkeypatch)["ping_interval"] is None - - -def test_the_frame_size_cap_is_still_off(server, monkeypatch): +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 From 4ce76146da9b76bb52041f52b869040ab3b700d9 Mon Sep 17 00:00:00 2001 From: Gotham-Zolio <18781106300@163.com> Date: Fri, 11 Sep 2026 15:31:53 -0400 Subject: [PATCH 4/4] exp: E8, the learn step does not trip the keepalive Writes up the measurement that refuted this branch's original premise, with both runs, their logs, and the log from the incident that started it. Two refutations. At default settings one of three learn steps ran about 24 seconds, already past the 20 second ping timeout, and closed nothing. With the epoch count raised to 400 the learn step ran 177 to 190 seconds, nine times the timeout, five cycles running, and closed nothing. The cause is a line in training_backend.py: learn goes through asyncio.to_thread, so the event loop is free the whole time. The incident itself was a machine suspending for one hour fifty three minutes, visible as a hole in a log written every thirty seconds, and the timeout that fired belonged to the client library rather than the server. Also indexes E8 in the experiments README, under the questions and under "What was measured badly, and corrected", and aligns the E2 row there with the authorship caveat that E2's own findings now carry. Co-Authored-By: Claude Opus 5 (1M context) --- experiments/README.md | 22 ++++++++++++--- .../e8-keepalive-hypothesis/FINDINGS.md | 28 +++++++++++-------- .../results/short-learns-client.log | 24 ++++++++++++++++ .../results/short-learns-server.log | 19 +++++++++++++ 4 files changed, 78 insertions(+), 15 deletions(-) create mode 100644 experiments/e8-keepalive-hypothesis/results/short-learns-client.log create mode 100644 experiments/e8-keepalive-hypothesis/results/short-learns-server.log 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 index 1bf0988..dab69b7 100644 --- a/experiments/e8-keepalive-hypothesis/FINDINGS.md +++ b/experiments/e8-keepalive-hypothesis/FINDINGS.md @@ -35,15 +35,21 @@ 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 | -|---|---|---|---|---|---|---| -| 1 | 16384 | 16 (default) | 256 | 3 | 7-11 s | **0** | -| 2 | 4096 | 400 | 1600 | 5 | 177-190 s | **0** | - -Run 2's learn step is **nine times** the 20 s ping timeout, on every one of -five cycles, and nothing closed. The durations are measured as gaps between -the client's 30 s periodic timing lines, so they include only what the client -waited. +| 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`: @@ -135,8 +141,8 @@ part that rested on the incident alone is the part that was wrong. ## Reproducing ```bash -bash run.sh before 16384 49152 1 8613 16 # default epochs: short learns -bash run.sh before 4096 20480 1 8615 400 # long learns, ~15 min +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 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.