webrtc logging.

internal/webrtc/cursor/image.go

@@ -13,7 +13,7 @@ import (
 
 func NewImage(desktop types.DesktopManager) *ImageCtx {
 	return &ImageCtx{
-		logger:    log.With().Str("module", "cursor-image").Logger(),
+		logger:    log.With().Str("module", "webrtc").Str("submodule", "cursor-image").Logger(),
 		desktop:   desktop,
 		listeners: map[uintptr]*func(entry *ImageEntry){},
 		cache:     map[uint64]*ImageEntry{},
@@ -50,10 +50,12 @@ func (manager *ImageCtx) Start() {
 			(*emit)(entry)
 		}
 	})
+
+	manager.logger.Info().Msg("starting")
 }
 
 func (manager *ImageCtx) Shutdown() {
-	manager.logger.Info().Msgf("shutting down")
+	manager.logger.Info().Msg("shutdown")
 
 	manager.emitMu.Lock()
 	for key := range manager.listeners {

internal/webrtc/cursor/position.go

@@ -12,7 +12,7 @@ import (
 
 func NewPosition(desktop types.DesktopManager) *PositionCtx {
 	return &PositionCtx{
-		logger:    log.With().Str("module", "cursor-position").Logger(),
+		logger:    log.With().Str("module", "webrtc").Str("submodule", "cursor-position").Logger(),
 		desktop:   desktop,
 		listeners: map[uintptr]*func(x, y int){},
 	}
@@ -26,7 +26,7 @@ type PositionCtx struct {
 }
 
 func (manager *PositionCtx) Shutdown() {
-	manager.logger.Info().Msgf("shutting down")
+	manager.logger.Info().Msg("shutdown")
 
 	manager.emitMu.Lock()
 	for key := range manager.listeners {

internal/webrtc/handler.go

@@ -5,6 +5,8 @@ import (
 	"encoding/binary"
 
 	"github.com/pion/webrtc/v3"
+
+	"demodesk/neko/internal/types"
 )
 
 const (
@@ -38,7 +40,10 @@ type PayloadKey struct {
 	Key uint32
 }
 
-func (manager *WebRTCManagerCtx) handle(msg webrtc.DataChannelMessage) error {
+func (manager *WebRTCManagerCtx) handle(msg webrtc.DataChannelMessage, session types.Session) error {
+	// add session id to logger context
+	logger := manager.logger.With().Str("session_id", session.ID()).Logger()
+
 	buffer := bytes.NewBuffer(msg.Data)
 	header := &PayloadHeader{}
 	hbytes := make([]byte, 3)
@@ -68,13 +73,11 @@ func (manager *WebRTCManagerCtx) handle(msg webrtc.DataChannelMessage) error {
 			return err
 		}
 
-		manager.logger.
+		manager.desktop.Scroll(int(payload.X), int(payload.Y))
-			Debug().
+		logger.Trace().
 			Int16("x", payload.X).
 			Int16("y", payload.Y).
 			Msg("scroll")
-
-		manager.desktop.Scroll(int(payload.X), int(payload.Y))
 	case OP_KEY_DOWN:
 		payload := &PayloadKey{}
 		if err := binary.Read(buffer, binary.BigEndian, payload); err != nil {
@@ -82,11 +85,10 @@ func (manager *WebRTCManagerCtx) handle(msg webrtc.DataChannelMessage) error {
 		}
 
 		if err := manager.desktop.KeyDown(payload.Key); err != nil {
-			manager.logger.Warn().Err(err).Msg("key down failed")
+			logger.Warn().Err(err).Uint32("key", payload.Key).Msg("key down failed")
-			break
+		} else {
+			logger.Trace().Uint32("key", payload.Key).Msg("key down")
 		}
-
-		manager.logger.Debug().Msgf("key down %d", payload.Key)
 	case OP_KEY_UP:
 		payload := &PayloadKey{}
 		if err := binary.Read(buffer, binary.BigEndian, payload); err != nil {
@@ -94,11 +96,10 @@ func (manager *WebRTCManagerCtx) handle(msg webrtc.DataChannelMessage) error {
 		}
 
 		if err := manager.desktop.KeyUp(payload.Key); err != nil {
-			manager.logger.Warn().Err(err).Msg("key up failed")
+			logger.Warn().Err(err).Uint32("key", payload.Key).Msg("key up failed")
-			break
+		} else {
+			logger.Trace().Uint32("key", payload.Key).Msg("key up")
 		}
-
-		manager.logger.Debug().Msgf("key up %d", payload.Key)
 	case OP_BTN_DOWN:
 		payload := &PayloadKey{}
 		if err := binary.Read(buffer, binary.BigEndian, payload); err != nil {
@@ -106,11 +107,10 @@ func (manager *WebRTCManagerCtx) handle(msg webrtc.DataChannelMessage) error {
 		}
 
 		if err := manager.desktop.ButtonDown(payload.Key); err != nil {
-			manager.logger.Warn().Err(err).Msg("button down failed")
+			logger.Warn().Err(err).Uint32("key", payload.Key).Msg("button down failed")
-			break
+		} else {
+			logger.Trace().Uint32("key", payload.Key).Msg("button down")
 		}
-
-		manager.logger.Debug().Msgf("button down %d", payload.Key)
 	case OP_BTN_UP:
 		payload := &PayloadKey{}
 		if err := binary.Read(buffer, binary.BigEndian, payload); err != nil {
@@ -118,11 +118,10 @@ func (manager *WebRTCManagerCtx) handle(msg webrtc.DataChannelMessage) error {
 		}
 
 		if err := manager.desktop.ButtonUp(payload.Key); err != nil {
-			manager.logger.Warn().Err(err).Msg("button up failed")
+			logger.Warn().Err(err).Uint32("key", payload.Key).Msg("button up failed")
-			break
+		} else {
+			logger.Trace().Uint32("key", payload.Key).Msg("button up")
 		}
-
-		manager.logger.Debug().Msgf("button up %d", payload.Key)
 	}
 
 	return nil

internal/webrtc/logger.go

@@ -81,6 +81,6 @@ func (l loggerFactory) NewLogger(subsystem string) logging.LeveledLogger {
 
 	return logger{
 		subsystem: subsystem,
-		logger:    l.logger.With().Str("subsystem", subsystem).Logger(),
+		logger:    l.logger.With().Str("submodule", "pion").Str("subsystem", subsystem).Logger(),
 	}
 }

internal/webrtc/manager.go

@@ -80,6 +80,8 @@ func (manager *WebRTCManagerCtx) Start() {
 		audio.RemoveListener(&audioListener)
 	}
 
+	manager.curImage.Start()
+
 	manager.logger.Info().
 		Bool("icelite", manager.config.ICELite).
 		Bool("icetrickle", manager.config.ICETrickle).
@@ -87,12 +89,10 @@ func (manager *WebRTCManagerCtx) Start() {
 		Str("nat1to1", strings.Join(manager.config.NAT1To1IPs, ",")).
 		Str("epr", fmt.Sprintf("%d-%d", manager.config.EphemeralMin, manager.config.EphemeralMax)).
 		Msg("webrtc starting")
-
-	manager.curImage.Start()
 }
 
 func (manager *WebRTCManagerCtx) Shutdown() error {
-	manager.logger.Info().Msgf("webrtc shutting down")
+	manager.logger.Info().Msg("webrtc shutdown")
 
 	manager.curImage.Shutdown()
 	manager.curPosition.Shutdown()
@@ -106,7 +106,9 @@ func (manager *WebRTCManagerCtx) ICEServers() []types.ICEServer {
 }
 
 func (manager *WebRTCManagerCtx) CreatePeer(session types.Session, videoID string) (*webrtc.SessionDescription, error) {
+	// add session id to logger context
 	logger := manager.logger.With().Str("session_id", session.ID()).Logger()
+	logger.Info().Msg("creating webrtc peer")
 
 	// Create MediaEngine
 	engine, err := manager.mediaEngine(videoID)
@@ -155,13 +157,13 @@ func (manager *WebRTCManagerCtx) CreatePeer(session types.Session, videoID strin
 	// create video track
 	videoStream, ok := manager.capture.Video(videoID)
 	if !ok {
-		manager.logger.Warn().Str("videoID", videoID).Msg("video stream not found")
+		logger.Warn().Str("video_id", videoID).Msg("video stream not found")
 		return nil, err
 	}
 
 	videoTrack, err := webrtc.NewTrackLocalStaticSample(videoStream.Codec().Capability, "video", "stream")
 	if err != nil {
-		manager.logger.Warn().Err(err).Msg("unable to create video track")
+		logger.Warn().Err(err).Msg("unable to create video track")
 		return nil, err
 	}
 
@@ -171,7 +173,7 @@ func (manager *WebRTCManagerCtx) CreatePeer(session types.Session, videoID strin
 				// The peerConnection has been closed.
 				return
 			}
-			manager.logger.Warn().Err(err).Msg("video pipeline failed to write")
+			logger.Warn().Err(err).Msg("video pipeline failed to write")
 		}
 	}
 
@@ -180,7 +182,7 @@ func (manager *WebRTCManagerCtx) CreatePeer(session types.Session, videoID strin
 	// should be stream started
 	if videoStream.ListenersCount() == 0 {
 		if err := videoStream.Start(); err != nil {
-			manager.logger.Warn().Err(err).Msg("unable to start video pipeline")
+			logger.Warn().Err(err).Msg("unable to start video pipeline")
 			return nil, err
 		}
 	}
@@ -239,6 +241,7 @@ func (manager *WebRTCManagerCtx) CreatePeer(session types.Session, videoID strin
 	}
 
 	peer := &WebRTCPeerCtx{
+		logger:      logger,
 		api:         api,
 		connection:  connection,
 		changeVideo: changeVideo,
@@ -248,7 +251,7 @@ func (manager *WebRTCManagerCtx) CreatePeer(session types.Session, videoID strin
 
 	cursorImage := func(entry *cursor.ImageEntry) {
 		if err := peer.SendCursorImage(entry.Cursor, entry.Image); err != nil {
-			manager.logger.Warn().Err(err).Msg("could not send cursor image")
+			logger.Warn().Err(err).Msg("could not send cursor image")
 		}
 	}
 
@@ -258,7 +261,7 @@ func (manager *WebRTCManagerCtx) CreatePeer(session types.Session, videoID strin
 		}
 
 		if err := peer.SendCursorPosition(x, y); err != nil {
-			manager.logger.Warn().Err(err).Msg("could not send cursor position")
+			logger.Warn().Err(err).Msg("could not send cursor position")
 		}
 	}
 
@@ -306,7 +309,7 @@ func (manager *WebRTCManagerCtx) CreatePeer(session types.Session, videoID strin
 		if err == nil {
 			cursorImage(entry)
 		} else {
-			manager.logger.Warn().Err(err).Msg("failed to get cursor image")
+			logger.Warn().Err(err).Msg("failed to get cursor image")
 		}
 
 		// send initial cursor position
@@ -324,7 +327,7 @@ func (manager *WebRTCManagerCtx) CreatePeer(session types.Session, videoID strin
 			return
 		}
 
-		if err = manager.handle(message); err != nil {
+		if err = manager.handle(message, session); err != nil {
 			logger.Warn().Err(err).Msg("data handle failed")
 		}
 	})

internal/webrtc/peer.go

@@ -4,10 +4,12 @@ import (
 	"sync"
 
 	"github.com/pion/webrtc/v3"
+	"github.com/rs/zerolog"
 )
 
 type WebRTCPeerCtx struct {
 	mu          sync.Mutex
+	logger      zerolog.Logger
 	api         *webrtc.API
 	connection  *webrtc.PeerConnection
 	dataChannel *webrtc.DataChannel
@@ -59,6 +61,7 @@ func (peer *WebRTCPeerCtx) SetVideoID(videoID string) error {
 	peer.mu.Lock()
 	defer peer.mu.Unlock()
 
+	peer.logger.Info().Str("video_id", videoID).Msg("change video id")
 	return peer.changeVideo(videoID)
 }