diff --git a/lib/safe-pg-migrations/base.rb b/lib/safe-pg-migrations/base.rb index 823cc71..75c13ee 100644 --- a/lib/safe-pg-migrations/base.rb +++ b/lib/safe-pg-migrations/base.rb @@ -1,6 +1,7 @@ # frozen_string_literal: true require 'safe-pg-migrations/configuration' +require 'safe-pg-migrations/helpers/logger' require 'safe-pg-migrations/helpers/satisfied_helper' require 'safe-pg-migrations/helpers/index_helper' require 'safe-pg-migrations/helpers/batch_over' @@ -31,15 +32,27 @@ class << self def setup_and_teardown(migration, connection, &block) @pg_version_num = get_pg_version_num(connection) @alternate_connection = nil - @current_migration = migration - stdout_sql_logger = VerboseSqlLogger.new.setup if verbose? - PLUGINS.each { |plugin| connection.extend(plugin) } - connection.with_setting :lock_timeout, SafePgMigrations.config.pg_lock_timeout, &block + with_current_migration(migration) do + stdout_sql_logger = VerboseSqlLogger.new.setup if verbose? + + VerboseSqlLogger.new.setup if verbose? + PLUGINS.each { |plugin| connection.extend(plugin) } + + connection.with_setting :lock_timeout, SafePgMigrations.config.pg_lock_timeout, &block + ensure + stdout_sql_logger&.teardown + end ensure close_alternate_connection + end + + def with_current_migration(migration, &block) + @current_migration = migration + + yield block + ensure @current_migration = nil - stdout_sql_logger&.teardown end def alternate_connection @@ -53,16 +66,6 @@ def close_alternate_connection @alternate_connection = nil end - ruby2_keywords def say(*args) - return unless current_migration - - current_migration.say(*args) - end - - ruby2_keywords def say_method_call(method, *args) - say "#{method}(#{args.map(&:inspect) * ', '})", true - end - def verbose? unless current_migration.class._safe_pg_migrations_verbose.nil? return current_migration.class._safe_pg_migrations_verbose @@ -98,8 +101,11 @@ def exec_migration(connection, direction) end def disable_ddl_transaction - UselessStatementsLogger.warn_useless '`disable_ddl_transaction`' if super - true + SafePgMigrations.with_current_migration(self) do + UselessStatementsLogger.warn_useless '`disable_ddl_transaction`' if super + + true + end end SAFE_METHODS = %i[ diff --git a/lib/safe-pg-migrations/helpers/blocking_activity_formatter.rb b/lib/safe-pg-migrations/helpers/blocking_activity_formatter.rb index 8148f23..f4470d6 100644 --- a/lib/safe-pg-migrations/helpers/blocking_activity_formatter.rb +++ b/lib/safe-pg-migrations/helpers/blocking_activity_formatter.rb @@ -5,20 +5,20 @@ module Helpers module BlockingActivityFormatter def log_queries(queries) if queries.empty? - SafePgMigrations.say 'Could not find any blocking query.', true + Logger.say 'Could not find any blocking query.', sub_item: true else - SafePgMigrations.say( - "Statement was being blocked by the following #{'query'.pluralize(queries.size)}:", - true - ) - SafePgMigrations.say '', true + Logger.say <<~MESSAGE.rstrip, sub_item: true + Statement was being blocked by the following #{'query'.pluralize(queries.size)}: + MESSAGE + + Logger.say '', sub_item: true output_blocking_queries(queries) - SafePgMigrations.say( - 'Beware, some of those queries might run in a transaction. In this case the locking query might be ' \ - 'located elsewhere in the transaction', - true - ) - SafePgMigrations.say '', true + Logger.say <<~MESSAGE, sub_item: true + Beware, some of those queries might run in a transaction. In this case the locking query might be located + elsewhere in the transaction + MESSAGE + + Logger.say '', sub_item: true end end @@ -27,8 +27,10 @@ def log_queries(queries) def output_blocking_queries(queries) if SafePgMigrations.config.blocking_activity_logger_verbose queries.each do |pid, query, start_time| - SafePgMigrations.say "Query with pid #{pid || 'null'} started #{format_start_time start_time}: #{query}", - true + Logger.say( + "Query with pid #{pid || 'null'} started #{format_start_time start_time}: #{query}", + sub_item: true + ) end else output_confidentially_blocking_queries(queries) @@ -37,13 +39,13 @@ def output_blocking_queries(queries) def output_confidentially_blocking_queries(queries) queries.each do |start_time, locktype, mode, pid, transactionid| - SafePgMigrations.say( + Logger.say( "Query with pid #{pid || 'null'} " \ "started #{format_start_time(start_time)}: " \ "lock type: #{locktype || 'null'}, " \ "lock mode: #{mode || 'null'}, " \ "lock transactionid: #{transactionid || 'null'}", - true + sub_item: true ) end end diff --git a/lib/safe-pg-migrations/helpers/logger.rb b/lib/safe-pg-migrations/helpers/logger.rb new file mode 100644 index 0000000..59de2d6 --- /dev/null +++ b/lib/safe-pg-migrations/helpers/logger.rb @@ -0,0 +1,27 @@ +# frozen_string_literal: true + +module SafePgMigrations + module Helpers + module Logger + class << self + def say(message, sub_item: false) + return unless SafePgMigrations.current_migration + + log message, sub_item: sub_item + end + + def say_method_call(method, *args, **options) + args += [options] unless options.empty? + + say "#{method}(#{args.map(&:inspect) * ', '})", sub_item: true + end + + private + + def log(message, sub_item:) + SafePgMigrations.current_migration.say message, sub_item + end + end + end + end +end diff --git a/lib/safe-pg-migrations/plugins/blocking_activity_logger.rb b/lib/safe-pg-migrations/plugins/blocking_activity_logger.rb index 05b5924..fcc68ad 100644 --- a/lib/safe-pg-migrations/plugins/blocking_activity_logger.rb +++ b/lib/safe-pg-migrations/plugins/blocking_activity_logger.rb @@ -5,8 +5,8 @@ module SafePgMigrations module BlockingActivityLogger - include ::SafePgMigrations::Helpers::BlockingActivityFormatter - include ::SafePgMigrations::Helpers::BlockingActivitySelector + include Helpers::BlockingActivityFormatter + include Helpers::BlockingActivitySelector %i[ add_column @@ -63,14 +63,14 @@ def log_blocking_queries_after_lock blocking_queries_retriever_thread.kill rescue ActiveRecord::LockWaitTimeout - SafePgMigrations.say 'Lock timeout.', true + Helpers::Logger.say 'Lock timeout.', sub_item: true queries = begin blocking_queries_retriever_thread.value rescue StandardError => e - SafePgMigrations.say( + Helpers::Logger.say( "Error while retrieving blocking queries: #{e}", - true + sub_item: true ) nil end diff --git a/lib/safe-pg-migrations/plugins/idempotent_statements.rb b/lib/safe-pg-migrations/plugins/idempotent_statements.rb index 72cd6d1..c4a1bd7 100644 --- a/lib/safe-pg-migrations/plugins/idempotent_statements.rb +++ b/lib/safe-pg-migrations/plugins/idempotent_statements.rb @@ -2,7 +2,7 @@ module SafePgMigrations module IdempotentStatements - include SafePgMigrations::Helpers::IndexHelper + include Helpers::IndexHelper ruby2_keywords def add_index(table_name, column_name, *args) options = args.last.is_a?(Hash) ? args.last : {} @@ -12,9 +12,9 @@ module IdempotentStatements return super unless index_name_exists?(index_definition.table, index_definition.name) if index_valid?(index_definition.name) - SafePgMigrations.say( + Helpers::Logger.say( "/!\\ Index '#{index_definition.name}' already exists in '#{table_name}'. Skipping statement.", - true + sub_item: true ) return end @@ -26,13 +26,18 @@ module IdempotentStatements ruby2_keywords def add_column(table_name, column_name, type, *) return super unless column_exists?(table_name, column_name) - SafePgMigrations.say("/!\\ Column '#{column_name}' already exists in '#{table_name}'. Skipping statement.", true) + Helpers::Logger.say( + "/!\\ Column '#{column_name}' already exists in '#{table_name}'. Skipping statement.", + sub_item: true + ) end ruby2_keywords def remove_column(table_name, column_name, type = nil, *) return super if column_exists?(table_name, column_name) - SafePgMigrations.say("/!\\ Column '#{column_name}' not found on table '#{table_name}'. Skipping statement.", true) + Helpers::Logger.say( + "/!\\ Column '#{column_name}' not found on table '#{table_name}'. Skipping statement.", sub_item: true + ) end ruby2_keywords def remove_index(table_name, *args) @@ -41,7 +46,9 @@ module IdempotentStatements return super if index_name_exists?(table_name, index_name) - SafePgMigrations.say("/!\\ Index '#{index_name}' not found on table '#{table_name}'. Skipping statement.", true) + Helpers::Logger.say( + "/!\\ Index '#{index_name}' not found on table '#{table_name}'. Skipping statement.", sub_item: true + ) end ruby2_keywords def add_foreign_key(from_table, to_table, *args) @@ -49,9 +56,9 @@ module IdempotentStatements suboptions = options.slice(:name, :column) return super unless foreign_key_exists?(from_table, suboptions.present? ? nil : to_table, **suboptions) - SafePgMigrations.say( + Helpers::Logger.say( "/!\\ Foreign key '#{from_table}' -> '#{to_table}' already exists. Skipping statement.", - true + sub_item: true ) end @@ -59,9 +66,9 @@ def remove_foreign_key(from_table, to_table = nil, **options) return super if foreign_key_exists?(from_table, to_table, **options) reference_name = to_table || options[:to_table] || options[:column] || options[:name] - SafePgMigrations.say( + Helpers::Logger.say( "/!\\ Foreign key '#{from_table}' -> '#{reference_name}' does not exist. Skipping statement.", - true + sub_item: true ) end @@ -69,13 +76,14 @@ def remove_foreign_key(from_table, to_table = nil, **options) options = args.last.is_a?(Hash) ? args.last : {} return super if options[:force] || !table_exists?(table_name) - SafePgMigrations.say "/!\\ Table '#{table_name}' already exists.", true + Helpers::Logger.say "/!\\ Table '#{table_name}' already exists.", sub_item: true td = create_table_definition(table_name, *args) yield td if block_given? - SafePgMigrations.say(td.indexes.empty? ? '-- Skipping statement' : '-- Creating indexes', true) + Helpers::Logger.say(td.indexes.empty? ? '-- Skipping statement' : '-- Creating indexes', + sub_item: true) td.indexes.each do |column_name, index_options| add_index(table_name, column_name, **index_options) @@ -88,7 +96,9 @@ def add_check_constraint(table_name, expression, **options) return super if constraint_definition.nil? - SafePgMigrations.say "/!\\ Constraint '#{constraint_definition.name}' already exists. Skipping statement.", true + Helpers::Logger.say <<~MESSAGE, sub_item: true + /!\\ Constraint '#{constraint_definition.name}' already exists. Skipping statement. + MESSAGE end def change_column_null(table_name, column_name, null, *) @@ -96,10 +106,9 @@ def change_column_null(table_name, column_name, null, *) return super if column.null != null - SafePgMigrations.say( - "/!\\ Column '#{table_name}.#{column.name}' is already set to 'null: #{null}'. Skipping statement.", - true - ) + Helpers::Logger.say <<~MESSAGE, sub_item: true + /!\\ Column '#{table_name}.#{column.name}' is already set to 'null: #{null}'. Skipping statement. + MESSAGE end def validate_check_constraint(table_name, **options) @@ -107,8 +116,9 @@ def validate_check_constraint(table_name, **options) return super unless constraint_definition.validated? - SafePgMigrations.say "/!\\ Constraint '#{constraint_definition.name}' already validated. Skipping statement.", - true + Helpers::Logger.say <<~MESSAGE, sub_item: true + /!\\ Constraint '#{constraint_definition.name}' already validated. Skipping statement. + MESSAGE end def change_column_default(table_name, column_name, default_or_changes) @@ -122,11 +132,9 @@ def change_column_default(table_name, column_name, default_or_changes) return super if new_alter_statement != previous_alter_statement - SafePgMigrations.say( - "/!\\ Column '#{table_name}.#{column.name}' is already set to 'default: #{column.default}'. " \ - 'Skipping statement.', - true - ) + Helpers::Logger.say <<~MESSAGE, sub_item: true + /!\\ Column '#{table_name}.#{column.name}' is already set to 'default: #{column.default}'. Skipping statement. + MESSAGE end end end diff --git a/lib/safe-pg-migrations/plugins/statement_insurer.rb b/lib/safe-pg-migrations/plugins/statement_insurer.rb index d492cdd..2ab66e1 100644 --- a/lib/safe-pg-migrations/plugins/statement_insurer.rb +++ b/lib/safe-pg-migrations/plugins/statement_insurer.rb @@ -23,12 +23,13 @@ def add_check_constraint(table_name, expression, **options) options = check_constraint_options(table_name, expression, options) - SafePgMigrations.say_method_call :add_check_constraint, table_name, expression, **options, validate: false + Helpers::Logger.say_method_call :add_check_constraint, table_name, expression, **options, +validate: false super table_name, expression, **options, validate: false return unless options.fetch(:validate, true) - SafePgMigrations.say_method_call :validate_check_constraint, table_name, name: options[:name] + Helpers::Logger.say_method_call :validate_check_constraint, table_name, name: options[:name] validate_check_constraint table_name, name: options[:name] end @@ -67,7 +68,7 @@ def add_check_constraint(table_name, expression, **options) options[:algorithm] = :concurrently end - SafePgMigrations.say_method_call(:add_index, table_name, column_name, **options) + Helpers::Logger.say_method_call(:add_index, table_name, column_name, **options) without_timeout { super(table_name, column_name, **options) } end @@ -75,7 +76,7 @@ def add_check_constraint(table_name, expression, **options) ruby2_keywords def remove_index(table_name, *args) options = args.last.is_a?(Hash) ? args.last : { column: args.last } options[:algorithm] = :concurrently unless options.key?(:algorithm) - SafePgMigrations.say_method_call(:remove_index, table_name, **options) + Helpers::Logger.say_method_call(:remove_index, table_name, **options) without_timeout { super(table_name, **options) } end @@ -87,12 +88,13 @@ def change_column_null(table_name, column_name, null, default = nil) add_check_constraint table_name, "#{column_name} IS NOT NULL" - SafePgMigrations.say_method_call :change_column_null, table_name, column_name, false + Helpers::Logger.say_method_call :change_column_null, table_name, column_name, false with_setting(:statement_timeout, SafePgMigrations.config.pg_statement_timeout) do super table_name, column_name, false end - SafePgMigrations.say_method_call :remove_check_constraint, table_name, "#{column_name} IS NOT NULL" + Helpers::Logger.say_method_call :remove_check_constraint, table_name, + "#{column_name} IS NOT NULL" remove_check_constraint table_name, "#{column_name} IS NOT NULL" end diff --git a/lib/safe-pg-migrations/plugins/statement_insurer/add_column.rb b/lib/safe-pg-migrations/plugins/statement_insurer/add_column.rb index e58a2af..a7a8836 100644 --- a/lib/safe-pg-migrations/plugins/statement_insurer/add_column.rb +++ b/lib/safe-pg-migrations/plugins/statement_insurer/add_column.rb @@ -15,14 +15,14 @@ module AddColumn null = options.delete(:null) with_setting(:statement_timeout, SafePgMigrations.config.pg_statement_timeout) do - SafePgMigrations.say_method_call(:add_column, table_name, column_name, type, options) + Helpers::Logger.say_method_call(:add_column, table_name, column_name, type, options) super table_name, column_name, type, **options end - SafePgMigrations.say_method_call(:change_column_default, table_name, column_name, default) + Helpers::Logger.say_method_call(:change_column_default, table_name, column_name, default) change_column_default(table_name, column_name, default) - SafePgMigrations.say_method_call(:backfill_column_default, table_name, column_name) + Helpers::Logger.say_method_call(:backfill_column_default, table_name, column_name) without_statement_timeout do backfill_column_default(table_name, column_name) end @@ -34,14 +34,14 @@ module AddColumn def should_keep_default_implementation?(default: nil, default_value_backfill: :auto, **) default_value_backfill != :update_in_batches || !default || - !SafePgMigrations::Helpers::SatisfiedHelper.satisfies_add_column_update_rows_backfill? + !Helpers::SatisfiedHelper.satisfies_add_column_update_rows_backfill? end def backfill_column_default(table_name, column_name) model = Class.new(ActiveRecord::Base) { self.table_name = table_name } quoted_column_name = quote_column_name(column_name) - SafePgMigrations::Helpers::BatchOver.new(model).each_batch do |batch| + Helpers::BatchOver.new(model).each_batch do |batch| batch .update_all("#{quoted_column_name} = DEFAULT") sleep SafePgMigrations.config.backfill_pause diff --git a/lib/safe-pg-migrations/plugins/statement_retrier.rb b/lib/safe-pg-migrations/plugins/statement_retrier.rb index d2ecab4..82f82a0 100644 --- a/lib/safe-pg-migrations/plugins/statement_retrier.rb +++ b/lib/safe-pg-migrations/plugins/statement_retrier.rb @@ -25,9 +25,9 @@ def retry_if_lock_timeout raise unless remaining_tries > 0 retry_delay = SafePgMigrations.config.retry_delay - SafePgMigrations.say "Retrying in #{retry_delay} seconds...", true + Helpers::Logger.say "Retrying in #{retry_delay} seconds...", sub_item: true sleep retry_delay - SafePgMigrations.say 'Retrying now.', true + Helpers::Logger.say 'Retrying now.', sub_item: true retry end end diff --git a/lib/safe-pg-migrations/plugins/useless_statements_logger.rb b/lib/safe-pg-migrations/plugins/useless_statements_logger.rb index 700e6cf..9411a2a 100644 --- a/lib/safe-pg-migrations/plugins/useless_statements_logger.rb +++ b/lib/safe-pg-migrations/plugins/useless_statements_logger.rb @@ -4,8 +4,10 @@ module SafePgMigrations module UselessStatementsLogger class << self ruby2_keywords def warn_useless(action, link = nil, *args) - SafePgMigrations.say "/!\\ No need to explicitly use #{action}, safe-pg-migrations does it for you", *args - SafePgMigrations.say "\t see #{link} for more details", *args if link + Helpers::Logger.say( + "/!\\ No need to explicitly use #{action}, safe-pg-migrations does it for you", *args + ) + Helpers::Logger.say "\t see #{link} for more details", *args if link end end diff --git a/test/blocking_activity_logger_test.rb b/test/blocking_activity_logger_test.rb index 44f7d40..63ff058 100644 --- a/test/blocking_activity_logger_test.rb +++ b/test/blocking_activity_logger_test.rb @@ -38,9 +38,9 @@ def test_add_index_unfiltered assert_includes calls, 'add_index("users", :email, {:algorithm=>:concurrently})' assert_includes calls, 'Statement was being blocked by the following query' - assert_match(/Query with pid \d+ started 1 second ago: SELECT pg_sleep\(3\)/, + assert_match(/Query with pid \d+ started 1 second ago: SELECT pg_sleep\(3\)/, calls) - assert_match(/Query with pid \d+ started 2 seconds ago: SELECT pg_sleep\(3\)/, + assert_match(/Query with pid \d+ started 2 seconds ago: SELECT pg_sleep\(3\)/, calls) end diff --git a/test/useless_statement_logger_test.rb b/test/useless_statement_logger_test.rb index a5a4838..e9b1f3f 100644 --- a/test/useless_statement_logger_test.rb +++ b/test/useless_statement_logger_test.rb @@ -13,7 +13,7 @@ def change end end.new - write_calls = record_calls(SafePgMigrations, :say) { run_migration }.map(&:first) + write_calls = record_calls(@migration, :write) { run_migration }.join("\n") assert_includes( write_calls, @@ -29,7 +29,7 @@ def change end end.new - write_calls = record_calls(SafePgMigrations, :say) { run_migration }.map(&:first) + write_calls = record_calls(@migration, :write) { run_migration }.join("\n") refute_includes write_calls, '/!\ No need to explicitly disable DDL transaction, safe-pg-migrations does it for you' end @@ -43,7 +43,7 @@ def change end end.new - write_calls = record_calls(SafePgMigrations, :say) { run_migration }.map(&:first) + write_calls = record_calls(@migration, :write) { run_migration }.join("\n") assert_includes( write_calls, @@ -60,7 +60,7 @@ def change end end.new - write_calls = record_calls(SafePgMigrations, :say) { run_migration }.map(&:first) + write_calls = record_calls(@migration, :write) { run_migration }.join("\n") refute_includes( write_calls, @@ -82,7 +82,7 @@ def change end end.new - write_calls = record_calls(SafePgMigrations, :say) { run_migration }.map(&:first) + write_calls = record_calls(@migration, :write) { run_migration }.join("\n") assert_includes( write_calls, @@ -104,7 +104,7 @@ def change end end.new - write_calls = record_calls(SafePgMigrations, :say) { run_migration }.map(&:first) + write_calls = record_calls(@migration, :write) { run_migration }.join("\n") refute_includes( write_calls,