diff --git a/.gitignore b/.gitignore index fee10a1ed..18990b958 100644 --- a/.gitignore +++ b/.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 diff --git a/Makefile b/Makefile index a296c61fb..e4ea5492d 100644 --- a/Makefile +++ b/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 diff --git a/cnf-certification-test/observability/suite.go b/cnf-certification-test/observability/suite.go index 8b97321f8..f4728bd39 100644 --- a/cnf-certification-test/observability/suite.go +++ b/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,13 +126,16 @@ 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 @@ -138,6 +143,7 @@ func testContainersLogging(check *checksdb.Check, env *provider.TestEnvironment) 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 { diff --git a/internal/log/custom_handler.go b/internal/log/custom_handler.go new file mode 100644 index 000000000..1b5b82882 --- /dev/null +++ b/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 +} diff --git a/internal/log/log.go b/internal/log/log.go new file mode 100644 index 000000000..12be527ce --- /dev/null +++ b/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) +} diff --git a/internal/log/multi_handler.go b/internal/log/multi_handler.go new file mode 100644 index 000000000..92b8f0e03 --- /dev/null +++ b/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...) +} diff --git a/main.go b/main.go index bdc7e7f60..b9a4c1b97 100644 --- a/main.go +++ b/main.go @@ -19,11 +19,12 @@ package main import ( _ "embed" "flag" + "fmt" "os" "path/filepath" "time" - log "github.com/sirupsen/logrus" + "github.com/sirupsen/logrus" "github.com/test-network-function/cnf-certification-test/pkg/certsuite" "github.com/test-network-function/cnf-certification-test/pkg/loghelper" "github.com/test-network-function/cnf-certification-test/pkg/versions" @@ -31,6 +32,7 @@ import ( "github.com/test-network-function/cnf-certification-test/cnf-certification-test/webserver" "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/configuration" ) @@ -43,6 +45,8 @@ const ( TNFReportKey = "cnf-certification-test" extraInfoKey = "testsExtraInfo" noLabelsExpr = "none" + logFileName = "cnf-certsuite.log" + logFilePermissions = 0o644 ) const ( @@ -96,14 +100,14 @@ func init() { func setLogLevel() { params := configuration.GetTestParameters() - var logLevel, err = log.ParseLevel(params.LogLevel) + var logLevel, err = logrus.ParseLevel(params.LogLevel) if err != nil { - log.Error("TNF_LOG_LEVEL environment set with an invalid value, defaulting to DEBUG \n Valid values are: trace, debug, info, warn, error, fatal, panic") - logLevel = log.DebugLevel + logrus.Error("TNF_LOG_LEVEL environment set with an invalid value, defaulting to DEBUG \n Valid values are: trace, debug, info, warn, error, fatal, panic") + logLevel = logrus.DebugLevel } - log.Info("Log level set to: ", logLevel) - log.SetLevel(logLevel) + logrus.Info("Log level set to: ", logLevel) + logrus.SetLevel(logLevel) } func getK8sClientsConfigFileNames() []string { @@ -117,58 +121,79 @@ func getK8sClientsConfigFileNames() []string { kubeConfigFilePath := filepath.Join(params.Home, ".kube", "config") // Check if the kubeconfig path exists if _, err := os.Stat(kubeConfigFilePath); err == nil { - log.Infof("kubeconfig path %s is present", kubeConfigFilePath) + logrus.Infof("kubeconfig path %s is present", kubeConfigFilePath) // Only add the kubeconfig to the list of paths if it exists, since it is not added by the user fileNames = append(fileNames, kubeConfigFilePath) } else { - log.Infof("kubeconfig path %s is not present", kubeConfigFilePath) + logrus.Infof("kubeconfig path %s is not present", kubeConfigFilePath) } } return fileNames } +//nolint:funlen func main() { err := configuration.LoadEnvironmentVariables() if err != nil { - log.Fatalf("could not load the environment variables, error: %v", err) + fmt.Fprintf(os.Stderr, "could not load the environment variables, err: %v", err) + os.Exit(1) } // Set up logging params for logrus loghelper.SetLogFormat() setLogLevel() - log.Infof("TNF Version : %v", versions.GitVersion()) - log.Infof("Claim Format Version: %s", versions.ClaimFormatVersion) - log.Infof("Labels filter : %v", *labelsFlag) + // Set up logger + err = os.Remove(logFileName) + if err != nil && !os.IsNotExist(err) { + fmt.Fprintf(os.Stderr, "could not delete old log file, err: %v", err) + os.Exit(1) + } + + logFile, err := os.OpenFile(logFileName, os.O_RDWR|os.O_CREATE, logFilePermissions) + if err != nil { + fmt.Fprintf(os.Stderr, "could not create log file, err: %v", err) + os.Exit(1) + } + defer logFile.Close() + + log.SetupLogger(logFile) + log.Info("Log file: %s", logFileName) + + certsuite.LoadChecksDB() + + logrus.Infof("TNF Version : %v", versions.GitVersion()) + logrus.Infof("Claim Format Version: %s", versions.ClaimFormatVersion) + logrus.Infof("Labels filter : %v", *labelsFlag) certsuite.LoadChecksDB() if *listFlag { // ToDo: List all the available checks, filtered with --labels. - log.Errorf("Not implemented yet.") - os.Exit(1) + logrus.Errorf("Not implemented yet.") + os.Exit(1) //nolint:gocritic } // Diagnostic functions will run when no labels are provided. if *labelsFlag == noLabelsExpr { - log.Warnf("CNF Certification Suite will run in diagnostic mode so no test case will be launched.") + logrus.Warnf("CNF Certification Suite will run in diagnostic mode so no test case will be launched.") } var timeout time.Duration timeout, err = time.ParseDuration(*timeoutFlag) if err != nil { - log.Errorf("Failed to parse timeout flag %v: %v, using default timeout value %v", *timeoutFlag, err, timeoutFlagDefaultvalue) + logrus.Errorf("Failed to parse timeout flag %v: %v, using default timeout value %v", *timeoutFlag, err, timeoutFlagDefaultvalue) timeout = timeoutFlagDefaultvalue } // Set clientsholder singleton with the filenames from the env vars. - log.Infof("Output folder for the claim file: %s", *claimPath) + logrus.Infof("Output folder for the claim file: %s", *claimPath) if *serverModeFlag { - log.Info("Running CNF Certification Suite in web server mode.") + logrus.Info("Running CNF Certification Suite in web server mode.") webserver.StartServer(*claimPath) } else { - log.Info("Running CNF Certification Suite in stand-alone mode.") + logrus.Info("Running CNF Certification Suite in stand-alone mode.") _ = clientsholder.GetClientsHolder(getK8sClientsConfigFileNames()...) certsuite.Run(*labelsFlag, *claimPath, timeout) } diff --git a/pkg/checksdb/check.go b/pkg/checksdb/check.go index 5bc0572ea..1fa97af2b 100644 --- a/pkg/checksdb/check.go +++ b/pkg/checksdb/check.go @@ -2,10 +2,13 @@ package checksdb import ( "fmt" + "log/slog" + "strings" "sync" "time" "github.com/sirupsen/logrus" + "github.com/test-network-function/cnf-certification-test/internal/log" "github.com/test-network-function/cnf-certification-test/pkg/testhelper" ) @@ -45,17 +48,45 @@ type Check struct { CapturedOutput string FailureReason string + logger *slog.Logger + logArchive *strings.Builder + StartTime, EndTime time.Time Timeout time.Duration Error error } func NewCheck(id string, labels []string) *Check { - return &Check{ - ID: id, - Labels: labels, - Result: CheckResultPassed, + check := &Check{ + ID: id, + Labels: labels, + Result: CheckResultPassed, + logArchive: &strings.Builder{}, } + + check.logger = log.GetMultiLogger(check.logArchive).With("check", check.ID) + + return check +} + +func (check *Check) LogDebug(msg string, args ...any) { + log.Logf(check.logger, slog.LevelDebug, msg, args...) +} + +func (check *Check) LogInfo(msg string, args ...any) { + log.Logf(check.logger, slog.LevelInfo, msg, args...) +} + +func (check *Check) LogWarn(msg string, args ...any) { + log.Logf(check.logger, slog.LevelWarn, msg, args...) +} + +func (check *Check) LogError(msg string, args ...any) { + log.Logf(check.logger, slog.LevelError, msg, args...) +} + +func (check *Check) GetLogs() string { + return check.logArchive.String() } func (check *Check) WithCheckFn(checkFn func(check *Check) error) *Check {