Add debug logging output to Bundler implementation

lib/vagrant/bundler.rb

@@ -27,6 +27,7 @@ module Vagrant
 
     def initialize
       @plugin_gem_path = Vagrant.user_data_path.join("gems", RUBY_VERSION).freeze
+      @logger = Log4r::Logger.new("vagrant::bundler")
     end
 
     # Initializes Bundler and the various gem paths so that we can begin
@@ -40,6 +41,8 @@ module Vagrant
         Gem::Dependency.new(name, info['gem_version'].to_s.empty? ? '> 0' : info['gem_version'])
       end
 
+      @logger.debug("Current generated plugin dependency list: #{plugin_deps}")
+
       # Load dependencies into a request set for resolution
       request_set = Gem::RequestSet.new(*plugin_deps)
       # Never allow dependencies to be remotely satisfied during init
@@ -65,15 +68,19 @@ module Vagrant
         # Compose set for resolution
         composed_set = Gem::Resolver.compose_sets(current_set, plugin_set)
 
+        @logger.debug("Composed local RubyGems set for plugin init resolution: #{composed_set}")
+
         # Resolve the request set to ensure proper activation order
         solution = request_set.resolve(composed_set)
       rescue Gem::UnsatisfiableDependencyError => failure
         if repair
           raise failure if @init_retried
+          @logger.debug("Resolution failed but attempting to repair. Failure: #{failure}")
           install(plugins)
           @init_retried = true
           retry
         else
+          @logger.debug("#{failure.class}: #{failure}")
           $stderr.puts "Vagrant failed to properly initialize due to an error while"
           $stderr.puts "while attempting to load configured plugins. This can be caused"
           $stderr.puts "by manually tampering with the 'plugins.json' file, or by a"
@@ -85,13 +92,17 @@ module Vagrant
         end
       end
 
+      @logger.debug("Initialization solution set: #{solution.map(&:full_name)}")
+
       # Activate the gems
       begin
         retried = false
         solution.each do |activation_request|
           unless activation_request.full_spec.activated?
+            @logger.debug("Activating gem #{activation_request.full_spec.full_name}")
             activation_request.full_spec.activate
             if(defined?(::Bundler))
+              @logger.debug("Marking gem #{activation_request.full_spec.full_name} loaded within Bundler.")
               ::Bundler.rubygems.mark_loaded activation_request.full_spec
             end
           end
@@ -114,6 +125,7 @@ module Vagrant
         solution.map(&:full_spec)
 
       if(defined?(::Bundler))
+        @logger.debug("Updating Bundler with full specification list")
         ::Bundler.rubygems.replace_entrypoints(full_vagrant_spec_list)
       end
 
@@ -147,6 +159,7 @@ module Vagrant
           "sources" => opts.fetch(:sources, Gem.sources.map(&:to_s))
         }
       }
+      @logger.debug("Installing local plugin - #{plugin_info}")
       internal_install(plugin_info, {})
       plugin_source.spec
     end
@@ -242,12 +255,15 @@ module Vagrant
         end
         Array(info["sources"]).each do |source|
           if !Gem.sources.include?(source)
+            @logger.debug("Adding RubyGems source for plugin install: #{source}")
             Gem.sources << source
           end
         end
         Gem::Dependency.new(name, gem_version)
       end
 
+      @logger.debug("Dependency list for installation: #{plugin_deps}")
+
       # Create the request set for the new plugins
       request_set = Gem::RequestSet.new(*plugin_deps)
 
@@ -263,9 +279,12 @@ module Vagrant
       # Generate the required solution set for new plugins
       solution = request_set.resolve(installer_set)
 
+      @logger.debug("Generated solution set: #{solution.map(&:full_name)}")
+
       # If any items in the solution set are local but not activated, turn them on
       solution.each do |activation_request|
         if activation_request.installed? && !activation_request.full_spec.activated?
+          @logger.debug("Activating gem specification: #{activation_request.full_spec.full_name}")
           activation_request.full_spec.activate
         end
       end