Agones: Gameservers using nodejs sdk die with GOAWAY ENHANCE_YOUR_CALM too_many_pings

[msannikov]

What happened:
All my gameservers die after 30-90 minutes when I started using nodejs sdk and upgraded agones from 1.0.0 to 1.3.0:
Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"

Anything else we need to know?:
This seems to be related to grpc/grpc-node#138. I've tried to upgrade agones's grpc to the latest v1.24.2, but that did not help.

gameserver container logs:

I 2020-01-23T18:24:14.871311349Z NODE_ENV production
...
E 2020-01-23T19:00:05.907467004Z   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings" 

agones-gameserver-sidecar logs:

I 2020-01-23T18:24:15.216010496Z Starting sdk sidecar 
...
I 2020-01-23T18:24:17.885301089Z Health Ping Received 
...
I 2020-01-23T18:25:05.185913691Z Received Ready request, adding to queue 
...
I 2020-01-23T18:25:05.902915961Z Health Ping Received 
...
I 2020-01-23T19:00:10.401435848Z GameServer Health Check failed 
I 2020-01-23T19:00:15.264434202Z Sending GameServer Event to connectedStreams 
I 2020-01-23T19:00:15.401710405Z GameServer Health Check failed 
I 2020-01-23T19:00:20.401923432Z GameServer Health Check failed 
I 2020-01-23T19:00:20.402013117Z GameServer has failed health check 
...

Environment:

• Agones version: 1.3.0
• Kubernetes version (use kubectl version): 1.13.12-gke.17
• Cloud provider or hardware configuration: GCP
• Install method (yaml/helm): N/A
• Troubleshooting guide log(s): N/A
• Others: N/A

[markmandel]

@KamiMay @steven-supersolid - have you seen this?

I'm also assuming you are using the most up to date nodejs client as well?

[steven-supersolid]

We're using the REST API but may be related to grpc/grpc-node#717

There is a comment to enable further debug https://github.com/grpc/grpc-node/issues/717#issuecomment-457408937

To troubleshoot @msannikov is it possible to run against Agones 1.2.0 and see if the error still occurs - this will make comparisons between versions easier?

If the latest version of grpc does not work then we may have to roll back to the latest working version, provided that is compatible with the grpc server in Agones 1.3.0

[msannikov]

I am using the latest nodejs sdk (1.3.0).

Just ran with agones 1.2.0, got the same error after 50 minutes. I've also passed GRPC_TRACE=all and GRPC_VERBOSITY=ERROR variables to gameserver container, but did not get much info:

E0129 14:25:39.175718686       6 chttp2_transport.cc:1167]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"

[steven-supersolid]

Thank you for helping to debug this. As you can reproduce would it be possible to try Agones 1.1.0 and reconfirm that 1.0.0 is still working?

Looking at past releases we did not change the node grpc npm module version, it has been 1.22.2 since Agones 1.0.0. This may indicate the change is due to an update to the grpc server version or incompatible grpc client version, however I don't believe this was changed in 1.2.0. Another possibility is due to the change to default port in #1180

[Cixelyn]

We're also encountering this issue. NodeJS SDK v1.2.0, Agones v1.2.0. Default Agones configuration through the quickstart yaml (e.g. no helm).

Our game servers get killed similarly:

E0207 19:43:15.721769804 24 chttp2_transport.cc:1167] Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"

Happens anywhere from 60-200 minutes or so.

[markmandel]

Looking at a few options here, it _might_ be that the node client is being too aggressive with it's pings?

I can't find it now, but there was a Java Netty user who solves this problem by configuring various keep alive options (I can't find the issue anymore, which is annoying me), such as
permitKeepAliveWithoutCalls and permitKeepAliveTime

There is the ability to configure these, looking at:
https://github.com/grpc/grpc-node/issues/154
https://github.com/grpc/grpc-node/issues/706

Various config options:
https://github.com/grpc/grpc/blob/v1.20.1/include/grpc/impl/codegen/grpc_types.h

It might be worth setting some of these and seeing if that resolves the issues.

[markmandel]

Just touching base - seeing if any of the above strategies helped?

[markmandel]

Just touching base again - wanted to see where you ended up with this?

Would also be curious to know what you are specifically doing with the SDK, that might also help narrow things down.

[msannikov]

I've used sdk only for ready() and health() requests. I've switched to REST. Don't currently have time/spare free cluster to debug this.

[markmandel]

Thanks for letting us know :+1:

[markmandel]

For reference, I found the issue with the workaround:
https://github.com/grpc/grpc-java/issues/5188#issuecomment-449449420

[raoneel]

I'm also getting this issue, thanks for looking into it. What's the schedule for releasing the 1.5.0 version of the node sdk?

[markmandel]

1.5.0 release comes out on Tuesday, but I don't think there are any changes, unfortunately.

We really need to setup an environment to reproduce these issues.

[markmandel]

Trying to reproduce, I just had a node.js server run overnight on 1.5.0-rc with the following configuration:
https://github.com/googleforgames/agones/pull/1469

And it's still up and healthy.

