cookpad/griffin

gRPC server and client for Ruby

Griffin

Griffin is gRPC server which supports multi process by using serverengine. Griffin also supports building gRPC client.

Installation

Add this line to your application's Gemfile:

gem 'griffin'

And then execute:

$ bundle

Or install it yourself as:

gem install griffin

Usage

Server

class GreeterServer < Helloworld::Greeter::Service
  def say_hello(hello_req, _unused_call)
    Helloworld::HelloReply.new(message: "Hello #{hello_req.name}")
  end
end

Griffin::Server.configure do |c|
  c.bind '127.0.0.1'

  c.port 50051

  c.services GreeterServer.new

  c.workers 2 # A number of worker process
end

Griffin::Server.run

Interceptors

• cookpad/griffin-interceptors collection of interceptors

Development

bundle install

Contributing

Bug reports and pull requests are welcome on GitHub at https://github.com/cookpad/griffin.

License

The gem is available as open source under the terms of the MIT License.

griffin's Issues

Graceful termination hanging with ongoing requests

Problem

Graceful termination does not seem to work when there are ongoing requests.

Reproduction steps:

• Launch server
• Send time-spending request (such as sleep for x seconds)
• Send SIGTERM to server before the request ends

Observed issues:

• the server hangs and stops forcibly after 30s
• all ongoing requests fail to reach the client, even after completion of their task

Additional information

Sample Protocol Buffer

syntax = "proto3";

// Package
package sleep;

// Service
service SleepService {
  rpc Sleep(SleepRequest) returns (SleepResponse) {}
}

message SleepRequest {
  int32 seconds = 1;
}

message SleepResponse {
  string message = 1;
}

Sample server implementation

require 'sleep/service_services_pb'

class SleepService < Sleep::SleepService::Service
  def sleep(sleep_req, _unused_call)
    puts "Sleep for #{sleep_req.seconds}"
    Kernel.sleep sleep_req.seconds
    puts "Slept for #{sleep_req.seconds}"
    Sleep::SleepResponse.new(message: "Slept for #{sleep_req.seconds}")
  end
end

Logs

Normal behavior: server logs when stopping the server after the request ends

