Use centralized Logger and add instrument methods

CHANGELOG.md

@@ -1,6 +1,8 @@
 Master
 ===
 
+* Use centralized Logger and add benchmark methods
+
 3.0.0.rc.3
 ====
 * Improve asset methods and link_to by making them more clever and aware of options such as relative_assets and http_prefix

middleman-core/lib/middleman-core/application.rb

@@ -4,6 +4,7 @@ require "tilt"
 # Use ActiveSupport JSON
 require "active_support/json"
 require "active_support/core_ext/integer/inflections"
+require "active_support/core_ext/float/rounding"
 
 # Simple callback library
 require "middleman-core/vendor/hooks-0.2.0/lib/hooks"
@@ -85,10 +86,6 @@ module Middleman
     # @return [String]
     set :environment, (ENV['MM_ENV'] && ENV['MM_ENV'].to_sym) || :development
 
-    # Whether logging is active, disabled by default
-    # @return [String]
-    set :logging, false
-
     # Which file should be used for directory indexes
     # @return [String]
     set :index_file,  "index.html"
@@ -228,12 +225,7 @@ module Middleman
       self
     end
     
-    # Whether we're logging
+    delegate :logger, :instrument, :to => ::Middleman::Util
-    #
-    # @return [Boolean] If we're logging
-    def logging?
-      logging
-    end
 
     # Work around this bug: http://bugs.ruby-lang.org/issues/4521
     # where Ruby will call to_s/inspect while printing exception

middleman-core/lib/middleman-core/cli/build.rb

@@ -28,6 +28,10 @@ module Middleman::Cli
       :type    => :boolean, 
       :default => false,
       :desc    => 'Print debug messages'
+    method_option :instrument,
+      :type    => :string, 
+      :default => false,
+      :desc    => 'Print instrument messages'
     
     # Core build Thor command
     # @return [void]
@@ -45,7 +49,7 @@ module Middleman::Cli
       @debugging = Middleman::Cli::Base.respond_to?(:debugging) && Middleman::Cli::Base.debugging
       @had_errors = false
       
-      self.class.shared_instance(options["verbose"])
+      self.class.shared_instance(options["verbose"], options["instrument"])
       
       self.class.shared_rack
 
@@ -73,10 +77,10 @@ module Middleman::Cli
       # Middleman::Application singleton
       #
       # @return [Middleman::Application]
-      def shared_instance(verbose=false)
+      def shared_instance(verbose=false, instrument=false)
         @_shared_instance ||= ::Middleman::Application.server.inst do
           set :environment, :build
-          set :logging,     verbose
+          logger(verbose ? 0 : 1, instrument)
         end
       end
       
@@ -146,6 +150,7 @@ module Middleman::Cli
   # A Thor Action, modular code, which does the majority of the work.
   class GlobAction < ::Thor::Actions::EmptyDirectory
     attr_reader :source
+    attr_reader :logger
 
     # Setup the action
     #
@@ -158,6 +163,8 @@ module Middleman::Cli
 
       @source = File.expand_path(base.find_in_source_paths(source.to_s))
 
+      @logger = Middleman::Cli::Build.shared_instance.logger
+
       super(base, @destination, config)
     end
     
@@ -221,7 +228,7 @@ module Middleman::Cli
       sort_order = %w(.png .jpeg .jpg .gif .bmp .svg .svgz .ico .woff .otf .ttf .eot .js .css)
       
       # Pre-request CSS to give Compass a chance to build sprites
-      puts "== Prerendering CSS" if @app.logging?
+      logger.debug "== Prerendering CSS"
 
       @app.sitemap.resources.select do |resource|
         resource.ext == ".css"
@@ -229,7 +236,7 @@ module Middleman::Cli
         Middleman::Cli::Build.shared_rack.get(URI.escape(resource.destination_path))
       end
       
-      puts "== Checking for Compass sprites" if @app.logging?
+      logger.debug "== Checking for Compass sprites"
 
       # Double-check for compass sprites
       @app.files.find_new_files(Pathname.new(@app.source_dir) + @app.images_dir)
@@ -238,7 +245,7 @@ module Middleman::Cli
       # find files in the build folder when it needs to generate sprites for the
       # css files
 
-      puts "== Building files" if @app.logging?
+      logger.debug "== Building files"
 
       resources = @app.sitemap.resources.sort do |a, b|
         a_idx = sort_order.index(a.ext) || 100

middleman-core/lib/middleman-core/cli/server.rb

@@ -25,6 +25,10 @@ module Middleman::Cli
       :type    => :boolean, 
       :default => false,
       :desc    => 'Print debug messages'
+    method_option :instrument,
+      :type    => :string, 
+      :default => false,
+      :desc    => 'Print instrument messages'
     method_option "disable-watcher", 
       :type    => :boolean, 
       :default => false,
@@ -47,6 +51,7 @@ module Middleman::Cli
         :host              => options["host"],
         :environment       => options["environment"],
         :debug             => options["verbose"],
+        :instrumenting     => options["instrument"],
         :"disable-watcher" => options["disable-watcher"]
       }
       

middleman-core/lib/middleman-core/core_extensions/extensions.rb

@@ -113,9 +113,9 @@ module Middleman
           end
       
           if ext_module.nil?
-            puts "== Unknown Extension: #{ext}"
+            logger.warning "== Unknown Extension: #{ext}"
           else
-            puts "== Activating: #{ext}" if logging?
+            logger.debug "== Activating: #{ext}"
             self.class.register(ext_module, options, &block)
           end
         end
@@ -133,7 +133,7 @@ module Middleman
           # Check for and evaluate local configuration
           local_config = File.join(root, "config.rb")
           if File.exists? local_config
-            puts "== Reading:  Local config" if logging?
+            logger.debug "== Reading:  Local config"
             instance_eval File.read(local_config), local_config, 1
           end
           
@@ -150,10 +150,9 @@ module Middleman
       
           run_hook :after_configuration
       
-          if logging?
+          logger.debug "Loaded extensions:"
-            self.class.extensions.each do |ext|
+          self.class.extensions.each do |ext|
-              puts "== Extension: #{ext}"
+            logger.debug "== Extension: #{ext}"
-            end
           end
         end
       end

middleman-core/lib/middleman-core/core_extensions/file_watcher.rb

@@ -53,6 +53,9 @@ module Middleman
       # Core File Change API class
       class API
         
+        attr_reader :app
+        delegate :logger, :to => :app
+        
         # Initialize api and internal path cache
         def initialize(app)
           @app = app
@@ -86,7 +89,7 @@ module Middleman
         # @return [void]
         def did_change(path)
           return if ignored?(path)
-          puts "== File Change: #{path.relative_path_from(@app.root_path)}" if @app.logging?
+          logger.debug "== File Change: #{path.relative_path_from(@app.root_path)}"
           @known_paths << path
           self.run_callbacks(path, :changed)
         end
@@ -97,7 +100,7 @@ module Middleman
         # @return [void]
         def did_delete(path)
           return if ignored?(path)
-          puts "== File Deletion: #{path.relative_path_from(@app.root_path)}" if @app.logging?
+          logger.debug "== File Deletion: #{path.relative_path_from(@app.root_path)}"
           @known_paths.delete(path)
           self.run_callbacks(path, :deleted)
         end

middleman-core/lib/middleman-core/core_extensions/front_matter.rb

@@ -46,6 +46,9 @@ module Middleman::CoreExtensions
     end
   
     class FrontmatterManager
+      attr_reader :app
+      delegate :logger, :to => :app
+    
       def initialize(app)
         @app = app
         @cache = {}
@@ -84,7 +87,7 @@ module Middleman::CoreExtensions
           begin
             data = YAML.load($1)
           rescue *YAML_ERRORS => e
-            puts "YAML Exception: #{e.message}"
+            logger.error "YAML Exception: #{e.message}"
             return false
           end
 
