From 6a4ec0c9a95db580f32b5ca42922624598ba30a8 Mon Sep 17 00:00:00 2001 From: Nathan Griffith Date: Fri, 9 Sep 2022 15:27:53 -0400 Subject: [PATCH] Upstream `Journaled::AuditLog` feature to rubygems release (#26) This upstreams Betterment's `Journaled::AuditLog` mixin (for ActiveRecord models) into the public rubygems release, making it easier for Betterment to consume it (and also making it available for others to use). It's similar to other audit logging / papertrail-like gems, in that it will record changes to models (insert/update/delete). But instead of storing these changes in a local `versions` table (etc), it will emit them in the form of journaled events. I've updated the README with some of the details (including how sensitive/encrypted fields are handled, etc). This pairs with the [5.0 release](https://github.com/Betterment/journaled/releases/tag/v5.0.0) that introduced transactionally-batched journaling. (So, if you're changing several records at once within the scope of a single transaction, you'll only end up enqueuing 1 journaled event job). --- app/models/concerns/journaled/changes.rb | 2 +- app/models/journaled/audit_log/event.rb | 87 +++ journaled.gemspec | 1 + .../journaled/audit_log/event.json | 31 + lib/journaled.rb | 2 + lib/journaled/audit_log.rb | 194 ++++++ lib/journaled/version.rb | 2 +- spec/dummy/config/application.rb | 14 +- spec/lib/journaled/audit_log_spec.rb | 581 ++++++++++++++++++ spec/spec_helper.rb | 49 +- 10 files changed, 947 insertions(+), 16 deletions(-) create mode 100644 app/models/journaled/audit_log/event.rb create mode 100644 journaled_schemas/journaled/audit_log/event.json create mode 100644 lib/journaled/audit_log.rb create mode 100644 spec/lib/journaled/audit_log_spec.rb diff --git a/app/models/concerns/journaled/changes.rb b/app/models/concerns/journaled/changes.rb index c84f2f5..d181fd9 100644 --- a/app/models/concerns/journaled/changes.rb +++ b/app/models/concerns/journaled/changes.rb @@ -56,7 +56,7 @@ def update_columns(attributes, opts = { force: false }) end class_methods do - def journal_changes_to(*attribute_names, as:, enqueue_with: {}) # rubocop:disable Naming/MethodParameterName + def journal_changes_to(*attribute_names, as:, enqueue_with: {}) if attribute_names.empty? || attribute_names.any? { |n| !n.is_a?(Symbol) } raise "one or more symbol attribute_name arguments is required" end diff --git a/app/models/journaled/audit_log/event.rb b/app/models/journaled/audit_log/event.rb new file mode 100644 index 0000000..abfd759 --- /dev/null +++ b/app/models/journaled/audit_log/event.rb @@ -0,0 +1,87 @@ +# FIXME: This cannot be included in lib/ because Journaled::Event is autoloaded via app/models +# Autoloading Journaled::Event isn't strictly necessary, and for compatibility it would +# make sense to move it to lib/. +module Journaled + module AuditLog + Event = Struct.new(:record, :database_operation, :unfiltered_changes) do + include Journaled::Event + + journal_attributes :class_name, :table_name, :record_id, + :database_operation, :changes, :snapshot, :actor, tagged: true + + def journaled_stream_name + AuditLog.default_stream_name || super + end + + def created_at + case database_operation + when 'insert' + record_created_at + when 'update' + record_updated_at + when 'delete' + Time.zone.now + else + raise "Unhandled database operation type: #{database_operation}" + end + end + + def record_created_at + record.try(:created_at) || Time.zone.now + end + + def record_updated_at + record.try(:updated_at) || Time.zone.now + end + + def class_name + record.class.name + end + + def table_name + record.class.table_name + end + + def record_id + record.id + end + + def changes + filtered_changes = unfiltered_changes.deep_dup.deep_symbolize_keys + filtered_changes.each do |key, value| + filtered_changes[key] = value.map { |val| '[FILTERED]' if val } if filter_key?(key) + end + end + + def snapshot + filtered_attributes if record._log_snapshot || AuditLog.snapshots_enabled + end + + def actor + Journaled.actor_uri + end + + private + + def filter_key?(key) + filter_params.include?(key) || encrypted_column?(key) + end + + def encrypted_column?(key) + key.to_s.end_with?('_crypt', '_hmac') || + (Rails::VERSION::MAJOR >= 7 && record.encrypted_attribute?(key)) + end + + def filter_params + Rails.application.config.filter_parameters + end + + def filtered_attributes + attrs = record.attributes.dup.symbolize_keys + attrs.each do |key, _value| + attrs[key] = '[FILTERED]' if filter_key?(key) + end + end + end + end +end diff --git a/journaled.gemspec b/journaled.gemspec index 5fb8460..484a546 100644 --- a/journaled.gemspec +++ b/journaled.gemspec @@ -23,6 +23,7 @@ Gem::Specification.new do |s| s.add_dependency "activejob" s.add_dependency "activerecord" + s.add_dependency "activesupport" s.add_dependency "aws-sdk-kinesis", "< 2" s.add_dependency "json-schema" s.add_dependency "railties", ">= 5.2" diff --git a/journaled_schemas/journaled/audit_log/event.json b/journaled_schemas/journaled/audit_log/event.json new file mode 100644 index 0000000..acab339 --- /dev/null +++ b/journaled_schemas/journaled/audit_log/event.json @@ -0,0 +1,31 @@ +{ + "type": "object", + "title": "audit_log_event", + "additionalProperties": false, + "required": [ + "id", + "event_type", + "created_at", + "class_name", + "table_name", + "record_id", + "database_operation", + "changes", + "snapshot", + "actor", + "tags" + ], + "properties": { + "id": { "type": "string" }, + "event_type": { "type": "string" }, + "created_at": { "type": "string" }, + "class_name": { "type": "string" }, + "table_name": { "type": "string" }, + "record_id": { "type": ["string", "integer"] }, + "database_operation": { "type": "string" }, + "changes": { "type": "object", "additionalProperties": true }, + "snapshot": { "type": ["object", "null"], "additionalProperties": true }, + "actor": { "type": "string" }, + "tags": { "type": "object", "additionalProperties": true } + } +} diff --git a/lib/journaled.rb b/lib/journaled.rb index 19c57e0..9fa3f83 100644 --- a/lib/journaled.rb +++ b/lib/journaled.rb @@ -69,3 +69,5 @@ def self.tag!(**tags) Current.tags = Current.tags.merge(tags) end end + +require 'journaled/audit_log' diff --git a/lib/journaled/audit_log.rb b/lib/journaled/audit_log.rb new file mode 100644 index 0000000..5071c29 --- /dev/null +++ b/lib/journaled/audit_log.rb @@ -0,0 +1,194 @@ +require 'active_support/core_ext/module/attribute_accessors_per_thread' + +module Journaled + module AuditLog + extend ActiveSupport::Concern + + DEFAULT_EXCLUDED_CLASSES = %w( + Delayed::Job + PaperTrail::Version + ActiveStorage::Attachment + ActiveStorage::Blob + ActiveRecord::InternalMetadata + ActiveRecord::SchemaMigration + ).freeze + + mattr_accessor(:default_ignored_columns) { %i(created_at updated_at) } + mattr_accessor(:default_stream_name) { Journaled.default_stream_name } + mattr_accessor(:excluded_classes) { DEFAULT_EXCLUDED_CLASSES.dup } + thread_mattr_accessor(:snapshots_enabled) { false } + thread_mattr_accessor(:_disabled) { false } + thread_mattr_accessor(:_force) { false } + + class << self + def exclude_classes! + excluded_classes.each do |name| + if Rails::VERSION::MAJOR >= 6 && Rails.autoloaders.zeitwerk_enabled? + zeitwerk_exclude!(name) + else + classic_exclude!(name) + end + end + end + + def with_snapshots + snapshots_enabled_was = snapshots_enabled + self.snapshots_enabled = true + yield + ensure + self.snapshots_enabled = snapshots_enabled_was + end + + def without_audit_logging + disabled_was = _disabled + self._disabled = true + yield + ensure + self._disabled = disabled_was + end + + private + + def zeitwerk_exclude!(name) + if Object.const_defined?(name) + name.constantize.skip_audit_log + else + Rails.autoloaders.main.on_load(name) { |klass, _path| klass.skip_audit_log } + end + end + + def classic_exclude!(name) + name.constantize.skip_audit_log + rescue NameError + nil + end + end + + Config = Struct.new(:enabled, :ignored_columns) do + private :enabled + def enabled? + !AuditLog._disabled && self[:enabled].present? + end + end + + included do + prepend BlockedMethods + singleton_class.prepend BlockedClassMethods + + class_attribute :audit_log_config, default: Config.new(false, AuditLog.default_ignored_columns) + attr_accessor :_log_snapshot + + after_create { _emit_audit_log!('insert') } + after_update { _emit_audit_log!('update') if _audit_log_changes.any? } + after_destroy { _emit_audit_log!('delete') } + end + + class_methods do + def has_audit_log(ignore: []) + ignored_columns = _audit_log_inherited_ignored_columns + [ignore].flatten(1) + self.audit_log_config = Config.new(true, ignored_columns.uniq) + end + + def skip_audit_log + self.audit_log_config = Config.new(false, _audit_log_inherited_ignored_columns.uniq) + end + + private + + def _audit_log_inherited_ignored_columns + (superclass.try(:audit_log_config)&.ignored_columns || []) + audit_log_config.ignored_columns + end + end + + module BlockedMethods + BLOCKED_METHODS = { + delete: '#destroy', + update_column: '#update!', + update_columns: '#update!', + }.freeze + + def delete(**kwargs) + _journaled_audit_log_check!(:delete, **kwargs) do + super() + end + end + + def update_column(name, value, **kwargs) + _journaled_audit_log_check!(:update_column, **kwargs.merge(name => value)) do + super(name, value) + end + end + + def update_columns(args = {}, **kwargs) + _journaled_audit_log_check!(:update_columns, **args.merge(kwargs)) do + super(args.merge(kwargs).except(:_force)) + end + end + + def _journaled_audit_log_check!(method, **kwargs) # rubocop:disable Metrics/AbcSize + force_was = AuditLog._force + AuditLog._force = kwargs.delete(:_force) if kwargs.key?(:_force) + audited_columns = kwargs.keys - audit_log_config.ignored_columns + + if method == :delete || audited_columns.any? + column_message = <<~MSG if kwargs.any? + You are attempting to change the following audited columns: + #{audited_columns.inspect} + + MSG + raise <<~MSG if audit_log_config.enabled? && !AuditLog._force + #{column_message}Using `#{method}` is blocked because it skips audit logging (and other Rails callbacks)! + Consider using `#{BLOCKED_METHODS[method]}` instead, or pass `_force: true` as an argument. + MSG + end + + yield + ensure + AuditLog._force = force_was + end + end + + module BlockedClassMethods + BLOCKED_METHODS = { + delete_all: '.destroy_all', + insert: '.create!', + insert_all: '.each { create!(...) }', + update_all: '.find_each { update!(...) }', + upsert: '.create_or_find_by!', + upsert_all: '.each { create_or_find_by!(...) }', + }.freeze + + BLOCKED_METHODS.each do |method, alternative| + define_method(method) do |*args, **kwargs, &block| + force_was = AuditLog._force + AuditLog._force = kwargs.delete(:_force) if kwargs.key?(:_force) + + raise <<~MSG if audit_log_config.enabled? && !AuditLog._force + `#{method}` is blocked because it skips callbacks and audit logs! + Consider using `#{alternative}` instead, or pass `_force: true` as an argument. + MSG + + super(*args, **kwargs, &block) + ensure + AuditLog._force = force_was + end + end + end + + def _emit_audit_log!(database_operation) + if audit_log_config.enabled? + event = Journaled::AuditLog::Event.new(self, database_operation, _audit_log_changes) + ActiveSupport::Notifications.instrument('journaled.audit_log.journal', event: event) do + event.journal! + end + end + end + + def _audit_log_changes + previous_changes.except(*audit_log_config.ignored_columns) + end + end +end + +ActiveSupport.on_load(:active_record) { include Journaled::AuditLog } +Journaled::Engine.config.after_initialize { Journaled::AuditLog.exclude_classes! } diff --git a/lib/journaled/version.rb b/lib/journaled/version.rb index 3a0a731..bc37eb6 100644 --- a/lib/journaled/version.rb +++ b/lib/journaled/version.rb @@ -1,3 +1,3 @@ module Journaled - VERSION = "5.0.0".freeze + VERSION = "5.1.0".freeze end diff --git a/spec/dummy/config/application.rb b/spec/dummy/config/application.rb index 9e1e0ba..615667c 100644 --- a/spec/dummy/config/application.rb +++ b/spec/dummy/config/application.rb @@ -10,16 +10,8 @@ module Dummy class Application < Rails::Application - # Settings in config/environments/* take precedence over those specified here. - # Application configuration should go into files in config/initializers - # -- all .rb files in that directory are automatically loaded. - - # Set Time.zone default to the specified zone and make Active Record auto-convert to this zone. - # Run "rake -D time" for a list of tasks for finding time zone names. Default is UTC. - # config.time_zone = 'Central Time (US & Canada)' - - # The default locale is :en and all translations from config/locales/*.rb,yml are auto loaded. - # config.i18n.load_path += Dir[Rails.root.join('my', 'locales', '*.{rb,yml}').to_s] - # config.i18n.default_locale = :de + config.autoloader = Rails::VERSION::MAJOR >= 7 ? :zeitwerk : :classic + config.active_record.sqlite3.represent_boolean_as_integer = true if Rails::VERSION::MAJOR < 6 + config.active_record.legacy_connection_handling = false if Rails::VERSION::MAJOR >= 7 end end diff --git a/spec/lib/journaled/audit_log_spec.rb b/spec/lib/journaled/audit_log_spec.rb new file mode 100644 index 0000000..12b7a14 --- /dev/null +++ b/spec/lib/journaled/audit_log_spec.rb @@ -0,0 +1,581 @@ +require 'rails_helper' + +RSpec.describe Journaled::AuditLog do + let(:auditable_model) do + Class.new do + extend ActiveModel::Callbacks + define_model_callbacks :create, :update, :destroy, only: %i(after) + + include Journaled::AuditLog + + def self.table_name + 'objects' + end + + def id + 'random-id' + end + + def created_at + 'very-recently' + end + + def updated_at + 'close-to-now' + end + + def attributes + { all: 'attributes', password: true } + end + + if Rails::VERSION::MAJOR >= 7 + def encrypted_attribute?(_key) + false + end + end + end + end + + before do + stub_const('MyModel', auditable_model) + end + + around do |example| + Journaled.tagged(request_id: 123) do + example.run + end + end + + describe '.default_ignored_columns' do + it 'defaults to timestamps, but is configurable' do + expect(described_class.default_ignored_columns).to eq %i(created_at updated_at) + described_class.default_ignored_columns = [] + expect(described_class.default_ignored_columns).to eq [] + ensure + described_class.default_ignored_columns = %i(created_at updated_at) + end + end + + describe '.default_stream_name' do + it 'defaults to primary default, but is configurable' do + expect(described_class.default_stream_name).to be_nil + described_class.default_stream_name = 'dont_cross_the_streams' + expect(described_class.default_stream_name).to eq 'dont_cross_the_streams' + ensure + described_class.default_stream_name = nil + end + end + + describe '.excluded_classes' do + let(:defaults) do + %w( + Delayed::Job + PaperTrail::Version + ActiveStorage::Attachment + ActiveStorage::Blob + ActiveRecord::InternalMetadata + ActiveRecord::SchemaMigration + ) + end + + it 'defaults to DJ and papertrail, but is configurable, and will disable audit logging' do + expect(described_class.excluded_classes).to eq defaults + described_class.excluded_classes += %w(MyModel) + expect(described_class.excluded_classes).to eq defaults + %w(MyModel) + ensure + described_class.excluded_classes = defaults + end + end + + describe '.has_audit_log, .skip_audit_log' do + around do |example| + described_class.default_ignored_columns = %i(DEFAULTS) + example.run + ensure + described_class.default_ignored_columns = %i(created_at updated_at) + end + + subject { MyModel } + + it 'enables/disables audit logging' do + expect(subject.audit_log_config.enabled?).to be(false) + expect(subject.audit_log_config.ignored_columns).to eq(%i(DEFAULTS)) + subject.has_audit_log + expect(subject.audit_log_config.enabled?).to be(true) + expect(subject.audit_log_config.ignored_columns).to eq(%i(DEFAULTS)) + subject.has_audit_log ignore: %i(foo bar baz) + expect(subject.audit_log_config.enabled?).to be(true) + expect(subject.audit_log_config.ignored_columns).to eq(%i(DEFAULTS foo bar baz)) + subject.skip_audit_log + expect(subject.audit_log_config.enabled?).to be(false) + expect(subject.audit_log_config.ignored_columns).to eq(%i(DEFAULTS foo bar baz)) + end + + it 'can be composed with multiple calls' do + subject.has_audit_log ignore: %i(foo) + subject.has_audit_log ignore: %i(bar) + expect(subject.audit_log_config.ignored_columns).to eq(%i(DEFAULTS foo bar)) + end + + it 'deduplicates identical fields' do + subject.has_audit_log ignore: %i(foo) + subject.has_audit_log ignore: %i(DEFAULTS foo) + expect(subject.audit_log_config.ignored_columns).to eq(%i(DEFAULTS foo)) + end + + it 'accepts a single name (instead of an array)' do + subject.has_audit_log ignore: :bar + expect(subject.audit_log_config.ignored_columns).to eq(%i(DEFAULTS bar)) + end + + context 'with a subclass' do + let(:auditable_subclass) do + Class.new(subject) { include Journaled::AuditLog } + end + + before do + stub_const('MySubclass', auditable_subclass) + end + + it 'inherits the config by default, and merges ignored columns' do + expect(MySubclass.audit_log_config.enabled?).to be(false) + expect(MySubclass.audit_log_config.ignored_columns).to eq(%i(DEFAULTS)) + subject.has_audit_log ignore: %i(foo) + expect(MySubclass.audit_log_config.enabled?).to be(true) + expect(MySubclass.audit_log_config.ignored_columns).to eq(%i(DEFAULTS foo)) + MySubclass.has_audit_log ignore: :bar + expect(MySubclass.audit_log_config.enabled?).to be(true) + expect(subject.audit_log_config.ignored_columns).to eq(%i(DEFAULTS foo)) + expect(MySubclass.audit_log_config.ignored_columns).to eq(%i(DEFAULTS foo bar)) + end + + it 'allows the subclass to skip audit logging, and vice versa' do + subject.has_audit_log ignore: %i(foo) + MySubclass.skip_audit_log + expect(subject.audit_log_config.enabled?).to be(true) + expect(subject.audit_log_config.ignored_columns).to eq(%i(DEFAULTS foo)) + expect(MySubclass.audit_log_config.enabled?).to be(false) + expect(MySubclass.audit_log_config.ignored_columns).to eq(%i(DEFAULTS foo)) + subject.skip_audit_log + MySubclass.has_audit_log ignore: %i(foo) + expect(subject.audit_log_config.enabled?).to be(false) + expect(subject.audit_log_config.ignored_columns).to eq(%i(DEFAULTS foo)) + expect(MySubclass.audit_log_config.enabled?).to be(true) + expect(MySubclass.audit_log_config.ignored_columns).to eq(%i(DEFAULTS foo)) + end + + it 'does not apply to subclasses that are in the exclusion list' do + excluded_classes_was = described_class.excluded_classes.dup + described_class.excluded_classes << 'MySubclass' + described_class.exclude_classes! # typically run via an initializer + + subject.has_audit_log + expect(subject.audit_log_config.enabled?).to be(true) + expect(MySubclass.audit_log_config.enabled?).to be(false) + ensure + described_class.excluded_classes = excluded_classes_was + end + end + end + + describe '#save, #update, #destroy' do + let(:attributes) { %i(name email_addr json synced_at) } + + before do + attrs = attributes + auditable_model.class_eval do + include ActiveModel::Dirty + + attr_reader(*attrs) + + define_attribute_methods(*attrs) + + attrs.each do |attr| + define_method("#{attr}=") do |val| + send("#{attr}_will_change!") unless val == send(attr) + instance_variable_set("@#{attr}", val) + end + end + + def initialize(**attrs) + assign_attrs(**attrs) + end + + def save + run_callbacks(:create) { changes_applied } # always a 'create' action, for simplicity + end + + def update(**attrs) + run_callbacks(:update) { assign_attrs(**attrs) && changes_applied } + end + + def destroy + run_callbacks(:destroy) { changes_applied } + end + + def assign_attrs(**attrs) + attrs.each { |attr, value| send("#{attr}=", value) } + end + end + end + + subject { MyModel.new(name: 'bob', email_addr: 'bob@example.org', json: { asdf: 123 }, synced_at: 'now') } + + it 'does not emit a journaled event (because audit logging is not enabled)' do + expect { subject.save } + .to not_journal_event_including(event_type: 'journaled_audit_log_event') + expect { subject.update(name: 'robert') } + .to not_journal_event_including(event_type: 'journaled_audit_log_event') + expect { subject.destroy } + .to not_journal_event_including(event_type: 'journaled_audit_log_event') + end + + context 'when audit logging is enabled' do + around { |example| freeze_time { example.run } } + before { auditable_model.class_eval { has_audit_log } } + + it 'emits events through the lifecycle of an object' do + expect { subject.save }.to journal_event_including( + event_type: 'journaled_audit_log_event', + created_at: 'very-recently', + class_name: 'MyModel', + table_name: 'objects', + record_id: 'random-id', + database_operation: 'insert', + changes: { + name: [nil, 'bob'], + email_addr: [nil, 'bob@example.org'], + json: [nil, { asdf: 123 }], + synced_at: [nil, 'now'], + }, + snapshot: {}, + actor: 'gid://dummy', + tags: { request_id: 123 }, + ) + expect { subject.update(name: 'robert') }.to journal_event_including( + event_type: 'journaled_audit_log_event', + created_at: 'close-to-now', + database_operation: 'update', + changes: { name: %w(bob robert) }, + snapshot: {}, + ) + expect { subject.update(name: 'robert') } + .to not_journal_event_including(event_type: 'journaled_audit_log_event') + expect { subject.destroy }.to journal_event_including( + event_type: 'journaled_audit_log_event', + created_at: Time.current, + database_operation: 'delete', + changes: {}, + snapshot: {}, + ) + end + + context 'when audit logging is disabled globally' do + around do |example| + described_class.without_audit_logging do + example.run + end + end + + it 'does not emit a journaled event' do + expect(subject.audit_log_config).not_to be_enabled + expect { subject.save } + .to not_journal_event_including(event_type: 'journaled_audit_log_event') + expect { subject.update(name: 'robert') } + .to not_journal_event_including(event_type: 'journaled_audit_log_event') + expect { subject.destroy } + .to not_journal_event_including(event_type: 'journaled_audit_log_event') + end + end + + context 'and a field is in the filter_paramters config' do + around do |example| + Rails.application.config.filter_parameters << :name + example.run + ensure + Rails.application.config.filter_parameters = Rails.application.config.filter_parameters - [:name] + end + + subject { MyModel.new(name: 'homer') } + + it 'filters that field through the lifecycle of the model' do + expect { subject.save } + .to journal_event_including(changes: { name: [nil, '[FILTERED]'] }) + expect { subject.update(name: 'bart') } + .to journal_event_including(changes: { name: ['[FILTERED]', '[FILTERED]'] }) + expect { subject.update(name: 'bart') } + .to not_journal_event_including(event_type: 'journaled_audit_log_event') + expect { subject.destroy }.to journal_event_including(changes: {}) + end + end + + context 'and fields end with _crypt or _hmac' do + let(:attributes) { super() + %i(favorite_color_crypt favorite_color_hmac) } + + subject { MyModel.new(name: 'homer', favorite_color_crypt: '123', favorite_color_hmac: '456') } + + it 'filters those fields through the lifecycle of the model' do + expect { subject.save }.to journal_event_including( + changes: { + name: [nil, 'homer'], + favorite_color_crypt: [nil, '[FILTERED]'], + favorite_color_hmac: [nil, '[FILTERED]'], + }, + ) + expect { subject.update(name: 'bart', favorite_color_crypt: '789', favorite_color_hmac: '789') } + .to journal_event_including( + changes: { + name: %w(homer bart), + favorite_color_crypt: ['[FILTERED]', '[FILTERED]'], + favorite_color_hmac: ['[FILTERED]', '[FILTERED]'], + }, + ) + expect { subject.update(name: 'bart', favorite_color_crypt: '789', favorite_color_hmac: '789') } + .to not_journal_event_including(event_type: 'journaled_audit_log_event') + expect { subject.destroy }.to journal_event_including(changes: {}) + end + end + + context 'and snapshotting is enabled via the attribute' do + subject { MyModel.new(name: 'bob', _log_snapshot: true) } + + it 'emits snapshots when `:_log_snapshot` is `true`, and filters the expected fields' do + expect { subject.save } + .to journal_event_including(snapshot: { all: 'attributes', password: '[FILTERED]' }) + expect { subject.update(name: 'robert') } + .to journal_event_including(snapshot: { all: 'attributes', password: '[FILTERED]' }) + subject._log_snapshot = false + expect { subject.update(name: 'bob') } + .to not_journal_event_including(snapshot: { all: 'attributes', password: '[FILTERED]' }) + subject._log_snapshot = true + expect { subject.destroy } + .to journal_event_including(snapshot: { all: 'attributes', password: '[FILTERED]' }) + end + end + + context 'and snapshotting is enabled globally' do + subject { MyModel.new(name: 'bob') } + + it 'emits snapshots through the lifecycle of the object, and filters the expected fields' do + described_class.with_snapshots do + expect { subject.save } + .to journal_event_including(snapshot: { all: 'attributes', password: '[FILTERED]' }) + expect { subject.update(name: 'robert') } + .to journal_event_including(snapshot: { all: 'attributes', password: '[FILTERED]' }) + end + expect { subject.update(name: 'bob') } + .to not_journal_event_including(snapshot: { all: 'attributes', password: '[FILTERED]' }) + described_class.with_snapshots do + expect { subject.destroy } + .to journal_event_including(snapshot: { all: 'attributes', password: '[FILTERED]' }) + end + end + end + end + + context 'and a field is ignored' do + before { auditable_model.class_eval { has_audit_log ignore: :synced_at } } + + subject { MyModel.new(name: 'bob', synced_at: 'earlier') } + + it 'excludes that field and does not emit events when the field changes' do + expect { subject.save } + .to journal_event_including(changes: { name: [nil, 'bob'] }) + .and not_journal_event_including(changes: { synced_at: [nil, 'earlier'] }) + expect { subject.update(synced_at: 'now') } + .to not_journal_event_including(event_type: 'journaled_audit_log_event') + expect { subject.destroy }.to journal_event_including( + event_type: 'journaled_audit_log_event', + database_operation: 'delete', + changes: {}, + ) + end + end + + context 'with a real ActiveRecord model' do + let(:journaled_class) do + Class.new(ActiveRecord::Base) do + has_audit_log + + self.table_name = 'widgets' + end + end + + before do + stub_const('Widget', journaled_class) + end + + subject do + Widget.new(name: 'test') + end + + around { |example| freeze_time { example.run } } + + it 'is audited and supports snapshots' do + expect { subject.save! }.to journal_event_including( + event_type: 'journaled_audit_log_event', + table_name: 'widgets', + class_name: 'Widget', + database_operation: 'insert', + changes: { + name: [nil, 'test'], + }, + snapshot: {}, + ).and not_journal_event_including(changes: { created_at: [nil, Time.zone.now] }) + .and emit_notification('journaled.event.stage') + .and emit_notification('journaled.batch.enqueue') + .and emit_notification('journaled.audit_log.journal') + expect { subject.save! }.to not_journal_event_including( + event_type: 'journaled_audit_log_event', + table_name: 'widgets', + ) + expect { subject.update!(name: 'not_test', _log_snapshot: true) }.to journal_event_including( + event_type: 'journaled_audit_log_event', + table_name: 'widgets', + database_operation: 'update', + changes: { + name: %w(test not_test), + }, + snapshot: { + name: 'not_test', + }, + ) + .and emit_notification('journaled.audit_log.journal') + + # rubocop:disable Rails/SkipsModelValidations + expect { subject.update_column(:name, 'banana') } + .to raise_error(/skips audit logging/) + expect { subject.update_column(:name, 'elephant', _force: true) } + .not_to raise_error + expect { subject.update_column(:name, 'other') } + .to raise_error(/skips audit logging/) + # rubocop:enable Rails/SkipsModelValidations + + expect { subject.destroy }.to journal_event_including( + event_type: 'journaled_audit_log_event', + table_name: 'widgets', + class_name: 'Widget', + database_operation: 'delete', + changes: {}, + snapshot: {}, + ) + .and emit_notification('journaled.audit_log.journal') + end + end + end + + # rubocop:disable Rails/SkipsModelValidations + describe '#delete, #update_column, #update_columns' do + before do + auditable_model.class_eval do + def delete(*); end + def update_column(*); end + def update_columns(*); end + end + end + + subject { MyModel.new } + + it 'does not block calls (because audit logging is disabled)' do + expect { subject.delete }.to not_raise_error + expect { subject.update_column(:foo, 'bar') }.to not_raise_error + expect { subject.update_columns(foo: 'bar') }.to not_raise_error + end + + context 'when audit logging is enabled' do + before { auditable_model.class_eval { has_audit_log } } + + it 'blocks the action' do + expect { subject.delete }.to raise_error(<<~MSG) + Using `delete` is blocked because it skips audit logging (and other Rails callbacks)! + Consider using `#destroy` instead, or pass `_force: true` as an argument. + MSG + expect { subject.update_column(:foo, 'bar') }.to raise_error(<<~MSG) + You are attempting to change the following audited columns: + [:foo] + + Using `update_column` is blocked because it skips audit logging (and other Rails callbacks)! + Consider using `#update!` instead, or pass `_force: true` as an argument. + MSG + expect { subject.update_columns(foo: 'bar') }.to raise_error(<<~MSG) + You are attempting to change the following audited columns: + [:foo] + + Using `update_columns` is blocked because it skips audit logging (and other Rails callbacks)! + Consider using `#update!` instead, or pass `_force: true` as an argument. + MSG + end + + it 'does not block the action if _force: true is passed' do + expect { subject.delete(_force: true) }.to not_raise_error + expect { subject.update_column(:foo, 'bar', _force: true) }.to not_raise_error + expect { subject.update_columns(foo: 'bar', _force: true) }.to not_raise_error + end + end + end + + describe '.delete_all, .insert, .insert_all, .update_all, .upsert, .upsert_all' do + subject { MyModel } + + before do + auditable_model.class_eval do + def self.delete_all(*); end + def self.insert(*); end + def self.insert_all(*); end + def self.update_all(*); end + def self.upsert(*); end + def self.upsert_all(*); end + end + end + + it 'does not block calls (because audit logging is disabled)' do + expect { subject.delete_all }.to not_raise_error + expect { subject.insert(foo: 'bar') }.to not_raise_error + expect { subject.insert_all([{ foo: 'bar' }]) }.to not_raise_error + expect { subject.update_all([{ foo: 'bar' }]) }.to not_raise_error + expect { subject.upsert(foo: 'bar') }.to not_raise_error + expect { subject.upsert_all([{ foo: 'bar' }]) }.to not_raise_error + end + + context 'when audit logging is enabled' do + before { auditable_model.class_eval { has_audit_log } } + + it 'blocks the action' do + expect { subject.delete_all }.to raise_error(<<~MSG) + `delete_all` is blocked because it skips callbacks and audit logs! + Consider using `.destroy_all` instead, or pass `_force: true` as an argument. + MSG + expect { subject.insert(foo: 'bar') }.to raise_error(<<~MSG) + `insert` is blocked because it skips callbacks and audit logs! + Consider using `.create!` instead, or pass `_force: true` as an argument. + MSG + expect { subject.insert_all([{ foo: 'bar' }]) }.to raise_error(<<~MSG) + `insert_all` is blocked because it skips callbacks and audit logs! + Consider using `.each { create!(...) }` instead, or pass `_force: true` as an argument. + MSG + expect { subject.update_all([{ foo: 'bar' }]) }.to raise_error(<<~MSG) + `update_all` is blocked because it skips callbacks and audit logs! + Consider using `.find_each { update!(...) }` instead, or pass `_force: true` as an argument. + MSG + expect { subject.upsert(foo: 'bar') }.to raise_error(<<~MSG) + `upsert` is blocked because it skips callbacks and audit logs! + Consider using `.create_or_find_by!` instead, or pass `_force: true` as an argument. + MSG + expect { subject.upsert_all([{ foo: 'bar' }]) }.to raise_error(<<~MSG) + `upsert_all` is blocked because it skips callbacks and audit logs! + Consider using `.each { create_or_find_by!(...) }` instead, or pass `_force: true` as an argument. + MSG + end + + it 'does not block the action when _force: true is passed' do + expect { subject.delete_all(_force: true) }.to not_raise_error + expect { subject.insert(foo: 'bar', _force: true) }.to not_raise_error + expect { subject.insert_all([{ foo: 'bar' }], _force: true) }.to not_raise_error + expect { subject.update_all([{ foo: 'bar' }], _force: true) }.to not_raise_error + expect { subject.upsert(foo: 'bar', _force: true) }.to not_raise_error + expect { subject.upsert_all([{ foo: 'bar' }], _force: true) }.to not_raise_error + end + end + end + # rubocop:enable Rails/SkipsModelValidations +end diff --git a/spec/spec_helper.rb b/spec/spec_helper.rb index a5b1367..7a091e5 100644 --- a/spec/spec_helper.rb +++ b/spec/spec_helper.rb @@ -1,9 +1,8 @@ rails_env = ENV['RAILS_ENV'] ||= 'test' require 'uncruft' -require File.expand_path('dummy/config/environment.rb', __dir__) +require 'active_support/testing/time_helpers' -Rails.application.config.active_record.sqlite3.represent_boolean_as_integer = true if Rails::VERSION::MAJOR < 6 -Rails.application.config.active_record.legacy_connection_handling = false if Rails::VERSION::MAJOR >= 7 +require File.expand_path('dummy/config/environment.rb', __dir__) Rails.configuration.database_configuration[rails_env].tap do |c| ActiveRecord::Tasks::DatabaseTasks.create(c) @@ -12,8 +11,11 @@ end RSpec::Matchers.define_negated_matcher :not_change, :change +RSpec::Matchers.define_negated_matcher :not_raise_error, :raise_error RSpec.configure do |config| + config.include ActiveSupport::Testing::TimeHelpers + config.expect_with :rspec do |expectations| expectations.include_chain_clauses_in_custom_matcher_descriptions = true end @@ -24,3 +26,44 @@ config.order = :random end + +RSpec::Matchers.define :emit_notification do |expected_event_name| + attr_reader :actual, :expected + + def supports_block_expectations? + true + end + + chain :with_payload, :expected_payload + chain :with_value, :expected_value + diffable + + match do |block| + @expected = { event_name: expected_event_name, payload: expected_payload, value: expected_value } + @actuals = [] + callback = ->(name, _started, _finished, _unique_id, payload) do + @actuals << { event_name: name, payload: payload.except(:value), value: payload[:value] } + end + + ActiveSupport::Notifications.subscribed(callback, expected_event_name, &block) + + unless expected_payload + @actuals.each { |a| a.delete(:payload) } + @expected.delete(:payload) + end + + @actual = @actuals.select { |a| values_match?(@expected.except(:value), a.except(:value)) } + @expected = [@expected] + values_match?(@expected, @actual) + end + + failure_message do + <<~MSG + Expected the code block to emit: + #{@expected.first.inspect} + + But instead, the following were emitted: + #{(@actual.presence || @actuals).map(&:inspect).join("\n ")} + MSG + end +end