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

Deadline exceeded error with any version after 1.1 #866

Closed
kbariotis opened this issue Jan 27, 2020 · 3 comments
Closed

Deadline exceeded error with any version after 1.1 #866

kbariotis opened this issue Jan 27, 2020 · 3 comments
Assignees
@feywind
Labels
api: pubsub Issues related to the googleapis/nodejs-pubsub API. status: investigating The issue is under investigation, which is determined to be non-trivial.

Comments

@kbariotis
Copy link

Environment details

  • OS: MacOS
  • Node.js version: 12
  • npm version: latest Yarn (1.x)
  • @google-cloud/pubsub version: All versions after 1.1

Steps to reproduce

Code:

import { v1 } from '@google-cloud/pubsub';

const subClient = new v1.SubscriberClient();

const subscriptionName = subClient.subscriptionPath(
    'example',
    'example',
  );

  const request = {
    subscription: subscriptionName,
    maxMessages: 10,
  };

  const [response] = await subClient.pull(request);

Logs

Below starts the execution of the above function with version 1.0, then I am installing version 1.1 and start the execution again.

yarn run v1.21.1
$ nodemon --watch 'src/**/*' -e ts,tsx --exec ts-node ./src/index.ts
[nodemon] 2.0.2
[nodemon] to restart at any time, enter `rs`
[nodemon] watching dir(s): src/**/*
[nodemon] watching extensions: ts,tsx
[nodemon] starting `ts-node ./src/index.ts`
[email protected] alert: no DSN provided, error reporting disabled
2020-01-27T12:35:57.084Z | resolving_load_balancer | pubsub.googleapis.com:443 IDLE -> IDLE
2020-01-27T12:35:57.084Z | connectivity_state | pubsub.googleapis.com:443 IDLE -> IDLE
2020-01-27T12:35:57.084Z | dns_resolver | Resolver constructed for target pubsub.googleapis.com:443
2020-01-27T12:35:57.085Z | resolving_load_balancer | pubsub.googleapis.com:443 IDLE -> IDLE
2020-01-27T12:35:57.085Z | connectivity_state | pubsub.googleapis.com:443 IDLE -> IDLE
2020-01-27T12:35:57.085Z | dns_resolver | Resolver constructed for target pubsub.googleapis.com:443
2020-01-27T12:35:57.087Z | channel | pubsub.googleapis.com:443 createCall [0] method="/google.pubsub.v1.Subscriber/Pull", deadline=Mon Jan 27 2020 12:36:22 GMT+0000 (Greenwich Mean Time)
2020-01-27T12:35:57.088Z | call_stream | [0] Sending metadata
2020-01-27T12:35:57.089Z | call_stream | [0] write() called with message of length 88
2020-01-27T12:35:57.090Z | dns_resolver | Resolution update requested for target pubsub.googleapis.com:443
2020-01-27T12:35:57.091Z | resolving_load_balancer | pubsub.googleapis.com:443 IDLE -> CONNECTING
2020-01-27T12:35:57.091Z | connectivity_state | pubsub.googleapis.com:443 IDLE -> CONNECTING
2020-01-27T12:35:57.091Z | resolving_load_balancer | pubsub.googleapis.com:443 CONNECTING -> CONNECTING
2020-01-27T12:35:57.091Z | connectivity_state | pubsub.googleapis.com:443 CONNECTING -> CONNECTING
2020-01-27T12:35:57.101Z | dns_resolver | Resolved addresses for target pubsub.googleapis.com:443: 216.58.204.42:443
2020-01-27T12:35:57.102Z | pick_first | IDLE -> IDLE
2020-01-27T12:35:57.102Z | resolving_load_balancer | pubsub.googleapis.com:443 CONNECTING -> IDLE
2020-01-27T12:35:57.102Z | connectivity_state | pubsub.googleapis.com:443 CONNECTING -> IDLE
2020-01-27T12:35:57.102Z | pick_first | Connect to address list 216.58.204.42:443
2020-01-27T12:35:57.103Z | subchannel | 216.58.204.42:443 callRefcount 0 -> 1
2020-01-27T12:35:57.103Z | subchannel | 216.58.204.42:443 callRefcount 1 -> 2
2020-01-27T12:35:57.103Z | pick_first | Start connecting to subchannel with address 216.58.204.42:443
2020-01-27T12:35:57.103Z | pick_first | IDLE -> CONNECTING
2020-01-27T12:35:57.103Z | resolving_load_balancer | pubsub.googleapis.com:443 IDLE -> CONNECTING
2020-01-27T12:35:57.103Z | connectivity_state | pubsub.googleapis.com:443 IDLE -> CONNECTING
2020-01-27T12:35:57.104Z | subchannel | 216.58.204.42:443 IDLE -> CONNECTING
2020-01-27T12:35:57.106Z | pick_first | CONNECTING -> CONNECTING
2020-01-27T12:35:57.106Z | resolving_load_balancer | pubsub.googleapis.com:443 CONNECTING -> CONNECTING
2020-01-27T12:35:57.107Z | connectivity_state | pubsub.googleapis.com:443 CONNECTING -> CONNECTING
2020-01-27T12:35:57.119Z | subchannel | 216.58.204.42:443 CONNECTING -> READY
2020-01-27T12:35:57.119Z | pick_first | Pick subchannel with address 216.58.204.42:443
2020-01-27T12:35:57.119Z | pick_first | CONNECTING -> READY
2020-01-27T12:35:57.119Z | resolving_load_balancer | pubsub.googleapis.com:443 CONNECTING -> READY
2020-01-27T12:35:57.128Z | connectivity_state | pubsub.googleapis.com:443 CONNECTING -> READY
2020-01-27T12:35:57.128Z | subchannel | 216.58.204.42:443 callRefcount 2 -> 3
2020-01-27T12:35:57.128Z | subchannel | 216.58.204.42:443 callRefcount 3 -> 2
2020-01-27T12:35:57.179Z | call_stream | [0] attachHttp2Stream from subchannel 216.58.204.42:443
2020-01-27T12:35:57.179Z | subchannel | 216.58.204.42:443 callRefcount 0 -> 1
2020-01-27T12:35:57.179Z | call_stream | [0] end() called
2020-01-27T12:35:57.180Z | call_stream | [0] calling end() on HTTP/2 stream
2020-01-27T12:36:15.486Z | call_stream | [0] received HTTP/2 headers frame
2020-01-27T12:36:15.487Z | call_stream | [0] receive HTTP/2 data frame of length 5
2020-01-27T12:36:15.488Z | call_stream | [0] parsed message of length 5
2020-01-27T12:36:15.488Z | call_stream | [0] filterReceivedMessage of length 5
2020-01-27T12:36:15.489Z | call_stream | [0] pushing to reader message of length 0
2020-01-27T12:36:15.491Z | call_stream | [0] received HTTP/2 trailing headers frame
2020-01-27T12:36:15.491Z | call_stream | [0] received HTTP/2 end of data flag
2020-01-27T12:36:15.491Z | call_stream | [0] pushing to reader message of length null
2020-01-27T12:36:15.492Z | call_stream | [0] ended with status: code=0 details=""
2020-01-27T12:36:15.492Z | subchannel | 216.58.204.42:443 callRefcount 1 -> 0
2020-01-27T12:36:15.493Z | call_stream | [0] HTTP/2 stream closed with code 0
2020-01-27T12:36:15.493Z | channel | pubsub.googleapis.com:443 createCall [1] method="/google.pubsub.v1.Subscriber/Pull", deadline=Mon Jan 27 2020 12:36:40 GMT+0000 (Greenwich Mean Time)
2020-01-27T12:36:15.494Z | call_stream | [1] Sending metadata
2020-01-27T12:36:15.494Z | call_stream | [1] write() called with message of length 88
2020-01-27T12:36:15.494Z | call_stream | [1] attachHttp2Stream from subchannel 216.58.204.42:443
2020-01-27T12:36:15.494Z | subchannel | 216.58.204.42:443 callRefcount 0 -> 1
2020-01-27T12:36:15.495Z | call_stream | [1] end() called
2020-01-27T12:36:15.495Z | call_stream | [1] calling end() on HTTP/2 stream
^C
exit 130
> yarn add @google-cloud/[email protected]
yarn add v1.21.1
[1/5] 🔍  Validating package.json...
[2/5] 🔍  Resolving packages...
[3/5] 🚚  Fetching packages...
[4/5] 🔗  Linking dependencies...
warning " > [email protected]" has unmet peer dependency "request@^2.34".
[5/5] 🔨  Building fresh packages...
success Saved lockfile.
success Saved 2 new dependencies.
info Direct dependencies
└─ @google-cloud/[email protected]
info All dependencies
├─ @google-cloud/[email protected]
└─ [email protected]
✨  Done in 1.80s.
> env GRPC_TRACE=all GRPC_VERBOSITY=DEBUG yarn start
yarn run v1.21.1
$ nodemon --watch 'src/**/*' -e ts,tsx --exec ts-node ./src/index.ts
[nodemon] 2.0.2
[nodemon] to restart at any time, enter `rs`
[nodemon] watching dir(s): src/**/*
[nodemon] watching extensions: ts,tsx
[nodemon] starting `ts-node ./src/index.ts`
[email protected] alert: no DSN provided, error reporting disabled
2020-01-27T12:36:32.082Z | resolving_load_balancer | pubsub.googleapis.com:443 IDLE -> IDLE
2020-01-27T12:36:32.082Z | connectivity_state | pubsub.googleapis.com:443 IDLE -> IDLE
2020-01-27T12:36:32.082Z | dns_resolver | Resolver constructed for target pubsub.googleapis.com:443
2020-01-27T12:36:32.083Z | resolving_load_balancer | pubsub.googleapis.com:443 IDLE -> IDLE
2020-01-27T12:36:32.083Z | connectivity_state | pubsub.googleapis.com:443 IDLE -> IDLE
2020-01-27T12:36:32.083Z | dns_resolver | Resolver constructed for target pubsub.googleapis.com:443
2020-01-27T12:36:32.084Z | channel | pubsub.googleapis.com:443 createCall [0] method="/google.pubsub.v1.Subscriber/Pull", deadline=Mon Jan 27 2020 12:36:37 GMT+0000 (Greenwich Mean Time)
2020-01-27T12:36:32.085Z | call_stream | [0] Sending metadata
2020-01-27T12:36:32.086Z | call_stream | [0] write() called with message of length 88
2020-01-27T12:36:32.086Z | dns_resolver | Resolution update requested for target pubsub.googleapis.com:443
2020-01-27T12:36:32.087Z | resolving_load_balancer | pubsub.googleapis.com:443 IDLE -> CONNECTING
2020-01-27T12:36:32.088Z | connectivity_state | pubsub.googleapis.com:443 IDLE -> CONNECTING
2020-01-27T12:36:32.088Z | resolving_load_balancer | pubsub.googleapis.com:443 CONNECTING -> CONNECTING
2020-01-27T12:36:32.088Z | connectivity_state | pubsub.googleapis.com:443 CONNECTING -> CONNECTING
2020-01-27T12:36:32.090Z | dns_resolver | Resolved addresses for target pubsub.googleapis.com:443: 216.58.204.42:443
2020-01-27T12:36:32.090Z | pick_first | IDLE -> IDLE
2020-01-27T12:36:32.090Z | resolving_load_balancer | pubsub.googleapis.com:443 CONNECTING -> IDLE
2020-01-27T12:36:32.090Z | connectivity_state | pubsub.googleapis.com:443 CONNECTING -> IDLE
2020-01-27T12:36:32.091Z | pick_first | Connect to address list 216.58.204.42:443
2020-01-27T12:36:32.091Z | subchannel | 216.58.204.42:443 callRefcount 0 -> 1
2020-01-27T12:36:32.091Z | subchannel | 216.58.204.42:443 callRefcount 1 -> 2
2020-01-27T12:36:32.091Z | pick_first | Start connecting to subchannel with address 216.58.204.42:443
2020-01-27T12:36:32.092Z | pick_first | IDLE -> CONNECTING
2020-01-27T12:36:32.092Z | resolving_load_balancer | pubsub.googleapis.com:443 IDLE -> CONNECTING
2020-01-27T12:36:32.092Z | connectivity_state | pubsub.googleapis.com:443 IDLE -> CONNECTING
2020-01-27T12:36:32.092Z | subchannel | 216.58.204.42:443 IDLE -> CONNECTING
2020-01-27T12:36:32.095Z | pick_first | CONNECTING -> CONNECTING
2020-01-27T12:36:32.095Z | resolving_load_balancer | pubsub.googleapis.com:443 CONNECTING -> CONNECTING
2020-01-27T12:36:32.095Z | connectivity_state | pubsub.googleapis.com:443 CONNECTING -> CONNECTING
2020-01-27T12:36:32.108Z | subchannel | 216.58.204.42:443 CONNECTING -> READY
2020-01-27T12:36:32.108Z | pick_first | Pick subchannel with address 216.58.204.42:443
2020-01-27T12:36:32.108Z | pick_first | CONNECTING -> READY
2020-01-27T12:36:32.108Z | resolving_load_balancer | pubsub.googleapis.com:443 CONNECTING -> READY
2020-01-27T12:36:32.116Z | connectivity_state | pubsub.googleapis.com:443 CONNECTING -> READY
2020-01-27T12:36:32.116Z | subchannel | 216.58.204.42:443 callRefcount 2 -> 3
2020-01-27T12:36:32.116Z | subchannel | 216.58.204.42:443 callRefcount 3 -> 2
2020-01-27T12:36:32.163Z | call_stream | [0] attachHttp2Stream from subchannel 216.58.204.42:443
2020-01-27T12:36:32.163Z | subchannel | 216.58.204.42:443 callRefcount 0 -> 1
2020-01-27T12:36:32.164Z | call_stream | [0] end() called
2020-01-27T12:36:32.164Z | call_stream | [0] calling end() on HTTP/2 stream
2020-01-27T12:36:37.086Z | call_stream | [0] ended with status: code=4 details="Deadline exceeded"
2020-01-27T12:36:37.086Z | subchannel | 216.58.204.42:443 callRefcount 1 -> 0
2020-01-27T12:36:37.087Z | call_stream | [0] received HTTP/2 end of data flag
2020-01-27T12:36:37.088Z | call_stream | [0] HTTP/2 stream closed with code 8
info Call to raven.captureException without sentry configured
{
  arguments: [
    Error: 4 DEADLINE_EXCEEDED: Deadline exceeded
        at Object.callErrorFromStatus (/node_modules/@grpc/grpc-js/src/call.ts:79:24)
        at Http2CallStream.<anonymous> (/node_modules/@grpc/grpc-js/src/client.ts:155:18)
        at Http2CallStream.emit (events.js:215:7)
        at Http2CallStream.EventEmitter.emit (domain.js:475:20)
        at /node_modules/@grpc/grpc-js/src/call-stream.ts:183:14
        at processTicksAndRejections (internal/process/task_queues.js:75:11) {
      code: 4,
      details: 'Deadline exceeded',
      metadata: Metadata { internalRepr: Map {}, options: {} },
      note: 'Exception occurred in retry method that was not classified as transient'
    }
  ]
}