@@ -107,7 +110,7 @@ module Middleman::CoreExtensions
             json = ($1+$2).sub(";;;", "{").sub(";;;", "}")
             data = ActiveSupport::JSON.decode(json)
           rescue => e
-            puts "JSON Exception: #{e.message}"
+            logger.error "JSON Exception: #{e.message}"
             return false
           end
 

middleman-core/lib/middleman-core/core_extensions/request.rb

@@ -197,7 +197,7 @@ module Middleman
           self.req = req = ::Rack::Request.new(env)
           self.res = res = ::Rack::Response.new
 
-          puts "== Request: #{env["PATH_INFO"]}" if logging?
+          logger.debug "== Request: #{env["PATH_INFO"]}"
 
           # Catch :halt exceptions and use that response if given
           catch(:halt) do
@@ -271,7 +271,7 @@ module Middleman
           end
 
           # End the request
-          puts "== Finishing Request: #{request_path} (#{(Time.now - start_time).round(2)}s)" if logging?
+          logger.debug "== Finishing Request: #{request_path} (#{(Time.now - start_time).round(2)}s)"
           halt res.finish
         end
       

middleman-core/lib/middleman-core/logger.rb

@@ -0,0 +1,29 @@
+# Use the Ruby/Rails logger
+require 'active_support/core_ext/logger'
+require "securerandom"
+
+module Middleman
+  
+  # The Middleman Logger
+  class Logger < ::Logger
+    
+    # Force output to STDOUT
+    def initialize(log_level=1, is_instrumenting=false, target=STDOUT)
+      super(STDOUT)
+      
+      self.level = log_level
+      @instrumenting = is_instrumenting
+      
+      if @instrumenting != false
+        ::ActiveSupport::Notifications.subscribe(/\.middleman$/, self)
+      end
+    end
+
+    def call(message, *args)
+      return if @instrumenting.is_a?(String) && @instrumenting != "instrument" && !message.include?(@instrumenting)
+
+      evt = ActiveSupport::Notifications::Event.new(message, *args)
+      self.info "== Instrument (#{evt.name.sub(/.middleman$/, '')}): #{evt.duration}ms"
+    end
+  end
+end

middleman-core/lib/middleman-core/preview_server.rb

@@ -9,23 +9,23 @@ module Middleman
     DEFAULT_PORT = 4567
     
     class << self
+      attr_reader :app
+      delegate :logger, :to => :app
       
       # Start an instance of Middleman::Application
       # @return [void]
       def start(options={})
-        app = ::Middleman::Application.server.inst do
+        @app = ::Middleman::Application.server.inst do
           if options[:environment]
             set :environment, options[:environment].to_sym
           end
           
-          if options[:debug]
+          logger(options[:debug] ? 0 : 1, options[:instrumenting] || false)
-            set :logging, true
-          end
         end
 
         port = options[:port] || DEFAULT_PORT
     
