Graceful termination does not seem to work when there are ongoing requests.
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
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
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.
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.