fix: minimize log data loss caused by LXC & PTY buffer #1270
No reviewers
limiting-factor
Labels
No labels
FreeBSD
Kind/Breaking
Kind/Bug
Kind/Chore
Kind/DependencyUpdate
Kind/Documentation
Kind/Enhancement
Kind/Feature
Kind/Security
Kind/Testing
Priority
Critical
Priority
High
Priority
Low
Priority
Medium
Reviewed
Confirmed
Reviewed
Duplicate
Reviewed
Invalid
Reviewed
Won't Fix
Status
Abandoned
Status
Blocked
Status
Need More Info
Windows
linux-powerpc64le
linux-riscv64
linux-s390x
run-end-to-end-tests
run-forgejo-tests
No milestone
No project
No assignees
4 participants
Notifications
Due date
No due date set.
Dependencies
No dependencies set.
Reference
forgejo/runner!1270
Loading…
Add table
Add a link
Reference in a new issue
No description provided.
Delete branch "mfenniak/forgejo-runner:host-executor-log-fix"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
Fixes #1258. Well, kinda.
First change: The existing code to close the pty used an odd "autostop" flag and a write of a EOT (
\x04) character. This write would occur immediately after the command executed, and didn't have any guarantee that data in the output buffer of the command or the pty was flushed --cmd.Run()doesn't provide this guarantee whenStdoutis an*os.File. This appears to be the primary cause of #1258. This code has been reworked stop copying from the pty when the pty is closed by the child process, rather than attempting to aggressively close it when the command finishes. This change improves log reliability for both LXC and host executor.After that first change, I would typically get the final lines of output from the reproducer in #1258 when run under LXC, and always run under the host executor. But when I increased the number of output records from 1200 -> 2400, I found that stats I was tracking on the amount of data being copied varied from run to run under LXC. That allowed me to discover that log data was missing in the middle of the output.
Second change: drain the pty buffer in a separate goroutine from that which writes to the runner's logs, with a
1 MB(now 100 MB) in-memory buffer between them. This works around a behaviour in lxc-attach which appears to me to be that if the kernel's pty buffer is full, data is dropped. Inline comments incopyPtyOutputprovide more context. With a 1 MB buffer, the reproducer works perfectly at 2400 log lines... but I do see data dropped intermittently if the reproducer is increased to 24000 log lines. This seems like a reasonable improvement for the moment -- in the future it might be worthwhile to bypasslxc-attachand use something lower level likensenterso that there's no intermediary deciding to drop buffers (just block the process's write, as would happen naturally if the buffer is full).9df02d47274f36e02a0cI ran into this again today and that fix is going to help ❤️
From what I read it looks like this bug also happens for host, not just LXC. If that is correct, would it simplify testing?
@mfenniak wrote in #1270 (comment):
I also noticed that.
4f36e02a0c8db89b5cb98db89b5cb9e3efbb058de3efbb058d26e65f8a0d@limiting-factor wrote in #1270 (comment):
I've observed log ends being trimmed on host, but roughly 2/10 occurrences where LXC is 9/10, and only relevant for the "first change" described in the PR. The second one seems to be LXC only.
I've got a test ready now that uses LXC. 👍 And it reproduced the problem well enough that I had to increase the data buffer size on my own machine.
WIP: fix: minimize log data loss caused by LXC & PTY bufferto fix: minimize log data loss caused by LXC & PTY bufferIronically the logs for the newly added test are being trimmed so that I don't see
TestRunnerLXCoutput in https://code.forgejo.org/forgejo/runner/actions/runs/14518/jobs/4/attempt/1 to confirm the test passed. 🤣 But the "AAAA..." output is there and the test exec succeeded.@ -274,3 +259,1 @@if _, err := io.Copy(writer, ppty); err != nil {return}pipeReader, pipeWriter := nio.Pipe(buffer.New(2 * 1024 * 1024))Ideally the buffer could be grown dynamically and have a very large upper bound (100MB) which, if used, is unlikely to be a problem for a host running a LXC workload as it will typically have enough RAM to allow for that. If that much output is buffered and sent to Forgejo, it will probably cause other problems (storage and display on the web UI) anyway.
https://github.com/acomagu/bufpipe?tab=readme-ov-file#how-does-it-differ-from-iopipe
The underlying implementation of
buffer.Newis dynamically allocated, so the easy path to this would be just replacing2with100. I'd be OK with changing it to a 100 MB size; I'll bump it.I think that practically speaking this will work fine with Forgejo as long as it's a single burst of data. For example, at the end of the end-to-end tests when a bunch of logs are
cat'd if an error occurred, that could be multi MB and should work fine.If it was constant output, I agree it will cause other problems. I'm not sure the right place to intentionally break or limit that output to prevent abuse... but I think making it work for real-world use-cases is clearly more important.
FYI,
niopipe is being used here (https://github.com/djherbis/nio) and a library of buffer options (https://github.com/djherbis/buffer) is provided by the same author. But I don't think any of the other buffer options are a better choice -- spilling to disk, for example, seems appealing but would likely be slower than the in-memory operation that we're targeting and doesn't seem likely to improve the problem.cascading-pr updated at actions/setup-forgejo#813
@mfenniak wrote in #1270 (comment):
Excellent find, it must not have been easy, kudos.
26e65f8a0d390924c1eecascading-pr updated at actions/setup-forgejo#813
When running locally,
Large Fast Logsconstantly fails for me.The actual value changes. I've seen values as low as 1500-ish.
It's on Debian GNU/Linux 13.
sigh, that's unfortunate. I also have a test system with Debian 13 and if I keep
go clean -testcache && go test -run TestRunnerLXC ./internal/app/runthen I've run it about a dozen times without an error.Is it always missing items at the end like that example, or is it sometimes ending with
2400as the last item in the array? This would indicate whether it's a problem with clean shutdown of the test's stdout, or, pty buffer overflow dropping chunks in the middle.Could you try changing
trueto!e.GetLXC()on lineif true /* allocate Terminal */ {and see if the test failures are gone? This will disable allocating a pty for LXC containers... it was an early approach I considered for this, and I'd like confirmation on your configuration that it would address the issue.
I think our options are limited to disabling the pty when using LXC, or possibly going lower-level and avoiding
lxc-attachso that we avoid its behaviour of dropping short write chunks.I've been able to reproduce this on my test system intermittently with
go test -count 100 -failfast -run TestRunnerLXC/Lo ./internal/app/run.I have three approaches in mind to fix this, and haven't settled on any yet.
Replace
lxc-attach, which has this "perform short writes and ignore it" behaviour. This branch drops down to usingnsenter. https://code.forgejo.org/forgejo/runner/compare/main...mfenniak/forgejo-runner:experiment-nsenter I've done quite a bit of comparative testing of everything I can think of for the process environment, and this seems to work well, but I think there's a pty problem -- the pty exists on the host and not the child, so it doesn't appear as a valid pty... but commands likels --color=autostill work correctly, so I'm not sure if it's a practical problem. This has passed my 100 test count twice without an error, so it seems like it proveslxc-attachis the core of the problem.lxc-attachhas a--pty-logoption which, in addition to passing data back to stdout, will log the terminal output to a file. This opens two other options:The problem with the
--pty-logoption is primarily that all the code around writing to the log file has the same "short write" issue that the terminal does -- if it's logging to a FIFO and the FIFO buffer is full, then a partial chunk write will occur and lxc-attach just logs a warning and moves on. If it's logging to a file then it's practically impossible for this to happen, but it's still not a reliable implementation, and then there has to be a capability to tail the terminal file... plus these options require weird permission management sincelxc-attachis run w/sudobut the file would be created and read by the runner.I've just gotten the first ugly draft of the
--pty-logoption working on my tests, and have only run it through a handful of test runs with the FIFO config -- but no failures yet.I'm leaning towards the nsenter option but would need to do more testing.
@mfenniak wrote in #1270 (comment):
It happens much more often when running
make integration-testthan when running that test alone.Sometimes, it ends with
2400.Looks like the test failures are gone. And if they are not, at least they have become very rare.
I don't know anything about pty,
lxc-attach, andnsenter. So I cannot offer any advice or opinion. I testedexperiment-nsenterand it does not exhibit any of symptoms that the previous solution did.Another thing I noticed yesterday is that when running in host mode, tons of logs end up in "Complete job". However, I don't know whether it's related to this change. In the last weeks, I've rarely used host mode.
#1287 is a second-pass at fixing this, with higher confidence on the log integrity. I've run through the test with
-count 100and had no errors.