Improve logging, hook up ion with zap logger

2026-03-30 13:25:42 +00:00 · 2021-06-09 12:31:29 -07:00
parent 321ebab99b
commit abedc05ce5
9 changed files with 59 additions and 60 deletions
--- a/go.mod
+++ b/go.mod
@@ -16,7 +16,7 @@ require (
 	github.com/mitchellh/go-homedir v1.1.0
 	github.com/pion/ice/v2 v2.1.7
 	github.com/pion/interceptor v0.0.12
-	github.com/pion/ion-sfu v1.10.3
+	github.com/pion/ion-sfu v1.10.5
 	github.com/pion/logging v0.2.2
 	github.com/pion/rtcp v1.2.6
 	github.com/pion/rtp v1.6.5
--- a/go.sum
+++ b/go.sum
@@ -230,8 +230,6 @@ github.com/lightstep/lightstep-tracer-common/golang/gogo v0.0.0-20190605223551-b
 github.com/lightstep/lightstep-tracer-go v0.18.1/go.mod h1:jlF1pusYV4pidLvZ+XD0UBX0ZE6WURAspgAczcDHrL4=
 github.com/lithammer/shortuuid/v3 v3.0.6 h1:pr15YQyvhiSX/qPxncFtqk+v4xLEpOZObbsY/mKrcvA=
 github.com/lithammer/shortuuid/v3 v3.0.6/go.mod h1:vMk8ke37EmiewwolSO1NLW8vP4ZaKlRuDIi8tWWmAts=
-github.com/livekit/protocol v0.5.1 h1:RSX0sQM2+NK2kCHTg/n6wPf0d3qYskc611GYV3h+5+8=
-github.com/livekit/protocol v0.5.1/go.mod h1:wo3CGfYB7XMF8GoVJAfTARrYSP/ombi+sbLl6AYdKP0=
 github.com/livekit/protocol v0.5.2 h1:jYj+50gKBrtJ1q6iEVdHDruHVllA1xtOhiM1/YKqgMk=
 github.com/livekit/protocol v0.5.2/go.mod h1:wo3CGfYB7XMF8GoVJAfTARrYSP/ombi+sbLl6AYdKP0=
 github.com/lucsky/cuid v1.0.2 h1:z4XlExeoderxoPj2/dxKOyPxe9RCOu7yNq9/XWxIUMQ=
@@ -317,10 +315,8 @@ github.com/pion/ice/v2 v2.1.7 h1:FjgDfUNrVYTxQabJrkBX6ld12tvYbgzHenqPh3PJF6E=
 github.com/pion/ice/v2 v2.1.7/go.mod h1:kV4EODVD5ux2z8XncbLHIOtcXKtYXVgLVCeVqnpoeP0=
 github.com/pion/interceptor v0.0.12 h1:eC1iVneBIAQJEfaNAfDqAncJWhMDAnaXPRCJsltdokE=
 github.com/pion/interceptor v0.0.12/go.mod h1:qzeuWuD/ZXvPqOnxNcnhWfkCZ2e1kwwslicyyPnhoK4=
-github.com/pion/ion-log v1.0.1 h1:D3kW75Xa6mxxTSNUP0xoYeDa/C+hINdB04XjicJ7H0Q=
-github.com/pion/ion-log v1.0.1/go.mod h1:jwcla9KoB9bB/4FxYDSRJPcPYSLp5XiUUMnOLaqwl4E=
-github.com/pion/ion-sfu v1.10.3 h1:/kliY0pRoE87v+PF3k472u3fVDIBA+tK/xJSaltRUDQ=
-github.com/pion/ion-sfu v1.10.3/go.mod h1:xdD571H5V7bHaHg6gcg/mqnuXPIljv5In6U5O+576Xs=
+github.com/pion/ion-sfu v1.10.5 h1:8VH7IwEEyAr/RiHtAyM2vSmaP0oGKGVD3sFlFCVQ6cg=
+github.com/pion/ion-sfu v1.10.5/go.mod h1:Wx6b4qGUjvSo1kGl+/fHl0ZF48g2IJOjzUFg0yCo9qY=
 github.com/pion/logging v0.2.2 h1:M9+AIj/+pxNsDfAT64+MAVgJO0rsyLnoJKCqf//DoeY=
 github.com/pion/logging v0.2.2/go.mod h1:k0/tDVsRCX2Mb2ZEmTqNa7CWsQPc+YYCB7Q+5pahoms=
 github.com/pion/mdns v0.0.5 h1:Q2oj/JB3NqfzY9xGZ1fPzZzK7sDSD8rZPOvcIQ10BCw=
--- a/pkg/logger/logger.go
+++ b/pkg/logger/logger.go
@@ -1,21 +1,27 @@
 package logger

 import (
+	"github.com/go-logr/zapr"
+	"github.com/pion/ion-sfu/pkg/buffer"
+	"github.com/pion/ion-sfu/pkg/sfu"
 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
 )

 var (
-	logger *zap.SugaredLogger
+	wrappedLogger *zap.SugaredLogger
+	// zap logger
+	defaultLogger *zap.Logger
 )

-func getLogger() *zap.SugaredLogger {
-	if logger == nil {
+func GetLogger() *zap.Logger {
+	if defaultLogger == nil {
 		InitDevelopment("")
 	}
-	return logger
+	return defaultLogger
 }

+// valid levels: debug, info, warn, error, fatal, panic
 func initLogger(config zap.Config, level string) {
 	if level != "" {
 		lvl := zapcore.Level(0)
@@ -23,8 +29,14 @@ func initLogger(config zap.Config, level string) {
 			config.Level = zap.NewAtomicLevelAt(lvl)
 		}
 	}
+	// skip one level to remove this helper file
 	l, _ := config.Build(zap.AddCallerSkip(1))
-	logger = l.Sugar()
+	wrappedLogger = l.Sugar()
+
+	defaultLogger, _ = config.Build()
+	ionLogger := zapr.NewLogger(defaultLogger)
+	sfu.Logger = ionLogger
+	buffer.Logger = ionLogger
 }

 func InitProduction(logLevel string) {
@@ -36,42 +48,35 @@ func InitDevelopment(logLevel string) {
 }

 func Debugw(msg string, keysAndValues ...interface{}) {
-	if logger == nil {
+	if wrappedLogger == nil {
 		return
 	}
-	logger.Debugw(msg, keysAndValues...)
+	wrappedLogger.Debugw(msg, keysAndValues...)
 }

 func Infow(msg string, keysAndValues ...interface{}) {
-	if logger == nil {
+	if wrappedLogger == nil {
 		return
 	}
-	logger.Infow(msg, keysAndValues...)
+	wrappedLogger.Infow(msg, keysAndValues...)
 }

 func Warnw(msg string, err error, keysAndValues ...interface{}) {
-	if logger == nil {
+	if wrappedLogger == nil {
 		return
 	}
 	if err != nil {
 		keysAndValues = append([]interface{}{"error", err}, keysAndValues...)
 	}
-	logger.Warnw(msg, keysAndValues...)
+	wrappedLogger.Warnw(msg, keysAndValues...)
 }

 func Errorw(msg string, err error, keysAndValues ...interface{}) {
-	if logger == nil {
+	if wrappedLogger == nil {
 		return
 	}
 	if err != nil {
 		keysAndValues = append([]interface{}{"error", err}, keysAndValues...)
 	}
-	logger.Errorw(msg, keysAndValues...)
-}
-
-func Desugar() *zap.Logger {
-	if logger == nil {
-		getLogger()
-	}
-	return logger.Desugar()
+	wrappedLogger.Errorw(msg, keysAndValues...)
 }
--- a/pkg/rtc/config.go
+++ b/pkg/rtc/config.go
@@ -39,7 +39,8 @@ type ReceiverConfig struct {
 // number of packets to buffer up
 const readBufferSize = 50

-func NewWebRTCConfig(conf *config.RTCConfig, externalIP string) (*WebRTCConfig, error) {
+func NewWebRTCConfig(conf *config.Config, externalIP string) (*WebRTCConfig, error) {
+	rtcConf := conf.RTC
 	c := webrtc.Configuration{
 		SDPSemantics: webrtc.SDPSemanticsUnifiedPlan,
 	}
@@ -48,7 +49,7 @@ func NewWebRTCConfig(conf *config.RTCConfig, externalIP string) (*WebRTCConfig,
 	lkLogger := loggerFactory.NewLogger("livekit-mux")

 	iceUrls := make([]string, 0)
-	for _, stunServer := range conf.StunServers {
+	for _, stunServer := range rtcConf.StunServers {
 		iceUrls = append(iceUrls, fmt.Sprintf("stun:%s", stunServer))
 	}
 	c.ICEServers = []webrtc.ICEServer{
@@ -56,18 +57,18 @@ func NewWebRTCConfig(conf *config.RTCConfig, externalIP string) (*WebRTCConfig,
 			URLs: iceUrls,
 		},
 	}
-	if conf.UseExternalIP && externalIP != "" {
+	if rtcConf.UseExternalIP && externalIP != "" {
 		s.SetNAT1To1IPs([]string{externalIP}, webrtc.ICECandidateTypeHost)
 	}

-	if conf.PacketBufferSize == 0 {
-		conf.PacketBufferSize = 500
+	if rtcConf.PacketBufferSize == 0 {
+		rtcConf.PacketBufferSize = 500
 	}
-	bufferFactory := buffer.NewBufferFactory(conf.PacketBufferSize, zapr.NewLogger(logger.Desugar()))
+	bufferFactory := buffer.NewBufferFactory(rtcConf.PacketBufferSize, zapr.NewLogger(logger.GetLogger()))
 	s.BufferFactory = bufferFactory.GetOrNew

 	networkTypes := make([]webrtc.NetworkType, 0, 4)
-	if !conf.ForceTCP {
+	if !rtcConf.ForceTCP {
 		networkTypes = append(networkTypes,
 			webrtc.NetworkTypeUDP4,
 		)
@@ -76,9 +77,9 @@ func NewWebRTCConfig(conf *config.RTCConfig, externalIP string) (*WebRTCConfig,
 	var udpMux *ice.UDPMuxDefault
 	var udpMuxConn *net.UDPConn
 	var err error
-	if conf.UDPPort != 0 {
+	if rtcConf.UDPPort != 0 {
 		udpMuxConn, err = net.ListenUDP("udp4", &net.UDPAddr{
-			Port: int(conf.UDPPort),
+			Port: int(rtcConf.UDPPort),
 		})
 		if err != nil {
 			return nil, err
@@ -91,30 +92,32 @@ func NewWebRTCConfig(conf *config.RTCConfig, externalIP string) (*WebRTCConfig,
 			UDPConn: udpMuxConn,
 		})
 		s.SetICEUDPMux(udpMux)
-		val, err := checkUDPReadBuffer()
-		if err == nil {
-			if val < minUDPBufferSize {
-				logger.Warnw("UDP receive buffer is too small for a production set-up", nil,
-					"current", val,
-					"suggested", minUDPBufferSize)
-			} else {
-				logger.Debugw("UDP receive buffer size", "current", val)
+		if !conf.Development {
+			val, err := checkUDPReadBuffer()
+			if err == nil {
+				if val < minUDPBufferSize {
+					logger.Warnw("UDP receive buffer is too small for a production set-up", nil,
+						"current", val,
+						"suggested", minUDPBufferSize)
+				} else {
+					logger.Debugw("UDP receive buffer size", "current", val)
+				}
 			}
 		}
-	} else if conf.ICEPortRangeStart != 0 && conf.ICEPortRangeEnd != 0 {
-		if err := s.SetEphemeralUDPPortRange(uint16(conf.ICEPortRangeStart), uint16(conf.ICEPortRangeEnd)); err != nil {
+	} else if rtcConf.ICEPortRangeStart != 0 && rtcConf.ICEPortRangeEnd != 0 {
+		if err := s.SetEphemeralUDPPortRange(uint16(rtcConf.ICEPortRangeStart), uint16(rtcConf.ICEPortRangeEnd)); err != nil {
 			return nil, err
 		}
 	}

 	// use TCP mux when it's set
 	var tcpListener *net.TCPListener
-	if conf.TCPPort != 0 {
+	if rtcConf.TCPPort != 0 {
 		networkTypes = append(networkTypes,
 			webrtc.NetworkTypeTCP4,
 		)
 		tcpListener, err = net.ListenTCP("tcp4", &net.TCPAddr{
-			Port: int(conf.TCPPort),
+			Port: int(rtcConf.TCPPort),
 		})
 		if err != nil {
 			return nil, err
@@ -134,8 +137,8 @@ func NewWebRTCConfig(conf *config.RTCConfig, externalIP string) (*WebRTCConfig,
 		SettingEngine: s,
 		BufferFactory: bufferFactory,
 		Receiver: ReceiverConfig{
-			packetBufferSize: conf.PacketBufferSize,
-			maxBitrate:       conf.MaxBitrate,
+			packetBufferSize: rtcConf.PacketBufferSize,
+			maxBitrate:       rtcConf.MaxBitrate,
 		},
 		UDPMux:         udpMux,
 		UDPMuxConn:     udpMuxConn,
--- a/pkg/rtc/utils.go
+++ b/pkg/rtc/utils.go
@@ -122,7 +122,7 @@ func RecoverSilent() {

 func Recover() {
 	if r := recover(); r != nil {
-		log := logger.Desugar().WithOptions(zap.AddCallerSkip(1))
+		log := logger.GetLogger().WithOptions(zap.AddCallerSkip(1))
 		log.Error("recovered panic", zap.Any("error", r))
 	}
 }
--- a/pkg/service/roommanager.go
+++ b/pkg/service/roommanager.go
@@ -34,7 +34,7 @@ type RoomManager struct {
 }

 func NewRoomManager(rp RoomStore, router routing.Router, currentNode routing.LocalNode, selector routing.NodeSelector, conf *config.Config) (*RoomManager, error) {
-	rtcConf, err := rtc.NewWebRTCConfig(&conf.RTC, currentNode.Ip)
+	rtcConf, err := rtc.NewWebRTCConfig(conf, currentNode.Ip)
 	if err != nil {
 		return nil, err
 	}
--- a/pkg/service/rtcservice.go
+++ b/pkg/service/rtcservice.go
@@ -28,12 +28,7 @@ func NewRTCService(conf *config.Config, roomStore RoomStore, roomManager *RoomMa
 	s := &RTCService{
 		router:      router,
 		roomManager: roomManager,
-		upgrader:    websocket.Upgrader{
-			// increase buffer size to avoid errors such as
-			// read: connection reset by peer
-			// ReadBufferSize:  10240,
-			// WriteBufferSize: 10240,
-		},
+		upgrader:    websocket.Upgrader{},
 		currentNode: currentNode,
 		isDev:       conf.Development,
 	}
--- a/pkg/service/utils.go
+++ b/pkg/service/utils.go
@@ -22,7 +22,7 @@ var ServiceSet = wire.NewSet(
 )

 func handleError(w http.ResponseWriter, status int, msg string) {
-	l := logger.Desugar().WithOptions(zap.AddCallerSkip(1))
+	l := logger.GetLogger().WithOptions(zap.AddCallerSkip(1))
 	l.Debug("error handling request", zap.String("error", msg), zap.Int("status", status))
 	w.WriteHeader(status)
 	_, _ = w.Write([]byte(msg))
--- a/version/version.go
+++ b/version/version.go
@@ -1,3 +1,3 @@
 package version

-const Version = "0.9.8"
+const Version = "0.9.9"