Logging of `vagrant`, action running, and warden

bin/vagrant

@@ -5,6 +5,10 @@ require 'vagrant/cli'
 env = Vagrant::Environment.new
 
 begin
+  # Begin logging early here
+  env.logger.info "`vagrant` invoked: #{ARGV.inspect}"
+
+  # Disable color if the proper argument was passed
   shell = ARGV.include?("--no-color") ? Thor::Shell::Basic.new : Thor::Base.shell.new
 
   # Set the UI early in case any errors are raised, and load

lib/vagrant/action.rb

@@ -129,6 +129,7 @@ module Vagrant
       end
 
       # We place a process lock around every action that is called
+      env.logger.info "Running action: #{callable_id}"
       env.lock do
         Busy.busy(int_callback) { callable.call(action_environment) }
       end

lib/vagrant/action/warden.rb

@@ -25,13 +25,16 @@ module Vagrant
           # Call the next middleware in the sequence, appending to the stack
           # of "recoverable" middlewares in case something goes wrong!
           raise Errors::VagrantInterrupt if env.interrupted?
-          @stack.unshift(@actions.shift).first.call(env)
+          action = @actions.shift
+          env["logger"].info("warden") { "Calling action: #{action}" }
+          @stack.unshift(action).first.call(env)
           raise Errors::VagrantInterrupt if env.interrupted?
         rescue SystemExit
           # This means that an "exit" or "abort" was called. In these cases,
           # we just exit immediately.
           raise
         rescue Exception => e
+          env["logger"].info("warden") { "Error occurred: #{e}" }
           env["vagrant.error"] = e
 
           # Something went horribly wrong. Start the rescue chain then
@@ -46,7 +49,10 @@ module Vagrant
       # which has already run, in reverse order.
       def begin_rescue(env)
         @stack.each do |act|
-          act.recover(env) if act.respond_to?(:recover)
+          if act.respond_to?(:recover)
+            env["logger"].info("warden") { "Calling recover: #{act}" }
+            act.recover(env)
+          end
         end
 
         # Clear stack so that warden down the middleware chain doesn't

lib/vagrant/environment.rb

@@ -309,7 +309,7 @@ module Vagrant
       # Create the logger and custom formatter
       @logger = Logger.new(output)
       @logger.formatter = Proc.new do |severity, datetime, progname, msg|
-        "#{datetime} - [#{resource}] #{msg}\n"
+        "#{datetime} - #{progname} - [#{resource}] #{msg}\n"
       end
 
       @logger