diff --git a/CHANGELOG.md b/CHANGELOG.md index 87758b4d..b15d736e 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/middleman-core/lib/middleman-core/application.rb b/middleman-core/lib/middleman-core/application.rb index a4259d77..cd35f07e 100644 --- a/middleman-core/lib/middleman-core/application.rb +++ b/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" @@ -17,7 +18,7 @@ module Middleman class Application # Uses callbacks include Hooks - + # Before request hook define_hook :before @@ -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" @@ -227,13 +224,8 @@ module Middleman def settings self end - - # Whether we're logging - # - # @return [Boolean] If we're logging - def logging? - logging - end + + delegate :logger, :instrument, :to => ::Middleman::Util # Work around this bug: http://bugs.ruby-lang.org/issues/4521 # where Ruby will call to_s/inspect while printing exception diff --git a/middleman-core/lib/middleman-core/cli/build.rb b/middleman-core/lib/middleman-core/cli/build.rb index fb1a9b34..b8041060 100644 --- a/middleman-core/lib/middleman-core/cli/build.rb +++ b/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 diff --git a/middleman-core/lib/middleman-core/cli/server.rb b/middleman-core/lib/middleman-core/cli/server.rb index 76a3582a..f34e487f 100644 --- a/middleman-core/lib/middleman-core/cli/server.rb +++ b/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"] } diff --git a/middleman-core/lib/middleman-core/core_extensions/extensions.rb b/middleman-core/lib/middleman-core/core_extensions/extensions.rb index 6bf2e32d..bd88559a 100644 --- a/middleman-core/lib/middleman-core/core_extensions/extensions.rb +++ b/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? - self.class.extensions.each do |ext| - puts "== Extension: #{ext}" - end + logger.debug "Loaded extensions:" + self.class.extensions.each do |ext| + logger.debug "== Extension: #{ext}" end end end diff --git a/middleman-core/lib/middleman-core/core_extensions/file_watcher.rb b/middleman-core/lib/middleman-core/core_extensions/file_watcher.rb index 00a6c8d3..35bd35c2 100644 --- a/middleman-core/lib/middleman-core/core_extensions/file_watcher.rb +++ b/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 diff --git a/middleman-core/lib/middleman-core/core_extensions/front_matter.rb b/middleman-core/lib/middleman-core/core_extensions/front_matter.rb index d3e8d35a..6529f56e 100644 --- a/middleman-core/lib/middleman-core/core_extensions/front_matter.rb +++ b/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 diff --git a/middleman-core/lib/middleman-core/core_extensions/request.rb b/middleman-core/lib/middleman-core/core_extensions/request.rb index af03da17..de654a9f 100644 --- a/middleman-core/lib/middleman-core/core_extensions/request.rb +++ b/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 diff --git a/middleman-core/lib/middleman-core/logger.rb b/middleman-core/lib/middleman-core/logger.rb new file mode 100644 index 00000000..6fd7a1a6 --- /dev/null +++ b/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 \ No newline at end of file diff --git a/middleman-core/lib/middleman-core/preview_server.rb b/middleman-core/lib/middleman-core/preview_server.rb index 8a173932..42e1cf78 100644 --- a/middleman-core/lib/middleman-core/preview_server.rb +++ b/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] - set :logging, true - end + logger(options[:debug] ? 0 : 1, options[:instrumenting] || false) 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 diff --git a/middleman-core/lib/middleman-core/renderers/markdown.rb b/middleman-core/lib/middleman-core/renderers/markdown.rb index 407818d2..6cf21580 100644 --- a/middleman-core/lib/middleman-core/renderers/markdown.rb +++ b/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 diff --git a/middleman-core/lib/middleman-core/sitemap/resource.rb b/middleman-core/lib/middleman-core/sitemap/resource.rb index 28f86e10..8d70c514 100644 --- a/middleman-core/lib/middleman-core/sitemap/resource.rb +++ b/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 @@ -111,30 +112,28 @@ module Middleman # @return [String] def render(opts={}, locs={}, &block) return File.open(source_file).read unless template? - - start_time = Time.now - puts "== Render Start: #{source_file}" if app.logging? - md = metadata.dup - opts = md[:options].deep_merge(opts) - locs = md[:locals].deep_merge(locs) - - # Forward remaining data to helpers - if md.has_key?(: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? + relative_source = Pathname(source_file).relative_path_from(Pathname(app.root)) - app.current_path ||= self.destination_path - result = app.render_template(source_file, locs, opts) + instrument "render.resource", :path => relative_source do + md = metadata.dup + opts = md[:options].deep_merge(opts) + locs = md[:locals].deep_merge(locs) - puts "== Render End: #{source_file} (#{(Time.now - start_time).round(2)}s)" if app.logging? - result + # Forward remaining data to helpers + if md.has_key?(: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 end # A path without the directory index - so foo/index.html becomes diff --git a/middleman-core/lib/middleman-core/util.rb b/middleman-core/lib/middleman-core/util.rb index b67a2065..2b035c7d 100644 --- a/middleman-core/lib/middleman-core/util.rb +++ b/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" @@ -6,6 +12,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 # diff --git a/middleman-more/lib/middleman-more/core_extensions/i18n.rb b/middleman-more/lib/middleman-more/core_extensions/i18n.rb index c4a8fedc..cd8d06e5 100644 --- a/middleman-more/lib/middleman-more/core_extensions/i18n.rb +++ b/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 diff --git a/middleman-more/lib/middleman-more/extensions/cache_buster.rb b/middleman-more/lib/middleman-more/extensions/cache_buster.rb index 01817004..5ff920ef 100755 --- a/middleman-more/lib/middleman-more/extensions/cache_buster.rb +++ b/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