Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Flaky SDK Conformance Tests #1779

Closed
markmandel opened this issue Sep 1, 2020 · 7 comments
Closed

Flaky SDK Conformance Tests #1779

markmandel opened this issue Sep 1, 2020 · 7 comments
Labels
area/tests Unit tests, e2e tests, anything to make sure things don't break help wanted We would love help on these issues. Please come help us! kind/bug These are bugs.
Milestone
1.9.0

Comments

@markmandel
Copy link
Member

What happened:

For a long time the SDK Conformance tests will occasionally flake.

What you expected to happen:

Them to pass all the time.

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

That's the problem - they are flaky 😄

This bug is a place to track the flakiness responses, and see if we can see a common pattern.

Anything else we need to know?:

Environment:

  • Agones version: Dev
  • Kubernetes version (use kubectl version): 1.16
  • Cloud provider or hardware configuration: GKE
  • Install method (yaml/helm): Helm
  • Troubleshooting guide log(s):

Context: https://console.cloud.google.com/cloud-build/builds/b61c074d-d6cd-4f68-b289-74a2d0f7ad2b?project=258182270954

/usr/bin/make run-sdk-conformance-no-build SDK_FOLDER=go GRPC_PORT=9001 HTTP_PORT=9101 FEATURE_GATES=PlayerTracking=true TESTS=ready,allocate,setlabel,setannotation,gameserver,health,shutdown,watch,reserve,getplayercapacity,setplayercapacity,playerconnect,playerdisconnect,getplayercount,isplayerconnected,getconnectedplayers
/usr/bin/make ensure-image IMAGE_TAG=agones-build-sdk-node:2ca282f4dc BUILD_TARGET=build-build-sdk-image SDK_FOLDER=node
/usr/bin/make ensure-image IMAGE_TAG=gcr.io/agones-images/agones-sdk:1.9.0-b831bb7 BUILD_TARGET=build-agones-sdk-server-image
/usr/bin/make ensure-image IMAGE_TAG=agones-build-sdk-go:6a1f217343 BUILD_TARGET=build-build-sdk-image SDK_FOLDER=go
+ /root/sdktest.sh
+ cd /go/src/agones.dev/agones/test/sdk/nodejs
+ npm run testSDK
/usr/bin/make ensure-image IMAGE_TAG=gcr.io/agones-images/agones-sdk:1.9.0-b831bb7 BUILD_TARGET=build-agones-sdk-server-image

> @ testSDK /go/src/agones.dev/agones/test/sdk/nodejs
> node ./testSDKClient.js

