Google-cloud-ruby: Stackdriver Debugger breaks grpc connections when working with Puma's forking/workers

[britg]

Edit Here's a StackOverflow question: https://stackoverflow.com/questions/47558606/google-stackdriver-working-with-pumas-cluster-mode-workers-outside-of-google-cl

I'm attempting to get the stackdriver logging gem working with puma's cluster mode on my own server (e.g. outside of Google Cloud). My set up is a brand new rails 5.1.4 ruby 2.4 app with only the stackdriver gem added. I am able to see all logs in the Stackdriver interface when I run in single-mode, but when I run in cluster-mode I do not see any logs. My application.rb and puma.rb are below. Is there something I need to do with puma's forking callbacks to enable stackdriver on each forked worker process?

application.rb

require_relative 'boot'

require 'rails/all'

Bundler.require(*Rails.groups)

require "google/cloud/logging/rails"

module StackTest
  class Application < Rails::Application
    config.google_cloud.logging.project_id = "valid-project-id"
    config.google_cloud.logging.keyfile = "config/stackdriver.json"
    config.google_cloud.use_logging = true
    config.google_cloud.logging.log_name = 'stackdriver-puma-test'
  end
end

puma.rb

project_dir = File.expand_path(File.expand_path(File.dirname(__FILE__)) + "/../")
threads_count = Integer(ENV['MAX_THREADS'] || 16)
workers Integer(ENV['WEB_CONCURRENCY'] || 2)
threads threads_count, threads_count

activate_control_app

rackup DefaultRackup

[quartzmo]

@britg Thanks for opening this issue. Are you running your cluster on GKE? Is this StackOverflow question relevant? gce container logs not showing up in cloud logging

/cc @dazuma

[quartzmo]

You may also want to open a StackOverflow question. If you do so, please link to it from this issue.

[britg]

Hi @quartzmo - thanks for the reply. I am running this rails app on my own server outside of Google Cloud. I've updated the issue to be more clear and I've created a Stack Overflow question.

[quartzmo]

@britg Great, thank you. Can you link to your Stack Overflow question?

[britg]

Sure, I have editing the original issue text with the Stack Overflow link, and here it is as well:

https://stackoverflow.com/questions/47558606/google-stackdriver-working-with-pumas-cluster-mode-workers-outside-of-google-cl

[quartzmo]

Ah, sorry, missed the edit. Thank you.

[bmclean]

@britg This might be the loading grpc before forking problem. There is a summary of the problem here. The grpc library is initialized when you require 'google/cloud/logging/rails'. Could you try forking the process first and then initialize the grpc library?

Also see grpc #7951.

[britg]

@bmclean Thanks for the pointers. Sounds like in order to solve this I need to require google/cloud/logging/rails after puma forks workers.

To accomplish this, though, I need to somehow set configuration on the config.google_cloud.logging config object, but config.google_cloud is nil on application start.

Is there a way to set config parameters without requiring google/cloud first? Seems to be a chicken and egg problem here where requiring the library to set config params also starts gRPC, which is the root cause of the forking problem.

[blowmage]

You can require google/cloud/logging pre-fork to configure. As long as you don’t create a Logging client you should be fine.

[britg]

@blowmage I may be misunderstanding, but in my application.rb when I change:

application.rb

#require "google/cloud/logging/rails"
require "google/cloud/logging"

I get the following error::

NoMethodError: undefined method `google_cloud' for #<Rails::Application::Configuration:0x007faa16089f68>
/Users/gardnerbr/.rvm/gems/ruby-2.2.2/gems/railties-5.0.0.1/lib/rails/railtie/configuration.rb:95:in `method_missing'
/Users/gardnerbr/Key-Ring-Production-API/config/application.rb:90:in `<class:Application>'
/Users/gardnerbr/Key-Ring-Production-API/config/application.rb:34:in `<module:KrOnRails>'
/Users/gardnerbr/Key-Ring-Production-API/config/application.rb:33:in `<top (required)>'
/Users/gardnerbr/Key-Ring-Production-API/Rakefile:4:in `require'
/Users/gardnerbr/Key-Ring-Production-API/Rakefile:4:in `<top (required)>'
/Users/gardnerbr/.rvm/gems/ruby-2.2.2/gems/rake-12.0.0/exe/rake:27:in `<top (required)>'
/Users/gardnerbr/.rvm/gems/ruby-2.2.2/bin/ruby_executable_hooks:15:in `eval'
/Users/gardnerbr/.rvm/gems/ruby-2.2.2/bin/ruby_executable_hooks:15:in `<main>'
(See full trace by running task with --trace)

[blowmage]

@dazuma Any input on this?

[britg]

Alternatively, if there's a way for me to manually construct a Google::Cloud::Logging.new -- are there any examples of how to do this with a project_id and keyfile.json?

Everything I found in the documentation assumes the configuration exists in the Rails.config

