websockets logging.

internal/websocket/filechooserdialog.go

@@ -11,11 +11,11 @@ func (manager *WebSocketManagerCtx) fileChooserDialogEvents() {
 
 	// when dialog opens, everyone should be notified.
 	manager.desktop.OnFileChooserDialogOpened(func() {
-		manager.logger.Info().Msg("FileChooserDialog opened")
+		manager.logger.Info().Msg("file chooser dialog opened")
 
 		host := manager.sessions.GetHost()
 		if host == nil {
-			manager.logger.Warn().Msg("no host for FileChooserDialog found, closing")
+			manager.logger.Warn().Msg("no host for file chooser dialog found, closing")
 			go manager.desktop.CloseFileChooserDialog()
 			return
 		}
@@ -30,7 +30,7 @@ func (manager *WebSocketManagerCtx) fileChooserDialogEvents() {
 
 	// when dialog closes, everyone should be notified.
 	manager.desktop.OnFileChooserDialogClosed(func() {
-		manager.logger.Info().Msg("FileChooserDialog closed")
+		manager.logger.Info().Msg("file chooser dialog closed")
 
 		activeSession = nil
 
@@ -45,14 +45,16 @@ func (manager *WebSocketManagerCtx) fileChooserDialogEvents() {
 			return
 		}
 
+		logger := manager.logger.With().Str("session_id", session.ID()).Logger()
+		logger.Debug().Msg("sending file chooser dialog status to a new session")
+
 		if err := session.Send(message.SessionID{
 			Event: event.FILE_CHOOSER_DIALOG_OPENED,
 			ID:    activeSession.ID(),
 		}); err != nil {
-			manager.logger.Warn().
+			logger.Warn().Err(err).
-				Err(err).
+				Str("event", event.FILE_CHOOSER_DIALOG_OPENED).
-				Str("session_id", session.ID()).
+				Msg("could not send event")
-				Msgf("could not send event `%s` to session", event.FILE_CHOOSER_DIALOG_OPENED)
 		}
 	})
 
@@ -62,6 +64,7 @@ func (manager *WebSocketManagerCtx) fileChooserDialogEvents() {
 			return
 		}
 
+		manager.logger.Info().Msg("file chooser dialog owner left, closing")
 		manager.desktop.CloseFileChooserDialog()
 	})
 }

internal/websocket/handler/clipboard.go

@@ -6,13 +6,15 @@ import (
 )
 
 func (h *MessageHandlerCtx) clipboardSet(session types.Session, payload *message.ClipboardData) error {
+	logger := h.logger.With().Str("session_id", session.ID()).Logger()
+
 	if !session.Profile().CanAccessClipboard {
-		h.logger.Debug().Str("session_id", session.ID()).Msg("cannot access clipboard")
+		logger.Debug().Msg("cannot access clipboard")
 		return nil
 	}
 
 	if !session.IsHost() {
-		h.logger.Debug().Str("session_id", session.ID()).Msg("is not the host")
+		logger.Debug().Msg("is not the host")
 		return nil
 	}
 

internal/websocket/handler/control.go

@@ -7,13 +7,15 @@ import (
 )
 
 func (h *MessageHandlerCtx) controlRelease(session types.Session) error {
+	logger := h.logger.With().Str("session_id", session.ID()).Logger()
+
 	if !session.Profile().CanHost {
-		h.logger.Debug().Str("session_id", session.ID()).Msg("is not allowed to host")
+		logger.Debug().Msg("is not allowed to host")
 		return nil
 	}
 
 	if !session.IsHost() {
-		h.logger.Debug().Str("session_id", session.ID()).Msg("is not the host")
+		logger.Debug().Msg("is not the host")
 		return nil
 	}
 
@@ -24,13 +26,15 @@ func (h *MessageHandlerCtx) controlRelease(session types.Session) error {
 }
 
 func (h *MessageHandlerCtx) controlRequest(session types.Session) error {
+	logger := h.logger.With().Str("session_id", session.ID()).Logger()
+
 	if !session.Profile().CanHost {
-		h.logger.Debug().Str("session_id", session.ID()).Msg("is not allowed to host")
+		logger.Debug().Msg("is not allowed to host")
 		return nil
 	}
 
 	if session.IsHost() {
-		h.logger.Debug().Str("session_id", session.ID()).Msg("is already the host")
+		logger.Debug().Msg("is already the host")
 		return nil
 	}
 

internal/websocket/handler/handler.go

@@ -18,10 +18,8 @@ func New(
 	capture types.CaptureManager,
 	webrtc types.WebRTCManager,
 ) *MessageHandlerCtx {
-	logger := log.With().Str("module", "handler").Logger()
-
 	return &MessageHandlerCtx{
-		logger:   logger,
+		logger:   log.With().Str("module", "websocket").Str("submodule", "handler").Logger(),
 		sessions: sessions,
 		desktop:  desktop,
 		capture:  capture,
@@ -38,9 +36,11 @@ type MessageHandlerCtx struct {
 }
 
 func (h *MessageHandlerCtx) Message(session types.Session, raw []byte) bool {
+	logger := h.logger.With().Str("session_id", session.ID()).Logger()
+
 	header := message.Message{}
 	if err := json.Unmarshal(raw, &header); err != nil {
-		h.logger.Error().Err(err).Msg("message parsing has failed")
+		logger.Error().Err(err).Msg("message parsing has failed")
 		return false
 	}
 
@@ -114,12 +114,12 @@ func (h *MessageHandlerCtx) Message(session types.Session, raw []byte) bool {
 			return h.sendBroadcast(session, payload)
 		})
 	default:
-		h.logger.Warn().Str("event", header.Event).Msg("unknown message event")
+		logger.Warn().Str("event", header.Event).Msg("unknown message event")
 		return false
 	}
 
 	if err != nil {
-		h.logger.Error().Err(err).Str("event", header.Event).Msg("message handler has failed")
+		logger.Error().Err(err).Str("event", header.Event).Msg("message handler has failed")
 	}
 
 	return true

internal/websocket/handler/keyboard.go

@@ -6,8 +6,10 @@ import (
 )
 
 func (h *MessageHandlerCtx) keyboardMap(session types.Session, payload *message.KeyboardMap) error {
+	logger := h.logger.With().Str("session_id", session.ID()).Logger()
+
 	if !session.IsHost() {
-		h.logger.Debug().Str("session_id", session.ID()).Msg("is not the host")
+		logger.Debug().Msg("is not the host")
 		return nil
 	}
 
@@ -18,8 +20,10 @@ func (h *MessageHandlerCtx) keyboardMap(session types.Session, payload *message.
 }
 
 func (h *MessageHandlerCtx) keyboardModifiers(session types.Session, payload *message.KeyboardModifiers) error {
+	logger := h.logger.With().Str("session_id", session.ID()).Logger()
+
 	if !session.IsHost() {
-		h.logger.Debug().Str("session_id", session.ID()).Msg("is not the host")
+		logger.Debug().Msg("is not the host")
 		return nil
 	}
 

internal/websocket/handler/screen.go

@@ -7,8 +7,10 @@ import (
 )
 
 func (h *MessageHandlerCtx) screenSet(session types.Session, payload *message.ScreenSize) error {
+	logger := h.logger.With().Str("session_id", session.ID()).Logger()
+
 	if !session.Profile().IsAdmin {
-		h.logger.Debug().Str("session_id", session.ID()).Msg("is not the admin")
+		logger.Debug().Msg("is not the admin")
 		return nil
 	}
 

internal/websocket/handler/send.go

@@ -7,9 +7,11 @@ import (
 )
 
 func (h *MessageHandlerCtx) sendUnicast(session types.Session, payload *message.SendUnicast) error {
+	logger := h.logger.With().Str("session_id", session.ID()).Logger()
+
 	receiver, ok := h.sessions.Get(payload.Receiver)
 	if !ok {
-		h.logger.Debug().Str("session_id", session.ID()).Msg("receiver session ID not found")
+		logger.Debug().Msg("receiver session ID not found")
 		return nil
 	}
 

internal/websocket/handler/signal.go

@@ -7,8 +7,10 @@ import (
 )
 
 func (h *MessageHandlerCtx) signalRequest(session types.Session, payload *message.SignalVideo) error {
+	logger := h.logger.With().Str("session_id", session.ID()).Logger()
+
 	if !session.Profile().CanWatch {
-		h.logger.Debug().Str("session_id", session.ID()).Msg("not allowed to watch")
+		logger.Debug().Msg("not allowed to watch")
 		return nil
 	}
 
@@ -33,9 +35,11 @@ func (h *MessageHandlerCtx) signalRequest(session types.Session, payload *messag
 }
 
 func (h *MessageHandlerCtx) signalRestart(session types.Session) error {
+	logger := h.logger.With().Str("session_id", session.ID()).Logger()
+
 	peer := session.GetWebRTCPeer()
 	if peer == nil {
-		h.logger.Debug().Str("session_id", session.ID()).Msg("webRTC peer does not exist")
+		logger.Debug().Msg("webRTC peer does not exist")
 		return nil
 	}
 
@@ -52,9 +56,11 @@ func (h *MessageHandlerCtx) signalRestart(session types.Session) error {
 }
 
 func (h *MessageHandlerCtx) signalAnswer(session types.Session, payload *message.SignalAnswer) error {
+	logger := h.logger.With().Str("session_id", session.ID()).Logger()
+
 	peer := session.GetWebRTCPeer()
 	if peer == nil {
-		h.logger.Debug().Str("session_id", session.ID()).Msg("webRTC peer does not exist")
+		logger.Debug().Msg("webRTC peer does not exist")
 		return nil
 	}
 
@@ -62,9 +68,11 @@ func (h *MessageHandlerCtx) signalAnswer(session types.Session, payload *message
 }
 
 func (h *MessageHandlerCtx) signalCandidate(session types.Session, payload *message.SignalCandidate) error {
+	logger := h.logger.With().Str("session_id", session.ID()).Logger()
+
 	peer := session.GetWebRTCPeer()
 	if peer == nil {
-		h.logger.Debug().Str("session_id", session.ID()).Msg("webRTC peer does not exist")
+		logger.Debug().Msg("webRTC peer does not exist")
 		return nil
 	}
 
@@ -72,9 +80,11 @@ func (h *MessageHandlerCtx) signalCandidate(session types.Session, payload *mess
 }
 
 func (h *MessageHandlerCtx) signalVideo(session types.Session, payload *message.SignalVideo) error {
+	logger := h.logger.With().Str("session_id", session.ID()).Logger()
+
 	peer := session.GetWebRTCPeer()
 	if peer == nil {
-		h.logger.Debug().Str("session_id", session.ID()).Msg("webRTC peer does not exist")
+		logger.Debug().Msg("webRTC peer does not exist")
 		return nil
 	}
 

internal/websocket/manager.go

@@ -44,50 +44,62 @@ type WebSocketManagerCtx struct {
 
 func (manager *WebSocketManagerCtx) Start() {
 	manager.sessions.OnCreated(func(session types.Session) {
+		logger := manager.logger.With().Str("session_id", session.ID()).Logger()
+
 		if err := manager.handler.SessionCreated(session); err != nil {
-			manager.logger.Warn().Str("session_id", session.ID()).Err(err).Msg("session created with an error")
+			logger.Warn().Err(err).Msg("session created with an error")
 		} else {
-			manager.logger.Debug().Str("session_id", session.ID()).Msg("session created")
+			logger.Debug().Msg("session created")
 		}
 	})
 
 	manager.sessions.OnDeleted(func(session types.Session) {
+		logger := manager.logger.With().Str("session_id", session.ID()).Logger()
+
 		if err := manager.handler.SessionDeleted(session); err != nil {
-			manager.logger.Warn().Str("session_id", session.ID()).Err(err).Msg("session deleted with an error")
+			logger.Warn().Err(err).Msg("session deleted with an error")
 		} else {
-			manager.logger.Debug().Str("session_id", session.ID()).Msg("session deleted")
+			logger.Debug().Msg("session deleted")
 		}
 	})
 
 	manager.sessions.OnConnected(func(session types.Session) {
+		logger := manager.logger.With().Str("session_id", session.ID()).Logger()
+
 		if err := manager.handler.SessionConnected(session); err != nil {
-			manager.logger.Warn().Str("session_id", session.ID()).Err(err).Msg("session connected with an error")
+			logger.Warn().Err(err).Msg("session connected with an error")
 		} else {
-			manager.logger.Debug().Str("session_id", session.ID()).Msg("session connected")
+			logger.Debug().Msg("session connected")
 		}
 	})
 
 	manager.sessions.OnDisconnected(func(session types.Session) {
+		logger := manager.logger.With().Str("session_id", session.ID()).Logger()
+
 		if err := manager.handler.SessionDisconnected(session); err != nil {
-			manager.logger.Warn().Str("session_id", session.ID()).Err(err).Msg("session disconnected with an error")
+			logger.Warn().Err(err).Msg("session disconnected with an error")
 		} else {
-			manager.logger.Debug().Str("session_id", session.ID()).Msg("session disconnected")
+			logger.Debug().Msg("session disconnected")
 		}
 	})
 
 	manager.sessions.OnProfileChanged(func(session types.Session) {
+		logger := manager.logger.With().Str("session_id", session.ID()).Logger()
+
 		if err := manager.handler.SessionProfileChanged(session); err != nil {
-			manager.logger.Warn().Str("session_id", session.ID()).Err(err).Msg("session profile changed with an error")
+			logger.Warn().Err(err).Msg("session profile changed with an error")
 		} else {
-			manager.logger.Debug().Str("session_id", session.ID()).Msg("session profile changed")
+			logger.Debug().Msg("session profile changed")
 		}
 	})
 
 	manager.sessions.OnStateChanged(func(session types.Session) {
+		logger := manager.logger.With().Str("session_id", session.ID()).Logger()
+
 		if err := manager.handler.SessionStateChanged(session); err != nil {
-			manager.logger.Warn().Str("session_id", session.ID()).Err(err).Msg("session state changed with an error")
+			logger.Warn().Err(err).Msg("session state changed with an error")
 		} else {
-			manager.logger.Debug().Str("session_id", session.ID()).Msg("session state changed")
+			logger.Debug().Msg("session state changed")
 		}
 	})
 
@@ -102,6 +114,11 @@ func (manager *WebSocketManagerCtx) Start() {
 		}
 
 		manager.sessions.Broadcast(msg, nil)
+
+		manager.logger.Debug().
+			Bool("has_host", msg.HasHost).
+			Str("host_id", msg.HostID).
+			Msg("session host changed")
 	})
 
 	manager.desktop.OnClipboardUpdated(func() {
@@ -122,13 +139,19 @@ func (manager *WebSocketManagerCtx) Start() {
 			// TODO: Send HTML?
 		}); err != nil {
 			manager.logger.Warn().Err(err).Msg("could not sync clipboard")
+			return
 		}
+
+		manager.logger.Debug().Msg("session sync clipboard")
 	})
 
 	manager.fileChooserDialogEvents()
+
+	manager.logger.Info().Msg("websocket starting")
 }
 
 func (manager *WebSocketManagerCtx) Shutdown() error {
+	manager.logger.Info().Msg("websocket shutdown")
 	return nil
 }
 
@@ -169,8 +192,11 @@ func (manager *WebSocketManagerCtx) Upgrade(w http.ResponseWriter, r *http.Reque
 		return
 	}
 
+	// add session id to logger context
+	logger := manager.logger.With().Str("session_id", session.ID()).Logger()
+
 	if !session.Profile().CanConnect {
-		manager.logger.Debug().Str("session_id", session.ID()).Msg("connection disabled")
+		logger.Debug().Msg("connection disabled")
 
 		// TODO: Refactor, return error code.
 		if err = connection.WriteJSON(
@@ -178,18 +204,18 @@ func (manager *WebSocketManagerCtx) Upgrade(w http.ResponseWriter, r *http.Reque
 				Event:   event.SYSTEM_DISCONNECT,
 				Message: "connection disabled",
 			}); err != nil {
-			manager.logger.Error().Err(err).Msg("failed to send disconnect event")
+			logger.Error().Err(err).Msg("failed to send disconnect event")
 		}
 
 		if err := connection.Close(); err != nil {
-			manager.logger.Warn().Err(err).Msg("connection closed with an error")
+			logger.Warn().Err(err).Msg("connection closed with an error")
 		}
 
 		return
 	}
 
 	if session.State().IsConnected {
-		manager.logger.Warn().Str("session_id", session.ID()).Msg("already connected")
+		logger.Warn().Msg("already connected")
 
 		if !manager.sessions.MercifulReconnect() {
 			// TODO: Refactor, return error code.
@@ -198,44 +224,40 @@ func (manager *WebSocketManagerCtx) Upgrade(w http.ResponseWriter, r *http.Reque
 					Event:   event.SYSTEM_DISCONNECT,
 					Message: "already connected",
 				}); err != nil {
-				manager.logger.Error().Err(err).Msg("failed to send disconnect event")
+				logger.Error().Err(err).Msg("failed to send disconnect event")
 			}
 
 			if err := connection.Close(); err != nil {
-				manager.logger.Warn().Err(err).Msg("connection closed with an error")
+				logger.Warn().Err(err).Msg("connection closed with an error")
 			}
 
 			return
 		}
 
-		manager.logger.Debug().Str("session_id", session.ID()).Msg("replacing peer connection")
+		logger.Info().Msg("replacing peer connection")
 
 		// replace peer connection
 		if err := session.GetWebSocketPeer().Destroy(); err != nil {
-			manager.logger.Warn().Err(err).Msg("previous connection closed with an error")
+			logger.Warn().Err(err).Msg("previous connection closed with an error")
 		}
 	}
 
 	peer := &WebSocketPeerCtx{
+		logger:     logger,
 		session:    session,
-		manager:    manager,
 		connection: connection,
 	}
 
 	session.SetWebSocketPeer(peer)
 
-	manager.logger.
+	logger.Info().
-		Debug().
-		Str("session_id", session.ID()).
 		Str("address", connection.RemoteAddr().String()).
 		Msg("connection started")
 
 	session.SetWebSocketConnected(peer, true)
 
 	defer func() {
-		manager.logger.
+		logger.Info().
-			Debug().
-			Str("session_id", session.ID()).
 			Str("address", connection.RemoteAddr().String()).
 			Msg("connection ended")
 
@@ -246,6 +268,9 @@ func (manager *WebSocketManagerCtx) Upgrade(w http.ResponseWriter, r *http.Reque
 }
 
 func (manager *WebSocketManagerCtx) handle(connection *websocket.Conn, session types.Session) {
+	// add session id to logger context
+	logger := manager.logger.With().Str("session_id", session.ID()).Logger()
+
 	bytes := make(chan []byte)
 	cancel := make(chan struct{})
 
@@ -257,9 +282,9 @@ func (manager *WebSocketManagerCtx) handle(connection *websocket.Conn, session t
 			_, raw, err := connection.ReadMessage()
 			if err != nil {
 				if websocket.IsUnexpectedCloseError(err, websocket.CloseGoingAway, websocket.CloseAbnormalClosure) {
-					manager.logger.Warn().Err(err).Msg("read message error")
+					logger.Warn().Err(err).Msg("read message error")
 				} else {
-					manager.logger.Debug().Err(err).Msg("read message error")
+					logger.Debug().Err(err).Msg("read message error")
 				}
 
 				close(cancel)
@@ -273,8 +298,7 @@ func (manager *WebSocketManagerCtx) handle(connection *websocket.Conn, session t
 	for {
 		select {
 		case raw := <-bytes:
-			manager.logger.Debug().
+			logger.Debug().
-				Str("session_id", session.ID()).
 				Str("address", connection.RemoteAddr().String()).
 				Str("raw", string(raw)).
 				Msg("received message from client")
@@ -289,13 +313,13 @@ func (manager *WebSocketManagerCtx) handle(connection *websocket.Conn, session t
 			}
 
 			if !handled {
-				manager.logger.Warn().Msg("unhandled message")
+				logger.Warn().Msg("unhandled message")
 			}
 		case <-cancel:
 			return
 		case <-ticker.C:
 			if err := connection.WriteMessage(websocket.PingMessage, nil); err != nil {
-				manager.logger.Error().Err(err).Msg("ping message has failed")
+				logger.Error().Err(err).Msg("ping message has failed")
 				return
 			}
 		}

internal/websocket/peer.go

@@ -5,6 +5,7 @@ import (
 	"sync"
 
 	"github.com/gorilla/websocket"
+	"github.com/rs/zerolog"
 
 	"demodesk/neko/internal/types"
 	"demodesk/neko/internal/types/event"
@@ -14,8 +15,8 @@ import (
 
 type WebSocketPeerCtx struct {
 	mu         sync.Mutex
+	logger     zerolog.Logger
 	session    types.Session
-	manager    *WebSocketManagerCtx
 	connection *websocket.Conn
 }
 
@@ -32,8 +33,7 @@ func (peer *WebSocketPeerCtx) Send(v interface{}) error {
 		return err
 	}
 
-	peer.manager.logger.Debug().
+	peer.logger.Debug().
-		Str("session_id", peer.session.ID()).
 		Str("address", peer.connection.RemoteAddr().String()).
 		Str("raw", string(raw)).
 		Msg("sending message to client")