log.go

// Copyright (c) 2020 Gitpod GmbH. All rights reserved.
// Licensed under the GNU Affero General Public License (AGPL).
// See License.AGPL.txt in the project root for license information.

package log

import (
	"bufio"
	"bytes"
	"encoding/json"
	"fmt"
	"os"
	"path"
	"reflect"
	"runtime"
	"strings"
	"time"

	"github.com/sirupsen/logrus"
	log "github.com/sirupsen/logrus"

	"github.com/gitpod-io/gitpod/components/scrubber"
)

// Log is the application wide console logger
var Log = log.WithFields(log.Fields{})

func New() *log.Entry {
	return Log.Dup()
}

// setup default log level for components without initial invocation of log.Init.
func init() {
	logLevelFromEnv()
}

func logLevelFromEnv() {
	level := os.Getenv("LOG_LEVEL")
	if len(level) == 0 {
		level = "info"
	}

	newLevel, err := logrus.ParseLevel(level)
	if err != nil {
		Log.WithError(err).Errorf("cannot change log level to '%v'", level)
		return
	}

	Log.Logger.SetLevel(newLevel)
}

// Init initializes/configures the application-wide logger
func Init(service, version string, json, verbose bool) {
	Log = log.WithFields(ServiceContext(service, version))
	log.SetReportCaller(true)

	log.AddHook(NewLogHook(DefaultMetrics))

	if json {
		Log.Logger.SetFormatter(newGcpFormatter(false))
	} else {
		Log.Logger.SetFormatter(&logrus.TextFormatter{
			TimestampFormat: time.RFC3339Nano,
			FullTimestamp:   true,
		})
	}

	// update default log level
	logLevelFromEnv()

	if verbose {
		Log.Logger.SetLevel(log.DebugLevel)
	}
}

// gcpFormatter formats errors according to GCP rules, see
type gcpFormatter struct {
	log.JSONFormatter
	skipScrub bool
}

func newGcpFormatter(skipScrub bool) *gcpFormatter {
	return &gcpFormatter{
		skipScrub: skipScrub,
		JSONFormatter: log.JSONFormatter{
			FieldMap: log.FieldMap{
				log.FieldKeyMsg: "message",
			},
			CallerPrettyfier: func(f *runtime.Frame) (string, string) {
				s := strings.Split(f.Function, ".")
				funcName := s[len(s)-1]
				return funcName, fmt.Sprintf("%s:%d", path.Base(f.File), f.Line)
			},
			TimestampFormat: time.RFC3339Nano,
		},
	}
}

func (f *gcpFormatter) Format(entry *log.Entry) ([]byte, error) {
	hasError := false
	for k, v := range entry.Data {
		switch v := v.(type) {
		case error:
			// Otherwise errors are ignored by `encoding/json`
			// https://github.com/sirupsen/logrus/issues/137
			//
			// Print errors verbosely to get stack traces where available
			entry.Data[k] = fmt.Sprintf("%+v", v)
			hasError = true
		}
	}
	// map to gcp severity. See https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#LogSeverity
	var severity string = "INFO"
	switch entry.Level {
	case logrus.TraceLevel:
		severity = "DEBUG"
	case logrus.DebugLevel:
		severity = "DEBUG"
	case logrus.InfoLevel:
		severity = "INFO"
	case logrus.WarnLevel:
		severity = "WARNING"
	case logrus.ErrorLevel:
		severity = "ERROR"
	case logrus.FatalLevel:
		severity = "CRITICAL"
	case logrus.PanicLevel:
		severity = "EMERGENCY"
	}
	entry.Data["severity"] = severity
	if entry.Level <= log.WarnLevel && hasError {
		entry.Data["@type"] = "type.googleapis.com/google.devtools.clouderrorreporting.v1beta1.ReportedErrorEvent"
	}

	if f.skipScrub {
		return f.JSONFormatter.Format(entry)
	}

	for key, value := range entry.Data {
		if key == "error" || key == "severity" || key == "message" || key == "time" || key == "serviceContext" || key == "context" {
			continue
		}
		switch v := value.(type) {
		case string:
			entry.Data[key] = scrubber.Default.KeyValue(key, v)
		case int, int8, int16, int32, int64, uint, uint8, uint16, uint32, uint64, float32, float64, complex64, complex128:
			// no-op
		case bool:
			// no-op
		case time.Time, time.Duration:
			// no-op
		case scrubber.TrustedValue:
			// no-op
		default:
			// handling of named primitive types
			rv := reflect.ValueOf(value)
			switch rv.Kind() {
			case reflect.String:
				entry.Data[key] = scrubber.Default.KeyValue(key, rv.String())
			case reflect.Int, reflect.Int8, reflect.Int16, reflect.Int32, reflect.Int64,
				reflect.Uint, reflect.Uint8, reflect.Uint16, reflect.Uint32, reflect.Uint64,
				reflect.Float32, reflect.Float64, reflect.Complex64, reflect.Complex128:
				// no-op
			case reflect.Bool:
				// no-op
			default:
				// implement TrustedValue for custom types
				// make sure to use the scrubber.Default to scrub sensitive data
				entry.Data[key] = "[redacted:nested]"
			}
		}
	}
	return f.JSONFormatter.Format(entry)
}

// FromBuffer extracts the output generated by a command
// containing JSON output, parsing and writing underlying
// log data stream.
func FromBuffer(buf *bytes.Buffer, logger *logrus.Entry) {
	scanner := bufio.NewScanner(buf)
	for scanner.Scan() {
		b := bytes.Trim(scanner.Bytes(), "\x00")
		if len(b) == 0 {
			continue
		}

		var entry jsonEntry
		if err := json.Unmarshal(b, &entry); err != nil {
			if _, ok := err.(*json.SyntaxError); !ok {
				Log.Errorf("log.FromReader decoding JSON: %v", err)
			}

			continue
		}

		// common field name
		message := entry.Message
		if message == "" {
			// msg is defined in runc
			message = entry.Msg
		}

		// do not log empty messages
		if message == "" {
			continue
		}

		logEntry := logger.Dup()
		logEntry.Level = entry.Level
		logEntry.Message = message
		if entry.Time != nil {
			logEntry.Time = *entry.Time
		} else {
			logEntry.Time = time.Now()
		}

		// check the log of the entry is enable for the logger
		if logEntry.Logger.IsLevelEnabled(entry.Level) {
			b, err := logEntry.Bytes()
			if err != nil {
				Log.Errorf("Failed to write to custom log, %v", err)
			}
			if _, err := logEntry.Logger.Out.Write(b); err != nil {
				Log.Errorf("Failed to write to custom log, %v", err)
			}
		}
	}
}

type jsonEntry struct {
	Level   logrus.Level `json:"level,omitempty"`
	Message string       `json:"message,omitempty"`
	Msg     string       `json:"msg,omitempty"`
	Time    *time.Time   `json:"time,omitempty"`
}

// TrustedValueWrap is a simple wrapper that treats the entire value as trusted, which are not processed by the scrubber.
// During JSON marshal, only the Value itself will be processed, without including Wrap.
type TrustedValueWrap struct {
	Value any
}

func (TrustedValueWrap) IsTrustedValue() {}

func (t TrustedValueWrap) MarshalJSON() ([]byte, error) {
	return json.Marshal(t.Value)
}