Rails Source Parsing Log Notification/subscribe

My habit of debugging rails code is to look at the logs while looking at the code, and through the logs you can see each of the rails ' operations on the DB. This is quite simple in web development, and only in a few cases use pry or debugger to debug the code. One can look directly at the log to see the logic you write code execution, such as when you execute the INSERT statement, you can probably guess that the Model.create method should be called. This is a convenient way to read the log directly. But the default rails is to display all of the SQL in the log, in fact, we are only concerned about the Insert/update/delete statement, as for the select is basically not too concerned about. But once the project logic is complex, and a request has hundreds of SQL, it is not easy to find insert/update/delete. So a gem was created to highlight the Insert/update/delete statement. Feel good about yourself and be able to find it on GitHub (https://github.com/xumc/simple-debug-for-rails/tree/v1.0.0). At present, it is relatively humble, and then gradually perfected. See figure:

The gem thing is not a table, the following is about the log related code in rails. This is also to write this gem to see this part of the code.

Relevant RB files related to log such as:

Rails caicai$ tree-c-f|grep "Subscribe\|notifications"
│││├──./actionmailer/lib/action_mailer/log_subscriber.rb
│├──./actionmailer/test/log_subscriber_test.rb
│││├──./actionpack/lib/action_controller/log_subscriber.rb
││├──./actionpack/test/controller/log_subscriber_test.rb
│││├──./actionview/lib/action_view/log_subscriber.rb
││├──./actionview/test/template/log_subscriber_test.rb
│││├──./activerecord/lib/active_record/explain_subscriber.rb
│││├──./activerecord/lib/active_record/log_subscriber.rb
││├──./activerecord/test/cases/explain_subscriber_test.rb
││├──./activerecord/test/cases/log_subscriber_test.rb
││├──./activerecord/test/fixtures/subscribers.yml
││├──./activerecord/test/models/subscriber.rb
│││├──./activesupport/lib/active_support/log_subscriber
││││└──./activesupport/lib/active_support/log_subscriber/test_helper.rb
│││├──./activesupport/lib/active_support/log_subscriber.rb
│││├──./activesupport/lib/active_support/notifications
││││├──./activesupport/lib/active_support/notifications/fanout.rb
││││└──./activesupport/lib/active_support/notifications/instrumenter.rb
│││├──./activesupport/lib/active_support/notifications.rb
│││├──./activesupport/lib/active_support/subscriber.rb
│├──./activesupport/test/log_subscriber_test.rb
│├──./activesupport/test/notifications
││├──./activesupport/test/notifications/evented_notification_test.rb
││└──./activesupport/test/notifications/instrumenter_test.rb
│├──./activesupport/test/notifications_test.rb
│├──./activesupport/test/subscriber_test.rb
│││└──./railties/test/application/initializers/notifications_test.rb

It is clear that rails uses the Pub/sub method to log logs. Similar to the meaning of Message Queuing. For example, SQL events are generated when SQL is executed, and log subscribers are able to accept these SQL events and log the relevant information to log. This avoids the direct writing of Logger.debug/info/error in the code. Decouple the log from the other components. From the file tree above, you can see that each of the major components of rails has a log_subscriber.rb file. The code inside is the code that captures the event generated inside the component and writes the event information to the log file.

Take/ACTIVERECORD/LIB/ACTIVE_RECORD/LOG_SUBSCRIBER.RB as an example:

Module ActiveRecord class Logsubscriber < Activesupport::logsubscriber ignore_payload_names = ["SCHEMA", "EXPLAIN"] def self.runtime= (value) Activerecord::runtimeregistry.sql_runtime = value End def self.runtime Active Record::runtimeregistry.sql_runtime | | = 0 End def self.reset_runtime rt, self.runtime = runtime, 0 RT End Def Initialize Super @          Odd = False End Def render_bind (column, value) if column if Column.binary?          # This specifically deals with the PG adapter it casts Bytea columns into a Hash. Value = Value[:value] If value.is_a? (Hash) value = value?      "<#{value.bytesize} bytes of binary data>": "<null binary data>" End [Column.name, value] else [nil, value] end end DEF SQL (event) Self.class.runtime + = event.duration return unless Lo      Gger.debug? Payload = Event.payload return if ignore_payload_names.include? (PayLoad[:name]) name = "#{payload[:name"} (#{event.duration.round (1)}ms) "sql = Payload[:sql] binds = nil Unless (Payload[:binds] | |        []). Empty?          Binds = "" + Payload[:binds].map {|col,v|        Render_bind (col, v)}.inspect End if odd?      name = Color (name, CYAN, true) sql = color (sql, nil, true) Else name = Color (name, MAGENTA, True)      End Debug "#{name} #{sql}#{binds}" End Def odd? @odd = [email protected] End def logger Activerecord::base.logger end Endendactiverecord::logsubscribe R.attach_to:active_record

This class inherits from the Activesupport::logsubscriber class, which is linked to the above file structure and can be guessed Activesupport:: Logsubscriber should be the base class for logsubscriber in the rails ' large components. The main function of this class in Active_record SQL (event) converts the information in the event Chengwei log text calls debug mode into log. The last sentence of the document uses attach_to meaning to use this class to listen for events generated by Active_record.

