`--progress=plain` too verbose

[grand prism]

hmm yeah plain is definitely being more verbose than it should be, seems like there's a bug - those consuming spans for example should definitely not be showing up

as an aside, have you tried --progress=report? it'll block and then just do one final print, which is much more readable, the main downside being that it doesn't stream, so you won't be able to watch the CI job live

[tepid rampart]

I haven't tried --progress=report yet in CI, let me try that. Not seeing the live progress may or may not be desirable. I'll report back on that experience. I'm afraid, it'll look bad if dagger seems to be stuck for long periods of time.

[tepid rampart]

I tried searching to codebase and docs but couldn't find it. Is there a way to globally set --progress=report via a env var?

[tepid rampart]

I tested --progress=report it's better than plain however I still see duplicate outputs especially for things like test/lint/sonar reports. I tried removing my explicit stdouts but it didn't seem to help.

It's hard to balance what I see in the TUI and non-tty. When I remove the explicit prints, I have to use -v to see stuff in the TUI.

[grand prism]

Would you be able to throw together a repro for this that you can share? I'd like to take a swing at it but I need to be able to interact with the specific scenario to really understand it and come up with a solution

[tepid rampart]

I should be able to, let me work on that.

[tepid rampart]

Ok I was able to reproduce but it's a tough one to share. Especially since I'm at work. I'll try my best. I am not showing all the files but there are 2 modules involved.

root
  module1
    dagger.json
    main.go
  module2
    main.go
  dagger.json

module 1 has a func "Test" that returns (string, error) via Stdout

module 2 uses module 1.
module 2 has a func "Mymodtest" that calls dag.Test (module 1) and returns the (string, error)

in the command line I run from root directory

dagger call mymodtest --progress=report

Sorry for the lame repro but this is the simplest one I could produce. I can't share a gist or a git repo as I can't push code anywhere from work 😦

I tried to mimic my setup. module1 would be in a separate "daggerverse" repo and module2 is an app module that uses module1. This is a common pattern I have. My daggerverse modules produce various artifacts like File, Directory, sometimes just Stdout or Stderr

When running the above, I see my test output 4 times.

[tepid rampart]

@grand prism are you good with the above example? If not I can try to re-create from my home PC tonight.

[grand prism]

sorry, I'm juggling a lot of priorities at the moment and that repro is still a somewhat high barrier to get going on this, so I'm focusing on other things in the meantime. I can try to get to it eventually based on what you shared (thanks!) but a straight up code repro would make it much easier for me to context-switch over and give it a try

[tepid rampart]

Understood, I'll push something to my personal repo and share

[grand prism]

I appreciate it!

[tepid rampart]

Here's a one-liner repro 🙂 dagger call -m github.com/nipuna-perera/examples mod-print --progress=report.. Doesn't get easier than this haha!

[grand prism]

Thanks so much! 🙇

lol, yep

▼ .modPrint: String! 1.5s
┃ Hello, this is a message from Module1!
├─● module1: Module1! 0.0s
╰─▼ .modulePrint: String! 1.1s
  ┃ Hello, this is a message from Module1!
  ├─● container: Container! 0.0s
  ├─$ .from(address: "alpine:latest"): Container! 0.3s CACHED
  ├─▼ .withExec(args: ["echo", "Hello, this is a message from Module1!"]): Container! 0.4s
  │ ┃ Hello, this is a message from Module1!
  ╰─▼ .stdout: String! 0.4s
    ┃ Hello, this is a message from Module1!

[tepid rampart]

Check my code too, IDK if I'm doing something I'm not supposed to? End goal is to print a report basically and I'd like the user to only see that

[grand prism]

definitely seems out of sync with the fancy TUI for some reason:

▶ connect 0.3s
▶ load module: github.com/nipuna-perera/examples 1.4s
● parsing command line arguments 0.0s

● examples: Examples! 0.0s
▶ .modPrint: String! 1.4s

Hello, this is a message from Module1!

[tepid rampart]

My real usecase is printing test results (pytest, go etc.). I want users to see the results in the TUI too

I see the same behavior in the TUI when I do -v (prints 4 times)

[grand prism]

yeah looks like it's because --progress=report raises the minimum verbosity level - it probably shouldn't do that

time to git blame myself

