Google::Cloud::Pubsub::Subscription::Listener.start does not appear to begin processing messages

NickTitle commented 7 years ago

While trying to use the latest version of the subscription#listen api, i'm unable to force the listener to block and process my messages. following the example added to the guide in #1608, i see the following behavior

creating a listener works
starting that listener works
no messages get pulled
manually pulling from the subscription shows me queued messages
calling listener.stop.wait! will stop the subscriber even with queued messages in the subscription

ps = Google::Cloud::Pubsub.new(project:'test')
topic = ps.topic('test-topic') || ps.create_topic('test-topic')
sub = topic.subscription('test-topic-sub') || topic.subscribe('test-topic-sub')
listener = sub.listen do |message|
  puts message
  message.ack!
end                  # -> <listener>

listener.start       # -> <listener>
listener.started?    # -> true

# publish a message in here
topic.publish "foo"

# no response from listener

listener.stop.wait! # -> <listener>
listener.started?   # -> false

sub.pull # -> message with data "foo" is returned

am i misunderstanding the guide, or is something going sideways under the hood? thank you for your time; i appreciate the look over!

blowmage commented 7 years ago

Hi @NickTitle, thanks for opening the issue. Your code looks correct. We have very similar code in our acceptance test as well. How long are you waiting for the subscriber to receive the message before stopping it? Do you have any other processes active that might be running similar code?

Can you try adding Thread.abort_on_exception = true to your code? This will make any errors in background threads more visible.

NickTitle commented 7 years ago

@blowmage you're awesome - sure enough, a very short stack trace complaining about a missing method is attached:

~/.rvm/gems/ruby-2.4.1/ruby/2.4.0/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/stream.rb:209:in `rescue in background_run': 12:Method not found: google.pubsub.v1.Subscriber/StreamingPull (Google::Cloud::UnimplementedError)
    ~/.rvm/gems/ruby-2.4.1/ruby/2.4.0/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/stream.rb:178:in `background_run'
    ~/.rvm/gems/ruby-2.4.1/ruby/2.4.0/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/stream.rb:235:in `block in start_streaming!'

blowmage commented 7 years ago

It looks like the API method StreamingPull is not enabled for your project. @geigerj, what can you tell us about this? Is there anything users need to do to enable this API?

geigerj commented 7 years ago

This method is should be enabled by default. Looping in @mdietz94.

geigerj commented 7 years ago

FYI @lukesneeringer

geigerj commented 7 years ago

We are investigating this internally. I'll update this issue when we know more.

geigerj commented 7 years ago

@NickTitle Are you still seeing this error?

NickTitle commented 7 years ago

Hi @geigerj, running my example above and aborting threads on exception, i still see the error around this missing method.

Thanks for investigating!

As an aside, I refactored my listen to a while true loop, polling for messages in the interim. Do you have any guidance for a reasonable frequency for me to hit p/s?

blowmage commented 7 years ago

@NickTitle the previous release's implementation that used pull is here:

https://github.com/GoogleCloudPlatform/google-cloud-ruby/blob/google-cloud-pubsub/v0.26.0/google-cloud-pubsub/lib/google/cloud/pubsub/subscription.rb#L339-L348

geigerj commented 7 years ago

@NickTitle I'm having trouble reproducing. I was able to run your snippet and saw the expected behavior.

Please install google-cloud-pubsub in a clean Ruby environment and run your snippet? If you're still seeing the issue, could you then give the output of running gem list? (Just in case the difference in behavior is coming from having dependencies on different versions of, say, gRPC.)

tiagopog commented 7 years ago

Hey there! Since I've updated google-cloud-pubsub from 0.23.0 to 0.27.0 I started experiencing the same issue reported by @NickTitle.

I did a little debug and that's what I've got so far:

root@ce6a91f8b9ce:/app# hanami c

[1] pry(main)> pubsub = Google::Cloud::Pubsub.new
=> #<Google::Cloud::Pubsub::Project:0x000000036d0e40 @service=Google::Cloud::Pubsub::Service(playground-500)>

[2] pry(main)> topic_name = 'foo'
=> "foo"

[3] pry(main)> sub = pubsub.subscription(topic_name) || pubsub.subscribe(topic_name)
D, [2017-08-17T21:53:11.853051 #251] DEBUG -- : calling pubsub:8042:443:/google.pubsub.v1.Subscriber/GetSubscription
=> #<Google::Cloud::Pubsub::Subscription:0x000000034a7a10
 @exists=nil,
 @grpc=
  <Google::Pubsub::V1::Subscription: name: "projects/playground-500/subscriptions/foo", topic: "projects/playground-500/topics/foo", push_config: <Google::Pubsub::V1::PushConfig: push_endpoint: "", attributes: {}>, ack_deadline_seconds: 10, retain_acked_messages: false, message_retention_duration: nil>,
 @lazy=nil,
 @service=Google::Cloud::Pubsub::Service(playground-500)>

[4] pry(main)> subscriber = sub.listen { |msg| puts msg }
=> #<Google::Cloud::Pubsub::Subscriber (subscription: projects/playground-500/subscriptions/foo, streams: 4)>

[5] pry(main)> subscriber.start
D, [2017-08-17T21:53:24.138220 #251] DEBUG -- : calling pubsub:8042:443:/google.pubsub.v1.Subscriber/StreamingPull
D, [2017-08-17T21:53:24.151024 #251] DEBUG -- : calling pubsub:8042:443:/google.pubsub.v1.Subscriber/StreamingPull
D, [2017-08-17T21:53:24.151639 #251] DEBUG -- : calling pubsub:8042:443:/google.pubsub.v1.Subscriber/StreamingPull
D, [2017-08-17T21:53:24.155436 #251] DEBUG -- : calling pubsub:8042:443:/google.pubsub.v1.Subscriber/StreamingPull
D, [2017-08-17T21:53:24.161769 #251] DEBUG -- : bidi-write-loop: starting
D, [2017-08-17T21:53:24.161940 #251] DEBUG -- : bidi-write-loop: 0
D, [2017-08-17T21:53:24.166590 #251] DEBUG -- : bidi-write-loop: starting
D, [2017-08-17T21:53:24.166727 #251] DEBUG -- : bidi-write-loop: 0
W, [2017-08-17T21:53:24.172468 #251]  WARN -- : bidi-write-loop: ended with error
W, [2017-08-17T21:53:24.193789 #251]  WARN -- : call#run_batch failed somehow (GRPC::Core::CallError)
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:152:in `run_batch'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:152:in `block in write_loop'
/usr/local/bundle/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/enumerator_queue.rb:45:in `block in each'
/usr/local/bundle/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/enumerator_queue.rb:42:in `loop'
/usr/local/bundle/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/enumerator_queue.rb:42:in `each'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:145:in `each'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:145:in `write_loop'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:90:in `block in run_on_client'
=> #<Google::Cloud::Pubsub::Subscriber (subscription: projects/playground-500/subscriptions/foo, streams: 4)>D, [2017-08-17T21:53:24.193014 #251] DEBUG -- : bidi-read-loop: starting
D, [2017-08-17T21:53:24.209188 #251] DEBUG -- : bidi-read-loop: 0

[6] pry(main)> D, [2017-08-17T21:53:24.193261 #251] DEBUG -- : bidi-read-loop: starting
D, [2017-08-17T21:53:24.193360 #251] DEBUG -- : bidi-write-loop: starting
D, [2017-08-17T21:53:24.193638 #251] DEBUG -- : bidi-read-loop: starting
D, [2017-08-17T21:53:24.212017 #251] DEBUG -- : bidi-read-loop: 0
D, [2017-08-17T21:53:24.192588 #251] DEBUG -- : bidi-read-loop: starting
D, [2017-08-17T21:53:24.193069 #251] DEBUG -- : bidi-write-loop: starting
D, [2017-08-17T21:53:24.215440 #251] DEBUG -- : bidi-write-loop: 0
D, [2017-08-17T21:53:24.211314 #251] DEBUG -- : bidi-read-loop: 0
D, [2017-08-17T21:53:24.211665 #251] DEBUG -- : bidi-write-loop: 0
D, [2017-08-17T21:53:24.193955 #251] DEBUG -- : bidi-write-loop: 1 writes done
D, [2017-08-17T21:53:24.216867 #251] DEBUG -- : bidi-write-loop: client sent 1, waiting
D, [2017-08-17T21:53:24.214588 #251] DEBUG -- : bidi-read-loop: 0
W, [2017-08-17T21:53:24.215667 #251]  WARN -- : bidi-write-loop: ended with error
W, [2017-08-17T21:53:24.222180 #251]  WARN -- : call#run_batch failed somehow (GRPC::Core::CallError)
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:152:in `run_batch'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:152:in `block in write_loop'
/usr/local/bundle/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/enumerator_queue.rb:45:in `block in each'
/usr/local/bundle/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/enumerator_queue.rb:42:in `loop'
/usr/local/bundle/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/enumerator_queue.rb:42:in `each'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:145:in `each'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:145:in `write_loop'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:90:in `block in run_on_client'
D, [2017-08-17T21:53:24.216321 #251] DEBUG -- : bidi-read-loop: null batch #<struct Struct::BatchResult send_message=nil, send_metadata=nil, send_close=nil, send_status=nil, message=nil, metadata={}, status=nil, cancelled=nil>
D, [2017-08-17T21:53:24.222983 #251] DEBUG -- : Failing with status #<struct Struct::Status code=12, details="Method not found: google.pubsub.v1.Subscriber/StreamingPull", metadata={}>
D, [2017-08-17T21:53:24.212597 #251] DEBUG -- : bidi-read-loop: null batch #<struct Struct::BatchResult send_message=nil, send_metadata=nil, send_close=nil, send_status=nil, message=nil, metadata={}, status=nil, cancelled=nil>
D, [2017-08-17T21:53:24.224083 #251] DEBUG -- : Failing with status #<struct Struct::Status code=12, details="Method not found: google.pubsub.v1.Subscriber/StreamingPull", metadata={}>
W, [2017-08-17T21:53:24.224386 #251]  WARN -- : bidi: read-loop failed
W, [2017-08-17T21:53:24.224472 #251]  WARN -- : 12:Method not found: google.pubsub.v1.Subscriber/StreamingPull (GRPC::Unimplemented)
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/active_call.rb:46:in `check_status'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:198:in `block in read_loop'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:185:in `loop'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:185:in `read_loop'
/usr/local/bundle/bin/hanami:1:in `each'
D, [2017-08-17T21:53:24.221526 #251] DEBUG -- : bidi-write-loop: done
D, [2017-08-17T21:53:24.224775 #251] DEBUG -- : bidi-write-loop: finished
W, [2017-08-17T21:53:24.220340 #251]  WARN -- : bidi-write-loop: ended with error
W, [2017-08-17T21:53:24.224929 #251]  WARN -- : call#run_batch failed somehow (GRPC::Core::CallError)
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:152:in `run_batch'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:152:in `block in write_loop'
/usr/local/bundle/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/enumerator_queue.rb:45:in `block in each'
/usr/local/bundle/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/enumerator_queue.rb:42:in `loop'
/usr/local/bundle/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/enumerator_queue.rb:42:in `each'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:145:in `each'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:145:in `write_loop'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:90:in `block in run_on_client'
D, [2017-08-17T21:53:24.225051 #251] DEBUG -- : bidi-write-loop: 1 writes done
D, [2017-08-17T21:53:24.225098 #251] DEBUG -- : bidi-write-loop: client sent 1, waiting
D, [2017-08-17T21:53:24.222503 #251] DEBUG -- : bidi-write-loop: 1 writes done
D, [2017-08-17T21:53:24.227534 #251] DEBUG -- : bidi-write-loop: client sent 1, waiting
D, [2017-08-17T21:53:24.227829 #251] DEBUG -- : bidi-write-loop: done
D, [2017-08-17T21:53:24.227910 #251] DEBUG -- : bidi-write-loop: finished
D, [2017-08-17T21:53:24.209672 #251] DEBUG -- : bidi-read-loop: null batch #<struct Struct::BatchResult send_message=nil, send_metadata=nil, send_close=nil, send_status=nil, message=nil, metadata={}, status=nil, cancelled=nil>
D, [2017-08-17T21:53:24.228442 #251] DEBUG -- : Failing with status #<struct Struct::Status code=12, details="Method not found: google.pubsub.v1.Subscriber/StreamingPull", metadata={}>
W, [2017-08-17T21:53:24.223743 #251]  WARN -- : bidi: read-loop failed
W, [2017-08-17T21:53:24.229091 #251]  WARN -- : 12:Method not found: google.pubsub.v1.Subscriber/StreamingPull (GRPC::Unimplemented)
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/active_call.rb:46:in `check_status'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:198:in `block in read_loop'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:185:in `loop'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:185:in `read_loop'
/usr/local/bundle/bin/hanami:1:in `each'
D, [2017-08-17T21:53:24.222065 #251] DEBUG -- : bidi-read-loop: null batch #<struct Struct::BatchResult send_message=nil, send_metadata=nil, send_close=nil, send_status=nil, message=nil, metadata={}, status=nil, cancelled=nil>
D, [2017-08-17T21:53:24.229465 #251] DEBUG -- : Failing with status #<struct Struct::Status code=12, details="Method not found: google.pubsub.v1.Subscriber/StreamingPull", metadata={}>
W, [2017-08-17T21:53:24.229580 #251]  WARN -- : bidi: read-loop failed
W, [2017-08-17T21:53:24.229628 #251]  WARN -- : 12:Method not found: google.pubsub.v1.Subscriber/StreamingPull (GRPC::Unimplemented)
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/active_call.rb:46:in `check_status'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:198:in `block in read_loop'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:185:in `loop'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:185:in `read_loop'
/usr/local/bundle/bin/hanami:1:in `each'
D, [2017-08-17T21:53:24.225653 #251] DEBUG -- : bidi-write-loop: done
D, [2017-08-17T21:53:24.229907 #251] DEBUG -- : bidi-write-loop: finished
W, [2017-08-17T21:53:24.228675 #251]  WARN -- : bidi: read-loop failed
W, [2017-08-17T21:53:24.230406 #251]  WARN -- : 12:Method not found: google.pubsub.v1.Subscriber/StreamingPull (GRPC::Unimplemented)
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/active_call.rb:46:in `check_status'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:198:in `block in read_loop'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:185:in `loop'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:185:in `read_loop'
/usr/local/bundle/bin/hanami:1:in `each'

Well, I don't have time enough now to go deeper into the gem's code and and try to check what's happening so I hope this report can somehow guide you guys on figuring it out.

Should I stick with and older version for now?

Cheers!

mdietz94 commented 7 years ago

Could you provide information about your environment, for example the OS, and the output of gem list? We have not yet been able to reproduce this on our machines, and understanding what is different about your environment would be a big help.

Thanks

tiagopog commented 7 years ago

All right, here's the requested information:

root@0677a78a0db2:/app# uname -a
Linux 0677a78a0db2 4.9.41-moby #1 SMP Thu Aug 10 20:01:08 UTC 2017 x86_64 GNU/Linux

root@0677a78a0db2:/app# cat /etc/issue.net
Debian GNU/Linux 8

root@0677a78a0db2:/app# gem list

*** LOCAL GEMS ***

activesupport (5.0.5)
addressable (2.4.0)
bigdecimal (default: 1.2.8)
bundler (1.15.1, 1.13.6)
byebug (9.0.5)
capybara (2.7.1)
coderay (1.1.1)
concurrent-ruby (1.0.2)
did_you_mean (1.0.0)
domain_name (0.5.20170404)
dotenv (2.1.1)
dry-configurable (0.1.7)
dry-container (0.3.4)
dry-equalizer (0.2.0)
dry-logic (0.3.0)
dry-monads (0.0.2)
dry-types (0.8.1)
dry-validation (0.9.3)
faraday (0.13.0)
google-cloud-core (1.0.0)
google-cloud-datastore (1.1.0)
google-cloud-env (1.0.1)
google-cloud-pubsub (0.27.0)
google-gax (0.8.6)
google-protobuf (3.2.0.2 x86_64-linux)
googleapis-common-protos (1.3.5)
googleauth (0.5.3)
grpc (1.4.5 x86_64-linux)
grpc-google-iam-v1 (0.6.8)
hanami (0.8.0)
hanami-assets (0.3.0)
hanami-controller (0.7.0)
hanami-helpers (0.4.0)
hanami-mailer (0.3.0)
hanami-model (0.6.1)
hanami-router (0.7.0)
hanami-utils (0.8.0)
hanami-validations (0.6.0)
hanami-view (0.7.0)
http-cookie (1.0.3)
http_router (0.11.2)
i18n (0.8.6)
ice_nine (0.11.2)
inflecto (0.0.2)
io-console (default: 0.4.5)
json (default: 1.8.3)
jwt (1.5.4)
little-plugger (1.1.4)
logging (2.2.2)
mail (2.6.4)
memoist (0.16.0)
method_source (0.8.2)
mime-types (3.1)
mime-types-data (3.2016.0521)
mini_portile2 (2.1.0)
minitest (5.9.0, 5.8.5)
multi_json (1.12.1)
multipart-post (2.0.0)
net-telnet (0.1.1)
netrc (0.11.0)
nokogiri (1.6.8)
os (0.9.6)
paypal-sdk-core (0.3.4)
paypal-sdk-merchant (1.117.2)
piped_ruby (0.2.1)
pkg-config (1.1.7)
power_assert (0.2.6)
pry (0.10.4)
pry-byebug (3.4.0)
psych (default: 2.1.0)
puma (3.6.0)
rack (1.6.4)
rack-test (0.6.3)
rake (11.2.2, 10.4.2)
rdoc (default: 4.2.1)
rest-client (2.0.2)
rly (0.2.3)
rubygems-update (2.6.8)
sequel (4.37.0)
shotgun (0.9.1)
signet (0.7.3)
slop (3.6.0)
test-unit (3.1.5)
thor (0.19.1)
thread_safe (0.3.6)
tilt (2.0.5)
tzinfo (1.2.3)
unf (0.1.4)
unf_ext (0.0.7.4)
url_mount (0.2.1)
xml-simple (1.1.5)
xpath (2.0.0)

groob commented 7 years ago

@mdietz94 (I work with @NickTitle )

We are on GKE, deploying our rails app in a FROM ruby:2.4.1 container. I'm in the ruby channel on GCP slack (also @groob) if I can be of further assistance. Here is our gem list:

GIT
  remote: git@github.com:acme/fake_stripe.git
  revision: ef58afcb0895cac22321d8bc97bbdb366c624641
  specs:
    fake_stripe (0.0.12)
      capybara
      sinatra
      webmock

GIT
  remote: git@github.com:acme/acme-private-api.git
  revision: a6b88407df4a9b164346401eb9813780b5f5ecdd
  ref: a6b8840
  specs:
    acme-private-api (0.2.2)
      hashie

GIT
  remote: git@github.com:acme/acme-private-configuration.git
  revision: 3c56308951ed994dcca56c6eed5f0cdd8a9e5029
  ref: 3c56308
  specs:
    acme-private-configuration (0.1.1)
      hashie

GIT
  remote: git@github.com:acme/ruby-sqlite-parser.git
  revision: 28662366e9bbeb5e6801fe3080a88843ea9e4569
  specs:
    sqlite_parser (0.1.0)
      execjs

GIT
  remote: git@github.com:zquestz/omniauth-google-oauth2.git
  revision: 6364a35581d0443c96b82535e02a86f3bf5b8732
  specs:
    omniauth-google-oauth2 (0.5.2)
      jwt (~> 1.5)
      multi_json (~> 1.3)
      omniauth (>= 1.1.1)
      omniauth-oauth2 (>= 1.3.1)

GIT
  remote: https://@github.com/acme/ua-parser-ruby.git
  revision: d67e8c82f22f678288c87bfbe64e6eefae591ff5
  specs:
    ua_parser (0.7.12)
      execjs

GIT
  remote: https://github.com/assaf/vanity.git
  revision: 7d21f20a7158c1cb621c04075abb0ee979d05b50
  ref: 7d21f20
  specs:
    vanity (2.2.7)
      i18n

GIT
  remote: https://github.com/influitive/apartment.git
  revision: 33bf153d233176a788fc5fda25f6598d54f4165b
  ref: 33bf153
  specs:
    apartment (1.2.0)
      activerecord (>= 3.1.2, < 6.0)
      public_suffix (~> 2.0.5)
      rack (>= 1.3.6)

GIT
  remote: https://github.com/acme/ace-rails-ap.git
  revision: 4f6fb8720c311297a4eb96c699e5a9b0aab624de
  ref: 4f6fb87
  specs:
    ace-rails-ap (4.1.2)

GEM
  remote: https://rubygems.org/
  remote: https://rails-assets.org/
  specs:
    actioncable (5.1.3)
      actionpack (= 5.1.3)
      nio4r (~> 2.0)
      websocket-driver (~> 0.6.1)
    actionmailer (5.1.3)
      actionpack (= 5.1.3)
      actionview (= 5.1.3)
      activejob (= 5.1.3)
      mail (~> 2.5, >= 2.5.4)
      rails-dom-testing (~> 2.0)
    actionpack (5.1.3)
      actionview (= 5.1.3)
      activesupport (= 5.1.3)
      rack (~> 2.0)
      rack-test (~> 0.6.3)
      rails-dom-testing (~> 2.0)
      rails-html-sanitizer (~> 1.0, >= 1.0.2)
    actionview (5.1.3)
      activesupport (= 5.1.3)
      builder (~> 3.1)
      erubi (~> 1.4)
      rails-dom-testing (~> 2.0)
      rails-html-sanitizer (~> 1.0, >= 1.0.3)
    activejob (5.1.3)
      activesupport (= 5.1.3)
      globalid (>= 0.3.6)
    activemodel (5.1.3)
      activesupport (= 5.1.3)
    activerecord (5.1.3)
      activemodel (= 5.1.3)
      activesupport (= 5.1.3)
      arel (~> 8.0)
    activerecord-session_store (1.1.0)
      actionpack (>= 4.0, < 5.2)
      activerecord (>= 4.0, < 5.2)
      multi_json (~> 1.11, >= 1.11.2)
      rack (>= 1.5.2, < 3)
      railties (>= 4.0, < 5.2)
    activesupport (5.1.3)
      concurrent-ruby (~> 1.0, >= 1.0.2)
      i18n (~> 0.7)
      minitest (~> 5.1)
      tzinfo (~> 1.1)
    addressable (2.5.1)
      public_suffix (~> 2.0, >= 2.0.2)
    arel (8.0.0)
    autoprefixer-rails (7.1.0)
      execjs
    aws-sdk (2.10.22)
      aws-sdk-resources (= 2.10.22)
    aws-sdk-core (2.10.22)
      aws-sigv4 (~> 1.0)
      jmespath (~> 1.0)
    aws-sdk-resources (2.10.22)
      aws-sdk-core (= 2.10.22)
    aws-sigv4 (1.0.1)
    base32 (0.3.2)
    bcrypt (3.1.11)
    best_in_place (3.1.0)
      actionpack (>= 3.2)
      railties (>= 3.2)
    bindex (0.5.0)
    bourbon (4.2.7)
      sass (~> 3.4)
      thor (~> 0.19)
    brakeman (3.7.0)
    browserify-rails (4.2.0)
      addressable (>= 2.4.0)
      railties (>= 4.0.0, < 5.2)
      sprockets (>= 3.6.0)
    bugsnag (5.3.3)
    builder (3.2.3)
    byebug (9.0.6)
    capybara (2.15.1)
      addressable
      mini_mime (>= 0.1.3)
      nokogiri (>= 1.3.3)
      rack (>= 1.0.0)
      rack-test (>= 0.5.4)
      xpath (~> 2.0)
    chunky_png (1.3.8)
    cliver (0.3.2)
    coderay (1.1.1)
    concurrent-ruby (1.0.5)
    connection_pool (2.2.1)
    content_for_in_controllers (0.0.2)
    crack (0.4.3)
      safe_yaml (~> 1.0.0)
    declarative (0.0.9)
    declarative-option (0.1.0)
    diff-lcs (1.3)
    digest-crc (0.4.1)
    domain_name (0.5.20170404)
      unf (>= 0.0.5, < 1.0.0)
    doorkeeper (4.2.0)
      railties (>= 4.2)
    dotenv (2.2.1)
    dotenv-rails (2.2.1)
      dotenv (= 2.2.1)
      railties (>= 3.2, < 5.2)
    erubi (1.6.1)
    et-orbi (1.0.5)
      tzinfo
    exception_notification (4.2.1)
      actionmailer (>= 4.0, < 6)
      activesupport (>= 4.0, < 6)
    execjs (2.7.0)
    factory_girl (4.7.0)
      activesupport (>= 3.0.0)
    factory_girl_rails (4.7.0)
      factory_girl (~> 4.7.0)
      railties (>= 3.0.0)
    faker (1.8.4)
      i18n (~> 0.5)
    faraday (0.11.0)
      multipart-post (>= 1.2, < 3)
    ffi (1.9.18)
    foreman (0.83.0)
      thor (~> 0.19.1)
    friendly_id (5.2.1)
      activerecord (>= 4.0.0)
    frozen_record (0.8.0)
      activemodel
    geocoder (1.4.0)
    geoip (1.6.2)
    globalid (0.4.0)
      activesupport (>= 4.2.0)
    google-api-client (0.13.0)
      addressable (~> 2.5, >= 2.5.1)
      googleauth (~> 0.5)
      httpclient (>= 2.8.1, < 3.0)
      mime-types (~> 3.0)
      representable (~> 3.0)
      retriable (>= 2.0, < 4.0)
    google-cloud-core (1.0.0)
      google-cloud-env (~> 1.0)
      googleauth (~> 0.5.1)
    google-cloud-env (1.0.1)
      faraday (~> 0.11)
    google-cloud-pubsub (0.27.0)
      concurrent-ruby (~> 1.0)
      google-cloud-core (~> 1.0)
      google-gax (~> 0.8.0)
      grpc (~> 1.1)
      grpc-google-iam-v1 (~> 0.6.8)
    google-cloud-storage (1.4.0)
      digest-crc (~> 0.4)
      google-api-client (~> 0.13.0)
      google-cloud-core (~> 1.0)
    google-gax (0.8.6)
      google-protobuf (~> 3.2)
      googleapis-common-protos (~> 1.3.5)
      googleauth (~> 0.5.1)
      grpc (~> 1.0)
      rly (~> 0.2.3)
    google-protobuf (3.3.0)
    googleapis-common-protos (1.3.5)
      google-protobuf (~> 3.2)
      grpc (~> 1.0)
    googleauth (0.5.1)
      faraday (~> 0.9)
      jwt (~> 1.4)
      logging (~> 2.0)
      memoist (~> 0.12)
      multi_json (~> 1.11)
      os (~> 0.9)
      signet (~> 0.7)
    gravtastic (3.2.6)
    grpc (1.3.4)
      google-protobuf (~> 3.1)
      googleauth (~> 0.5.1)
    grpc-google-iam-v1 (0.6.8)
      googleapis-common-protos (~> 1.3.1)
      googleauth (~> 0.5.1)
      grpc (~> 1.0)
    hashdiff (0.3.5)
    hashie (3.5.6)
    health_check (2.5.0)
      rails (>= 4.0)
    http-cookie (1.0.3)
      domain_name (~> 0.5)
    httpclient (2.8.3)
    i18n (0.8.6)
    inline_svg (0.11.1)
      activesupport (>= 4.0)
      loofah (>= 2.0)
      nokogiri (~> 1.6)
    intercom-rails (0.3.4)
      activesupport (> 3.0)
    jbuilder (2.7.0)
      activesupport (>= 4.2.0)
      multi_json (>= 1.2)
    jmespath (1.3.1)
    jquery-rails (4.3.1)
      rails-dom-testing (>= 1, < 3)
      railties (>= 4.2.0)
      thor (>= 0.14, < 2.0)
    json (2.1.0)
    jsonb_accessor (1.0.0.beta.6)
      activerecord (>= 5.0)
      activesupport (>= 5.0)
      pg (>= 0.18.1)
    jwt (1.5.6)
    kaminari (1.0.1)
      activesupport (>= 4.1.0)
      kaminari-actionview (= 1.0.1)
      kaminari-activerecord (= 1.0.1)
      kaminari-core (= 1.0.1)
    kaminari-actionview (1.0.1)
      actionview
      kaminari-core (= 1.0.1)
    kaminari-activerecord (1.0.1)
      activerecord
      kaminari-core (= 1.0.1)
    kaminari-core (1.0.1)
    launchy (2.4.3)
      addressable (~> 2.3)
    letter_opener (1.4.1)
      launchy (~> 2.2)
    listen (3.1.5)
      rb-fsevent (~> 0.9, >= 0.9.4)
      rb-inotify (~> 0.9, >= 0.9.7)
      ruby_dep (~> 1.2)
    little-plugger (1.1.4)
    logging (2.2.2)
      little-plugger (~> 1.1)
      multi_json (~> 1.10)
    lograge (0.5.1)
      actionpack (>= 4, < 5.2)
      activesupport (>= 4, < 5.2)
      railties (>= 4, < 5.2)
    loofah (2.0.3)
      nokogiri (>= 1.5.9)
    mail (2.6.6)
      mime-types (>= 1.16, < 4)
    memoist (0.16.0)
    method_source (0.8.2)
    migration_data (0.3.0)
    mime-types (3.1)
      mime-types-data (~> 3.2015)
    mime-types-data (3.2016.0521)
    mini_mime (0.1.4)
    mini_portile2 (2.1.0)
    minitest (5.10.3)
    multi_json (1.12.1)
    multi_xml (0.6.0)
    multipart-post (2.0.0)
    munemo (1.0.1)
    mustermann (1.0.0)
    netrc (0.11.0)
    nio4r (2.1.0)
    nokogiri (1.7.2)
      mini_portile2 (~> 2.1.0)
    oauth2 (1.3.1)
      faraday (>= 0.8, < 0.12)
      jwt (~> 1.0)
      multi_json (~> 1.3)
      multi_xml (~> 0.5)
      rack (>= 1.2, < 3)
    octokit (4.7.0)
      sawyer (~> 0.8.0, >= 0.5.3)
    oj (3.0.6)
    omniauth (1.6.1)
      hashie (>= 3.4.6, < 3.6.0)
      rack (>= 1.6.2, < 3)
    omniauth-azure-activedirectory (1.0.0)
      jwt (~> 1.5)
      omniauth (~> 1.1)
    omniauth-github (1.2.3)
      omniauth (~> 1.5)
      omniauth-oauth2 (>= 1.4.0, < 2.0)
    omniauth-oauth2 (1.4.0)
      oauth2 (~> 1.0)
      omniauth (~> 1.2)
    os (0.9.6)
    percy-capybara (2.3.3)
      percy-client (~> 1.9)
    percy-client (1.13.3)
      addressable
      faraday (>= 0.9)
      httpclient (>= 2.6)
    pg (0.20.0)
    phony (2.15.47)
    phony_rails (0.14.4)
      activesupport (>= 3.0)
      phony (~> 2.15)
    poltergeist (1.13.0)
      capybara (~> 2.1)
      cliver (~> 0.3.1)
      websocket-driver (>= 0.2.0)
    prometheus-client (0.6.0)
      quantile (~> 0.2.0)
    pry (0.10.4)
      coderay (~> 1.1.0)
      method_source (~> 0.8.1)
      slop (~> 3.4)
    pry-rails (0.3.6)
      pry (>= 0.10.4)
    public_suffix (2.0.5)
    puma (3.9.1)
    quantile (0.2.0)
    rack (2.0.3)
    rack-attack (5.0.1)
      rack
    rack-protection (2.0.0)
      rack
    rack-test (0.6.3)
      rack (>= 1.0)
    rails (5.1.3)
      actioncable (= 5.1.3)
      actionmailer (= 5.1.3)
      actionpack (= 5.1.3)
      actionview (= 5.1.3)
      activejob (= 5.1.3)
      activemodel (= 5.1.3)
      activerecord (= 5.1.3)
      activesupport (= 5.1.3)
      bundler (>= 1.3.0)
      railties (= 5.1.3)
      sprockets-rails (>= 2.0.0)
    rails-assets-animate.css (3.5.2)
    rails-assets-clipboard (1.5.16)
    rails-assets-gmaps.js (0.4.24)
    rails-assets-normalize-css (5.0.0)
    rails-controller-testing (1.0.1)
      actionpack (~> 5.x)
      actionview (~> 5.x)
      activesupport (~> 5.x)
    rails-dom-testing (2.0.3)
      activesupport (>= 4.2.0)
      nokogiri (>= 1.6)
    rails-html-sanitizer (1.0.3)
      loofah (~> 2.0)
    rails_12factor (0.0.3)
      rails_serve_static_assets
      rails_stdout_logging
    rails_serve_static_assets (0.0.5)
    rails_stdout_logging (0.0.5)
    railties (5.1.3)
      actionpack (= 5.1.3)
      activesupport (= 5.1.3)
      method_source
      rake (>= 0.8.7)
      thor (>= 0.18.1, < 2.0)
    rake (12.0.0)
    rb-fsevent (0.10.2)
    rb-inotify (0.9.10)
      ffi (>= 0.5.0, < 2)
    recaptcha (4.1.0)
      json
    redcarpet (3.4.0)
    redis (3.3.3)
    redis-actionpack (5.0.1)
      actionpack (>= 4.0, < 6)
      redis-rack (>= 1, < 3)
      redis-store (>= 1.1.0, < 1.4.0)
    redis-activesupport (5.0.1)
      activesupport (>= 3, < 6)
      redis-store (~> 1.2.0)
    redis-namespace (1.5.2)
      redis (~> 3.0, >= 3.0.4)
    redis-rack (2.0.2)
      rack (>= 1.5, < 3)
      redis-store (>= 1.2, < 1.4)
    redis-rails (5.0.1)
      redis-actionpack (~> 5.0.0)
      redis-activesupport (~> 5.0.0)
      redis-store (~> 1.2.0)
    redis-store (1.2.0)
      redis (>= 2.2)
    representable (3.0.4)
      declarative (< 0.1.0)
      declarative-option (< 0.2.0)
      uber (< 0.2.0)
    rest-client (2.0.2)
      http-cookie (>= 1.0.2, < 2.0)
      mime-types (>= 1.16, < 4.0)
      netrc (~> 0.8)
    retriable (3.1.1)
    rly (0.2.3)
    rotp (3.3.0)
    rqrcode (0.10.1)
      chunky_png (~> 1.0)
    rspec-core (3.6.0)
      rspec-support (~> 3.6.0)
    rspec-expectations (3.6.0)
      diff-lcs (>= 1.2.0, < 2.0)
      rspec-support (~> 3.6.0)
    rspec-json_expectations (2.1.0)
    rspec-mocks (3.6.0)
      diff-lcs (>= 1.2.0, < 2.0)
      rspec-support (~> 3.6.0)
    rspec-rails (3.6.0)
      actionpack (>= 3.0)
      activesupport (>= 3.0)
      railties (>= 3.0)
      rspec-core (~> 3.6.0)
      rspec-expectations (~> 3.6.0)
      rspec-mocks (~> 3.6.0)
      rspec-support (~> 3.6.0)
    rspec-support (3.6.0)
    rspec_junit_formatter (0.2.3)
      builder (< 4)
      rspec-core (>= 2, < 4, != 2.12.0)
    ruby_dep (1.5.0)
    rufus-scheduler (3.4.2)
      et-orbi (~> 1.0)
    safe_yaml (1.0.4)
    sass (3.4.25)
    sass-rails (5.0.6)
      railties (>= 4.0.0, < 6)
      sass (~> 3.1)
      sprockets (>= 2.8, < 4.0)
      sprockets-rails (>= 2.0, < 4.0)
      tilt (>= 1.1, < 3)
    sawyer (0.8.1)
      addressable (>= 2.3.5, < 2.6)
      faraday (~> 0.8, < 1.0)
    scss_lint (0.54.0)
      rake (>= 0.9, < 13)
      sass (~> 3.4.20)
    secure_headers (3.5.1)
      useragent
    shoulda-matchers (3.1.1)
      activesupport (>= 4.0.0)
    sidekiq (4.2.6)
      concurrent-ruby (~> 1.0)
      connection_pool (~> 2.2, >= 2.2.0)
      rack-protection (>= 1.5.0)
      redis (~> 3.2, >= 3.2.1)
    sidekiq-cron (0.4.5)
      redis-namespace (>= 1.5.2)
      rufus-scheduler (>= 2.0.24)
      sidekiq (>= 4.2.1)
    sidekiq-unique-jobs (5.0.8)
      sidekiq (>= 4.0, <= 6.0)
      thor (~> 0)
    signet (0.7.3)
      addressable (~> 2.3)
      faraday (~> 0.9)
      jwt (~> 1.5)
      multi_json (~> 1.10)
    simple_form (3.5.0)
      actionpack (> 4, < 5.2)
      activemodel (> 4, < 5.2)
    sinatra (2.0.0)
      mustermann (~> 1.0)
      rack (~> 2.0)
      rack-protection (= 2.0.0)
      tilt (~> 2.0)
    skylight (1.3.1)
      activesupport (>= 3.0.0)
    slack-notifier (1.5.1)
    slop (3.6.0)
    spring (2.0.2)
      activesupport (>= 4.2)
    spring-commands-rspec (1.0.4)
      spring (>= 0.9.1)
    spring-watcher-listen (2.0.1)
      listen (>= 2.7, < 4.0)
      spring (>= 1.2, < 3.0)
    sprockets (3.7.1)
      concurrent-ruby (~> 1.0)
      rack (> 1, < 3)
    sprockets-rails (3.2.0)
      actionpack (>= 4.0)
      activesupport (>= 4.0)
      sprockets (>= 3.0.0)
    stripe (3.2.0)
      faraday (~> 0.9)
    terminal-notifier (1.7.1)
    thor (0.19.4)
    thread_safe (0.3.6)
    tilt (2.0.8)
    turbolinks (5.0.1)
      turbolinks-source (~> 5)
    turbolinks-source (5.0.3)
    twilio-ruby (4.13.0)
      builder (>= 2.1.2)
      jwt (~> 1.0)
      multi_json (>= 1.3.0)
    tzinfo (1.2.3)
      thread_safe (~> 0.1)
    uber (0.1.0)
    uglifier (3.2.0)
      execjs (>= 0.3.0, < 3)
    unf (0.1.4)
      unf_ext
    unf_ext (0.0.7.4)
    useragent (0.16.8)
    web-console (3.5.1)
      actionview (>= 5.0)
      activemodel (>= 5.0)
      bindex (>= 0.4.0)
      railties (>= 5.0)
    webmock (3.0.1)
      addressable (>= 2.3.6)
      crack (>= 0.3.2)
      hashdiff
    webpacker (2.0)
      activesupport (>= 4.2)
      multi_json (~> 1.2)
      railties (>= 4.2)
    websocket-driver (0.6.5)
      websocket-extensions (>= 0.1.0)
    websocket-extensions (0.1.2)
    xpath (2.1.0)
      nokogiri (~> 1.3)
    zxcvbn-js (4.4.2)
      execjs

PLATFORMS
  ruby

DEPENDENCIES
  ace-rails-ap!
  activerecord-session_store (= 1.1.0)
  apartment!
  autoprefixer-rails (= 7.1)
  aws-sdk (~> 2.9)
  base32 (= 0.3.2)
  bcrypt (~> 3.1.7)
  best_in_place (= 3.1.0)
  bourbon (= 4.2.7)
  brakeman
  browserify-rails (= 4.2.0)
  bugsnag
  byebug
  capybara
  content_for_in_controllers (= 0.0.2)
  doorkeeper (= 4.2.0)
  dotenv-rails (= 2.2.1)
  exception_notification (= 4.2.1)
  factory_girl_rails (= 4.7.0)
  fake_stripe!
  faker
  faraday (= 0.11)
  foreman (= 0.83.0)
  friendly_id (= 5.2.1)
  frozen_record (= 0.8.0)
  geocoder (= 1.4.0)
  geoip (= 1.6.2)
  google-api-client (= 0.13.0)
  google-cloud-env
  google-cloud-pubsub
  google-cloud-storage (~> 1.3)
  googleauth (= 0.5.1)
  gravtastic (= 3.2.6)
  grpc (= 1.3.4)
  health_check (= 2.5.0)
  inline_svg (= 0.11.1)
  intercom-rails (= 0.3.4)
  jbuilder (~> 2.5)
  jquery-rails
  jsonb_accessor (= 1.0.0.beta.6)
  jwt (= 1.5.6)
  kaminari (= 1.0.1)
  acme-private-api!
  acme-private-configuration (= 0.1.1)!
  letter_opener (= 1.4.1)
  listen (>= 3.0.5, < 3.2)
  lograge (= 0.5.1)
  migration_data (= 0.3.0)
  munemo (= 1.0.1)
  nokogiri (= 1.7.2)
  oauth2 (= 1.3.1)
  octokit (= 4.7.0)
  oj (= 3.0.6)
  omniauth (= 1.6.1)
  omniauth-azure-activedirectory (= 1.0.0)
  omniauth-github (= 1.2.3)
  omniauth-google-oauth2!
  percy-capybara (= 2.3.3)
  pg (= 0.20.0)
  phony_rails (= 0.14.4)
  poltergeist (= 1.13.0)
  prometheus-client (= 0.6.0)
  pry (= 0.10.4)
  pry-rails
  puma (~> 3.7)
  rack-attack (= 5.0.1)
  rails (= 5.1.3)
  rails-assets-animate.css (= 3.5.2)!
  rails-assets-clipboard (= 1.5.16)!
  rails-assets-gmaps.js (= 0.4.24)!
  rails-assets-normalize-css (= 5.0.0)!
  rails-controller-testing (= 1.0.1)
  rails_12factor (= 0.0.3)
  recaptcha (= 4.1.0)
  redcarpet (= 3.4.0)
  redis-namespace (= 1.5.2)
  redis-rails (= 5.0.1)
  rest-client (= 2.0.2)
  rotp (= 3.3.0)
  rqrcode (= 0.10.1)
  rspec-json_expectations (= 2.1.0)
  rspec-rails (= 3.6)
  rspec_junit_formatter (= 0.2.3)
  sass-rails (~> 5.0)
  scss_lint
  secure_headers (= 3.5.1)
  shoulda-matchers (= 3.1.1)
  sidekiq (= 4.2.6)
  sidekiq-cron (= 0.4.5)
  sidekiq-unique-jobs (= 5.0.8)
  signet (= 0.7.3)
  simple_form (= 3.5.0)
  skylight
  slack-notifier (= 1.5.1)
  spring
  spring-commands-rspec
  spring-watcher-listen (~> 2.0.0)
  sqlite_parser!
  stripe (= 3.2.0)
  terminal-notifier (= 1.7.1)
  turbolinks (~> 5)
  twilio-ruby (= 4.13.0)
  tzinfo-data
  ua_parser!
  uglifier (>= 1.3.0)
  vanity!
  web-console
  webpacker (= 2.0)
  zxcvbn-js (= 4.4.2)

BUNDLED WITH
   1.15.3

And gem list from macOS environment that nick is working off of:

*** LOCAL GEMS ***

actioncable (5.1.3, 5.1.1, 5.1.0)
actionmailer (5.1.3, 5.1.1, 5.1.0)
actionpack (5.1.3, 5.1.1, 5.1.0)
actionview (5.1.3, 5.1.1, 5.1.0)
activejob (5.1.3, 5.1.1, 5.1.0)
activemodel (5.1.3, 5.1.1, 5.1.0)
activerecord (5.1.3, 5.1.1, 5.1.0)
activerecord-session_store (1.1.0)
activesupport (5.1.3, 5.1.1, 5.1.0)
addressable (2.5.1)
arel (8.0.0)
autoprefixer-rails (7.1.0)
aws-sdk (2.10.22)
aws-sdk-core (2.10.22)
aws-sdk-resources (2.10.22)
aws-sigv4 (1.0.1)
base32 (0.3.2)
bcrypt (3.1.11)
best_in_place (3.1.0)
bigdecimal (default: 1.3.0)
bindex (0.5.0)
binding_of_caller (0.7.2)
bourbon (4.2.7)
brakeman (3.7.0, 3.6.2, 3.6.1)
browserify-rails (4.2.0)
bugsnag (5.3.3, 5.3.2)
builder (3.2.3)
bundler (1.15.3, 1.15.2, 1.15.1, 1.15.0)
byebug (9.0.6)
capybara (2.15.1, 2.14.3, 2.14.0)
chunky_png (1.3.8)
cliver (0.3.2)
coderay (1.1.1)
concurrent-ruby (1.0.5)
connection_pool (2.2.1)
content_for_in_controllers (0.0.2)
crack (0.4.3)
database_cleaner (1.6.1)
debug_inspector (0.0.3)
declarative (0.0.9)
declarative-option (0.1.0)
did_you_mean (1.1.0)
diff-lcs (1.3)
digest-crc (0.4.1)
domain_name (0.5.20170404)
doorkeeper (4.2.0)
dotenv (2.2.1)
dotenv-rails (2.2.1)
erubi (1.6.1, 1.6.0)
et-orbi (1.0.5, 1.0.4)
exception_notification (4.2.1)
execjs (2.7.0)
factory_girl (4.7.0)
factory_girl_rails (4.7.0)
faker (1.8.4)
faraday (0.13.0, 0.12.1, 0.11.0)
ffi (1.9.18)
foreman (0.83.0)
friendly_id (5.2.1)
frozen_record (0.8.0)
geocoder (1.4.0)
geoip (1.6.2)
globalid (0.4.0)
google-api-client (0.13.0, 0.11.2)
google-cloud-core (1.0.0)
google-cloud-debugger (0.27.0)
google-cloud-env (1.0.1, 1.0.0)
google-cloud-error_reporting (0.26.1, 0.25.0)
google-cloud-logging (1.2.1, 1.1.0)
google-cloud-pubsub (0.25.0)
google-cloud-storage (1.4.0)
google-cloud-trace (0.27.0, 0.25.0)
google-gax (0.8.6, 0.8.3, 0.8.2)
google-protobuf (3.4.0 universal-darwin, 3.3.0 universal-darwin, 3.2.0 universal-darwin)
googleapis-common-protos (1.3.5)
googleauth (0.5.3, 0.5.2, 0.5.1)
gravtastic (3.2.6)
grpc (1.4.5 universal-darwin, 1.4.1 universal-darwin, 1.3.4 universal-darwin)
grpc-google-iam-v1 (0.6.8)
hashdiff (0.3.5)
hashie (3.5.6, 3.5.5)
health_check (2.5.0)
http-cookie (1.0.3)
httpclient (2.8.3)
i18n (0.8.6, 0.8.4, 0.8.1)
inline_svg (0.11.1)
intercom-rails (0.3.4)
io-console (default: 0.4.6)
jbuilder (2.7.0, 2.6.4)
jmespath (1.3.1)
jquery-rails (4.3.1)
json (2.1.0, default: 2.0.2)
jsonb_accessor (1.0.0.beta.6)
jwt (1.5.6)
kaminari (1.0.1)
kaminari-actionview (1.0.1)
kaminari-activerecord (1.0.1)
kaminari-core (1.0.1)
launchy (2.4.3)
letter_opener (1.4.1)
listen (3.1.5)
little-plugger (1.1.4)
logging (2.2.2)
lograge (0.5.1, 0.5.0)
loofah (2.0.3)
mail (2.6.6, 2.6.5)
memoist (0.16.0, 0.15.0)
method_source (0.8.2)
migration_data (0.3.0)
mime-types (3.1)
mime-types-data (3.2016.0521)
mini_mime (0.1.4)
mini_portile2 (2.1.0)
minitest (5.10.3, 5.10.2, 5.10.1)
multi_json (1.12.1)
multi_xml (0.6.0)
multipart-post (2.0.0)
munemo (1.0.1)
mustermann (1.0.0)
net-telnet (0.1.1)
netrc (0.11.0)
nio4r (2.1.0, 2.0.0)
nokogiri (1.7.2)
oauth2 (1.3.1)
octokit (4.7.0)
oj (3.0.6)
omniauth (1.6.1)
omniauth-azure-activedirectory (1.0.0)
omniauth-github (1.2.3)
omniauth-oauth2 (1.4.0)
openssl (default: 2.0.3)
os (0.9.6)
percy-capybara (2.3.3)
percy-client (1.13.3, 1.12.0, 1.11.0)
pg (0.20.0)
phony (2.15.47, 2.15.44)
phony_rails (0.14.4)
poltergeist (1.13.0)
power_assert (0.4.1)
prometheus-client (0.6.0)
pry (0.10.4)
pry-rails (0.3.6)
psych (default: 2.2.2)
public_suffix (2.0.5)
puma (3.9.1, 3.8.2)
quantile (0.2.0)
rack (2.0.3)
rack-attack (5.0.1)
rack-protection (2.0.0)
rack-test (0.6.3)
rails (5.1.3, 5.1.1, 5.1.0)
rails-assets-animate.css (3.5.2)
rails-assets-clipboard (1.5.16)
rails-assets-gmaps.js (0.4.24)
rails-assets-normalize-css (5.0.0)
rails-controller-testing (1.0.1)
rails-dom-testing (2.0.3)
rails-html-sanitizer (1.0.3)
rails_12factor (0.0.3)
rails_serve_static_assets (0.0.5)
rails_stdout_logging (0.0.5)
railties (5.1.3, 5.1.1, 5.1.0)
rake (12.0.0)
rb-fsevent (0.10.2, 0.9.8)
rb-inotify (0.9.10, 0.9.8)
rdoc (default: 5.0.0)
recaptcha (4.1.0)
redcarpet (3.4.0)
redis (3.3.3)
redis-actionpack (5.0.1)
redis-activesupport (5.0.1)
redis-namespace (1.5.2)
redis-rack (2.0.2)
redis-rails (5.0.1)
redis-store (1.2.0)
representable (3.0.4)
rest-client (2.0.2)
retriable (3.1.1, 3.0.2)
rly (0.2.3)
rotp (3.3.0)
rqrcode (0.10.1)
rspec-core (3.6.0)
rspec-expectations (3.6.0)
rspec-json_expectations (2.1.0)
rspec-mocks (3.6.0)
rspec-rails (3.6.0)
rspec-support (3.6.0)
rspec_junit_formatter (0.2.3)
ruby-kafka (0.3.17)
ruby_dep (1.5.0)
rufus-scheduler (3.4.2, 3.4.0)
safe_yaml (1.0.4)
sass (3.4.25, 3.4.24, 3.4.23)
sass-rails (5.0.6)
sawyer (0.8.1)
scss_lint (0.54.0, 0.53.0)
secure_headers (3.5.1)
shoulda-matchers (3.1.1)
sidekiq (4.2.6)
sidekiq-cron (0.4.5)
sidekiq-unique-jobs (5.0.8)
signet (0.7.3)
simple_form (3.5.0)
sinatra (2.0.0)
skylight (1.3.1, 1.2.2)
slack-notifier (1.5.1)
slop (3.6.0)
spring (2.0.2, 2.0.1)
spring-commands-rspec (1.0.4)
spring-watcher-listen (2.0.1)
sprockets (3.7.1)
sprockets-rails (3.2.0)
stackdriver (0.8.0, 0.6.0)
stackdriver-core (1.2.0, 1.1.0)
stripe (3.2.0)
terminal-notifier (1.7.1)
test-unit (3.2.3)
thor (0.19.4)
thread_safe (0.3.6)
tilt (2.0.8, 2.0.7)
turbolinks (5.0.1)
turbolinks-source (5.0.3)
twilio-ruby (4.13.0)
tzinfo (1.2.3)
uber (0.1.0)
uglifier (3.2.0)
unf (0.1.4)
unf_ext (0.0.7.4)
useragent (0.16.8)
web-console (3.5.1)
webmock (3.0.1)
webpacker (2.0)
websocket-driver (0.6.5)
websocket-extensions (0.1.2)
xmlrpc (0.2.1)
xpath (2.1.0, 2.0.0)
zxcvbn-js (4.4.2)

tiagopog commented 7 years ago

FYK I've downgraded from 0.27.0 to 0.26.0 and things got back working as expected.

blowmage commented 7 years ago

Yes, 0.27.0 included several changes, including calls to the new StreamingPull API. Downgrading to 0.26.0 will use the synchronous Pull.

geigerj commented 7 years ago

@groob @tiagopog @NickTitle We're still having trouble reproducing this bug internally. Could you run the reproduction code from the original report with the following environment variables set: GRPC_TRACE=http GRPC_VERBOSITY=debug? Then put the output into a gist or attach it as a text file to this issue.

That'll let see what is being sent over-the-wire from your environments and whether something is different from what we're sending when we try to reproduce.

NickTitle commented 7 years ago

@geigerj @blowmage @tiagopog i just figured it out!

Locally I was running the p/s emulator in docker, and though my gems were updated, the cloud-sdk image i had installed was WAY out of date.

google/cloud-sdk                                   latest              e226ddb12871        4 days ago          1.64GB
google/cloud-sdk                                   <none>              882e80ea5d89        7 weeks ago         1.65GB

I happened to update it when troubleshooting something else, and when I ran the example code today with the original commit checked out, it worked! By changing the docker image to the outdated one, the behavior came back.

Not sure how to communicate that best to users, but I figured I'd let you folks know. Thanks for your attention and time, hopefully this helps someone in the future!

blowmage commented 7 years ago

@groob Are you also targeting an emulator?

tiagopog commented 7 years ago

@geigerj, running with the env vars you've asked:

root@102514d8d65a:/app# GRPC_TRACE=http GRPC_VERBOSITY=debug hanami c
[1] pry(main)> ps = Google::Cloud::Pubsub.new(project:'test')
=> #<Google::Cloud::Pubsub::Project:0x0000000471d078 @service=Google::Cloud::Pubsub::Service(test)>

[2] pry(main)> topic = ps.topic('test-topic') || ps.create_topic('test-topic')
I0824 13:18:53.926786287     187 ev_epollsig_linux.c:90]     epoll engine will be using signal: 40
D0824 13:18:53.926842624     187 ev_posix.c:121]             Using polling engine: epollsig
D0824 13:18:53.926892967     187 dns_resolver.c:316]         Using native dns resolver
D0824 13:18:53.927418074     187 rb_channel.c:706]           GRPC_RUBY: wait for channel polling thread to start
D0824 13:18:53.927551623     193 rb_channel.c:696]           GRPC_RUBY: run_poll_channels_loop - create connection polling thread
D0824 13:18:53.927629336     193 rb_channel.c:620]           GRPC_RUBY: run_poll_channels_loop_no_gil - begin
D, [2017-08-24T13:18:53.940398 #187] DEBUG -- : calling pubsub:8042:443:/google.pubsub.v1.Publisher/GetTopic
I0824 13:18:53.942896807     194 socket_utils_common_posix.c:238] Disabling AF_INET6 sockets because ::1 is not available.
D0824 13:18:53.943311339     193 chttp2_transport.c:814]     W:0x7fc8640028b0 CLIENT state IDLE -> WRITING [initial_write]
D0824 13:18:53.943352193     193 chttp2_transport.c:814]     W:0x7fc8640028b0 CLIENT state WRITING -> WRITING+MORE [push_setting]
D0824 13:18:53.943470560     193 chttp2_transport.c:814]     W:0x7fc8640028b0 CLIENT state WRITING+MORE -> WRITING [begin writing]
D0824 13:18:53.943541180     193 chttp2_transport.c:814]     W:0x7fc8640028b0 CLIENT state WRITING -> IDLE [finish writing]
D0824 13:18:53.943715283     194 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc868004880]: [COVERED] SEND_INITIAL_METADATA{key=3a 73 63 68 65 6d 65 ':scheme' value=68 74 74 70 'http', key=3a 6d 65 74 68 6f 64 ':method' value=50 4f 53 54 'POST', key=3a 70 61 74 68 ':path' value=2f 67 6f 6f 67 6c 65 2e 70 75 62 73 75 62 2e 76 31 2e 50 75 62 6c 69 73 68 65 72 2f 47 65 74 54 6f 70 69 63 '/google.pubsub.v1.Publisher/GetTopic', key=3a 61 75 74 68 6f 72 69 74 79 ':authority' value=70 75 62 73 75 62 3a 38 30 34 32 'pubsub:8042', key=78 2d 67 6f 6f 67 2d 61 70 69 2d 63 6c 69 65 6e 74 'x-goog-api-client' value=67 6c 2d 72 75 62 79 2f 32 2e 33 2e 33 20 67 63 63 6c 2f 30 2e 32 37 2e 30 20 67 61 70 69 63 2f 30 2e 36 2e 38 20 67 61 78 2f 30 2e 38 2e 36 20 67 72 70 63 2f 31 2e 34 2e 35 'gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5', key=67 6f 6f 67 6c 65 2d 63 6c 6f 75 64 2d 72 65 73 6f 75 72 63 65 2d 70 72 65 66 69 78 'google-cloud-resource-prefix' value=70 72 6f 6a 65 63 74 73 2f 74 65 73 74 'projects/test', key=74 65 'te' value=74 72 61 69 6c 65 72 73 'trailers', key=63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type' value=61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc', key=75 73 65 72 2d 61 67 65 6e 74 'user-agent' value=67 72 70 63 2d 63 2f 34 2e 30 2e 30 20 28 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 3b 20 67 72 65 67 61 72 69 6f 75 73 29 'grpc-c/4.0.0 (linux; chttp2; gregarious)', key=67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding' value=69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip' deadline=279008.467269090} SEND_MESSAGE:flags=0x00000000:len=33 SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_MESSAGE RECV_TRAILING_METADATA
D0824 13:18:53.943803384     193 chttp2_transport.c:1254]    perform_stream_op_locked: [COVERED] SEND_INITIAL_METADATA{key=3a 73 63 68 65 6d 65 ':scheme' value=68 74 74 70 'http', key=3a 6d 65 74 68 6f 64 ':method' value=50 4f 53 54 'POST', key=3a 70 61 74 68 ':path' value=2f 67 6f 6f 67 6c 65 2e 70 75 62 73 75 62 2e 76 31 2e 50 75 62 6c 69 73 68 65 72 2f 47 65 74 54 6f 70 69 63 '/google.pubsub.v1.Publisher/GetTopic', key=3a 61 75 74 68 6f 72 69 74 79 ':authority' value=70 75 62 73 75 62 3a 38 30 34 32 'pubsub:8042', key=78 2d 67 6f 6f 67 2d 61 70 69 2d 63 6c 69 65 6e 74 'x-goog-api-client' value=67 6c 2d 72 75 62 79 2f 32 2e 33 2e 33 20 67 63 63 6c 2f 30 2e 32 37 2e 30 20 67 61 70 69 63 2f 30 2e 36 2e 38 20 67 61 78 2f 30 2e 38 2e 36 20 67 72 70 63 2f 31 2e 34 2e 35 'gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5', key=67 6f 6f 67 6c 65 2d 63 6c 6f 75 64 2d 72 65 73 6f 75 72 63 65 2d 70 72 65 66 69 78 'google-cloud-resource-prefix' value=70 72 6f 6a 65 63 74 73 2f 74 65 73 74 'projects/test', key=74 65 'te' value=74 72 61 69 6c 65 72 73 'trailers', key=63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type' value=61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc', key=75 73 65 72 2d 61 67 65 6e 74 'user-agent' value=67 72 70 63 2d 63 2f 34 2e 30 2e 30 20 28 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 3b 20 67 72 65 67 61 72 69 6f 75 73 29 'grpc-c/4.0.0 (linux; chttp2; gregarious)', key=67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding' value=69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip' deadline=279008.467269090} SEND_MESSAGE:flags=0x00000000:len=33 SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_MESSAGE RECV_TRAILING_METADATA; on_complete = 0x7fc8680045e0
I0824 13:18:53.943845736     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :scheme: http
I0824 13:18:53.943869909     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :method: POST
I0824 13:18:53.943887989     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :path: /google.pubsub.v1.Publisher/GetTopic
I0824 13:18:53.943903072     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :authority: pubsub:8042
I0824 13:18:53.943920452     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: x-goog-api-client: gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5
I0824 13:18:53.943941528     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: google-cloud-resource-prefix: projects/test
I0824 13:18:53.943959008     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: te: trailers
I0824 13:18:53.943975590     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: content-type: application/grpc
I0824 13:18:53.943992371     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: user-agent: grpc-c/4.0.0 (linux; chttp2; gregarious)
D0824 13:18:53.944023236     193 chttp2_transport.c:1043]    HTTP:CLI: Allocating new grpc_chttp2_stream 0x7fc868004880 to id 1
D0824 13:18:53.944201934     193 chttp2_transport.c:814]     W:0x7fc8640028b0 CLIENT state IDLE -> WRITING [new_stream]
D0824 13:18:53.944285041     193 chttp2_transport.c:814]     W:0x7fc8640028b0 CLIENT state WRITING -> WRITING+MORE+COVERED [op.send_message]
D0824 13:18:53.944415493     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc8680045e0 refs=4 flags=0x0003 desc=op->on_complete err="No Error"
D0824 13:18:53.944721049     193 writing.c:235]              W:0x7fc8640028b0 CLIENT[1] im-(sent,send)=(0,1) announce=5
D0824 13:18:53.944769094     193 hpack_encoder.c:432]        Encode: ':path: /google.pubsub.v1.Publisher/GetTopic', elem_interned=0 [2], k_interned=1, v_interned=0
D0824 13:18:53.944808350     193 hpack_encoder.c:432]        Encode: 'x-goog-api-client: gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5', elem_interned=0 [0], k_interned=0, v_interned=0
D0824 13:18:53.944840314     193 hpack_encoder.c:432]        Encode: 'google-cloud-resource-prefix: projects/test', elem_interned=0 [0], k_interned=0, v_interned=0
D0824 13:18:53.944891356     193 hpack_encoder.c:432]        Encode: 'grpc-timeout: 60S', elem_interned=0 [2], k_interned=1, v_interned=0
D0824 13:18:53.944982753     193 chttp2_transport.c:814]     W:0x7fc8640028b0 CLIENT state WRITING+MORE+COVERED -> WRITING [begin writing]
D0824 13:18:53.945265834     193 chttp2_transport.c:814]     W:0x7fc8640028b0 CLIENT state WRITING -> IDLE [finish writing]
D0824 13:18:53.945654595     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc8680045e0 refs=3 flags=0x0003 desc=send_initial_metadata_finished err="No Error"
D0824 13:18:53.945695549     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc8680045e0 refs=2 flags=0x0003 desc=finish_write_cb err="No Error"
D0824 13:18:53.945730210     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc8680045e0 refs=1 flags=0x0003 desc=send_trailing_metadata_finished err="No Error"
D0824 13:18:53.953073723     193 frame_settings.c:228]       CHTTP2:CLI:ipv4:172.20.0.4:8042: got setting MAX_CONCURRENT_STREAMS = 2147483647
D0824 13:18:53.953772834     193 frame_settings.c:222]       adding 983041 for initial_window change
D0824 13:18:53.954024050     193 frame_settings.c:228]       CHTTP2:CLI:ipv4:172.20.0.4:8042: got setting INITIAL_WINDOW_SIZE = 1048576
D0824 13:18:53.954687502     193 chttp2_transport.c:814]     W:0x7fc8640028b0 CLIENT state IDLE -> WRITING [send_ping]
D0824 13:18:53.954902359     193 chttp2_transport.c:814]     W:0x7fc8640028b0 CLIENT state WRITING -> WRITING [begin writing]
D0824 13:18:53.955506877     193 chttp2_transport.c:814]     W:0x7fc8640028b0 CLIENT state WRITING -> IDLE [finish writing]
I0824 13:18:53.965217020     187 parsing.c:499]              HTTP:1:HDR:CLI: :status: 32 30 30 '200'
I0824 13:18:53.965731939     187 parsing.c:499]              HTTP:1:HDR:CLI: content-type: 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc'
I0824 13:18:53.966201009     187 parsing.c:499]              HTTP:1:HDR:CLI: grpc-encoding: 69 64 65 6e 74 69 74 79 'identity'
I0824 13:18:53.966270531     187 parsing.c:499]              HTTP:1:HDR:CLI: grpc-accept-encoding: 67 7a 69 70 'gzip'
I0824 13:18:53.966702144     187 parsing.c:579]              HTTP:1:TRL:CLI: grpc-status: 30 '0'
D0824 13:18:53.967037565     187 chttp2_transport.c:1109]    complete_closure_step: 0x7fc8680045e0 refs=0 flags=0x0003 desc=recv_trailing_metadata_finished err="No Error"
=> #<Google::Cloud::Pubsub::Topic:0x000000046796d0
 @async_opts={},
 @exists=nil,
 @grpc=<Google::Pubsub::V1::Topic: name: "projects/test/topics/test-topic">,
 @lazy=nil,
 @service=Google::Cloud::Pubsub::Service(test)>

[3] pry(main)> sub = topic.subscription('test-topic-sub') || topic.subscribe('test-topic-sub')
D0824 13:19:09.954197857     187 rb_channel.c:706]           GRPC_RUBY: wait for channel polling thread to start
D, [2017-08-24T13:19:09.955983 #187] DEBUG -- : calling pubsub:8042:443:/google.pubsub.v1.Subscriber/GetSubscription
D0824 13:19:09.959683767     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state IDLE -> WRITING [initial_write]
D0824 13:19:09.965828133     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING -> WRITING+MORE [push_setting]
D0824 13:19:09.965924424     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING+MORE -> WRITING [begin writing]
D0824 13:19:09.966565900     193 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc864010280]: [COVERED] SEND_INITIAL_METADATA{key=3a 73 63 68 65 6d 65 ':scheme' value=68 74 74 70 'http', key=3a 6d 65 74 68 6f 64 ':method' value=50 4f 53 54 'POST', key=3a 70 61 74 68 ':path' value=2f 67 6f 6f 67 6c 65 2e 70 75 62 73 75 62 2e 76 31 2e 53 75 62 73 63 72 69 62 65 72 2f 47 65 74 53 75 62 73 63 72 69 70 74 69 6f 6e '/google.pubsub.v1.Subscriber/GetSubscription', key=3a 61 75 74 68 6f 72 69 74 79 ':authority' value=70 75 62 73 75 62 3a 38 30 34 32 'pubsub:8042', key=78 2d 67 6f 6f 67 2d 61 70 69 2d 63 6c 69 65 6e 74 'x-goog-api-client' value=67 6c 2d 72 75 62 79 2f 32 2e 33 2e 33 20 67 63 63 6c 2f 30 2e 32 37 2e 30 20 67 61 70 69 63 2f 30 2e 36 2e 38 20 67 61 78 2f 30 2e 38 2e 36 20 67 72 70 63 2f 31 2e 34 2e 35 'gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5', key=67 6f 6f 67 6c 65 2d 63 6c 6f 75 64 2d 72 65 73 6f 75 72 63 65 2d 70 72 65 66 69 78 'google-cloud-resource-prefix' value=70 72 6f 6a 65 63 74 73 2f 74 65 73 74 'projects/test', key=74 65 'te' value=74 72 61 69 6c 65 72 73 'trailers', key=63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type' value=61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc', key=75 73 65 72 2d 61 67 65 6e 74 'user-agent' value=67 72 70 63 2d 63 2f 34 2e 30 2e 30 20 28 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 3b 20 67 72 65 67 61 72 69 6f 75 73 29 'grpc-c/4.0.0 (linux; chttp2; gregarious)', key=67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding' value=69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip' deadline=279024.482840721} SEND_MESSAGE:flags=0x00000000:len=44 SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_MESSAGE RECV_TRAILING_METADATA
D0824 13:19:09.966659395     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING -> IDLE [finish writing]
D0824 13:19:09.966721724     193 chttp2_transport.c:1254]    perform_stream_op_locked: [COVERED] SEND_INITIAL_METADATA{key=3a 73 63 68 65 6d 65 ':scheme' value=68 74 74 70 'http', key=3a 6d 65 74 68 6f 64 ':method' value=50 4f 53 54 'POST', key=3a 70 61 74 68 ':path' value=2f 67 6f 6f 67 6c 65 2e 70 75 62 73 75 62 2e 76 31 2e 53 75 62 73 63 72 69 62 65 72 2f 47 65 74 53 75 62 73 63 72 69 70 74 69 6f 6e '/google.pubsub.v1.Subscriber/GetSubscription', key=3a 61 75 74 68 6f 72 69 74 79 ':authority' value=70 75 62 73 75 62 3a 38 30 34 32 'pubsub:8042', key=78 2d 67 6f 6f 67 2d 61 70 69 2d 63 6c 69 65 6e 74 'x-goog-api-client' value=67 6c 2d 72 75 62 79 2f 32 2e 33 2e 33 20 67 63 63 6c 2f 30 2e 32 37 2e 30 20 67 61 70 69 63 2f 30 2e 36 2e 38 20 67 61 78 2f 30 2e 38 2e 36 20 67 72 70 63 2f 31 2e 34 2e 35 'gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5', key=67 6f 6f 67 6c 65 2d 63 6c 6f 75 64 2d 72 65 73 6f 75 72 63 65 2d 70 72 65 66 69 78 'google-cloud-resource-prefix' value=70 72 6f 6a 65 63 74 73 2f 74 65 73 74 'projects/test', key=74 65 'te' value=74 72 61 69 6c 65 72 73 'trailers', key=63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type' value=61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc', key=75 73 65 72 2d 61 67 65 6e 74 'user-agent' value=67 72 70 63 2d 63 2f 34 2e 30 2e 30 20 28 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 3b 20 67 72 65 67 61 72 69 6f 75 73 29 'grpc-c/4.0.0 (linux; chttp2; gregarious)', key=67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding' value=69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip' deadline=279024.482840721} SEND_MESSAGE:flags=0x00000000:len=44 SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_MESSAGE RECV_TRAILING_METADATA; on_complete = 0x7fc86400ffe0
I0824 13:19:09.966752989     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :scheme: http
I0824 13:19:09.966778660     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :method: POST
I0824 13:19:09.966789848     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :path: /google.pubsub.v1.Subscriber/GetSubscription
I0824 13:19:09.966893730     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :authority: pubsub:8042
I0824 13:19:09.966904219     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: x-goog-api-client: gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5
I0824 13:19:09.966915406     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: google-cloud-resource-prefix: projects/test
I0824 13:19:09.966926593     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: te: trailers
I0824 13:19:09.966935883     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: content-type: application/grpc
I0824 13:19:09.966942276     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: user-agent: grpc-c/4.0.0 (linux; chttp2; gregarious)
D0824 13:19:09.966952564     193 chttp2_transport.c:1043]    HTTP:CLI: Allocating new grpc_chttp2_stream 0x7fc864010280 to id 1
D0824 13:19:09.966963152     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state IDLE -> WRITING [new_stream]
D0824 13:19:09.966975938     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING -> WRITING+MORE+COVERED [op.send_message]
D0824 13:19:09.966989023     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc86400ffe0 refs=4 flags=0x0003 desc=op->on_complete err="No Error"
D0824 13:19:09.967015293     193 writing.c:235]              W:0x7fc86400b740 CLIENT[1] im-(sent,send)=(0,1) announce=5
D0824 13:19:09.967044860     193 hpack_encoder.c:432]        Encode: ':path: /google.pubsub.v1.Subscriber/GetSubscription', elem_interned=0 [2], k_interned=1, v_interned=0
D0824 13:19:09.967072229     193 hpack_encoder.c:432]        Encode: 'x-goog-api-client: gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5', elem_interned=0 [0], k_interned=0, v_interned=0
D0824 13:19:09.967125968     193 hpack_encoder.c:432]        Encode: 'google-cloud-resource-prefix: projects/test', elem_interned=0 [0], k_interned=0, v_interned=0
D0824 13:19:09.967167322     193 hpack_encoder.c:432]        Encode: 'grpc-timeout: 60S', elem_interned=0 [2], k_interned=1, v_interned=0
D0824 13:19:09.967179608     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING+MORE+COVERED -> WRITING [begin writing]
D0824 13:19:09.967352712     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING -> IDLE [finish writing]
D0824 13:19:09.967385775     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc86400ffe0 refs=3 flags=0x0003 desc=send_initial_metadata_finished err="No Error"
D0824 13:19:09.967396963     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc86400ffe0 refs=2 flags=0x0003 desc=finish_write_cb err="No Error"
D0824 13:19:09.967407750     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc86400ffe0 refs=1 flags=0x0003 desc=send_trailing_metadata_finished err="No Error"
D0824 13:19:09.973506169     193 frame_settings.c:228]       CHTTP2:CLI:ipv4:172.20.0.4:8042: got setting MAX_CONCURRENT_STREAMS = 2147483647
D0824 13:19:09.973562305     193 frame_settings.c:222]       adding 983041 for initial_window change
D0824 13:19:09.974047058     193 frame_settings.c:228]       CHTTP2:CLI:ipv4:172.20.0.4:8042: got setting INITIAL_WINDOW_SIZE = 1048576
D0824 13:19:09.974106891     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state IDLE -> WRITING [send_ping]
D0824 13:19:09.974174315     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING -> WRITING [begin writing]
D0824 13:19:09.974307864     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING -> IDLE [finish writing]
I0824 13:19:09.982219036     187 parsing.c:499]              HTTP:1:HDR:CLI: :status: 32 30 30 '200'
I0824 13:19:09.982312831     187 parsing.c:499]              HTTP:1:HDR:CLI: content-type: 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc'
I0824 13:19:09.982345793     187 parsing.c:499]              HTTP:1:HDR:CLI: grpc-encoding: 69 64 65 6e 74 69 74 79 'identity'
I0824 13:19:09.982848526     187 parsing.c:499]              HTTP:1:HDR:CLI: grpc-accept-encoding: 67 7a 69 70 'gzip'
I0824 13:19:09.985315442     187 parsing.c:579]              HTTP:1:TRL:CLI: grpc-status: 30 '0'
D0824 13:19:09.986112842     187 chttp2_transport.c:1109]    complete_closure_step: 0x7fc86400ffe0 refs=0 flags=0x0003 desc=recv_trailing_metadata_finished err="No Error"
=> #<Google::Cloud::Pubsub::Subscription:0x000000045ffb50
 @exists=nil,
 @grpc=
  <Google::Pubsub::V1::Subscription: name: "projects/test/subscriptions/test-topic-sub", topic: "projects/test/topics/test-topic", push_config: <Google::Pubsub::V1::PushConfig: push_endpoint: "", attributes: {}>, ack_deadline_seconds: 10, retain_acked_messages: false, message_retention_duration: nil>,
 @lazy=nil,
 @service=Google::Cloud::Pubsub::Service(test)>

[4] pry(main)> listener = sub.listen { |message| puts message }
=> #<Google::Cloud::Pubsub::Subscriber (subscription: projects/test/subscriptions/test-topic-sub, streams: 4)>

[5] pry(main)> listener.start
D, [2017-08-24T13:19:22.080143 #187] DEBUG -- : calling pubsub:8042:443:/google.pubsub.v1.Subscriber/StreamingPull
D0824 13:19:22.080407763     200 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc85c0051e8]: [COVERED] SEND_INITIAL_METADATA{key=3a 73 63 68 65 6d 65 ':scheme' value=68 74 74 70 'http', key=3a 6d 65 74 68 6f 64 ':method' value=50 4f 53 54 'POST', key=3a 70 61 74 68 ':path' value=2f 67 6f 6f 67 6c 65 2e 70 75 62 73 75 62 2e 76 31 2e 53 75 62 73 63 72 69 62 65 72 2f 53 74 72 65 61 6d 69 6e 67 50 75 6c 6c '/google.pubsub.v1.Subscriber/StreamingPull', key=3a 61 75 74 68 6f 72 69 74 79 ':authority' value=70 75 62 73 75 62 3a 38 30 34 32 'pubsub:8042', key=78 2d 67 6f 6f 67 2d 61 70 69 2d 63 6c 69 65 6e 74 'x-goog-api-client' value=67 6c 2d 72 75 62 79 2f 32 2e 33 2e 33 20 67 63 63 6c 2f 30 2e 32 37 2e 30 20 67 61 70 69 63 2f 30 2e 36 2e 38 20 67 61 78 2f 30 2e 38 2e 36 20 67 72 70 63 2f 31 2e 34 2e 35 'gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5', key=67 6f 6f 67 6c 65 2d 63 6c 6f 75 64 2d 72 65 73 6f 75 72 63 65 2d 70 72 65 66 69 78 'google-cloud-resource-prefix' value=70 72 6f 6a 65 63 74 73 2f 74 65 73 74 'projects/test', key=74 65 'te' value=74 72 61 69 6c 65 72 73 'trailers', key=63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type' value=61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc', key=75 73 65 72 2d 61 67 65 6e 74 'user-agent' value=67 72 70 63 2d 63 2f 34 2e 30 2e 30 20 28 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 3b 20 67 72 65 67 61 72 69 6f 75 73 29 'grpc-c/4.0.0 (linux; chttp2; gregarious)', key=67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding' value=69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip' deadline=279576.607016321}
D0824 13:19:22.080504753     193 chttp2_transport.c:1254]    perform_stream_op_locked: [COVERED] SEND_INITIAL_METADATA{key=3a 73 63 68 65 6d 65 ':scheme' value=68 74 74 70 'http', key=3a 6d 65 74 68 6f 64 ':method' value=50 4f 53 54 'POST', key=3a 70 61 74 68 ':path' value=2f 67 6f 6f 67 6c 65 2e 70 75 62 73 75 62 2e 76 31 2e 53 75 62 73 63 72 69 62 65 72 2f 53 74 72 65 61 6d 69 6e 67 50 75 6c 6c '/google.pubsub.v1.Subscriber/StreamingPull', key=3a 61 75 74 68 6f 72 69 74 79 ':authority' value=70 75 62 73 75 62 3a 38 30 34 32 'pubsub:8042', key=78 2d 67 6f 6f 67 2d 61 70 69 2d 63 6c 69 65 6e 74 'x-goog-api-client' value=67 6c 2d 72 75 62 79 2f 32 2e 33 2e 33 20 67 63 63 6c 2f 30 2e 32 37 2e 30 20 67 61 70 69 63 2f 30 2e 36 2e 38 20 67 61 78 2f 30 2e 38 2e 36 20 67 72 70 63 2f 31 2e 34 2e 35 'gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5', key=67 6f 6f 67 6c 65 2d 63 6c 6f 75 64 2d 72 65 73 6f 75 72 63 65 2d 70 72 65 66 69 78 'google-cloud-resource-prefix' value=70 72 6f 6a 65 63 74 73 2f 74 65 73 74 'projects/test', key=74 65 'te' value=74 72 61 69 6c 65 72 73 'trailers', key=63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type' value=61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc', key=75 73 65 72 2d 61 67 65 6e 74 'user-agent' value=67 72 70 63 2d 63 2f 34 2e 30 2e 30 20 28 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 3b 20 67 72 65 67 61 72 69 6f 75 73 29 'grpc-c/4.0.0 (linux; chttp2; gregarious)', key=67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding' value=69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip' deadline=279576.607016321}; on_complete = 0x7fc85c004b90
I0824 13:19:22.080535519     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :scheme: http
I0824 13:19:22.080554797     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :method: POST
I0824 13:19:22.080562089     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :path: /google.pubsub.v1.Subscriber/StreamingPull
I0824 13:19:22.080576572     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :authority: pubsub:8042
I0824 13:19:22.080584164     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: x-goog-api-client: gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5
I0824 13:19:22.080591156     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: google-cloud-resource-prefix: projects/test
I0824 13:19:22.080608636     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: te: trailers
I0824 13:19:22.080616128     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: content-type: application/grpc
I0824 13:19:22.080623020     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: user-agent: grpc-c/4.0.0 (linux; chttp2; gregarious)
D0824 13:19:22.080641898     193 chttp2_transport.c:1043]    HTTP:CLI: Allocating new grpc_chttp2_stream 0x7fc85c0051e8 to id 3
D0824 13:19:22.080650888     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state IDLE -> WRITING [new_stream]
D0824 13:19:22.080670866     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc85c004b90 refs=1 flags=0x0002 desc=op->on_complete err="No Error"
D0824 13:19:22.080683651     193 writing.c:235]              W:0x7fc86400b740 CLIENT[3] im-(sent,send)=(0,1) announce=0
D0824 13:19:22.080704228     193 hpack_encoder.c:432]        Encode: ':path: /google.pubsub.v1.Subscriber/StreamingPull', elem_interned=0 [2], k_interned=1, v_interned=0
D0824 13:19:22.080713318     193 hpack_encoder.c:432]        Encode: 'x-goog-api-client: gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5', elem_interned=0 [0], k_interned=0, v_interned=0
D0824 13:19:22.080721509     193 hpack_encoder.c:432]        Encode: 'google-cloud-resource-prefix: projects/test', elem_interned=0 [0], k_interned=0, v_interned=0
D0824 13:19:22.080745581     193 hpack_encoder.c:432]        Encode: 'grpc-timeout: 600S', elem_interned=0 [2], k_interned=1, v_interned=0
D0824 13:19:22.080763661     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING -> WRITING [begin writing]
D0824 13:19:22.080849065     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING -> IDLE [finish writing]
D0824 13:19:22.080860751     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc85c004b90 refs=0 flags=0x0002 desc=send_initial_metadata_finished err="No Error"
D, [2017-08-24T13:19:22.081340 #187] DEBUG -- : calling pubsub:8042:443:/google.pubsub.v1.Subscriber/StreamingPull
D0824 13:19:22.081519508     201 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc868009798]: [COVERED] SEND_INITIAL_METADATA{key=3a 73 63 68 65 6d 65 ':scheme' value=68 74 74 70 'http', key=3a 6d 65 74 68 6f 64 ':method' value=50 4f 53 54 'POST', key=3a 70 61 74 68 ':path' value=2f 67 6f 6f 67 6c 65 2e 70 75 62 73 75 62 2e 76 31 2e 53 75 62 73 63 72 69 62 65 72 2f 53 74 72 65 61 6d 69 6e 67 50 75 6c 6c '/google.pubsub.v1.Subscriber/StreamingPull', key=3a 61 75 74 68 6f 72 69 74 79 ':authority' value=70 75 62 73 75 62 3a 38 30 34 32 'pubsub:8042', key=78 2d 67 6f 6f 67 2d 61 70 69 2d 63 6c 69 65 6e 74 'x-goog-api-client' value=67 6c 2d 72 75 62 79 2f 32 2e 33 2e 33 20 67 63 63 6c 2f 30 2e 32 37 2e 30 20 67 61 70 69 63 2f 30 2e 36 2e 38 20 67 61 78 2f 30 2e 38 2e 36 20 67 72 70 63 2f 31 2e 34 2e 35 'gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5', key=67 6f 6f 67 6c 65 2d 63 6c 6f 75 64 2d 72 65 73 6f 75 72 63 65 2d 70 72 65 66 69 78 'google-cloud-resource-prefix' value=70 72 6f 6a 65 63 74 73 2f 74 65 73 74 'projects/test', key=74 65 'te' value=74 72 61 69 6c 65 72 73 'trailers', key=63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type' value=61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc', key=75 73 65 72 2d 61 67 65 6e 74 'user-agent' value=67 72 70 63 2d 63 2f 34 2e 30 2e 30 20 28 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 3b 20 67 72 65 67 61 72 69 6f 75 73 29 'grpc-c/4.0.0 (linux; chttp2; gregarious)', key=67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding' value=69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip' deadline=279576.608219164}
D0824 13:19:22.081593824     193 chttp2_transport.c:1254]    perform_stream_op_locked: [COVERED] SEND_INITIAL_METADATA{key=3a 73 63 68 65 6d 65 ':scheme' value=68 74 74 70 'http', key=3a 6d 65 74 68 6f 64 ':method' value=50 4f 53 54 'POST', key=3a 70 61 74 68 ':path' value=2f 67 6f 6f 67 6c 65 2e 70 75 62 73 75 62 2e 76 31 2e 53 75 62 73 63 72 69 62 65 72 2f 53 74 72 65 61 6d 69 6e 67 50 75 6c 6c '/google.pubsub.v1.Subscriber/StreamingPull', key=3a 61 75 74 68 6f 72 69 74 79 ':authority' value=70 75 62 73 75 62 3a 38 30 34 32 'pubsub:8042', key=78 2d 67 6f 6f 67 2d 61 70 69 2d 63 6c 69 65 6e 74 'x-goog-api-client' value=67 6c 2d 72 75 62 79 2f 32 2e 33 2e 33 20 67 63 63 6c 2f 30 2e 32 37 2e 30 20 67 61 70 69 63 2f 30 2e 36 2e 38 20 67 61 78 2f 30 2e 38 2e 36 20 67 72 70 63 2f 31 2e 34 2e 35 'gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5', key=67 6f 6f 67 6c 65 2d 63 6c 6f 75 64 2d 72 65 73 6f 75 72 63 65 2d 70 72 65 66 69 78 'google-cloud-resource-prefix' value=70 72 6f 6a 65 63 74 73 2f 74 65 73 74 'projects/test', key=74 65 'te' value=74 72 61 69 6c 65 72 73 'trailers', key=63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type' value=61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc', key=75 73 65 72 2d 61 67 65 6e 74 'user-agent' value=67 72 70 63 2d 63 2f 34 2e 30 2e 30 20 28 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 3b 20 67 72 65 67 61 72 69 6f 75 73 29 'grpc-c/4.0.0 (linux; chttp2; gregarious)', key=67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding' value=69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip' deadline=279576.608219164}; on_complete = 0x7fc868009140
I0824 13:19:22.081622692     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :scheme: http
I0824 13:19:22.081641371     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :method: POST
I0824 13:19:22.081648662     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :path: /google.pubsub.v1.Subscriber/StreamingPull
I0824 13:19:22.081667341     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :authority: pubsub:8042
I0824 13:19:22.081685721     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: x-goog-api-client: gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5
I0824 13:19:22.081693612     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: google-cloud-resource-prefix: projects/test
I0824 13:19:22.081711891     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: te: trailers
I0824 13:19:22.081730071     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: content-type: application/grpc
I0824 13:19:22.081737063     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: user-agent: grpc-c/4.0.0 (linux; chttp2; gregarious)
D0824 13:19:22.081755442     193 chttp2_transport.c:1043]    HTTP:CLI: Allocating new grpc_chttp2_stream 0x7fc868009798 to id 5
D0824 13:19:22.081774121     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state IDLE -> WRITING [new_stream]
D0824 13:19:22.081793199     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc868009140 refs=1 flags=0x0002 desc=op->on_complete err="No Error"
D0824 13:19:22.081817072     193 writing.c:235]              W:0x7fc86400b740 CLIENT[5] im-(sent,send)=(0,1) announce=0
D0824 13:19:22.081836351     193 hpack_encoder.c:432]        Encode: ':path: /google.pubsub.v1.Subscriber/StreamingPull', elem_interned=0 [2], k_interned=1, v_interned=0
D0824 13:19:22.081857127     193 hpack_encoder.c:432]        Encode: 'x-goog-api-client: gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5', elem_interned=0 [0], k_interned=0, v_interned=0
D0824 13:19:22.081876705     193 hpack_encoder.c:432]        Encode: 'google-cloud-resource-prefix: projects/test', elem_interned=0 [0], k_interned=0, v_interned=0
D0824 13:19:22.081900278     193 hpack_encoder.c:432]        Encode: 'grpc-timeout: 600S', elem_interned=0 [2], k_interned=1, v_interned=0
D0824 13:19:22.081919756     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING -> WRITING [begin writing]
D0824 13:19:22.081994472     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING -> IDLE [finish writing]
D0824 13:19:22.082018046     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc868009140 refs=0 flags=0x0002 desc=send_initial_metadata_finished err="No Error"
D, [2017-08-24T13:19:22.083449 #187] DEBUG -- : calling pubsub:8042:443:/google.pubsub.v1.Subscriber/StreamingPull
D0824 13:19:22.084228451     202 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc860002ca8]: [COVERED] SEND_INITIAL_METADATA{key=3a 73 63 68 65 6d 65 ':scheme' value=68 74 74 70 'http', key=3a 6d 65 74 68 6f 64 ':method' value=50 4f 53 54 'POST', key=3a 70 61 74 68 ':path' value=2f 67 6f 6f 67 6c 65 2e 70 75 62 73 75 62 2e 76 31 2e 53 75 62 73 63 72 69 62 65 72 2f 53 74 72 65 61 6d 69 6e 67 50 75 6c 6c '/google.pubsub.v1.Subscriber/StreamingPull', key=3a 61 75 74 68 6f 72 69 74 79 ':authority' value=70 75 62 73 75 62 3a 38 30 34 32 'pubsub:8042', key=78 2d 67 6f 6f 67 2d 61 70 69 2d 63 6c 69 65 6e 74 'x-goog-api-client' value=67 6c 2d 72 75 62 79 2f 32 2e 33 2e 33 20 67 63 63 6c 2f 30 2e 32 37 2e 30 20 67 61 70 69 63 2f 30 2e 36 2e 38 20 67 61 78 2f 30 2e 38 2e 36 20 67 72 70 63 2f 31 2e 34 2e 35 'gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5', key=67 6f 6f 67 6c 65 2d 63 6c 6f 75 64 2d 72 65 73 6f 75 72 63 65 2d 70 72 65 66 69 78 'google-cloud-resource-prefix' value=70 72 6f 6a 65 63 74 73 2f 74 65 73 74 'projects/test', key=74 65 'te' value=74 72 61 69 6c 65 72 73 'trailers', key=63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type' value=61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc', key=75 73 65 72 2d 61 67 65 6e 74 'user-agent' value=67 72 70 63 2d 63 2f 34 2e 30 2e 30 20 28 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 3b 20 67 72 65 67 61 72 69 6f 75 73 29 'grpc-c/4.0.0 (linux; chttp2; gregarious)', key=67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding' value=69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip' deadline=279576.610321791}
D0824 13:19:22.084749263     193 chttp2_transport.c:1254]    perform_stream_op_locked: [COVERED] SEND_INITIAL_METADATA{key=3a 73 63 68 65 6d 65 ':scheme' value=68 74 74 70 'http', key=3a 6d 65 74 68 6f 64 ':method' value=50 4f 53 54 'POST', key=3a 70 61 74 68 ':path' value=2f 67 6f 6f 67 6c 65 2e 70 75 62 73 75 62 2e 76 31 2e 53 75 62 73 63 72 69 62 65 72 2f 53 74 72 65 61 6d 69 6e 67 50 75 6c 6c '/google.pubsub.v1.Subscriber/StreamingPull', key=3a 61 75 74 68 6f 72 69 74 79 ':authority' value=70 75 62 73 75 62 3a 38 30 34 32 'pubsub:8042', key=78 2d 67 6f 6f 67 2d 61 70 69 2d 63 6c 69 65 6e 74 'x-goog-api-client' value=67 6c 2d 72 75 62 79 2f 32 2e 33 2e 33 20 67 63 63 6c 2f 30 2e 32 37 2e 30 20 67 61 70 69 63 2f 30 2e 36 2e 38 20 67 61 78 2f 30 2e 38 2e 36 20 67 72 70 63 2f 31 2e 34 2e 35 'gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5', key=67 6f 6f 67 6c 65 2d 63 6c 6f 75 64 2d 72 65 73 6f 75 72 63 65 2d 70 72 65 66 69 78 'google-cloud-resource-prefix' value=70 72 6f 6a 65 63 74 73 2f 74 65 73 74 'projects/test', key=74 65 'te' value=74 72 61 69 6c 65 72 73 'trailers', key=63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type' value=61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc', key=75 73 65 72 2d 61 67 65 6e 74 'user-agent' value=67 72 70 63 2d 63 2f 34 2e 30 2e 30 20 28 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 3b 20 67 72 65 67 61 72 69 6f 75 73 29 'grpc-c/4.0.0 (linux; chttp2; gregarious)', key=67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding' value=69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip' deadline=279576.610321791}; on_complete = 0x7fc860002650
I0824 13:19:22.084781627     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :scheme: http
I0824 13:19:22.085046428     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :method: POST
I0824 13:19:22.085073897     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :path: /google.pubsub.v1.Subscriber/StreamingPull
I0824 13:19:22.085096671     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :authority: pubsub:8042
I0824 13:19:22.085107459     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: x-goog-api-client: gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5
I0824 13:19:22.085130034     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: google-cloud-resource-prefix: projects/test
I0824 13:19:22.085152608     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: te: trailers
I0824 13:19:22.085173784     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: content-type: application/grpc
I0824 13:19:22.085183973     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: user-agent: grpc-c/4.0.0 (linux; chttp2; gregarious)
D0824 13:19:22.085209145     193 chttp2_transport.c:1043]    HTTP:CLI: Allocating new grpc_chttp2_stream 0x7fc860002ca8 to id 7
D0824 13:19:22.085483435     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state IDLE -> WRITING [new_stream]
D0824 13:19:22.085517197     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc860002650 refs=1 flags=0x0002 desc=op->on_complete err="No Error"
D0824 13:19:22.085548961     193 writing.c:235]              W:0x7fc86400b740 CLIENT[7] im-(sent,send)=(0,1) announce=0
D0824 13:19:22.085577129     193 hpack_encoder.c:432]        Encode: ':path: /google.pubsub.v1.Subscriber/StreamingPull', elem_interned=0 [2], k_interned=1, v_interned=0
D0824 13:19:22.085605897     193 hpack_encoder.c:432]        Encode: 'x-goog-api-client: gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5', elem_interned=0 [0], k_interned=0, v_interned=0
D0824 13:19:22.085631568     193 hpack_encoder.c:432]        Encode: 'google-cloud-resource-prefix: projects/test', elem_interned=0 [0], k_interned=0, v_interned=0
D0824 13:19:22.085844627     193 hpack_encoder.c:432]        Encode: 'grpc-timeout: 600S', elem_interned=0 [2], k_interned=1, v_interned=0
D0824 13:19:22.085875792     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING -> WRITING [begin writing]
D0824 13:19:22.085966889     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING -> IDLE [finish writing]
D0824 13:19:22.086228694     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc860002650 refs=0 flags=0x0002 desc=send_initial_metadata_finished err="No Error"
I0824 13:19:22.086290724     193 parsing.c:499]              HTTP:3:HDR:CLI: :status: 32 30 30 '200'
I0824 13:19:22.086321489     193 parsing.c:499]              HTTP:3:HDR:CLI: content-type: 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc'
I0824 13:19:22.086350556     193 parsing.c:499]              HTTP:3:HDR:CLI: grpc-status: 31 32 '12'
I0824 13:19:22.086388813     193 parsing.c:499]              HTTP:3:HDR:CLI: grpc-message: 4d 65 74 68 6f 64 20 6e 6f 74 20 66 6f 75 6e 64 3a 20 67 6f 6f 67 6c 65 2e 70 75 62 73 75 62 2e 76 31 2e 53 75 62 73 63 72 69 62 65 72 2f 53 74 72 65 61 6d 69 6e 67 50 75 6c 6c 'Method not found: google.pubsub.v1.Subscriber/StreamingPull'
D0824 13:19:22.086595880     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state IDLE -> WRITING [push_setting]
D0824 13:19:22.086821125     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING -> WRITING+MORE [push_setting]
D0824 13:19:22.086897040     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING+MORE -> WRITING [begin writing]
D0824 13:19:22.087142163     193 chttp2_transport.c:2339]    ipv4:172.20.0.4:8042: Start BDP ping
D0824 13:19:22.087192107     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING -> IDLE [finish writing]
D, [2017-08-24T13:19:22.088161 #187] DEBUG -- : bidi-read-loop: starting
D, [2017-08-24T13:19:22.088833 #187] DEBUG -- : bidi-read-loop: 0
D0824 13:19:22.088974296     206 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc868009798]: [COVERED] RECV_INITIAL_METADATA RECV_MESSAGE
D0824 13:19:22.089054106     193 chttp2_transport.c:1254]    perform_stream_op_locked: [COVERED] RECV_INITIAL_METADATA RECV_MESSAGE; on_complete = 0x7fc868009eb0
D0824 13:19:22.089090265     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc868009eb0 refs=0 flags=0x0000 desc=op->on_complete err="No Error"
D, [2017-08-24T13:19:22.089353 #187] DEBUG -- : bidi-write-loop: starting
I0824 13:19:22.095298559     206 parsing.c:499]              HTTP:5:HDR:CLI: :status: 32 30 30 '200'
I0824 13:19:22.095354496     206 parsing.c:499]              HTTP:5:HDR:CLI: content-type: 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc'
I0824 13:19:22.095383763     206 parsing.c:499]              HTTP:5:HDR:CLI: grpc-status: 31 32 '12'
I0824 13:19:22.095799394     206 parsing.c:499]              HTTP:5:HDR:CLI: grpc-message: 4d 65 74 68 6f 64 20 6e 6f 74 20 66 6f 75 6e 64 3a 20 67 6f 6f 67 6c 65 2e 70 75 62 73 75 62 2e 76 31 2e 53 75 62 73 63 72 69 62 65 72 2f 53 74 72 65 61 6d 69 6e 67 50 75 6c 6c 'Method not found: google.pubsub.v1.Subscriber/StreamingPull'
I0824 13:19:22.096110842     206 parsing.c:499]              HTTP:7:HDR:CLI: :status: 32 30 30 '200'
I0824 13:19:22.096160486     206 parsing.c:499]              HTTP:7:HDR:CLI: content-type: 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc'
I0824 13:19:22.096187056     206 parsing.c:499]              HTTP:7:HDR:CLI: grpc-status: 31 32 '12'
I0824 13:19:22.096314513     206 parsing.c:499]              HTTP:7:HDR:CLI: grpc-message: 4d 65 74 68 6f 64 20 6e 6f 74 20 66 6f 75 6e 64 3a 20 67 6f 6f 67 6c 65 2e 70 75 62 73 75 62 2e 76 31 2e 53 75 62 73 63 72 69 62 65 72 2f 53 74 72 65 61 6d 69 6e 67 50 75 6c 6c 'Method not found: google.pubsub.v1.Subscriber/StreamingPull'
D0824 13:19:22.096366054     206 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state IDLE -> WRITING [force_rst_stream]
D0824 13:19:22.096398518     206 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING -> WRITING+MORE [force_rst_stream]
D0824 13:19:22.096579014     206 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING+MORE -> WRITING [begin writing]
D0824 13:19:22.096681099     206 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING -> IDLE [finish writing]
D0824 13:19:22.099263085     193 chttp2_transport.c:2352]    ipv4:172.20.0.4:8042: Complete BDP ping
D, [2017-08-24T13:19:22.103682 #187] DEBUG -- : bidi-write-loop: 0
D0824 13:19:22.104715532     203 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc85c0051e8]: [COVERED] SEND_MESSAGE:flags=0x00000000:len=46
D0824 13:19:22.104945673     203 chttp2_transport.c:1254]    perform_stream_op_locked: [COVERED] SEND_MESSAGE:flags=0x00000000:len=46; on_complete = 0x7fc85c005980
D, [2017-08-24T13:19:22.089718 #187] DEBUG -- : bidi-write-loop: starting
D, [2017-08-24T13:19:22.105150 #187] DEBUG -- : bidi-write-loop: 0
D0824 13:19:22.105398761     203 chttp2_transport.c:1109]    complete_closure_step: 0x7fc85c005980 refs=1 flags=0x0002 desc=fetching_send_message_finished err={"created":"@1503580762.105381681","description":"Attempt to send message after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":1365}
D0824 13:19:22.105352813     207 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc860002ca8]: [COVERED] SEND_MESSAGE:flags=0x00000000:len=46
=> D0824 13:19:22.105632098     203 chttp2_transport.c:1109]    complete_closure_step: 0x7fc85c005980 refs=0 flags=0x0002 desc=op->on_complete err="No Error"
D0824 13:19:22.105750165     203 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc85c0051e8]: [UNCOVERED] CANCEL:{"created":"@1503580762.105466185","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":1119,"referenced_errors":[{"created":"@1503580762.105381681","description":"Attempt to send message after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":1365}],"target_address":"ipv4:172.20.0.4:8042"}
D0824 13:19:22.106088183     207 chttp2_transport.c:1254]    perform_stream_op_locked: [COVERED] SEND_MESSAGE:flags=0x00000000:len=46; on_complete = 0x7fc860003440
D0824 13:19:22.106192466     207 chttp2_transport.c:1109]    complete_closure_step: 0x7fc860003440 refs=1 flags=0x0002 desc=fetching_send_message_finished err={"created":"@1503580762.106176184","description":"Attempt to send message after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":1365}
D0824 13:19:22.106248103     207 chttp2_transport.c:1109]    complete_closure_step: 0x7fc860003440 refs=0 flags=0x0002 desc=op->on_complete err="No Error"
D0824 13:19:22.106537776     207 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc860002ca8]: [UNCOVERED] CANCEL:{"created":"@1503580762.106242310","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":1119,"referenced_errors":[{"created":"@1503580762.106176184","description":"Attempt to send message after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":1365}],"target_address":"ipv4:172.20.0.4:8042"}
D0824 13:19:22.106716574     207 chttp2_transport.c:1254]    perform_stream_op_locked: [UNCOVERED] CANCEL:{"created":"@1503580762.105466185","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":1119,"referenced_errors":[{"created":"@1503580762.105381681","description":"Attempt to send message after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":1365}],"target_address":"ipv4:172.20.0.4:8042"}; on_complete = 0x7fc85c012200
D0824 13:19:22.106801279     207 chttp2_transport.c:1109]    complete_closure_step: 0x7fc85c012200 refs=0 flags=0x0000 desc=op->on_complete err="No Error"
D0824 13:19:22.106862709     207 chttp2_transport.c:1254]    perform_stream_op_locked: [UNCOVERED] CANCEL:{"created":"@1503580762.106242310","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":1119,"referenced_errors":[{"created":"@1503580762.106176184","description":"Attempt to send message after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":1365}],"target_address":"ipv4:172.20.0.4:8042"}; on_complete = 0x7fc8580017a0
D0824 13:19:22.107021930     207 chttp2_transport.c:1109]    complete_closure_step: 0x7fc8580017a0 refs=0 flags=0x0000 desc=op->on_complete err="No Error"
D, [2017-08-24T13:19:22.103578 #187] DEBUG -- : bidi-write-loop: starting
D, [2017-08-24T13:19:22.110521 #187] DEBUG -- : bidi-write-loop: 0
D0824 13:19:22.110975069     205 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc868009798]: [COVERED] SEND_MESSAGE:flags=0x00000000:len=46
D0824 13:19:22.111147474     205 chttp2_transport.c:1254]    perform_stream_op_locked: [COVERED] SEND_MESSAGE:flags=0x00000000:len=46; on_complete = 0x7fc86800a000
D0824 13:19:22.111215697     205 chttp2_transport.c:1109]    complete_closure_step: 0x7fc86800a000 refs=1 flags=0x0002 desc=fetching_send_message_finished err={"created":"@1503580762.111197518","description":"Attempt to send message after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":1365}
D0824 13:19:22.111305396     205 chttp2_transport.c:1109]    complete_closure_step: 0x7fc86800a000 refs=0 flags=0x0002 desc=op->on_complete err="No Error"
D0824 13:19:22.111428357     205 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc868009798]: [UNCOVERED] CANCEL:{"created":"@1503580762.111261945","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":1119,"referenced_errors":[{"created":"@1503580762.111197518","description":"Attempt to send message after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":1365}],"target_address":"ipv4:172.20.0.4:8042"}
D0824 13:19:22.111498678     205 chttp2_transport.c:1254]    perform_stream_op_locked: [UNCOVERED] CANCEL:{"created":"@1503580762.111261945","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":1119,"referenced_errors":[{"created":"@1503580762.111197518","description":"Attempt to send message after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":1365}],"target_address":"ipv4:172.20.0.4:8042"}; on_complete = 0x7fc868015b00
D0824 13:19:22.111549421     205 chttp2_transport.c:1109]    complete_closure_step: 0x7fc868015b00 refs=0 flags=0x0000 desc=op->on_complete err="No Error"
D, [2017-08-24T13:19:22.089570 #187] DEBUG -- : bidi-read-loop: starting
D, [2017-08-24T13:19:22.111835 #187] DEBUG -- : bidi-read-loop: 0
D0824 13:19:22.111943676     204 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc85c0051e8]: [COVERED] RECV_INITIAL_METADATA RECV_MESSAGE
D0824 13:19:22.112016993     204 chttp2_transport.c:1254]    perform_stream_op_locked: [COVERED] RECV_INITIAL_METADATA RECV_MESSAGE; on_complete = 0x7fc85c005a50
D0824 13:19:22.112065438     204 chttp2_transport.c:1109]    complete_closure_step: 0x7fc85c005a50 refs=0 flags=0x0000 desc=op->on_complete err="No Error"
#<Google::Cloud::Pubsub::Subscriber (subscription: projects/test/subscriptions/test-topic-sub, streams: 4)>

[6] pry(main)> D, [2017-08-24T13:19:22.103478 #187] DEBUG -- : bidi-read-loop: starting
D, [2017-08-24T13:19:22.114010 #187] DEBUG -- : bidi-read-loop: 0
D0824 13:19:22.114230096     208 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc860002ca8]: [COVERED] RECV_INITIAL_METADATA RECV_MESSAGE
W, [2017-08-24T13:19:22.111641 #187]  WARN -- : bidi-write-loop: ended with error
D0824 13:19:22.114732129     193 chttp2_transport.c:1254]    perform_stream_op_locked: [COVERED] RECV_INITIAL_METADATA RECV_MESSAGE; on_complete = 0x7fc860003510
D0824 13:19:22.114782073     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc860003510 refs=0 flags=0x0000 desc=op->on_complete err="No Error"
W, [2017-08-24T13:19:22.114701 #187]  WARN -- : call#run_batch failed somehow (GRPC::Core::CallError)
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:152:in `run_batch'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:152:in `block in write_loop'
/usr/local/bundle/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/enumerator_queue.rb:45:in `block in each'
/usr/local/bundle/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/enumerator_queue.rb:42:in `loop'
/usr/local/bundle/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/enumerator_queue.rb:42:in `each'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:145:in `each'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:145:in `write_loop'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:90:in `block in run_on_client'
D, [2017-08-24T13:19:22.112178 #187] DEBUG -- : bidi-read-loop: null batch #<struct Struct::BatchResult send_message=nil, send_metadata=nil, send_close=nil, send_status=nil, message=nil, metadata={}, status=nil, cancelled=nil>
D0824 13:19:22.115473792     204 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc85c0051e8]: [COVERED] RECV_TRAILING_METADATA
D0824 13:19:22.115575877     204 chttp2_transport.c:1254]    perform_stream_op_locked: [COVERED] RECV_TRAILING_METADATA; on_complete = 0x7fc85c004f48
D0824 13:19:22.115639705     204 chttp2_transport.c:1109]    complete_closure_step: 0x7fc85c004f48 refs=1 flags=0x0001 desc=recv_trailing_metadata_finished err="No Error"
D0824 13:19:22.115716918     204 chttp2_transport.c:1109]    complete_closure_step: 0x7fc85c004f48 refs=0 flags=0x0001 desc=op->on_complete err="No Error"
D, [2017-08-24T13:19:22.115832 #187] DEBUG -- : Failing with status #<struct Struct::Status code=12, details="Method not found: google.pubsub.v1.Subscriber/StreamingPull", metadata={}>
W, [2017-08-24T13:19:22.112250 #187]  WARN -- : bidi-write-loop: ended with error
D, [2017-08-24T13:19:22.104476 #187] DEBUG -- : bidi-read-loop: null batch #<struct Struct::BatchResult send_message=nil, send_metadata=nil, send_close=nil, send_status=nil, message=nil, metadata={}, status=nil, cancelled=nil>
D0824 13:19:22.116500933     206 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc868009798]: [COVERED] RECV_TRAILING_METADATA
D0824 13:19:22.116542786     193 chttp2_transport.c:1254]    perform_stream_op_locked: [COVERED] RECV_TRAILING_METADATA; on_complete = 0x7fc8680094f8
D0824 13:19:22.116560466     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc8680094f8 refs=1 flags=0x0001 desc=recv_trailing_metadata_finished err="No Error"
D0824 13:19:22.116571953     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc8680094f8 refs=0 flags=0x0001 desc=op->on_complete err="No Error"
D, [2017-08-24T13:19:22.116661 #187] DEBUG -- : Failing with status #<struct Struct::Status code=12, details="Method not found: google.pubsub.v1.Subscriber/StreamingPull", metadata={}>
D, [2017-08-24T13:19:22.115069 #187] DEBUG -- : bidi-read-loop: null batch #<struct Struct::BatchResult send_message=nil, send_metadata=nil, send_close=nil, send_status=nil, message=nil, metadata={}, status=nil, cancelled=nil>
D0824 13:19:22.117708271     208 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc860002ca8]: [COVERED] RECV_TRAILING_METADATA
D0824 13:19:22.117868190     208 chttp2_transport.c:1254]    perform_stream_op_locked: [COVERED] RECV_TRAILING_METADATA; on_complete = 0x7fc860002a08
D0824 13:19:22.117921730     208 chttp2_transport.c:1109]    complete_closure_step: 0x7fc860002a08 refs=1 flags=0x0001 desc=recv_trailing_metadata_finished err="No Error"
D0824 13:19:22.117934915     208 chttp2_transport.c:1109]    complete_closure_step: 0x7fc860002a08 refs=0 flags=0x0001 desc=op->on_complete err="No Error"
D, [2017-08-24T13:19:22.115271 #187] DEBUG -- : bidi-write-loop: 1 writes done
D, [2017-08-24T13:19:22.118825 #187] DEBUG -- : bidi-write-loop: client sent 1, waiting
D0824 13:19:22.118949070     205 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc868009798]: [COVERED] SEND_TRAILING_METADATA{}
D0824 13:19:22.119092609     205 chttp2_transport.c:1254]    perform_stream_op_locked: [COVERED] SEND_TRAILING_METADATA{}; on_complete = 0x7fc86800a1a0
W, [2017-08-24T13:19:22.116088 #187]  WARN -- : bidi: read-loop failed
W, [2017-08-24T13:19:22.119189 #187]  WARN -- : 12:Method not found: google.pubsub.v1.Subscriber/StreamingPull (GRPC::Unimplemented)
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/active_call.rb:46:in `check_status'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:198:in `block in read_loop'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:185:in `loop'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:185:in `read_loop'
/usr/local/bundle/bin/hanami:1:in `each'
W, [2017-08-24T13:19:22.117493 #187]  WARN -- : bidi: read-loop failed
D0824 13:19:22.119885514     205 chttp2_transport.c:1109]    complete_closure_step: 0x7fc86800a1a0 refs=1 flags=0x0002 desc=send_trailing_metadata_finished err="No Error"
D0824 13:19:22.120300146     205 chttp2_transport.c:1109]    complete_closure_step: 0x7fc86800a1a0 refs=0 flags=0x0002 desc=op->on_complete err="No Error"
D, [2017-08-24T13:19:22.118539 #187] DEBUG -- : Failing with status #<struct Struct::Status code=12, details="Method not found: google.pubsub.v1.Subscriber/StreamingPull", metadata={}>
W, [2017-08-24T13:19:22.121066 #187]  WARN -- : bidi: read-loop failed
W, [2017-08-24T13:19:22.112226 #187]  WARN -- : bidi-write-loop: ended with error
W, [2017-08-24T13:19:22.121863 #187]  WARN -- : call#run_batch failed somehow (GRPC::Core::CallError)
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:152:in `run_batch'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:152:in `block in write_loop'
/usr/local/bundle/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/enumerator_queue.rb:45:in `block in each'
/usr/local/bundle/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/enumerator_queue.rb:42:in `loop'
/usr/local/bundle/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/enumerator_queue.rb:42:in `each'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:145:in `each'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:145:in `write_loop'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:90:in `block in run_on_client'
W, [2017-08-24T13:19:22.119828 #187]  WARN -- : 12:Method not found: google.pubsub.v1.Subscriber/StreamingPull (GRPC::Unimplemented)
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/active_call.rb:46:in `check_status'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:198:in `block in read_loop'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:185:in `loop'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:185:in `read_loop'
/usr/local/bundle/bin/hanami:1:in `each'
D, [2017-08-24T13:19:22.120764 #187] DEBUG -- : bidi-write-loop: done
W, [2017-08-24T13:19:22.121394 #187]  WARN -- : 12:Method not found: google.pubsub.v1.Subscriber/StreamingPull (GRPC::Unimplemented)
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/active_call.rb:46:in `check_status'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:198:in `block in read_loop'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:185:in `loop'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:185:in `read_loop'
/usr/local/bundle/bin/hanami:1:in `each'
D, [2017-08-24T13:19:22.104320 #187] DEBUG -- : calling pubsub:8042:443:/google.pubsub.v1.Subscriber/StreamingPull
D0824 13:19:22.124317413     209 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc850002ca8]: [COVERED] SEND_INITIAL_METADATA{key=3a 73 63 68 65 6d 65 ':scheme' value=68 74 74 70 'http', key=3a 6d 65 74 68 6f 64 ':method' value=50 4f 53 54 'POST', key=3a 70 61 74 68 ':path' value=2f 67 6f 6f 67 6c 65 2e 70 75 62 73 75 62 2e 76 31 2e 53 75 62 73 63 72 69 62 65 72 2f 53 74 72 65 61 6d 69 6e 67 50 75 6c 6c '/google.pubsub.v1.Subscriber/StreamingPull', key=3a 61 75 74 68 6f 72 69 74 79 ':authority' value=70 75 62 73 75 62 3a 38 30 34 32 'pubsub:8042', key=78 2d 67 6f 6f 67 2d 61 70 69 2d 63 6c 69 65 6e 74 'x-goog-api-client' value=67 6c 2d 72 75 62 79 2f 32 2e 33 2e 33 20 67 63 63 6c 2f 30 2e 32 37 2e 30 20 67 61 70 69 63 2f 30 2e 36 2e 38 20 67 61 78 2f 30 2e 38 2e 36 20 67 72 70 63 2f 31 2e 34 2e 35 'gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5', key=67 6f 6f 67 6c 65 2d 63 6c 6f 75 64 2d 72 65 73 6f 75 72 63 65 2d 70 72 65 66 69 78 'google-cloud-resource-prefix' value=70 72 6f 6a 65 63 74 73 2f 74 65 73 74 'projects/test', key=74 65 'te' value=74 72 61 69 6c 65 72 73 'trailers', key=63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type' value=61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc', key=75 73 65 72 2d 61 67 65 6e 74 'user-agent' value=67 72 70 63 2d 63 2f 34 2e 30 2e 30 20 28 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 3b 20 67 72 65 67 61 72 69 6f 75 73 29 'grpc-c/4.0.0 (linux; chttp2; gregarious)', key=67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding' value=69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip' deadline=279576.631195935}
D0824 13:19:22.124454758     193 chttp2_transport.c:1254]    perform_stream_op_locked: [COVERED] SEND_INITIAL_METADATA{key=3a 73 63 68 65 6d 65 ':scheme' value=68 74 74 70 'http', key=3a 6d 65 74 68 6f 64 ':method' value=50 4f 53 54 'POST', key=3a 70 61 74 68 ':path' value=2f 67 6f 6f 67 6c 65 2e 70 75 62 73 75 62 2e 76 31 2e 53 75 62 73 63 72 69 62 65 72 2f 53 74 72 65 61 6d 69 6e 67 50 75 6c 6c '/google.pubsub.v1.Subscriber/StreamingPull', key=3a 61 75 74 68 6f 72 69 74 79 ':authority' value=70 75 62 73 75 62 3a 38 30 34 32 'pubsub:8042', key=78 2d 67 6f 6f 67 2d 61 70 69 2d 63 6c 69 65 6e 74 'x-goog-api-client' value=67 6c 2d 72 75 62 79 2f 32 2e 33 2e 33 20 67 63 63 6c 2f 30 2e 32 37 2e 30 20 67 61 70 69 63 2f 30 2e 36 2e 38 20 67 61 78 2f 30 2e 38 2e 36 20 67 72 70 63 2f 31 2e 34 2e 35 'gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5', key=67 6f 6f 67 6c 65 2d 63 6c 6f 75 64 2d 72 65 73 6f 75 72 63 65 2d 70 72 65 66 69 78 'google-cloud-resource-prefix' value=70 72 6f 6a 65 63 74 73 2f 74 65 73 74 'projects/test', key=74 65 'te' value=74 72 61 69 6c 65 72 73 'trailers', key=63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type' value=61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc', key=75 73 65 72 2d 61 67 65 6e 74 'user-agent' value=67 72 70 63 2d 63 2f 34 2e 30 2e 30 20 28 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 3b 20 67 72 65 67 61 72 69 6f 75 73 29 'grpc-c/4.0.0 (linux; chttp2; gregarious)', key=67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding' value=69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip' deadline=279576.631195935}; on_complete = 0x7fc850002650
I0824 13:19:22.124491117     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :scheme: http
I0824 13:19:22.124504402     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :method: POST
I0824 13:19:22.124514990     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :path: /google.pubsub.v1.Subscriber/StreamingPull
I0824 13:19:22.124526277     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: :authority: pubsub:8042
I0824 13:19:22.124536765     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: x-goog-api-client: gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5
I0824 13:19:22.124547653     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: google-cloud-resource-prefix: projects/test
I0824 13:19:22.124558241     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: te: trailers
I0824 13:19:22.124568529     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: content-type: application/grpc
I0824 13:19:22.124579017     193 chttp2_transport.c:1236]    HTTP:0:HDR:CLI: user-agent: grpc-c/4.0.0 (linux; chttp2; gregarious)
D0824 13:19:22.124594500     193 chttp2_transport.c:1043]    HTTP:CLI: Allocating new grpc_chttp2_stream 0x7fc850002ca8 to id 9
D0824 13:19:22.124611181     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state IDLE -> WRITING [new_stream]
D0824 13:19:22.124626464     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc850002650 refs=1 flags=0x0002 desc=op->on_complete err="No Error"
D0824 13:19:22.124647840     193 writing.c:235]              W:0x7fc86400b740 CLIENT[9] im-(sent,send)=(0,1) announce=0
D0824 13:19:22.124664521     193 hpack_encoder.c:432]        Encode: ':path: /google.pubsub.v1.Subscriber/StreamingPull', elem_interned=0 [2], k_interned=1, v_interned=0
D0824 13:19:22.124684199     193 hpack_encoder.c:432]        Encode: 'x-goog-api-client: gl-ruby/2.3.3 gccl/0.27.0 gapic/0.6.8 gax/0.8.6 grpc/1.4.5', elem_interned=0 [0], k_interned=0, v_interned=0
D0824 13:19:22.124698782     193 hpack_encoder.c:432]        Encode: 'google-cloud-resource-prefix: projects/test', elem_interned=0 [0], k_interned=0, v_interned=0
D0824 13:19:22.124720358     193 hpack_encoder.c:432]        Encode: 'grpc-timeout: 600S', elem_interned=0 [2], k_interned=1, v_interned=0
D0824 13:19:22.124734842     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING -> WRITING [begin writing]
D0824 13:19:22.124845117     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING -> IDLE [finish writing]
D0824 13:19:22.124866093     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc850002650 refs=0 flags=0x0002 desc=send_initial_metadata_finished err="No Error"
D, [2017-08-24T13:19:22.122353 #187] DEBUG -- : bidi-write-loop: 1 writes done
I0824 13:19:22.129580374     193 parsing.c:499]              HTTP:9:HDR:CLI: :status: 32 30 30 '200'
D, [2017-08-24T13:19:22.129705 #187] DEBUG -- : bidi-write-loop: client sent 1, waiting
I0824 13:19:22.129840380     193 parsing.c:499]              HTTP:9:HDR:CLI: content-type: 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc'
I0824 13:19:22.130186689     193 parsing.c:499]              HTTP:9:HDR:CLI: grpc-status: 31 32 '12'
I0824 13:19:22.130209064     193 parsing.c:499]              HTTP:9:HDR:CLI: grpc-message: 4d 65 74 68 6f 64 20 6e 6f 74 20 66 6f 75 6e 64 3a 20 67 6f 6f 67 6c 65 2e 70 75 62 73 75 62 2e 76 31 2e 53 75 62 73 63 72 69 62 65 72 2f 53 74 72 65 61 6d 69 6e 67 50 75 6c 6c 'Method not found: google.pubsub.v1.Subscriber/StreamingPull'
D0824 13:19:22.130277487     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state IDLE -> WRITING [send_ping]
D0824 13:19:22.130329728     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING -> WRITING+MORE [force_rst_stream]
D0824 13:19:22.130350305     193 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING+MORE -> WRITING [begin writing]
D0824 13:19:22.130043251     203 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc85c0051e8]: [COVERED] SEND_TRAILING_METADATA{}
D0824 13:19:22.131068195     203 chttp2_transport.c:1254]    perform_stream_op_locked: [COVERED] SEND_TRAILING_METADATA{}; on_complete = 0x7fc85c005bf0
D0824 13:19:22.131175673     203 chttp2_transport.c:1109]    complete_closure_step: 0x7fc85c005bf0 refs=1 flags=0x0002 desc=send_trailing_metadata_finished err="No Error"
D0824 13:19:22.131331198     203 chttp2_transport.c:1109]    complete_closure_step: 0x7fc85c005bf0 refs=0 flags=0x0002 desc=op->on_complete err="No Error"
D0824 13:19:22.131403117     203 chttp2_transport.c:814]     W:0x7fc86400b740 CLIENT state WRITING -> IDLE [finish writing]
D, [2017-08-24T13:19:22.122913 #187] DEBUG -- : bidi-write-loop: finished
D, [2017-08-24T13:19:22.125505 #187] DEBUG -- : bidi-read-loop: starting
D, [2017-08-24T13:19:22.131962 #187] DEBUG -- : bidi-read-loop: 0
D0824 13:19:22.132389603     211 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc850002ca8]: [COVERED] RECV_INITIAL_METADATA RECV_MESSAGE
D0824 13:19:22.132721429     193 chttp2_transport.c:1254]    perform_stream_op_locked: [COVERED] RECV_INITIAL_METADATA RECV_MESSAGE; on_complete = 0x7fc850003440
D0824 13:19:22.133094208     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc850003440 refs=0 flags=0x0000 desc=op->on_complete err="No Error"
W, [2017-08-24T13:19:22.116231 #187]  WARN -- : call#run_batch failed somehow (GRPC::Core::CallError)
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:152:in `run_batch'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:152:in `block in write_loop'
/usr/local/bundle/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/enumerator_queue.rb:45:in `block in each'
/usr/local/bundle/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/enumerator_queue.rb:42:in `loop'
/usr/local/bundle/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/enumerator_queue.rb:42:in `each'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:145:in `each'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:145:in `write_loop'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:90:in `block in run_on_client'
D, [2017-08-24T13:19:22.134107 #187] DEBUG -- : bidi-write-loop: 1 writes done
D, [2017-08-24T13:19:22.134252 #187] DEBUG -- : bidi-write-loop: client sent 1, waiting
D0824 13:19:22.134393242     207 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc860002ca8]: [COVERED] SEND_TRAILING_METADATA{}
D0824 13:19:22.135243583     207 chttp2_transport.c:1254]    perform_stream_op_locked: [COVERED] SEND_TRAILING_METADATA{}; on_complete = 0x7fc8600036b0
D0824 13:19:22.135484611     207 chttp2_transport.c:1109]    complete_closure_step: 0x7fc8600036b0 refs=1 flags=0x0002 desc=send_trailing_metadata_finished err="No Error"
D, [2017-08-24T13:19:22.133549 #187] DEBUG -- : bidi-read-loop: null batch #<struct Struct::BatchResult send_message=nil, send_metadata=nil, send_close=nil, send_status=nil, message=nil, metadata={}, status=nil, cancelled=nil>
D0824 13:19:22.135614964     211 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc850002ca8]: [COVERED] RECV_TRAILING_METADATA
D0824 13:19:22.135614964     207 chttp2_transport.c:1109]    complete_closure_step: 0x7fc8600036b0 refs=0 flags=0x0002 desc=op->on_complete err="No Error"
D, [2017-08-24T13:19:22.125633 #187] DEBUG -- : bidi-write-loop: starting
D0824 13:19:22.136292699     211 chttp2_transport.c:1254]    perform_stream_op_locked: [COVERED] RECV_TRAILING_METADATA; on_complete = 0x7fc850002a08
D0824 13:19:22.136335950     211 chttp2_transport.c:1109]    complete_closure_step: 0x7fc850002a08 refs=1 flags=0x0001 desc=recv_trailing_metadata_finished err="No Error"
D0824 13:19:22.136349934     211 chttp2_transport.c:1109]    complete_closure_step: 0x7fc850002a08 refs=0 flags=0x0001 desc=op->on_complete err="No Error"
D, [2017-08-24T13:19:22.131499 #187] DEBUG -- : bidi-write-loop: done
D, [2017-08-24T13:19:22.136616 #187] DEBUG -- : bidi-write-loop: finished
D, [2017-08-24T13:19:22.135758 #187] DEBUG -- : bidi-write-loop: 0
D0824 13:19:22.137368185     210 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc850002ca8]: [COVERED] SEND_MESSAGE:flags=0x00000000:len=46
D0824 13:19:22.137526906     193 chttp2_transport.c:1254]    perform_stream_op_locked: [COVERED] SEND_MESSAGE:flags=0x00000000:len=46; on_complete = 0x7fc8500035e0
D0824 13:19:22.137608614     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc8500035e0 refs=1 flags=0x0002 desc=fetching_send_message_finished err={"created":"@1503580762.137591134","description":"Attempt to send message after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":1365}
D0824 13:19:22.137826268     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc8500035e0 refs=0 flags=0x0002 desc=op->on_complete err="No Error"
D0824 13:19:22.137953225     193 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc850002ca8]: [UNCOVERED] CANCEL:{"created":"@1503580762.137816979","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":1119,"referenced_errors":[{"created":"@1503580762.137591134","description":"Attempt to send message after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":1365}],"target_address":"ipv4:172.20.0.4:8042"}
D0824 13:19:22.137996376     193 chttp2_transport.c:1254]    perform_stream_op_locked: [UNCOVERED] CANCEL:{"created":"@1503580762.137816979","description":"Error in HTTP transport completing operation","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":1119,"referenced_errors":[{"created":"@1503580762.137591134","description":"Attempt to send message after stream was closed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":1365}],"target_address":"ipv4:172.20.0.4:8042"}; on_complete = 0x7fc86400b640
D0824 13:19:22.138132822     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc86400b640 refs=0 flags=0x0000 desc=op->on_complete err="No Error"
D, [2017-08-24T13:19:22.137006 #187] DEBUG -- : Failing with status #<struct Struct::Status code=12, details="Method not found: google.pubsub.v1.Subscriber/StreamingPull", metadata={}>
W, [2017-08-24T13:19:22.138629 #187]  WARN -- : bidi: read-loop failed
W, [2017-08-24T13:19:22.138706 #187]  WARN -- : 12:Method not found: google.pubsub.v1.Subscriber/StreamingPull (GRPC::Unimplemented)
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/active_call.rb:46:in `check_status'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:198:in `block in read_loop'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:185:in `loop'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:185:in `read_loop'
/usr/local/bundle/bin/hanami:1:in `each'
W, [2017-08-24T13:19:22.138221 #187]  WARN -- : bidi-write-loop: ended with error
D, [2017-08-24T13:19:22.138482 #187] DEBUG -- : bidi-write-loop: done
D, [2017-08-24T13:19:22.141326 #187] DEBUG -- : bidi-write-loop: finished
W, [2017-08-24T13:19:22.139047 #187]  WARN -- : call#run_batch failed somehow (GRPC::Core::CallError)
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:152:in `run_batch'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:152:in `block in write_loop'
/usr/local/bundle/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/enumerator_queue.rb:45:in `block in each'
/usr/local/bundle/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/enumerator_queue.rb:42:in `loop'
/usr/local/bundle/gems/google-cloud-pubsub-0.27.0/lib/google/cloud/pubsub/subscriber/enumerator_queue.rb:42:in `each'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:145:in `each'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:145:in `write_loop'
/usr/local/bundle/gems/grpc-1.4.5-x86_64-linux/src/ruby/lib/grpc/generic/bidi_call.rb:90:in `block in run_on_client'
D, [2017-08-24T13:19:22.144222 #187] DEBUG -- : bidi-write-loop: 1 writes done
D, [2017-08-24T13:19:22.144467 #187] DEBUG -- : bidi-write-loop: client sent 1, waiting
D0824 13:19:22.145269569     210 chttp2_transport.c:1497]    perform_stream_op[s=0x7fc850002ca8]: [COVERED] SEND_TRAILING_METADATA{}
D0824 13:19:22.145361965     193 chttp2_transport.c:1254]    perform_stream_op_locked: [COVERED] SEND_TRAILING_METADATA{}; on_complete = 0x7fc8500036b0
D0824 13:19:22.145374650     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc8500036b0 refs=1 flags=0x0002 desc=send_trailing_metadata_finished err="No Error"
D0824 13:19:22.145382741     193 chttp2_transport.c:1109]    complete_closure_step: 0x7fc8500036b0 refs=0 flags=0x0002 desc=op->on_complete err="No Error"
D, [2017-08-24T13:19:22.145430 #187] DEBUG -- : bidi-write-loop: done
D, [2017-08-24T13:19:22.146050 #187] DEBUG -- : bidi-write-loop: finished

tiagopog commented 7 years ago

@blowmage I'm targeting an emulator as well, by the way, in that last test I was running this image: https://hub.docker.com/r/adilsoncarvalho/gcloud-pubsub-emulator/

blowmage commented 7 years ago

@tiagopog Can you update to the latest emulator and verify whether that fixes this for you?

somethingnew2-0 commented 7 years ago

Although this issue is now closed, is there a workaround for this issue besides downgrading to 0.26?

NickTitle commented 7 years ago

@somethingnew2-0 i was able to get around the issue by replacing the pull message logic with a rough rework of the old internal method - snippet looks like this:

note: we're acking after consuming the message, so make sure you handle errors or else messages that crash will never get removed off the queue (they'll replay over and over)

      def consume(&blk)
        # in our case, there will always be one subscription of a known name
        subscription = topics.first.subscriptions.first

        # this is the method that does the autoack, that i got rid of for now
        # pull_messages(subscription, &blk)

        # this method is the workaround
        hack_pull_messages(subscription, &blk)
      end

      def hack_pull_messages(subscription, &blk)
        while true
          sleep 1
          msgs = subscription.pull(max: 10)
          msgs.each do |msg|
            yield msg
            msg.ack!
          end
        end
      end

googleapis / google-cloud-ruby

Google::Cloud::Pubsub::Subscription::Listener.start does not appear to begin processing messages #1672