attempting to connect
connected!
{"message":"Ready request has been received!","sdkName":"node","severity":"info","source":"*sdkserver.LocalSDKServer","time":"2020-09-01T10:31:19.057025478Z"}
{"message":"Connected to watch GameServer...","sdkName":"node","severity":"info","source":"*sdkserver.LocalSDKServer","time":"2020-09-01T10:31:19.057141103Z"}
{"message":"Gameserver update received","sdkName":"node","severity":"info","source":"*sdkserver.LocalSDKServer","time":"2020-09-01T10:31:19.057354483Z"}
{"message":"Getting GameServer details","sdkName":"node","severity":"info","source":"*sdkserver.LocalSDKServer","time":"2020-09-01T10:31:19.063013179Z"}
watch {
  objectMeta: {
    name: 'local',
    namespace: 'default',
    uid: '5229266051501086426',
    resourceVersion: 'v1',
    generation: 1,
    creationTimestamp: 1598956249,
    deletionTimestamp: 0,
    annotationsMap: [ [Array] ],
    labelsMap: [ [Array] ]
  },
  spec: {
    health: {
      disabled: false,
      periodSeconds: 3,
      failureThreshold: 5,
      initialDelaySeconds: 10
    }
  },
  status: {
    state: 'Ready',
    address: '127.0.0.1',
    portsList: [ [Object] ],
    players: undefined
  }
}
Setting annotation  5229266051501086426
{"message":"Setting annotation","sdkName":"node","severity":"info","source":"*sdkserver.LocalSDKServer","time":"2020-09-01T10:31:19.069942988Z","values":{"key":"annotation","value":"5229266051501086426"}}
{"message":"Gameserver update received","sdkName":"node","severity":"info","source":"*sdkserver.LocalSDKServer","time":"2020-09-01T10:31:19.070179458Z"}
{"message":"Setting label","sdkName":"node","severity":"info","source":"*sdkserver.LocalSDKServer","time":"2020-09-01T10:31:19.07306106Z","values":{"key":"label","value":"1598956249"}}
{"message":"Gameserver update received","sdkName":"node","severity":"info","source":"*sdkserver.LocalSDKServer","time":"2020-09-01T10:31:19.07320512Z"}
watch {
  objectMeta: {
    name: 'local',
    namespace: 'default',
    uid: '5229266051501086426',
    resourceVersion: 'v1',
    generation: 1,
    creationTimestamp: 1598956249,
    deletionTimestamp: 0,
    annotationsMap: [ [Array], [Array] ],
    labelsMap: [ [Array] ]
  },
  spec: {
    health: {
      disabled: false,
      periodSeconds: 3,
      failureThreshold: 5,
      initialDelaySeconds: 10
    }
  },
  status: {
    state: 'Ready',
    address: '127.0.0.1',
    portsList: [ [Object] ],
    players: undefined
  }
}
gameServer {
  objectMeta: {
    name: 'local',
    namespace: 'default',
    uid: '5229266051501086426',
    resourceVersion: 'v1',
    generation: 1,
    creationTimestamp: 1598956249,
    deletionTimestamp: 0,
    annotationsMap: [ [Array] ],
    labelsMap: [ [Array] ]
  },
  spec: {
    health: {
      disabled: false,
      periodSeconds: 3,
      failureThreshold: 5,
      initialDelaySeconds: 10
    }
  },
  status: {
    state: 'Ready',
    address: '127.0.0.1',
    portsList: [ [Object] ],
    players: undefined
  }
}
creation Timestamp 1598956249
health undefined
watch {
  objectMeta: {
    name: 'local',
    namespace: 'default',
    uid: '5229266051501086426',
    resourceVersion: 'v1',
    generation: 1,
    creationTimestamp: 1598956249,
    deletionTimestamp: 0,
    annotationsMap: [ [Array], [Array] ],
    labelsMap: [ [Array], [Array] ]
  },
  spec: {
    health: {
      disabled: false,
      periodSeconds: 3,
      failureThreshold: 5,
      initialDelaySeconds: 10
    }
  },
  status: {
    state: 'Ready',
    address: '127.0.0.1',
    portsList: [ [Object] ],
    players: undefined
  }
}
{"duration":{"seconds":5},"message":"Reserve request has been received!","sdkName":"node","severity":"info","source":"*sdkserver.LocalSDKServer","time":"2020-09-01T10:31:19.07671884Z"}
{"message":"Health Ping Received!","sdkName":"node","severity":"info","source":"*sdkserver.LocalSDKServer","time":"2020-09-01T10:31:19.076763512Z"}
{"message":"Gameserver update received","sdkName":"node","severity":"info","source":"*sdkserver.LocalSDKServer","time":"2020-09-01T10:31:19.07695493Z"}
watch {
  objectMeta: {
    name: 'local',
    namespace: 'default',
    uid: '5229266051501086426',
    resourceVersion: 'v1',
    generation: 1,
    creationTimestamp: 1598956249,
    deletionTimestamp: 0,
    annotationsMap: [ [Array], [Array] ],
    labelsMap: [ [Array], [Array] ]
  },
  spec: {
    health: {
      disabled: false,
      periodSeconds: 3,
      failureThreshold: 5,
      initialDelaySeconds: 10
    }
  },
  status: {
    state: 'Reserved',
    address: '127.0.0.1',
    portsList: [ [Object] ],
    players: undefined
  }
}
{"message":"shutting down sdk server","severity":"info","source":"main","time":"2020-09-01T10:31:19.455406386Z"}
{"message":"Could not find a request which was expected","request":"allocate","sdkName":"node","severity":"error","source":"*sdkserver.LocalSDKServer","time":"2020-09-01T10:31:19.45549336Z"}
{"expected":["ready","allocate","setlabel","setannotation","gameserver","health","shutdown","watch","reserve"],"message":"Testing Failed","received":["ready","watch","gameserver","setannotation","setlabel","health","reserve"],"sdkName":"node","severity":"info","source":"*sdkserver.LocalSDKServer","time":"2020-09-01T10:31:19.455509623Z"}
/go/src/agones.dev/agones/sdks/nodejs/src/agonesSDK.js:130
			throw error;
			^

