Nodejs-pubsub: Getting GOAWAY error

Created on 28 Dec 2017 · 29Comments · Source: googleapis/nodejs-pubsub

I have been getting the following error a lot after upgrading to 0.15.0

Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"

It seems that the grpc module is printing it (it is the only place in my code base where this string exists) and pubsub is the only component using grpc... Anyone else having this problem? What is the impact and how can we stop it?

Thanks!
Mo

Environment details

OS: Debian 8.10, x86_64 GNU/Linux
Node.js version: 6.12.2
npm version: 3.10.10
@google-cloud/pubsub version: 0.16.1

Steps to reproduce

Unsure, we are subscribing with multiple instances to a very active subscription

pubsub p2 triaged for GA bug

Source

mkamioner

Most helpful comment

Sorry, the fix was not shipped with 1.8.0. I'm creating a new release (v1.8.4) that includes this fix. I'll update this thread after it's done.

y-zeng on 8 Jan 2018

👍2 ❤1 🎉1

All 29 comments

This issue was moved to grpc/grpc-node#138

stephenplusplus on 28 Dec 2017

Thanks for reporting. I moved the issue to the gRPC repo, since it shouldn't be logging anything unless a user opts-in for that. As far as the error itself (too many pings), is this anything we need to be worried about @callmehiphop?

stephenplusplus on 28 Dec 2017

@mkamioner

Could you describe your deployment environment? The error is likely from a proxy between your client and the GCP service.

wenbozhu on 4 Jan 2018

We run on GKE in GCP. We didn't create any proxy between my client and pubsub and I am unaware of any proxies that exist by default.

mkamioner on 4 Jan 2018

@mkamioner

Thanks for the info. One more question, how soon did you see the error, after the stream was opened?

wenbozhu on 4 Jan 2018

I'm getting the same with version 0.16.1

rvillane on 4 Jan 2018

@wenbozhu in my most recent logs I initiate the connection 08:59:17 and the first error occurs @ 14:03:00. From that point it consistently re-occurs on the hour but not every hour (strange).

Here is an example:

E1228 14:03:00.117621924      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1228 16:03:50.323131306      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1228 17:04:22.202916299      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1228 20:05:10.558617429      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1228 21:05:22.105440952      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1228 22:06:01.389912933      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1229 00:06:13.582234487      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1229 01:06:35.161913991      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1229 02:06:35.314368801      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1229 03:06:47.515937509      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1229 05:09:49.093620147      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1229 06:09:37.586189424      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1229 07:09:54.284050047      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1229 11:10:20.440515153      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1229 16:12:04.981807827      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1230 00:16:36.654963239      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1230 01:17:00.605992805      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1230 05:18:43.957560584      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1230 06:18:48.283699085      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1230 09:19:35.028748569      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1230 10:19:46.818521952      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1230 13:20:25.096976548      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1230 14:20:57.143170263      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1230 15:20:50.274729532      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1230 16:20:54.880674065      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1230 17:21:07.851103925      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1231 00:22:38.238116498      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1231 02:23:03.537033404      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1231 03:23:15.907218899      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1231 07:24:03.487587281      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1231 08:24:27.392483578      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1231 10:24:52.660965167      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1231 11:25:19.539137407      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1231 12:25:23.207442435      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1231 14:26:40.090942356      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1231 16:26:37.840394228      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1231 19:28:06.309392701      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1231 21:27:50.818383530      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E1231 23:28:23.582235036      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0101 01:29:58.505372749      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0101 02:30:05.455040999      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0101 10:32:02.867810906      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0101 12:32:06.341291508      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0101 13:31:54.443162588      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0101 17:33:28.030865028      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0101 18:33:00.779645583      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0101 22:34:44.337638199      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0101 23:35:06.416398275      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0102 00:35:19.354039067      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0102 03:36:51.412283382      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0102 06:37:19.486895014      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0102 07:38:08.825468219      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0102 09:38:10.951810384      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0102 12:39:02.985451665      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0102 13:39:23.500176906      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0102 14:40:10.392002706      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0102 15:39:31.820980020      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0102 16:40:16.968085654      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0102 19:39:54.634580677      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0102 20:41:03.274507411      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0103 00:41:52.183306048      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0103 03:43:01.804411937      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0103 14:47:16.874566428      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0103 17:48:03.778525393      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0103 21:48:42.810535040      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0104 00:49:59.887270255      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0104 01:50:33.453060583      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0104 02:50:42.531002612      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0104 03:50:41.354668132      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0104 04:50:57.751567061      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0104 05:50:58.272540249      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0104 07:51:44.686055140      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0104 08:51:28.640229643      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0104 09:52:00.924753201      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0104 11:52:31.357451439      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0104 13:53:07.309155629      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0104 15:54:13.613259404      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0104 16:54:18.126859871      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"
E0104 17:54:37.253329098      21 chttp2_transport.cc:1147]   Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings"

