diff --git a/internal/websocket/filechooserdialog.go b/internal/websocket/filechooserdialog.go index ea732a12..9791ea4f 100644 --- a/internal/websocket/filechooserdialog.go +++ b/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(). - Err(err). - Str("session_id", session.ID()). - Msgf("could not send event `%s` to session", event.FILE_CHOOSER_DIALOG_OPENED) + logger.Warn().Err(err). + Str("event", event.FILE_CHOOSER_DIALOG_OPENED). + Msg("could not send event") } }) @@ -62,6 +64,7 @@ func (manager *WebSocketManagerCtx) fileChooserDialogEvents() { return } + manager.logger.Info().Msg("file chooser dialog owner left, closing") manager.desktop.CloseFileChooserDialog() }) } diff --git a/internal/websocket/handler/clipboard.go b/internal/websocket/handler/clipboard.go index 62a1d79c..6c4618c6 100644 --- a/internal/websocket/handler/clipboard.go +++ b/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 } diff --git a/internal/websocket/handler/control.go b/internal/websocket/handler/control.go index ac348464..14cc03b2 100644 --- a/internal/websocket/handler/control.go +++ b/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 } diff --git a/internal/websocket/handler/handler.go b/internal/websocket/handler/handler.go index 5b1531d9..2b849c22 100644 --- a/internal/websocket/handler/handler.go +++ b/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 diff --git a/internal/websocket/handler/keyboard.go b/internal/websocket/handler/keyboard.go index 112552ee..72d21a26 100644 --- a/internal/websocket/handler/keyboard.go +++ b/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 } diff --git a/internal/websocket/handler/screen.go b/internal/websocket/handler/screen.go index a88b6c06..07a6fc2c 100644 --- a/internal/websocket/handler/screen.go +++ b/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 } diff --git a/internal/websocket/handler/send.go b/internal/websocket/handler/send.go index 70e2763e..73eac541 100644 --- a/internal/websocket/handler/send.go +++ b/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 } diff --git a/internal/websocket/handler/signal.go b/internal/websocket/handler/signal.go index 647a9bdc..e32becd0 100644 --- a/internal/websocket/handler/signal.go +++ b/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 } diff --git a/internal/websocket/manager.go b/internal/websocket/manager.go index cbb90fbb..0fa1d168 100644 --- a/internal/websocket/manager.go +++ b/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. - Debug(). - Str("session_id", session.ID()). + logger.Info(). Str("address", connection.RemoteAddr().String()). Msg("connection started") session.SetWebSocketConnected(peer, true) defer func() { - manager.logger. - Debug(). - Str("session_id", session.ID()). + logger.Info(). 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(). - Str("session_id", session.ID()). + logger.Debug(). 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 } } diff --git a/internal/websocket/peer.go b/internal/websocket/peer.go index 6bf1c344..fc464b8a 100644 --- a/internal/websocket/peer.go +++ b/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(). - Str("session_id", peer.session.ID()). + peer.logger.Debug(). Str("address", peer.connection.RemoteAddr().String()). Str("raw", string(raw)). Msg("sending message to client")