Error: 14 UNAVAILABLE: Connection dropped
    at Object.callErrorFromStatus (/go/src/agones.dev/agones/sdks/nodejs/node_modules/@grpc/grpc-js/build/src/call.js:31:26)
    at Object.onReceiveStatus (/go/src/agones.dev/agones/sdks/nodejs/node_modules/@grpc/grpc-js/build/src/client.js:327:49)
    at Object.onReceiveStatus (/go/src/agones.dev/agones/sdks/nodejs/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:305:181)
    at Http2CallStream.outputStatus (/go/src/agones.dev/agones/sdks/nodejs/node_modules/@grpc/grpc-js/build/src/call-stream.js:117:74)
    at Http2CallStream.maybeOutputStatus (/go/src/agones.dev/agones/sdks/nodejs/node_modules/@grpc/grpc-js/build/src/call-stream.js:156:22)
    at Http2CallStream.endCall (/go/src/agones.dev/agones/sdks/nodejs/node_modules/@grpc/grpc-js/build/src/call-stream.js:142:18)
    at Http2CallStream.disconnectListener (/go/src/agones.dev/agones/sdks/nodejs/node_modules/@grpc/grpc-js/build/src/call-stream.js:104:18)
    at Socket.<anonymous> (/go/src/agones.dev/agones/sdks/nodejs/node_modules/@grpc/grpc-js/build/src/subchannel.js:371:25)
    at Object.onceWrapper (events.js:422:26)
    at Socket.emit (events.js:327:22) {
  code: 14,
  details: 'Connection dropped',
  metadata: Metadata { internalRepr: Map {}, options: {} }
}
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! @ testSDK: `node ./testSDKClient.js`
npm ERR! Exit status 1
npm ERR! 
npm ERR! Failed at the @ testSDK script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.

npm ERR! A complete log of this run can be found in:
npm ERR!     /root/.npm/_logs/2020-09-01T10_31_19_506Z-debug.log
make[2]: *** [run-sdk-conformance-no-build] Error 1
includes/sdk.mk:145: recipe for target 'run-sdk-conformance-no-build' failed
make[1]: *** [run-sdk-conformance-test] Error 2
includes/sdk.mk:152: recipe for target 'run-sdk-conformance-test' failed
make: *** [run-sdk-conformance-test-node] Error 2
make: *** Waiting for unfinished jobs....
includes/sdk.mk:159: recipe for target 'run-sdk-conformance-test-node' failed
includes/sdk.mk:88: recipe for target 'run-sdk-command' failed
make[3]: *** [run-sdk-command] Error 1
  • Others:
@markmandel markmandel added kind/bug These are bugs. area/tests Unit tests, e2e tests, anything to make sure things don't break help wanted We would love help on these issues. Please come help us! labels Sep 1, 2020
@markmandel
Copy link
Member Author

https://console.cloud.google.com/cloud-build/builds/68a4c348-6b8f-40f8-ad6a-eaadb9d85c1d?project=258182270954

make[3]: Leaving directory '/workspace/build'
/usr/bin/make run-sdk-command COMMAND=build-sdk-test
Error: Failed to connect before the deadline
at checkState (/go/src/agones.dev/agones/sdks/nodejs/node_modules/@grpc/grpc-js/build/src/client.js:70:26)
at Timeout._onTimeout (/go/src/agones.dev/agones/sdks/nodejs/node_modules/@grpc/grpc-js/build/src/channel.js:297:17)
at listOnTimeout (internal/timers.js:549:17)
at processTimers (internal/timers.js:492:7)

