1

I was using Open3.capture3 in my ruby code and started to notice deadlocks. I did some research and came across this great blog about how open3 can cause deadlocks. Taking this into account I came up with my own capture3 method (still using Open3.popen3) to replace one I was currently using (see below). However I have found that deadlocks still seem to be occurring and the responsible party is the blocking call on the wait_thread.value to get the Process::Status. Looking into Open3 source code I can see this wait_thread is just a Process::Waiter that you get from a Process.detach call. I was wondering what could be causing this deadlock? Is there some way I can check to see if this thread is deadlocked, kill it and return a custom Process::Status (I'd like to return a Process::Status as opposed to just an integer to stay inline with Open3.capture3)

def capture3(cmd)
  out_buff = ''
  err_buff = ''
  chunk_size = 4096
  # Progressive timeout array
  sleeps = [[0.05]*20,[0.1]*5,[0.5]*3,1,2].flatten
  _in, out, err, wait_thread = Open3.popen3(cmd)
  _in.close
  open_pipes = [out, err]
  while !open_pipes.empty?
    timeout = sleeps.shift || timeout
    ready_pipes, *_ = IO.select(open_pipes, nil, nil, timeout)
    ready_pipes.each do |pipe|
      tmp = ''
      begin
        tmp << pipe.readpartial(chunk_size)
      rescue EOFError
        pipe.close
        open_pipes.delete(pipe)
      end
      out_buff << tmp if pipe == out
      err_buff << tmp if pipe == err
    end
  end
  [out_buff, err_buff, wait_thread.value]
end

Note ruby version I'm using is 2.2.5 and running on Mac.

Edit: The exact error is No live threads left. Deadlock? (fatal) pointing to line number of the wait_thread.value call. I'm calling the capture3 method in another function where I fork the process like so

def fork_process(cmd, options={})
  pid = fork {
    Process.setproctitle(options[:process_name]) unless options[:process_name].nil?
    ENV.merge!(options[:environment])
    stdout, stderr, status = capture3(cmd)
    yield(stdout, stderr, status) if block_given?
  }
  Process.detach(pid)
end

Full stacktrace:

/home/myapp/utils.rb:769:in `value': No live threads left. Deadlock? (fatal)
        from /home/myapp/utils.rb:769:in `capture3'
        from /home/myapp/utils.rb:106:in `block in fork_process'
        from /home/myapp/utils.rb:104:in `fork'
        from /home/myapp/utils.rb:104:in `fork_process'
        from /home/myapp/server.rb:396:in `block in <class:MyServer>'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:1611:in `call'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:1611:in `block in compile!'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:975:in `[]'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:975:in `block (3 levels) in route!'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:994:in `route_eval'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:975:in `block (2 levels) in route!'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:1015:in `block in process_route'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:1013:in `catch'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:1013:in `process_route'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:973:in `block in route!'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:972:in `each'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:972:in `route!'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:1085:in `block in dispatch!'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `block in invoke'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `catch'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `invoke'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:1082:in `dispatch!'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:907:in `block in call!'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `block in invoke'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `catch'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `invoke'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:907:in `call!'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:895:in `call'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/rack-protection-1.5.3/lib/rack/protection/xss_header.rb:18:in `call'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/rack-protection-1.5.3/lib/rack/protection/path_traversal.rb:16:in `call'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/rack-protection-1.5.3/lib/rack/protection/json_csrf.rb:18:in `call'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/rack-protection-1.5.3/lib/rack/protection/frame_options.rb:31:in `call'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/rack-1.6.5/lib/rack/nulllogger.rb:9:in `call'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/rack-1.6.5/lib/rack/head.rb:13:in `call'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/show_exceptions.rb:25:in `call'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:182:in `call'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:2013:in `call'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:1487:in `block in call'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:1787:in `synchronize'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/sinatra-1.4.8/lib/sinatra/base.rb:1487:in `call'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/puma-3.8.2/lib/puma/configuration.rb:224:in `call'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/puma-3.8.2/lib/puma/server.rb:600:in `handle_request'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/puma-3.8.2/lib/puma/server.rb:435:in `process_client'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/puma-3.8.2/lib/puma/server.rb:299:in `block in run'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/puma-3.8.2/lib/puma/thread_pool.rb:120:in `call'
        from /Users/app/.rvm/gems/ruby-2.2.5/gems/puma-3.8.2/lib/puma/thread_pool.rb:120:in `block in spawn_thread'
Nick Hyland
  • 357
  • 1
  • 10
  • How exactly are you experiencing these deadlocks (stack trace/full exception)? Your code lacks error handling too. – D. SM Nov 21 '20 at 15:36
  • Added complete stacktrace with how it's called – Nick Hyland Nov 21 '20 at 18:33
  • I think you should be joining the thread before asking for its value. – D. SM Nov 22 '20 at 02:48
  • `Thread#value` uses join to wait for thread to complete and then returns the value, so that shouldn't be the issue. – Nick Hyland Nov 22 '20 at 11:14
  • Write a program that reproduces the issue, put a breakpoint before the value call, ensure that all of the output was consumed and all file descriptors are closed. – D. SM Nov 22 '20 at 18:28

0 Answers0