fix: bound blocking calls and stop failing silently (#1174)

Jobs occasionally go silent ([example](https://gitea.com/gitea/runner/actions/runs/805045/jobs/1055123)) mid-run and Gitea reaped them after `ZOMBIE_TASK_TIMEOUT`, with no error in the log. This contains a number of related fixes, all with full test coverage:

1. Bound every RPC to Gitea with a timeout, a stalled report otherwise parked logs and heartbeats for the whole job.
2. Cap `runner.fetch_timeout` at that ceiling.
3. Let only the daemon loop close its own channel, the race panicked the process.
4. Stop the job on any terminal server result, not just `RESULT_CANCELLED`.
5. Report that result instead of relabelling it as cancelled.
6. Log reporting failures once at each end of an outage instead of discarding them.
7. Clamp the acknowledged log index, a too-large ack panicked on a slice bound.
8. Stop reading server health from a `FetchTask` deadline, it marked the runner healthy and reset the error backoff on a timeout.
9. Return an error from the Docker version probe instead of a `logrus` panic.
10. Pass the context to go-git's fetch and pull.
11. Fail the clone when a refresh dies on a cancelled context.
12. Set `terminationGracePeriodSeconds` in the Kubernetes examples.

Also contains a deprecation fix for goreleaser.

Reviewed-on: https://gitea.com/gitea/runner/pulls/1174
Reviewed-by: bircni <bircni@icloud.com>
Co-authored-by: silverwind <me@silverwind.io>
This commit is contained in:
silverwind
2026-08-19 11:13:21 +00:00
committed by silverwind
parent 3f70822458
commit bc8161c673
21 changed files with 422 additions and 63 deletions
+7 -5
View File
@@ -17,7 +17,7 @@ import (
"gitea.dev/actionslib/runner/v1/runnerv1connect"
)
func getHTTPClient(endpoint string, insecure bool) *http.Client {
func getHTTPClient(endpoint string, insecure bool, timeout time.Duration) *http.Client {
transport := &http.Transport{
Proxy: http.ProxyFromEnvironment,
MaxIdleConns: 10,
@@ -29,11 +29,13 @@ func getHTTPClient(endpoint string, insecure bool) *http.Client {
InsecureSkipVerify: true,
}
}
return &http.Client{Transport: transport}
return &http.Client{Transport: transport, Timeout: timeout}
}
// New returns a new runner client.
func New(endpoint string, insecure bool, uuid, token string, opts ...connect.ClientOption) *HTTPClient {
// New returns a new runner client. timeout bounds every RPC: without it a
// stalled connection parks the reporter for the whole job context, so logs and
// heartbeats stop together and the task is reaped as a zombie.
func New(endpoint string, insecure bool, uuid, token string, timeout time.Duration, opts ...connect.ClientOption) *HTTPClient {
baseURL := strings.TrimRight(endpoint, "/") + "/api/actions"
opts = append(opts, connect.WithInterceptors(connect.UnaryInterceptorFunc(func(next connect.UnaryFunc) connect.UnaryFunc {
@@ -49,7 +51,7 @@ func New(endpoint string, insecure bool, uuid, token string, opts ...connect.Cli
}
})))
httpClient := getHTTPClient(endpoint, insecure)
httpClient := getHTTPClient(endpoint, insecure, timeout)
return &HTTPClient{
PingServiceClient: pingv1connect.NewPingServiceClient(
httpClient,
+7 -5
View File
@@ -8,6 +8,7 @@ import (
"net/http/httptest"
"strings"
"testing"
"time"
"connectrpc.com/connect"
pingv1 "gitea.dev/actionslib/ping/v1"
@@ -17,7 +18,8 @@ import (
func TestGetHTTPClientUsesProxyFromEnvironment(t *testing.T) {
t.Setenv("HTTP_PROXY", "http://proxy.example.com:8080")
client := getHTTPClient("http://gitea.example.com", false)
client := getHTTPClient("http://gitea.example.com", false, time.Minute)
require.Equal(t, time.Minute, client.Timeout)
transport, ok := client.Transport.(*http.Transport)
require.True(t, ok)
@@ -32,7 +34,7 @@ func TestGetHTTPClientUsesProxyFromEnvironment(t *testing.T) {
func TestGetHTTPClientInsecureTLS(t *testing.T) {
// insecure only takes effect for https endpoints
httpsInsecure := getHTTPClient("https://gitea.example.com", true)
httpsInsecure := getHTTPClient("https://gitea.example.com", true, time.Minute)
transport, ok := httpsInsecure.Transport.(*http.Transport)
require.True(t, ok)
require.NotNil(t, transport.TLSClientConfig)
@@ -47,7 +49,7 @@ func TestGetHTTPClientInsecureTLS(t *testing.T) {
{"http insecure ignored", "http://gitea.example.com", true},
} {
t.Run(tc.name, func(t *testing.T) {
c := getHTTPClient(tc.endpoint, tc.insecure)
c := getHTTPClient(tc.endpoint, tc.insecure, time.Minute)
tr, ok := c.Transport.(*http.Transport)
require.True(t, ok)
require.Nil(t, tr.TLSClientConfig)
@@ -66,7 +68,7 @@ func TestNewSetsBaseURLAndHeaders(t *testing.T) {
defer server.Close()
// trailing slash must be trimmed before "/api/actions" is appended
c := New(server.URL+"/", false, "the-uuid", "the-token")
c := New(server.URL+"/", false, "the-uuid", "the-token", time.Minute)
// Address returns the endpoint as supplied (untrimmed)
require.Equal(t, server.URL+"/", c.Address())
require.False(t, c.Insecure())
@@ -87,7 +89,7 @@ func TestNewOmitsEmptyHeaders(t *testing.T) {
}))
defer server.Close()
c := New(server.URL, false, "", "")
c := New(server.URL, false, "", "", time.Minute)
_, _ = c.Ping(t.Context(), connect.NewRequest(&pingv1.PingRequest{Data: "hi"}))
require.Empty(t, gotHeaders.Get(UUIDHeader))
+1
View File
@@ -34,6 +34,7 @@ runner:
# Whether skip verifying the TLS certificate of the Gitea instance.
#insecure: false
# The timeout for fetching the job from the Gitea instance.
# Values above the 60s RPC timeout are capped to it.
#fetch_timeout: 5s
# The interval for fetching the job from the Gitea instance.
#fetch_interval: 2s
+7
View File
@@ -20,6 +20,9 @@ import (
"go.yaml.in/yaml/v4"
)
// RequestTimeout bounds every RPC to Gitea, and with it runner.fetch_timeout.
const RequestTimeout = 60 * time.Second
// DefaultPostTaskScriptTimeout is the fallback cap on how long the post-task
// script may run when post_task_script is set without an explicit timeout. It is
// applied both at config load (for a configured script) and at the point of use
@@ -334,6 +337,10 @@ func LoadDefault(file string) (*Config, error) {
log.Warnf("runner.tool_cache_mode %q with capacity %d: two jobs writing the same tool version at once corrupt it",
ToolCacheModeShared, cfg.Runner.Capacity)
}
if cfg.Runner.FetchTimeout > RequestTimeout {
log.Warnf("fetch_timeout (%v) exceeds the RPC timeout (%v), capping it", cfg.Runner.FetchTimeout, RequestTimeout)
cfg.Runner.FetchTimeout = RequestTimeout
}
if cfg.Runner.FetchIntervalMax < cfg.Runner.FetchInterval {
log.Warnf("fetch_interval_max (%v) is less than fetch_interval (%v), setting fetch_interval_max to fetch_interval",
cfg.Runner.FetchIntervalMax, cfg.Runner.FetchInterval)
+12
View File
@@ -416,3 +416,15 @@ func TestLoadDefault_ShippedConfigsChangeNothing(t *testing.T) {
}
assert.Empty(t, hook.AllEntries())
}
func TestLoadDefault_ClampsFetchTimeout(t *testing.T) {
path := filepath.Join(t.TempDir(), "config.yaml")
require.NoError(t, os.WriteFile(path, []byte(`
runner:
fetch_timeout: 120s
`), 0o600))
cfg, err := LoadDefault(path)
require.NoError(t, err)
assert.Equal(t, RequestTimeout, cfg.Runner.FetchTimeout)
}
+60 -32
View File
@@ -26,6 +26,9 @@ import (
"google.golang.org/protobuf/types/known/timestamppb"
)
// errOutputsNotSent travels the same return path as transport failures but is not one.
var errOutputsNotSent = errors.New("there are still outputs that have not been sent")
// Size limits for the outputs reported to the server.
const (
maxOutputKeyLen = 255
@@ -56,8 +59,13 @@ type Reporter struct {
// so the gauge skips no-op Set calls when the buffer size is unchanged.
lastLogBufferRows int
state *runnerv1.TaskState
stateChanged bool
state *runnerv1.TaskState
stateChanged bool
// reportFailing keeps an outage to one log line at each end.
reportFailing map[string]bool
// serverResult is what the server decided, e.g. the zombie reaper failing
// the task. Guarded by stateMu.
serverResult runnerv1.Result
stateMu sync.RWMutex
outputsMu sync.Mutex
outputs map[string]jobOutput
@@ -77,6 +85,8 @@ type Reporter struct {
// closeTimeout bounds each RPC attempt in the final flush, on a context
// detached from r.ctx so a server cancel can't abort the acknowledgement.
closeTimeout time.Duration
// daemonWait bounds how long Close waits for the daemon loop to acknowledge.
daemonWait time.Duration
// Event notification channels (non-blocking, buffered 1)
logNotify chan struct{} // signal: new log rows arrived
@@ -119,10 +129,13 @@ func NewReporter(ctx context.Context, cancel context.CancelFunc, client client.C
state: &runnerv1.TaskState{
Id: task.Id,
},
reportFailing: map[string]bool{},
daemon: make(chan struct{}),
heartbeatStop: make(chan struct{}),
}
rv.daemonWait = 6 * rv.effectiveCloseTimeout()
if task.Secrets["ACTIONS_STEP_DEBUG"] == "true" {
rv.debugOutputEnabled = true
}
@@ -293,6 +306,21 @@ func (r *Reporter) Fire(entry *log.Entry) error {
return nil
}
// Only the daemon loop calls this, so reportFailing needs no lock.
func (r *Reporter) noteReport(method string, err error) {
if errors.Is(err, errOutputsNotSent) {
err = nil // the RPC itself succeeded
}
switch {
case err != nil && !r.reportFailing[method]:
r.reportFailing[method] = true
log.Warnf("%s error: %v, retrying until reconnected", method, err)
case err == nil && r.reportFailing[method]:
delete(r.reportFailing, method)
log.Infof("%s reconnected", method)
}
}
func (r *Reporter) RunDaemon() {
go r.runDaemonLoop()
}
@@ -319,6 +347,8 @@ func (r *Reporter) stopLatencyTimer(active *bool, timer *time.Timer) {
}
func (r *Reporter) runDaemonLoop() {
defer close(r.daemon)
logTicker := time.NewTicker(r.logReportInterval)
stateTicker := time.NewTicker(r.stateReportInterval)
@@ -337,11 +367,11 @@ func (r *Reporter) runDaemonLoop() {
for {
select {
case <-logTicker.C:
_ = r.ReportLog(false)
r.noteReport(metrics.LabelMethodUpdateLog, r.ReportLog(false))
r.stopLatencyTimer(&maxLatencyActive, maxLatencyTimer)
case <-stateTicker.C:
_ = r.ReportState(false)
r.noteReport(metrics.LabelMethodUpdateTask, r.ReportState(false))
case <-r.logNotify:
r.stateMu.RLock()
@@ -349,7 +379,7 @@ func (r *Reporter) runDaemonLoop() {
r.stateMu.RUnlock()
if n >= r.logBatchSize {
_ = r.ReportLog(false)
r.noteReport(metrics.LabelMethodUpdateLog, r.ReportLog(false))
r.stopLatencyTimer(&maxLatencyActive, maxLatencyTimer)
} else if !maxLatencyActive && n > 0 {
maxLatencyTimer.Reset(r.logReportMaxLatency)
@@ -358,25 +388,23 @@ func (r *Reporter) runDaemonLoop() {
case <-r.stateNotify:
// Step transition or job result — flush both immediately for frontend UX.
_ = r.ReportLog(false)
_ = r.ReportState(false)
r.noteReport(metrics.LabelMethodUpdateLog, r.ReportLog(false))
r.noteReport(metrics.LabelMethodUpdateTask, r.ReportState(false))
r.stopLatencyTimer(&maxLatencyActive, maxLatencyTimer)
case <-maxLatencyTimer.C:
maxLatencyActive = false
_ = r.ReportLog(false)
r.noteReport(metrics.LabelMethodUpdateLog, r.ReportLog(false))
case <-r.ctx.Done():
// Stop heartbeating on cancel so Gitea sees the runner as offline
// during cleanup and won't assign an overlapping task. Close() still
// delivers the final flush on a detached context (flushFinal).
close(r.daemon)
return
case <-r.heartbeatStop:
// Stop heartbeating during post-task script execution. Close() still
// delivers the final flush on a detached context (flushFinal).
close(r.daemon)
return
}
@@ -384,7 +412,6 @@ func (r *Reporter) runDaemonLoop() {
closed := r.closed
r.stateMu.RUnlock()
if closed {
close(r.daemon)
return
}
}
@@ -435,28 +462,23 @@ func (r *Reporter) Close(lastWords string) error {
r.stateMu.Lock()
r.closed = true
if r.state.Result == runnerv1.Result_RESULT_UNSPECIFIED {
// When r.ctx has been cancelled (server returned RESULT_CANCELLED via
// rpcCtx/ReportState, see line 590) the job is being torn down on the
// cancellation path: surface that explicitly instead of attributing it
// to a generic failure.
cancelled := errors.Is(r.ctx.Err(), context.Canceled)
// No result of its own, so say why it stopped.
result, words := runnerv1.Result_RESULT_FAILURE, "Early termination"
switch {
case r.serverResult != runnerv1.Result_RESULT_UNSPECIFIED:
result, words = r.serverResult, "Ended by the server"
case errors.Is(r.ctx.Err(), context.Canceled):
result, words = runnerv1.Result_RESULT_CANCELLED, "Cancelled"
}
if lastWords == "" {
if cancelled {
lastWords = "Cancelled"
} else {
lastWords = "Early termination"
}
lastWords = words
}
for _, v := range r.state.Steps {
if v.Result == runnerv1.Result_RESULT_UNSPECIFIED {
v.Result = runnerv1.Result_RESULT_CANCELLED
}
}
if cancelled {
r.state.Result = runnerv1.Result_RESULT_CANCELLED
} else {
r.state.Result = runnerv1.Result_RESULT_FAILURE
}
r.state.Result = result
r.logRows = append(r.logRows, &runnerv1.LogRow{
Time: timestamppb.Now(),
Content: lastWords,
@@ -476,9 +498,8 @@ func (r *Reporter) Close(lastWords string) error {
// Wait for Acknowledge
select {
case <-r.daemon:
case <-time.After(60 * time.Second):
close(r.daemon)
log.Error("No Response from RunDaemon for 60s, continue best effort")
case <-time.After(r.daemonWait):
log.Errorf("No Response from RunDaemon for %s, continue best effort", r.daemonWait)
}
// Gitea's UpdateLog short-circuits on len(Rows)==0 before honoring NoMore,
@@ -569,8 +590,10 @@ func (r *Reporter) ReportLog(noMore bool) error {
}
r.stateMu.Lock()
r.logRows = r.logRows[ack-r.logOffset:]
submitted := r.logOffset + len(rows)
// A server can ack beyond what it was sent; clamp to stay within the buffer.
ack = min(ack, submitted)
r.logRows = r.logRows[ack-r.logOffset:]
r.logOffset = ack
remaining := len(r.logRows)
r.stateMu.Unlock()
@@ -655,11 +678,16 @@ func (r *Reporter) ReportState(reportResult bool) error {
}
r.outputsMu.Unlock()
if resp.Msg.State != nil && resp.Msg.State.Result == runnerv1.Result_RESULT_CANCELLED {
// A terminal result means the server is done with this task; keep running and
// the job holds a capacity slot until runner.timeout.
if state := resp.Msg.State; state != nil && state.Result != runnerv1.Result_RESULT_UNSPECIFIED {
r.stateMu.Lock()
r.serverResult = state.Result
r.stateMu.Unlock()
r.cancel()
}
if len(noSent) > 0 {
return fmt.Errorf("there are still outputs that have not been sent: %v", noSent)
return fmt.Errorf("%w: %v", errOutputsNotSent, noSent)
}
return nil
+132
View File
@@ -12,6 +12,7 @@ import (
"net/url"
"slices"
"strings"
"sync"
"sync/atomic"
"testing"
"time"
@@ -19,10 +20,12 @@ import (
"gitea.com/gitea/runner/act/runner"
"gitea.com/gitea/runner/internal/pkg/client/mocks"
"gitea.com/gitea/runner/internal/pkg/config"
"gitea.com/gitea/runner/internal/pkg/metrics"
connect_go "connectrpc.com/connect"
runnerv1 "gitea.dev/actionslib/runner/v1"
log "github.com/sirupsen/logrus"
logrustest "github.com/sirupsen/logrus/hooks/test"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/mock"
"github.com/stretchr/testify/require"
@@ -1169,3 +1172,132 @@ func TestReporter_masksEncodedSecrets(t *testing.T) {
assert.NotContains(t, row.Content, base64.StdEncoding.EncodeToString([]byte(secret)))
}
}
// A server that acknowledges more rows than were sent must not take the runner
// process down with it.
func TestReporter_AckIndexBeyondBuffer(t *testing.T) {
client := mocks.NewClient(t)
client.On("UpdateLog", mock.Anything, mock.Anything).Return(func(_ context.Context, _ *connect_go.Request[runnerv1.UpdateLogRequest]) (*connect_go.Response[runnerv1.UpdateLogResponse], error) {
return connect_go.NewResponse(&runnerv1.UpdateLogResponse{AckIndex: 1000}), nil
})
ctx, cancel := context.WithCancel(context.Background())
defer cancel()
taskCtx, err := structpb.NewStruct(map[string]any{})
require.NoError(t, err)
cfg, _ := config.LoadDefault("")
reporter := NewReporter(ctx, cancel, client, &runnerv1.Task{Context: taskCtx}, cfg)
reporter.ResetSteps(1)
require.NoError(t, reporter.Fire(&log.Entry{
Message: "hello",
Data: log.Fields{"stage": "Main", "stepNumber": 0, "raw_output": true},
Level: log.InfoLevel,
}))
require.NoError(t, reporter.ReportLog(false))
}
// Close has to survive giving up on a daemon still parked in an RPC.
func TestReporter_CloseWithStuckDaemon(t *testing.T) {
release := make(chan struct{})
entered := make(chan struct{})
var once sync.Once
client := mocks.NewClient(t)
client.On("UpdateLog", mock.Anything, mock.Anything).Return(func(_ context.Context, req *connect_go.Request[runnerv1.UpdateLogRequest]) (*connect_go.Response[runnerv1.UpdateLogResponse], error) {
once.Do(func() {
close(entered)
<-release
})
return connect_go.NewResponse(&runnerv1.UpdateLogResponse{
AckIndex: req.Msg.Index + int64(len(req.Msg.Rows)),
}), nil
})
client.On("UpdateTask", mock.Anything, mock.Anything).Return(func(_ context.Context, _ *connect_go.Request[runnerv1.UpdateTaskRequest]) (*connect_go.Response[runnerv1.UpdateTaskResponse], error) {
return connect_go.NewResponse(&runnerv1.UpdateTaskResponse{}), nil
}).Maybe()
ctx, cancel := context.WithCancel(context.Background())
defer cancel()
taskCtx, err := structpb.NewStruct(map[string]any{})
require.NoError(t, err)
cfg, _ := config.LoadDefault("")
cfg.Runner.LogReportInterval = 10 * time.Millisecond
reporter := NewReporter(ctx, cancel, client, &runnerv1.Task{Context: taskCtx}, cfg)
reporter.daemonWait = time.Millisecond
reporter.RunDaemon()
reporter.ResetSteps(1)
require.NoError(t, reporter.Fire(&log.Entry{
Message: "hello",
Data: log.Fields{"stage": "Main", "stepNumber": 0, "raw_output": true},
Level: log.InfoLevel,
}))
select {
case <-entered:
case <-time.After(5 * time.Second):
t.Fatal("daemon never reached UpdateLog")
}
go func() {
time.Sleep(10 * reporter.daemonWait)
close(release)
}()
require.NoError(t, reporter.Close(""))
}
// The zombie reaper marks a task failed, and cancelling the context is how the
// runner stops, so the two must not be conflated into "cancelled".
func TestReporter_ServerFailureResultIsReportedAsFailure(t *testing.T) {
var lastState *runnerv1.TaskState
client := mocks.NewClient(t)
client.On("UpdateTask", mock.Anything, mock.Anything).Return(func(_ context.Context, req *connect_go.Request[runnerv1.UpdateTaskRequest]) (*connect_go.Response[runnerv1.UpdateTaskResponse], error) {
lastState = req.Msg.State
return connect_go.NewResponse(&runnerv1.UpdateTaskResponse{
State: &runnerv1.TaskState{Result: runnerv1.Result_RESULT_FAILURE},
}), nil
})
client.On("UpdateLog", mock.Anything, mock.Anything).Return(func(_ context.Context, req *connect_go.Request[runnerv1.UpdateLogRequest]) (*connect_go.Response[runnerv1.UpdateLogResponse], error) {
return connect_go.NewResponse(&runnerv1.UpdateLogResponse{
AckIndex: req.Msg.Index + int64(len(req.Msg.Rows)),
}), nil
}).Maybe()
ctx, cancel := context.WithCancel(context.Background())
defer cancel()
taskCtx, err := structpb.NewStruct(map[string]any{})
require.NoError(t, err)
cfg, _ := config.LoadDefault("")
reporter := NewReporter(ctx, cancel, client, &runnerv1.Task{Context: taskCtx}, cfg)
close(reporter.daemon) // no daemon loop to acknowledge
require.NoError(t, reporter.ReportState(false))
require.ErrorIs(t, ctx.Err(), context.Canceled)
require.NoError(t, reporter.Close(""))
require.NotNil(t, lastState)
assert.Equal(t, runnerv1.Result_RESULT_FAILURE, lastState.Result)
}
func TestReporter_NoteReport(t *testing.T) {
hook := logrustest.NewGlobal()
defer hook.Reset()
reporter := &Reporter{reportFailing: map[string]bool{}}
// A pending output is not a transport failure and must not read as one.
reporter.noteReport(metrics.LabelMethodUpdateTask, fmt.Errorf("wrapped: %w", errOutputsNotSent))
assert.Empty(t, hook.AllEntries())
// An outage logs once at each end, not every report interval for hours.
reporter.noteReport(metrics.LabelMethodUpdateTask, errors.New("connection refused"))
reporter.noteReport(metrics.LabelMethodUpdateTask, errors.New("connection refused"))
require.Len(t, hook.AllEntries(), 1)
assert.Contains(t, hook.LastEntry().Message, "connection refused")
reporter.noteReport(metrics.LabelMethodUpdateTask, nil)
require.Len(t, hook.AllEntries(), 2)
assert.Contains(t, hook.LastEntry().Message, "reconnected")
}