Skip to content

Forward each sly-net-client log line once across restarts - #127

Draft
supervisely-integrations[bot] wants to merge 3 commits into
masterfrom
agent/6216-work
Draft

supervisely-integrations[bot] wants to merge 3 commits into
masterfrom
agent/6216-work

Conversation

@supervisely-integrations

Copy link
Copy Markdown

Resolves https://github.com/supervisely/issues/issues/6216

What Problem This Solves

When the sly-net-client container restarted or its log stream reconnected, the agent re-read the container's whole Docker log from the beginning and sent it to worker-api again. worker-api turned every replayed line into its own events.publish, so a net-client that restarts about once a minute flooded API. The agent now resumes from the last line it delivered, or from agent start if it has delivered nothing, so each line reaches worker-api once and new lines still arrive.

Why This Change Was Made

Two things caused the duplicates, and both are fixed.

  1. logs(follow=True, stream=True) had no since, so every reconnect started from the beginning of the log.
  2. task_stream_net_client_logs attached another TaskHandler and file handler on each re-entry from _run_daemon, so every line was sent once per past reconnect.

The new ContainerLogFollower in agent_utils.py keeps a cursor based on Docker's own log timestamps (timestamps=True). A time-based cursor still works when the container restarts or is recreated under the same name; a container-ID or byte-offset cursor would not. Docker's since is inclusive and whole-second, so lines at or below the cursor are skipped only until the stream has passed what was already delivered. After that, a stderr line stamped slightly earlier than the stdout line before it is still delivered. Docker stamps stdout and stderr separately, so these lines are new and must not be dropped. With no cursor yet, the start point is the agent's start time, so history from before this agent is never forwarded. The net_client logger is now set up once.

This continues the existing branch agent/6216-work (c90032d, 99ae435, a813723) as the human asked. This round added no new commits: the branch was re-verified and handed off.

User Impact

Agents that include this fix stop re-sending old sly-net-client log lines to worker-api on every net-client restart. The events.publish storm on API from a crash-looping net-client goes away. After an agent restart, net-client lines logged before that agent started are no longer forwarded. No configuration or migration is needed. It does not fix the stand-specific trigger (sly-net-server missing on sergey-dev), which is a deployment problem.

Evidence

  • Before, on the pre-fix code (c78a8e2) with the new Docker regression test. Throwaway copy: removed the follower import and setup line, which do not exist in the old code. Ran pytest -q tests/test_net_client_logs.py -k restarting on a real Docker 28.3.3 daemon with a busybox net-client that crashes every second (restart=always), under the agent's real _run_daemon, drained by submit_log into a recorded Log RPC. Result: FAILED. 15 lines were delivered more than once (Left contains 15 more items, first extra item: 'line-ad0609f5-...').
  • After, on branch agent/6216-work at a813723: the same test passed 3 of 3 runs, about 12 s each. Every line was sent to the Log RPC exactly once, no history from before start was sent, the new lines arrived in order without gaps, and at least 9 lines arrived across at least 3 restarts.
  • After: pytest -q tests/test_net_client_logs.py tests/test_run_daemon.py → 17 passed in 11.95s. This includes unit tests for: reconnect exactly-once, lines sharing a timestamp across a reconnect, out-of-order stderr lines, multibyte text split across chunks, and timestamp parsing.
  • pytest -q tests (whole directory) fails at collection with KeyError: 'ACCESS_TOKEN' from tests/clean_functions and the import order that follows. It fails the same way on the pre-fix commit c78a8e2, so it was already broken and this change did not cause it.
  • Passed an independent review of a81372305967 in a fresh checkout.
  • Not verified: Not checked end to end against a real worker-api and API. The regression test stops at the agent's Log gRPC call to worker-api, which is where lines leave the agent. I did not measure events.publish counts on API; If the stream reconnects and a genuinely new stderr line carries a timestamp earlier than the cursor and arrives before the first line past the cursor, it is dropped. This only happens with interleaving within the same few microseconds at a reconnect; The Docker regression test skips itself when no Docker daemon is reachable or busybox:1.36 cannot be pulled; Running the whole tests/ directory in one pytest call was already broken (tests/clean_functions needs ACCESS_TOKEN at import), so the replay names the two test files explicitly; The deployment trigger (sly-net-server missing from sergey-dev) is a separate problem and was not changed here.

supervisely-agent added 3 commits September 24, 2026 22:36
The net-client log reader re-read the container's whole docker log on every
reconnect and attached another log handler each time, so every restart re-sent
all historical lines (multiplied) to events.publish.

Follow the stream with timestamps and resume from the last delivered line's
timestamp (starting at agent start), and set up the net_client logger once.

Refs supervisely/issues#6216
…played prefix

Docker stamps stdout and stderr in separate goroutines, so a live stderr line
(e.g. curl's error) can follow a stdout line with a later timestamp. The follower
dropped every line older than its cursor, including such new lines; the
timestamp filter now only applies until the stream has passed what was already
delivered.
…al supervisor

The Docker regression test called the reader body by hand and stopped at the
agent's log queue. Run it under _run_daemon (the loop that reconnects after each
net-client restart) and drain it with submit_log into a recorded Log RPC, the
point where lines leave the agent for worker-api. Wait for delivered lines
instead of sleeping, since docker's restart delay grows with each crash.

Refs supervisely/issues#6216
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

0 participants