Datastore: does not work inside Puma webserver

Would be good to receive independent confirmation, but from what I can tell is that Datastore queries hang if run inside Puma webserver. Same query runs fine from rails console process. Worker processes running other queries/inserts also look to be running ok. All environment is the same.

Web process just hangs when calling dataset.run(query)

Actually same Puma server runs fine on localhost. The problem only manifests on Heroku, in web Dyno, and only using v1beta3 API. Weird

@timanovsky

@timanovsky I don't know what this is about. I'll investigate. What size are your dynos? How many threads are you running on each one? How many dynos are you running?

This is scary: grpc/grpc#6278

@timanovsky

@timanovsky Is there anything interesting in the logs before the process hangs? Feel free to email me a private gist if you don't want to share publicly.

@blowmage

@blowmage Unfortunately I can reproduce this as well on 1 standard professional dyno.

Puma config:
threads_count = 5
workers = 2
preload_app!

Heroku logs:

2016-05-12T18:04:40.011516+00:00 heroku[router]: at=error code=H12 desc="Request timeout" method=GET path="/" request_id=ff9a7f0a-2202-49b3-8f56-376be41623f1 fwd="198.169.134.185" dyno=web.1 connect=20ms service=30000ms status=503 bytes=0
2016-05-12T18:08:10.052634+00:00 app[web.1]: D0512 18:08:10.052580224      37 chttp2_transport.c:698]     got goaway [0]: 73 65 73 73 69 6f 6e 5f 74 69 6d 65 64 5f 6f 75 74 'session_timed_out'

@murgatroid99

@murgatroid99 @nicolasnoble Sorry to pull you guys in on this, but do you have any insight on why the GRPC client would hang on Heroku?

I don't recognize this specific problem. It would help to have more information. If you run with the environment variable GRPC_TRACE=all, it will output a bunch of log information that might contain something useful (make sure to remove private information).

The problem could be a bug in the gRPC client, or it could be that the server is not responding properly.

@murgatroid99

@murgatroid99 I added the environment variable GRPC_TRACE=all and the output is captured here.

What I see happening in that log is: grpc connects to the server, completes a TLS handshake, and starts initializing an HTTP2 stream. And then it suddenly stops, and ~20 seconds later, Heroku kills it. Unfortunately, I don't recognize that failure case.

Can you open a bug against grpc (https://github.com/grpc/grpc) including that trace and a description of how you encountered the error?

@murgatroid99

Thanks for your help @murgatroid99!

@blowmage

OK, will do. @blowmage the gcloud-ruby gcloud.gemspec lists "grpc", "~> 0.13.1". It looks like the current version is 0.14.1. Any chance this has already been fixed?

@bmclean

@bmclean We'd like to bump the dependency, but we have an open issue that is blocking us from doing that.

@timanovsky

@timanovsky Are you able to connect to an actual datastore while running Puma locally? If I run Puma localhost and connect to the datastore emulator it is fine but if I run Puma localhost and connect to my actual datastore it hangs with:
D0512 21:17:47.508334000 123145307635712 chttp2_transport.c:698] got goaway [0]: 73 65 73 73 69 6f 6e 5f 74 69 6d 65 64 5f 6f 75 74 'session_timed_out'

@timanovsky

Yes, from local puma with same settings it works. This is Linux VM though.
On 13 May 2016 6:11 am, "Bryce McLean" notifications@github.com wrote:

@timanovsky https://github.com/timanovsky Are you able to connect to an
actual datastore while running Puma locally?

—
You are receiving this because you were mentioned.
Reply to this email directly or view it on GitHub
#691 (comment)

Btw those got goaway log messages are pretty frequent even in normally working processes (local, or non-puma).

@blowmage

@blowmage Unfortunately Puma still hangs. I tried your branch as follows:
gem 'gcloud', :git => 'https://github.com/blowmage/gcloud-ruby.git', :branch => 'grpc-0.15'
I ran bundle install and verified that I was now using grpc (0.15.0 universal-darwin).
I moved the require 'gcloud/datastore' back to the top of the Rails CloudDatastore initializer.
I ran my app with rails s -e production connected to an actual cloud datastore.
It still hangs.

Hello, any updates on this? Unfortunately I have to require "gcloud/datastore" at the top, as I have several functions which do not need dataset object, but work with objects likeGcloud::Datastore::Key. It would be a mess to change all such functions to require "gcloud/datastore"inside.

Update workaround for those with similar problem:

require 'gcloud'
module ::Gcloud
  def self.const_missing(name)
    if name.to_s == 'Datastore'
      require 'gcloud/datastore'
      const_get(name)
    end || super
  end
end

Does the 0.20.0 release using grpc 1.0 change this at all?

@blowmage

@blowmage No, the problem still exists with 0.20.0.

Can you take a look at #875? I think it might help remove the need for const_missing hacks. It should even allow you to create a Google::Cloud::Datastore::Dataset object in an initializer as long as you don't make any API calls with it before Puma forks the sub-processes.

@blowmage

@blowmage Sure, I will give it a try.

@blowmage

@blowmage I tried your branch:
:git => 'https://github.com/blowmage/gcloud-ruby.git', :branch => 'grpc-delay-require'
Using an initializer like this:


require 'google/cloud/datastore'

module CloudDatastore
  def self.dataset
    @dataset ||= Google::Cloud.datastore(ENV['GCLOUD_PROJECT'])
  end
end

and Puma works fine configured with 2 workers.

Great. Thank you!

Does the 0.20.1 release (with PR #875) resolve this issue?

Yes.

@timanovsky

@timanovsky Can you confirm 0.20.1 release (with PR #875) as a fix?

Seems to work, thanks for fixing this!

fix!: handle GCP enum name start with uppercase IPProtocol (#691)

Navigation Menu

Repository navigation

Datastore: does not work inside Puma webserver #691

17 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Datastore: does not work inside Puma webserver #691

Description

Activity

timanovsky commented on May 12, 2016

blowmage commented on May 12, 2016

timanovsky commented on May 12, 2016

blowmage commented on May 12, 2016

bmclean commented on May 12, 2016

blowmage commented on May 12, 2016

murgatroid99 commented on May 12, 2016

bmclean commented on May 12, 2016

murgatroid99 commented on May 12, 2016

blowmage commented on May 12, 2016

bmclean commented on May 13, 2016

blowmage commented on May 13, 2016

bmclean commented on May 13, 2016

timanovsky commented on May 13, 2016

timanovsky commented on May 13, 2016

17 remaining items

bmclean commented on Jun 30, 2016

timanovsky commented on Jul 22, 2016

blowmage commented on Aug 29, 2016

bmclean commented on Aug 30, 2016

blowmage commented on Sep 1, 2016

bmclean commented on Sep 1, 2016

bmclean commented on Sep 1, 2016

blowmage commented on Sep 2, 2016

quartzmo commented on Sep 7, 2016

bmclean commented on Sep 8, 2016

quartzmo commented on Sep 9, 2016

timanovsky commented on Sep 9, 2016

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions