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

A subscription suddenly and silently stops receiving messages #1779

Closed
webnator opened this issue Jul 26, 2023 · 5 comments
Closed

A subscription suddenly and silently stops receiving messages #1779

webnator opened this issue Jul 26, 2023 · 5 comments
Labels
api: pubsub Issues related to the googleapis/nodejs-pubsub API. priority: p2 Moderately-important priority. Fix may not be included in next release. type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns.

Comments

@webnator
Copy link

This issue might be related to #979 or #1135

Environment details

  • OS: Docker
  • Node.js version: node:18-alpine
  • npm version: 9.8.1
  • @google-cloud/pubsub version: 3.7.2

Steps to reproduce

  1. Set up a subscription to a Pubsub topic with the following settings:
    Delivery type: Pull
    Subscription expiration: Subscription expires in 31 days if there is no activity.
    Acknowledgement deadline: 300 seconds
    Subscription message retention duration: 7 days
    Retain acknowledged messages: No
    Exactly once delivery: Disabled
    Message ordering: Disabled
    Dead lettering: Disabled
    Retry policy: Retry immediately

Also, locally it's created with:

flowControl: {
  maxMessages: 15,
},
  1. Send messages (around 1 every 2-3 minutes)
  2. It works for hours, and at some point, the subscription decides not to receive any more messages. No error is thrown, no log, nothing

Other details

Code implementation

Code is running in cloud run.

This is how I register a subscription

async function registerTopic(topic, handler, opts) {
    try {
      await pubSubService.createTopicIfNotExists(topic);
    } catch (err) {
      logger.warn({ topic }, 'Topic couldnt be created. Attempting to create subscription');
    }
    const subscription = await createSubscriptionIfNotExists(topic, opts);

    subscription.on('message', queueHandler(handler));

    subscription.on('error', (...params) => {
      return errorHandling(subscription, { topic, handler, opts }, params);
    });

    subscription.on('close', (...params) => {
      return errorHandling(subscription, { topic, handler, opts }, params);
    });
  }

async function createSubscriptionIfNotExists(topicName, opts) {
      const topicObject = pubsub.topic(topicNameModel(config, topicName));
      const subsOpts = Object.assign({}, config.subscriptionOptions, opts);
      let bjSubs = topicObject.subscription(subscriptionNameModel(config, topicName), subsOpts);
      const [ subscriptionExists ] = await bjSubs.exists();
      if (!subscriptionExists) {
        const [ subscription ] = await topicObject.createSubscription(
          subscriptionNameModel(config, topicName), subsOpts);
        bjSubs = subscription;
      }

      return bjSubs;
    },

async function errorHandling(subscription, route) {
    const childLog = logger.child({ topic: route.topic });
    childLog.info('Error with subscription');
    try {
      process.nextTick(() => subscription.removeAllListeners());
      await subscription.close();
      childLog.debug('Listener removed');
    } catch (err) {
      childLog.debug('Couldnt remove listener, subscription already removed');
    }

    try {
      await registerTopic(route.topic, route.handler, route.opts);
    } catch (err) {
      childLog.error('Couldnt recreate topic subscription. Exiting');
      // For now we'll kill the process to make sure messages don't get stalled, we need to revisit this soon
      // eslint-disable-next-line no-process-exit
      process.exit(1);
    }
  }

As you see I'm handling both 'error' and 'close' events but they are never triggered

GRPC logs

By the recommendations in one of the threads, I've enabled the grpc trace logs, and this is what I have.

This is a normal execution of my process