root@f03f33dbd4cf:/go/src/agones.dev/agones# kubectl logs nodejs-simple-bm5sq -c agones-gameserver-sidecar
{"ctlConf":{"Address":"localhost","IsLocal":false,"LocalFile":"","Delay":0,"Timeout":0,"Test":"","GRPCPort":9357,"HTTPPort":9358},"featureGates":"ContainerPortAllocation=false\u0026Example=true\u0026PlayerTracking=false","message":"Starting sdk sidecar","severity":"info","source":"main","time":"2020-04-14T01:08:59.206158265Z","version":"1.5.0-rc"}
{"gsKey":"default/nodejs-simple-bm5sq","message":"Created GameServer sidecar","severity":"info","source":"*sdkserver.SDKServer","time":"2020-04-14T01:08:59.208991438Z"}
{"grpcEndpoint":"localhost:9357","message":"Starting SDKServer grpc service...","severity":"info","source":"main","time":"2020-04-14T01:08:59.232362931Z"}
{"gsKey":"default/nodejs-simple-bm5sq","message":"Starting workers...","queue":"agones.dev.default.nodejs-simple-bm5sq","severity":"info","source":"*sdkserver.SDKServer","time":"2020-04-14T01:08:59.310046005Z","workers":1}
{"httpEndpoint":"localhost:9358","message":"Starting SDKServer grpc-gateway...","severity":"info","source":"main","time":"2020-04-14T01:09:00.244648641Z"}

root@f03f33dbd4cf:/go/src/agones.dev/agones# kubectl logs nodejs-simple-bm5sq -c nodejs-simple  | grep ENHANCE_YOUR_CALM
root@f03f33dbd4cf:/go/src/agones.dev/agones#

:shrug: This is on a slower health check ping? What are yours set to? (maybe that is a workaround?)

[raoneel]

I've actually completely disabled health checking and I still saw this. My GameServer workflow is

Reserve(20) -> [DNS registration stuff] -> Ready() -> Allocate()

And I believe I've seen that error when calling Ready/Allocate. I'm not sure exactly which one, I will check my logs to see if I can give more info. I think it happens after calling allocate because I've seen Allocated GameServers with 0 players having joined (which is unusual in the way I set up my app, since users join immediately after allocating). So I think those GameServers died immediately after calling Allocate.

EDIT: I checked the logs for my long standing Allocated servers (>20 mins) and didn't see this problem. But..previously I added some code to shutdown Allocated servers if it got into this weird state (where it got the ENHANCE_YOUR_CALM issue, but stayed in Allocated, so no one could join). So the issue might still be happening, but those servers are just removed. That gives more evidence that this is happening when calling Allocate. Maybe too many successive Allocate calls?

[markmandel]

Maybe too many successive Allocate calls?

Shouldn't make any difference on the type of call as far as I can tell. It's the underlying gRPC connection that's causing the issue - but I'd like to be able to replicate so I can try some workarounds in the linked issues and determine if it's been fixed or not.

[raoneel]

One idea to replicate this, could you simulate a scenario where multiple GameServers are making calls at the same time? I believe I was getting this more when lots of people were connecting, which caused the autoscaler to spin up new GameServers. Maybe trigger a fleet scale up and add lots of health() calls and see what happens?

[markmandel]

One idea to replicate this, could you simulate a scenario where multiple GameServers are making calls at the same time

It's possible, but this seems unlikely a culprit. The SDK talks to it's own gRPC sidecar process, I don't know how they could be impacting each other? I mean, it's possible?

[lfg-ryan]

I am currently getting this. Nothing super fancy. Nodejs server doing health checks on a 20 second interval where the configuration period is 60s. Using agones 1.5.0.

What is the current suggested work around/fix?

[markmandel]

@lfg-ryan can you check with the 1.6.0 SDK please?

The SDK API is the same, but the backing gRPC implementation has been switched out. Be good to know if there is still this issue.

[markmandel]

Checking in again to see if anyone has had this issue since the update in the 1.6.0 SDK updates?

[markmandel]

It's been over a week with no response. I'm going to close this issue for now. Please reopen if people still have this issue.

[lfg-ryan]

Sorry for the delay, I have not been able to get back to this. I will be able to in the next week. I will reopen or start a new issue if it is not resolved.

[raoneel]

EDIT: Removed standard error message which I thought was causing the issue.

I'm still seeing issues after upgrading to 1.8.0. It looks like some % of my node servers will still randomly crash after 5-90 minutes. In the last 24 hours for my project, it seems like around 450 servers crashed randomly, and 300 shutdown correctly.

This seems to be flakey and I can't tell from the logs what makes these crash specifically.
Some more info on my setup:

GKE with node pool autoscaling
no health checking
fleet + autoscaler with config (some values replaced with X)

apiVersion: "agones.dev/v1"
kind: Fleet
metadata:
  name: dj3d-fleet
spec:
  replicas: X
  template:
    spec:
      ports:
        - name: default
          portPolicy: Dynamic
          containerPort: 8079
          protocol: TCP
      health:
        disabled: true
        initialDelaySeconds: 60
        failureThreshold: 3

---
apiVersion: "autoscaling.agones.dev/v1"
kind: FleetAutoscaler
metadata:
  name: dj3d-autoscaler
spec:
  fleetName: dj3d-fleet
  policy:
    type: Buffer
    buffer:
      bufferSize: XX
      maxReplicas: XXX

I'd be happy to add some additional logging to my servers if it would help debug this. I'm just not sure where to add it

[markmandel]

Thanks for reporting! Can you please provide the full error logging, so we can see all the details?

[raoneel]

After digging into the logs I'm actually not seeing the ENHANCE_YOUR_CALM error anymore. It just seems like my servers will randomly go into the "shutdown" state. So they are not crashing as they were previously but they are still shutting down (without any calls to shutdown() from my end). Should I create a new issue for this?

[markmandel]

@raoneel yes please!