[dazuma]

The problem appears to be at the gax/gapic layer. The gapic clients are supposed to avoid requiring grpc until an actual service connection needs to be opened. However, gax is messing this up. Requiring "google/gax" by itself already causes grpc to be loaded: google/gax.rb -> google/gax/errors.rb -> google/gax/grpc.rb -> grpc

[dazuma]

@britg a couple ideas:

• Does turning off preload help?
• Have you tried initializing during on_worker_boot?

[britg]

@dazuma Turning off preloading does not help. I have tried with both preloading on and off and neither produce Stackdriver logs (but running in single mode does produce logs).

How would I go about initializing in on_worker_boot -- re: my last question on Google::Cloud::Logging.new -- all I have is a project_id and a valid keyfile.json. I can't find an example of setting up a logger with just these two pieces without relying on the Rails conf

[blowmage]

@dazuma Can you give us an update?

[shaneog]

Sadly this is a complete blocker for me. We use Passenger Enterprise and see the same issue.

If there is no fix coming, can there be an official workaround that works with a default Rails project, which uses Puma?

[jopotts]

I had problems getting the logging working on a Rails app running on Passenger from GKE (currently only staging). Thought it might be this issue.

However, it turned out to be config.google_cloud.use_debugger = true that was stopping the other services working when using the stackdriver gem. When set to false, the logging now works. I think it's a service account permissions issue.

Also worth noting is that by default the stackdriver gem is only enabled for production, so an explicit config.google_cloud.use_logging = true is required for staging.

https://googlecloudplatform.github.io/google-cloud-ruby/#/docs/stackdriver/v0.14.0/guides/instrumentation_configuration

[dazuma]

@jopotts Thanks for the tip about disabling the debugger. I spent some time investigating the debugger's behavior in the presence of preforking, and indeed it's opening a grpc connection too early, before the workers are forked, which appears to be wreaking all sorts of havoc with the grpc connection.

So yes, turning off the debugger should be an effective workaround for now. And this is probably the root cause of most of the various prefork issues people have been seeing in this thread. I'm currently working on a more permanent fix.

[dazuma]

We released google-cloud-debugger 0.32.0 and stackdriver 0.15.0 with a workaround that delays the debugger startup until after workers are forked. That should mitigate the problem for now. The root cause is https://github.com/grpc/grpc/issues/7951 which is being investigated.

I'm going to close this now. Please feel free to reopen if you are still observing this behavior with the new gem versions.

[locriani]

@dazuma This is still broken with 0.32.0 / 0.15.0 with a passenger setup:

Phusion Passenger 5.3.1
nginx version: nginx/1.14.0

Gems included by the bundle:
  * google-cloud-core (1.2.0)
  * google-cloud-debugger (0.32.0)
  * google-cloud-env (1.0.1)
  * google-cloud-error_reporting (0.30.0)
  * google-cloud-logging (1.5.0)
  * google-cloud-trace (0.33.0)
  * google-gax (1.2.0)
  * google-protobuf (3.5.1.2)
  * googleapis-common-protos (1.3.7)
  * googleapis-common-protos-types (1.0.1)
  * googleauth (0.6.2)
  * grpc (1.12.0)
  * stackdriver (0.15.0)
  * stackdriver-core (1.3.0)

config.ru:

require ::File.expand_path('../config/environment',  __FILE__)
run Rails.application

use Rack::Cors do
  allow do
    origins 'localhost:3000', '127.0.0.1:3000',
            /^http:\/\/192\.168\.0\.\d{1,3}(:\d+)?$/

    resource '/file/list_all/', :headers => 'x-domain-token'
    resource '/file/at/*',
        :methods => [:get, :post, :put, :delete, :options],
        :headers => 'x-domain-token',
        :max_age => 600
  end

  allow do
    origins '*'
    resource '/public/*', :headers => :any, :methods => :get
  end
end

if defined?(PhusionPassenger)
 PhusionPassenger.on_event(:starting_worker_process) do |forked|
   if forked
     Google::Cloud::Debugger::Middleware.start_agents
   end
 end
end

Disabling forking causes all functionality (logging, tracing, error reporting) to work immediately, enabling forking causes it all to fail immediately.

[joe1chen]

This is still not working for us as well with google-cloud-debugger 0.32.4 and stackdriver 0.15.2.

[blowmage]

Can you upgrade google-gax to 1.3.0 and grpc to 1.15.0 and see if the behavior is the same?

[blowmage]

@locriani @joe1chen Can each of you open new issues explaining the behavior you are seeing and include all relevant information. Ruby runtime versions, rails version, operating system, backtraces, etc. A simple rails application that reproduces the behavior is extremely useful, if you don't want to share too much about your applications.

Right now we don't have enough information from either of you to know for sure that this is the same issue.

I am going to re-close this issue. Please reference this issue in your new issues.