Add logging about reconnects.

Also add a timeout-manager test.

features/reconnect.feature

@@ -95,3 +95,22 @@ Feature: Players can create and connect a network of players
     Then "green" receives the network event "connected" with the argument "[Peer: 3t3cfgcqup9e]"
     And "blue" receives the network event "connected" with the argument "[Peer: h5yzwyizlwao]"
 
+
+  Scenario: A disconnected player is removed from the lobby
+    Given "green" is connected and ready for game "325a2754-1a6f-4578-b768-196463271229"
+    And "blue" creates a network for game "325a2754-1a6f-4578-b768-196463271229"
+
+    When "green" creates a lobby
+    Then "green" receives the network event "lobby" with the argument "prb67ouj837u"
+
+    When the websocket of "green" is reconnected
+    Then "green" receives the network event "signalingreconnected"
+    And "green" has recieved the peer ID "19yrzmetd2bn7"
+
+    When "green" disconnects
+    And timeout disconnect threshold passes
+
+    When "blue" requests all lobbies
+    Then "blue" should have received only these lobbies
+      | code         | playerCount |
+      | prb67ouj837u | 0           |

features/support/steps/util.ts

@@ -5,6 +5,10 @@ When('I sleep for {int} second', async function (this: World, seconds: number) {
   await new Promise(resolve => setTimeout(resolve, seconds * 1000))
 })
 
+When('timeout disconnect threshold passes', async function (this: World) {
+  await new Promise(resolve => setTimeout(resolve, 1000))
+})
+
 let time: number = 0
 When(/I (start|stop) measuring time/, function (this: World, act: string) {
   if (act === 'start') {

internal/signaling/handler.go

@@ -55,7 +55,7 @@ func Handler(ctx context.Context, store stores.Store, cloudflare *cloudflare.Cre
 			retrievedIDCallback: manager.Reconnected,
 		}
 		defer func() {
-			logger.Debug("peer websocket closed", zap.String("id", peer.ID))
+			logger.Info("peer websocket closed", zap.String("peer", peer.ID))
 			conn.Close(websocket.StatusInternalError, "unexpceted closure")
 
 			// At this point ctx has already been cancelled, so we create a new one to use for the disconnect.

internal/signaling/peer.go

@@ -29,6 +29,7 @@ type Peer struct {
 
 func (p *Peer) Close(ctx context.Context) {
 	logger := logging.GetLogger(ctx)
+	logger.Info("closing peer", zap.String("peer", p.ID))
 	if p.ID != "" && p.Game != "" && p.Lobby != "" {
 		packet := DisconnectPacket{
 			Type: "disconnect",
@@ -152,6 +153,7 @@ func (p *Peer) HandlePacket(ctx context.Context, typ string, raw []byte) error {
 
 	case "leave":
 		go metrics.Record(ctx, "lobby", "leave", p.Game, p.ID, p.Lobby)
+		logger.Info("leaving lobby", zap.String("lobby", p.Lobby))
 
 		others, err := p.store.LeaveLobby(ctx, p.Game, p.Lobby, p.ID)
 		if err != nil {
@@ -220,7 +222,7 @@ func (p *Peer) HandleHelloPacket(ctx context.Context, packet HelloPacket) error
 		clientIsReconnecting = true
 		p.ID = packet.ID
 		p.Secret = packet.Secret
-		logger.Info("peer reconnecting", zap.String("game", p.Game), zap.String("peer", p.ID))
+		logger.Info("peer reconnecting", zap.String("game", p.Game), zap.String("peer", p.ID), zap.String("lobby_in_packet", packet.Lobby))
 	} else {
 		p.ID = util.GeneratePeerID(ctx)
 		p.Secret = util.GenerateSecret(ctx)
@@ -243,7 +245,7 @@ func (p *Peer) HandleHelloPacket(ctx context.Context, packet HelloPacket) error
 			return err
 		}
 		if hasReconnected && inLobby {
-			logger.Debug("peer rejoining lobby", zap.String("game", p.Game), zap.String("peer", p.ID), zap.String("lobby", p.Lobby))
+			logger.Info("peer rejoining lobby", zap.String("game", p.Game), zap.String("peer", p.ID), zap.String("lobby", p.Lobby))
 			p.Lobby = packet.Lobby
 			p.store.Subscribe(ctx, p.Game+p.Lobby+p.ID, p.ForwardMessage)
 			go metrics.Record(ctx, "lobby", "reconnected", p.Game, p.ID, p.Lobby)
@@ -323,7 +325,7 @@ func (p *Peer) HandleCreatePacket(ctx context.Context, packet CreatePacket) erro
 		return err
 	}
 
-	logger.Info("created lobby", zap.String("game", p.Game), zap.String("lobby", p.Lobby))
+	logger.Info("created lobby", zap.String("game", p.Game), zap.String("lobby", p.Lobby), zap.String("peer", p.ID))
 	go metrics.Record(ctx, "lobby", "created", p.Game, p.ID, p.Lobby)
 
 	return p.Send(ctx, JoinedPacket{

internal/signaling/timeout_manager.go

@@ -3,6 +3,7 @@ package signaling
 import (
 	"context"
 	"encoding/json"
+	"os"
 	"time"
 
 	"github.com/koenbollen/logging"
@@ -21,8 +22,14 @@ func (i *TimeoutManager) Run(ctx context.Context) {
 		i.DisconnectThreshold = time.Minute
 	}
 
+	interval := time.Second
+	if os.Getenv("ENV") == "test" {
+		i.DisconnectThreshold = 500 * time.Millisecond
+		interval = 100 * time.Millisecond
+	}
+
 	for ctx.Err() == nil {
-		time.Sleep(time.Second)
+		time.Sleep(interval)
 		i.RunOnce(ctx)
 	}
 }
@@ -32,7 +39,7 @@ func (i *TimeoutManager) RunOnce(ctx context.Context) {
 
 	for ctx.Err() == nil {
 		hasNext, err := i.Store.ClaimNextTimedOutPeer(ctx, i.DisconnectThreshold, func(peerID, gameID string, lobbies []string) error {
-			logger.Debug("peer timed out closing peer", zap.String("id", peerID))
+			logger.Info("peer timed out closing peer", zap.String("id", peerID))
 
 			for _, lobby := range lobbies {
 				if err := i.disconnectPeerInLobby(ctx, peerID, gameID, lobby, logger); err != nil {