sftpgo/internal/logger/logger.go

// Copyright (C) 2019 Nicola Murino
//
// This program is free software: you can redistribute it and/or modify
// it under the terms of the GNU Affero General Public License as published
// by the Free Software Foundation, version 3.
//
// This program is distributed in the hope that it will be useful,
// but WITHOUT ANY WARRANTY; without even the implied warranty of
// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
// GNU Affero General Public License for more details.
//
// You should have received a copy of the GNU Affero General Public License
// along with this program. If not, see <https://www.gnu.org/licenses/>.

// Package logger provides logging capabilities.
// It is a wrapper around zerolog for logging and lumberjack for log rotation.
// Logs are written to the specified log file.
// Logging on the console is provided to print initialization info, errors and warnings.
// The package provides a request logger to log the HTTP requests for REST API too.
// The request logger uses chi.middleware.RequestLogger,
// chi.middleware.LogFormatter and chi.middleware.LogEntry to build a structured
// logger using zerolog
package logger

import (
	"errors"
	"fmt"
	"io/fs"
	"os"
	"path/filepath"
	"time"
	"unsafe"

	ftpserverlog "github.com/fclairamb/go-log"
	"github.com/rs/zerolog"
	lumberjack "gopkg.in/natefinch/lumberjack.v2"
)

const (
	dateFormat = "2006-01-02T15:04:05.000" // YYYY-MM-DDTHH:MM:SS.ZZZ
)

// LogLevel defines log levels.
type LogLevel uint8

// defines our own log levels, just in case we'll change logger in future
const (
	LevelDebug LogLevel = iota
	LevelInfo
	LevelWarn
	LevelError
)

var (
	logger        zerolog.Logger
	consoleLogger zerolog.Logger
	rollingLogger *lumberjack.Logger
)

func init() {
	zerolog.TimeFieldFormat = dateFormat
}

// GetLogger get the configured logger instance
func GetLogger() *zerolog.Logger {
	return &logger
}

// InitLogger configures the logger using the given parameters
func InitLogger(logFilePath string, logMaxSize int, logMaxBackups int, logMaxAge int, logCompress, logUTCTime bool,
	level zerolog.Level,
) {
	SetLogTime(logUTCTime)
	if isLogFilePathValid(logFilePath) {
		logDir := filepath.Dir(logFilePath)
		if _, err := os.Stat(logDir); errors.Is(err, fs.ErrNotExist) {
			err = os.MkdirAll(logDir, os.ModePerm)
			if err != nil {
				fmt.Printf("unable to create log dir %q: %v", logDir, err)
			}
		}
		rollingLogger = &lumberjack.Logger{
			Filename:   logFilePath,
			MaxSize:    logMaxSize,
			MaxBackups: logMaxBackups,
			MaxAge:     logMaxAge,
			Compress:   logCompress,
			LocalTime:  !logUTCTime,
		}
		logger = zerolog.New(rollingLogger)
		EnableConsoleLogger(level)
	} else {
		logger = zerolog.New(&logSyncWrapper{
			output: os.Stdout,
		})
		consoleLogger = zerolog.Nop()
	}
	logger = logger.Level(level)
}

// InitStdErrLogger configures the logger to write to stderr
func InitStdErrLogger(level zerolog.Level) {
	logger = zerolog.New(&logSyncWrapper{
		output: os.Stderr,
	}).Level(level)
	consoleLogger = zerolog.Nop()
}

// DisableLogger disable the main logger.
// ConsoleLogger will not be affected
func DisableLogger() {
	logger = zerolog.Nop()
	rollingLogger = nil
}

// EnableConsoleLogger enables the console logger
func EnableConsoleLogger(level zerolog.Level) {
	consoleOutput := zerolog.ConsoleWriter{
		Out:        os.Stdout,
		TimeFormat: dateFormat,
	}
	consoleLogger = zerolog.New(consoleOutput).With().Timestamp().Logger().Level(level)
}

// RotateLogFile closes the existing log file and immediately create a new one
func RotateLogFile() error {
	if rollingLogger != nil {
		return rollingLogger.Rotate()
	}
	return errors.New("logging to file is disabled")
}

