Improved logging configuration (#342)

cmd/server/main.go

@@ -59,6 +59,11 @@ func main() {
 				Usage:   "IP address of the current node, used to advertise to clients. Automatically determined by default",
 				EnvVars: []string{"NODE_IP"},
 			},
+			&cli.IntFlag{
+				Name:    "udp-port",
+				Usage:   "Single UDP port to use for WebRTC traffic",
+				EnvVars: []string{"UDP_PORT"},
+			},
 			&cli.StringFlag{
 				Name:    "redis-host",
 				Usage:   "host (incl. port) to redis server",
@@ -69,6 +74,17 @@ func main() {
 				Usage:   "password to redis",
 				EnvVars: []string{"REDIS_PASSWORD"},
 			},
+			&cli.StringFlag{
+				Name:    "turn-cert",
+				Usage:   "tls cert file for TURN server",
+				EnvVars: []string{"LIVEKIT_TURN_CERT"},
+			},
+			&cli.StringFlag{
+				Name:    "turn-key",
+				Usage:   "tls key file for TURN server",
+				EnvVars: []string{"LIVEKIT_TURN_KEY"},
+			},
+			// debugging flags
 			&cli.StringFlag{
 				Name:  "cpuprofile",
 				Usage: "write cpu profile to `file`",
@@ -81,16 +97,6 @@ func main() {
 				Name:  "dev",
 				Usage: "sets log-level to debug, and console formatter",
 			},
-			&cli.StringFlag{
-				Name:    "turn-cert",
-				Usage:   "tls cert file for TURN server",
-				EnvVars: []string{"LIVEKIT_TURN_CERT"},
-			},
-			&cli.StringFlag{
-				Name:    "turn-key",
-				Usage:   "tls key file for TURN server",
-				EnvVars: []string{"LIVEKIT_TURN_KEY"},
-			},
 		},
 		Action: startServer,
 		Commands: []*cli.Command{
@@ -160,11 +166,7 @@ func startServer(c *cli.Context) error {
 		return err
 	}
 
-	if conf.Development {
-		serverlogger.InitDevelopment(conf.LogLevel)
-	} else {
-		serverlogger.InitProduction(conf.LogLevel)
-	}
+	serverlogger.InitFromConfig(conf.Logging)
 
 	if cpuProfile != "" {
 		if f, err := os.Create(cpuProfile); err != nil {

config-sample.yaml

@@ -2,9 +2,6 @@
 # for production setups, this port should be placed behind a load balancer with TLS
 port: 7880
 
-# log level, valid values: debug, info, warning, error
-log_level: info
-
 # when redis is set, LiveKit will automatically operate in a fully distributed fashion
 # clients could connect to any node and be routed to the same room
 redis:
@@ -67,6 +64,19 @@ keys:
   key1: secret1
   key2: secret2
 
+# Logging config
+# logging:
+#   # log level, valid values: debug, info, warning, error
+#   level: info
+#   # log level for pion, default error
+#   pion_level: error
+#   # when set to true, emit json fields
+#   json: false
+#   # for production setups, enables sampling algorithm
+#   # https://github.com/uber-go/zap/blob/master/FAQ.md#why-sample-application-logs
+#   sample: false
+
+
 # Default room config
 # Each room created will inherit these settings. If rooms are created explicitly with CreateRoom, they will take
 # precedence over defaults

pkg/config/config.go

@@ -37,8 +37,10 @@ type Config struct {
 	KeyFile        string             `yaml:"key_file"`
 	Keys           map[string]string  `yaml:"keys"`
 	Region         string             `yaml:"region"`
-	LogLevel       string             `yaml:"log_level"`
-	Limit          LimitConfig        `yaml:"limit"`
+	// LogLevel is deprecated
+	LogLevel string        `yaml:"log_level"`
+	Logging  LoggingConfig `yaml:"logging"`
+	Limit    LimitConfig   `yaml:"limit"`
 
 	Development bool `yaml:"development"`
 }
@@ -112,6 +114,13 @@ type CodecSpec struct {
 	FmtpLine string `yaml:"fmtp_line"`
 }
 
+type LoggingConfig struct {
+	JSON      bool   `yaml:"json"`
+	Level     string `yaml:"level"`
+	Sample    bool   `yaml:"sample"`
+	PionLevel string `yaml:"pion_level"`
+}
+
 type TURNConfig struct {
 	Enabled     bool   `yaml:"enabled"`
 	Domain      string `yaml:"domain"`
@@ -187,6 +196,9 @@ func NewConfig(confString string, c *cli.Context) (*Config, error) {
 			},
 			EmptyTimeout: 5 * 60,
 		},
+		Logging: LoggingConfig{
+			PionLevel: "error",
+		},
 		TURN: TURNConfig{
 			Enabled: false,
 		},
@@ -244,6 +256,13 @@ func NewConfig(confString string, c *cli.Context) (*Config, error) {
 		conf.Limit.BytesPerSec = defaultLimitBytesPerSec
 	}
 
+	if conf.LogLevel != "" {
+		conf.Logging.Level = conf.LogLevel
+	}
+	if conf.Logging.Level == "" && conf.Development {
+		conf.Logging.Level = "debug"
+	}
+
 	return conf, nil
 }
 
@@ -281,6 +300,9 @@ func (conf *Config) updateFromCLI(c *cli.Context) error {
 	if c.IsSet("node-ip") {
 		conf.RTC.NodeIP = c.String("node-ip")
 	}
+	if c.IsSet("udp-port") {
+		conf.RTC.UDPPort = uint32(c.Int("udp-port"))
+	}
 
 	return nil
 }

pkg/logger/logadapter.go

@@ -1,47 +1,24 @@
-package rtc
+package serverlogger
 
 import (
 	"fmt"
 
 	"github.com/go-logr/logr"
-	"github.com/pion/logging"
+	"go.uber.org/zap/zapcore"
 )
 
-// implements webrtc.LoggerFactory
-type loggerFactory struct {
-	logger logr.Logger
-}
-
-func newLoggerFactory(logger logr.Logger) *loggerFactory {
-	if logger.GetSink() == nil {
-		return nil
-	}
-	return &loggerFactory{
-		logger: logger,
-	}
-}
-
-func (f *loggerFactory) NewLogger(scope string) logging.LeveledLogger {
-	return &logAdapter{
-		logger: f.logger.WithName(scope),
-		// treat info as debug
-		verbosity: 1,
-	}
-}
-
 // implements webrtc.LeveledLogger
 type logAdapter struct {
 	logger logr.Logger
-	// 0 - most verbose
-	verbosity int
+	level  zapcore.Level
 }
 
 func (l *logAdapter) Trace(msg string) {
-	l.Tracef(msg)
+	// ignore trace
 }
 
 func (l *logAdapter) Tracef(format string, args ...interface{}) {
-	l.logger.V(2 + l.verbosity).Info(fmt.Sprintf(format, args...))
+	// ignore trace
 }
 
 func (l *logAdapter) Debug(msg string) {
@@ -49,7 +26,10 @@ func (l *logAdapter) Debug(msg string) {
 }
 
 func (l *logAdapter) Debugf(format string, args ...interface{}) {
-	l.logger.V(1 + l.verbosity).Info(fmt.Sprintf(format, args...))
+	if l.level > zapcore.DebugLevel {
+		return
+	}
+	l.logger.V(1).Info(fmt.Sprintf(format, args...))
 }
 
 func (l *logAdapter) Info(msg string) {
@@ -57,7 +37,10 @@ func (l *logAdapter) Info(msg string) {
 }
 
 func (l *logAdapter) Infof(format string, args ...interface{}) {
-	l.logger.V(l.verbosity).Info(fmt.Sprintf(format, args...))
+	if l.level > zapcore.InfoLevel {
+		return
+	}
+	l.logger.Info(fmt.Sprintf(format, args...))
 }
 
 func (l *logAdapter) Warn(msg string) {
@@ -65,6 +48,9 @@ func (l *logAdapter) Warn(msg string) {
 }
 
 func (l *logAdapter) Warnf(format string, args ...interface{}) {
+	if l.level > zapcore.WarnLevel {
+		return
+	}
 	l.logger.Info(fmt.Sprintf(format, args...))
 }
 
@@ -73,5 +59,8 @@ func (l *logAdapter) Error(msg string) {
 }
 
 func (l *logAdapter) Errorf(format string, args ...interface{}) {
+	if l.level > zapcore.ErrorLevel {
+		return
+	}
 	l.logger.Error(nil, fmt.Sprintf(format, args...))
 }

pkg/logger/logger.go

@@ -3,6 +3,7 @@ package serverlogger
 import (
 	"github.com/go-logr/logr"
 	"github.com/go-logr/zapr"
+	"github.com/livekit/livekit-server/pkg/config"
 	"github.com/livekit/protocol/logger"
 	"github.com/pion/logging"
 	"go.uber.org/zap"
@@ -13,15 +14,29 @@ import (
 )
 
 var (
-	// pion/webrtc, pion/turn
-	defaultFactory logging.LoggerFactory
+	logConfig config.LoggingConfig
+	pionLevel zapcore.Level
 )
 
-func LoggerFactory() logging.LoggerFactory {
-	if defaultFactory == nil {
-		defaultFactory = logging.NewDefaultLoggerFactory()
+// implements webrtc.LoggerFactory
+type LoggerFactory struct {
+	logger logr.Logger
+}
+
+func NewLoggerFactory(logger logr.Logger) *LoggerFactory {
+	if logger.GetSink() == nil {
+		logger = logr.Discard()
+	}
+	return &LoggerFactory{
+		logger: logger,
+	}
+}
+
+func (f *LoggerFactory) NewLogger(scope string) logging.LeveledLogger {
+	return &logAdapter{
+		logger: f.logger.WithName(scope),
+		level:  pionLevel,
 	}
-	return defaultFactory
 }
 
 // Note: only pass in logr.Logger with default depth
@@ -31,24 +46,45 @@ func SetLogger(l logr.Logger) {
 	buffer.Logger = sfu.Logger
 }
 
-func InitProduction(logLevel string) {
-	initLogger(zap.NewProductionConfig(), logLevel)
-}
-
-func InitDevelopment(logLevel string) {
-	initLogger(zap.NewDevelopmentConfig(), logLevel)
+func InitFromConfig(config config.LoggingConfig) {
+	logConfig = config
+	lvl := parseLevel(config.Level)
+	pionLevel = parseLevel(config.PionLevel)
+	if lvl > pionLevel {
+		pionLevel = lvl
+	}
+	zapConfig := zap.Config{
+		Level:            zap.NewAtomicLevelAt(lvl),
+		Development:      false,
+		Encoding:         "console",
+		EncoderConfig:    zap.NewDevelopmentEncoderConfig(),
+		OutputPaths:      []string{"stderr"},
+		ErrorOutputPaths: []string{"stderr"},
+	}
+	if config.Sample {
+		zapConfig.Sampling = &zap.SamplingConfig{
+			Initial:    100,
+			Thereafter: 100,
+		}
+	}
+	if config.JSON {
+		zapConfig.Encoding = "json"
+		zapConfig.EncoderConfig = zap.NewProductionEncoderConfig()
+	}
+	initLogger(zapConfig)
 }
 
 // valid levels: debug, info, warn, error, fatal, panic
-func initLogger(config zap.Config, level string) {
-	if level != "" {
-		lvl := zapcore.Level(0)
-		if err := lvl.UnmarshalText([]byte(level)); err == nil {
-			config.Level = zap.NewAtomicLevelAt(lvl)
-		}
-	}
-
+func initLogger(config zap.Config) {
 	l, _ := config.Build()
 	zapLogger := zapr.NewLogger(l)
 	SetLogger(zapLogger)
 }
+
+func parseLevel(level string) zapcore.Level {
+	lvl := zapcore.InfoLevel
+	if level != "" {
+		_ = lvl.UnmarshalText([]byte(level))
+	}
+	return lvl
+}

pkg/rtc/config.go

@@ -4,12 +4,13 @@ import (
 	"errors"
 	"net"
 
+	logging "github.com/livekit/livekit-server/pkg/logger"
+	"github.com/livekit/protocol/logger"
 	"github.com/pion/ice/v2"
 	"github.com/pion/sdp/v3"
 	"github.com/pion/webrtc/v3"
 
 	"github.com/livekit/livekit-server/pkg/config"
-	serverlogger "github.com/livekit/livekit-server/pkg/logger"
 	"github.com/livekit/livekit-server/pkg/sfu/buffer"
 )
 
@@ -60,7 +61,7 @@ func NewWebRTCConfig(conf *config.Config, externalIP string) (*WebRTCConfig, err
 		SDPSemantics: webrtc.SDPSemanticsUnifiedPlan,
 	}
 	s := webrtc.SettingEngine{
-		LoggerFactory: serverlogger.LoggerFactory(),
+		LoggerFactory: logging.NewLoggerFactory(logger.GetLogger()),
 	}
 	s.SetLite(true)
 

pkg/rtc/room.go

@@ -215,8 +215,8 @@ func (r *Room) Join(participant types.LocalParticipant, opts *ParticipantOptions
 		"pID", participant.ID(),
 		"participant", participant.Identity(),
 		"protocol", participant.ProtocolVersion(),
-		"room", r.Room.Name,
-		"roomID", r.Room.Sid)
+		"roomID", r.Room.Sid,
+		"options", opts)
 
 	if participant.IsRecorder() && !r.Room.ActiveRecording {
 		r.Room.ActiveRecording = true

pkg/rtc/room_test.go

@@ -24,7 +24,7 @@ const (
 )
 
 func init() {
-	serverlogger.InitDevelopment("")
+	serverlogger.InitFromConfig(config.LoggingConfig{Level: "debug"})
 }
 
 var iceServersForRoom = []*livekit.ICEServer{{Urls: []string{"stun:stun.l.google.com:19302"}}}

pkg/rtc/transport.go

@@ -8,6 +8,7 @@ import (
 
 	"github.com/bep/debounce"
 	"github.com/go-logr/logr"
+	"github.com/livekit/livekit-server/pkg/logger"
 	"github.com/livekit/protocol/livekit"
 	"github.com/livekit/protocol/logger"
 	"github.com/pion/interceptor"
@@ -85,7 +86,7 @@ func newPeerConnection(params TransportParams) (*webrtc.PeerConnection, *webrtc.
 
 	se := params.Config.SettingEngine
 	se.DisableMediaEngineCopy(true)
-	lf := newLoggerFactory(logr.Logger(params.Logger))
+	lf := serverlogger.NewLoggerFactory(logr.Logger(params.Logger))
 	if lf != nil {
 		se.LoggerFactory = lf
 	}

pkg/service/turn.go

@@ -36,7 +36,7 @@ func NewTurnServer(conf *config.Config, authHandler turn.AuthHandler) (*turn.Ser
 	serverConfig := turn.ServerConfig{
 		Realm:         LivekitRealm,
 		AuthHandler:   authHandler,
-		LoggerFactory: logging.LoggerFactory(),
+		LoggerFactory: logging.NewLoggerFactory(logger.GetLogger()),
 	}
 	relayAddrGen := &turn.RelayAddressGeneratorPortRange{
 		RelayAddress: net.ParseIP(conf.RTC.NodeIP),

test/integration_helpers.go

@@ -43,7 +43,7 @@ var (
 )
 
 func init() {
-	serverlogger.InitDevelopment("")
+	serverlogger.InitFromConfig(config.LoggingConfig{Level: "debug"})
 }
 
 func setupSingleNodeTest(name string, roomName string) (*service.LivekitServer, func()) {