Let's look at the Activesupport::logsubscriber class:

Module Activesupport Class Logsubscriber < subscriber # Embed in a String to clear all previous ANSI sequences. CLEAR = "\e[0m" BOLD = "\e[1m" # Colors BLACK = "\e[30m" RED = "\e[31m" GREEN = "\e[32m" YE  Llow = "\e[33m" BLUE = "\e[34m" MAGENTA = "\e[35m" CYAN = "\e[36m" white = "\e[37m" Mattr_accessor : colorize_logging self.colorize_logging = True class << self def Logger @logger | | = if defined? (Rails) && rails.respond_to?          (: Logger) Rails.logger End END Attr_writer:logger def log_subscribers subscribers end # Flus      H all log_subscribers ' logger.        def flush_all! Logger.flush if logger.respond_to? (: Flush) END End Def logger Logsubscriber.logger end def start (name, ID, payload) Super if Logg ER end def finish (name, ID, payload) Super if logger rescue Exception = e logger.error "Could not L og #{name.inspect} event.      #{e.class}: #{e.message} #{e.backtrace} "end protected%w (Info debug warn error fatal unknown). Each do |level| Class_eval <<-method, __file__, __line__ + 1 def #{level} (progname = nil, &block) Logger.#{lev El} (Progname, &block) If Logger end METHOD End # Set color by using a string or one of the defined C Onstants. If A third # option is set to +true+, it also adds bold to the string. This was based # on the Highline implementation and would automatically append CLEAR to the # end of the returned Stri    Ng. def color (text, color, bold=false) return text unless colorize_logging color = Self.class.const_get (color.upcase ) If color.is_a? (Symbol) Bold = bold? BOLD: "" "#{bold}#{color}#{text}#{clear}" end EndEnd

The method is also a good auxiliary method, this is the class and inherit from the Subscribe class, here is very obvious, this subscribe class should write a pub/sub mechanism of some methods, not just the log mechanism to use. Open to see:

Module Activesupport # Activesupport::subscriber is a object set to consume # Activesupport::notifications.  The Subscriber dispatches notifications to # A registered object based on its given namespace. # An example would is Active Record subscriber responsible for collecting # statistics about queries: # # Module A Ctiverecord # class Statssubscriber < Activesupport::subscriber # def SQL (event) # statsd.timing ("    Sql.#{event.payload[:name]} ", event.duration) # end # end # end # # and it ' s finally registered as: # # Activerecord::statssubscriber.attach_to:active_record # Since We need to know all instance methods before Attachin  G The log # Subscriber, the line above should is called after your subscriber definition. # # After configured, whenever a ' Sql.active_record ' notification is published, # It'll properly dispatch the event (a  Ctivesupport::notifications::event) to # The +sql+ method. Class Subscriber Class << Self # Attach the Subscriber to a namespace. Def attach_to (namespace, subscriber=new, notifier=activesupport::notifications) @namespace = namespace @sub Scriber = Subscriber @notifier = notifier subscribers << Subscriber # ADD event subscribers F        or all existing methods on the class.          Subscriber.public_methods (FALSE). Each do |event|      Add_event_subscriber (event) end End # Adds event subscribers for all new methods added to the class. def method_added (event) # Only public methods is added as subscribers, and only if a notifier # have been Set up.        This means, subscribers would only is set up to # classes that call #attach_to. If public_method_defined? (event) && notifier add_event_subscriber (event) end End Def subscribers @ @subscri bers | | = [] End protected Attr_reader:subscriber,: Notifier,: Namespace def Add_event_subscriber (event) return if%w{start finish}.include? (event.to_s) pattern = "#{event}.#{namespace}" # don ' t add multiple subscribers (eg. if methods are redefine D) return if Subscriber.patterns.include? (pattern) Subscriber.patterns << pattern notifier.subscribe (pattern, subscriber) end end at Tr_reader:p atterns #: Nodoc:def Initialize @queue_key = [Self.class.name, Object_id].join "-" @patterns =  [] Super End def start (name, ID, payload) e = activesupport::notifications::event.new (name, Time.now, Nil, ID, payload) parent = Event_stack.last Parent << e If parent Event_stack.push e end def finish (Name, ID, payload) finished = Time.now Event = Event_stack.pop Event.end = finished Event.payloa d.merge! (payload) method = Name.split ('. '). First Send (method, event) End private Def event_stack SubscriberqueueregistrY.instance.get_queue (@queue_key) End END # This was a registry for all the event stacks kept for subscribers.  # See the documentation of <tt>activesupport::P erthreadregistry</tt> # for further details. Class Subscriberqueueregistry #: Nodoc:extend perthreadregistry def Initialize @registry = {} End def ge T_queue (Queue_key) @registry [Queue_key] | | = [] End EndEnd

It's not hard to understand. Is the definition of public behavior.

Rails Source Parsing Log Notification/subscribe