Improve logging, add timeout (enforce ping)

room-hub/connectionManager.go

@@ -2,7 +2,6 @@ package main
 
 import (
 	"errors"
-	"log"
 	"sync"
 )
 
@@ -70,7 +69,6 @@ func (connectionManager *ConnectionManager) generatePIN() (string, error) {
 
 		var pin, err = randomString(PINLength, Digits)
 		if err != nil {
-			log.Printf("failed to generate room ID: %s", err)
 			return "", err
 		}
 
@@ -83,7 +81,7 @@ func (connectionManager *ConnectionManager) generatePIN() (string, error) {
 		}
 	}
 	// No pin generated after maxTries
-	return "", errors.New("PIN generation failed")
+	return "", errors.New("Max tries reached")
 }
 
 // Get room by PIN

room-hub/go.mod

@@ -15,10 +15,13 @@ require (
 	github.com/go-playground/locales v0.14.1 // indirect
 	github.com/go-playground/universal-translator v0.18.1 // indirect
 	github.com/leodido/go-urn v1.4.0 // indirect
+	github.com/mattn/go-colorable v0.1.13 // indirect
+	github.com/mattn/go-isatty v0.0.20 // indirect
 	github.com/pmezard/go-difflib v1.0.0 // indirect
+	github.com/rs/zerolog v1.33.0 // indirect
 	golang.org/x/crypto v0.19.0 // indirect
 	golang.org/x/net v0.21.0 // indirect
-	golang.org/x/sys v0.17.0 // indirect
+	golang.org/x/sys v0.28.0 // indirect
 	golang.org/x/text v0.14.0 // indirect
 	gopkg.in/yaml.v3 v3.0.1 // indirect
 )

room-hub/go.sum

@@ -1,3 +1,4 @@
+github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
 github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
 github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/gabriel-vasile/mimetype v1.4.3 h1:in2uUcidCuFcDKtdcBxlR0rJ1+fsokWf+uqxgUFjbI0=
@@ -10,22 +11,38 @@ github.com/go-playground/universal-translator v0.18.1 h1:Bcnm0ZwsGyWbCzImXv+pAJn
 github.com/go-playground/universal-translator v0.18.1/go.mod h1:xekY+UJKNuX9WP91TpwSH2VMlDf28Uj24BCp08ZFTUY=
 github.com/go-playground/validator/v10 v10.23.0 h1:/PwmTwZhS0dPkav3cdK9kV1FsAmrL8sThn8IHr/sO+o=
 github.com/go-playground/validator/v10 v10.23.0/go.mod h1:dbuPbCMFw/DrkbEynArYaCwl3amGuJotoKCe95atGMM=
+github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA=
 github.com/google/uuid v1.6.0 h1:NIvaJDMOsjHA8n1jAhLSgzrAzy1Hgr+hNrb57e+94F0=
 github.com/google/uuid v1.6.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo=
 github.com/gorilla/websocket v1.5.3 h1:saDtZ6Pbx/0u+bgYQ3q96pZgCzfhKXGPqt7kZ72aNNg=
 github.com/gorilla/websocket v1.5.3/go.mod h1:YR8l580nyteQvAITg2hZ9XVh4b55+EU/adAjf1fMHhE=
 github.com/leodido/go-urn v1.4.0 h1:WT9HwE9SGECu3lg4d/dIA+jxlljEa1/ffXKmRjqdmIQ=
 github.com/leodido/go-urn v1.4.0/go.mod h1:bvxc+MVxLKB4z00jd1z+Dvzr47oO32F/QSNjSBOlFxI=
+github.com/mattn/go-colorable v0.1.13 h1:fFA4WZxdEF4tXPZVKMLwD8oUnCTTo08duU7wxecdEvA=
+github.com/mattn/go-colorable v0.1.13/go.mod h1:7S9/ev0klgBDR4GtXTXX8a3vIGJpMovkB8vQcUbaXHg=
+github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM=
+github.com/mattn/go-isatty v0.0.19/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y=
+github.com/mattn/go-isatty v0.0.20 h1:xfD0iDuEKnDkl03q4limB+vH+GxLEtL/jb4xVJSWWEY=
+github.com/mattn/go-isatty v0.0.20/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y=
+github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
+github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
+github.com/rs/zerolog v1.33.0 h1:1cU2KZkvPxNyfgEmhHAz/1A9Bz+llsdYzklWFzgp0r8=
+github.com/rs/zerolog v1.33.0/go.mod h1:/7mN4D5sKwJLZQ2b/znpjC3/GQWY/xaDXUM0kKWRHss=
 github.com/stretchr/testify v1.8.4 h1:CcVxjf3Q8PM0mHUKJCdn+eZZtm5yQwehR5yeSVQQcUk=
 github.com/stretchr/testify v1.8.4/go.mod h1:sz/lmYIOXD/1dqDmKjjqLyZ2RngseejIcXlSw2iwfAo=
 golang.org/x/crypto v0.19.0 h1:ENy+Az/9Y1vSrlrvBSyna3PITt4tiZLf7sgCjZBX7Wo=
 golang.org/x/crypto v0.19.0/go.mod h1:Iy9bg/ha4yyC70EfRS8jz+B6ybOBKMaSxLj6P6oBDfU=
 golang.org/x/net v0.21.0 h1:AQyQV4dYCvJ7vGmJyKki9+PBdyvhkSd8EIx/qb0AYv4=
 golang.org/x/net v0.21.0/go.mod h1:bIjVDfnllIU7BJ2DNgfnXvpSvtn8VRwhlsaeUTyUS44=
+golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.17.0 h1:25cE3gD+tdBA7lp7QfhuV+rJiE9YXTcS3VG1SqssI/Y=
 golang.org/x/sys v0.17.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
+golang.org/x/sys v0.28.0 h1:Fksou7UEQUWlKvIdsqzJmUmCX3cZuD2+P3XyyzwMhlA=
+golang.org/x/sys v0.28.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
 golang.org/x/text v0.14.0 h1:ScX5w1eTa3QqT8oi6+ziP7dTV1S2+ALU0bI+0zXKWiQ=
 golang.org/x/text v0.14.0/go.mod h1:18ZOQIKpY8NJVqYksKHtTdi31H5itFRjB5/qKTNYzSU=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM=

room-hub/messages.go

@@ -3,14 +3,15 @@ package main
 import (
 	"encoding/json"
 	"errors"
-	"log"
+	"github.com/rs/zerolog/log"
 )
 
 // Define custom types and constants for the Type field
 type MessageType string
 
 const (
 	MessageTypePing                     MessageType = "Ping"                     // ping
+	MessageTypePong                     MessageType = "Pong"                     // pong
 	MessageTypePairingPIN               MessageType = "PairingPIN"               // assign pin to room (server -> appliance)
 	MessageTypeRegisterRoom             MessageType = "RegisterRoom"             // appliance registers with room config (appliance -> server)
 	MessageTypePairingPINUserInput      MessageType = "PairingPINUserInput"      // connect to room (plugin -> server)
@@ -23,6 +24,7 @@ const (
 	MessageTypeJoinURLs                 MessageType = "JoinURLs"                 // the plugin generates join urls for the room appliance, this message is send from the plugin to the server and then forwarded to the appliance
 	MessageTypeRoomDisconnected         MessageType = "RoomDisconnected"         // the server sends a message to the plugin that the room appliance has disconnected
 	MessageTypePluginDisconnected       MessageType = "PluginDisconnected"       // the server sends a message to the plugin that the plugin has disconnected
+	MessageTypeDisconnect               MessageType = "Disconnect"               // disconnect message
 	MessageTypeInvalid                  MessageType = "Invalid"                  // invalid message
 	MessageTypeData                     MessageType = "Data"                     // data message
 )
@@ -37,6 +39,10 @@ type PingMessage struct {
 	Type MessageType `json:"type" validate:"required"`
 }
 
+type PongMessage struct {
+	Type MessageType `json:"type" validate:"required"`
+}
+
 type RegisterRoomMessage struct {
 	Type       MessageType `json:"type" validate:"required"`
 	RoomConfig RoomConfig  `json:"roomConfig" validate:"required"`
@@ -107,6 +113,11 @@ type PluginDisconnectedMessage struct {
 	Type MessageType `json:"type" validate:"required"`
 }
 
+// Disconnect Message
+type DisconnectMessage struct {
+	Type MessageType `json:"type" validate:"required"`
+}
+
 type InvalidMessage struct {
 	Type MessageType `json:"type" validate:"required"`
 }
@@ -122,13 +133,13 @@ func parseMessage(msg []byte) (BaseMessage, error) {
 	baseMessage.rawMessage = msg
 	err := json.Unmarshal(msg, &baseMessage)
 	if err != nil {
-		log.Printf("Error parsing message: %s", msg)
+		log.Error().Str("message", string(msg)).Msg("Error parsing message")
 		baseMessage.Type = MessageTypeInvalid
 		return baseMessage, err
 	}
 	err = validate.Struct(baseMessage)
 	if err != nil {
-		log.Printf("Message format invalid: %s", err)
+		log.Error().Str("message", string(msg)).Err(err).Msg("Message format invalid")
 		baseMessage.Type = MessageTypeInvalid
 		return baseMessage, err
 	}
@@ -140,19 +151,19 @@ func unmarshalMessage[T any](baseMessage BaseMessage, msgType MessageType) (T, e
 
 	var message T
 	if baseMessage.Type != msgType {
-		log.Printf("Protocol violation: Expected message type %s, got %s", msgType, baseMessage.Type)
+		log.Warn().Str("expected_type", string(msgType)).Str("type", string(baseMessage.Type)).Msg("Protocol violation")
 		return message, errors.New("protocol violation")
 	}
 
 	err := json.Unmarshal(baseMessage.rawMessage, &message)
 	if err != nil {
-		log.Printf("Error unmarshalling to %T: %s", message, err)
+		log.Error().Err(err).Str("message", string(baseMessage.rawMessage)).Type("type", message).Msg("Error unmarshalling message")
 		return message, err
 	}
 
 	err = validate.Struct(message)
 	if err != nil {
-		log.Printf("Error validating %T: %s", message, err)
+		log.Error().Err(err).Type("message", message).Type("type", message).Msg("Error validating message")
 		return message, err
 	}
 

room-hub/plugin.go

@@ -4,7 +4,8 @@ import (
 	"encoding/json"
 	"github.com/google/uuid"
 	"github.com/gorilla/websocket"
-	"log"
+	"github.com/rs/zerolog/log"
+	"net"
 )
 
 type Plugin struct {
@@ -22,6 +23,9 @@ func newPlugin(conn *websocket.Conn) *Plugin {
 		Conn: conn,
 	}
 
+	ip, _, _ := net.SplitHostPort(conn.RemoteAddr().String())
+	log.Info().Str("plugin", pluginID).Str("ip", ip).Msg("New plugin created")
+
 	return plugin
 }
 
@@ -32,7 +36,7 @@ func (plugin *Plugin) getRoom() *Room {
 func (plugin *Plugin) pairWithRoom(pin string) *Room {
 	room := connManager.getRoomByPIN(pin)
 	if room == nil {
-		log.Printf("Pairing with pin %s failed", pin)
+		log.Warn().Str("plugin", plugin.Id).Msg("Pairing failed, invalid PIN")
 
 		// Respond with an error message
 		message := PairingPINFailedMessage{
@@ -48,61 +52,59 @@ func (plugin *Plugin) pairWithRoom(pin string) *Room {
 
 	plugin.RoomID = room.Id
 
-	log.Printf("Pairing with pin %s started, connecting to roomId %s", pin, room.Id)
+	log.Info().Str("room", room.Id).Str("plugin", plugin.Id).Msg("Pairing successfully")
 
 	room.verifyConnection()
 
 	return room
 }
 
-func (plugin *Plugin) disconnect() {
-	log.Printf("Plugin disconnected with ID: %s", plugin.Id)
+func (plugin *Plugin) close() {
+	log.Warn().Str("plugin", plugin.Id).Msg("Websocket connection closed")
 
 	// Plugin disconnected, close the connection
 	plugin.Conn.Close()
 
-	log.Printf("Connection closed, start cleanup")
+	plugin.disconnect()
+
+	// Remove plugin from connection manager
+	connManager.removePlugin(plugin)
+}
+
+func (plugin *Plugin) disconnect() {
+	// Get room
+	room := plugin.getRoom()
 
 	// Check if plugin was connected to a room
-	if plugin.RoomID != "" {
-		// Get room
-		room := plugin.getRoom()
-
-		// If room is connected to the plugin, notify the room
-		if room != nil {
-			// Send PluginDisconnected message to room
-			pluginDisconnectedMessage := PluginDisconnectedMessage{
-				Type: MessageTypePluginDisconnected,
-			}
-
-			if room.sendMessage(pluginDisconnectedMessage) {
-				// Reset room
-				room.reset()
-			}
+	if room != nil {
+		log.Info().Str("plugin", plugin.Id).Str("room", room.Id).Msg("Disconnecting plugin from room")
+
+		// Reset plugin roomID
+		plugin.RoomID = ""
+
+		// Send PluginDisconnected message to room
+		pluginDisconnectedMessage := PluginDisconnectedMessage{
+			Type: MessageTypePluginDisconnected,
 		}
-	}
 
-	// Remove plugin from connection manager
-	connManager.removePlugin(plugin)
+		room.sendMessage(pluginDisconnectedMessage)
+
+		room.disconnect()
+	}
 }
 
 func (plugin *Plugin) sendMessage(message any) bool {
 
 	messageJSON, err := json.Marshal(message)
 	if err != nil {
-		log.Printf("failed to marshal message")
+		log.Error().Err(err).Str("plugin", plugin.Id).Msg("Failed to marshal message")
 		return false
 	}
 
 	if err := plugin.Conn.WriteMessage(websocket.TextMessage, messageJSON); err != nil {
-		log.Println("write error:", err)
-		plugin.disconnect()
+		log.Error().Err(err).Str("plugin", plugin.Id).Msg("Websocket write error")
+		plugin.close()
 		return false
 	}
 	return true
 }
-
-func (plugin *Plugin) reset() {
-	// Reset plugin roomID
-	plugin.RoomID = ""
-}