Exceptionally verbose logging on `rake db:migrate`

[seddy]

When running rake db:migrate on revieworld or filler, I get the following output once migrations have run:

2016-12-12 15:57:47.678091 D [36137:70318572313540 log_subscriber.rb:93] (1.080ms) Sapience::Extensions::ActiveRecord::LogSubscriber -- { :sql => "SELECT fk.referenced_table_name as 'to_table'\n ,fk.referenced_column_name as 'primary_key'\n ,fk.column_name as 'column'\n ,fk.constraint_name as 'name'\nFROM information_schema.key_column_usage fk\nWHERE fk.referenced_column_name is not null\n AND fk.table_schema = 'revieworld_live'\n AND fk.table_name = 'vetting_sessions'\n", :name => nil, :connection_id => 70318636601720, :statement_name => nil, :binds => [], :tags => [ "request" ] }
2016-12-12 15:57:47.679205 D [36137:70318572313540 log_subscriber.rb:93] Rails --    (0.8ms)  SHOW CREATE TABLE `vetting_sessions`
2016-12-12 15:57:47.679369 D [36137:70318572313540 log_subscriber.rb:93] (1.080ms) Sapience::Extensions::ActiveRecord::LogSubscriber -- { :sql => "SHOW CREATE TABLE `vetting_sessions`", :name => nil, :connection_id => 70318636601720, :statement_name => nil, :binds => [], :tags => [ "request" ] }
2016-12-12 15:57:47.683208 D [36137:70318572313540 log_subscriber.rb:93] Rails --    (2.3ms)  SELECT fk.referenced_table_name as 'to_table'
      ,fk.referenced_column_name as 'primary_key'
      ,fk.column_name as 'column'
      ,fk.constraint_name as 'name'
FROM information_schema.key_column_usage fk
WHERE fk.referenced_column_name is not null
  AND fk.table_schema = 'revieworld_live'
  AND fk.table_name = 'video_click_throughs'

2016-12-12 15:57:47.683744 D [36137:70318572313540 log_subscriber.rb:93] (3.080ms) Sapience::Extensions::ActiveRecord::LogSubscriber -- { :sql => "SELECT fk.referenced_table_name as 'to_table'\n ,fk.referenced_column_name as 'primary_key'\n ,fk.column_name as 'column'\n ,fk.constraint_name as 'name'\nFROM information_schema.key_column_usage fk\nWHERE fk.referenced_column_name is not null\n AND fk.table_schema = 'revieworld_live'\n AND fk.table_name = 'video_click_throughs'\n", :name => nil, :connection_id => 70318636601720, :statement_name => nil, :binds => [], :tags => [ "request" ] }
2016-12-12 15:57:47.689773 D [36137:70318572313540 log_subscriber.rb:93] Rails --    (4.7ms)  SHOW CREATE TABLE `video_click_throughs`
2016-12-12 15:57:47.690079 D [36137:70318572313540 log_subscriber.rb:93] (5.230ms) Sapience::Extensions::ActiveRecord::LogSubscriber -- { :sql => "SHOW CREATE TABLE `video_click_throughs`", :name => nil, :connection_id => 70318636601720, :statement_name => nil, :binds => [], :tags => [ "request" ] }
2016-12-12 15:57:47.693305 D [36137:70318572313540 log_subscriber.rb:93] Rails --    (2.4ms)  SELECT fk.referenced_table_name as 'to_table'
      ,fk.referenced_column_name as 'primary_key'
      ,fk.column_name as 'column'
      ,fk.constraint_name as 'name'
FROM information_schema.key_column_usage fk
WHERE fk.referenced_column_name is not null
  AND fk.table_schema = 'revieworld_live'
  AND fk.table_name = 'vouchers'

There are over 3000 lines of this unnecessary logging, meaning you effectively lose any logging from your migrations as it may have gone out of your terminal history (if you don't have unlimited scroll on; realistically it just means scrolling up a hell of a lot). I realise we're just hooking into Notifications (or something like that... don't know Sapience too well), but it would be good if we could filter it out (as would normally happen when running a rake task!)

[mhenrixon]

The problem seems to be that we are attaching another subscriber.

[5.0.1@2.3.1] 0:(Sapience::Rails::Engine) > ActiveRecord::LogSubscriber.subscribers
=> [#<ActionController::LogSubscriber:0x007fe69c2f2c10
  @patterns=
   ["logger.action_controller",
    "send_file.action_controller",
    "start_processing.action_controller",
    "process_action.action_controller",
    "halted_callback.action_controller",
    "redirect_to.action_controller",
    "send_data.action_controller",
    "unpermitted_parameters.action_controller",
    "write_fragment.action_controller",
    "read_fragment.action_controller",
    "exist_fragment?.action_controller",
    "expire_fragment.action_controller",
    "expire_page.action_controller",
    "write_page.action_controller"],
  @queue_key="ActionController::LogSubscriber-70314219771400">,
 #<ActionView::LogSubscriber:0x007fe69bc1b1a8 @patterns=["logger.action_view", "render_template.action_view", "render_partial.action_view", "render_collection.action_view"], @queue_key="ActionView::LogSubscriber-70314216184020", @root=nil>,
 #<ActiveRecord::LogSubscriber:0x007fe69bb3b328 @odd=false, @patterns=["sql.active_record", "render_bind.active_record"], @queue_key="ActiveRecord::LogSubscriber-70314215725460">,
 #<ActiveModelSerializers::Logging::LogSubscriber:0x007fe69b436960 @patterns=["logger.active_model_serializers", "render.active_model_serializers"], @queue_key="ActiveModelSerializers::Logging::LogSubscriber-70314212046000">,
 #<ActiveJob::Logging::LogSubscriber:0x007fe69be52598 @patterns=["perform.active_job", "enqueue.active_job", "enqueue_at.active_job", "perform_start.active_job"], @queue_key="ActiveJob::Logging::LogSubscriber-70314217345740">,
 #<Sapience::Extensions::ActionController::LogSubscriber:0x007fe69be50f90
  @patterns=["orig_start_processing.action_controller", "start_processing.action_controller", "orig_process_action.action_controller", "process_action.action_controller"],
  @queue_key="Sapience::Extensions::ActionController::LogSubscriber-70314217342920">,
 #<Sapience::Extensions::ActiveRecord::LogSubscriber:0x007fe69be50400 @odd=false, @patterns=["sql.active_record", "identity.active_record"], @queue_key="Sapience::Extensions::ActiveRecord::LogSubscriber-70314217341440">]

As is visible above there is a second subscriber which not only adds overhead because some of them are processed multiple times. It also has a different patterns/keys.

@amalkov I think we need to override the current implementation rather than create another subscriber.

[mhenrixon]

On the other hand: Rails 5 does not have this problem in the test app.

[mhenrixon]

@seddy can you clarify where and when it happens? I can't replicate this behaviour at least not for filler.

[jelamo]

We have a code change to fix this, will be merge to master at some point today.

[jelamo]

fixed on release v2.0.3

[seddy]

Yay, thanks @jelamo 😸 !