act_runner/act/runner/logger.go

// Copyright 2022 The Gitea Authors. All rights reserved.
// Copyright 2020 The nektos/act Authors. All rights reserved.
// SPDX-License-Identifier: MIT

package runner

import (
	"bytes"
	"context"
	"encoding/base64"
	"encoding/json/jsontext"
	"encoding/json/v2"
	"fmt"
	"io"
	"net/url"
	"os"
	"slices"
	"strings"
	"sync"

	"gitea.com/gitea/runner/act/common"
	"gitea.com/gitea/runner/act/common/logging"

	"golang.org/x/term"
)

const (
	// nocolor = 0
	red     = 31
	green   = 32
	yellow  = 33
	blue    = 34
	magenta = 35
	cyan    = 36
	gray    = 37
)

const (
	// The "stage" of the log entries of a step, and of the job level entries that finalize the job after its steps.
	StagePre      = "Pre"
	StageMain     = "Main"
	StagePost     = "Post"
	StageComplete = "Complete"
	// StepStartedField marks the log entry of a step that is about to run, unlike one that is skipped.
	StepStartedField = "stepStarted"
)

const (
	rawOutputField      = "raw_output"
	scriptLineCyanField = "script_line_cyan"
)

var (
	colors    = []int{blue, yellow, green, magenta, red, gray, cyan}
	nextColor int
	mux       sync.Mutex
)

type masksContextKey string

const masksContextKeyVal = masksContextKey("logrus.FieldLogger")

type valueMaskerContextKey struct{}

// Logger returns the appropriate logger for current context
func Masks(ctx context.Context) *[]string {
	if masks, ok := ctx.Value(masksContextKeyVal).(*[]string); ok {
		return masks
	}
	return &[]string{}
}

// WithMasks adds a value to the context for the logger
func WithMasks(ctx context.Context, masks *[]string) context.Context {
	return context.WithValue(ctx, masksContextKeyVal, masks)
}

// JobLoggerFactory supplies the handler a job's own log output goes to, in place of stdout.
type JobLoggerFactory interface {
	WithJobLogger() logging.Handler
}

type jobLoggerFactoryContextKey string

var jobLoggerFactoryContextKeyVal = jobLoggerFactoryContextKey("jobloggerkey")

func WithJobLoggerFactory(ctx context.Context, factory JobLoggerFactory) context.Context {
	return context.WithValue(ctx, jobLoggerFactoryContextKeyVal, factory)
}

// WithJobLogger attaches a new logger to context that is aware of steps
func WithJobLogger(ctx context.Context, jobID, jobName string, config *Config, masks *[]string, matrix map[string]any) context.Context {
	masker := valueMasker(config.InsecureSecrets, config.maskers())
	ctx = context.WithValue(ctx, valueMaskerContextKey{}, masker)
	ctx = WithMasks(ctx, masks)

	var output logging.Handler
	if jobLoggerFactory, ok := ctx.Value(jobLoggerFactoryContextKeyVal).(JobLoggerFactory); ok && jobLoggerFactory != nil {
		output = jobLoggerFactory.WithJobLogger()
	} else if config.JSONLogger {
		output = newJobLogJSONHandler(os.Stdout)
	} else {
		mux.Lock()
		nextColor++
		color := colors[nextColor%len(colors)]
		mux.Unlock()
		output = newJobLogHandler(os.Stdout, color)
	}

	var handlers []logging.Handler
	if h := common.LoggerHandler(ctx); h != nil { // Adapt to Gitea
		handlers = append(handlers, h)
	}
	handlers = append(handlers, &maskedHandler{
		Handler: output,
		masker:  masker,
	})

	level := logging.LevelTrace
	if config.JobLoggerLevel != nil {
		level = *config.JobLoggerLevel
	}

	rtn := logging.New(logging.NewLevelHandler(logging.NewMultiHandler(handlers...), level)).With(
		"job", jobName,
		"jobID", jobID,
		"dryrun", common.Dryrun(ctx),
		"matrix", matrix,
	).WithContext(ctx)

	return common.WithLogger(ctx, rtn)
}

func WithCompositeLogger(ctx context.Context, masks *[]string) context.Context {
	ctx = WithMasks(ctx, masks)
	return common.WithLogger(ctx, common.Logger(ctx).WithContext(ctx))
}

func WithCompositeStepLogger(ctx context.Context, stepID string) context.Context {
	stepIDs := append(slices.Clone(common.StepIDs(ctx)), stepID)
	ctx = common.WithStepIDs(ctx, stepIDs)

	return common.WithLogger(ctx, common.Logger(ctx).With("stepID", stepIDs).WithContext(ctx))
}

