nats-server/logger/log.go

// Copyright 2012-2019 The NATS Authors
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
// http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.

// Package logger provides logging facilities for the NATS server
package logger

import (
	"fmt"
	"log"
	"os"
	"path/filepath"
	"sort"
	"strings"
	"sync"
	"sync/atomic"
	"time"
)

// Logger is the server logger
type Logger struct {
	sync.Mutex
	logger     *log.Logger
	debug      bool
	trace      bool
	infoLabel  string
	warnLabel  string
	errorLabel string
	fatalLabel string
	debugLabel string
	traceLabel string
	fl         *fileLogger
}

type LogOption interface {
	isLoggerOption()
}

// LogUTC controls whether timestamps in the log output should be UTC or local time.
type LogUTC bool

func (l LogUTC) isLoggerOption() {}

func logFlags(time bool, opts ...LogOption) int {
	flags := 0
	if time {
		flags = log.LstdFlags | log.Lmicroseconds
	}

	for _, opt := range opts {
		switch v := opt.(type) {
		case LogUTC:
			if time && bool(v) {
				flags |= log.LUTC
			}
		}
	}

	return flags
}

// NewStdLogger creates a logger with output directed to Stderr
func NewStdLogger(time, debug, trace, colors, pid bool, opts ...LogOption) *Logger {
	flags := logFlags(time, opts...)

	pre := ""
	if pid {
		pre = pidPrefix()
	}

	l := &Logger{
		logger: log.New(os.Stderr, pre, flags),
		debug:  debug,
		trace:  trace,
	}

	if colors {
		setColoredLabelFormats(l)
	} else {
		setPlainLabelFormats(l)
	}

	return l
}

// NewFileLogger creates a logger with output directed to a file
func NewFileLogger(filename string, time, debug, trace, pid bool, opts ...LogOption) *Logger {
	flags := logFlags(time, opts...)

	pre := ""
	if pid {
		pre = pidPrefix()
	}

	fl, err := newFileLogger(filename, pre, time)
	if err != nil {
		log.Fatalf("error opening file: %v", err)
		return nil
	}

	l := &Logger{
		logger: log.New(fl, pre, flags),
		debug:  debug,
		trace:  trace,
		fl:     fl,
	}
	fl.Lock()
	fl.l = l
	fl.Unlock()

	setPlainLabelFormats(l)
	return l
}

type writerAndCloser interface {
	Write(b []byte) (int, error)
	Close() error
	Name() string
}

type fileLogger struct {
	out       int64
	canRotate int32
	sync.Mutex
	l            *Logger
	f            writerAndCloser
	limit        int64
	olimit       int64
	pid          string
	time         bool
	closed       bool
	archiveLimit int
}

func newFileLogger(filename, pidPrefix string, time bool) (*fileLogger, error) {
	fileflags := os.O_WRONLY | os.O_APPEND | os.O_CREATE
	f, err := os.OpenFile(filename, fileflags, 0660)
	if err != nil {
		return nil, err
	}
	stats, err := f.Stat()
	if err != nil {
		f.Close()
		return nil, err
	}
	fl := &fileLogger{
		canRotate: 0,
		f:         f,
		out:       stats.Size(),
		pid:       pidPrefix,
		time:      time,
	}
	return fl, nil
}

func (l *fileLogger) setLimit(limit int64) {
	l.Lock()
	l.olimit, l.limit = limit, limit
	atomic.StoreInt32(&l.canRotate, 1)
	rotateNow := l.out > l.limit
	l.Unlock()
	if rotateNow {
		l.l.Noticef("Rotating logfile...")
	}
}

func (l *fileLogger) setArchiveLimit(limit int) {
	l.Lock()
	l.archiveLimit = limit
	l.Unlock()
}