@markmandel
Copy link
Member Author

https://console.cloud.google.com/cloud-build/builds/e2f2d946-e3fc-4a3b-8fb6-fd1b994a8ab7?project=258182270954

{"message":"shutting down sdk server","severity":"info","source":"main","time":"2020-09-08T21:43:45.966680175Z"}
{"message":"Could not find a request which was expected","request":"ready","sdkName":"go","severity":"error","source":"*sdkserver.LocalSDKServer","time":"2020-09-08T21:43:45.966802274Z"}
{"expected":["ready","allocate","setlabel","setannotation","gameserver","health","shutdown","watch","reserve","getplayercapacity","setplayercapacity","playerconnect","playerdisconnect","getplayercount","isplayerconnected","getconnectedplayers"],"message":"Testing Failed","received":[],"sdkName":"go","severity":"info","source":"*sdkserver.LocalSDKServer","time":"2020-09-08T21:43:45.966838567Z"}
make[1]: *** [run-sdk-conformance-no-build] Error 1
includes/sdk.mk:145: recipe for target 'run-sdk-conformance-no-build' failed
make: *** [run-sdk-conformance-test-go] Error 2
make: *** Waiting for unfinished jobs....
includes/sdk.mk:162: recipe for target 'run-sdk-conformance-test-go' failed

@aLekSer
Copy link
Collaborator

aLekSer commented Sep 9, 2020

https://console.cloud.google.com/cloud-build/builds/3884cc38-5a5b-4a59-adaf-0b9ef7fcf736;step=23?project=agones-images
This one is different and I see that make runs was out of sync at all
SDK server listener already has closed when node ./testSDKClient.js was in attempting to connect stage.

docker run -p 9002:9002 -p 9102:9102 -e "FEATURE_GATES=" -e "ADDRESS=" -e "TEST=ready,allocate,setlabel,setannotation,gameserver,health,shutdown,watch,reserve" -e "SDK_NAME=node" -e "TIMEOUT=30" -e "DELAY=1" \
--net=host gcr.io/agones-images/agones-sdk:1.9.0-3317115 --grpc-port 9002 --http-port 9102
WARNING: Published ports are discarded when using host network mode
{"ctlConf":{"Address":"","IsLocal":false,"LocalFile":"","Delay":1,"Timeout":30,"Test":"ready,allocate,setlabel,setannotation,gameserver,health,shutdown,watch,reserve","TestSdkName":"node","GRPCPort":9002,"HTTPPort":9102},"featureGates":"ContainerPortAllocation=true\u0026Example=true\u0026PlayerTracking=false\u0026SDKWatchSendOnExecute=false","message":"Starting sdk sidecar","severity":"info","source":"main","time":"2020-09-09T14:59:37.647849379Z","version":"1.9.0-3317115"}
{"message":"Waiting 1 seconds before starting","severity":"info","source":"main","time":"2020-09-09T14:59:37.648074846Z"}
{"grpcEndpoint":":9002","message":"Starting SDKServer grpc service...","severity":"info","source":"main","time":"2020-09-09T14:59:38.649733702Z"}
{"httpEndpoint":":9102","message":"Starting SDKServer grpc-gateway...","severity":"info","source":"main","time":"2020-09-09T14:59:39.650910324Z"}
cd build-sdk-images; \
if [ "node" != "tool" ] && [ -f node/sdktest.sh ] ; then \
	cd - ; \
	/usr/bin/make ensure-build-sdk-image SDK_FOLDER=node ; \
	docker run --rm -v /workspace/build//.config/gcloud:/root/.config/gcloud -v ~/.kube/:/root/.kube -v ~/.config/helm:/root/.config/helm -v ~/.cache/helm:/root/.cache/helm -v /workspace:/go/src/agones.dev/agones -v /workspace/build//.gomod:/go/pkg/mod -v /workspace/build//.gocache:/root/.cache/go-build -e "VERSION=1.9.0-3317115" \
		--net host -e AGONES_SDK_GRPC_PORT=9002 -e AGONES_SDK_HTTP_PORT=9102 -e FEATURE_GATES=  agones-build-sdk-node:2ca282f4dc sdktest ; \
