From 6dd4c5ebeb98e9b35e5508389d8634193761ffcb Mon Sep 17 00:00:00 2001
From: Joachim Bauch <bauch@struktur.de>
Date: Thu, 28 Oct 2021 10:54:37 +0200
Subject: [PATCH] Debug flaky test TestClientTakeoverRoomSession

---
 clientsession.go       | 1 +
 natsclient_loopback.go | 8 ++++++--
 2 files changed, 7 insertions(+), 2 deletions(-)

diff --git a/clientsession.go b/clientsession.go
index 61c83fe..59a3d8f 100644
--- a/clientsession.go
+++ b/clientsession.go
@@ -857,6 +857,7 @@ func (s *ClientSession) processNatsMessage(msg *NatsMessage) *ServerMessage {
 			} else if msg.Message.Event.Target == "room" {
 				// Can happen mostly during tests where an older room NATS message
 				// could be received by a subscriber that joined after it was sent.
+				log.Printf("Message %+v was sent at %s, room joined at %s", msg.Message, msg.SendTime, s.getRoomJoinTime())
 				if msg.SendTime.Before(s.getRoomJoinTime()) {
 					log.Printf("Message %+v was sent before room was joined, ignoring", msg.Message)
 					return nil
diff --git a/natsclient_loopback.go b/natsclient_loopback.go
index aaa1699..c13eb6e 100644
--- a/natsclient_loopback.go
+++ b/natsclient_loopback.go
@@ -175,8 +175,10 @@ func (c *LoopbackNatsClient) PublishNats(subject string, message *NatsMessage) e
 }
 
 func (c *LoopbackNatsClient) PublishMessage(subject string, message *ServerMessage) error {
+	now := time.Now()
+	log.Printf("Send message at %s: %+v", now, message)
 	msg := &NatsMessage{
-		SendTime: time.Now(),
+		SendTime: now,
 		Type:     "message",
 		Message:  message,
 	}
@@ -184,8 +186,10 @@ func (c *LoopbackNatsClient) PublishMessage(subject string, message *ServerMessa
 }
 
 func (c *LoopbackNatsClient) PublishBackendServerRoomRequest(subject string, message *BackendServerRoomRequest) error {
+	now := time.Now()
+	log.Printf("Send message at %s: %+v", now, message)
 	msg := &NatsMessage{
-		SendTime: time.Now(),
+		SendTime: now,
 		Type:     "room",
 		Room:     message,
 	}