func (l *fileLogger) logDirect(label, format string, v ...interface{}) int {
	var entrya = [256]byte{}
	var entry = entrya[:0]
	if l.pid != "" {
		entry = append(entry, l.pid...)
	}
	if l.time {
		now := time.Now()
		year, month, day := now.Date()
		hour, min, sec := now.Clock()
		microsec := now.Nanosecond() / 1000
		entry = append(entry, fmt.Sprintf("%04d/%02d/%02d %02d:%02d:%02d.%06d ",
			year, month, day, hour, min, sec, microsec)...)
	}
	entry = append(entry, label...)
	entry = append(entry, fmt.Sprintf(format, v...)...)
	entry = append(entry, '\r', '\n')
	l.f.Write(entry)
	return len(entry)
}

func (l *fileLogger) archivePurge(fname string) {
	// Evaluate number of saved backups for purge
	// l readlock held
	var backups []string
	lDir := filepath.Dir(fname)
	lBase := filepath.Base(fname)
	entries, err := os.ReadDir(lDir)
	if err != nil {
		l.logDirect(l.l.errorLabel, "Unable to read directory %q for log purge (%v), will attempt next rotation", lDir, err)
		return
	}
	for _, entry := range entries {
		if entry.IsDir() || entry.Name() == lBase || !strings.HasPrefix(entry.Name(), lBase) {
			continue
		}
		stamp, found := strings.CutPrefix(entry.Name(), fmt.Sprintf("%s%s", lBase, "."))
		if found {
			_, err := time.Parse("2006:01:02:15:04:05.999999999", strings.Replace(stamp, ".", ":", 5))
			if err == nil {
				backups = append(backups, entry.Name())
			}
		}
	}
	archives := len(backups)
	if archives > l.archiveLimit {
		// Oldest to latest
		sort.Slice(backups, func(i, j int) bool {
			return backups[i] < backups[j]
		})
		for i := 0; i < archives-l.archiveLimit; i++ {
			if err := os.Remove(fmt.Sprintf("%s%s%s", lDir, string(os.PathSeparator), backups[i])); err != nil {
				l.logDirect(l.l.errorLabel, "Unable to remove backup log file %q (%v), will attempt next rotation", backups[i], err)
				// Bail fast, we'll try again next rotation
				return
			}
			l.logDirect(l.l.infoLabel, "Removed archived log file %q", backups[i])
		}
	}
}

func (l *fileLogger) Write(b []byte) (int, error) {
	if atomic.LoadInt32(&l.canRotate) == 0 {
		n, err := l.f.Write(b)
		if err == nil {
			atomic.AddInt64(&l.out, int64(n))
		}
		return n, err
	}
	l.Lock()
	n, err := l.f.Write(b)
	if err == nil {
		l.out += int64(n)
		if l.out > l.limit {
			if err := l.f.Close(); err != nil {
				l.limit *= 2
				l.logDirect(l.l.errorLabel, "Unable to close logfile for rotation (%v), will attempt next rotation at size %v", err, l.limit)
				l.Unlock()
				return n, err
			}
			fname := l.f.Name()
			now := time.Now()
			bak := fmt.Sprintf("%s.%04d.%02d.%02d.%02d.%02d.%02d.%09d", fname,
				now.Year(), now.Month(), now.Day(), now.Hour(), now.Minute(),
				now.Second(), now.Nanosecond())
			os.Rename(fname, bak)
			fileflags := os.O_WRONLY | os.O_APPEND | os.O_CREATE
			f, err := os.OpenFile(fname, fileflags, 0660)
			if err != nil {
				l.Unlock()
				panic(fmt.Sprintf("Unable to re-open the logfile %q after rotation: %v", fname, err))
			}
			l.f = f
			n := l.logDirect(l.l.infoLabel, "Rotated log, backup saved as %q", bak)
			l.out = int64(n)
			l.limit = l.olimit
			if l.archiveLimit > 0 {
				l.archivePurge(fname)
			}
		}
	}
	l.Unlock()
	return n, err
}

