From cc2993993516d7183452477a9f48aab5f10ffafb Mon Sep 17 00:00:00 2001 From: Mark Mandel Date: Mon, 10 Feb 2020 18:29:00 -0800 Subject: [PATCH] Extra Debugging for TestGameServerReserve 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 | 30 +++++++++++------ test/e2e/gameserver_test.go | 45 ++++++++++++++++++++----- vendor_fixes/k8s.io/apimachinery/go.sum | 2 ++ 3 files changed, 59 insertions(+), 18 deletions(-) create mode 100644 vendor_fixes/k8s.io/apimachinery/go.sum diff --git a/test/e2e/framework/framework.go b/test/e2e/framework/framework.go index fa265d1746..8e7b3e8248 100644 --- a/test/e2e/framework/framework.go +++ b/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() diff --git a/test/e2e/gameserver_test.go b/test/e2e/gameserver_test.go index d9b275ba83..5a91755ced 100644 --- a/test/e2e/gameserver_test.go +++ b/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) { diff --git a/vendor_fixes/k8s.io/apimachinery/go.sum b/vendor_fixes/k8s.io/apimachinery/go.sum new file mode 100644 index 0000000000..061778d1f5 --- /dev/null +++ b/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=