refactor(logging): use the logging package in internal (#1302)

Move the log calls in `internal` onto `logging`, and add what the process-wide logger setup and its tests need: `SetTextFormat` with a line filter for secret masking (replacing `report.MaskingFormatter`), `SetReportCaller`, `SetDefault` and `logtest.SetDefault`. After this only the `logging` package imports logrus.

Stacked on https://gitea.com/gitea/runner/pulls/1301.

Assisted-by: Codet
Co-authored-by: bircni <[email protected]>
Reviewed-on: https://gitea.com/gitea/runner/pulls/1302
Reviewed-by: bircni <[email protected]>

internal/pkg/config/config.example.yaml

@@ -6,7 +6,7 @@
 # each task's log kept under log.job. Neither controls how workflow step output is streamed
 # to the Gitea UI; tune that with runner.log_report_* below.
 log:
-  # logrus severity: trace, debug, info, warn, error, fatal, panic.
+  # Severity: trace, debug, info, warn, error. fatal and panic are accepted and mean error.
   # trace and debug turn on caller/file:line in log lines. Default if omitted: info.
   #level: info
   # Write a copy of each task's log to dir as <start time>-task-<id>.log, so a job's output

internal/pkg/config/config.go

@@ -15,9 +15,10 @@ import (
 	"strings"
 	"time"
 
+	"gitea.com/gitea/runner/act/common/logging"
+
 	"github.com/docker/go-units"
 	"github.com/joho/godotenv"
-	log "github.com/sirupsen/logrus"
 	"go.yaml.in/yaml/v4"
 	"golang.org/x/net/http/httpguts"
 )
@@ -408,26 +409,26 @@ func LoadDefault(file string) (*Config, error) {
 
 	// Validate and fix invalid config combinations to prevent confusing behavior.
 	if cfg.Runner.ToolCacheMode == ToolCacheModeShared && cfg.Runner.Capacity > 1 {
-		log.Warnf("runner.tool_cache_mode %q with capacity %d: two jobs writing the same tool version at once corrupt it",
+		logging.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)
+		logging.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",
+		logging.Warnf("fetch_interval_max (%v) is less than fetch_interval (%v), setting fetch_interval_max to fetch_interval",
 			cfg.Runner.FetchIntervalMax, cfg.Runner.FetchInterval)
 		cfg.Runner.FetchIntervalMax = cfg.Runner.FetchInterval
 	}
 	if cfg.Runner.LogReportMaxLatency >= cfg.Runner.LogReportInterval {
-		log.Warnf("log_report_max_latency (%v) >= log_report_interval (%v), the max-latency timer will never fire before the periodic ticker; consider lowering log_report_max_latency",
+		logging.Warnf("log_report_max_latency (%v) >= log_report_interval (%v), the max-latency timer will never fire before the periodic ticker; consider lowering log_report_max_latency",
 			cfg.Runner.LogReportMaxLatency, cfg.Runner.LogReportInterval)
 	}
 
 	// although `container.network_mode` will be deprecated, but we have to be compatible with it for now.
 	if cfg.Container.NetworkMode != "" && cfg.Container.Network == "" {
-		log.Warn("You are trying to use deprecated configuration item of `container.network_mode`, please use `container.network` instead.")
+		logging.Warn("You are trying to use deprecated configuration item of `container.network_mode`, please use `container.network` instead.")
 		if cfg.Container.NetworkMode == "bridge" {
 			// Previously, if the value of `container.network_mode` is `bridge`, we will create a new network for job.
 			// But “bridge” is easily confused with the bridge network created by Docker by default.
@@ -493,7 +494,7 @@ func warnUnknownKeys(file string, document *yaml.Node) {
 	var loadErrs *yaml.LoadErrors
 	if err := document.Load(&Config{}, yaml.WithV3Defaults(), yaml.WithKnownFields()); errors.As(err, &loadErrs) {
 		for _, loadErr := range loadErrs.Errors {
-			log.Warnf("config file %q: %s, it will be ignored", file, loadErr)
+			logging.Warnf("config file %q: %s, it will be ignored", file, loadErr)
 		}
 	}
 }

internal/pkg/config/config_test.go

@@ -16,7 +16,8 @@ import (
 	"testing"
 	"time"
 
-	"github.com/sirupsen/logrus/hooks/test"
+	"gitea.com/gitea/runner/act/common/logging/logtest"
+
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 )
@@ -391,14 +392,13 @@ func TestLoadDefault_WarnsOnUnknownKeysButStillLoads(t *testing.T) {
 	path := filepath.Join(dir, "config.yaml")
 	require.NoError(t, os.WriteFile(path, []byte("container:\n  volumes:\n    - /host:/ctr\n  privileged: true\n"), 0o600))
 
-	hook := test.NewGlobal()
-	defer hook.Reset()
+	hook := logtest.SetDefault(t)
 
 	cfg, err := LoadDefault(path)
 	require.NoError(t, err)
 	assert.True(t, cfg.Container.Privileged)
-	require.Len(t, hook.Entries, 1)
-	assert.Contains(t, hook.LastEntry().Message, "field volumes not found")
+	require.Len(t, hook.AllRecords(), 1)
+	assert.Contains(t, hook.LastRecord().Message, "field volumes not found")
 }
 
 func TestContainerNetworkCreateOptions(t *testing.T) {
@@ -539,8 +539,7 @@ cache:
 // The shipped configs must parse, hold no key the config does not know, and leave
 // every option at its default, as all of their values are commented out.
 func TestLoadDefault_ShippedConfigsChangeNothing(t *testing.T) {
-	hook := test.NewGlobal()
-	defer hook.Reset()
+	hook := logtest.SetDefault(t)
 
 	defaults, err := LoadDefault("")
 	require.NoError(t, err)
@@ -554,7 +553,7 @@ func TestLoadDefault_ShippedConfigsChangeNothing(t *testing.T) {
 		require.NoError(t, err, name)
 		assert.Equal(t, defaults, cfg, name)
 	}
-	assert.Empty(t, hook.AllEntries())
+	assert.Empty(t, hook.AllRecords())
 }
 
 func TestLoadDefault_ClampsFetchTimeout(t *testing.T) {

internal/pkg/metrics/server.go

@@ -8,8 +8,9 @@ import (
 	"net/http"
 	"time"
 
+	"gitea.com/gitea/runner/act/common/logging"
+
 	"github.com/prometheus/client_golang/prometheus/promhttp"
-	log "github.com/sirupsen/logrus"
 )
 
 // StartServer starts an HTTP server that serves Prometheus metrics on /metrics
@@ -26,9 +27,9 @@ func StartServer(ctx context.Context, addr string, readiness func() (bool, strin
 	}
 
 	go func() {
-		log.Infof("metrics server listening on %s", addr)
+		logging.Infof("metrics server listening on %s", addr)
 		if err := srv.ListenAndServe(); err != nil && err != http.ErrServerClosed {
-			log.WithError(err).Error("metrics server failed")
+			logging.WithError(err).Error("metrics server failed")
 		}
 	}()
 
@@ -37,7 +38,7 @@ func StartServer(ctx context.Context, addr string, readiness func() (bool, strin
 		shutCtx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
 		defer cancel()
 		if err := srv.Shutdown(shutCtx); err != nil {
-			log.WithError(err).Warn("metrics server shutdown error")
+			logging.WithError(err).Warn("metrics server shutdown error")
 		}
 	}()
 }

internal/pkg/report/globalmask.go

@@ -9,8 +9,6 @@ import (
 	"sync/atomic"
 
 	"gitea.com/gitea/runner/act/runner"
-
-	log "github.com/sirupsen/logrus"
 )
 
 // A job's plan runs before its job logger exists and logs through the process-wide one, which
@@ -47,21 +45,12 @@ func rebuildGlobalReplacer() { // caller holds globalMu
 	globalReplacer.Store(runner.NewSecretReplacer(oldnew))
 }
 
-// MaskingFormatter wraps f so a registered value cannot reach the process-wide log, fields included.
-func MaskingFormatter(f log.Formatter) log.Formatter {
-	return &maskingFormatter{inner: f}
-}
-
-type maskingFormatter struct{ inner log.Formatter }
-
-func (m *maskingFormatter) Format(entry *log.Entry) ([]byte, error) {
-	line, err := m.inner.Format(entry)
-	if err != nil {
-		return nil, err
-	}
+// MaskGlobal hides every registered value in a formatted line of the process-wide log, fields
+// included. It is meant for logging.TextOptions.Filter.
+func MaskGlobal(line []byte) []byte {
 	replacer := globalReplacer.Load()
 	if replacer == nil { // nothing to hide, so an idle daemon pays no copy
-		return line, nil
+		return line
 	}
-	return []byte(replacer.Replace(string(line))), nil
+	return []byte(replacer.Replace(string(line)))
 }

internal/pkg/report/globalmask_test.go

@@ -4,19 +4,27 @@
 package report
 
 import (
+	"strings"
 	"testing"
 
-	log "github.com/sirupsen/logrus"
+	"gitea.com/gitea/runner/act/common/logging"
+
 	"github.com/stretchr/testify/assert"
-	"github.com/stretchr/testify/require"
 )
 
 func TestGlobalMasks(t *testing.T) {
-	formatter := MaskingFormatter(&log.TextFormatter{DisableTimestamp: true})
+	prevOut := logging.Output()
+	t.Cleanup(func() {
+		logging.SetOutput(prevOut)
+		logging.SetTextFormat(logging.TextOptions{})
+	})
+	var out strings.Builder
+	logging.SetOutput(&out)
+	logging.SetTextFormat(logging.TextOptions{DisableTimestamp: true, Filter: MaskGlobal})
 	format := func(job string) string {
-		line, err := formatter.Format(log.WithField("job", job))
-		require.NoError(t, err)
-		return string(line)
+		out.Reset()
+		logging.With("job", job).Info("line")
+		return out.String()
 	}
 	register := func(oldnew ...string) *Reporter {
 		r := &Reporter{oldnew: oldnew}

internal/pkg/report/joblog.go

@@ -10,9 +10,8 @@ import (
 	"strings"
 	"time"
 
+	"gitea.com/gitea/runner/act/common/logging"
 	"gitea.com/gitea/runner/internal/pkg/config"
-
-	log "github.com/sirupsen/logrus"
 )
 
 const (
@@ -37,7 +36,7 @@ func openJobLog(cfg config.LogJob, taskID int64, started time.Time) *jobLog {
 	}
 
 	if err := os.MkdirAll(cfg.Dir, 0o700); err != nil { // repository output, readable by this user only
-		log.Warnf("cannot create job log directory %s: %v", cfg.Dir, err)
+		logging.Warnf("cannot create job log directory %s: %v", cfg.Dir, err)
 		return nil
 	}
 	pruneJobLogs(cfg.Dir, cfg.Retention, started)
@@ -45,10 +44,10 @@ func openJobLog(cfg config.LogJob, taskID int64, started time.Time) *jobLog {
 	name := fmt.Sprintf("%s-task-%d.log", started.UTC().Format(jobLogNameLayout), taskID)
 	file, err := os.OpenFile(filepath.Join(cfg.Dir, name), os.O_WRONLY|os.O_CREATE|os.O_TRUNC, 0o600)
 	if err != nil {
-		log.Warnf("cannot create job log: %v", err)
+		logging.Warnf("cannot create job log: %v", err)
 		return nil
 	}
-	log.Infof("writing the log of task %d to %s", taskID, file.Name())
+	logging.Infof("writing the log of task %d to %s", taskID, file.Name())
 	return &jobLog{file: file, max: int64(cfg.MaxSize)}
 }
 
@@ -72,7 +71,7 @@ func (j *jobLog) close(trailer string) {
 	j.closed = true
 	j.line(runnerLine(trailer)) // past the cap on purpose: no trailer means the runner died mid-job
 	if err := j.file.Close(); err != nil {
-		log.Warnf("cannot close %s: %v", j.file.Name(), err)
+		logging.Warnf("cannot close %s: %v", j.file.Name(), err)
 	}
 }
 
@@ -83,7 +82,7 @@ func (j *jobLog) line(content string) {
 	j.size += int64(n)
 	if err != nil {
 		j.stopped = true // reported once, a failing write is a full disk and retrying floods the log
-		log.Warnf("cannot write %s: %v", j.file.Name(), err)
+		logging.Warnf("cannot write %s: %v", j.file.Name(), err)
 	}
 }
 
@@ -99,7 +98,7 @@ func pruneJobLogs(root string, retention time.Duration, now time.Time) {
 	}
 	entries, err := os.ReadDir(root)
 	if err != nil {
-		log.Warnf("cannot list job log directory %s: %v", root, err)
+		logging.Warnf("cannot list job log directory %s: %v", root, err)
 		return
 	}
 
@@ -114,7 +113,7 @@ func pruneJobLogs(root string, retention time.Duration, now time.Time) {
 		}
 		name := filepath.Join(root, entry.Name())
 		if err := os.Remove(name); err != nil {
-			log.Warnf("cannot remove expired job log %s: %v", name, err)
+			logging.Warnf("cannot remove expired job log %s: %v", name, err)
 		}
 	}
 }

internal/pkg/report/reporter.go

@@ -23,7 +23,6 @@ import (
 	"connectrpc.com/connect"
 	runnerv1 "gitea.dev/actionslib/runner/v1"
 	"github.com/avast/retry-go/v5"
-	log "github.com/sirupsen/logrus"
 	"google.golang.org/protobuf/proto"
 	"google.golang.org/protobuf/types/known/timestamppb"
 )
@@ -357,10 +356,10 @@ func (r *Reporter) noteReport(method string, err error) {
 	switch {
 	case err != nil && !r.reportFailing[method]:
 		r.reportFailing[method] = true
-		log.Warnf("%s error: %v, retrying until reconnected", method, err)
+		logging.Warnf("%s error: %v, retrying until reconnected", method, err)
 	case err == nil && r.reportFailing[method]:
 		delete(r.reportFailing, method)
-		log.Infof("%s reconnected", method)
+		logging.Infof("%s reconnected", method)
 	}
 }
 
@@ -497,17 +496,17 @@ func (r *Reporter) SetOutputs(outputs map[string]string) {
 	}
 	for k, v := range outputs {
 		if l := len(k); l > maxOutputKeyLen {
-			log.Warnf("ignore output %q because the key is too long: %d > %d", k, l, maxOutputKeyLen)
+			logging.Warnf("ignore output %q because the key is too long: %d > %d", k, l, maxOutputKeyLen)
 			r.logf("ignore output %q because the key is too long: %d > %d", k, l, maxOutputKeyLen)
 			continue
 		}
 		if l := len(v); l > maxOutputValueLen {
-			log.Warnf("ignore output %q because the value is too long: %d > %d", k, l, maxOutputValueLen)
+			logging.Warnf("ignore output %q because the value is too long: %d > %d", k, l, maxOutputValueLen)
 			r.logf("ignore output %q because the value is too long: %d > %d", k, l, maxOutputValueLen)
 			continue
 		}
 		if r.logReplacer.Replace(v) != v { // GitHub skips an output that may carry a secret rather than masking it
-			log.Warnf("ignore output %q because it may contain a secret", k)
+			logging.Warnf("ignore output %q because it may contain a secret", k)
 			r.logf("ignore output %q because it may contain a secret", k)
 			continue
 		}
@@ -559,7 +558,7 @@ func (r *Reporter) Close(lastWords string) error {
 	select {
 	case <-r.daemon:
 	case <-time.After(r.daemonWait):
-		log.Errorf("No Response from RunDaemon for %s, continue best effort", r.daemonWait)
+		logging.Errorf("No Response from RunDaemon for %s, continue best effort", r.daemonWait)
 	}
 
 	// Gitea's UpdateLog short-circuits on len(Rows)==0 before honoring NoMore,

internal/pkg/report/reporter_test.go

@@ -18,6 +18,7 @@ import (
 	"time"
 
 	"gitea.com/gitea/runner/act/common/logging"
+	"gitea.com/gitea/runner/act/common/logging/logtest"
 	"gitea.com/gitea/runner/act/runner"
 	"gitea.com/gitea/runner/internal/pkg/client/mocks"
 	"gitea.com/gitea/runner/internal/pkg/config"
@@ -26,7 +27,6 @@ import (
 	connect_go "connectrpc.com/connect"
 	"gitea.dev/actionslib/pkg/model"
 	runnerv1 "gitea.dev/actionslib/runner/v1"
-	logrustest "github.com/sirupsen/logrus/hooks/test"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/mock"
 	"github.com/stretchr/testify/require"
@@ -1311,24 +1311,23 @@ func TestReporter_ServerFailureResultIsReportedAsFailure(t *testing.T) {
 }
 
 func TestReporter_NoteReport(t *testing.T) {
-	hook := logrustest.NewGlobal()
-	defer hook.Reset()
+	hook := logtest.SetDefault(t)
 
 	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())
+	assert.Empty(t, hook.AllRecords())
 
 	// 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")
+	require.Len(t, hook.AllRecords(), 1)
+	assert.Contains(t, hook.LastRecord().Message, "connection refused")
 
 	reporter.noteReport(metrics.LabelMethodUpdateTask, nil)
-	require.Len(t, hook.AllEntries(), 2)
-	assert.Contains(t, hook.LastEntry().Message, "reconnected")
+	require.Len(t, hook.AllRecords(), 2)
+	assert.Contains(t, hook.LastRecord().Message, "reconnected")
 }
 
 // A job's final error can carry a secret, e.g. one interpolated into a failing

internal/pkg/telemetry/metrics.go

@@ -12,12 +12,12 @@ import (
 	"strings"
 	"time"
 
+	"gitea.com/gitea/runner/act/common/logging"
 	"gitea.com/gitea/runner/internal/pkg/metrics"
 
 	"gitea.dev/actionslib/runner/v1/runnerv1connect"
 	"github.com/prometheus/client_golang/prometheus"
 	dto "github.com/prometheus/client_model/go"
-	log "github.com/sirupsen/logrus"
 	"go.opentelemetry.io/otel/attribute"
 	"go.opentelemetry.io/otel/sdk/resource"
 	commonpb "go.opentelemetry.io/proto/otlp/common/v1"
@@ -61,7 +61,7 @@ func pushMetrics(exporter *client, res *resource.Resource, gatherer prometheus.G
 				return
 			case <-ticker.C:
 				if err := push(ctx); err != nil && ctx.Err() == nil {
-					log.WithError(err).Warn("OTLP metrics export failed, set OTEL_METRICS_EXPORTER=none to disable it")
+					logging.WithError(err).Warn("OTLP metrics export failed, set OTEL_METRICS_EXPORTER=none to disable it")
 				}
 			}
 		}

internal/pkg/telemetry/telemetry.go

@@ -21,6 +21,7 @@ import (
 	"sync"
 	"time"
 
+	"gitea.com/gitea/runner/act/common/logging"
 	"gitea.com/gitea/runner/internal/pkg/ver"
 
 	"gitea.dev/actionslib/pkg/model"
@@ -28,7 +29,6 @@ import (
 	"github.com/avast/retry-go/v5"
 	"github.com/docker/go-connections/tlsconfig"
 	"github.com/prometheus/client_golang/prometheus"
-	log "github.com/sirupsen/logrus"
 	"go.opentelemetry.io/otel/attribute"
 	"go.opentelemetry.io/otel/codes"
 	"go.opentelemetry.io/otel/exporters/otlp/otlptrace"
@@ -90,7 +90,7 @@ func Setup(ctx context.Context, uuid, name string, gatherer prometheus.Gatherer)
 		compressionKey := otlpKey(signal, "COMPRESSION")
 		compression := os.Getenv(compressionKey)
 		if !slices.Contains([]string{"", "none", "gzip"}, strings.ToLower(compression)) {
-			log.Warnf("ignoring unsupported %s=%q", compressionKey, compression)
+			logging.Warnf("ignoring unsupported %s=%q", compressionKey, compression)
 		}
 		httpClient, err := newHTTPClient(signal)
 		if err != nil {
@@ -144,7 +144,7 @@ func exportsOTLP(signal string) bool {
 		case "none":
 			known = true
 		default:
-			log.Warnf("ignoring unsupported %s value %q", key, value)
+			logging.Warnf("ignoring unsupported %s value %q", key, value)
 		}
 	}
 	return otlp || !known
@@ -166,7 +166,7 @@ func millis(key string, fallback, zero time.Duration) time.Duration {
 	}
 	ms, err := strconv.ParseInt(value, 10, 32)
 	if err != nil || ms < 0 {
-		log.Warnf("ignoring %s=%q, it must be a non-negative number of milliseconds", key, value)
+		logging.Warnf("ignoring %s=%q, it must be a non-negative number of milliseconds", key, value)
 		return fallback
 	}
 	return cmp.Or(time.Duration(ms)*time.Millisecond, zero)