agones icon indicating copy to clipboard operation
agones copied to clipboard
verified publisher icon googleforgames

Flaky: e2e TestGameServerCreationAfterDeletingOneExtensionsPod

Open markmandel opened this issue 1 year ago • 2 comments

What happened:

VERBOSE:         	Error Trace:	/go/src/agones.dev/agones/test/e2e/extensions/high_availability_test.go:36
VERBOSE:         	Error:      	Received unexpected error:
VERBOSE:         	            	context deadline exceeded
VERBOSE:         	Test:       	TestGameServerCreationAfterDeletingOneExtensionsPod
VERBOSE: time="2023-12-15 00:34:39.398" level=info msg="Length of pod list is 4" test=TestGameServerCreationAfterDeletingOneExtensionsPod
VERBOSE: time="2023-12-15 00:34:39.398" level=info msg="Name of extensions pod 0: agones-extensions-575b9b8b85-hhstl" test=TestGameServerCreationAfterDeletingOneExtensionsPod
VERBOSE: time="2023-12-15 00:34:39.398" level=info msg="Host IP 10.138.0.24" test=TestGameServerCreationAfterDeletingOneExtensionsPod
VERBOSE: time="2023-12-15 00:34:39.398" level=info msg="Pod IPs [{10.72.9.45}]" test=TestGameServerCreationAfterDeletingOneExtensionsPod
VERBOSE: time="2023-12-15 00:34:39.398" level=info msg="Name of extensions pod 1: agones-extensions-5d8d46b879-2ljnr" test=TestGameServerCreationAfterDeletingOneExtensionsPod
VERBOSE: time="2023-12-15 00:34:39.398" level=info msg="Host IP 10.138.0.80" test=TestGameServerCreationAfterDeletingOneExtensionsPod
VERBOSE: time="2023-12-15 00:34:39.399" level=info msg="Pod IPs [{10.72.5.40}]" test=TestGameServerCreationAfterDeletingOneExtensionsPod
VERBOSE: time="2023-12-15 00:34:39.399" level=info msg="Name of extensions pod 2: agones-extensions-5d8d46b879-gwzv8" test=TestGameServerCreationAfterDeletingOneExtensionsPod
VERBOSE: time="2023-12-15 00:34:39.399" level=info msg="Host IP 10.138.0.80" test=TestGameServerCreationAfterDeletingOneExtensionsPod
VERBOSE: time="2023-12-15 00:34:39.399" level=info msg="Pod IPs [{10.72.5.41}]" test=TestGameServerCreationAfterDeletingOneExtensionsPod
VERBOSE: time="2023-12-15 00:34:39.399" level=info msg="Name of extensions pod 3: agones-extensions-7b5b7ff4bc-mgx9m" test=TestGameServerCreationAfterDeletingOneExtensionsPod
VERBOSE: time="2023-12-15 00:34:39.399" level=info msg="Host IP 10.138.0.102" test=TestGameServerCreationAfterDeletingOneExtensionsPod
VERBOSE: time="2023-12-15 00:34:39.399" level=info msg="Pod IPs [{10.72.11.11}]" test=TestGameServerCreationAfterDeletingOneExtensionsPod
VERBOSE: time="2023-12-15 00:34:39.399" level=info msg="Removing one of the Extensions Pods: agones-extensions-5d8d46b879-2ljnr" test=TestGameServerCreationAfterDeletingOneExtensionsPod
VERBOSE: panic: test timed out after 10m0s
VERBOSE: running tests:
VERBOSE: 	TestGameServerCreationAfterDeletingOneExtensionsPod (10m0s)
VERBOSE: 
VERBOSE: goroutine 647 [running]:
VERBOSE: testing.(*M).startAlarm.func1()
VERBOSE: 	/usr/local/go/src/testing/testing.go:2241 +0x219
VERBOSE: created by time.goFunc
VERBOSE: 	/usr/local/go/src/time/sleep.go:176 +0x48

Context:

  • #3595
  • #3541

What you expected to happen:

Tests to pass.

How to reproduce it (as minimally and precisely as possible):

Not entirely sure. Seems to mostly happen in CI, have yet to try and reproduce locally.

Anything else we need to know?:

Environment:

  • Agones version: dev
  • Kubernetes version (use kubectl version): varies
  • Cloud provider or hardware configuration: GKE
  • Install method (yaml/helm): helm
  • Troubleshooting guide log(s): See above.
  • Others: N/A

markmandel avatar Jan 18 '24 17:01 markmandel

I am able to reproduce this issue locally.

Steps:

  1. Installed dev version of Agones in cluster
  2. Scaled agones-extensions deployment replicas to 4 using this command: kubectl scale deployment agones-extensions --replicas=4 -n agones-system

deployment.apps/agones-extensions scaled

  1. Then, I ran go test -count=1 on https://github.com/googleforgames/agones/tree/main/test/e2e/extensions and got below error:
WARN[2024-01-30 08:37:30.546] Error creating inClusterConfig, trying to build config from flagsunable to load in-cluster configuration, KUBERNETES_SERVICE_HOST and KUBERNETES_SERVICE_PORT must be defined  error="unable to load in-cluster configuration, KUBERNETES_SERVICE_HOST and KUBERNETES_SERVICE_PORT must be defined" source=framework
INFO[2024-01-30 08:37:30.548] Starting e2e test(s)                          cloudProduct=generic featureGates="CountsAndLists=false&DisableResyncOnSDKServer=false&Example=false&FleetAllocationOverflow=true&GKEAutopilotExtendedDurationPods=false&PlayerAllocationFilter=false&PlayerTracking=false" gameServerImage="us-docker.pkg.dev/agones-images/examples/simple-game-server:0.25" namespace= perfOutputDir= pullSecret= stressTestLevel=0 version=
INFO[2024-01-30 08:37:30.548] Cleaning up now.                             
INFO[2024-01-30 08:37:31.597] Finished cleanup.                            
INFO[2024-01-30 08:42:31.773] Length of pod list is 4                       test=TestGameServerCreationAfterDeletingOneExtensionsPod
INFO[2024-01-30 08:42:31.773] Name of extensions pod 0: agones-extensions-7d5bbd6bb8-4xrc6  test=TestGameServerCreationAfterDeletingOneExtensionsPod
INFO[2024-01-30 08:42:31.773] Host IP 10.138.0.51                           test=TestGameServerCreationAfterDeletingOneExtensionsPod
INFO[2024-01-30 08:42:31.773] Pod IPs [{10.72.11.73}]                       test=TestGameServerCreationAfterDeletingOneExtensionsPod
INFO[2024-01-30 08:42:31.773] Name of extensions pod 1: agones-extensions-7d5bbd6bb8-dkj5p  test=TestGameServerCreationAfterDeletingOneExtensionsPod
INFO[2024-01-30 08:42:31.773] Host IP 10.138.0.49                           test=TestGameServerCreationAfterDeletingOneExtensionsPod
INFO[2024-01-30 08:42:31.773] Pod IPs [{10.72.9.6}]                         test=TestGameServerCreationAfterDeletingOneExtensionsPod
INFO[2024-01-30 08:42:31.773] Name of extensions pod 2: agones-extensions-7d5bbd6bb8-p7b2j  test=TestGameServerCreationAfterDeletingOneExtensionsPod
INFO[2024-01-30 08:42:31.773] Host IP 10.138.0.44                           test=TestGameServerCreationAfterDeletingOneExtensionsPod
INFO[2024-01-30 08:42:31.773] Pod IPs [{10.72.4.8}]                         test=TestGameServerCreationAfterDeletingOneExtensionsPod
INFO[2024-01-30 08:42:31.773] Name of extensions pod 3: agones-extensions-7d5bbd6bb8-v2gnd  test=TestGameServerCreationAfterDeletingOneExtensionsPod
INFO[2024-01-30 08:42:31.773] Host IP 10.138.0.43                           test=TestGameServerCreationAfterDeletingOneExtensionsPod
INFO[2024-01-30 08:42:31.773] Pod IPs [{10.72.3.22}]                        test=TestGameServerCreationAfterDeletingOneExtensionsPod
INFO[2024-01-30 08:42:31.773] Removing one of the Extensions Pods: agones-extensions-7d5bbd6bb8-dkj5p  test=TestGameServerCreationAfterDeletingOneExtensionsPod
panic: test timed out after 10m0s
running tests:
        TestGameServerCreationAfterDeletingOneExtensionsPod (10m0s)

goroutine 705 [running]:
testing.(*M).startAlarm.func1()
        /usr/lib/google-golang/src/testing/testing.go:2380 +0x385
created by time.goFunc
        /usr/lib/google-golang/src/time/sleep.go:177 +0x2d

goroutine 1 [chan receive, 10 minutes]

Similarly, When I scale replica to 1 then i got below error which is expected behavior as per test:

WARN[2024-01-30 07:11:50.114] Error creating inClusterConfig, trying to build config from flagsunable to load in-cluster configuration, KUBERNETES_SERVICE_HOST and KUBERNETES_SERVICE_PORT must be defined  error="unable to load in-cluster configuration, KUBERNETES_SERVICE_HOST and KUBERNETES_SERVICE_PORT must be defined" source=framework
INFO[2024-01-30 07:11:50.116] Starting e2e test(s)                          cloudProduct=generic featureGates="CountsAndLists=false&DisableResyncOnSDKServer=false&Example=false&FleetAllocationOverflow=true&GKEAutopilotExtendedDurationPods=false&PlayerAllocationFilter=false&PlayerTracking=false" gameServerImage="us-docker.pkg.dev/agones-images/examples/simple-game-server:0.25" namespace= perfOutputDir= pullSecret= stressTestLevel=0 version=
INFO[2024-01-30 07:11:50.116] Cleaning up now.                             
INFO[2024-01-30 07:11:51.197] Finished cleanup.                            
INFO[2024-01-30 07:16:51.362] Length of pod list is 1                       test=TestGameServerCreationAfterDeletingOneExtensionsPod
INFO[2024-01-30 07:16:51.362] Name of extensions pod 0: agones-extensions-7d5bbd6bb8-p7b2j  test=TestGameServerCreationAfterDeletingOneExtensionsPod
INFO[2024-01-30 07:16:51.362] Host IP 10.138.0.44                           test=TestGameServerCreationAfterDeletingOneExtensionsPod
INFO[2024-01-30 07:16:51.362] Pod IPs [{10.72.4.8}]                         test=TestGameServerCreationAfterDeletingOneExtensionsPod
--- FAIL: TestGameServerCreationAfterDeletingOneExtensionsPod (300.16s)
    high_availability_test.go:36: 
                Error Trace:    /usr/local/google/home/ashutoshnsingh/Documents/googleforgames/agones/test/e2e/extensions/high_availability_test.go:36
                Error:          Received unexpected error:
                                context deadline exceeded
                Test:           TestGameServerCreationAfterDeletingOneExtensionsPod
    high_availability_test.go:46: 
                Error Trace:    /usr/local/google/home/ashutoshnsingh/Documents/googleforgames/agones/test/e2e/extensions/high_availability_test.go:46
                Error:          "1" is not greater than "1"
                Test:           TestGameServerCreationAfterDeletingOneExtensionsPod
                Messages:       Cluster has no Extensions pod or has only 1 extensions pod
panic: runtime error: index out of range [1] with length 1 [recovered]
        panic: runtime error: index out of range [1] with length 1

goroutine 56 [running]:
testing.tRunner.func1.2({0x1a9de40, 0xc00091fe48})
        /usr/lib/google-golang/src/testing/testing.go:1631 +0x24a
testing.tRunner.func1()
        /usr/lib/google-golang/src/testing/testing.go:1634 +0x377
panic({0x1a9de40?, 0xc00091fe48?})

ashutosji avatar Jan 30 '24 09:01 ashutosji

I did bit debugging, the wait.PollUntilContextTimeout() function is getinng false and nil value on each poll and resulting it's terminate polling after timeout duration here: https://github.com/googleforgames/agones/blob/main/test/e2e/extensions/high_availability_test.go#L108 And this is happening because of this if condition: https://github.com/googleforgames/agones/blob/main/test/e2e/extensions/high_availability_test.go#L114-L116

ashutosji avatar Jan 30 '24 10:01 ashutosji

Reopening, since we're still seeing this issue.

generic-1.28: 
generic-1.28: BUILD FAILURE: Build step failure: build step 1 "e2e-runner" failed: step exited with non-zero status: 2
generic-1.28: ERROR: (gcloud.builds.submit) build 9a08e38d-eb78-4d7c-bdbd-8da0ba26f940 completed with status "FAILURE"

From: https://console.cloud.google.com/cloud-build/builds/9a08e38d-eb78-4d7c-bdbd-8da0ba26f940;step=1?e=13803378&mods=logs_tg_prod&project=agones-images

echo "Starting e2e extensions high availability test!"
Starting e2e extensions high availability test!
gotestsum --format=testname --post-run-command="sh -c 'echo; echo --- RAW VERBOSE OUTPUT ---; jq -j \"select(.Output != null) | (\\\"VERBOSE: \\\" + .Output)\" < /tmp/agones.gotestsum.json; echo --- END RAW VERBOSE OUTPUT ---'" --jsonfile=/tmp/agones.gotestsum.json --hide-summary=skipped --rerun-fails=2  --packages=agones.dev/agones/test/e2e/extensions -- -mod=vendor -race -parallel=16 -parallel=1 -args \
	--kubeconfig /root/.kube/config --cloud-product="generic" --gameserver-image=us-docker.pkg.dev/agones-images/examples/simple-game-server:0.27 --feature-gates="PlayerAllocationFilter=true&PlayerTracking=true&FleetAllocationOverflow=false&CountsAndLists=true&DisableResyncOnSDKServer=true&Example=true" --pullsecret=
