logs.go

package logs

import (
	"bytes"
	"encoding/json"
	"fmt"
	"github.com/MindscapeHQ/raygun4go"
	log "github.com/sirupsen/logrus"
	"gitlab.bob.co.za/bob-public-utils/bobgroup-go-utils/date_utils"
	"gitlab.bob.co.za/bob-public-utils/bobgroup-go-utils/errors"
	"gitlab.bob.co.za/bob-public-utils/bobgroup-go-utils/string_utils"
	"gitlab.bob.co.za/bob-public-utils/bobgroup-go-utils/utils"
	"io"
	"net/http"
	"net/url"
	"os"
	"reflect"
	"regexp"
	"runtime"
	"strings"

	"github.com/aws/aws-lambda-go/events"
)

const (
	FatalLevel = log.FatalLevel
	ErrorLevel = log.ErrorLevel
	WarnLevel  = log.WarnLevel
	InfoLevel  = log.InfoLevel
	DebugLevel = log.DebugLevel
)

type LogEntryWithLevel struct {
	// LogBuffer *bytes.Buffer
	LogEntry *log.Entry
	Message  interface{}
	LogLevel log.Level
}

var logger *log.Entry
var cachedLogEntries []LogEntryWithLevel

var apiRequest *events.APIGatewayProxyRequest
var currentRequestID *string
var isDebug = false
var storeLogsUntilTriggered = false
var disableLogging = false
var build string
var raygunClient *raygun4go.Client

// Password filtering
var passwordRegex = regexp.MustCompile(`(?i:\\?"password\\?"\s*:\s*\\?"(.*)\\?").*`)
var byteArrayRegex = regexp.MustCompile(`(?i:\\?"(?i:[\w]*)(?i:byte|data)(?i:[\w]*)\\?"\s*:\s*\[([\d\s,]+)*\])`)

func SanitiseLogs(logString string) string {
	var isValidJsonString bool
	isValidJsonString, logString = string_utils.PrettyJSON(logString)
	if !isValidJsonString {
		return logString
	}

	logString = MaskByteArraysInJsonString(logString)
	logString = MaskPasswordsInJsonString(logString)

	return logString
}

// MaskPasswordsInJsonString takes a string and sanitises all the instances of fields named password.
// E.g. "{"password": "xyz123"}" will become "{"password": "***"}"
func MaskPasswordsInJsonString(jsonString string) string {
	return string_utils.ReplaceAllRegexStringSubmatch(passwordRegex, jsonString, "***")
}

// MaskByteArraysInJsonString takes a string and truncates all the instances of number array fields have the word
// "byte" in the name. E.g. {"file_bytes": [123,68,103]} will become "{"file_bytes": [...]}"
func MaskByteArraysInJsonString(jsonString string) string {
	return string_utils.ReplaceAllRegexStringSubmatch(byteArrayRegex, jsonString, "...")
}

func SanitiseFields(fields map[string]interface{}) map[string]interface{} {
	sanitisedFields := make(map[string]interface{})

	// Check if each field is a string or string pointer, and sanitize them if they are
	for key, field := range fields {
		value := reflect.ValueOf(field)
		if value.Kind() == reflect.Ptr && value.IsValid() {
			pointerValue := value.Elem()
			if pointerValue.Kind() == reflect.String {
				sanitisedString := SanitiseLogs(pointerValue.String())
				sanitisedFields[key] = &sanitisedString
			} else {
				// Don't sanitise fields that are not strings
				sanitisedFields[key] = field
			}
		} else if value.Kind() == reflect.String {
			sanitisedFields[key] = SanitiseLogs(value.String())
		} else {
			// Don't sanitise fields that are not strings
			sanitisedFields[key] = field
		}
	}

	return sanitisedFields
}

