Extra Debugging for TestGameServerReserve (#1334)

Adds new WaitForGameServerStateWithLogger() function that makes it
easier to track debug output for state checking for specific tests.

Also dumped out event data for the pod and gameserver on this test to
see what else we can see.

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=