// SetLogTime sets logging time related setting
func SetLogTime(utc bool) {
	if utc {
		zerolog.TimestampFunc = func() time.Time {
			return time.Now().UTC()
		}
	} else {
		zerolog.TimestampFunc = time.Now
	}
}

// Log logs at the specified level for the specified sender
func Log(level LogLevel, sender string, connectionID string, format string, v ...any) {
	var ev *zerolog.Event
	switch level {
	case LevelDebug:
		ev = logger.Debug()
	case LevelInfo:
		ev = logger.Info()
	case LevelWarn:
		ev = logger.Warn()
	default:
		ev = logger.Error()
	}
	ev.Timestamp().Str("sender", sender)
	if connectionID != "" {
		ev.Str("connection_id", connectionID)
	}
	ev.Msg(fmt.Sprintf(format, v...))
}

// Debug logs at debug level for the specified sender
func Debug(sender, connectionID, format string, v ...any) {
	Log(LevelDebug, sender, connectionID, format, v...)
}

// Info logs at info level for the specified sender
func Info(sender, connectionID, format string, v ...any) {
	Log(LevelInfo, sender, connectionID, format, v...)
}

// Warn logs at warn level for the specified sender
func Warn(sender, connectionID, format string, v ...any) {
	Log(LevelWarn, sender, connectionID, format, v...)
}

// Error logs at error level for the specified sender
func Error(sender, connectionID, format string, v ...any) {
	Log(LevelError, sender, connectionID, format, v...)
}

// DebugToConsole logs at debug level to stdout
func DebugToConsole(format string, v ...any) {
	consoleLogger.Debug().Msg(fmt.Sprintf(format, v...))
}

// InfoToConsole logs at info level to stdout
func InfoToConsole(format string, v ...any) {
	consoleLogger.Info().Msg(fmt.Sprintf(format, v...))
}

// WarnToConsole logs at info level to stdout
func WarnToConsole(format string, v ...any) {
	consoleLogger.Warn().Msg(fmt.Sprintf(format, v...))
}

// ErrorToConsole logs at error level to stdout
func ErrorToConsole(format string, v ...any) {
	consoleLogger.Error().Msg(fmt.Sprintf(format, v...))
}

// TransferLog logs uploads or downloads
func TransferLog(operation, path string, elapsed int64, size int64, user, connectionID, protocol, localAddr,
	remoteAddr, ftpMode string, err error,
) {
	var ev *zerolog.Event
	if err != nil {
		ev = logger.Error()
	} else {
		ev = logger.Info()
	}
	ev.
		Timestamp().
		Str("sender", operation).
		Str("local_addr", localAddr).
		Str("remote_addr", remoteAddr).
		Int64("elapsed_ms", elapsed).
		Int64("size_bytes", size).
		Str("username", user).
		Str("file_path", path).
		Str("connection_id", connectionID).
		Str("protocol", protocol)
	if ftpMode != "" {
		ev.Str("ftp_mode", ftpMode)
	}
	ev.AnErr("error", err).Send()
}

// CommandLog logs an SFTP/SCP/SSH command
func CommandLog(command, path, target, user, fileMode, connectionID, protocol string, uid, gid int, atime, mtime,
	sshCommand string, size int64, localAddr, remoteAddr string, elapsed int64) {
	logger.Info().
		Timestamp().
		Str("sender", command).
		Str("local_addr", localAddr).
		Str("remote_addr", remoteAddr).
		Str("username", user).
		Str("file_path", path).
		Str("target_path", target).
		Str("filemode", fileMode).
		Int("uid", uid).
		Int("gid", gid).
		Str("access_time", atime).
		Str("modification_time", mtime).
		Int64("size", size).
		Int64("elapsed", elapsed).
		Str("ssh_command", sshCommand).
		Str("connection_id", connectionID).
		Str("protocol", protocol).
		Send()
}

// ConnectionFailedLog logs failed attempts to initialize a connection.
// A connection can fail for an authentication error or other errors such as
// a client abort or a time out if the login does not happen in two minutes.
// These logs are useful for better integration with Fail2ban and similar tools.
func ConnectionFailedLog(user, ip, loginType, protocol, errorString string) {
	logger.Debug().
		Timestamp().
		Str("sender", "connection_failed").
		Str("client_ip", ip).
		Str("username", user).
		Str("login_type", loginType).
		Str("protocol", protocol).
		Str("error", errorString).
		Send()
}