func InitLogs(requestID *string, isDebugBuild bool, buildVersion string, request *events.APIGatewayProxyRequest, client *raygun4go.Client) {
	currentRequestID = requestID
	apiRequest = request
	isDebug = isDebugBuild
	build = buildVersion
	raygunClient = client
	disableLogging = false
	storeLogsUntilTriggered = false
	cachedLogEntries = []LogEntryWithLevel{}

	if isDebugBuild {
		log.SetReportCaller(true)
		log.SetFormatter(&log.TextFormatter{
			ForceColors:      true,
			PadLevelText:     true,
			DisableTimestamp: true,
			CallerPrettyfier: func(f *runtime.Frame) (string, string) {
				// Exclude the caller, will rather be added as a field
				return "", ""
			},
		})
	} else {
		log.SetReportCaller(true)
		log.SetFormatter(&CustomLogFormatter{})
	}
	log.SetLevel(LogLevel())

	val, exists := os.LookupEnv("DEBUGGING")
	if exists && val == "true" {
		log.SetLevel(log.TraceLevel)
		log.SetReportCaller(true)
	}

	logger = log.WithFields(log.Fields{
		"environment": getEnvironment(),
	})

	if requestID != nil {
		logger = log.WithFields(log.Fields{
			"request_id": *requestID,
		})
	}
}

func SetLevel(logLevel log.Level) {
	log.SetLevel(logLevel)
}

func LogLevel() log.Level {
	logLevelString := os.Getenv("LOG_LEVEL")

	logLevel := log.InfoLevel

	if logLevelString != "" {
		logLevelString = strings.ToLower(logLevelString)

		switch logLevelString {
		case "error":
			logLevel = log.ErrorLevel
		case "warn":
			logLevel = log.WarnLevel
		case "info":
			logLevel = log.InfoLevel
		case "debug":
			logLevel = log.DebugLevel
		}
		log.SetLevel(logLevel)
	}
	return logLevel
}

func getEnvironment() string {
	environment := os.Getenv("ENVIRONMENT")
	if environment == "" {
		environment = "dev"
		os.Setenv("ENVIRONMENT", "dev")
	}
	return environment
}

func getLogger() *log.Entry {
	if logger == nil {
		logger = log.WithFields(log.Fields{
			"environment": getEnvironment(),
		})
	}

	return logger
}

func InfoWithFields(fields map[string]interface{}, message interface{}) {
	if disableLogging {
		return
	}

	if reflect.TypeOf(message).Kind() == reflect.String {
		message = SanitiseLogs(message.(string))
	}
	sanitisedFields := SanitiseFields(fields)

	logEntry := getLogger().WithFields(sanitisedFields)
	if storeLogsUntilTriggered {
		storeLogEntry(logEntry, message, log.InfoLevel)
	} else {
		logEntry.Info(message)
	}
}

func Info(format string, a ...interface{}) {
	if disableLogging {
		return
	}

	message := SanitiseLogs(fmt.Sprintf(format, a...))

	logEntry := getLogger()
	if storeLogsUntilTriggered {
		storeLogEntry(logEntry, message, log.InfoLevel)
	} else {
		logEntry.Info(message)
	}
}

func ErrorWithFields(fields map[string]interface{}, err error) {
	if disableLogging {
		return
	}

	sanitisedFields := SanitiseFields(fields)
	sendRaygunError(sanitisedFields, err)

	logEntry := getLogger().WithFields(sanitisedFields)
	if storeLogsUntilTriggered {
		storeLogEntry(logEntry, err, log.ErrorLevel)
	} else {
		logEntry.Error(err)
	}
}

func ErrorWithMsg(message string, err error) {
	if disableLogging {
		return
	}

	if err == nil {
		err = errors.Error(message)
	}
	ErrorWithFields(map[string]interface{}{
		"message": message,
	}, err)
}

func ErrorMsg(message string) {
	if disableLogging {
		return
	}

	ErrorWithMsg(message, nil)
}