-        puts "== The Middleman is standing watch on port #{port}"
+        logger.info "== The Middleman is standing watch on port #{port}"
 
         @webrick ||= setup_webrick(
           options[:host]  || "0.0.0.0",
@@ -54,7 +54,7 @@ module Middleman
       # Detach the current Middleman::Application instance
       # @return [void]
       def stop
-        puts "== The Middleman is shutting down"
+        logger.info "== The Middleman is shutting down"
         if @listener
           @listener.stop
           @listener = nil

middleman-core/lib/middleman-core/renderers/markdown.rb

@@ -43,7 +43,7 @@ module Middleman
                 ::Tilt.prefer(markdown_engine_klass)
               end  
             rescue LoadError
-              $stderr.puts "Requested Markdown engine (#{markdown_engine}) not found. Maybe the gem needs to be installed and required?"
+              logger.warn "Requested Markdown engine (#{markdown_engine}) not found. Maybe the gem needs to be installed and required?"
             end
           end
         end

middleman-core/lib/middleman-core/sitemap/resource.rb

@@ -11,6 +11,7 @@ module Middleman
         
       # @return [Middleman::Application]
       attr_reader :app
+      delegate :logger, :instrument, :to => :app
     
       # @return [Middleman::Sitemap::Store]
       attr_reader :store
@@ -112,29 +113,27 @@ module Middleman
       def render(opts={}, locs={}, &block)
         return File.open(source_file).read unless template?
 
-        start_time = Time.now
+        relative_source = Pathname(source_file).relative_path_from(Pathname(app.root))
-        puts "== Render Start: #{source_file}" if app.logging?
         
-        md   = metadata.dup
+        instrument "render.resource", :path => relative_source  do
-        opts = md[:options].deep_merge(opts)
+          md   = metadata.dup
-        locs = md[:locals].deep_merge(locs)
+          opts = md[:options].deep_merge(opts)
+          locs = md[:locals].deep_merge(locs)
 
-        # Forward remaining data to helpers
+          # Forward remaining data to helpers
-        if md.has_key?(:page)
+          if md.has_key?(:page)
-          app.data.store("page", md[:page])
+            app.data.store("page", md[:page])
+          end
+        
+          md[:blocks].each do |aBlock|
+            app.instance_eval(&aBlock)
+          end
+      
+          app.instance_eval(&block) if block_given?
+        
+          app.current_path ||= self.destination_path
+          app.render_template(source_file, locs, opts)
         end
-
-        md[:blocks].each do |aBlock|
-          app.instance_eval(&aBlock)
-        end
-      
-        app.instance_eval(&block) if block_given?
-        
-        app.current_path ||= self.destination_path
-        result = app.render_template(source_file, locs, opts)
-
-        puts "== Render End: #{source_file} (#{(Time.now - start_time).round(2)}s)" if app.logging?
-        result
       end
     
       # A path without the directory index - so foo/index.html becomes

middleman-core/lib/middleman-core/util.rb

@@ -1,3 +1,9 @@
+# Our custom logger
+require "middleman-core/logger"
+
+# For instrumenting
+require "active_support/notifications"
+
 # Using Thor's indifferent hash access
 require "thor"
 
@@ -7,6 +13,23 @@ require "pathname"
 module Middleman
   module Util
 
+    # The logger
+    #
+    # @return [Middleman::Logger] The logger
+    def self.logger(*args)
+      if !@_logger || args.length > 0
+        @_logger = ::Middleman::Logger.new(*args)
+      end
+      
+      @_logger
+    end
+    
+    # Facade for ActiveSupport/Notification
+    def self.instrument(name, payload={}, &block)
+      name << ".middleman" unless name =~ /\.middleman$/
+      ::ActiveSupport::Notifications.instrument(name, payload, &block)
+    end
+    
     # Recursively convert a normal Hash into a HashWithIndifferentAccess
     #
     # @private

middleman-more/lib/middleman-more/core_extensions/i18n.rb

@@ -23,6 +23,9 @@ module Middleman
       end
   
       class Localizer
+        attr_reader :app
+        delegate :logger, :to => :app
+      
         def initialize(app, options={})
           @app = app
           @maps = {}
@@ -34,7 +37,7 @@ module Middleman
           @mount_at_root = @options.has_key?(:mount_at_root) ? @options[:mount_at_root] : langs.first
       
           if !@app.build?
-            puts "== Locales: #{langs.join(", ")}"
+            logger.info "== Locales: #{langs.join(", ")}"
           end
       
           # Don't output localizable files

middleman-more/lib/middleman-more/extensions/cache_buster.rb

@@ -21,7 +21,7 @@ module Middleman
               if File.readable?(real_path)
                 File.mtime(real_path).strftime("%s") 
               else
-                $stderr.puts "WARNING: '#{File.basename(path)}' was not found (or cannot be read) in #{File.dirname(real_path)}"
+                logger.warn "WARNING: '#{File.basename(path)}' was not found (or cannot be read) in #{File.dirname(real_path)}"
               end
             end
           end