func withStepLogger(ctx context.Context, stepNumber int, stepID, stepName, stageName string) context.Context {
	if masker, ok := ctx.Value(valueMaskerContextKey{}).(entryProcessor); ok {
		stepName = masker(ctx, logging.Record{Message: stepName}).Message
	}
	stepIDs := []string{stepID}
	ctx = common.WithStepIDs(ctx, stepIDs)

	rtn := common.Logger(ctx).With(
		"stepNumber", stepNumber,
		"step", stepName,
		"stepID", stepIDs,
		"stage", stageName,
	)
	return common.WithLogger(ctx, rtn)
}

// entryProcessor rewrites a record before the output handler sees it.
type entryProcessor func(ctx context.Context, r logging.Record) logging.Record

var secretValueEncoders = []func(string) string{
	func(v string) string { return base64.StdEncoding.EncodeToString([]byte(v)) },
	base64ShiftEncoder(1),
	base64ShiftEncoder(2),
	base64InteriorEncoder(0),
	base64InteriorEncoder(1),
	base64InteriorEncoder(2),
	expressionStringEscape,
	jsonStringEscape,
	jsonStringEscapeNoHTML,
	uriDataEscape,
	url.QueryEscape, // the form-encoded twin of uriDataEscape, which spells a space "+"
	url.PathEscape,
	xmlDataEscaper.Replace,
	trimDoubleQuotes,
}

// base64ShiftEncoder reproduces the 3-byte alignments of `Basic base64("user:token")`, and
// its padded tail only matches a secret that ends the payload.
func base64ShiftEncoder(shift int) func(string) string {
	return func(v string) string {
		value := []byte(v)
		if len(value) > shift {
			value = value[shift:]
		}
		return base64.StdEncoding.EncodeToString(value)
	}
}

const minInteriorBase64Len = 8 // below this a fragment matches unrelated output

// base64InteriorEncoder keeps the aligned middle, so a secret with data after it still matches.
func base64InteriorEncoder(shift int) func(string) string {
	return func(v string) string {
		buf := make([]byte, shift+len(v))
		copy(buf[shift:], v)
		encoded := base64.StdEncoding.EncodeToString(buf)
		if len(encoded) < 8+minInteriorBase64Len {
			return ""
		}
		return encoded[4 : len(encoded)-4]
	}
}

func expressionStringEscape(v string) string {
	return strings.ReplaceAll(v, "'", "''")
}

func uriDataEscape(v string) string {
	return strings.ReplaceAll(url.QueryEscape(v), "+", "%20")
}

var xmlDataEscaper = strings.NewReplacer(
	"&", "&amp;",
	"<", "&lt;",
	">", "&gt;",
	`"`, "&quot;",
	"'", "&apos;",
)

func trimDoubleQuotes(v string) string {
	if len(v) > 8 && strings.HasPrefix(v, `"`) && strings.HasSuffix(v, `"`) {
		return v[1 : len(v)-1]
	}
	return ""
}

// jsonStringEscape returns v as it appears inside a JSON string, without the quotes,
// which is what `toJSON(secrets)` or any action logging a JSON body produces. Go's encoder
// escapes <, >, & (as act's own toJSON does); the non-HTML variant below covers the runtimes
// that do not. When v has none of those characters both forms are equal and deduplicated.
func jsonStringEscape(v string) string {
	encoded, err := json.Marshal(v, jsontext.EscapeForHTML(true))
	if err != nil {
		return v
	}
	return string(encoded[1 : len(encoded)-1])
}

// jsonStringEscapeNoHTML is jsonStringEscape without HTML escaping, matching the JSON a
// JavaScript (JSON.stringify) or .NET action emits, so a secret containing < > or & is
// masked in that form too.
func jsonStringEscapeNoHTML(v string) string {
	encoded, err := json.Marshal(v)
	if err != nil {
		return v
	}
	return string(encoded[1 : len(encoded)-1])
}

// AppendSecretMaskers skips the debug settings, as GitHub does: they arrive as secrets, but
// masking "true" would corrupt unrelated log lines and drop job outputs that say it.
func AppendSecretMaskers(oldnew []string, secrets map[string]string) []string {
	for k, v := range secrets {
		if k != "ACTIONS_STEP_DEBUG" && k != "ACTIONS_RUNNER_DEBUG" {
			oldnew = AppendSecretMasker(oldnew, v)
		}
	}
	return oldnew
}

