search

googleapis / nodejs-pubsub

Node.js client for Google Cloud Pub/Sub: Ingest event streams from anywhere, at any scale, for simple, reliable, real-time stream analytics.
https://cloud.google.com/pubsub/
Apache License 2.0
518 stars 228 forks source link

A subscription suddenly and silently stops receiving messages #1779

Closed webnator closed 1 year ago

webnator commented 1 year ago

This issue might be related to #979 or #1135

Environment details

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
2023-07-25 06:07:51 [oas-tools] INFO: 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
2023-07-25 06:07:87 [oas-tools] INFO: 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!

APTy commented 1 year ago

Also seeing this on @google-cloud/pub-sub@3.7.3, 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 commented 1 year ago

Check the comment here and see if it helps with any of this: https://github.com/googleapis/nodejs-pubsub/issues/1515#issuecomment-1665969983

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

feywind commented 1 year ago

I was pointed at this as a similar sort of behaviour: https://github.com/grpc/grpc-node/issues/2502

The recommendation is to go ahead and enable keepalives as in https://github.com/googleapis/nodejs-pubsub/issues/1515#issuecomment-1665969983, and see if that helps.

webnator commented 1 year ago

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 commented 1 year ago

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