Debugging bundler stalling issues

README.md

The following is a way to determine where in the codebase bundler is stalling when fetching from external sources (rubygems.org, github.com, etc.). Use this as a way to determine where in the codebase bundler is stalling when it is happening without stopping the process or requiring modifications to the source directly.

Usage

1. Download the bundler_trap.rb script and put is somewhere easily accessible (I use the home directory in my examples).
2. Run bundler using the following command: ruby -I~ -rbundler_trap bin/bundle update
3. You will have to repeat step to until you get to a situation where bundler has stalled. When it does, send the INFO signal to the process (CMD+t on OSX, and on Linux, it should be kill -sINFO pid, but you might have to use a different signal).

This should print out debugging information regarding the current state of all of the threads used by bundler so we can determine where a fix needs to be made. This won't kill the process so this can be run mutiple times, and should be obvious on the start and end of the output.

I personally have found issues with running parallel requests when fetching the index from rubygems, so this is optimized to highlight issues from there and determine if it is a specific request or just common issue (in my case, it was an issue with the Net::HTTP#connect method not timing out when failing to connect to a host. This could be from my ISP, crappy WiFi setup, or otherthings unrelated to the codebase). I have also attempted to highlight any threads currently working on shell out commands, which should include any git based requests.

Acknowledgements

The idea for the script comes from the following excellent blog posts:

• https://tenderlovemaking.com/2016/02/05/i-am-a-puts-debuggerer.html
• http://www.schneems.com/2016/01/25/ruby-debugging-magic-cheat-sheet.html

bundler_trap.rb

require 'bundler'

vendored_lib = Gem::Specification.find_by_name('bundler').gem_dir
$:.unshift File.join(vendored_lib, 'lib', 'bundler', 'vendor')
require 'bundler/vendor/net/http/persistent'

module ExtraThreadInformation
  def connection_for uri
    # Add a thread variable to bundler's net/http/persistent 
    # to log requests used by this thread.
    key = ['net_http_persistent', @name].compact
    request_info_key = [key, 'request_uris'].join('_').intern

    Thread.current[request_info_key] ||= []
    Thread.current[request_info_key] +=  [uri]

    super uri
  end
end

Net::HTTP::Persistent.send(:prepend, ExtraThreadInformation)

trap(:INFO) {
  threads = Thread.list
  
  # Select threads that are either shelling out currently, or trying a Net::HTTP#connect
  # Matches stack traces that either match:
  #   - "in `connect'"
  #   - "in ``'"
  #
  # Somewhat crude and not precise, but it should only be inclusive to false positives,
  # which is fine for this, and should be apparent from the rest of the stack trace.
  working_threads = threads.select do |t|
    t.backtrace.first =~ /in `(connect|`)'$/
  end

  puts
  puts
  puts "Thread Count:     #{threads.count}"
  puts "Working Threads:  #{working_threads.count}"
  puts

  threads.each do |t|
    # Highlight working (stalled) threads
    color = working_threads.detect {|wt| wt.object_id == t.object_id } ? "\e[36m" : ''
    puts color + "#" * 50
     # Comment out this line and use the following line for a more concise output 
     # (though the first is preferred when reporting an issue)
    puts t.backtrace
    # puts t.backtrace.first
    
    # Report on Thread specific variables
    puts t.keys.inspect
    t.keys.each do |t_key|
      puts "#{t_key}: #{t[t_key]}"
    end
    puts "#" * 50 + "\e[0m"
  end

  puts
}