Merge pull request #4102 from wkloucek/fix-logging-levels

fix logging levels and go micro default log level

changelog/unreleased/fix-logging-levels.md

@@ -0,0 +1,15 @@
+Bugfix: Fix logging levels
+
+We've fixed the configuration of logging levels. Previously it was not possible
+to configure a service with a more or less verbose log level then all other services
+when running in the supervised / runtime mode `ocis server`.
+
+For example `OCIS_LOG_LEVEL=error PROXY_LOG_LEVEL=debug ocis server` did not configure
+error logging for all services except the proxy, which should be on debug logging. This is now fixed
+and working properly.
+
+Also we fixed the format of go-micro logs to always default to error level.
+Previously this was only ensured in the supervised / runtime mode.
+
+https://github.com/owncloud/ocis/pull/4102
+https://github.com/owncloud/ocis/issues/4089

ocis-pkg/log/log.go

@@ -6,15 +6,37 @@ import (
 	"strings"
 	"time"
 
+	mzlog "github.com/go-micro/plugins/v4/logger/zerolog"
 	"github.com/owncloud/ocis/v2/ocis-pkg/shared"
-
 	"github.com/rs/zerolog"
 	"github.com/rs/zerolog/log"
-	mdlog "go-micro.dev/v4/debug/log"
-	mlog "go-micro.dev/v4/util/log"
-	"go-micro.dev/v4/util/ring"
+	"go-micro.dev/v4/logger"
 )
 