else \
	echo "Command sdktest not found - nothing to execute" ; \
fi
/workspace/build
/usr/bin/make ensure-image IMAGE_TAG=gcr.io/agones-images/agones-sdk:1.9.0-3317115 BUILD_TARGET=build-agones-sdk-server-image
{"message":"shutting down sdk server","severity":"info","source":"main","time":"2020-09-09T14:59:48.078413197Z"}
{"message":"Received requests match expected list. Test run was successful","sdkName":"go","severity":"info","source":"*sdkserver.LocalSDKServer","time":"2020-09-09T14:59:48.07854491Z"}
{"error":"http: Server closed","message":"http server closed","severity":"info","source":"main","time":"2020-09-09T14:59:48.078693847Z"}
# run with feature flags enabled
/usr/bin/make run-sdk-conformance-no-build SDK_FOLDER=go GRPC_PORT=9001 HTTP_PORT=9101 FEATURE_GATES=PlayerTracking=true TESTS=ready,allocate,setlabel,setannotation,gameserver,health,shutdown,watch,reserve,getplayercapacity,setplayercapacity,playerconnect,playerdisconnect,getplayercount,isplayerconnected,getconnectedplayers
/usr/bin/make ensure-image IMAGE_TAG=agones-build-sdk-node:2ca282f4dc BUILD_TARGET=build-build-sdk-image SDK_FOLDER=node
/usr/bin/make ensure-image IMAGE_TAG=agones-build-sdk-go:6a1f217343 BUILD_TARGET=build-build-sdk-image SDK_FOLDER=go
/usr/bin/make ensure-image IMAGE_TAG=gcr.io/agones-images/agones-sdk:1.9.0-3317115 BUILD_TARGET=build-agones-sdk-server-image
{"message":"shutting down sdk server","severity":"info","source":"main","time":"2020-09-09T15:00:08.649479539Z"}
{"message":"Could not find a request which was expected","request":"ready","sdkName":"node","severity":"error","source":"*sdkserver.LocalSDKServer","time":"2020-09-09T15:00:08.649615765Z"}
{"expected":["ready","allocate","setlabel","setannotation","gameserver","health","shutdown","watch","reserve"],"message":"Testing Failed","received":[],"sdkName":"node","severity":"info","source":"*sdkserver.LocalSDKServer","time":"2020-09-09T15:00:08.649638801Z"}
make[2]: *** [run-sdk-conformance-no-build] Error 1
includes/sdk.mk:145: recipe for target 'run-sdk-conformance-no-build' failed
make[1]: *** [run-sdk-conformance-test] Error 2
includes/sdk.mk:152: recipe for target 'run-sdk-conformance-test' failed
includes/sdk.mk:159: recipe for target 'run-sdk-conformance-test-node' failed
make: *** [run-sdk-conformance-test-node] Error 2
make: *** Waiting for unfinished jobs....
DOCKER_RUN_ARGS="--net host -e AGONES_SDK_GRPC_PORT=9001 -e AGONES_SDK_HTTP_PORT=9101 -e FEATURE_GATES=PlayerTracking=true " COMMAND=sdktest /usr/bin/make run-sdk-command & \
docker run -p 9001:9001 -p 9101:9101 -e "FEATURE_GATES=PlayerTracking=true" -e "ADDRESS=" -e "TEST=ready,allocate,setlabel,setannotation,gameserver,health,shutdown,watch,reserve,getplayercapacity,setplayercapacity,playerconnect,playerdisconnect,getplayercount,isplayerconnected,getconnectedplayers" -e "SDK_NAME=go" -e "TIMEOUT=30" -e "DELAY=1" \
--net=host gcr.io/agones-images/agones-sdk:1.9.0-3317115 --grpc-port 9001 --http-port 9101
WARNING: Published ports are discarded when using host network mode
+ /root/sdktest.sh
+ cd /go/src/agones.dev/agones/test/sdk/nodejs
+ npm run testSDK
{"ctlConf":{"Address":"","IsLocal":false,"LocalFile":"","Delay":1,"Timeout":30,"Test":"ready,allocate,setlabel,setannotation,gameserver,health,shutdown,watch,reserve,getplayercapacity,setplayercapacity,playerconnect,playerdisconnect,getplayercount,isplayerconnected,getconnectedplayers","TestSdkName":"go","GRPCPort":9001,"HTTPPort":9101},"featureGates":"ContainerPortAllocation=true\u0026Example=true\u0026PlayerTracking=true\u0026SDKWatchSendOnExecute=false","message":"Starting sdk sidecar","severity":"info","source":"main","time":"2020-09-09T15:00:19.400098007Z","version":"1.9.0-3317115"}
{"message":"Waiting 1 seconds before starting","severity":"info","source":"main","time":"2020-09-09T15:00:19.400242234Z"}

