From 907c3b318acd7f10000ce54df6b7bd3fad67d1e6 Mon Sep 17 00:00:00 2001
From: Mitchell Hashimoto <mitchell.hashimoto@gmail.com>
Date: Sun, 10 Jul 2011 16:48:00 -0700
Subject: [PATCH] Logging of `vagrant`, action running, and warden

---
 bin/vagrant                  |  4 ++++
 lib/vagrant/action.rb        |  1 +
 lib/vagrant/action/warden.rb | 10 ++++++++--
 lib/vagrant/environment.rb   |  2 +-
 4 files changed, 14 insertions(+), 3 deletions(-)

diff --git a/bin/vagrant b/bin/vagrant
index 8cc7a9d6e..d78b9825a 100755
--- a/bin/vagrant
+++ b/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
diff --git a/lib/vagrant/action.rb b/lib/vagrant/action.rb
index 032199895..73b609962 100644
--- a/lib/vagrant/action.rb
+++ b/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
diff --git a/lib/vagrant/action/warden.rb b/lib/vagrant/action/warden.rb
index 68e5dbc99..73be36053 100644
--- a/lib/vagrant/action/warden.rb
+++ b/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
diff --git a/lib/vagrant/environment.rb b/lib/vagrant/environment.rb
index d36f6e2da..053cf8d4a 100644
--- a/lib/vagrant/environment.rb
+++ b/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