// AppendSecretMasker registers v and each of its lines, as GitHub does.
func AppendSecretMasker(oldnew []string, v string) []string {
	ret := appendMaskedValue(oldnew, v)
	for l := range strings.FieldsFuncSeq(v, func(r rune) bool { return r == '\r' || r == '\n' }) {
		ret = appendMaskedValue(ret, strings.TrimSpace(l))
	}
	return ret
}

// appendMaskedValue registers one value and every shape it takes on its way into a log.
func appendMaskedValue(ret []string, v string) []string {
	// formatted JSON secrets could otherwise mask {,[,],} everywhere
	if len(strings.TrimSpace(v)) <= 1 || slices.Contains(ret, v) {
		return ret
	}
	ret = append(ret, v, "***")
	// command data reaches the log escaped, so "pass%word" also arrives as "pass%25word"
	if strings.ContainsAny(v, "%\r\n") {
		ret = append(ret, EscapeCommandData(v), "***")
	}
	for _, encode := range secretValueEncoders {
		encoded := encode(v)
		// An encoding that leaves the value unchanged is already masked above.
		if encoded == v || len(encoded) <= 1 || slices.Contains(ret, encoded) {
			continue
		}
		ret = append(ret, encoded, "***")
	}
	return ret
}

// valueMasker applies secrets and ::add-mask:: patterns to every log entry, including
// raw_output (command/stream) lines; there is no bypass by field.
func valueMasker(insecureSecrets bool, oldnew []string) entryProcessor {
	oldnew = slices.Clip(oldnew)
	defReplacer := NewSecretReplacer(oldnew)

	// A ::add-mask:: only ever appends to the job's mask slice, so the replacer built for
	// it stays valid until the slice grows. Cache it, keyed by the slice itself and its
	// length, instead of encoding every secret and mask again for each log line.
	var (
		mu       sync.Mutex
		masksRef *[]string
		pairs    []string
		masked   int
		replacer *strings.Replacer
	)

	return func(ctx context.Context, r logging.Record) logging.Record {
		if insecureSecrets {
			return r
		}

		masks := Masks(ctx)

		if len(*masks) == 0 {
			r.Message = defReplacer.Replace(r.Message)
			return r
		}

		mu.Lock()
		// A composite action logs through the same masker with its own mask slice, so a
		// different slice starts the cache over.
		if masksRef != masks {
			masksRef, pairs, masked, replacer = masks, oldnew, 0, nil
		}
		if replacer == nil || masked != len(*masks) {
			for _, v := range (*masks)[masked:] {
				pairs = AppendSecretMasker(pairs, v)
			}
			masked = len(*masks)
			replacer = NewSecretReplacer(pairs)
		}
		cmasker := replacer
		mu.Unlock()

		r.Message = cmasker.Replace(r.Message)

		return r
	}
}

type maskedHandler struct {
	logging.Handler
	masker entryProcessor
}

func (m *maskedHandler) Handle(ctx context.Context, r logging.Record) error {
	return m.Handler.Handle(ctx, m.masker(ctx, r))
}

func (m *maskedHandler) WithAttrs(attrs []logging.Attr) logging.Handler {
	return &maskedHandler{Handler: m.Handler.WithAttrs(attrs), masker: m.masker}
}

// jobLogHandler writes a job's log to w, one record per line in the shape format gives it.
type jobLogHandler struct {
	w      io.Writer
	mu     *sync.Mutex // shared by every handler derived with WithAttrs, as they share w
	attrs  []logging.Attr
	format func(logging.Record) ([]byte, error)
}

// newJobLogHandler writes readable text.
func newJobLogHandler(w io.Writer, color int) *jobLogHandler {
	return &jobLogHandler{w: w, mu: &sync.Mutex{}, format: textFormatter{w: w, color: color}.format}
}

func (h *jobLogHandler) Enabled(context.Context, logging.Level) bool { return true }

func (h *jobLogHandler) WithAttrs(attrs []logging.Attr) logging.Handler {
	c := *h
	c.attrs = slices.Concat(h.attrs, attrs)
	return &c
}

func (h *jobLogHandler) Handle(_ context.Context, r logging.Record) error {
	r.Attrs = slices.Concat(h.attrs, r.Attrs)
	line, err := h.format(r)
	if err != nil {
		return err
	}
	h.mu.Lock()
	defer h.mu.Unlock()
	_, err = h.w.Write(line)
	return err
}

type textFormatter struct {
	w     io.Writer
	color int
}