I, [2019-07-18T09:23:50.903992 #56302]  INFO -- : Griffin v0.2.3 starts as single mode
I, [2019-07-18T09:23:50.904370 #56302]  INFO -- : Handle /sleep.SleepService/Sleep
D, [2019-07-18T09:23:50.904667 #56302] DEBUG -- : Griffin worker thread 1 started
Sleep for 5
Slept for 5
I, [2019-07-18T09:23:58.050704 #56302]  INFO -- : {"system"=>"grpc", "span.kind"=>"server", "grpc.method"=>:Sleep, "grpc.service_name"=>"sleep.SleepService", "grpc.start_time"=>"2019-07-18 09:23:53 +0900", "grpc.code"=>"0", "grpc.x_request_id"=>"7569c2fc-e48b-4815-bf9a-45d1a26f35f7", "grpc.duration"=>"5.002614"}
^CI, [2019-07-18T09:24:00.387299 #56302]  INFO -- : Shutting down sever(id=0) gracefully...
D, [2019-07-18T09:24:00.387452 #56302] DEBUG -- : Shutdown waiting 1 workers
D, [2019-07-18T09:24:00.387715 #56302] DEBUG -- : worker thread Griffin worker thread 1 is stopping

Issue : server logs when stopping the server while the request is ongoing

I, [2019-07-18T09:25:42.210141 #58493]  INFO -- : Griffin v0.2.3 starts as single mode
I, [2019-07-18T09:25:42.210474 #58493]  INFO -- : Handle /sleep.SleepService/Sleep
D, [2019-07-18T09:25:42.210714 #58493] DEBUG -- : Griffin worker thread 1 started
Sleep for 5
I, [2019-07-18T09:25:46.664875 #58493]  INFO -- : Shutting down sever(id=0) gracefully...
D, [2019-07-18T09:25:46.665000 #58493] DEBUG -- : Shutdown waiting 0 workers
I, [2019-07-18T09:25:46.665378 #58493]  INFO -- : ping ack is received
D, [2019-07-18T09:25:47.666421 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:25:48.668457 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:25:49.668696 #58493] DEBUG -- : Shutdown waiting 0 workers
Slept for 5
I, [2019-07-18T09:25:50.640183 #58493]  INFO -- : {"system"=>"grpc", "span.kind"=>"server", "grpc.method"=>:Sleep, "grpc.service_name"=>"sleep.SleepService", "grpc.start_time"=>"2019-07-18 09:25:45 +0900", "grpc.code"=>"0", "grpc.x_request_id"=>"1898236c-5592-40b3-8b15-0252ba6aa2a4", "grpc.duration"=>"5.003559"}
D, [2019-07-18T09:25:50.672957 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:25:51.675338 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:25:52.679192 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:25:53.684137 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:25:54.687010 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:25:55.689714 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:25:56.692436 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:25:57.692803 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:25:58.695436 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:25:59.697576 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:26:00.702297 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:26:01.707246 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:26:02.711485 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:26:03.712357 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:26:04.714134 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:26:05.714473 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:26:06.715646 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:26:07.718471 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:26:08.722171 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:26:09.726579 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:26:10.727619 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:26:11.730942 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:26:12.734251 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:26:13.739045 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:26:14.740369 #58493] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:26:15.743004 #58493] DEBUG -- : Shutdown waiting 0 workers
E, [2019-07-18T09:26:16.665788 #58493] ERROR -- : Graceful shutdown is timeout (30sec). Perform shutdown forceibly
E, [2019-07-18T09:26:16.666627 #58493] ERROR -- : An error occured on top level in worker Griffin worker thread 1: Bad file descriptor (Errno::EBADF)
~/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/griffin-0.2.3/lib/griffin/thread_pool.rb:89:in `backtrace'
~/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/griffin-0.2.3/lib/griffin/thread_pool.rb:89:in `rescue in block (2 levels) in spawn_thread'
~/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/griffin-0.2.3/lib/griffin/thread_pool.rb:86:in `block (2 levels) in spawn_thread'
~/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/griffin-0.2.3/lib/griffin/thread_pool.rb:74:in `loop'
~/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/griffin-0.2.3/lib/griffin/thread_pool.rb:74:in `block in spawn_thread'  
D, [2019-07-18T09:26:16.666807 #58493] DEBUG -- : worker thread Griffin worker thread 1 is stopping

Source of the problem

I didn't check the code thoroughly but the issue seems to lie with GrpcKit draining mechanism.
Forcibly disabling GrpcKit's draining mechanism with the following patch seems to solve this issue, but I am not sure how it affects the rest of the code.

module GrpcKit
  module Session
    class ServerSession < DS9::Server
      def drain
      end
    end
  end
end

I, [2019-07-18T09:27:40.812925 #62406]  INFO -- : Griffin v0.2.3 starts as single mode
I, [2019-07-18T09:27:40.813372 #62406]  INFO -- : Handle /sleep.SleepService/Sleep
D, [2019-07-18T09:27:40.813743 #62406] DEBUG -- : Griffin worker thread 1 started
Sleep for 5
I, [2019-07-18T09:27:48.273437 #62406]  INFO -- : Shutting down sever(id=0) gracefully...
D, [2019-07-18T09:27:48.273636 #62406] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:27:49.277749 #62406] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:27:50.280339 #62406] DEBUG -- : Shutdown waiting 0 workers
D, [2019-07-18T09:27:51.284829 #62406] DEBUG -- : Shutdown waiting 0 workers
Slept for 5
I, [2019-07-18T09:27:52.229329 #62406]  INFO -- : {"system"=>"grpc", "span.kind"=>"server", "grpc.method"=>:Sleep, "grpc.service_name"=>"sleep.SleepService", "grpc.start_time"=>"2019-07-18 09:27:47 +0900", "grpc.code"=>"0", "grpc.x_request_id"=>"804f2a28-fab9-4e23-955b-e5cee426548b", "grpc.duration"=>"5.001566"}
D, [2019-07-18T09:27:52.233253 #62406] DEBUG -- : worker thread Griffin worker thread 1 is stopping

I wasn't sure if it is a GrpcKit issue or only occurring when used with Griffin, so I posted the issue here.