time="2024-03-12 21:52:36.045" level=warning msg="Error creating inClusterConfig, trying to build config from flagsunable to load in-cluster configuration, KUBERNETES_SERVICE_HOST and KUBERNETES_SERVICE_PORT must be defined" error="unable to load in-cluster configuration, KUBERNETES_SERVICE_HOST and KUBERNETES_SERVICE_PORT must be defined" source=framework
time="2024-03-12 21:52:36.058" level=info msg="Starting e2e test(s)" cloudProduct=generic featureGates="CountsAndLists=true&DisableResyncOnSDKServer=true&Example=true&FleetAllocationOverflow=false&GKEAutopilotExtendedDurationPods=false&PlayerAllocationFilter=true&PlayerTracking=true" gameServerImage="us-docker.pkg.dev/agones-images/examples/simple-game-server:0.27" namespace= perfOutputDir= pullSecret= stressTestLevel=0 version=
time="2024-03-12 21:52:36.059" level=info msg="Cleaning up now."
time="2024-03-12 21:52:36.545" level=info msg="Finished cleanup."
FAIL test/e2e/extensions
=== RUN   TestGameServerCreationAfterDeletingOneExtensionsPod
    high_availability_test.go:36: 
        	Error Trace:	/go/src/agones.dev/agones/test/e2e/extensions/high_availability_test.go:36
        	Error:      	Received unexpected error:
        	            	context deadline exceeded
        	Test:       	TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.631" level=info msg="Length of pod list is 3" test=TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.631" level=info msg="Logging events for the Deployment due to pod count > 2 before deleting extensions pod" podCount=3 test=TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.631" level=info msg="Name of extensions pod 0: agones-extensions-5b5fbcfdc9-j4z4d" test=TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.632" level=info msg="Status of extensions pod {Failed [{DisruptionTarget True 0001-01-01 00:00:00 +0000 UTC 2024-03-12 11:01:53 +0000 UTC TerminationByKubelet The node was low on resource: ephemeral-storage. Threshold quantity: 10120387530, available: 9866260Ki. } {Initialized True 0001-01-01 00:00:00 +0000 UTC 2024-03-12 11:00:09 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2024-03-12 11:01:53 +0000 UTC PodFailed } {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2024-03-12 11:01:53 +0000 UTC PodFailed } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2024-03-12 11:00:09 +0000 UTC  }] The node was low on resource: ephemeral-storage. Threshold quantity: 10120387530, available: 9866260Ki.  Evicted  10.138.0.72 10.68.34.144 [{10.68.34.144}] 2024-03-12 11:00:09 +0000 UTC [] [{agones-extensions {nil nil &ContainerStateTerminated{ExitCode:137,Signal:0,Reason:ContainerStatusUnknown,Message:The container could not be located when the pod was terminated,StartedAt:0001-01-01 00:00:00 +0000 UTC,FinishedAt:0001-01-01 00:00:00 +0000 UTC,ContainerID:,}} {nil nil &ContainerStateTerminated{ExitCode:137,Signal:0,Reason:ContainerStatusUnknown,Message:The container could not be located when the pod was deleted.  The container used to be Running,StartedAt:0001-01-01 00:00:00 +0000 UTC,FinishedAt:0001-01-01 00:00:00 +0000 UTC,ContainerID:,}} false 1 us-docker.pkg.dev/agones-images/ci/agones-extensions:1.39.0-dev-66cd0e2   0xc000345daf map[] nil}] BestEffort [] }" test=TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.632" level=info msg="Dumping Events:" kind= test=TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.722" level=info msg="Name of extensions pod 1: agones-extensions-66f4bfccc9-2xc7k" test=TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.722" level=info msg="Status of extensions pod {Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2024-03-12 21:37:36 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2024-03-12 21:37:42 +0000 UTC  } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2024-03-12 21:37:42 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2024-03-12 21:37:36 +0000 UTC  }]    10.138.0.70 10.68.33.24 [{10.68.33.24}] 2024-03-12 21:37:36 +0000 UTC [] [{agones-extensions {nil &ContainerStateRunning{StartedAt:2024-03-12 21:37:38 +0000 UTC,} nil} {nil nil nil} true 0 us-docker.pkg.dev/agones-images/ci/agones-extensions:1.39.0-dev-206df53 us-docker.pkg.dev/agones-images/ci/agones-extensions@sha256:7f7011be6d4bb3649cc306df72e2b88f6729ba1cd7b4ba61621eb207bba3d34c containerd://2341d18a8767db31024a0737c5ecc55dc50a379f013ff9d09235c5736010a014 0xc000320b5f map[] nil}] BestEffort [] }" test=TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.723" level=info msg="Dumping Events:" kind= test=TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.792" level=info msg="Event!" lastTimestamp="2024-03-12 21:37:36 +0000 UTC" message="Successfully assigned agones-system/agones-extensions-66f4bfccc9-2xc7k to gke-standard-e2e-test-c-agones-system-ea6808b5-2f2p" reason=Scheduled test=TestGameServerCreationAfterDeletingOneExtensionsPod type=Normal
time="2024-03-12 21:57:36.793" level=info msg="Event!" lastTimestamp="2024-03-12 21:37:36 +0000 UTC" message="Pulling image \"us-docker.pkg.dev/agones-images/ci/agones-extensions:1.39.0-dev-206df53\"" reason=Pulling test=TestGameServerCreationAfterDeletingOneExtensionsPod type=Normal
time="2024-03-12 21:57:36.794" level=info msg="Event!" lastTimestamp="2024-03-12 21:37:37 +0000 UTC" message="Successfully pulled image \"us-docker.pkg.dev/agones-images/ci/agones-extensions:1.39.0-dev-206df53\" in 1.323s (1.323s including waiting)" reason=Pulled test=TestGameServerCreationAfterDeletingOneExtensionsPod type=Normal
time="2024-03-12 21:57:36.795" level=info msg="Event!" lastTimestamp="2024-03-12 21:37:38 +0000 UTC" message="Created container agones-extensions" reason=Created test=TestGameServerCreationAfterDeletingOneExtensionsPod type=Normal
time="2024-03-12 21:57:36.795" level=info msg="Event!" lastTimestamp="2024-03-12 21:37:38 +0000 UTC" message="Started container agones-extensions" reason=Started test=TestGameServerCreationAfterDeletingOneExtensionsPod type=Normal
time="2024-03-12 21:57:36.796" level=info msg="Name of extensions pod 2: agones-extensions-66f4bfccc9-ldrgv" test=TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.796" level=info msg="Status of extensions pod {Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2024-03-12 21:37:36 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2024-03-12 21:37:42 +0000 UTC  } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2024-03-12 21:37:42 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2024-03-12 21:37:36 +0000 UTC  }]    10.138.0.70 10.68.33.23 [{10.68.33.23}] 2024-03-12 21:37:36 +0000 UTC [] [{agones-extensions {nil &ContainerStateRunning{StartedAt:2024-03-12 21:37:38 +0000 UTC,} nil} {nil nil nil} true 0 us-docker.pkg.dev/agones-images/ci/agones-extensions:1.39.0-dev-206df53 us-docker.pkg.dev/agones-images/ci/agones-extensions@sha256:7f7011be6d4bb3649cc306df72e2b88f6729ba1cd7b4ba61621eb207bba3d34c containerd://62338c0d1d395bd6dfeb5c4271c7e49cd328a1e75a8ca9044890f9706fbccc0a 0xc00032145f map[] nil}] BestEffort [] }" test=TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.797" level=info msg="Dumping Events:" kind= test=TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.864" level=info msg="Event!" lastTimestamp="2024-03-12 21:37:36 +0000 UTC" message="Successfully assigned agones-system/agones-extensions-66f4bfccc9-ldrgv to gke-standard-e2e-test-c-agones-system-ea6808b5-2f2p" reason=Scheduled test=TestGameServerCreationAfterDeletingOneExtensionsPod type=Normal
time="2024-03-12 21:57:36.864" level=info msg="Event!" lastTimestamp="2024-03-12 21:37:36 +0000 UTC" message="Pulling image \"us-docker.pkg.dev/agones-images/ci/agones-extensions:1.39.0-dev-206df53\"" reason=Pulling test=TestGameServerCreationAfterDeletingOneExtensionsPod type=Normal
time="2024-03-12 21:57:36.864" level=info msg="Event!" lastTimestamp="2024-03-12 21:37:37 +0000 UTC" message="Successfully pulled image \"us-docker.pkg.dev/agones-images/ci/agones-extensions:1.39.0-dev-206df53\" in 1.32s (1.32s including waiting)" reason=Pulled test=TestGameServerCreationAfterDeletingOneExtensionsPod type=Normal
time="2024-03-12 21:57:36.865" level=info msg="Event!" lastTimestamp="2024-03-12 21:37:38 +0000 UTC" message="Created container agones-extensions" reason=Created test=TestGameServerCreationAfterDeletingOneExtensionsPod type=Normal
time="2024-03-12 21:57:36.865" level=info msg="Event!" lastTimestamp="2024-03-12 21:37:38 +0000 UTC" message="Started container agones-extensions" reason=Started test=TestGameServerCreationAfterDeletingOneExtensionsPod type=Normal
time="2024-03-12 21:57:36.865" level=info msg="Removing one of the Extensions Pods: agones-extensions-66f4bfccc9-2xc7k" test=TestGameServerCreationAfterDeletingOneExtensionsPod
FAIL test/e2e/extensions.TestGameServerCreationAfterDeletingOneExtensionsPod (-1.00s)

=== Failed
=== FAIL: test/e2e/extensions  (0.00s)
time="2024-03-12 21:52:36.045" level=warning msg="Error creating inClusterConfig, trying to build config from flagsunable to load in-cluster configuration, KUBERNETES_SERVICE_HOST and KUBERNETES_SERVICE_PORT must be defined" error="unable to load in-cluster configuration, KUBERNETES_SERVICE_HOST and KUBERNETES_SERVICE_PORT must be defined" source=framework
time="2024-03-12 21:52:36.058" level=info msg="Starting e2e test(s)" cloudProduct=generic featureGates="CountsAndLists=true&DisableResyncOnSDKServer=true&Example=true&FleetAllocationOverflow=false&GKEAutopilotExtendedDurationPods=false&PlayerAllocationFilter=true&PlayerTracking=true" gameServerImage="us-docker.pkg.dev/agones-images/examples/simple-game-server:0.27" namespace= perfOutputDir= pullSecret= stressTestLevel=0 version=
time="2024-03-12 21:52:36.059" level=info msg="Cleaning up now."
time="2024-03-12 21:52:36.545" level=info msg="Finished cleanup."
panic: test timed out after 10m0s
running tests:
	TestGameServerCreationAfterDeletingOneExtensionsPod (10m0s)

goroutine 659 [running]:
testing.(*M).startAlarm.func1()
	/usr/local/go/src/testing/testing.go:2259 +0x259
created by time.goFunc
	/usr/local/go/src/time/sleep.go:176 +0x45

goroutine 1 [chan receive, 10 minutes]:
testing.(*T).Run(0xc0000e01a0, {0x276788b, 0x33}, 0x2814490)
	/usr/local/go/src/testing/testing.go:1649 +0x871
testing.runTests.func1(0x0?)
	/usr/local/go/src/testing/testing.go:2054 +0x85
testing.tRunner(0xc0000e01a0, 0xc0004f9960)
	/usr/local/go/src/testing/testing.go:1595 +0x262
testing.runTests(0xc000303040?, {0x37b70e0, 0x2, 0x2}, {0x0?, 0x0?, 0x37d6820?})
	/usr/local/go/src/testing/testing.go:2052 +0x8ae
testing.(*M).Run(0xc000303040)
	/usr/local/go/src/testing/testing.go:1925 +0xcd8
agones.dev/agones/test/e2e/extensions.TestMain(0x721c6274cb0a8bbd?)
	/go/src/agones.dev/agones/test/e2e/extensions/main_test.go:64 +0x55e
main.main()
	_testmain.go:51 +0x308

goroutine 267 [IO wait]:
internal/poll.runtime_pollWait(0x7fcf98724eb0, 0x72)
	/usr/local/go/src/runtime/netpoll.go:343 +0x85
internal/poll.(*pollDesc).wait(0xc000184420, 0xc0005c0000?, 0x0)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0xb1
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc000184400, {0xc0005c0000, 0x8000, 0x8000})
	/usr/local/go/src/internal/poll/fd_unix.go:164 +0x405
net.(*netFD).Read(0xc000184400, {0xc0005c0000, 0x8000, 0x8000})
	/usr/local/go/src/net/fd_posix.go:55 +0x4b
net.(*conn).Read(0xc000122010, {0xc0005c0000, 0x8000, 0x8000})
	/usr/local/go/src/net/net.go:179 +0xad
crypto/tls.(*atLeastReader).Read(0xc0005ddd88, {0xc0005c0000, 0x8000, 0x8000})
	/usr/local/go/src/crypto/tls/conn.go:805 +0x89
bytes.(*Buffer).ReadFrom(0xc000204d28, {0x2a46640, 0xc0005ddd88})
	/usr/local/go/src/bytes/buffer.go:211 +0x110
crypto/tls.(*Conn).readFromUntil(0xc000204a80, {0x7fcf50298958?, 0xc000696000}, 0x5)
	/usr/local/go/src/crypto/tls/conn.go:827 +0x1ea
crypto/tls.(*Conn).readRecordOrCCS(0xc000204a80, 0x0)
	/usr/local/go/src/crypto/tls/conn.go:625 +0x606
crypto/tls.(*Conn).readRecord(...)
	/usr/local/go/src/crypto/tls/conn.go:587
crypto/tls.(*Conn).Read(0xc000204a80, {0xc000251000, 0x1000, 0x0?})
	/usr/local/go/src/crypto/tls/conn.go:1369 +0x290
bufio.(*Reader).Read(0xc000109bc0, {0xc000174040, 0x9, 0x9})
	/usr/local/go/src/bufio/bufio.go:244 +0x4be
io.ReadAtLeast({0x2a44de0, 0xc000109bc0}, {0xc000174040, 0x9, 0x9}, 0x9)
	/usr/local/go/src/io/io.go:335 +0xd0
io.ReadFull(...)
	/usr/local/go/src/io/io.go:354
golang.org/x/net/http2.readFrameHeader({0xc000174040, 0x9, 0x9}, {0x2a44de0, 0xc000109bc0})
	/go/src/agones.dev/agones/vendor/golang.org/x/net/http2/frame.go:237 +0x9b
golang.org/x/net/http2.(*Framer).ReadFrame(0xc000174000)
	/go/src/agones.dev/agones/vendor/golang.org/x/net/http2/frame.go:498 +0xf5
golang.org/x/net/http2.(*clientConnReadLoop).run(0xc0004f1f98)
	/go/src/agones.dev/agones/vendor/golang.org/x/net/http2/transport.go:2275 +0x205
golang.org/x/net/http2.(*ClientConn).readLoop(0xc0002ee000)
	/go/src/agones.dev/agones/vendor/golang.org/x/net/http2/transport.go:2170 +0xe5
created by golang.org/x/net/http2.(*Transport).newClientConn in goroutine 266
	/go/src/agones.dev/agones/vendor/golang.org/x/net/http2/transport.go:821 +0x1c6b

goroutine 22 [select]:
k8s.io/apimachinery/pkg/util/wait.loopConditionUntilContext({0x2a5db00, 0xc0001fef50}, {0x2a53568?, 0xc0004a2ca0}, 0x1, 0x0, 0x2a5d9e8?)
	/go/src/agones.dev/agones/vendor/k8s.io/apimachinery/pkg/util/wait/loop.go:91 +0x3d3
k8s.io/apimachinery/pkg/util/wait.PollUntilContextTimeout({0x2a5d9e8, 0x3806fc0}, 0x3b9aca00, 0x1?, 0x80?, 0x1?)
	/go/src/agones.dev/agones/vendor/k8s.io/apimachinery/pkg/util/wait/poll.go:48 +0xd9
agones.dev/agones/test/e2e/extensions.waitForAgonesExtensionsRunning(...)
	/go/src/agones.dev/agones/test/e2e/extensions/high_availability_test.go:117
agones.dev/agones/test/e2e/extensions.TestGameServerCreationAfterDeletingOneExtensionsPod(0xc0000e0340)
	/go/src/agones.dev/agones/test/e2e/extensions/high_availability_test.go:60 +0x8f9
testing.tRunner(0xc0000e0340, 0x2814490)
	/usr/local/go/src/testing/testing.go:1595 +0x262
created by testing.(*T).Run in goroutine 1
	/usr/local/go/src/testing/testing.go:1648 +0x846
FAIL	agones.dev/agones/test/e2e/extensions	600.690s

=== FAIL: test/e2e/extensions TestGameServerCreationAfterDeletingOneExtensionsPod (unknown)
    high_availability_test.go:36: 
        	Error Trace:	/go/src/agones.dev/agones/test/e2e/extensions/high_availability_test.go:36
        	Error:      	Received unexpected error:
        	            	context deadline exceeded
        	Test:       	TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.631" level=info msg="Length of pod list is 3" test=TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.631" level=info msg="Logging events for the Deployment due to pod count > 2 before deleting extensions pod" podCount=3 test=TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.631" level=info msg="Name of extensions pod 0: agones-extensions-5b5fbcfdc9-j4z4d" test=TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.632" level=info msg="Status of extensions pod {Failed [{DisruptionTarget True 0001-01-01 00:00:00 +0000 UTC 2024-03-12 11:01:53 +0000 UTC TerminationByKubelet The node was low on resource: ephemeral-storage. Threshold quantity: 10120387530, available: 9866260Ki. } {Initialized True 0001-01-01 00:00:00 +0000 UTC 2024-03-12 11:00:09 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2024-03-12 11:01:53 +0000 UTC PodFailed } {ContainersReady False 0001-01-01 00:00:00 +0000 UTC 2024-03-12 11:01:53 +0000 UTC PodFailed } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2024-03-12 11:00:09 +0000 UTC  }] The node was low on resource: ephemeral-storage. Threshold quantity: 10120387530, available: 9866260Ki.  Evicted  10.138.0.72 10.68.34.144 [{10.68.34.144}] 2024-03-12 11:00:09 +0000 UTC [] [{agones-extensions {nil nil &ContainerStateTerminated{ExitCode:137,Signal:0,Reason:ContainerStatusUnknown,Message:The container could not be located when the pod was terminated,StartedAt:0001-01-01 00:00:00 +0000 UTC,FinishedAt:0001-01-01 00:00:00 +0000 UTC,ContainerID:,}} {nil nil &ContainerStateTerminated{ExitCode:137,Signal:0,Reason:ContainerStatusUnknown,Message:The container could not be located when the pod was deleted.  The container used to be Running,StartedAt:0001-01-01 00:00:00 +0000 UTC,FinishedAt:0001-01-01 00:00:00 +0000 UTC,ContainerID:,}} false 1 us-docker.pkg.dev/agones-images/ci/agones-extensions:1.39.0-dev-66cd0e2   0xc000345daf map[] nil}] BestEffort [] }" test=TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.632" level=info msg="Dumping Events:" kind= test=TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.722" level=info msg="Name of extensions pod 1: agones-extensions-66f4bfccc9-2xc7k" test=TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.722" level=info msg="Status of extensions pod {Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2024-03-12 21:37:36 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2024-03-12 21:37:42 +0000 UTC  } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2024-03-12 21:37:42 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2024-03-12 21:37:36 +0000 UTC  }]    10.138.0.70 10.68.33.24 [{10.68.33.24}] 2024-03-12 21:37:36 +0000 UTC [] [{agones-extensions {nil &ContainerStateRunning{StartedAt:2024-03-12 21:37:38 +0000 UTC,} nil} {nil nil nil} true 0 us-docker.pkg.dev/agones-images/ci/agones-extensions:1.39.0-dev-206df53 us-docker.pkg.dev/agones-images/ci/agones-extensions@sha256:7f7011be6d4bb3649cc306df72e2b88f6729ba1cd7b4ba61621eb207bba3d34c containerd://2341d18a8767db31024a0737c5ecc55dc50a379f013ff9d09235c5736010a014 0xc000320b5f map[] nil}] BestEffort [] }" test=TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.723" level=info msg="Dumping Events:" kind= test=TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.792" level=info msg="Event!" lastTimestamp="2024-03-12 21:37:36 +0000 UTC" message="Successfully assigned agones-system/agones-extensions-66f4bfccc9-2xc7k to gke-standard-e2e-test-c-agones-system-ea6808b5-2f2p" reason=Scheduled test=TestGameServerCreationAfterDeletingOneExtensionsPod type=Normal
time="2024-03-12 21:57:36.793" level=info msg="Event!" lastTimestamp="2024-03-12 21:37:36 +0000 UTC" message="Pulling image \"us-docker.pkg.dev/agones-images/ci/agones-extensions:1.39.0-dev-206df53\"" reason=Pulling test=TestGameServerCreationAfterDeletingOneExtensionsPod type=Normal
time="2024-03-12 21:57:36.794" level=info msg="Event!" lastTimestamp="2024-03-12 21:37:37 +0000 UTC" message="Successfully pulled image \"us-docker.pkg.dev/agones-images/ci/agones-extensions:1.39.0-dev-206df53\" in 1.323s (1.323s including waiting)" reason=Pulled test=TestGameServerCreationAfterDeletingOneExtensionsPod type=Normal
time="2024-03-12 21:57:36.795" level=info msg="Event!" lastTimestamp="2024-03-12 21:37:38 +0000 UTC" message="Created container agones-extensions" reason=Created test=TestGameServerCreationAfterDeletingOneExtensionsPod type=Normal
time="2024-03-12 21:57:36.795" level=info msg="Event!" lastTimestamp="2024-03-12 21:37:38 +0000 UTC" message="Started container agones-extensions" reason=Started test=TestGameServerCreationAfterDeletingOneExtensionsPod type=Normal
time="2024-03-12 21:57:36.796" level=info msg="Name of extensions pod 2: agones-extensions-66f4bfccc9-ldrgv" test=TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.796" level=info msg="Status of extensions pod {Running [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2024-03-12 21:37:36 +0000 UTC  } {Ready True 0001-01-01 00:00:00 +0000 UTC 2024-03-12 21:37:42 +0000 UTC  } {ContainersReady True 0001-01-01 00:00:00 +0000 UTC 2024-03-12 21:37:42 +0000 UTC  } {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2024-03-12 21:37:36 +0000 UTC  }]    10.138.0.70 10.68.33.23 [{10.68.33.23}] 2024-03-12 21:37:36 +0000 UTC [] [{agones-extensions {nil &ContainerStateRunning{StartedAt:2024-03-12 21:37:38 +0000 UTC,} nil} {nil nil nil} true 0 us-docker.pkg.dev/agones-images/ci/agones-extensions:1.39.0-dev-206df53 us-docker.pkg.dev/agones-images/ci/agones-extensions@sha256:7f7011be6d4bb3649cc306df72e2b88f6729ba1cd7b4ba61621eb207bba3d34c containerd://62338c0d1d395bd6dfeb5c4271c7e49cd328a1e75a8ca9044890f9706fbccc0a 0xc00032145f map[] nil}] BestEffort [] }" test=TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.797" level=info msg="Dumping Events:" kind= test=TestGameServerCreationAfterDeletingOneExtensionsPod
time="2024-03-12 21:57:36.864" level=info msg="Event!" lastTimestamp="2024-03-12 21:37:36 +0000 UTC" message="Successfully assigned agones-system/agones-extensions-66f4bfccc9-ldrgv to gke-standard-e2e-test-c-agones-system-ea6808b5-2f2p" reason=Scheduled test=TestGameServerCreationAfterDeletingOneExtensionsPod type=Normal
time="2024-03-12 21:57:36.864" level=info msg="Event!" lastTimestamp="2024-03-12 21:37:36 +0000 UTC" message="Pulling image \"us-docker.pkg.dev/agones-images/ci/agones-extensions:1.39.0-dev-206df53\"" reason=Pulling test=TestGameServerCreationAfterDeletingOneExtensionsPod type=Normal
time="2024-03-12 21:57:36.864" level=info msg="Event!" lastTimestamp="2024-03-12 21:37:37 +0000 UTC" message="Successfully pulled image \"us-docker.pkg.dev/agones-images/ci/agones-extensions:1.39.0-dev-206df53\" in 1.32s (1.32s including waiting)" reason=Pulled test=TestGameServerCreationAfterDeletingOneExtensionsPod type=Normal
time="2024-03-12 21:57:36.865" level=info msg="Event!" lastTimestamp="2024-03-12 21:37:38 +0000 UTC" message="Created container agones-extensions" reason=Created test=TestGameServerCreationAfterDeletingOneExtensionsPod type=Normal
time="2024-03-12 21:57:36.865" level=info msg="Event!" lastTimestamp="2024-03-12 21:37:38 +0000 UTC" message="Started container agones-extensions" reason=Started test=TestGameServerCreationAfterDeletingOneExtensionsPod type=Normal
time="2024-03-12 21:57:36.865" level=info msg="Removing one of the Extensions Pods: agones-extensions-66f4bfccc9-2xc7k" test=TestGameServerCreationAfterDeletingOneExtensionsPod

markmandel avatar Mar 12 '24 22:03 markmandel