func (f textFormatter) format(r logging.Record) ([]byte, error) {
	b := &bytes.Buffer{}

	// the web renderer decodes command data, so this local view has to as well
	if _, _, _, ok := parseActionCommand(r.Message, ""); ok && (strings.HasPrefix(r.Message, "::") || strings.HasPrefix(r.Message, "##[")) {
		r.Message = UnescapeCommandData(r.Message)
	}
	r.Message = strings.TrimSuffix(r.Message, "\n")

	if f.isColored() {
		f.printColored(b, r)
	} else {
		f.print(b, r)
	}

	b.WriteByte('\n')
	return b.Bytes(), nil
}

func attrIsTrue(r logging.Record, key string) bool {
	v, _ := r.Attr(key)
	return v == true
}

func (f textFormatter) printColored(b *bytes.Buffer, r logging.Record) {
	job, _ := r.Attr("job")

	debugFlag := ""
	if r.Level == logging.LevelDebug {
		debugFlag = "[DEBUG] "
	}

	switch {
	case attrIsTrue(r, rawOutputField):
		if attrIsTrue(r, scriptLineCyanField) {
			fmt.Fprintf(b, "\x1b[%dm|\x1b[0m \x1b[36;1m%s\x1b[0m", f.color, r.Message)
		} else {
			fmt.Fprintf(b, "\x1b[%dm|\x1b[0m %s", f.color, r.Message)
		}
	case attrIsTrue(r, "dryrun"):
		fmt.Fprintf(b, "\x1b[1m\x1b[%dm\x1b[7m*DRYRUN*\x1b[0m \x1b[%dm[%s] \x1b[0m%s%s", gray, f.color, job, debugFlag, r.Message)
	default:
		fmt.Fprintf(b, "\x1b[%dm[%s] \x1b[0m%s%s", f.color, job, debugFlag, r.Message)
	}
}

func (f textFormatter) print(b *bytes.Buffer, r logging.Record) {
	job, _ := r.Attr("job")

	debugFlag := ""
	if r.Level == logging.LevelDebug {
		debugFlag = "[DEBUG] "
	}

	switch {
	case attrIsTrue(r, rawOutputField):
		fmt.Fprintf(b, "[%s]   | %s", job, r.Message)
	case attrIsTrue(r, "dryrun"):
		fmt.Fprintf(b, "*DRYRUN* [%s] %s%s", job, debugFlag, r.Message)
	default:
		fmt.Fprintf(b, "[%s] %s%s", job, debugFlag, r.Message)
	}
}

func (f textFormatter) isColored() bool {
	file, ok := f.w.(*os.File)
	isColored := ok && term.IsTerminal(int(file.Fd()))

	if force, ok := os.LookupEnv("CLICOLOR_FORCE"); ok && force != "0" {
		isColored = true
	} else if ok && force == "0" {
		isColored = false
	} else if os.Getenv("CLICOLOR") == "0" {
		isColored = false
	}

	return isColored
}

// maskSecrets hides this job's secrets in a value that reaches somewhere the log maskers cannot,
// such as a container name or a job summary. Masks added at runtime count, so a summary written
// after ::add-mask:: is covered too.
func (rc *RunContext) maskSecrets(value string) string {
	oldnew := rc.Config.maskers()
	for _, mask := range rc.Masks {
		oldnew = AppendSecretMasker(oldnew, mask)
	}
	return NewSecretReplacer(oldnew).Replace(value)
}

// maskers is every value this job's configuration says to hide, whatever the sink.
func (c *Config) maskers() []string {
	oldnew := AppendSecretMaskers(nil, c.Secrets)
	for _, mask := range c.ExtraMasks {
		oldnew = AppendSecretMasker(oldnew, mask)
	}
	return oldnew
}

// NewSecretReplacer masks the longest secret first. Replacer matches in argument order, so a
// secret that prefixes another would otherwise mask only that prefix and print the rest.
func NewSecretReplacer(oldnew []string) *strings.Replacer {
	pairs := make([][2]string, 0, len(oldnew)/2)
	for i := 0; i+1 < len(oldnew); i += 2 {
		pairs = append(pairs, [2]string{oldnew[i], oldnew[i+1]})
	}
	slices.SortFunc(pairs, func(a, b [2]string) int { return len(b[0]) - len(a[0]) })

	sorted := make([]string, 0, len(pairs)*2)
	for _, pair := range pairs {
		sorted = append(sorted, pair[0], pair[1])
	}
	return strings.NewReplacer(sorted...)
}