func Warn(format string, a ...interface{}) {
	if disableLogging {
		return
	}

	message := SanitiseLogs(fmt.Sprintf(format, a...))

	logEntry := getLogger()
	if storeLogsUntilTriggered {
		storeLogEntry(logEntry, message, log.WarnLevel)
	} else {
		logEntry.Warn(message)
	}
}

func WarnWithFields(fields map[string]interface{}, err error) {
	if disableLogging {
		return
	}

	sanitisedFields := SanitiseFields(fields)

	logEntry := getLogger().WithFields(sanitisedFields)
	if storeLogsUntilTriggered {
		storeLogEntry(logEntry, err, log.WarnLevel)
	} else {
		logEntry.Warn(err)
	}
}

func SQLDebugInfo(sql string) {
	if disableLogging {
		return
	}

	logEntry := getLogger().WithFields(map[string]interface{}{
		"sql": sql,
	})
	if storeLogsUntilTriggered {
		storeLogEntry(logEntry, "SQL query", log.DebugLevel)
	} else {
		logEntry.Debug("SQL query")
	}
}

func LogShipmentID(id int64) {
	if disableLogging {
		return
	}

	InfoWithFields(map[string]interface{}{
		"shipment_id": id,
	}, "Current-shipment-ID")
}

func LogRequestInfo(req events.APIGatewayProxyRequest, shouldExcludeBody bool, extraFields map[string]interface{}) {
	if disableLogging {
		return
	}

	fields := map[string]interface{}{
		"path":   req.Path,
		"method": req.HTTPMethod,
	}

	if !shouldExcludeBody {
		fields["body"] = req.Body
	}

	if req.QueryStringParameters != nil {
		fields["query"] = req.QueryStringParameters
	}

	if req.Headers["client-version"] != "" {
		fields["client_version"] = req.Headers["client-version"]
	}

	for k, v := range extraFields {
		if k != "" {
			fields[k] = v
		}
	}

	InfoWithFields(fields, "Req")
}

func LogResponseInfo(req events.APIGatewayProxyRequest, res events.APIGatewayProxyResponse, err error) {
	if disableLogging {
		return
	}

	fields := map[string]interface{}{
		"status_code": res.StatusCode,
	}

	if err != nil {
		fields["error"] = err
	}

	if req.HTTPMethod == http.MethodPost || req.HTTPMethod == http.MethodPatch || req.HTTPMethod == http.MethodPut {
		fields["body"] = res.Body
	}

	InfoWithFields(fields, "Res")
}

func LogApiAudit(fields log.Fields) {
	if disableLogging {
		return
	}

	logEntry := getLogger().WithFields(fields)
	if storeLogsUntilTriggered {
		storeLogEntry(logEntry, "api-audit-log", log.InfoLevel)
	} else {
		logEntry.Info("api-audit-log")
	}
}

func LogSQSEvent(event events.SQSEvent) {
	if disableLogging {
		return
	}

	sqsReducedEvents := []map[string]string{}

	for _, record := range event.Records {
		reducedEvent := map[string]string{
			"message_id": record.MessageId,
			"body":       record.Body,
			"sender":     record.Attributes["SenderId"],
		}

		for key, attribute := range record.MessageAttributes {
			if key != "Name" {
				reducedEvent[key] = *attribute.StringValue
			}
		}
		sqsReducedEvents = append(sqsReducedEvents, reducedEvent)
	}

	InfoWithFields(map[string]interface{}{
		"records": sqsReducedEvents,
	}, "")
}

func SetOutput(out io.Writer) {
	log.SetOutput(out)
}

func SetOutputToFile(file *os.File) {
	log.SetOutput(file)
}

func StoreLogsUntilTriggered(storeLogs bool) {
	storeLogsUntilTriggered = storeLogs
}

func DisableLogging() {
	disableLogging = true
}

func ClearInfo() {
	logger = nil
	cachedLogEntries = []LogEntryWithLevel{}
}

