Files
mesh-controller/vendor/github.com/nats-io/nats-server/v2/logger/log.go
T
jochen be92762969 Give every test a bus of its own, at the release the mesh runs (hq ADR 0237)
The live tests reached one shared bus and assert, read and remove the mesh's own objects by
their fixed names, so packages run in parallel deleted what each other read and the suite
passed only one package at a time; a red suite read as noise. internal/testbus starts a server
per test, linked in at the nats-server release go.mod pins, and a test holds that pin to the
catalogue's bus image and to the facts snapshot's bus when there is one, so the tests never run
a bus the mesh does not. The waiter test read a timing (the most connections held at one look)
and now reads the state it means (the fewest held across the wait). make check runs the packages
in parallel under the race detector, with a timeout.
2026-10-06 21:17:02 +02:00

406 lines
9.5 KiB
Go

// Copyright 2012-2025 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"
"strings"
"sync"
"sync/atomic"
"time"
)
// Default file permissions for log files.
const defaultLogPerms = os.FileMode(0640)
// 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
maxNumFiles 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, defaultLogPerms)
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) setMaxNumFiles(max int) {
l.Lock()
l.maxNumFiles = max
l.Unlock()
}
func (l *fileLogger) logDirect(label, format string, v ...any) 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) logPurge(fname string) {
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
}
if stamp, found := strings.CutPrefix(entry.Name(), fmt.Sprintf("%s%s", lBase, ".")); found {
_, err := time.Parse("2006:01:02:15:04:05.999999999", strings.Replace(stamp, ".", ":", 5))
if err == nil {
backups = append(backups, entry.Name())
}
}
}
currBackups := len(backups)
maxBackups := l.maxNumFiles - 1
if currBackups > maxBackups {
// backups sorted oldest to latest based on timestamped lexical filename (ReadDir)
for i := 0; i < currBackups-maxBackups; i++ {
if err := os.Remove(filepath.Join(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, "Purged 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, defaultLogPerms)
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.maxNumFiles > 0 {
l.logPurge(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
}
// SetMaxNumFiles sets the number of archived log files that will be retained
func (l *Logger) SetMaxNumFiles(max int) error {
l.Lock()
if l.fl == nil {
l.Unlock()
return fmt.Errorf("can set log max number of files only for file logger")
}
fl := l.fl
l.Unlock()
fl.setMaxNumFiles(max)
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 ...any) {
l.logger.Printf(l.infoLabel+format, v...)
}
// Warnf logs a notice statement
func (l *Logger) Warnf(format string, v ...any) {
l.logger.Printf(l.warnLabel+format, v...)
}
// Errorf logs an error statement
func (l *Logger) Errorf(format string, v ...any) {
l.logger.Printf(l.errorLabel+format, v...)
}
// Fatalf logs a fatal error
func (l *Logger) Fatalf(format string, v ...any) {
l.logger.Fatalf(l.fatalLabel+format, v...)
}
// Debugf logs a debug statement
func (l *Logger) Debugf(format string, v ...any) {
if l.debug {
l.logger.Printf(l.debugLabel+format, v...)
}
}
// Tracef logs a trace statement
func (l *Logger) Tracef(format string, v ...any) {
if l.trace {
l.logger.Printf(l.traceLabel+format, v...)
}
}