[email protected] alert: no DSN provided, error reporting disabled
2020-01-27T12:36:37.109Z | channel | pubsub.googleapis.com:443 createCall [1] method="/google.pubsub.v1.Subscriber/Pull", deadline=Mon Jan 27 2020 12:36:42 GMT+0000 (Greenwich Mean Time)
2020-01-27T12:36:37.109Z | call_stream | [1] Sending metadata
2020-01-27T12:36:37.109Z | call_stream | [1] write() called with message of length 88
2020-01-27T12:36:37.110Z | call_stream | [1] attachHttp2Stream from subchannel 216.58.204.42:443
2020-01-27T12:36:37.110Z | subchannel | 216.58.204.42:443 callRefcount 0 -> 1
2020-01-27T12:36:37.111Z | call_stream | [1] end() called
2020-01-27T12:36:37.111Z | call_stream | [1] calling end() on HTTP/2 stream
^C
exit 130
@feywind feywind added the status: investigating The issue is under investigation, which is determined to be non-trivial. label Jan 27, 2020
@feywind feywind self-assigned this Jan 27, 2020
@feywind
Copy link
Collaborator

feywind commented Jan 27, 2020

@kbariotis Thanks for the detailed reproduction steps! I'll put this in the queue to look at.

@google-cloud-label-sync google-cloud-label-sync bot added the api: pubsub Issues related to the googleapis/nodejs-pubsub API. label Jan 30, 2020
@feywind feywind mentioned this issue Feb 5, 2020
Closed
@feywind
Copy link
Collaborator

feywind commented Feb 28, 2020

Sorry for the delay - I'm looking at what changed between 1.0 and 1.1, and it looks like that was when a potentially flaky update to grpc-js was introduced:

deps: update dependency @grpc/grpc-js to ^0.6.0 (#759) (fda95c7)

Newer versions are more stable - can you try again with nodejs-pubsub 1.5.0?

@feywind
Copy link
Collaborator

feywind commented May 5, 2020

I'm going to go ahead and close this, since it hasn't seen a reply in a while, but please feel free to re-open/comment if needed.

@feywind feywind closed this as completed May 5, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@feywind feywind

Labels
api: pubsub Issues related to the googleapis/nodejs-pubsub API. status: investigating The issue is under investigation, which is determined to be non-trivial.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@kbariotis @feywind