logs are not streamed when spread is run with `-vv`

[carlcsaposs-canonical]

Expected behavior

When spread is run with -vv, stdout from the task is streamed to the terminal that spread is executed from

Actual behavior

When spread is run with -vv, stdout from the task is only shown after the task script completes (except for small snippets of stdout that are shown every warn-timeout)

Impact

Delayed logs (e.g. on pull request CI) can make monitoring/troubleshooting tests more difficult. When the test suite is flaky or prone to stalling (e.g. lack of timeouts, timeouts set too high), monitoring real-time logs can make iterations quicker—since a fix can be pushed or a test can be cancelled & retried before the task fails

Additional information

When we run spread on GitHub Actions (for our pull request CI), we provision a runner for each spread job. On each runner, we run spread & select a single job

For this use case (single spread job & single machine), streaming of stdout is desired
If spread was run with multiple machines (and using -vv), streaming of stdout may be undesirable (since the logs from the different machines would presumably get mixed together)

In Frankfurt, we briefly mentioned this to @jnsgruk and it sounds like maybe the current behavior could be considered a bug—but given that spread could be run with multiple machines, wanted to check: is the current behavior the intended behavior—or would implementing log streaming (in a verbose mode) be compatible with spread's design?

[cmatsuoka]

Is your typical use case to run Spread with only a single job at a time?

[carlcsaposs-canonical]

Is your typical use case to run Spread with only a single job?

Yes, on GitHub Actions we only invoke spread with a single job (since spread cannot provision GitHub Actions runners)

[niemeyer]

So the idea is to run a single task at a time, with no buffering, and so that every single output is sent out to the terminal? That does not sound like a valid use case for Spread. We built this tool to organize the running of a volume of tasks that are streamed to remote systems, in parallel and with a work stealing model, and more often that not these tasks will succeed, so we do not want to look into the output of every single task that runs. When tasks do fail, these should be the ones reported, as that's where our attention needs to be. Before Spread, snapd used to rely on Autopkgtests, which look a lot like the mechanism you describe, with a rolling terminal that becomes very hard to understand once anything doesn't work as expected.

If this doesn't seem reasonable, I'm happy to discuss this in more detail so I can understand why. Also, if all you want is to run something in a terminal, one thing at a time, no buffering, etc, have you considered just literally running the script? Spread isn't helping you much by then.

This report seems related to PR 138, so I'm copy & pasting the feedback provided there as well:

---

This PR has been left unattended for years now. It has no motivation in its description, and its implementation is broken because it modifies the CLI behavior for options that have been out for a decade by now.

All I can do is guess why this was proposed, so some quick feedback:

1. One of the seed motivations for the creation of Spread back then was because autopkgtests offers a wall of text, and then you have to browse against a never-ending scrolling of pages to try to make sense of what it is saying. We should not bring that back.

2. You can get a list of which tasks are run, and thus a sense of "progress", by simply providing -v. I would discourage its use in CI because, again, you're forcing everyone to see a very long list of tasks that are irrelevant, instead of focusing on the things that do need attention.

3. If the goal is seeing things that are hanging, Spread does that automatically, with a configurable timeout (see warning-timeout), which will display the output until the point where it has stopped.

4. If the goal is to debug tasks that are failing, you can get a comprehensive output by using -vv today already.

So all of this are independent reasons why this could be unnecessary and unwanted. Ideally, though, such changes should be discussed in advance so that we can tell why something is being proposed at all, and what might be the best way of doing it.

[jnsgruk]

I think the big difference here is that the potential use-cases for spread have expanded since it was first written.

Critically, it's now the backbone of craft test, and therefore used much more in the development workflow than just a CI/validation workflow. We designed craft test to be a developer aid to help people test their charms, but also replicate easily the environments they test in (locally, and in CI, for example).

In this light running spread, through craft test, in single-task mode and wanting real-time output makes much more sense, so I think we should give this some due consideration.

I'd be happy to have this as a seperate option completely, meaning that existing workflows and modes of operation are not affected, but given that this can be completely opt-in, and the code required is very small indeed in surface, I'm struggling to see a reason not to consider this and dramatically improve the experience for 100s of new developers who are going to be using craft test every day.

