logstream truncates output from WITH DOCKER
#4063
Comments
rrjjvv
changed the title
WITH DOCKER output truncates last line of outputWITH DOCKER + logstream output truncates last line of output
rrjjvv
changed the title
WITH DOCKER + logstream output truncates last line of outputWITH DOCKER
|
I experienced the same bug today while working on #4064 (I actually ended up adding an extra |
|
the output is still technically there: we can see that the "ello\n" shows up: followed by a bunch of spaces: followed by a "output....": but then we get to: which at this point I suspect is causing the cursor to reset to the beginning of the line which causes the text to disappear. Maybe there's a way we can prevent docker from outputting these characters? |
|
Yeah, I had uncovered that same control sequence in my report (I know my tendency to be thorough can result in stuff getting overlooked and have the opposite effect...). However, since disabling logbus results in the correct output, my assumption is that it's not docker's console magic emitting it. (Or maybe it is, but legacy and logbus handle it differently.) That control character is actually present in the earthly codebase: earthly/logbus/formatter/formatter.go Line 45 in 23000c0 That was actually the first thing I found and started seeing if I could backtrack, but then got lost in the weeds with the logstream stuff. |
|
I decided to take up the quest again for a little bit. It turns out there's one other place in the codebase where that sequence is defined. And out of the three places it's used, one of them is the key to this issue. If I comment out Lines 177 to 180 in 23000c0 |
|
Okay, I've figured this out... it took a long time to realize it wasn't a logic/algorithm error, and even more frustrating since my previous two comments had 90% of the answer, but I didn't recognize it as such at the time. The root cause is that in a standard build (post- Current (with logbus): I added a line indicating when the code wants to delete the line, but doesn't actually do so. From the earlier output, it's clear that the purpose is to delete a "0% blah" if/when a matching "100% blah" comes up. The problem is that 'outmon' is not aware something else was written between the 0% and 100% progress that it is tracking. With logstream disabled: Though there are two monitor 'operations', involved, it is the same instance (sharing the same state). There's basically three different places where monitors are used; the main/parent one is the only one where the 'solvermon' flavor is used Lines 75 to 85 in 23000c0 earthly/builder/image_solver.go Line 342 in 23000c0 earthly/builder/image_solver.go Line 106 in 23000c0 That may have been simple oversight, but I'm guessing that the solvermon one needs to be refactored to be a 'child' monitor (i.e., the |
What went wrong?
Some time ago I noticed that the last line of output from a
WITH DOCKERblock was missing. I'm not sure if this was 100% of the time since usually I only care about the output on a failure. In some projects where this was bothersome I started adding a dummyecho "hi"to theRUNcommand, which would then allow me to see the last line of output (as the dummy echo would then get truncated).I basically did a 'bisect' with all the earthly versions I have locally; the issue was reproduced 100% of the time with every version I tried between
0.7.19and0.8.9and was absent in every version I tried between0.7.0and0.7.17. Anecdotally, the regression occurs between0.7.17and0.7.19.A workaround (discovered shortly after my initial post) is to disable logstream, which may or may not be acceptable to typical Earthly Cloud users:
--logstream=false --logstream-upload=false(both are necessary).This
Earthfilewas atVERSION 0.8for all the 0.8.x client versions I tried, then changed toVERSION 0.7to test against the 0.7.x client versions:In all cases, the
+test-loadand+test-pullhad the same behavior. The+test-plaindoes not have this behavior, which implies the issue isn't withWITH DOCKERper-se, but with output related to image transfers.Here, in the older version, you see "pull" in the output:
In the next version, that output is missing:
If you watch the build carefully for the whole duration, you'll see that the output actually does appear in the terminal for a short time, then disappears. After noticing that, it was clear the issue was the fancy terminal magic. Relevant snippet of the 'raw' output (relatively speaking) from the
0.7.17:My understanding is that the
ESC [ Ksequence means "delete here to the end of the line", which is an effective no-op since it's already at the end of the line.In
0.7.19:My understanding is that
ESC [ Ameans "go up one line", which would put the cursor to the last line of user-generated and 'overwriting' it. That's somewhat supported when looking at the target/stage for the "transferring" line from the working version:compared to the broken version:
What should have happened?
The expectation is that stuff that the user outputs is displayed. Sometimes one lines doesn't matter, but when one takes care to generate 'clean' output, it matters. In my real use-case, I was confused because I was certain I had written X tests, but was only seeing X-1. In order to see every test:
I had to insert that dummy echo:
What earthly version?
As mentioned above, I can consistently reproduce with many versions starting at
0.7.19(including the latest0.8.9). Versions I explicitly tested:0.8.9(broken)0.8.2(broken)0.7.22(broken)0.7.20(broken)0.7.19(broken)0.7.17(ok)0.7.15(ok)0.7.14(ok)0.7.9(ok)0.7.0(ok)Buildkit Logs
No response
Other Helpful Information
The changelog for
0.7.19doesn't give any obvious clues, though it does mention logging changes. The diff shows a substantial number of changes to logging (more than I'd guess from the changelog), but nothing jumped out immediately.This could be red herring, but I saw code related to "de-duplicating" log output (like in the old days, when you'd see "ongoing"
messagesrepeated. In0.7.17version, when running in verbose mode, you seewhich then disappears, and with verbose mode in
0.7.19you seewhich then collapses to just one.
My hunch is that the issue isn't related to changes to logstream/logbus per-se, but maybe it's an existing issue that appeared since it's the default (though I did try disabling it to no avail).
EDIT
I mentioned previously that I had tried disabling logstream but that it had no effect. I had assumed that
--logstream=falsewas a global kill-switch, but it must be more nuanced. This release had a second related flag that had a new default, and disabling both has the desired effect.And my real build:
In the current earthly version, setting both
--logstream=falseand--logstream-upload=falseresult in my dummy line being shown (thus no longer needed).The text was updated successfully, but these errors were encountered: