log: add new log package that uses slog as global logger

.gitignore

@@ -3,6 +3,7 @@ catalog.json
 claim.json
 tnf-execution.log
 cnf-certification-test/tnf-execution.log
+cnf-certification-test/cnf-test-log
 .idea
 vendor
 *.test

Makefile

@@ -115,7 +115,7 @@ build-cnf-tests: results-html
 
 # build the CNF test binary for local development
 dev:
-	PATH=${PATH}:${GOBIN} go build -ldflags "${LINKER_TNF_RELEASE_FLAGS}" ./cnf-certification-test
+	PATH=${PATH}:${GOBIN} go build -ldflags "${LINKER_TNF_RELEASE_FLAGS}" -o ./cnf-certification-test
 
 # Builds the CNF test binary with debug flags
 build-cnf-tests-debug: results-html

cnf-certification-test/observability/suite.go

@@ -28,6 +28,7 @@ import (
 	pdbv1 "github.com/test-network-function/cnf-certification-test/cnf-certification-test/observability/pdb"
 
 	"github.com/test-network-function/cnf-certification-test/internal/clientsholder"
+	"github.com/test-network-function/cnf-certification-test/internal/log"
 	"github.com/test-network-function/cnf-certification-test/pkg/checksdb"
 	"github.com/test-network-function/cnf-certification-test/pkg/provider"
 	"github.com/test-network-function/cnf-certification-test/pkg/testhelper"
@@ -47,6 +48,7 @@ var (
 
 func LoadChecks() {
 	logrus.Debugf("Entering %s suite", common.ObservabilityTestKey)
+	log.Debug("Loading %s suite checks", common.ObservabilityTestKey)
 
 	checksGroup := checksdb.NewChecksGroup(common.ObservabilityTestKey).
 		WithBeforeEachFn(beforeEachFn)
@@ -124,20 +126,24 @@ func containerHasLoggingOutput(cut *provider.Container) (bool, error) {
 func testContainersLogging(check *checksdb.Check, env *provider.TestEnvironment) {
 	// Iterate through all the CUTs to get their log output. The TC checks that at least
 	// one log line is found.
+	check.LogInfo("Entering testContainersLogging")
 	var compliantObjects []*testhelper.ReportObject
 	var nonCompliantObjects []*testhelper.ReportObject
 	for _, cut := range env.Containers {
 		logrus.Info(fmt.Sprintf("Checking %s has some logging output", cut))
+		check.LogInfo("Container %s has some logging output", cut)
 		hasLoggingOutput, err := containerHasLoggingOutput(cut)
 		if err != nil {
 			tnf.Logf(logrus.ErrorLevel, "Failed to get %s log output: %s", cut, err)
+			check.LogError("Failed to get container %s log output, err: %v", cut, err)
 			nonCompliantObjects = append(nonCompliantObjects,
 				testhelper.NewContainerReportObject(cut.Namespace, cut.Podname, cut.Name, "Could not get log output", false))
 			continue
 		}
 
 		if !hasLoggingOutput {
 			tnf.Logf(logrus.ErrorLevel, "%s does not have any line of log to stderr/stdout", cut)
+			check.LogError("Container %s does not have any line of log to stderr/stdout", cut)
 			nonCompliantObjects = append(nonCompliantObjects,
 				testhelper.NewContainerReportObject(cut.Namespace, cut.Podname, cut.Name, "No log line to stderr/stdout found", false))
 		} else {

internal/log/custom_handler.go

@@ -0,0 +1,118 @@
+package log
+
+import (
+	"context"
+	"fmt"
+	"io"
+	"log/slog"
+	"path/filepath"
+	"runtime"
+	"sync"
+	"time"
+)
+
+type CustomHandler struct {
+	opts  Options
+	attrs []slog.Attr
+	mu    *sync.Mutex
+	out   io.Writer
+}
+
+type Options struct {
+	// Level reports the minimum level to log.
+	// Levels with lower levels are discarded.
+	// If nil, the Handler uses [slog.LevelInfo].
+	Level slog.Leveler
+}
+
+func NewCustomHandler(out io.Writer, opts *Options) *CustomHandler {
+	h := &CustomHandler{out: out, mu: &sync.Mutex{}}
+	if opts != nil {
+		h.opts = *opts
+	}
+	if h.opts.Level == nil {
+		h.opts.Level = slog.LevelInfo
+	}
+	return h
+}
+
+func (h *CustomHandler) Enabled(_ context.Context, level slog.Level) bool {
+	return level >= h.opts.Level.Level()
+}
+
+// The Handle method will write a log line with the following format:
+// LOG_LEVEL [TIME] [SOURCE_FILE] [CUSTOM_ATTRS] MSG
+//
+//nolint:gocritic // r param is heavy but defined in the slog.Handler interface
+func (h *CustomHandler) Handle(_ context.Context, r slog.Record) error {
+	var buf []byte
+	// Level
+	buf = h.appendAttr(buf, slog.Any(slog.LevelKey, r.Level))
+	// Time
+	if !r.Time.IsZero() {
+		buf = h.appendAttr(buf, slog.Time(slog.TimeKey, r.Time))
+	}
+	// Source
+	if r.PC != 0 {
+		fs := runtime.CallersFrames([]uintptr{r.PC})
+		f, _ := fs.Next()
+		buf = h.appendAttr(buf, slog.String(slog.SourceKey, fmt.Sprintf("%s: %d", filepath.Base(f.File), f.Line)))
+	}
+	// Attributes
+	for _, attr := range h.attrs {
+		buf = h.appendAttr(buf, attr)
+	}
+	// Message
+	buf = h.appendAttr(buf, slog.String(slog.MessageKey, r.Message))
+	buf = append(buf, "\n"...)
+	h.mu.Lock()
+	defer h.mu.Unlock()
+	_, err := h.out.Write(buf)
+	return err
+}
+
+// Not implemented. Returns the nil handler.
+func (h *CustomHandler) WithGroup(_ string) slog.Handler {
+	return nil
+}
+
+func (h *CustomHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
+	if len(attrs) == 0 {
+		return h
+	}
+
+	// Create a new handler with default attributes
+	h2 := *h
+	// A deep copy of the attributes is required
+	h2.attrs = make([]slog.Attr, len(h.attrs)+len(attrs))
+	copy(h2.attrs, h.attrs)
+	h2.attrs = append(h2.attrs, attrs...)
+
+	return &h2
+}
+
+func (h *CustomHandler) appendAttr(buf []byte, a slog.Attr) []byte {
+	// Resolve the Attr's value before doing anything else.
+	a.Value = a.Value.Resolve()
+	// Ignore empty Attrs.
+	if a.Equal(slog.Attr{}) {
+		return buf
+	}
+	switch a.Value.Kind() {
+	case slog.KindString:
+		if a.Key == slog.MessageKey {
+			buf = fmt.Appendf(buf, "%s ", a.Value.String())
+		} else {
+			buf = fmt.Appendf(buf, "[%s] ", a.Value.String())
+		}
+	case slog.KindTime:
+		buf = fmt.Appendf(buf, "[%s] ", a.Value.Time().Format(time.StampMilli))
+	default:
+		if a.Key == slog.LevelKey {
+			buf = fmt.Appendf(buf, "%-5s ", a.Value.String())
+		} else {
+			buf = fmt.Appendf(buf, "[%s: %s] ", a.Key, a.Value)
+		}
+	}
+	return buf
+}

internal/log/log.go

@@ -0,0 +1,59 @@
+package log
+
+import (
+	"context"
+	"fmt"
+	"io"
+	"log/slog"
+	"runtime"
+	"time"
+)
+
+type Logger struct {
+	*slog.Logger
+}
+
+var logger *slog.Logger
+
+func SetupLogger(logWriter io.Writer) {
+	opts := Options{
+		Level: slog.LevelDebug,
+	}
+	logger = slog.New(NewCustomHandler(logWriter, &opts))
+}
+
+func Debug(msg string, args ...any) {
+	Logf(logger, slog.LevelDebug, msg, args...)
+}
+
+func Info(msg string, args ...any) {
+	Logf(logger, slog.LevelInfo, msg, args...)
+}
+
+func Warn(msg string, args ...any) {
+	Logf(logger, slog.LevelWarn, msg, args...)
+}
+
+func Error(msg string, args ...any) {
+	Logf(logger, slog.LevelError, msg, args...)
+}
+
+func GetMultiLogger(w io.Writer) *slog.Logger {
+	opts := Options{
+		Level: slog.LevelDebug,
+	}
+	return slog.New(NewMultiHandler(logger.Handler(), NewCustomHandler(w, &opts)))
+}
+
+// The Logf function should be called inside a log wrapper function.
+// Otherwise the code source reference will be invalid.
+func Logf(logger *slog.Logger, level slog.Level, format string, args ...any) {
+	if !logger.Enabled(context.Background(), level) {
+		return
+	}
+	var pcs [1]uintptr
+	// skip [Callers, Log, LogWrapper]
+	runtime.Callers(3, pcs[:]) //nolint:gomnd
+	r := slog.NewRecord(time.Now(), level, fmt.Sprintf(format, args...), pcs[0])
+	_ = logger.Handler().Handle(context.Background(), r)
+}

internal/log/multi_handler.go

@@ -0,0 +1,53 @@
+package log
+
+import (
+	"context"
+	"log/slog"
+)
+
+type MultiHandler struct {
+	handlers []slog.Handler
+}
+
+func NewMultiHandler(handlers ...slog.Handler) *MultiHandler {
+	return &MultiHandler{
+		handlers: handlers,
+	}
+}
+
+func (h *MultiHandler) Enabled(ctx context.Context, level slog.Level) bool {
+	for i := range h.handlers {
+		if h.handlers[i].Enabled(ctx, level) {
+			return true
+		}
+	}
+
+	return false
+}
+
+//nolint:gocritic
+func (h *MultiHandler) Handle(ctx context.Context, r slog.Record) error {
+	for i := range h.handlers {
+		if err := h.handlers[i].Handle(ctx, r.Clone()); err != nil {
+			return err
+		}
+	}
+
+	return nil
+}
+
+func (h *MultiHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
+	handlersWithAttrs := make([]slog.Handler, len(h.handlers))
+	for i := range h.handlers {
+		handlersWithAttrs[i] = h.handlers[i].WithAttrs(attrs)
+	}
+	return NewMultiHandler(handlersWithAttrs...)
+}
+
+func (h *MultiHandler) WithGroup(name string) slog.Handler {
+	handlersWithGroup := make([]slog.Handler, len(h.handlers))
+	for i := range h.handlers {
+		handlersWithGroup[i] = h.handlers[i].WithGroup(name)
+	}
+	return NewMultiHandler(handlersWithGroup...)
+}