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)))
-}