Extra Debugging for TestGameServerReserve

test/e2e/framework/framework.go

@@ -121,7 +121,7 @@ func (f *Framework) CreateGameServerAndWaitUntilReady(ns string, gs *agonesv1.Ga
 		return nil, fmt.Errorf("creating %v GameServer instances failed (%v): %v", gs.Spec, gs.Name, err)
 	}
 
-	logrus.WithField("name", newGs.ObjectMeta.Name).Info("GameServer created, waiting for Ready")
+	logrus.WithField("gs", newGs.ObjectMeta.Name).Info("GameServer created, waiting for Ready")
 
 	readyGs, err := f.WaitForGameServerState(newGs, agonesv1.GameServerStateReady, 5*time.Minute)
 
@@ -133,36 +133,46 @@ func (f *Framework) CreateGameServerAndWaitUntilReady(ns string, gs *agonesv1.Ga
 		return nil, fmt.Errorf("Ready GameServer instance has no port: %v", readyGs.Status)
 	}
 
-	logrus.WithField("name", newGs.ObjectMeta.Name).Info("GameServer Ready")
+	logrus.WithField("gs", newGs.ObjectMeta.Name).Info("GameServer Ready")
 
 	return readyGs, nil
 }
 
-// WaitForGameServerState Waits untils the gameserver reach a given state before the timeout expires
-func (f *Framework) WaitForGameServerState(gs *agonesv1.GameServer, state agonesv1.GameServerState,
-	timeout time.Duration) (*agonesv1.GameServer, error) {
-	var readyGs *agonesv1.GameServer
+// WaitForGameServerStateWithLogger Waits untils the gameserver reach a given state before the timeout expires, and logs against
+// a give logger (usually useful to log the name of the test with the checks)
+func (f *Framework) WaitForGameServerStateWithLogger(logger *logrus.Entry, gs *agonesv1.GameServer, state agonesv1.GameServerState, timeout time.Duration) (*agonesv1.GameServer, error) {
+	var checkGs *agonesv1.GameServer
 
-	err := wait.PollImmediate(2*time.Second, timeout, func() (bool, error) {
+	err := wait.PollImmediate(1*time.Second, timeout, func() (bool, error) {
 		var err error
-		readyGs, err = f.AgonesClient.AgonesV1().GameServers(gs.Namespace).Get(gs.Name, metav1.GetOptions{})
+		checkGs, err = f.AgonesClient.AgonesV1().GameServers(gs.Namespace).Get(gs.Name, metav1.GetOptions{})
 
 		if err != nil {
 			logrus.WithError(err).Warn("error retrieving gameserver")
 			return false, nil
 		}
 
-		if readyGs.Status.State == state {
+		logger.WithField("gs", checkGs.ObjectMeta.Name).
+			WithField("currentState", checkGs.Status.State).
+			WithField("awaitingState", state).Info("Waiting for states to match")
+
+		if checkGs.Status.State == state {
 			return true, nil
 		}
 
 		return false, nil
 	})
 
-	return readyGs, errors.Wrapf(err, "waiting for GameServer to be %v %v/%v",
+	return checkGs, errors.Wrapf(err, "waiting for GameServer to be %v %v/%v",
 		state, gs.Namespace, gs.Name)
 }
 
+// WaitForGameServerState Waits untils the gameserver reach a given state before the timeout expires (with a default logger)
+func (f *Framework) WaitForGameServerState(gs *agonesv1.GameServer, state agonesv1.GameServerState,
+	timeout time.Duration) (*agonesv1.GameServer, error) {
+	return f.WaitForGameServerStateWithLogger(logrus.WithFields(nil), gs, state, timeout)
+}
+
 // AssertFleetCondition waits for the Fleet to be in a specific condition or fails the test if the condition can't be met in 5 minutes.
 func (f *Framework) AssertFleetCondition(t *testing.T, flt *agonesv1.Fleet, condition func(fleet *agonesv1.Fleet) bool) {
 	t.Helper()

test/e2e/gameserver_test.go

@@ -29,6 +29,7 @@ import (
 	"k8s.io/apimachinery/pkg/api/resource"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/util/wait"
+	"k8s.io/client-go/kubernetes/scheme"
 )
 
 const (
@@ -476,28 +477,56 @@ func TestGameServerReadyAllocateReady(t *testing.T) {
 
 func TestGameServerReserve(t *testing.T) {
 	t.Parallel()
+	logger := logrus.WithField("test", t.Name())
+
 	gs := framework.DefaultGameServer(defaultNs)
-	readyGs, err := framework.CreateGameServerAndWaitUntilReady(defaultNs, gs)
+	gs, err := framework.CreateGameServerAndWaitUntilReady(defaultNs, gs)
 	if err != nil {
 		t.Fatalf("Could not get a GameServer ready: %v", err)
 	}
-	defer framework.AgonesClient.AgonesV1().GameServers(defaultNs).Delete(readyGs.ObjectMeta.Name, nil) // nolint: errcheck
-	assert.Equal(t, readyGs.Status.State, agonesv1.GameServerStateReady)
+	defer framework.AgonesClient.AgonesV1().GameServers(defaultNs).Delete(gs.ObjectMeta.Name, nil) // nolint: errcheck
+	assert.Equal(t, gs.Status.State, agonesv1.GameServerStateReady)
 
-	reply, err := e2eframework.SendGameServerUDP(readyGs, "RESERVE")
+	logger.Info("sending RESERVE command")
+	reply, err := e2eframework.SendGameServerUDP(gs, "RESERVE")
 	if !assert.NoError(t, err) {
 		assert.FailNow(t, "Could not message GameServer")
 	}
+	logger.Info("Received response")
 	assert.Equal(t, "ACK: RESERVE\n", reply)
 
-	gs, err = framework.WaitForGameServerState(readyGs, agonesv1.GameServerStateReserved, time.Minute)
-	assert.NoError(t, err, fmt.Sprintf("GameServer Name: %s", readyGs.ObjectMeta.Name))
-	assert.Equal(t, agonesv1.GameServerStateReserved, gs.Status.State, fmt.Sprintf("GameServer Name: %s", readyGs.ObjectMeta.Name))
+	gs, err = framework.WaitForGameServerStateWithLogger(logger, gs, agonesv1.GameServerStateReserved, time.Minute)
+	assert.NoError(t, err, fmt.Sprintf("GameServer Name: %s", gs.ObjectMeta.Name))
+	assert.Equal(t, agonesv1.GameServerStateReserved, gs.Status.State, fmt.Sprintf("GameServer Name: %s", gs.ObjectMeta.Name))
 
 	// it should go back after 10 seconds
-	gs, err = framework.WaitForGameServerState(readyGs, agonesv1.GameServerStateReady, 15*time.Second)
+	gs, err = framework.WaitForGameServerStateWithLogger(logger, gs, agonesv1.GameServerStateReady, 15*time.Second)
 	assert.NoError(t, err)
 	assert.Equal(t, agonesv1.GameServerStateReady, gs.Status.State)
+
+	list, err := framework.KubeClient.CoreV1().Events(defaultNs).Search(scheme.Scheme, gs)
+	assert.NoError(t, err)
+
+	for _, e := range list.Items {
+		logger.WithField("first-time", e.FirstTimestamp).WithField("count", e.Count).
+			WithField("last-time", e.LastTimestamp).
+			WithField("name", e.Name).
+			WithField("reason", e.Reason).WithField("message", e.Message).Info("gs event details")
+	}
+
+	pod, err := framework.KubeClient.CoreV1().Pods(defaultNs).Get(gs.ObjectMeta.Name, metav1.GetOptions{})
+	assert.NoError(t, err)
+	logger.WithField("status", pod.Status).Info("Pod Status")
+
+	list, err = framework.KubeClient.CoreV1().Events(defaultNs).Search(scheme.Scheme, pod)
+	assert.NoError(t, err)
+
+	for _, e := range list.Items {
+		logger.WithField("first-time", e.FirstTimestamp).WithField("count", e.Count).
+			WithField("last-time", e.LastTimestamp).
+			WithField("name", e.Name).
+			WithField("reason", e.Reason).WithField("message", e.Message).Info("gs event details")
+	}
 }
 
 func TestGameServerShutdown(t *testing.T) {

vendor_fixes/k8s.io/apimachinery/go.sum

@@ -0,0 +1,2 @@
+github.com/go-logr/logr v0.1.0/go.mod h1:ixOQHD9gLJUVQQ2ZOR7zLEifBX6tGkNJF4QyIY7sIas=
+k8s.io/klog v1.0.0/go.mod h1:4Bi6QPql/J/LkTDqv7R/cd3hPo4k2DG6Ptcz060Ez5I=