2023-07-25 08:34:30.488 CEST
https://api.memoirframes.com/public/device/current-picture-id
2023-07-25 08:34:30.499 CEST
{"hostname":"localhost", "level":20, "msg":"Authenticating", "pid":12, "time":1.690266870499E12}
2023-07-25 08:34:30.510 CEST
�[90m�[3m2023-07-25 06:07:51�[23m�[39m �[36m�[1m[oas-tools]�[22m�[39m �[34m�[1mINFO:�[22m�[39m Requested GET /public/device/current-picture-id
2023-07-25 08:34:30.510 CEST
{"entrypoint":"/public/device/current-picture-id", "hostname":"localhost", "level":20, "method":"GET", "msg":"Executing", "pid":12, "requestUuid":"f36d15af-d622-494c-a2f9-2147a0fafa4b", "time":1.69026687051E12}
2023-07-25 08:34:30.511 CEST
{"hostname":"localhost", "level":20, "msg":"Publishing", "pid":12, "time":1.690266870511E12, "topic":"cycle-picture"}
2023-07-25 08:34:30.512 CEST
{"deviceId":8, "hostname":"localhost", "level":20, "msg":"Device requesting its current picture", "pid":12, "time":1.69026687051E12}
2023-07-25 08:34:30.512 CEST
{"deviceId":8, "hostname":"localhost", "level":30, "msg":"Time to update picture!", "pid":12, "time":1.690266870511E12}
2023-07-25 08:34:30.523 CEST
D 2023-07-25T06:34:30.523Z | channel | (59) dns:pubsub.googleapis.com:443 createResolvingCall [636] method="/google.pubsub.v1.Publisher/Publish", deadline=2023-07-25T06:36:10.522Z
2023-07-25 08:34:30.523 CEST
D 2023-07-25T06:34:30.523Z | channel | (59) dns:pubsub.googleapis.com:443 createRetryingCall [637] method="/google.pubsub.v1.Publisher/Publish"
2023-07-25 08:34:30.523 CEST
D 2023-07-25T06:34:30.523Z | channel | (59) dns:pubsub.googleapis.com:443 createLoadBalancingCall [638] method="/google.pubsub.v1.Publisher/Publish"
2023-07-25 08:34:30.554 CEST
{"entrypoint":"projects/memoir-frame/topics/dev_cycle-picture", "hostname":"localhost", "level":20, "method":"QUEUE", "msg":"Executing", "pid":12, "requestUuid":"435a0023-0c8e-46c4-8956-d4aa5b9fad80", "time":1.690266870554E12}
2023-07-25 08:34:30.554 CEST
{"deviceId":8, "hostname":"localhost", "level":20, "msg":"Cycling picture for device", "pid":12, "time":1.690266870554E12}
2023-07-25 08:34:30.556 CEST
{"hostname":"localhost", "level":20, "msg":"Published", "pid":12, "time":1.690266870555E12, "topic":"cycle-picture"}
2023-07-25 08:34:30.556 CEST
{"entrypoint":"/public/device/current-picture-id", "hostname":"localhost", "level":20, "method":"GET", "msg":"Executed correctly", "pid":12, "requestUuid":"f36d15af-d622-494c-a2f9-2147a0fafa4b", "time":1.690266870556E12}
2023-07-25 08:34:30.656 CEST
D 2023-07-25T06:34:30.656Z | channel | (30) dns:pubsub.googleapis.com:443 createResolvingCall [640] method="/google.pubsub.v1.Subscriber/ModifyAckDeadline", deadline=2023-07-25T06:35:30.656Z
2023-07-25 08:34:30.657 CEST
D 2023-07-25T06:34:30.657Z | channel | (30) dns:pubsub.googleapis.com:443 createRetryingCall [641] method="/google.pubsub.v1.Subscriber/ModifyAckDeadline"
2023-07-25 08:34:30.657 CEST
D 2023-07-25T06:34:30.657Z | channel | (30) dns:pubsub.googleapis.com:443 createLoadBalancingCall [642] method="/google.pubsub.v1.Subscriber/ModifyAckDeadline"
2023-07-25 08:34:30.676 CEST
{"entrypoint":"projects/memoir-frame/topics/dev_cycle-picture", "hostname":"localhost", "level":20, "method":"QUEUE", "msg":"Executed correctly", "pid":12, "requestUuid":"435a0023-0c8e-46c4-8956-d4aa5b9fad80", "time":1.690266870676E12}
2023-07-25 08:34:30.676 CEST
{"hostname":"localhost", "level":30, "msg":"Queue request completed", "pid":12, "requestUuid":"435a0023-0c8e-46c4-8956-d4aa5b9fad80", "time":1.690266870676E12}
2023-07-25 08:34:30.778 CEST
D 2023-07-25T06:34:30.778Z | channel | (30) dns:pubsub.googleapis.com:443 createResolvingCall [644] method="/google.pubsub.v1.Subscriber/Acknowledge", deadline=2023-07-25T06:35:30.777Z
2023-07-25 08:34:30.778 CEST
D 2023-07-25T06:34:30.778Z | channel | (30) dns:pubsub.googleapis.com:443 createRetryingCall [645] method="/google.pubsub.v1.Subscriber/Acknowledge"
2023-07-25 08:34:30.778 CEST
D 2023-07-25T06:34:30.778Z | channel | (30) dns:pubsub.googleapis.com:443 createLoadBalancingCall [646] method="/google.pubsub.v1.Subscriber/Acknowledge"
2023-07-25 08:34:31.857 CEST
https://api.memoirframes.com/public/device/picture/968
2023-07-25 08:34:31.861 CEST
{"hostname":"localhost", "level":20, "msg":"Authenticating", "pid":12, "time":1.690266871861E12}
2023-07-25 08:34:31.865 CEST
�[90m�[3m2023-07-25 06:07:87�[23m�[39m �[36m�[1m[oas-tools]�[22m�[39m �[34m�[1mINFO:�[22m�[39m Requested GET /public/device/picture/968
2023-07-25 08:34:31.912 CEST
{"entrypoint":"/public/device/picture/:pictureId", "hostname":"localhost", "level":20, "method":"GET", "msg":"Executing", "pid":12, "requestUuid":"fae4c137-ae3b-4f14-8bd8-0e960776783a", "time":1.690266871911E12}
2023-07-25 08:34:31.913 CEST
{"deviceId":8, "hostname":"localhost", "level":20, "msg":"Device requesting picture", "pictureId":968, "pid":12, "time":1.690266871912E12}
2023-07-25 08:34:31.920 CEST
{"hostname":"localhost", "level":20, "msg":"Getting signed URL from GCS", "path":"/processedPictures/2/89dac333-b746-4c94-8836-1e5dbd812ede.png", "pid":12, "time":1.69026687192E12}
2023-07-25 08:34:31.924 CEST
{"deviceId":8, "hostname":"localhost", "level":20, "msg":"Returning pixels", "pictureId":968, "pid":12, "time":1.690266871923E12}
2023-07-25 08:34:32.533 CEST
{"entrypoint":"/public/device/picture/:pictureId", "hostname":"localhost", "level":20, "method":"GET", "msg":"Executed correctly", "pid":12, "requestUuid":"fae4c137-ae3b-4f14-8bd8-0e960776783a", "time":1.690266872533E12}

As far as I understand, grpc traces look ok, publishing, then modifying the ack, and then acknowledging. This happens non-stop for hours.
Here are only the grpc traces:

2023-07-25 08:34:30.523 CEST
D 2023-07-25T06:34:30.523Z | channel | (59) dns:pubsub.googleapis.com:443 createResolvingCall [636] method="/google.pubsub.v1.Publisher/Publish", deadline=2023-07-25T06:36:10.522Z
2023-07-25 08:34:30.523 CEST
D 2023-07-25T06:34:30.523Z | channel | (59) dns:pubsub.googleapis.com:443 createRetryingCall [637] method="/google.pubsub.v1.Publisher/Publish"
2023-07-25 08:34:30.523 CEST
D 2023-07-25T06:34:30.523Z | channel | (59) dns:pubsub.googleapis.com:443 createLoadBalancingCall [638] method="/google.pubsub.v1.Publisher/Publish"
D 2023-07-25T06:34:30.656Z | channel | (30) dns:pubsub.googleapis.com:443 createResolvingCall [640] method="/google.pubsub.v1.Subscriber/ModifyAckDeadline", deadline=2023-07-25T06:35:30.656Z
2023-07-25 08:34:30.657 CEST
D 2023-07-25T06:34:30.657Z | channel | (30) dns:pubsub.googleapis.com:443 createRetryingCall [641] method="/google.pubsub.v1.Subscriber/ModifyAckDeadline"
2023-07-25 08:34:30.657 CEST
D 2023-07-25T06:34:30.657Z | channel | (30) dns:pubsub.googleapis.com:443 createLoadBalancingCall [642] method="/google.pubsub.v1.Subscriber/ModifyAckDeadline"
2023-07-25 08:34:30.778 CEST
D 2023-07-25T06:34:30.778Z | channel | (30) dns:pubsub.googleapis.com:443 createResolvingCall [644] method="/google.pubsub.v1.Subscriber/Acknowledge", deadline=2023-07-25T06:35:30.777Z
2023-07-25 08:34:30.778 CEST
D 2023-07-25T06:34:30.778Z | channel | (30) dns:pubsub.googleapis.com:443 createRetryingCall [645] method="/google.pubsub.v1.Subscriber/Acknowledge"
2023-07-25 08:34:30.778 CEST
D 2023-07-25T06:34:30.778Z | channel | (30) dns:pubsub.googleapis.com:443 createLoadBalancingCall [646] method="/google.pubsub.v1.Subscriber/Acknowledge"

Then, all of a sudden, with no external input, these starts to appear

2023-07-25 08:36:32.152 CEST
D 2023-07-25T06:36:32.152Z | connectivity_state | (30) dns:pubsub.googleapis.com:443 CONNECTING -> CONNECTING
2023-07-25 08:36:35.752 CEST
D 2023-07-25T06:36:35.751Z | channel | (30) dns:pubsub.googleapis.com:443 createResolvingCall [651] method="/google.pubsub.v1.Subscriber/StreamingPull", deadline=2023-07-25T06:51:35.751Z
2023-07-25 08:36:35.752 CEST
D 2023-07-25T06:36:35.752Z | channel | (30) dns:pubsub.googleapis.com:443 createResolvingCall [652] method="/google.pubsub.v1.Subscriber/StreamingPull", deadline=2023-07-25T06:51:35.752Z
2023-07-25 08:36:35.951 CEST
D 2023-07-25T06:36:35.951Z | channel | (30) dns:pubsub.googleapis.com:443 createResolvingCall [653] method="/google.pubsub.v1.Subscriber/StreamingPull", deadline=2023-07-25T06:51:35.851Z
2023-07-25 08:36:36.051 CEST
D 2023-07-25T06:36:35.951Z | channel | (30) dns:pubsub.googleapis.com:443 createResolvingCall [654] method="/google.pubsub.v1.Subscriber/StreamingPull", deadline=2023-07-25T06:51:35.951Z
2023-07-25 08:36:37.851 CEST
D 2023-07-25T06:36:37.651Z | channel | (30) dns:pubsub.googleapis.com:443 createRetryingCall [655] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:38.351 CEST
D 2023-07-25T06:36:38.351Z | channel | (30) dns:pubsub.googleapis.com:443 createLoadBalancingCall [656] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:38.551 CEST
D 2023-07-25T06:36:38.451Z | channel | (30) dns:pubsub.googleapis.com:443 createRetryingCall [657] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:38.551 CEST
D 2023-07-25T06:36:38.551Z | channel | (30) dns:pubsub.googleapis.com:443 createLoadBalancingCall [658] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:38.551 CEST
D 2023-07-25T06:36:38.551Z | channel | (30) dns:pubsub.googleapis.com:443 createRetryingCall [659] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:40.052 CEST
D 2023-07-25T06:36:38.551Z | channel | (30) dns:pubsub.googleapis.com:443 createLoadBalancingCall [660] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:40.052 CEST
D 2023-07-25T06:36:40.052Z | channel | (30) dns:pubsub.googleapis.com:443 createRetryingCall [661] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:40.052 CEST
D 2023-07-25T06:36:40.052Z | channel | (30) dns:pubsub.googleapis.com:443 createLoadBalancingCall [662] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:40.552 CEST
D 2023-07-25T06:36:40.551Z | channel | (30) dns:pubsub.googleapis.com:443 createResolvingCall [663] method="/google.pubsub.v1.Subscriber/StreamingPull", deadline=2023-07-25T06:51:40.551Z
2023-07-25 08:36:40.552 CEST
D 2023-07-25T06:36:40.552Z | channel | (30) dns:pubsub.googleapis.com:443 createResolvingCall [664] method="/google.pubsub.v1.Subscriber/StreamingPull", deadline=2023-07-25T06:51:40.552Z
2023-07-25 08:36:40.752 CEST
D 2023-07-25T06:36:40.751Z | channel | (30) dns:pubsub.googleapis.com:443 createResolvingCall [665] method="/google.pubsub.v1.Subscriber/StreamingPull", deadline=2023-07-25T06:51:40.751Z
2023-07-25 08:36:40.951 CEST
D 2023-07-25T06:36:40.752Z | channel | (30) dns:pubsub.googleapis.com:443 createResolvingCall [666] method="/google.pubsub.v1.Subscriber/StreamingPull", deadline=2023-07-25T06:51:40.752Z
2023-07-25 08:36:42.352 CEST
D 2023-07-25T06:36:42.351Z | channel | (30) dns:pubsub.googleapis.com:443 createResolvingCall [667] method="/google.pubsub.v1.Subscriber/StreamingPull", deadline=2023-07-25T06:51:42.351Z
2023-07-25 08:36:42.756 CEST
D 2023-07-25T06:36:42.756Z | channel | (30) dns:pubsub.googleapis.com:443 createRetryingCall [668] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:42.756 CEST
D 2023-07-25T06:36:42.756Z | channel | (30) dns:pubsub.googleapis.com:443 createLoadBalancingCall [669] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:42.851 CEST
D 2023-07-25T06:36:42.851Z | channel | (30) dns:pubsub.googleapis.com:443 createRetryingCall [670] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:42.851 CEST
D 2023-07-25T06:36:42.851Z | channel | (30) dns:pubsub.googleapis.com:443 createLoadBalancingCall [671] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:42.851 CEST
D 2023-07-25T06:36:42.851Z | channel | (30) dns:pubsub.googleapis.com:443 createRetryingCall [672] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:42.851 CEST
D 2023-07-25T06:36:42.851Z | channel | (30) dns:pubsub.googleapis.com:443 createLoadBalancingCall [673] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:42.851 CEST
D 2023-07-25T06:36:42.851Z | channel | (30) dns:pubsub.googleapis.com:443 createRetryingCall [674] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:42.851 CEST
D 2023-07-25T06:36:42.851Z | channel | (30) dns:pubsub.googleapis.com:443 createLoadBalancingCall [675] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:42.851 CEST
D 2023-07-25T06:36:42.851Z | channel | (30) dns:pubsub.googleapis.com:443 createRetryingCall [676] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:42.851 CEST
D 2023-07-25T06:36:42.851Z | channel | (30) dns:pubsub.googleapis.com:443 createLoadBalancingCall [677] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:47.651 CEST
D 2023-07-25T06:36:47.651Z | channel | (30) dns:pubsub.googleapis.com:443 createResolvingCall [678] method="/google.pubsub.v1.Subscriber/StreamingPull", deadline=2023-07-25T06:51:47.551Z
2023-07-25 08:36:48.051 CEST
D 2023-07-25T06:36:48.051Z | channel | (30) dns:pubsub.googleapis.com:443 createResolvingCall [679] method="/google.pubsub.v1.Subscriber/StreamingPull", deadline=2023-07-25T06:51:48.051Z
2023-07-25 08:36:48.052 CEST
D 2023-07-25T06:36:48.052Z | channel | (30) dns:pubsub.googleapis.com:443 createResolvingCall [680] method="/google.pubsub.v1.Subscriber/StreamingPull", deadline=2023-07-25T06:51:48.052Z
2023-07-25 08:36:48.856 CEST
D 2023-07-25T06:36:48.856Z | channel | (30) dns:pubsub.googleapis.com:443 createResolvingCall [681] method="/google.pubsub.v1.Subscriber/StreamingPull", deadline=2023-07-25T06:51:48.856Z
2023-07-25 08:36:48.956 CEST
D 2023-07-25T06:36:48.956Z | channel | (30) dns:pubsub.googleapis.com:443 createResolvingCall [682] method="/google.pubsub.v1.Subscriber/StreamingPull", deadline=2023-07-25T06:51:48.956Z
2023-07-25 08:36:49.952 CEST
D 2023-07-25T06:36:49.951Z | channel | (30) dns:pubsub.googleapis.com:443 createRetryingCall [683] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:49.952 CEST
D 2023-07-25T06:36:49.952Z | channel | (30) dns:pubsub.googleapis.com:443 createLoadBalancingCall [684] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:49.952 CEST
D 2023-07-25T06:36:49.952Z | channel | (30) dns:pubsub.googleapis.com:443 createRetryingCall [685] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:49.952 CEST
D 2023-07-25T06:36:49.952Z | channel | (30) dns:pubsub.googleapis.com:443 createLoadBalancingCall [686] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:49.952 CEST
D 2023-07-25T06:36:49.952Z | channel | (30) dns:pubsub.googleapis.com:443 createRetryingCall [687] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:49.952 CEST
D 2023-07-25T06:36:49.952Z | channel | (30) dns:pubsub.googleapis.com:443 createLoadBalancingCall [688] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:49.952 CEST
D 2023-07-25T06:36:49.952Z | channel | (30) dns:pubsub.googleapis.com:443 createRetryingCall [689] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:49.952 CEST
D 2023-07-25T06:36:49.952Z | channel | (30) dns:pubsub.googleapis.com:443 createLoadBalancingCall [690] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:49.952 CEST
D 2023-07-25T06:36:49.952Z | channel | (30) dns:pubsub.googleapis.com:443 createRetryingCall [691] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:50.151 CEST
D 2023-07-25T06:36:49.952Z | channel | (30) dns:pubsub.googleapis.com:443 createLoadBalancingCall [692] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:36:53.151 CEST
D 2023-07-25T06:36:53.151Z | subchannel | (88) 173.194.76.95:443 CONNECTING -> READY
2023-07-25 08:36:53.252 CEST
D 2023-07-25T06:36:53.251Z | channel | (30) dns:pubsub.googleapis.com:443 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
2023-07-25 08:36:53.451 CEST
D 2023-07-25T06:36:53.252Z | connectivity_state | (30) dns:pubsub.googleapis.com:443 CONNECTING -> READY
2023-07-25 08:36:55.651 CEST
D 2023-07-25T06:36:55.552Z | subchannel | (89) 2a00:1450:400c:c0a::5f:443 CONNECTING -> READY
2023-07-25 08:36:57.252 CEST
D 2023-07-25T06:36:57.252Z | subchannel | (90) 142.250.13.95:443 CONNECTING -> READY
2023-07-25 08:37:01.452 CEST
D 2023-07-25T06:37:01.452Z | subchannel | (94) 64.233.184.95:443 CONNECTING -> READY
2023-07-25 08:37:02.752 CEST
D 2023-07-25T06:37:02.752Z | subchannel | (95) 74.125.206.95:443 CONNECTING -> READY
2023-07-25 08:37:04.151 CEST
D 2023-07-25T06:37:04.151Z | subchannel | (96) 64.233.167.95:443 CONNECTING -> READY
2023-07-25 08:37:04.852 CEST
D 2023-07-25T06:37:04.852Z | subchannel | (97) 66.102.1.95:443 CONNECTING -> READY
2023-07-25 08:37:07.052 CEST
D 2023-07-25T06:37:07.052Z | subchannel | (98) 74.125.133.95:443 CONNECTING -> READY
2023-07-25 08:37:08.283 CEST
https://api.memoirframes.com/public/device/current-picture-id
2023-07-25 08:37:08.294 CEST
D 2023-07-25T06:37:08.293Z | subchannel | (99) 108.177.15.95:443 CONNECTING -> READY
2023-07-25 08:37:08.302 CEST
D 2023-07-25T06:37:08.302Z | channel | (30) dns:pubsub.googleapis.com:443 createResolvingCall [708] method="/google.pubsub.v1.Subscriber/StreamingPull", deadline=2023-07-25T06:52:08.302Z
2023-07-25 08:37:08.303 CEST
D 2023-07-25T06:37:08.302Z | channel | (30) dns:pubsub.googleapis.com:443 createResolvingCall [709] method="/google.pubsub.v1.Subscriber/StreamingPull", deadline=2023-07-25T06:52:08.302Z
2023-07-25 08:37:08.303 CEST
D 2023-07-25T06:37:08.303Z | channel | (30) dns:pubsub.googleapis.com:443 createResolvingCall [710] method="/google.pubsub.v1.Subscriber/StreamingPull", deadline=2023-07-25T06:52:08.303Z
2023-07-25 08:37:08.303 CEST
D 2023-07-25T06:37:08.303Z | channel | (30) dns:pubsub.googleapis.com:443 createResolvingCall [711] method="/google.pubsub.v1.Subscriber/StreamingPull", deadline=2023-07-25T06:52:08.303Z
2023-07-25 08:37:08.303 CEST
D 2023-07-25T06:37:08.303Z | channel | (30) dns:pubsub.googleapis.com:443 createResolvingCall [712] method="/google.pubsub.v1.Subscriber/StreamingPull", deadline=2023-07-25T06:52:08.303Z
2023-07-25 08:37:08.303 CEST
D 2023-07-25T06:37:08.303Z | channel | (30) dns:pubsub.googleapis.com:443 createRetryingCall [713] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:37:08.303 CEST
D 2023-07-25T06:37:08.303Z | channel | (30) dns:pubsub.googleapis.com:443 createLoadBalancingCall [714] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:37:08.303 CEST
D 2023-07-25T06:37:08.303Z | channel | (30) dns:pubsub.googleapis.com:443 createRetryingCall [715] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:37:08.303 CEST
D 2023-07-25T06:37:08.303Z | channel | (30) dns:pubsub.googleapis.com:443 createLoadBalancingCall [716] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:37:08.303 CEST
D 2023-07-25T06:37:08.303Z | channel | (30) dns:pubsub.googleapis.com:443 createRetryingCall [717] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:37:08.303 CEST
D 2023-07-25T06:37:08.303Z | channel | (30) dns:pubsub.googleapis.com:443 createLoadBalancingCall [718] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:37:08.303 CEST
D 2023-07-25T06:37:08.303Z | channel | (30) dns:pubsub.googleapis.com:443 createRetryingCall [719] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:37:08.303 CEST
D 2023-07-25T06:37:08.303Z | channel | (30) dns:pubsub.googleapis.com:443 createLoadBalancingCall [720] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:37:08.304 CEST
D 2023-07-25T06:37:08.303Z | channel | (30) dns:pubsub.googleapis.com:443 createRetryingCall [721] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:37:08.304 CEST
D 2023-07-25T06:37:08.304Z | channel | (30) dns:pubsub.googleapis.com:443 createLoadBalancingCall [722] method="/google.pubsub.v1.Subscriber/StreamingPull"
2023-07-25 08:37:08.305 CEST
D 2023-07-25T06:37:08.304Z | subchannel | (89) 2a00:1450:400c:c0a::5f:443 READY -> IDLE
2023-07-25 08:37:08.305 CEST
D 2023-07-25T06:37:08.305Z | subchannel | (90) 142.250.13.95:443 READY -> IDLE
2023-07-25 08:37:08.305 CEST
D 2023-07-25T06:37:08.305Z | subchannel | (94) 64.233.184.95:443 READY -> IDLE
2023-07-25 08:37:08.305 CEST
D 2023-07-25T06:37:08.305Z | subchannel | (95) 74.125.206.95:443 READY -> IDLE
2023-07-25 08:37:08.305 CEST
D 2023-07-25T06:37:08.305Z | subchannel | (96) 64.233.167.95:443 READY -> IDLE
2023-07-25 08:37:08.305 CEST
D 2023-07-25T06:37:08.305Z | subchannel | (97) 66.102.1.95:443 READY -> IDLE
2023-07-25 08:37:08.305 CEST
D 2023-07-25T06:37:08.305Z | subchannel | (98) 74.125.133.95:443 READY -> IDLE
2023-07-25 08:37:08.305 CEST
D 2023-07-25T06:37:08.305Z | subchannel | (99) 108.177.15.95:443 READY -> IDLE
2023-07-25 08:37:08.305 CEST
D 2023-07-25T06:37:08.305Z | subchannel | (101) 2a00:1450:400c:c04::5f:443 CONNECTING -> IDLE
2023-07-25 08:37:08.305 CEST
D 2023-07-25T06:37:08.305Z | subchannel | (102) 2a00:1450:400c:c0b::5f:443 CONNECTING -> IDLE
2023-07-25 08:37:08.305 CEST
D 2023-07-25T06:37:08.305Z | subchannel | (103) 2a00:1450:400c:c03::5f:443 CONNECTING -> IDLE
2023-07-25 08:37:08.305 CEST
D 2023-07-25T06:37:08.305Z | subchannel | (104) 64.233.166.95:443 CONNECTING -> IDLE

And after that, no more messages are received by the subscription.
Screenshot from 2023-07-26 08-27-08

I believe this is a bug, and it's related to previous bugs that haven't been solved, or that are reappearing again. Am I doing something wrong? Is there anything I'm missing? Thanks!

Thanks!
@webnator webnator added priority: p2 Moderately-important priority. Fix may not be included in next release. type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns. labels Jul 26, 2023
@product-auto-label product-auto-label bot added the api: pubsub Issues related to the googleapis/nodejs-pubsub API. label Jul 26, 2023
@APTy
Copy link

APTy commented Aug 2, 2023

Also seeing this on @google-cloud/[email protected], although in some cases subscriptions never start to begin with, and no indication (errors emitted) as to why.

Code is also running on Cloud Run (with minimum instance count > 0).

When I listen for debug messages on the subscription, I occasionally see Subscriber stream 4 has ended with status 4; will be retried., which feels related.

@feywind
Copy link
Collaborator

feywind commented Aug 4, 2023

Check the comment here and see if it helps with any of this: #1515 (comment)

I'll forward this on to our grpc-js person to see if he sees anything interesting in the logs.

@feywind
Copy link
Collaborator

feywind commented Aug 4, 2023

I was pointed at this as a similar sort of behaviour: grpc/grpc-node#2502

The recommendation is to go ahead and enable keepalives as in #1515 (comment), and see if that helps.

@webnator
Copy link
Author

webnator commented Aug 7, 2023

This seems to be solving the issue. It was a bit random so I can't tell for sure, but it was happening every 3-4 hours and now there's been around 24 hours without this issue

@webnator
Copy link
Author

webnator commented Aug 15, 2023 •
edited
Loading

Marking this as closed since adding this to the client config seems to solve the issue

const pubsub = new PubSub({
    projectId: config.PROJECT_ID,
    'grpc.keepalive_timeout_ms': 10000,
    'grpc.keepalive_time_ms': 30000,
  });

Not pretty but gets the job done

@maxolofsson1 maxolofsson1 mentioned this issue Nov 10, 2023
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
api: pubsub Issues related to the googleapis/nodejs-pubsub API. priority: p2 Moderately-important priority. Fix may not be included in next release. type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@APTy @webnator @feywind