side question, trying to find a happy medium between plain (streaming, but kind of inherently verbose even aside from bugs around revealing too many spans) and report ("just enough" verbosity, but no streaming)

would it help any if we just had it print . for every function that it sees complete, and then the final report? - sort of like traditional test output (e.g. rspec), it's just a ton of dots and X symbols like .......X...... followed by the failure summary

--progress=dots?

https://github.com/dagger/dagger/pull/10615 - here's that, at least

[tepid rampart]

Interesting.. I would have to see an example to judge it. In general, in CI we are used to seeing at least a partial streaming output. So with report, if the dagger stage takes a long time it will feel like things are stuck. Jenkins streams output every 5-10 seconds. Is something like that is possible with dagger?

[grand prism]

here's a prototype of the dots idea: https://asciinema.org/a/g4UsIKnv2FyHOyfnGhR5CVxQY

hmm I think Jenkins might support line-rewriting too which could open up some possibilities

I also prototyped a Heroku style log printer recently, could give that a go

[tepid rampart]

Do you have a Jenkins instance to test? I think this dots will actually look like a triangle because it will progressively print the current dots state. I've seen it happen when I don't enable batch mode with maven. Or when downloading something with curl.

[grand prism]

it shouldn't - it literally just prints . one after another, what you're describing sounds like a misbehaving line-rewriting thing (like a progress bar)

[grand prism]

sounds like that eliminates this option haha

[tepid rampart]

I'd be happy to test it and report back. My end goal is only showing the user the final output. With the ability to make it verbose if necessary. I honestly like how the --progress=plain prints stuff as it goes. If only it was much less verbose.

Some builds/tests stages like maven could take upto 15m or more. So if the output is frozen for that long its awkward.

[grand prism]

gotcha - like they print logs for a long time, so it'd be a long pause before a dot gets printed? (even with the dots mode)

[tepid rampart]

I'm thinking about the --progress=report mode. If the dots gets printed the user will at least know something is going on. But it's still not ideal because they can't see what's actually going on. In regular console output in jenkins, I can see dependencies being downloaded for example.

[grand prism]

so, the hard part with showing logs streaming is doing it without having the repeated logs you mentioned. here's dots + prefixed log printing:

❯ dagger-dev call -m github.com/nipuna-perera/examples mod-print --progress=dots
............................................................[Container.withExec] Hello, this is a message from Module1!
[Container.withExec]
.....[Container.stdout] Hello, this is a message from Module1!
[Container.stdout]
[Module1.modulePrint] Hello, this is a message from Module1!
[Module1.modulePrint]
.........[mod-print --progress=dots] Hello, this is a message from Module1!
[mod-print --progress=dots]
[mod-print --progress=dots]
[mod-print --progress=dots]
[Examples.modPrint] Hello, this is a message from Module1!
[Examples.modPrint]


▶ connect 0.1s
▶ load module: github.com/nipuna-perera/examples 4.7s
● parsing command line arguments 0.0s

● examples: Examples! 0.0s
▶ .modPrint: String! 1.2s

Hello, this is a message from Module1!


Full trace at https://dagger.cloud/dagger/traces/bc12289658f4f305dad31969e9b90e23

maybe dots could just print a dot when logs are received too, so it doesn't look stuck as long as something is happening?

or maybe I can have it somehow skip API call response logs, since that accounts for Container.stdout and Examples.modPrint above

[grand prism]

@tepid rampart hmm might be onto something here: https://asciinema.org/a/9wVs63Gy0VUA3um0sdRto3gDO

(that's from a cold cache so there's a long lead time)

notes:

• it's called --progress=dots but I got rid of the dots to test the log streaming independently. maybe they're still useful though to show progress in between logs
• doesn't show logs from API calls (Container.stdout, Examples.modPrint)
• doesn't show logs from the root span, since that gets printed at the very end
• prints a header whenever it's switching contexts, instead of prefixing every line (easier to copy/paste, less noisy)

[tepid rampart]

That looks really clean! I love it! Can we make it the default? :).. My only nit would be the initializing period it looks like it's frozen. Would it be possible to print something like initializing or similar? This is getting very close to perfect. Nice work!

I mentioned this earlier too. Would it be possible to make the --progress flag configurable via ENV var? That would make it easy to use with CI.

[grand prism]

yeah that's easy enough 👍 it'll be DAGGER_PROGRESS