func sendRaygunError(fields map[string]interface{}, errToSend error) {
	if isDebug || raygunClient == nil {
		// Don't log raygun errors on debug
		return
	}

	if customErr, ok := errToSend.(*errors.CustomError); ok && customErr.ShouldBypassRaygun() {
		return
	}

	env := getEnvironment()

	tags := []string{env}
	raygunClient.Version(build)
	tags = append(tags, build)

	if apiRequest != nil {
		methodAndPath := apiRequest.HTTPMethod + ": " + apiRequest.Path
		tags = append(tags, methodAndPath)
		fields["body"] = apiRequest.Body
		fields["query"] = apiRequest.QueryStringParameters
		fields["identity"] = apiRequest.RequestContext.Identity
	}

	raygunClient.Tags(tags)
	if currentRequestID != nil {
		fields["request_id"] = currentRequestID
	}

	fields["env"] = env
	sanitisedFields := SanitiseFields(fields)
	raygunClient.CustomData(sanitisedFields)
	raygunClient.Request(fakeHttpRequest())

	if errToSend == nil {
		errToSend = errors.Error("")
	}
	err := raygunClient.SendError(errToSend)
	if err != nil {
		log.Println("Failed to send raygun error:", err.Error())
	}
}

func fakeHttpRequest() *http.Request {
	if apiRequest == nil {
		return nil
	}

	// Mask authorization header for raygun logs
	headers := utils.DeepCopy(apiRequest.MultiValueHeaders).(map[string][]string)
	if len(headers["authorization"]) != 0 {
		headers["authorization"] = []string{"***"}
	}
	if len(headers["Authorization"]) != 0 {
		headers["Authorization"] = []string{"***"}
	}

	requestURL := url.URL{
		Path: apiRequest.Path,
		Host: apiRequest.Headers["Host"],
	}
	request := http.Request{
		Method: apiRequest.HTTPMethod,
		URL:    &requestURL,
		Header: headers,
	}
	return &request
}

type CustomLogFormatter struct {
}

func (f *CustomLogFormatter) Format(entry *log.Entry) ([]byte, error) {
	data := map[string]any{}
	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
			data[k] = v.Error()
		default:
			data[k] = v
		}
	}
	if entry.Message != "" {
		data["msg"] = entry.Message
	}

	// Format body
	if value, ok := data["body"].(string); ok {
		cleanValue := strings.ReplaceAll(value, "\n", "")
		cleanValue = strings.ReplaceAll(cleanValue, "\"", "'")
		data["body"] = cleanValue
	}

	var b *bytes.Buffer
	if entry.Buffer != nil {
		b = entry.Buffer
	} else {
		b = &bytes.Buffer{}
	}

	encoder := json.NewEncoder(b)
	encoder.SetEscapeHTML(true)
	if err := encoder.Encode(data); err != nil {
		return nil, fmt.Errorf("failed to marshal fields to JSON, %w", err)
	}

	return b.Bytes(), nil
}

func storeLogEntry(logEntry *log.Entry, message interface{}, logLevel log.Level) {
	if logEntry != nil &&
		logEntry.Logger != nil &&
		logEntry.Logger.IsLevelEnabled(logLevel) {
		logWithTime := logEntry.WithField("log_time", date_utils.CurrentDate())

		cachedLogEntries = append(cachedLogEntries, LogEntryWithLevel{
			LogEntry: logWithTime,
			Message:  message,
			LogLevel: logLevel,
		})
	}
}

func LogAllStoredLogs() {
	log.SetOutput(os.Stderr)
	for _, cachedLogEntry := range cachedLogEntries {
		switch cachedLogEntry.LogLevel {
		case log.InfoLevel:
			cachedLogEntry.LogEntry.Info(cachedLogEntry.Message)
		case log.ErrorLevel:
			cachedLogEntry.LogEntry.Error(cachedLogEntry.Message)
		case log.WarnLevel:
			cachedLogEntry.LogEntry.Warn(cachedLogEntry.Message)
		case log.DebugLevel:
			cachedLogEntry.LogEntry.Debug(cachedLogEntry.Message)
		}
	}
}