bug: runner gets into a defunct state if reporting job result to the Forgejo instance times out #1166
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
run-multi-platform-tests
No milestone
No assignees
3 participants
Notifications
Due date
No due date set.
Dependencies
No dependencies set
Reference
forgejo/runner#1166
Loading…
Reference in a new issue
No description provided.
Delete branch "%!s()"
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?
Can you reproduce the bug on the Forgejo test instance?
No
Description
On the same slow machine that #1091 is happening on, we see cases where reporting the job result fails like this:
There are no further logs past this point; after this, the runner daemon keeps going but appears as offline on Forgejo and no longer takes new jobs. This then requires manual intervention to fix.
I'd say there are 2 things that need to be done here:
Forgejo Version
Codeberg current
Runner Version
v11.3.1
How are you running Forgejo?
Codeberg
How are you running the Runner?
make build+ systemdLogs
No response
Workflow file
No response
The "ReportLog error: ..." message comes from
RunDaemon, which is the background process that spools logs to Forgejo. A warning in this process is just a warning printed to the logs; it continues to send logs atreportInterval(1s) in spite of the warning:err := r.ReportLog(false)if err != nil {log.Warnf("ReportLog error: %v", err)}When a job completes, the final logs & state are transmitted to Forgejo in a retry loop; theoretically this should attempt 10 retries with 100ms delays between. Although this isn't the relevant code path observed in the logs, just noting that it does exist when finalizing a job:
return retry.Do(func() error {if err := r.ReportLog(true); err != nil {return err}return r.ReportState()}, retry.Context(r.ctx))Another thought reviewing this code is that the error condition might leave an internal lock being held, preventing future progress. I can't see any obvious case of that that -- when
ReportLogis executed and returns an error at line 358 (where it could get "connection timed out"), it looks like all the internal locks would be released and so nothing should prevent it from continuing to operate.func (r *Reporter) ReportLog(noMore bool) error {r.clientM.Lock()defer r.clientM.Unlock()r.stateMu.RLock()rows := r.logRowsr.stateMu.RUnlock()if needMore := r.masker.replace(rows, noMore); needMore {return NewErrRetry(errRetryNeedMoreRows)}resp, err := r.client.UpdateLog(r.ctx, connect.NewRequest(&runnerv1.UpdateLogRequest{TaskId: r.state.Id,Index: int64(r.logOffset),Rows: rows,NoMore: noMore,}))if err != nil {return err}ack := int(resp.Msg.GetAckIndex())if ack < r.logOffset {return fmt.Errorf("submitted logs are lost %d < %d", ack, r.logOffset)}r.stateMu.Lock()r.logRows = r.logRows[ack-r.logOffset:]r.logOffset = ackr.stateMu.Unlock()if noMore && len(r.logRows) > 0 {return NewErrRetry(errRetrySendAll, len(r.logRows))}return nil}I don't see a clear problem with any of this, but here's some plausible things I'll check into.
Closeretry may not really be the documented 10 retry attempts -- it could fall into an infinite retry loop and not reporting/logging the errorI'll post an update when I can reproduce some similar errors and see what really happens.
I've tested a couple scenarios and have found that:
The most obvious fix here is to ensure that retry attempt errors are logged for clarity. @alexrp: 10 retries over 50 seconds (+ time to execute) is the intended value, do you think that is a reasonable configuration? It could be tweaked to more retries or more delays between them.
The HTTP client used for connection to Forgejo relies on default values for timeouts. The scenario I can imagine is that this box had some network issue, and that the client was either:
TLSHandshakeTimeoutwhich has a default of "no timeout".So I think doing a pass on the timeouts and ensuring there are none that are undefined is also warranted. It's my best guess as to why the runner would have been frozen, assuming it was like that for a long time when you reached it.
TODO:
For what it's worth, I don't think we're looking at some intermittent network issue; almost every job that gets scheduled on this machine over the last few days runs into network timeout problems, with only a couple exceptions.
This machine is just very slow. Even something as simple as printing systemd logs takes a long time -- multiple minutes -- compared to the other machines with equivalent hardware. I think we just lost the silicon lottery with this particular machine.
@mfenniak wrote in #1166 (comment):
I imagine this is the problem? I think the timeout itself just needs to be longer. It would be nice if all network-related timeouts were configurable in
config.yamlso we could mitigate this machine's slowness that way.@alexrp wrote in #1166 (comment):
The default HTTP client being used has no timeout, making some operations infinite. Typically this has some other bound, like the max job length -- but when performing the final log reporting, it escapes that bound so that even a job that hits the job timeout can report its cancellation. This could explain the system becoming frozen; if it has capacity 1 and hits this infinite timeout, it could become stuck. It also won't effectively retry if it's stuck in an operation with no timeout.
(It isn't clear to me what specific operation/failure could really be infinite in this configuration... most TCP interactions have some kind of exit mode assuming a well behaved server counterpart.)
#1171 proposes to fix this with making HTTP interactions to Forgejo have a timeout. A one minute timeout is the default, and it can be overridden by the environment variable
FORGEJO_CLIENT_TIMEOUT(in seconds).Ok, I see. It seems like the only practical path forward here is to get #1170 and #1171 actually deployed on the machine, see what happens, and proceed from there.
@mfenniak i think the retry should use an increasing delay so the retry can better handle longer remote failures
The retry should never be infinity by default without setting
Attempts(0)🤔Interestingly, the machine in question just reconnected to Codeberg after going offline (due to this issue) some hours earlier, so it seems it doesn't truly get stuck.
It's currently running a job so I can't really do much on it, but once it's done, I'll see if there's anything interesting in the service log.
@viceice wrote in #1166 (comment):
It does -- the default is 100ms with doubling between retries. I think maybe more time between retries makes sense in this very slow machine... but it's hard to say? So I've put in some new config options to allow some flexibility: #1173
Forgejo Runner v12.0.0 has been released with these hopefully relevant fixes:
I'm going to tentatively close this issue, but if there's ongoing problems and more we can do here please feel free to reopen it with additional information.
Okay, after upgrading to v12.0.0 (and not changing anything in
config.yaml), we got this:OK, great information... so the 60s HTTP timeout is active and it's being hit, and the Go process thinks that it's waiting for a server response. The retries are occurring with slightly increasing delays as expected.
My first thought here is that if, at the very end of the CI process, the last step dumps a large volume of log output, that could cause the "uploading final logs" to be a large upload and be more likely to hit a timeout. But when I look at your riscv64-linux-release builds, I don't see any sign of sudden large log dumps at the end of the jobs. And since the log you posted has a "🏁 Job succeeded", I can't imagine there were any large outputs, as I'm looking at other successful jobs that don't have any additional large output. So, this line of thinking doesn't seem helpful.
It's unexpected to me that the process thinks it is waiting for Codeberg to respond --
exceeded while awaiting headersseems to reflect that the Go HTTP client wrote its request to the network buffers and it is waiting on a read from the remote. 🤔 It's possible that the request is actually still outgoing in kernel network buffers or something like that, but a minute for a small post request... feels like we're missing a real root cause here.I'm thinking two reconfiguration steps that might help:
FORGEJO_CLIENT_TIMEOUTis the timeout being hit here, and it is a default 60 seconds. Increase it... maybe you can find some evidence from successful runs in the logs about how long it could take?runner.report_retry.initial_delayup from100ms, perhaps to even1m.I was thinking something similar. I'll try a silly value like 10 minutes for starters; if that works, we're definitely onto something. Failing that, I'll give
FORGEJO_CLIENT_TIMEOUTa try.Note that retry time will double on each retry, so you might want to set the max retry time to the same value, or drop the number of retry times, or both. 👍
No dice; still just times out. But I notice that when this happens,
sshandscpalso become super flaky even though nothing is going on on the machine almost an hour after the job finished - and more interestingly,dmesgsays the link went down momentarily a couple of times.I think this is starting to point towards faulty networking equipment. For now, I've swapped the cable to the second Ethernet port to see if that makes any difference; next step will be replacing the cable. I'll report back on that, though at this point I'm reasonably confident it'll turn out that there's no runner issue here.
After changing Ethernet port, the runner went from
to
with the failure there being a legitimate failure, and no more general network slowness. So I think we have our answer.
Excellent, good to hear! 👍