@tepid rampart here's the latest iteration - brought the dots back to fix the 'it looks like it's stuck' problem, now it'll go back and forth between dots and logs: https://asciinema.org/a/d2kFu3nMb3Gh8LqF1k0B5KNy1

here's a PR if you wanna give it a go: https://github.com/dagger/dagger/pull/10617

[tepid rampart]

I think it looks great! I'd love to test and I can certainly test on my personal machine. I'd need both the CLI and engine for this right? What's the easiest way to spin it up myself for your PR?

Ah! I think I need to read up on this - https://github.com/dagger/dagger/blob/main/.dagger/README.md 🙂

[tepid rampart]

Looks pretty neat! To the point I'm thinking this is even usable locally (instead of the TUI). It's refreshing to see only the output I'm expecting from each of my WithExecs.

The only nit I have is would it be possible to make the dot lines uniform in length? Since they aren't really conveying a datapoint, it would be nice if they all were just a single, same length line. Like a progress bar going to 100%. As shown in the screenshot, the different lengths don't seem tidy to me. Multi line dots vs a single line doesn't convey much to me in the sense of what happened. In the current form, a 10 dot line could take longer than a 100s of dot line. So it's not any speed (ETA) indication either.

[grand prism]

I don't think that's possible; it's not predictable what would constitute 100%. The dots are just to give a rough idea of how many things (spans) have completed so far, and as a sign of activity so you know it isn't hanging. If you've ever used RSpec or other test runners that print a . or a X for each test that completes, it should be pretty familiar

I'm looking into tweaks to make it look a little less janky though - like those overhang indicators (the little arrows at the end) are probably doing more harm than good

Also trying a version that groups the dots into their top-level span, but not sure I like it; feel like the noise takes too much attention from the logs

The call headers are especially verbose there

[tepid rampart]

Yeah I agree.

Would it be possible to line wrap the dots where the text typically wraps? Then it won't look like overflow.

[grand prism]

hmm better to leave the wrapping to the terminal, I think - if we wrap it ourselves it'll look weird when you resize (e.g. for folks that use a bunch of split panes). As long as we simply print dots on a line the terminal will wrap it for you. The current form is consistent with RSpec etc so I'd expect Jenkins and other CI runners to handle it properly, too

[tepid rampart]

ok cool! I'm good with that. I don't have a way to test in Jenkins yet though. May have to wait till it's merged

I agree that it's better to remove the overhang indicators.

[grand prism]

yeah those are normally meant to indicate that a span's logs were context-switched away from before a linebreak was seen, which might still be valuable - but it's definitely weird when context-switching from the dots

[grand prism]

alright, here's that: https://asciinema.org/a/723921

[tepid rampart]

This is amazing! I lowkey like this better than the TUI tbh.. TUI is great for troubleshooting but for everyday runs, this works well!

[grand prism]

merged!

[tepid rampart]

Did you forget to press merge? 🙂 It's ready to merge though. I'll take it

[grand prism]

oh oops lol. maybe it didn't take (I did it on mobile). but now I can add a changelog 😛

[grand prism]

ok NOW it's merged

[grand prism]

@tepid rampart just following up - this shipped in v0.18.12

i also fixed plain verbosity so you should see some improvements there if you stick with it, there was indeed a bug. it's still more verbose than dots of course but should at least be consistent with the pretty frontend

[tepid rampart]

hey! Yes, it looks good! Sorry, I meant to follow up but got distracted. I still see a few places (with dots) where it duplicates output. But it could be because of me printing stuff out manually. I haven't had a ton of time to deep dive on those. But in general it definitely looks better.

I am assuming your tracing API PR will eliminate the need to print out anything because then I'd be writing spans.

[grand prism]

hmm, not quite, since with dots those spans would just become . 😛

[tepid rampart]

oh dotdotdot

What would be the best way to display spans in non-tty then? --progress=plain? That would bring back all the output duplicates wouldn't it?

[grand prism]

hmm, I guess you would still see them in the report that gets printed at the end, especially if you use Status.withReveal to make sure you see the spans you care about.

It really depends on what you're trying to see, and when. If you want to see spans while streaming, you'll have to use plain, but yes that will be more verbose. If you just want to see things printed while streaming, you can continue writing to logs and use dots, which silences some of the verbose output (API call responses). I can apply that same fix to plain but it might still be too verbose.