Skip to content

Stream the logs, and bound every copy of a run's output - #72

Open
jorgeMFS wants to merge 1 commit into
output-provenancefrom
live-logs
Open

jorgeMFS wants to merge 1 commit into
output-provenancefrom
live-logs

Conversation

@jorgeMFS

Copy link
Copy Markdown
Contributor

Refs #6 and #8, both of which are already delivered — this completes them.

Merge order

Stacked. Base this on output-provenance (#71).

Why this is separate

It was originally mixed into #71, which is #18 (provenance). It belongs to #6 (per-step logs) and #8 (progress) instead, so it is its own PR.

The logs were recorded once, after the process exited

#6 delivered them and #8 delivered per-step progress from the same lines — but the mechanism to stream was already there: on_line hands over every line as it arrives. They are handed to the run twice a second now, so a run still going can be read as it goes.

The timer is the half that matters. Checking the clock only when a line arrives looks equivalent and is not: a tool that prints "starting" and then works silently for ten minutes would show nothing for ten minutes — precisely the run someone wants the logs for. A thread does the waking.

Only that thread delivers. If a reader thread could deliver too, two of them could build snapshots in one order and hand them over in the other, and a client polling twice would see the log go backwards. It also keeps a slow consumer away from the readers draining the tool's pipes: if they stall the pipe fills and the tool stops writing.

Every copy of a run's output is now bounded

Including the runner's own capture, which never was — a chatty tool could decide how much memory the agent used. Nothing is lost that would have survived being recorded, since the store keeps BIOCHEF_MAX_LOG_BYTES either way.

TailBuffer is that ceiling, in one place rather than three:

the tail is kept, not the head an error arrives at the end; a truncated beginning costs progress chatter
truncation is announced a log that starts mid-sentence with no marker reads like a broken tool
one line longer than the budget is truncated to its own tail a tool emitting no newline — a progress bar redrawing with \r, or binary on stdout — arrives as a single line of any size

Lifetime

The ticker is stopped in a finally, and close() waits for a delivery already in flight: perform_run closes the log and then records the authoritative output, so a flush still running could otherwise overwrite a complete log with a partial one.

What a poll returns mid-run is a partial log. The authoritative one is recorded when the process exits, from the runner's complete capture.

Verified

Against real snakemake, not a fixture: a 4.34 s two-step workflow flushed at +0.87 s, +1.98 s and +3.12 s with the visible output growing each time. Thread counts are asserted across twelve runs and twelve failing runs — zero leaked.

275 tests pass.

#6 delivered the logs and #8 delivered per-step progress from the same lines,
but the logs were still recorded once, after the process exited. The mechanism
to do better already existed: on_line delivers every line as it arrives.

They are handed to the run twice a second now, so a run still going can be read
as it goes.

The timer is the half that matters. Checking the clock only when a line arrives
looks equivalent and is not: a tool that prints "starting" and then works
silently for ten minutes would show nothing for ten minutes, which is precisely
the run someone wants the logs for. A thread does the waking.

Only that thread delivers. If a reader thread could deliver too, two of them
could build snapshots in one order and hand them over in the other, and a client
polling twice would see the log go backwards. It also keeps a slow consumer away
from the readers draining the tool's pipes -- if they stall the pipe fills and
the tool stops writing.

Everything holding a run's output is now bounded by the same MAX_LOG_BYTES,
including the runner's own capture, which never was. A chatty tool could
otherwise decide how much memory the agent used, and nothing is lost that would
have survived being recorded.

TailBuffer is that ceiling, in one place rather than three:

  the tail is kept, not the head    an error arrives at the end; a truncated
                                    beginning costs progress chatter
  truncation is announced           a log that starts mid-sentence with no
                                    marker reads like a broken tool
  one line longer than the budget   a tool emitting no newline -- a progress bar
  is truncated to its own tail      redrawing with \r, or binary on stdout --
                                    arrives as a single line of any size

What a poll returns mid-run is a partial log. The authoritative one is recorded
when the process exits, from the runner's complete capture, so anything trimmed
or still buffered costs nothing in the end.

The ticker is stopped in a finally, and close() waits for a delivery already in
flight: perform_run closes the log and then records the authoritative output, so
a flush still running could otherwise overwrite a complete log with a partial
one.

Refs #6 #8
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.

1 participant