From 755fa30718dece466f2481453d4543a6ecb11a1f Mon Sep 17 00:00:00 2001 From: Koen Bollen Date: Wed, 16 Aug 2023 10:56:14 +0200 Subject: [PATCH] Add logging about reconnects. Also add a timeout-manager test. --- features/reconnect.feature | 19 +++++++++++++++++++ features/support/steps/util.ts | 4 ++++ internal/signaling/handler.go | 2 +- internal/signaling/peer.go | 8 +++++--- internal/signaling/timeout_manager.go | 11 +++++++++-- 5 files changed, 38 insertions(+), 6 deletions(-) diff --git a/features/reconnect.feature b/features/reconnect.feature index 7608cc2..ac63723 100644 --- a/features/reconnect.feature +++ b/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 | diff --git a/features/support/steps/util.ts b/features/support/steps/util.ts index b39cc52..2ab2756 100644 --- a/features/support/steps/util.ts +++ b/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') { diff --git a/internal/signaling/handler.go b/internal/signaling/handler.go index d961694..cdd31f8 100644 --- a/internal/signaling/handler.go +++ b/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. diff --git a/internal/signaling/peer.go b/internal/signaling/peer.go index 23bcaf3..9d728d2 100644 --- a/internal/signaling/peer.go +++ b/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{ diff --git a/internal/signaling/timeout_manager.go b/internal/signaling/timeout_manager.go index e2d2f68..b288a26 100644 --- a/internal/signaling/timeout_manager.go +++ b/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 {