Merge pull request #366 from Icinga/child-loggers

Child loggers

cmd/icingadb/main.go

@@ -3,6 +3,7 @@ package main
 import (
 	"context"
 	"github.com/icinga/icingadb/internal/command"
+	"github.com/icinga/icingadb/internal/logging"
 	"github.com/icinga/icingadb/pkg/com"
 	"github.com/icinga/icingadb/pkg/common"
 	"github.com/icinga/icingadb/pkg/contracts"
@@ -34,13 +35,23 @@ func main() {
 
 func run() int {
 	cmd := command.New()
+	logs, err := logging.NewLogging(
+		cmd.Config.Logging.Level,
+		cmd.Config.Logging.Options,
+	)
+	if err != nil {
+		utils.Fatal(errors.Wrap(err, "can't configure logging"))
+	}
 
-	logger := cmd.Logger
+	logger := logs.GetLogger()
 	defer logger.Sync()
 
 	logger.Info("Starting Icinga DB")
 
-	db := cmd.Database()
+	db, err := cmd.Database(logs.GetChildLogger("database"))
+	if err != nil {
+		logger.Fatalf("%+v", errors.Wrap(err, "can't create database connection pool from config"))
+	}
 	defer db.Close()
 	{
 		logger.Info("Connecting to database")
@@ -54,7 +65,10 @@ func run() int {
 		logger.Fatalf("%+v", err)
 	}
 
-	rc := cmd.Redis()
+	rc, err := cmd.Redis(logs.GetChildLogger("redis"))
+	if err != nil {
+		logger.Fatalf("%+v", errors.Wrap(err, "can't create Redis client from config"))
+	}
 	{
 		logger.Info("Connecting to Redis")
 		_, err := rc.Ping(context.Background()).Result()
@@ -66,9 +80,8 @@ func run() int {
 	ctx, cancelCtx := context.WithCancel(context.Background())
 	defer cancelCtx()
 
-	heartbeat := icingaredis.NewHeartbeat(ctx, rc, logger)
-	ha := icingadb.NewHA(ctx, db, heartbeat, logger)
-
+	heartbeat := icingaredis.NewHeartbeat(ctx, rc, logs.GetChildLogger("heartbeat"))
+	ha := icingadb.NewHA(ctx, db, heartbeat, logs.GetChildLogger("high-availability"))
 	// Closing ha on exit ensures that this instance retracts its heartbeat
 	// from the database so that another instance can take over immediately.
 	defer func() {
@@ -78,11 +91,10 @@ func run() int {
 		ha.Close(ctx)
 		cancelCtx()
 	}()
-
-	s := icingadb.NewSync(db, rc, logger)
-	hs := history.NewSync(db, rc, logger)
-	rt := icingadb.NewRuntimeUpdates(db, rc, logger)
-	ods := overdue.NewSync(db, rc, logger)
+	s := icingadb.NewSync(db, rc, logs.GetChildLogger("config-sync"))
+	hs := history.NewSync(db, rc, logs.GetChildLogger("history-sync"))
+	rt := icingadb.NewRuntimeUpdates(db, rc, logs.GetChildLogger("runtime-updates"))
+	ods := overdue.NewSync(db, rc, logs.GetChildLogger("overdue-sync"))
 
 	sig := make(chan os.Signal, 1)
 	signal.Notify(sig, os.Interrupt, syscall.SIGTERM, syscall.SIGHUP)
@@ -110,7 +122,7 @@ func run() int {
 							logger.Fatalf("%+v", err)
 						}
 
-						dump := icingadb.NewDumpSignals(rc, logger)
+						dump := icingadb.NewDumpSignals(rc, logs.GetChildLogger("dump-signals"))
 						g.Go(func() error {
 							logger.Info("Staring config dump signal handling")
 
@@ -193,7 +205,7 @@ func run() int {
 							com.ErrgroupReceive(g, dbErrs)
 
 							g.Go(func() error {
-								return s.ApplyDelta(ctx, icingadb.NewDelta(ctx, actualCvs, cvs1, cv, logger))
+								return s.ApplyDelta(ctx, icingadb.NewDelta(ctx, actualCvs, cvs1, cv, logs.GetChildLogger("config-sync")))
 							})
 
 							cvFlat := common.NewSyncSubject(v1.NewCustomvarFlat)
@@ -208,7 +220,7 @@ func run() int {
 							com.ErrgroupReceive(g, dbErrs)
 
 							g.Go(func() error {
-								return s.ApplyDelta(ctx, icingadb.NewDelta(ctx, actualCvFlats, cvFlats, cvFlat, logger))
+								return s.ApplyDelta(ctx, icingadb.NewDelta(ctx, actualCvFlats, cvFlats, cvFlat, logs.GetChildLogger("config-sync")))
 							})
 
 							return nil

config.yml.example

@@ -1,8 +1,28 @@
+# This is the configuration file for Icinga DB.
+
 database:
   host: icingadb
   port: 3306
   database: icingadb
   user: icingadb
   password: icingadb
+
 redis:
   address: redis:6380
+
+logging:
+  # Default logging level. Can be set to 'fatal', 'error', 'warning', 'info' or 'debug'.
+  # If not set, defaults to 'info'.
+  level:
+
+  # Map of component-logging level pairs to define a different log level than the default value for each component.
+  options:
+    database:
+    redis:
+    heartbeat:
+    high-availability:
+    config-sync:
+    history-sync:
+    runtime-updates:
+    overdue-sync:
+    dump-signals:

doc/03-Configuration.md

@@ -24,3 +24,26 @@ port                     | **Required.** Database port.
 database                 | **Required.** Database database.
 user                     | **Required.** Database username.
 password                 | **Required.** Database password.
+
+## Logging Configuration <a id="configuration-logging"></a>
+
+Configuration of the logging component used by Icinga DB.
+
+Option                   | Description
+-------------------------|-----------------------------------------------
+level                    | **Optional.** Specifies the default logging level. Can be set to `fatal`, `error`, `warning`, `info` or `debug`. Defaults to `info`.
+options                  | **Optional.** Map of component name to logging level in order to set a different logging level for each component instead of the default one. See [logging components](#logging-components) for details.
+
+### Logging Components <a id="logging-components"></a>
+
+Component                | Description
+-------------------------|-----------------------------------------------
+database                 | Database connection status and queries.
+redis                    | Redis connection status and queries.
+heartbeat                | Icinga heartbeats received through Redis.
+high-availability        | Manages responsibility of Icinga DB instances.
+config-sync              | Config object synchronization between Redis and MySQL.
+history-sync             | Synchronization of history entries from Redis to MySQL.
+runtime-updates          | Runtime updates of config objects after the initial config synchronization.
+overdue-sync             | Calculation and synchronization of the overdue status of checkables.
+dump-signals             | Dump signals received from Icinga.

internal/command/command.go

@@ -17,7 +17,6 @@ import (
 type Command struct {
 	Flags  *config.Flags
 	Config *config.Config
-	Logger *zap.SugaredLogger
 }
 
 // New creates and returns a new Command, parses CLI flags and YAML the config, and initializes the logger.
@@ -42,38 +41,18 @@ func New() *Command {
 		utils.Fatal(err)
 	}
 
-	loggerCfg := zap.NewDevelopmentConfig()
-	// Disable zap's automatic stack trace capturing, as we call errors.Wrap() before logging with "%+v".
-	loggerCfg.DisableStacktrace = true
-	logger, err := loggerCfg.Build()
-	if err != nil {
-		utils.Fatal(errors.Wrap(err, "can't create logger"))
-	}
-	sugar := logger.Sugar()
-
 	return &Command{
 		Flags:  flags,
 		Config: cfg,
-		Logger: sugar,
 	}
 }
 
 // Database creates and returns a new icingadb.DB connection from config.Config.
-func (c Command) Database() *icingadb.DB {
-	db, err := c.Config.Database.Open(c.Logger)
-	if err != nil {
-		c.Logger.Fatalf("%+v", errors.Wrap(err, "can't create database connection pool from config"))
-	}
-
-	return db
+func (c Command) Database(l *zap.SugaredLogger) (*icingadb.DB, error) {
+	return c.Config.Database.Open(l)
 }
 
 // Redis creates and returns a new icingaredis.Client connection from config.Config.
-func (c Command) Redis() *icingaredis.Client {
-	rc, err := c.Config.Redis.NewClient(c.Logger)
-	if err != nil {
-		c.Logger.Fatalf("%+v", errors.Wrap(err, "can't create Redis client from config"))
-	}
-
-	return rc
+func (c Command) Redis(l *zap.SugaredLogger) (*icingaredis.Client, error) {
+	return c.Config.Redis.NewClient(l)
 }

internal/logging/logging.go

@@ -0,0 +1,107 @@
+package logging
+
+import (
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+	"os"
+	"sync"
+)
+
+// Logging implements access to a default logger and named child loggers.
+// Log levels can be configured per named child via Options which, if not configured,
+// fall back on a default log level.
+type Logging struct {
+	level  zap.AtomicLevel
+	logger *zap.SugaredLogger
+	// encoder defines the zapcore.Encoder,
+	// which is used to create the default logger and the child loggers
+	encoder zapcore.Encoder
+	// syncer defines the zapcore.WriterSyncer,
+	// which is used to create the default logger and the child loggers
+	syncer  zapcore.WriteSyncer
+	mu      sync.Mutex
+	loggers map[string]*zap.SugaredLogger
+	options Options
+}
+
+// defaultEncConfig stores default zapcore.EncoderConfig for this package.
+var defaultEncConfig = zapcore.EncoderConfig{
+	TimeKey:        "ts",
+	LevelKey:       "level",
+	NameKey:        "logger",
+	CallerKey:      "caller",
+	MessageKey:     "msg",
+	StacktraceKey:  "stacktrace",
+	LineEnding:     zapcore.DefaultLineEnding,
+	EncodeLevel:    zapcore.CapitalLevelEncoder,
+	EncodeTime:     zapcore.ISO8601TimeEncoder,
+	EncodeDuration: zapcore.StringDurationEncoder,
+	EncodeCaller:   zapcore.ShortCallerEncoder,
+}
+
+// Options define child loggers with their desired log level.
+type Options map[string]zapcore.Level
+
+// NewLogging takes log level for default logger, output where log messages are written to
+// and options having log levels for named child loggers and initializes a new Logging.
+func NewLogging(level zapcore.Level, options Options) (*Logging, error) {
+	atom := zap.NewAtomicLevelAt(level)
+
+	encoder := zapcore.NewConsoleEncoder(defaultEncConfig)
+	syncer := zapcore.Lock(os.Stderr)
+
+	logger := zap.New(zapcore.NewCore(
+		encoder,
+		syncer,
+		atom,
+	))
+
+	return &Logging{
+			level:   atom,
+			logger:  logger.Sugar(),
+			encoder: encoder,
+			syncer:  syncer,
+			loggers: map[string]*zap.SugaredLogger{},
+			options: options,
+		},
+		nil
+}
+
+// GetChildLogger returns a named child logger.
+// Log levels for named child loggers are obtained from the logging options and, if not found,
+// set to the default log level.
+func (l *Logging) GetChildLogger(name string) *zap.SugaredLogger {
+	l.mu.Lock()
+	defer l.mu.Unlock()
+
+	if logger, ok := l.loggers[name]; ok {
+		return logger
+	}
+
+	if level, found := l.options[name]; found {
+		atom := zap.NewAtomicLevelAt(level)
+
+		logger := l.logger.Desugar().WithOptions(
+			zap.WrapCore(func(c zapcore.Core) zapcore.Core {
+				return zapcore.NewCore(
+					l.encoder,
+					l.syncer,
+					atom,
+				)
+			})).Sugar().Named(name)
+
+		l.loggers[name] = logger
+
+		return logger
+	}
+
+	logger := l.logger.Named(name)
+	l.loggers[name] = logger
+
+	return logger
+}
+
+// GetLogger returns the default logger.
+func (l *Logging) GetLogger() *zap.SugaredLogger {
+	return l.logger
+}

pkg/config/config.go

@@ -12,6 +12,7 @@ import (
 type Config struct {
 	Database Database `yaml:"database"`
 	Redis    Redis    `yaml:"redis"`
+	Logging  Logging  `yaml:"logging"`
 }
 
 // Validate checks constraints in the supplied configuration and returns an error if they are violated.

pkg/config/logging.go

@@ -0,0 +1,14 @@
+package config
+
+import (
+	"github.com/icinga/icingadb/internal/logging"
+	"go.uber.org/zap/zapcore"
+)
+
+// Logging defines Logger configuration.
+type Logging struct {
+	// zapcore.Level at 0 is for info level.
+	Level zapcore.Level `yaml:"level" default:"0"`
+
+	logging.Options `yaml:"options"`
+}