mkamioner on 4 Jan 2018

I can also report getting this on version 0.15.0 on node 8.9 on GKE as well. Same behavior of the long initial duration and then the hourly report.

baronfel on 5 Jan 2018

We believe the issue is caused by a bug introduced in grpc 1.7.0 (fixed in 1.8.0).

@y-zeng

The error should only happen when there is no outstanding request on a channel. Let us know if this is not the case.

wenbozhu on 6 Jan 2018

We were using 1.8.0 (just double checked) :-/

mkamioner on 7 Jan 2018

Same for us, our deployed grpc version is 1.8.0 per the lock file.

baronfel on 8 Jan 2018

Sorry, the fix was not shipped with 1.8.0. I'm creating a new release (v1.8.4) that includes this fix. I'll update this thread after it's done.

y-zeng on 8 Jan 2018

👍2 ❤1 🎉1

Yes please! 😄

nunofgs on 9 Jan 2018

@y-zeng we've locked our dependency on gRPC to the 1.7.x range, due to a bug introduced in 1.8.0: https://github.com/grpc/grpc-node/issues/130. Do you know if that issue has been resolved?

stephenplusplus on 9 Jan 2018

I've published the gRPC core v1.8.4 release (https://github.com/grpc/grpc/releases/tag/v1.8.4) which included the PING bug fixes.

@murgatroid99 could you please do a new grpc-node release with v1.8.4?

y-zeng on 10 Jan 2018

@murgatroid99 do you know if there is any update on grpc/grpc-node#130?

y-zeng on 10 Jan 2018

I expect to be able to publish the grpc-node 1.8.4 by tomorrow, and it has a change that should improve that situation. Specifically, it makes some network errors (I think including that one) report a status of UNAVAILABLE, which should be retried.

murgatroid99 on 10 Jan 2018

I can see that the grpc-node 1.8.4 is still not published, and there is also no 1.8.4 tag for grpc on npm. When can we expect it to be published?

jkolaric on 18 Jan 2018

grpc-node 1.8.4 has been published. @mkamioner, @baronfel Could you please update grpc-node and verify the fix? Thanks!

y-zeng on 23 Jan 2018

Unfortunately after updating to grpc-node 1.8.4 the bug still occurs :-(

What is the next step @y-zeng ?

mkamioner on 30 Jan 2018

@y-zeng ping...

Bueller? Bueller?... ;-)

mkamioner on 5 Feb 2018

No longer relevant for us. We moved to SQS. I highly recommend getting this SDK stuff together. We were on pubsub for over a year and the we decided that the SDK is just not stable enough right now and we need something that is production ready

mkamioner on 4 Mar 2018

👍1

@mkamioner

Sorry to hear about this.

We had been tracking the issue with you and other users on the grpc repo.

https://github.com/grpc/grpc-node/issues/138#issuecomment-354649395

Would still be useful to have the log in case you have it.

Thanks.

wenbozhu on 6 Mar 2018

UPDATE: Probably best to mention we're on v 0.13.2 if the lib...

Just for anyone else that might find this thread.

We have recently had this issue, and I resolved it by having a new instance of pubsub for each subscription that we poll in our app. We had around 5 working on a single instance, but when we added a sixth we started to get the Received a GOAWAY with error code ENHANCE_YOUR_CALM and debug data equal to "too_many_pings" errors. Here is the example of what we changed:

We had:

import createPubsub from '@google-cloud/pubsub';

const pubsub = createPubsub({
  projectId: GCP_PROJECT_ID,
});

which we then wrapped and used like this:

const withLogging = (subscriptionKey, handleMessage) => message =>
  handleMessage(message)
    .then(() => {
      logger.info(`Processed Message for ${subscrippubsubtionKey}`);
      message.ack();
    })
    .catch((err) => {
      logger.error(`Could Not Process Message for ${subscriptionKey}: ${err.message}`, err);
    });

const toOptions = R.curry(
  (ps, topicKey, subscriptionKey, interval, maxInProgress, handleMessage) => {
    const topic = ps.topic(topicKey);
    const subscription = topic.subscription(subscriptionKey, {
      returnImmediately: true,
      interval,
      maxMessages: maxInProgress,
    });
    return Promise.resolve({
      topic,
      subscription,
      handleMessage: withLogging(subscriptionKey, handleMessage),
    });
  }
);

const createIfNotExists = R.curry(
  (field, options, exists) => {
    if (exists) {
      return Promise.resolve(options);
    }
    return options[field].create()
      .then(() => Promise.resolve(options));
  });

const confirmExists = R.curry(
  (field, options) =>
    options[field].exists()
      .then((data) => createIfNotExists(field, options, data[0])));

const subscribe = (options) => {
  options.subscription.on(
    'error', err =>
      logger.error(`error on subscription - ${options.subscription.name}: ${err}`, err)
  );
  options.subscription.on('message', options.handleMessage);
  return Promise.resolve(options);
};

export const initSubscription = R.pipeP(
      toOptions(pubsub),
      confirmExists('topic'),
      confirmExists('subscription'),
      subscribe);


export const ensureTopicExists = R.pipeP(
  (topicKey) => Promise.resolve({ topic: pubsub.topic(topicKey) }),
  confirmExists('topic')
);

export const pushToTopic = (sender, topicKey, requestId, data) =>
  new Promise((resolve, reject) => {
    const topic = pubsub.topic(topicKey);
    const attributes = {
      requestid: requestId,
      sender,
    };
    const message = { data, attributes };
    topic.publish(message, { raw: true }, (err) => {
      if (err) {
        reject(err);
      } else {
        resolve();
      }
    });
  });

But then we changed it to this (just the changed functions below):

const toOptions = R.curry(
  (topicKey, subscriptionKey, interval, maxInProgress, handleMessage, ps) => {
    const topic = ps.topic(topicKey);
    const subscription = topic.subscription(subscriptionKey, {
      returnImmediately: true,
      interval,
      maxMessages: maxInProgress,
    });
    return Promise.resolve({
      topic,
      subscription,
      handleMessage: withLogging(subscriptionKey, handleMessage),
    });
  }
);

export const initSubscription =
  (topicKey, subscriptionKey, interval, maxInProgress, handleMessage) => {
    const localPubsub = createPubsub({
      projectId: GCP_PROJECT_ID,
    });
    return R.pipeP(
      toOptions(topicKey, subscriptionKey, interval, maxInProgress, handleMessage),
      confirmExists('topic'),
      confirmExists('subscription'),
      subscribe)(localPubsub);
  };

initSubscription is called from elsewhere like this:

 initSubscription(TOPIC, SUBSCRIPTION,
                   INTERVAL_IN_MILLISECONDS,
                   MAX_MESSAGES_PER_PULL, callbackFunction),

UPDATE 2

Although this removed the error, we instead had the issue where messages started to get stuck in the queue (see here: https://github.com/googleapis/nodejs-pubsub/issues/11). So I have reverted this change, updated the libs to 0.17.0, and and pegged GRPC to 1.7.3. We still see the error, but way less frequently, and no stuck messages.

domparry on 23 Mar 2018

We have what we think is a solution that we will publish in a gRPC patch release soon.

murgatroid99 on 27 Mar 2018

We have published gRPC version 1.10.1 with another change that should help with this.

murgatroid99 on 29 Mar 2018

I solved this problem as follow.

npm install google-gax --save

google-gax depends on gRPC, but google-gax v0.16.0 used in pubsub v0.18.0 uses the gRPC library with this bug. We need to upgrade to google-gax ^0.16.1.

Mahito on 9 Jun 2018

Any news on this issue or how to solve it? We're experiencing random peaks of these errors during the day for a couple minutes, and then they seem to resolve. We're seeing this using Spanner.
Any idea what could be causing this, or how to solve it?