func (l *fileLogger) close() error {
	l.Lock()
	if l.closed {
		l.Unlock()
		return nil
	}
	l.closed = true
	l.Unlock()
	return l.f.Close()
}

// SetSizeLimit sets the size of a logfile after which a backup
// is created with the file name + "year.month.day.hour.min.sec.nanosec"
// and the current log is truncated.
func (l *Logger) SetSizeLimit(limit int64) error {
	l.Lock()
	if l.fl == nil {
		l.Unlock()
		return fmt.Errorf("can set log size limit only for file logger")
	}
	fl := l.fl
	l.Unlock()
	fl.setLimit(limit)
	return nil
}

// SetArchiveLimit sets the number of archived log files that will be retained
func (l *Logger) SetArchiveLimit(limit int) error {
	l.Lock()
	if l.fl == nil {
		l.Unlock()
		return fmt.Errorf("can set log archive limit only for file logger")
	}
	fl := l.fl
	l.Unlock()
	fl.setArchiveLimit(limit)
	return nil
}

// NewTestLogger creates a logger with output directed to Stderr with a prefix.
// Useful for tracing in tests when multiple servers are in the same pid
func NewTestLogger(prefix string, time bool) *Logger {
	flags := 0
	if time {
		flags = log.LstdFlags | log.Lmicroseconds
	}
	l := &Logger{
		logger: log.New(os.Stderr, prefix, flags),
		debug:  true,
		trace:  true,
	}
	setColoredLabelFormats(l)
	return l
}

// Close implements the io.Closer interface to clean up
// resources in the server's logger implementation.
// Caller must ensure threadsafety.
func (l *Logger) Close() error {
	if l.fl != nil {
		return l.fl.close()
	}
	return nil
}

// Generate the pid prefix string
func pidPrefix() string {
	return fmt.Sprintf("[%d] ", os.Getpid())
}

func setPlainLabelFormats(l *Logger) {
	l.infoLabel = "[INF] "
	l.debugLabel = "[DBG] "
	l.warnLabel = "[WRN] "
	l.errorLabel = "[ERR] "
	l.fatalLabel = "[FTL] "
	l.traceLabel = "[TRC] "
}

func setColoredLabelFormats(l *Logger) {
	colorFormat := "[\x1b[%sm%s\x1b[0m] "
	l.infoLabel = fmt.Sprintf(colorFormat, "32", "INF")
	l.debugLabel = fmt.Sprintf(colorFormat, "36", "DBG")
	l.warnLabel = fmt.Sprintf(colorFormat, "0;93", "WRN")
	l.errorLabel = fmt.Sprintf(colorFormat, "31", "ERR")
	l.fatalLabel = fmt.Sprintf(colorFormat, "31", "FTL")
	l.traceLabel = fmt.Sprintf(colorFormat, "33", "TRC")
}

// Noticef logs a notice statement
func (l *Logger) Noticef(format string, v ...interface{}) {
	l.logger.Printf(l.infoLabel+format, v...)
}

// Warnf logs a notice statement
func (l *Logger) Warnf(format string, v ...interface{}) {
	l.logger.Printf(l.warnLabel+format, v...)
}

// Errorf logs an error statement
func (l *Logger) Errorf(format string, v ...interface{}) {
	l.logger.Printf(l.errorLabel+format, v...)
}

// Fatalf logs a fatal error
func (l *Logger) Fatalf(format string, v ...interface{}) {
	l.logger.Fatalf(l.fatalLabel+format, v...)
}

// Debugf logs a debug statement
func (l *Logger) Debugf(format string, v ...interface{}) {
	if l.debug {
		l.logger.Printf(l.debugLabel+format, v...)
	}
}

// Tracef logs a trace statement
func (l *Logger) Tracef(format string, v ...interface{}) {
	if l.trace {
		l.logger.Printf(l.traceLabel+format, v...)
	}
}