(To be clear: I don't think this should be enabled by default!)

[jnsgruk]

If the goal is to debug tasks that are failing, you can get a comprehensive output by using -vv today already.

My understanding was also that this would work, and that the output would be unbuffered, but according to this report, that turns out not to be the case which makes this a valid bug report whether or not we introduce a new option to stream output.

[niemeyer]

Hi Jon. Your comments disagree somewhat with the description used in the issue. For example, this is the first sentence:

When spread is run with -vv, stdout from the task is streamed to the terminal that spread is executed from

We won't do this globally, ever, because you'll get lines coming from all tasks executing in parallel mixed together in a single very confusing rolling screen. Makes sense?

Then, while you talk about debugging something, the issue is actually talking about Pull Requests:

Delayed logs (e.g. on pull request CI) can make monitoring/troubleshooting tests more difficult.

So, how are we running single tasks in pull requests?

I'm keen on supporting the craft test use cases, but only while the use of Spread seems to help the case. If we get to a point where we're simply using Spread as a remote script runner, and having to corrupt fundamental ideas that turn Spread into a worthwhile framework, then we should consider not using Spread anymore for the purpose.

I'd be happy to have this as a seperate option completely, meaning that existing workflows and modes of operation are not affected, but given that this can be completely opt-in, and the code required is very small indeed in surface, I'm struggling to see a reason not to consider this and dramatically improve the experience for 100s of new developers who are going to be using craft test every day.

Are you talking about PR #138? That PR is completely broken, does not do any of the constraints that are being discussed here, and does not even do what this issue is asking for (it does not stream the output), so I hope we can at least agree that it should not be merged.

If you are talking about a different PR with different constraints, then I'm not talking about that hypothetical PR. :)

[jnsgruk]

Ha, no I'm not advocating for us merging #138.

To give an idea of a typical-ish setup, consider the following charm: https://github.com/jnsgruk/zinc-k8s-operator

• The spread.yaml has two backends, one called lxd-vm and another called github-ci
• The github-ci backend is certainly a bit of a workaround. It essentially tells spread to SSH into the Github Runner it's being invoked from. This allows us to take advantage of the free Github Runners, and parallelise test execution more easily
• In the workflow, the list of spread tasks matching the github-ci: filter are turned into a JSON list, which is then used to define a matrix of jobs - essentially creating 1 Github Runner per spread test
• This all results in a workflow such as this: https://github.com/jnsgruk/zinc-k8s-operator/actions/runs/13370036811

In these cases, spread is indeed running a single job because it's being forced to, mostly because that allows us to take advantage of the infra Github makes available. In these cases, I'd argue that it would be beneficial to be able to see the output of the tests - obviously this wouldn't be well suited to cases where multiple jobs are running, because interleaving the output from the jobs would be a nightmare!

It's worth mentioning that the task.yaml files for these tests are very simple - and one might make the argument that simply running make integration could be a better option.

Perhaps that is true, but the goal here was to ensure that once we're pushing charms in to the bug bad publishing machine, developers have a way of replicating the setup that'll be used there. Making use of the top-level prepare/restore makes for a very compelling experience locally, and on Github Actions.

Hopefully this makes sense - even if it does mean we need to reconsider how we go forward with craft test - but I think even if we do, there are some positives to be had from enabling log streaming from jobs - with some constraints (number of jobs == 1, probably).

[niemeyer]

essentially creating 1 Github Runner per spread test

Won't that scale quite poorly?

In either case, again, I still don't feel like the CI case should be driving this feature. CI is the golden reason why Spread was created, and Spread simply cannot work properly if we're streaming every task.

there are some positives to be had from enabling log streaming from jobs - with some constraints (number of jobs == 1, probably)

Yeah, that specific case seems doable. As a rule of thumb, we can support streaming if the output of streaming and not streaming would be exactly the same. For example, with -vv we already get the output, so if the specific conditions that Spread is being run would mean a serial output, it supposedly would make no difference if the output is being streamed instead of buffered, so that would be okay. I suspect it may not be as straightforward and clean to support this as #138 could have hinted unfortunately, because that one was still just buffering and then flushing, but happy to be wrong.

[jnsgruk]

For example, with -vv we already get the output, so if the specific conditions that Spread is being run would mean a serial output, it supposedly would make no difference if the output is being streamed instead of buffered, so that would be okay.

Yeh, that seems like a reasonable feature for us to aim off for. Thanks 👍