func isLogFilePathValid(logFilePath string) bool {
	cleanInput := filepath.Clean(logFilePath)
	if cleanInput == "." || cleanInput == ".." {
		return false
	}
	return true
}

// StdLoggerWrapper is a wrapper for standard logger compatibility
type StdLoggerWrapper struct {
	Sender string
}

// Write implements the io.Writer interface. This is useful to set as a writer
// for the standard library log.
func (l *StdLoggerWrapper) Write(p []byte) (n int, err error) {
	n = len(p)
	if n > 0 && p[n-1] == '\n' {
		// Trim CR added by stdlog.
		p = p[0 : n-1]
	}

	Log(LevelError, l.Sender, "", "%s", bytesToString(p))
	return
}

// LeveledLogger is a logger that accepts a message string and a variadic number of key-value pairs
type LeveledLogger struct {
	Sender            string
	additionalKeyVals []any
}

func addKeysAndValues(ev *zerolog.Event, keysAndValues ...any) {
	kvLen := len(keysAndValues)
	if kvLen%2 != 0 {
		extra := keysAndValues[kvLen-1]
		keysAndValues = append(keysAndValues[:kvLen-1], "EXTRA_VALUE_AT_END", extra)
	}
	for i := 0; i < len(keysAndValues); i += 2 {
		key, val := keysAndValues[i], keysAndValues[i+1]
		if keyStr, ok := key.(string); ok && keyStr != "timestamp" {
			ev.Str(keyStr, fmt.Sprintf("%v", val))
		}
	}
}

// Error logs at error level for the specified sender
func (l *LeveledLogger) Error(msg string, keysAndValues ...any) {
	ev := logger.Error()
	ev.Timestamp().Str("sender", l.Sender)
	if len(l.additionalKeyVals) > 0 {
		addKeysAndValues(ev, l.additionalKeyVals...)
	}
	addKeysAndValues(ev, keysAndValues...)
	ev.Msg(msg)
}

// Info logs at info level for the specified sender
func (l *LeveledLogger) Info(msg string, keysAndValues ...any) {
	ev := logger.Info()
	ev.Timestamp().Str("sender", l.Sender)
	if len(l.additionalKeyVals) > 0 {
		addKeysAndValues(ev, l.additionalKeyVals...)
	}
	addKeysAndValues(ev, keysAndValues...)
	ev.Msg(msg)
}

// Debug logs at debug level for the specified sender
func (l *LeveledLogger) Debug(msg string, keysAndValues ...any) {
	ev := logger.Debug()
	ev.Timestamp().Str("sender", l.Sender)
	if len(l.additionalKeyVals) > 0 {
		addKeysAndValues(ev, l.additionalKeyVals...)
	}
	addKeysAndValues(ev, keysAndValues...)
	ev.Msg(msg)
}

// Warn logs at warn level for the specified sender
func (l *LeveledLogger) Warn(msg string, keysAndValues ...any) {
	ev := logger.Warn()
	ev.Timestamp().Str("sender", l.Sender)
	if len(l.additionalKeyVals) > 0 {
		addKeysAndValues(ev, l.additionalKeyVals...)
	}
	addKeysAndValues(ev, keysAndValues...)
	ev.Msg(msg)
}

// Panic logs the panic at error level for the specified sender
func (l *LeveledLogger) Panic(msg string, keysAndValues ...any) {
	l.Error(msg, keysAndValues...)
}

// With returns a LeveledLogger with additional context specific keyvals
func (l *LeveledLogger) With(keysAndValues ...any) ftpserverlog.Logger {
	return &LeveledLogger{
		Sender:            l.Sender,
		additionalKeyVals: append(l.additionalKeyVals, keysAndValues...),
	}
}

func bytesToString(b []byte) string {
	// unsafe.SliceData relies on cap whereas we want to rely on len
	if len(b) == 0 {
		return ""
	}
	// https://github.com/golang/go/blob/4ed358b57efdad9ed710be7f4fc51495a7620ce2/src/strings/builder.go#L41
	return unsafe.String(unsafe.SliceData(b), len(b))
}