README.md in semantic_logger-0.3.3 vs README.md in semantic_logger-0.4.0

- old
+ new

@@ -1,15 +1,13 @@ semantic-logger-ruby ==================== * http://github.com/ClarityServices/semantic-logger-ruby -Feedback is welcome and appreciated :) - ### Introduction -SemanticLogger is a Logger that supports logging of meta-data, not only text messages +SemanticLogger is a Logger that supports logging of meta-data, along with text messages Machines can understand the logged data without having to use complex Regular Expressions or other text parsing techniques SemanticLogger, sits on top of existing logger implementations and can also @@ -34,44 +32,370 @@ :duration => duration, :result => result, :table => "users", :action => "query") -Using this semantic example, a machine can easily find all queries for table -'users' that took longer than 100 ms. +Using the MongoDB appender, we can easily find all queries for table 'users' +that took longer than 100 ms: - db.logs.find({"metadata.table":"users", "metadata.action":"query"}) + db.logs.find({"payload.table":"users", "payload.action":"query", "payload.duration":{$gt:100} }) Since SemanticLogger can call existing Loggers, it does not force end-users to have to adopt a Semantic aware adapter. Although, such adapters create tremendous value in the problem monitoring and determination processes. -For ease of use each Appender can be used directly if required. It is preferred -however to use the SemanticLogger interface and supply the configuration to it. -In this way the adapter can be changed without modifying the application -source code. +### Logging API -# Future -- Web Interface to view and search log information -- Override the log level at the appender level +#### Standard Logging methods -# Configuration +The Semantic Logger logging API supports the existing logging interface for +the Rails and Ruby Loggers. For example: + logger.info("Hello World") + +Or to query whether a specific log level is set + + logger.info? + +The following logging methods are all available + + logger.trace(message, payload) { # optional block } + logger.debug(message, payload) { # optional block } + logger.info(message, payload) { # optional block } + logger.warn(message, payload) { # optional block } + logger.error(message, payload) { # optional block } + logger.fatal(message, payload) { # optional block } + +Parameters + +- message: The text message to log. + Mandatory only if no block is supplied +- payload: Optional, either a Ruby Exception object or a Hash +- block: The optional block is executed only if the corresponding log level + is active. Can be used to prevent unnecessary calculations of debug data in + production. + +Examples: + + logger.debug("Calling Supplier") + + logger.debug("Calling Supplier", :request => 'update', :user => 'Jack') + + logger.debug { "A total of #{result.inject(0) {|sum, i| i+sum }} were processed" } + +### Exceptions + +The Semantic Logger adds an extra parameter to the existing log methods so that +a corresponding Exception can be logged in a standard way + + begin + # ... Code that can raise an exception + rescue Exception => exception + logger.error("Oops external call failed", exception) + # Re-raise or handle the exception + raise exception + end + + +#### Payload + +The Semantic Logger adds an extra parameter to the existing log methods so that +additional payload can be logged, such as a Hash or a Ruby Exception object. + + logger.info("Oops external call failed", :result => :failed, :reason_code => -10) + +The additional payload is machine readable so that we don't have to write complex +regular expressions so that a program can analyze log output. With the MongoDB +appender the payload is written directly to MongoDB as part of the document and +is therefore fully searchable + +#### Benchmarking + +Another common logging requirement is to measure the time it takes to execute a block +of code based on the log level. For example: + + Rails.logger.benchmark_info "Calling external interface" do + # Code to call external service ... + end + +The following output will be written to file: + + 2012-08-30 15:37:29.474 I [48308:ScriptThreadProcess: script/rails] Rails -- Calling external interface (5.2ms) + +If an exception is raised during the block the exception is logged +at the same log level as the benchmark along with the duration and message + +#### Logging levels + +The following logging levels are available through Semantic Logger + + :trace, :debug, :info, :warn, :error, :fatal + +The log levels are listed above in the order of precedence with the most detail to the least. +For example :debug would include :info, :warn, :error, :fatal levels but not :trace +And :fatal would only log :fatal error messages and nothing else + +:unknown has been mapped to :fatal for Rails and Ruby Logger + +:trace is a new level that is often used for tracing low level calls such +as the data sent or received to external web services. It is also commonly used +in the development environment for low level trace logging of methods calls etc. + +If only the rails logger is being used, then :trace level calls will be logged +as debug calls only if the log level is set to trace + +#### Changing the Class name for Log Entries + +When Semantic Logger is included on a Rails project it automatically replaces the +loggers for Rails, ActiveRecord::Base, ActionController::Base, and ActiveResource::Base +with wrappers that set their Class name. For example in railtie.rb: + + ActiveRecord::Base.logger = SemanticLogger::Logger.new(ActiveRecord) + +By replacing their loggers we now get the class name in the text logging output: + + 2012-08-30 15:24:13.439 D [47900:main] ActiveRecord -- SQL (12.0ms) SELECT `schema_migrations`.`version` FROM `schema_migrations` + +It is recommended to include a class specific logger for all major classes that will +be logging. For Example: + + class ExternalSupplier + # Gem sync_attr is a dependency of semantic_logger so is already installed + include SyncAttr + + # Lazy initializes the class logger on it's first call in a thread-safe way + sync_cattr_reader :logger do + SemanticLogger::Logger.new(self) + end + + def call(params) + self.class.logger.benchmark_info "Calling external interface" do + # Code to call external service ... + end + end + end + +This will result in the log output identitying the log entry as from the ExternalSupplier class + + 2012-08-30 15:37:29.474 I [48308:ScriptThreadProcess: script/rails] ExternalSupplier -- Calling external interface (5.2ms) + +#### Tagged Logging + + logger.with_tags(tracking_number) do + logger.debug("Hello World") + # ... + end + +#### Payload injected logging + + logger.with_payload(:user => 'Jack') do + logger.debug("Hello World") + # ... + end + +### Configuration + The Semantic Logger follows the principle where multiple appenders can be active at the same time. This allows one to log to MongoDB and the Rails ActiveResource::BufferedLogger at the same time. +#### Rails Configuration + +Add the following line to Gemfile + + gem 'semantic_logger' + +Also add the following line to Gemfile if you want to log to MongoDB + + gem 'mongo' + +Install required gems with bundler + + bundle install + +This will automatically replace the standard Rails logger with Semantic Logger +which will write all log data to the configured Rails logger. + +By default Semantic Logger will detect the log level from Rails. To set the +log level explicitly, add the following line to +config/environments/production.rb inside the Application.configure block + + config.log_level = :trace + +To log to both the Rails logger and MongoDB add the following lines to +config/environments/production.rb inside the Application.configure block + + config.after_initialize do + # Re-use the existing MongoDB connection, or create a new one here + db = Mongo::Connection.new['production_logging'] + + # Besides logging to the standard Rails logger, also log to MongoDB + config.semantic_logger.appenders << SemanticLogger::Appender::MongoDB.new( + :db => db, + :collection_size => 25.gigabytes + ) + end + +#### Custom Formatters + +The formatting for each appender can be replaced with custom code. To replace the +existing formatter supply a block of code when creating the appender. + +For example to replace the Rails or Ruby text log formatter, in the environment configuration file: + + config.after_initialize do + # Since the Rails logger is already initialized, replace its default formatter + config.semantic_logger.appenders.first.formatter = Proc.new do |log| + # log is a struct with the following fields: + # + # level + # Log level of the supplied log call + # :trace, :debug, :info, :warn, :error, :fatal + # + # thread_name + # Name of the thread in which the logging call was called + # + # name + # Class name supplied to the logging instance + # + # message + # Text message to be logged + # + # payload + # Optional Hash or Ruby Exception object to be logged + # + # time + # The time at which the log entry was created + # + # duration + # The time taken to complete a benchmark call + # + # tags + # Any tags active on the thread when the log call was made + # + + message = log.message.to_s + tags = log.tags.collect { |tag| "[#{tag}]" }.join(" ") + " " if log.tags && (log.tags.size > 0) + + if log.payload + if log.payload.is_a?(Exception) + exception = log.payload + message << " -- " << "#{exception.class}: #{exception.message}\n#{(exception.backtrace || []).join("\n")}" + else + message << " -- " << log.payload.inspect + end + end + + str = "#{log.time.strftime("%Y-%m-%d %H:%M:%S")}.#{"%03d" % (log.time.usec/1000)} #{log.level.to_s[0..0].upcase} [#{$$}:#{log.thread_name}] #{tags}#{log.name} -- #{message}" + str << " (#{'%.1f' % log.duration}ms)" if log.duration + str + end + end + +For example to replace the MongoDB formatter, in the environment configuration file: + + config.after_initialize do + # Log to MongoDB and supply a custom document formatter + mongodb_appender = SemanticLogger::Appender::MongoDB.new( + :db => Cache::Work.db, + :collection_size => 25.gigabytes + ) do |log| + # log is a struct with the following fields: + # level + # Log level of the supplied log call + # :trace, :debug, :info, :warn, :error, :fatal + # + # thread_name + # Name of the thread in which the logging call was called + # + # name + # Class name supplied to the logging instance + # + # message + # Text message to be logged + # + # payload + # Optional Hash or Ruby Exception object to be logged + # + # time + # The time at which the log entry was created + # + # duration + # The time taken to complete a benchmark call + # + # tags + # Any tags active on the thread when the log call was made + # + + # Return a document (Hash) of the data to be saved to MongoDB + document = { + :time => log.time, + :host_name => SemanticLogger::Appender::MongoDB.host_name, + :pid => $PID, + :thread_name => log.thread_name, + :name => log.name, + :level => log.level, + } + document[:application] = 'MyApplication' + document[:message] = SemanticLogger::Appender::MongoDB.strip_colorizing(log.message) if log.message + document[:duration] = log.duration if log.duration + document[:tags] = log.tags if log.tags && (log.tags.size > 0) + + if log.payload + if log.payload.is_a?(Exception) + exception = log.payload + document[:payload] = { + :exception => exception.class.name, + :message => exception.message, + :backtrace => exception.backtrace + } + else + document[:payload] = log.payload + end + end + document + end + config.semantic_logger.appenders << mongodb_appender + end + +### Architecture & Performance + +In order to ensure that logging does not hinder the performance of the application +all log entries are written to thread-safe Queue. A separate thread is responsible +for writing the log entries to each of the appenders. + +In this way formatting and disk or network write delays will not affect the +performance of the application. Also adding more than one appender does not affect +the runtime performance of the application + +The additional thread is automatically started on initialization. When the program +terminates it will complete writing out all log data and flush the appenders before +the program exits. + +Calling SemanticLogger::Logger#flush will wait until all outstanding log messages +have been written and flushed to their respective appenders before returning. +Since all logging is now from this thread calling flush is no longer thread +specific. + ### Dependencies - Ruby MRI 1.8.7 (or above) Or, JRuby 1.6.3 (or above) - Optional: Rails 3.0.10 (or above) - Optional: To log to MongoDB, Mongo Ruby Driver 1.5.2 or above ### Install - gem install semantic-logger + gem install semantic-logger +To log to MongoDB + + gem install mongo + +### Future + +- Web Interface to view and search log information stored in MongoDB + Development ----------- Want to contribute to Semantic Logger? @@ -91,12 +415,9 @@ 1. [Fork](http://help.github.com/forking/) semantic-logger 2. Create a topic branch - `git checkout -b my_branch` 3. Push to your branch - `git push origin my_branch` 4. Create an [Issue](http://github.com/ClarityServices/semantic-logger/issues) with a link to your branch 5. That's it! - -We are looking for volunteers to create implementations in other languages such as: -* Java, C# and Go Meta ---- * Code: `git clone git://github.com/ClarityServices/semantic-logger.git`