> @ testSDK /go/src/agones.dev/agones/test/sdk/nodejs
> node ./testSDKClient.js

attempting to connect

@aLekSer
Copy link
Collaborator

aLekSer commented Sep 9, 2020

TODO to make debugging much easier using logs only: we should add timestamps into all log lines, not just inside SDK server Go binary:

--net=host gcr.io/agones-images/agones-sdk:1.9.0-3317115 --grpc-port 9002 --http-port 9102
WARNING: Published ports are discarded when using host network mode
{"ctlConf":{"Address":"","IsLocal":false,"LocalFile":"","Delay":1,"Timeout":30,"Test":"ready,allocate,setlabel,setannotation,gameserver,health,shutdown,watch,reserve","TestSdkName":"node","GRPCPort":9002,"HTTPPort":9102},"featureGates":"ContainerPortAllocation=true\u0026Example=true\u0026PlayerTracking=false\u0026SDKWatchSendOnExecute=false","message":"Starting sdk sidecar","severity":"info","source":"main","time":"2020-09-09T14:59:37.647849379Z","version":"1.9.0-3317115"}

but before these lines > node ./testSDKClient.js also.

@aLekSer
Copy link
Collaborator

aLekSer commented Sep 11, 2020

I found the similar thing with Golang sdk when tests step overlaps with sdk-conformance in cloud build:

"tests": 	docker run --rm -v /workspace/build//.config/gcloud:/root/.config/gcloud -v ~/.kube/:/root/.kube -v ~/.config/helm:/root/.config/helm -v ~/.cache/helm:/root/.cache/helm -v /workspace:/go/src/agones.dev/agones -v /workspace/build//.gomod:/go/pkg/mod -v /workspace/build//.gocache:/root/.cache/go-build -e "VERSION=1.9.0-b63b5f7" \
Step #17 - "tests": 		 agones-build-sdk-go:6a1f217343 test ; \
Step #17 - "tests": else \
Step #17 - "tests": 	echo "Command test not found - nothing to execute" ; \
Step #17 - "tests": fi
Step #17 - "tests": /workspace/build
Step #23 - "sdk-conformance": + /root/sdktest.sh
Step #23 - "sdk-conformance": + GO111MODULE=off
Step #23 - "sdk-conformance": + cd /go/src/agones.dev/agones/test/sdk/go
Step #23 - "sdk-conformance": + go run sdk-client-test.go

make tests would run test.sh, while SDK conformance would run sdktest.sh but them should not be invoked simultaneously.

@aLekSer aLekSer mentioned this issue Sep 11, 2020
Merged
@markmandel
Copy link
Member Author

@aLekSer seems like we can close this now? Looks like you solved the problem!

@aLekSer
Copy link
Collaborator

aLekSer commented Sep 15, 2020

Yes, I left this ticket in an Open state just to see the rarity of failures in at least 10 runs.

@aLekSer aLekSer closed this as completed Sep 15, 2020
@markmandel markmandel added this to the 1.9.0 milestone Sep 22, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
area/tests Unit tests, e2e tests, anything to make sure things don't break help wanted We would love help on these issues. Please come help us! kind/bug These are bugs.
Projects
None yet
Milestone
1.9.0
Development

No branches or pull requests
2 participants
@markmandel @aLekSer