Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with HTTPS or Subversion.

Download ZIP

Loading…

Nested Diagnostic Contexts #4

Merged
merged 8 commits into from
Commits on Jan 2, 2013
Commits on Jan 6, 2013
Commits on Jan 10, 2013
  1. Added Rack middleware

    authored
    Middleware ensures that the nested diagnostic context is cleared between
    requests. It is added by default by the Railtie.
This page is out of date. Refresh to see the latest.
View
15 RELEASE.md
@@ -1,5 +1,20 @@
# Release notes
+## 0.2.0
+
+ * Added nested diagnostic context and Rack middleware to clear it between
+ requests
+
+### Note
+
+The `Hatchet::Message` constructor has been altered, going forward it will take
+a Hash of arguments instead of fixed arguments. It is currently backwards
+compatible but this will likely be dropped for 1.0.0 so it is advised you update
+your libraries now.
+
+This should only affect custom formatters which may want to take advantage of
+the nested diagnostic context which is now available anyway.
+
## 0.1.0
No changes from 0.0.20, just time for a minor version release.
View
6 lib/hatchet.rb
@@ -1,7 +1,5 @@
# -*- encoding: utf-8 -*-
-require 'logger'
-
require_relative 'hatchet/level_manager'
require_relative 'hatchet/backtrace_formatter'
require_relative 'hatchet/thread_name_formatter'
@@ -10,6 +8,8 @@
require_relative 'hatchet/hatchet_logger'
require_relative 'hatchet/logger_appender'
require_relative 'hatchet/message'
+require_relative 'hatchet/middleware'
+require_relative 'hatchet/nested_diagnostic_context'
require_relative 'hatchet/plain_formatter'
require_relative 'hatchet/simple_formatter'
require_relative 'hatchet/standard_formatter'
@@ -66,7 +66,7 @@ module Hatchet
# Returns a HatchetLogger for the object.
#
def logger
- @_hatchet_logger ||= HatchetLogger.new self, Hatchet.configuration
+ @_hatchet_logger ||= HatchetLogger.new(self, Hatchet.configuration, Hatchet::NestedDiagnosticContext.current)
end
# Public: Returns a HatchetLogger for the object.
View
16 lib/hatchet/hatchet_logger.rb
@@ -1,5 +1,7 @@
# -*- encoding: utf-8 -*-
+require 'logger'
+
module Hatchet
# Public: Class that handles logging calls and distributes them to all its
@@ -60,15 +62,21 @@ class HatchetLogger
Logger::FATAL => :fatal
}
+ # Public: Gets the NestedDiagnosticContext for the logger.
+ #
+ attr_reader :ndc
+
# Internal: Creates a new logger.
#
# host - The object the logger gains its context from.
# configuration - The configuration of Hatchet.
+ # ndc - The nested diagnostic context of the logger.
#
- def initialize(host, configuration)
- @context = context host
+ def initialize(host, configuration, ndc)
+ @context = host_name(host)
@configuration = configuration
@appenders = configuration.appenders
+ @ndc = ndc
end
[:debug, :info, :warn, :error, :fatal].each do |level|
@@ -103,7 +111,7 @@ def initialize(host, configuration)
#
define_method level do |message = nil, error = nil, &block|
return unless message or block
- add level, Message.new(message, error, &block)
+ add level, Message.new(ndc: @ndc.context.clone, message: message, error: error, &block)
end
# Public: Returns true if any of the appenders will log messages for the
@@ -193,7 +201,7 @@ def add(level, message)
# Ruby, the host itself when the host is a module, otherwise the object's
# class.
#
- def context(host)
+ def host_name(host)
if host.inspect == 'main'
'main'
elsif [Module, Class].include? host.class
View
55 lib/hatchet/message.rb
@@ -8,6 +8,9 @@ module Hatchet
# If an error is associated with the message this will be available via the
# #error attribute.
#
+ # The nested diagnostic context of the message will be availble via the #ndc
+ # attribute.
+ #
# Blocks will be lazily evaluated once for all appenders when required.
#
class Message
@@ -16,27 +19,61 @@ class Message
#
attr_reader :error
- # Internal: Creates a new message.
+ # Public: Gets the nested diagnostic context values.
+ #
+ attr_reader :ndc
+
+ # Public: Creates a new message.
+ #
+ # args - The Hash used to provide context for the message (default: {}):
+ # :ndc - An Array of nested diagnostic context values
+ # (default: []).
+ # :message - An already evaluated message, usually a String
+ # (default: nil).
+ # :error - An error that is associated with the message
+ # (default: nil).
+ # block - An optional block which will provide a message when invoked.
+ #
+ # Examples
+ #
+ # Message.new(ndc: [], message: "Evaluated message", error: e)
+ # Message.new(ndc: %w{Foo Bar}) { "Lazily evaluated message" }
+ #
+ # The signature of the constructor was originally:
#
# message - An already evaluated message, usually a String (default: nil).
# error - An error that is associated with the message (default: nil).
# block - An optional block which will provide a message when invoked.
#
- # One of message or block must be provided. If both are provided then the
- # block is preferred as it is assumed to provide more detail.
+ # This format is also supported for compatibility to version 0.1.0 and below
+ # and will be deprecated in the future.
#
# Examples
#
- # Message.new "Evaluated message"
+ # Message.new("Evaluated message", e)
# Message.new { "Lazily evaluated message" }
#
- def initialize(message = nil, error = nil, &block)
- @block = block
- @error = error
- @message = message unless @block
+ # One of message or block must be provided. If both are provided then the
+ # block is preferred as it is assumed to provide more detail.
+ #
+ def initialize(args = {}, error = nil, &block)
+ if args.kind_of? Hash
+ # If args is a Hash then using new constructor format or no parameters
+ # specified. Either way, use the new format.
+ @ndc = args[:ndc] || []
+ @error = args[:error]
+ @message = args[:message] unless block
+ else
+ # Otherwise assume the old format and coerce args accordingly.
+ @ndc = []
+ @error = error
+ @message = args unless block
+ end
+
+ @block = block
end
- # Internal: Returns the String representation of the message.
+ # Public: Returns the String representation of the message.
#
def to_s
@message ||= @block.call
View
34 lib/hatchet/middleware.rb
@@ -0,0 +1,34 @@
+module Hatchet
+
+ # Public: Middleware for making sure the nested diagnostic context is cleared
+ # between requests.
+ #
+ class Middleware
+ include Hatchet
+
+ # Public: Creates a new instance of the middleware, wrapping the given
+ # application.
+ #
+ # app - The application to wrap.
+ #
+ def initialize(app)
+ @app = app
+ end
+
+ # Public: Calls the wrapped application with the given environment, ensuring
+ # the nested diagnostic context is cleared afterwards.
+ #
+ # env - The enviroment Hash for the request.
+ #
+ # Returns the status, headers, body Array returned by the wrapped
+ # application.
+ #
+ def call(env)
+ @app.call(env)
+ ensure
+ log.ndc.clear!
+ end
+
+ end
+
+end
View
160 lib/hatchet/nested_diagnostic_context.rb
@@ -0,0 +1,160 @@
+module Hatchet
+
+ # Public: Class that manages the nested diagnostic context for a thread.
+ #
+ # All access to this class is performed through internal classes.
+ #
+ class NestedDiagnosticContext
+
+ # Internal: Gets the current context stack.
+ #
+ attr_reader :context
+
+ # Internal: Gets the NestedDiagnosticContext for the current thread, lazily
+ # initializing it as necessary.
+ #
+ def self.current
+ Thread.current[:hatchet_ndc] ||= NestedDiagnosticContext.new
+ end
+
+ # Internal: Creates a new instance of the class.
+ #
+ def initialize
+ clear!
+ end
+
+ # Public: Adds one or more messages onto the context stack.
+ #
+ # values - One or more messages to add to the context stack.
+ #
+ # Returns nothing.
+ #
+ def push(*values)
+ @context.push(*values)
+ end
+
+ # Public: Removes one or more message from the context stack.
+ #
+ # n - The number of messages to remove from the context stack (default:
+ # nil). If no number is provided then one message will be removed.
+ #
+ # Returns the message or messages removed from the context stack. If n was
+ # not specified it will return a single message, otherwise it will return an
+ # Array of up to n messages.
+ #
+ def pop(n = nil)
+ if n
+ @context.pop(n)
+ else
+ @context.pop
+ end
+ end
+
+ # Public: Adds one more or message onto the context stack for the scope of
+ # the given block.
+ #
+ # values - One or more messages to add to the context stack for the scope of
+ # the given block.
+ # block - The block to execute with the additional messages.
+ #
+ # Returns the result of calling the block.
+ #
+ def scope(*values, &block)
+ before = @context.clone
+ push(*values)
+ block.call
+ ensure
+ @context = before
+ end
+
+ # Public: Clears all messages from the context stack.
+ #
+ # Intend for use when the current thread is, or may, be reused in the future
+ # and the accumlated context is no longer wanted.
+ #
+ # Returns nothing.
+ #
+ def clear!
+ @context = ContextStack.new
+ nil
+ end
+
+ # Public: Class for holding the context stack of a NestedDiagnosticContext.
+ #
+ # Deliberately intended to have a similar API to Array to make testing
+ # easier.
+ #
+ class ContextStack
+
+ # Internal: Gets the internal stack.
+ #
+ attr_reader :stack
+
+ # Internal: Creates a new instance.
+ #
+ # stack - An Array of values to initialize the stack with (default: []).
+ #
+ def initialize(stack = [])
+ @stack = stack
+ end
+
+ # Public: Returns true if the stack contains any messages, otherwise
+ # returns false.
+ #
+ def any?
+ @stack.size != 0
+ end
+
+ # Internal: Returns a clone of the stack.
+ #
+ def clone
+ ContextStack.new(@stack.clone)
+ end
+
+ # Public: Returns a String created by converting each message of the stack
+ # to a String, separated by separator.
+ #
+ # separator - The String to separate the messages of the stack with
+ # (default: $,).
+ #
+ # Returns a String created by converting each message of the stack to a
+ # String, separated by separator.
+ #
+ def join(separator = $,)
+ @stack.join(separator)
+ end
+
+ # Internal: Pushes the given messages onto the stack.
+ #
+ # values - One or more messages to add to the context stack.
+ #
+ # Returns nothing.
+ #
+ def push(*values)
+ @stack.push(*values)
+ nil
+ end
+
+ # Internal: Removes one or more message from the stack.
+ #
+ # n - The number of messages to remove from the cstack (default: nil). If
+ # no number is provided then one message will be removed.
+ #
+ # Returns the message or messages removed from the context stack. If n was
+ # not specified it will return a single message, otherwise it will return
+ # an Array of up to n messages.
+ #
+ def pop(n = nil)
+ if n
+ @stack.pop(n)
+ else
+ @stack.pop
+ end
+ end
+
+ end
+
+ end
+
+end
+
View
7 lib/hatchet/railtie.rb
@@ -15,6 +15,13 @@ class Railtie < Rails::Railtie
#
self.config.hatchet = Hatchet.configuration
+ # Add the Hatchet::Middleware to the middleware stack to enable nested
+ # diagnostic context clearance between requests.
+ #
+ initializer "hatchet_railtie.insert_middleware" do |app|
+ app.config.middleware.use Hatchet::Middleware
+ end
+
# Wrap the default Rails.logger, Rails.application.assets.logger, and all
# log subscribers found in ActiveSupport::LogSubscriber.log_subscribers
# collection on initialization.
View
7 lib/hatchet/simple_formatter.rb
@@ -31,11 +31,12 @@ class SimpleFormatter
#
def format(level, context, message)
msg = message.to_s.strip
+ thread = thread_context ? "[#{thread_name}] - " : nil
- if thread_context
- msg = "[#{thread_name}] - #{level.to_s.upcase} - #{context} - #{msg}"
+ if message.ndc.any?
+ msg = "#{thread}#{level.to_s.upcase} - #{context} #{message.ndc.join(' ')} - #{msg}"
else
- msg = "#{level.to_s.upcase} - #{context} - #{msg}"
+ msg = "#{thread}#{level.to_s.upcase} - #{context} - #{msg}"
end
with_backtrace(message, msg)
View
10 lib/hatchet/standard_formatter.rb
@@ -12,6 +12,7 @@ class StandardFormatter
#
def initialize
@secs = 0
+ @level_cache = {}
end
# Public: Returns the formatted message.
@@ -29,7 +30,12 @@ def initialize
#
def format(level, context, message)
msg = message.to_s.strip
- msg = "#{timestamp} [#{thread_name}] #{format_level level} #{context} - #{msg}"
+
+ if message.ndc.any?
+ msg = "#{timestamp} [#{thread_name}] #{format_level(level)} #{context} #{message.ndc.join(' ')} - #{msg}"
+ else
+ msg = "#{timestamp} [#{thread_name}] #{format_level(level)} #{context} - #{msg}"
+ end
with_backtrace(message, msg)
end
@@ -58,7 +64,7 @@ def timestamp
# Private: Returns the level formatted for log output as a String.
#
def format_level(level)
- level.to_s.upcase.ljust(5)
+ @level_cache[level] ||= level.to_s.upcase.ljust(5)
end
end
View
2  lib/hatchet/version.rb
@@ -4,6 +4,6 @@ module Hatchet
# Public: The version of Hatchet.
#
- VERSION = '0.1.0'
+ VERSION = '0.2.0'
end
View
1  spec/helpers/storing_appender.rb
@@ -17,5 +17,6 @@ def initialize(default_level = nil)
def add(level, context, message)
@messages << OpenStruct.new(level: level, context: context, message: message)
end
+
end
View
84 spec/logger_spec.rb
@@ -8,9 +8,15 @@
let(:appenders) { [appender, disabled_appender] }
let(:configuration) { Configuration.new }
let(:context) { Context::Class.new }
+ let(:ndc) { NestedDiagnosticContext.new }
+
+ def last_message
+ appender.messages.last.message
+ end
+
let(:subject) do
configuration.appenders.push(*appenders)
- HatchetLogger.new context, configuration
+ HatchetLogger.new context, configuration, ndc
end
ALL_LEVELS.each do |level|
@@ -139,5 +145,81 @@
end
end
end
+
+ describe 'nested diagnostic context' do
+
+ describe 'pushing context' do
+
+ it 'passes the context with the message' do
+ subject.ndc.push(:foo)
+ subject.info 'Message'
+ assert_equal [:foo], last_message.ndc.stack
+ end
+
+ it 'stacks contexts with the message' do
+ subject.ndc.push(:foo, :bar, :baz)
+ subject.info 'Message'
+ assert_equal [:foo, :bar, :baz], last_message.ndc.stack
+ end
+
+ it 'pops contexts individually' do
+ subject.ndc.push(:foo, :bar, :baz)
+
+ subject.info 'Message'
+ assert_equal [:foo, :bar, :baz], last_message.ndc.stack
+
+ subject.ndc.pop
+ subject.info 'Message'
+ assert_equal [:foo, :bar], last_message.ndc.stack
+
+ subject.ndc.pop
+ subject.info 'Message'
+ assert_equal [:foo], last_message.ndc.stack
+
+ subject.ndc.pop
+ subject.info 'Message'
+ assert_equal [], last_message.ndc.stack
+ end
+
+ it 'pops a specified number of contexts' do
+ subject.ndc.push(:foo, :bar, :baz)
+
+ subject.info 'Message'
+ assert_equal [:foo, :bar, :baz], last_message.ndc.stack
+
+ subject.ndc.pop(2)
+ subject.info 'Message'
+ assert_equal [:foo], last_message.ndc.stack
+
+ subject.ndc.pop(2)
+ subject.info 'Message'
+ assert_equal [], last_message.ndc.stack
+ end
+
+ it 'scopes contexts when used with blocks' do
+ subject.ndc.scope(:foo) do
+ subject.info 'Message'
+ assert_equal [:foo], last_message.ndc.stack
+ end
+
+ subject.info 'Message'
+ assert_equal [], last_message.ndc.stack
+ end
+
+ it 'can clear all contexts' do
+ subject.ndc.push(:foo, :bar, :baz)
+
+ subject.info 'Message'
+ assert_equal [:foo, :bar, :baz], last_message.ndc.stack
+
+ subject.ndc.clear!
+
+ subject.info 'Message'
+ assert_equal [], last_message.ndc.stack
+ end
+
+ end
+
+ end
end
View
48 spec/message_spec.rb
@@ -4,7 +4,7 @@
describe Message do
describe 'providing an evaluted message' do
- let(:subject) { Message.new 'Evaluated' }
+ let(:subject) { Message.new(ndc: [], message: 'Evaluated') }
it 'returns the given message' do
assert_equal 'Evaluated', subject.to_s
@@ -14,7 +14,7 @@
describe 'providing a block message' do
let(:subject) do
@evaluated = 0
- Message.new do
+ Message.new(ndc: []) do
@evaluated += 1
'Block'
end
@@ -33,7 +33,7 @@
describe 'providing both an evaluated and block message' do
let(:subject) do
- Message.new 'Evaluated' do
+ Message.new(ndc: [], message: 'Evaluated') do
'Block'
end
end
@@ -42,5 +42,47 @@
assert_equal 'Block', subject.to_s
end
end
+
+ describe 'supporting the old constructor format' do
+ describe 'providing an evaluted message' do
+ let(:subject) { Message.new('Evaluated') }
+
+ it 'returns the given message' do
+ assert_equal 'Evaluated', subject.to_s
+ end
+ end
+
+ describe 'providing a block message' do
+ let(:subject) do
+ @evaluated = 0
+ Message.new do
+ @evaluated += 1
+ 'Block'
+ end
+ end
+
+ it 'returns the result of evaluating the block' do
+ assert_equal 'Block', subject.to_s
+ end
+
+ it 'only evaluates the block once for multiple calls' do
+ subject.to_s
+ subject.to_s
+ assert_equal 1, @evaluated
+ end
+ end
+
+ describe 'providing both an evaluated and block message' do
+ let(:subject) do
+ Message.new('Evaluated') do
+ 'Block'
+ end
+ end
+
+ it 'returns the result of evaluating the block' do
+ assert_equal 'Block', subject.to_s
+ end
+ end
+ end
end
View
115 spec/middleware_spec.rb
@@ -0,0 +1,115 @@
+require_relative 'spec_helper'
+
+describe Middleware do
+
+ class App
+ include Hatchet
+
+ def initialize
+ @request = 1
+ end
+
+ def call(env)
+ log.ndc.push(@request)
+
+ log.info "Start"
+
+ one = One.new
+ one.run(env)
+
+ log.ndc.push(:end)
+ log.info "Finish"
+
+ @request += 1
+
+ [:status, :headers, :body]
+ end
+
+ class One
+ include Hatchet
+
+ def run(env)
+ log.ndc.push(:one)
+ log.info env[:one]
+ end
+ end
+
+ end
+
+ let(:storing_appender) { StoringAppender.new :debug }
+ let(:messages) { storing_appender.messages }
+
+ let(:subject) do
+ Hatchet.configure do |config|
+ config.reset!
+ config.appenders << storing_appender
+ end
+
+ app = App.new
+ Middleware.new(app)
+ end
+
+ before do
+ messages.clear
+ end
+
+ describe "maintaining the result" do
+
+ before do
+ @status, @headers, @body = subject.call(one: 'Testing')
+ end
+
+ it "maintains the status" do
+ assert_equal :status, @status
+ end
+
+ it "maintains the headers" do
+ assert_equal :headers, @headers
+ end
+
+ it "maintains the body" do
+ assert_equal :body, @body
+ end
+
+ end
+
+ describe "accumulating context" do
+
+ before do
+ subject.call(one: 'Testing')
+ end
+
+ it "logs accumulating context" do
+ assert_equal "Start", messages[0].message.to_s
+ assert_equal [1], messages[0].message.ndc.stack
+
+ assert_equal 'Testing', messages[1].message.to_s
+ assert_equal [1, :one], messages[1].message.ndc.stack
+
+ assert_equal 'Finish', messages[2].message.to_s
+ assert_equal [1, :one, :end], messages[2].message.ndc.stack
+ end
+
+ end
+
+ describe "clearing context between requests" do
+
+ before do
+ subject.call(one: 'Testing')
+ subject.call(one: 'TestingAgain')
+ end
+
+ it "clears context from previous requests" do
+ assert_equal "Start", messages[3].message.to_s
+ assert_equal [2], messages[3].message.ndc.stack
+
+ assert_equal 'TestingAgain', messages[4].message.to_s
+ assert_equal [2, :one], messages[4].message.ndc.stack
+
+ assert_equal 'Finish', messages[5].message.to_s
+ assert_equal [2, :one, :end], messages[5].message.ndc.stack
+ end
+
+ end
+
+end
View
4 spec/plain_formatter_spec.rb
@@ -10,7 +10,7 @@
describe 'without an error' do
before do
- @message = Message.new(' Hello, World ')
+ @message = Message.new(ndc: [], message: ' Hello, World ')
end
it 'outputs the message in the MESSAGE format' do
@@ -24,7 +24,7 @@
before do
error = OpenStruct.new(message: 'Boom!', backtrace: ['foo.rb:1:a', 'foo.rb:20:b'])
- @message = Message.new(' Hello, World ', error)
+ @message = Message.new(ndc: [], message: ' Hello, World ', error: error)
end
describe 'with backtraces enabled' do
View
19 spec/simple_formatter_spec.rb
@@ -10,7 +10,7 @@
describe 'without an error' do
before do
- @message = Message.new(' Hello, World ')
+ @message = Message.new(ndc: [], message: ' Hello, World ')
end
it 'outputs the message in the LEVEL - CONTEXT - MESSAGE format' do
@@ -24,7 +24,7 @@
before do
error = OpenStruct.new(message: 'Boom!', backtrace: ['foo.rb:1:a', 'foo.rb:20:b'])
- @message = Message.new(' Hello, World ', error)
+ @message = Message.new(ndc: [], message: ' Hello, World ', error: error)
end
describe 'with backtraces enabled' do
@@ -57,7 +57,7 @@
before do
subject.thread_context = true
- @message = Message.new(' Hello, World ')
+ @message = Message.new(ndc: [], message: ' Hello, World ')
end
it 'outputs the message in the [THREAD] - LEVEL - CONTEXT - MESSAGE format' do
@@ -67,6 +67,19 @@
end
+ describe 'with ndc' do
+
+ before do
+ @message = Message.new(ndc: [:foo, 123], message: ' Hello, World ')
+ end
+
+ it 'outputs the message in the [THREAD] - LEVEL - CONTEXT NDC - MESSAGE format' do
+ message = subject.format(:info, 'Custom::Context', @message)
+ assert "INFO - Custom::Context foo 123 - Hello, World" == message, "got #{message}"
+ end
+
+ end
+
end
end
View
10 spec/standard_formatter_spec.rb
@@ -10,7 +10,8 @@
describe 'when formatting a message' do
before do
- @message = Message.new('Hello, World')
+ ndc = NestedDiagnosticContext::ContextStack.new([:foo, 12])
+ @message = Message.new(ndc: ndc, message: 'Hello, World')
@context = 'Custom::Context'
@level = :info
@formatted_message = subject.format(@level, @context, @message)
@@ -37,7 +38,7 @@
end
it 'formats the message after the time as expected' do
- expected = "[#{Process.pid}] #{@level.to_s.upcase.ljust 5} #{@context} - #{@message}"
+ expected = "[#{Process.pid}] #{@level.to_s.upcase.ljust 5} #{@context} foo 12 - #{@message}"
actual_without_time = @formatted_message[24..-1]
assert_equal expected, actual_without_time
@@ -58,7 +59,7 @@
before do
error = OpenStruct.new(message: 'Boom!', backtrace: ['foo.rb:1:a', 'foo.rb:20:b'])
- @message = Message.new(' Hello, World ', error)
+ @message = Message.new(ndc: [], message: ' Hello, World ', error: error)
end
describe 'with backtraces enabled' do
@@ -98,7 +99,8 @@
end
took = Time.now - start
- limit = 0.4
+ limit = 0.6
+ puts "\nMessages took #{took} to generate\n"
assert took < limit, "Expected messages to take less than #{limit} but took #{took}"
end
end
Something went wrong with that request. Please try again.