+func init() {
+	// this is ugly, but "logger.DefaultLogger" is a global variable and we need to set it _before_ anybody uses it
+	setMicroLogger()
+}
+
+// for logging reasons we don't want the same logging level on both oCIS and micro. As a framework builder we do not
+// want to expose to the end user the internal framework logs unless explicitly specified.
+func setMicroLogger() {
+	if os.Getenv("MICRO_LOG_LEVEL") == "" {
+		_ = os.Setenv("MICRO_LOG_LEVEL", "error")
+	}
+
+	lev, err := zerolog.ParseLevel(os.Getenv("MICRO_LOG_LEVEL"))
+	if err != nil {
+		lev = zerolog.ErrorLevel
+	}
+	logger.DefaultLogger = mzlog.NewLogger(
+		logger.WithLevel(logger.Level(lev)),
+		logger.WithFields(map[string]interface{}{
+			"system": "go-micro",
+		}),
+	)
+}
+
 // Logger simply wraps the zerolog logger.
 type Logger struct {
 	zerolog.Logger
@@ -35,31 +57,27 @@ func LoggerFromConfig(name string, cfg *shared.Log) Logger {
 func NewLogger(opts ...Option) Logger {
 	options := newOptions(opts...)
 
+	// set GlobalLevel() to the minimum value -1 = TraceLevel, so that only the services' log level matter
+	zerolog.SetGlobalLevel(zerolog.TraceLevel)
+
+	var logLevel zerolog.Level
 	switch strings.ToLower(options.Level) {
 	case "panic":
-		zerolog.SetGlobalLevel(zerolog.PanicLevel)
-		mlog.SetLevel(mlog.LevelFatal)
+		logLevel = zerolog.PanicLevel
 	case "fatal":
-		zerolog.SetGlobalLevel(zerolog.FatalLevel)
-		mlog.SetLevel(mlog.LevelFatal)
+		logLevel = zerolog.FatalLevel
 	case "error":
-		zerolog.SetGlobalLevel(zerolog.ErrorLevel)
-		mlog.SetLevel(mlog.LevelError)
+		logLevel = zerolog.ErrorLevel
 	case "warn":
-		zerolog.SetGlobalLevel(zerolog.WarnLevel)
-		mlog.SetLevel(mlog.LevelWarn)
+		logLevel = zerolog.WarnLevel
 	case "info":
-		zerolog.SetGlobalLevel(zerolog.InfoLevel)
-		mlog.SetLevel(mlog.LevelInfo)
+		logLevel = zerolog.InfoLevel
 	case "debug":
-		zerolog.SetGlobalLevel(zerolog.DebugLevel)
-		mlog.SetLevel(mlog.LevelDebug)
+		logLevel = zerolog.DebugLevel
 	case "trace":
-		zerolog.SetGlobalLevel(zerolog.DebugLevel)
-		mlog.SetLevel(mlog.LevelTrace)
+		logLevel = zerolog.TraceLevel
 	default:
-		zerolog.SetGlobalLevel(zerolog.ErrorLevel)
-		mlog.SetLevel(mlog.LevelError)
+		logLevel = zerolog.ErrorLevel
 	}
 
 	var logger zerolog.Logger
@@ -88,105 +106,9 @@ func NewLogger(opts ...Option) Logger {
 	logger = logger.With().
 		Str("service", options.Name).
 		Timestamp().
-		Logger()
-
-	mlog.SetLogger(
-		microZerolog{
-			logger: logger,
-			buffer: ring.New(mdlog.DefaultSize),
-		},
-	)
+		Logger().Level(logLevel)
 
 	return Logger{
 		logger,
 	}
 }
-
-// microZerolog implements the required interface for the go-micro logger.
-type microZerolog struct {
-	logger zerolog.Logger
-	buffer *ring.Buffer
-}
-
-func (mz microZerolog) Read(opts ...mdlog.ReadOption) ([]mdlog.Record, error) {
-	options := mdlog.ReadOptions{}
-	for _, o := range opts {
-		o(&options)
-	}
-
-	var entries []*ring.Entry
-
-	if !options.Since.IsZero() {
-		entries = mz.buffer.Since(options.Since)
-	}
-
-	if options.Count > 0 {
-		switch len(entries) > 0 {
-		case true:
-			if options.Count > len(entries) {
-				entries = entries[0:options.Count]
-			}
-		default:
-			entries = mz.buffer.Get(options.Count)
-		}
-	}
-
-	records := make([]mdlog.Record, 0, len(entries))
-	for _, entry := range entries {
-		record := mdlog.Record{
-			Timestamp: entry.Timestamp,
-			Message:   entry.Value,
-		}
-		records = append(records, record)
-	}
-
-	return records, nil
-}
-
-func (mz microZerolog) Write(record mdlog.Record) error {
-	level := record.Metadata["level"]
-	mz.log(level, fmt.Sprint(record.Message))
-	mz.buffer.Put(record.Message)
-	return nil
-}
-
-func (mz microZerolog) Stream() (mdlog.Stream, error) {
-	stream, stop := mz.buffer.Stream()
-	records := make(chan mdlog.Record, 128)
-	last10 := mz.buffer.Get(10)
-
-	go func() {
-		for _, entry := range last10 {
-			records <- mdlog.Record{
-				Timestamp: entry.Timestamp,
-				Message:   entry.Value,
-				Metadata:  make(map[string]string),
-			}
-		}
-		for entry := range stream {
-			records <- mdlog.Record{
-				Timestamp: entry.Timestamp,
-				Message:   entry.Value,
-				Metadata:  make(map[string]string),
-			}
-		}
-	}()
-	return &logStream{
-		stream: records,
-		stop:   stop,
-	}, nil
-}
-
-func (mz microZerolog) log(level string, msg string) {
-	l, err := zerolog.ParseLevel(level)
-	if err != nil {
-		l = zerolog.InfoLevel
-	}
-
-	mz.logger.WithLevel(l).Msg(msg)
-
-	// Invoke os.Exit because unlike zerolog.Logger.Fatal zerolog.Logger.WithLevel won't stop the execution.
-	if l == zerolog.FatalLevel {
-		os.Exit(1)
-	}
-}

ocis/pkg/runtime/service/service.go

@@ -15,7 +15,6 @@ import (
 
 	"github.com/owncloud/ocis/v2/ocis-pkg/shared"
 
-	mzlog "github.com/go-micro/plugins/v4/logger/zerolog"
 	"github.com/mohae/deepcopy"
 	"github.com/olekukonko/tablewriter"
 
@@ -50,9 +49,7 @@ import (
 	users "github.com/owncloud/ocis/v2/services/users/pkg/command"
 	web "github.com/owncloud/ocis/v2/services/web/pkg/command"
 	webdav "github.com/owncloud/ocis/v2/services/webdav/pkg/command"
-	"github.com/rs/zerolog"
 	"github.com/thejerf/suture/v4"
-	"go-micro.dev/v4/logger"
 )
 
 var (
@@ -157,8 +154,6 @@ func Start(o ...Option) error {
 	halt := make(chan os.Signal, 1)
 	signal.Notify(halt, syscall.SIGINT, syscall.SIGTERM, syscall.SIGQUIT, syscall.SIGHUP)
 
-	setMicroLogger()
-
 	// tolerance controls backoff cycles from the supervisor.
 	tolerance := 5
 	totalBackoff := 0
@@ -301,17 +296,3 @@ func trap(s *Service, halt chan os.Signal) {
 	s.Log.Debug().Str("service", "runtime service").Msgf("terminating with signal: %v", s)
 	os.Exit(0)
 }
-
-// for logging reasons we don't want the same logging level on both oCIS and micro. As a framework builder we do not
-// want to expose to the end user the internal framework logs unless explicitly specified.
-func setMicroLogger() {
-	if os.Getenv("MICRO_LOG_LEVEL") == "" {
-		_ = os.Setenv("MICRO_LOG_LEVEL", "error")
-	}
-
-	lev, err := zerolog.ParseLevel(os.Getenv("MICRO_LOG_LEVEL"))
-	if err != nil {
-		lev = zerolog.ErrorLevel
-	}
-	logger.DefaultLogger = mzlog.NewLogger(logger.WithLevel(logger.Level(lev)))
-}