diff --git a/.rubocop.yml b/.rubocop.yml index bb4bb23d..49e88553 100644 --- a/.rubocop.yml +++ b/.rubocop.yml @@ -58,6 +58,10 @@ Style/ArgumentsForwarding: Style/Documentation: Enabled: false +Style/FormatStringToken: + Exclude: + - spec/tooling/rubocop/**/* + Style/HashSyntax: EnforcedShorthandSyntax: never diff --git a/Gemfile b/Gemfile index a1986501..22d34594 100644 --- a/Gemfile +++ b/Gemfile @@ -45,6 +45,7 @@ group :development, :test do gem 'shoulda-matchers', '~> 5.3' gem 'rspec_junit_formatter', '~> 0.6.0', require: false + gem 'rspec-parameterized', '~> 1.0' gem 'database_cleaner-active_record', '~> 2.1' @@ -66,3 +67,5 @@ gem 'graphql', '~> 2.1' gem 'seed-fu', '~> 2.3' gem 'sidekiq', '~> 7.1' + +gem 'lograge', '~> 0.14.0' diff --git a/Gemfile.lock b/Gemfile.lock index 71207007..b3cfd851 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -79,9 +79,12 @@ GEM base64 (0.2.0) bcrypt (3.1.20) bigdecimal (3.1.4) + binding_of_caller (1.0.0) + debug_inspector (>= 0.0.1) bootsnap (1.17.0) msgpack (~> 1.2) builder (3.2.4) + coderay (1.1.3) concurrent-ruby (1.2.2) connection_pool (2.4.1) crass (1.0.6) @@ -93,6 +96,7 @@ GEM debug (1.8.0) irb (>= 1.5.0) reline (>= 0.3.1) + debug_inspector (1.1.0) diff-lcs (1.5.0) docile (1.4.0) drb (2.2.0) @@ -115,6 +119,11 @@ GEM reline (>= 0.3.8) json (2.6.3) language_server-protocol (3.17.0.3) + lograge (0.14.0) + actionpack (>= 4) + activesupport (>= 4) + railties (>= 4) + request_store (~> 1.0) loofah (2.22.0) crass (~> 1.0.2) nokogiri (>= 1.12.0) @@ -145,6 +154,10 @@ GEM ast (~> 2.4.1) racc pg (1.5.4) + proc_to_ast (0.1.0) + coderay + parser + unparser psych (5.1.1.1) stringio puma (6.4.0) @@ -196,7 +209,13 @@ GEM regexp_parser (2.8.2) reline (0.4.1) io-console (~> 0.5) + request_store (1.5.1) + rack (>= 1.4) rexml (3.2.6) + rspec (3.12.0) + rspec-core (~> 3.12.0) + rspec-expectations (~> 3.12.0) + rspec-mocks (~> 3.12.0) rspec-core (3.12.2) rspec-support (~> 3.12.0) rspec-expectations (3.12.3) @@ -205,6 +224,17 @@ GEM rspec-mocks (3.12.6) diff-lcs (>= 1.2.0, < 2.0) rspec-support (~> 3.12.0) + rspec-parameterized (1.0.0) + rspec-parameterized-core (< 2) + rspec-parameterized-table_syntax (< 2) + rspec-parameterized-core (1.0.0) + parser + proc_to_ast + rspec (>= 2.13, < 4) + unparser + rspec-parameterized-table_syntax (1.0.1) + binding_of_caller + rspec-parameterized-core (< 2) rspec-rails (6.1.0) actionpack (>= 6.1) activesupport (>= 6.1) @@ -271,6 +301,9 @@ GEM tzinfo (2.0.6) concurrent-ruby (~> 1.0) unicode-display_width (2.5.0) + unparser (0.6.10) + diff-lcs (~> 1.3) + parser (>= 3.2.2.4) webrick (1.8.1) websocket-driver (0.7.6) websocket-extensions (>= 0.1.0) @@ -287,9 +320,11 @@ DEPENDENCIES debug factory_bot_rails (~> 6.2) graphql (~> 2.1) + lograge (~> 0.14.0) pg (~> 1.1) puma (>= 5.0) rails (~> 7.1.2) + rspec-parameterized (~> 1.0) rspec-rails (~> 6.0) rspec_junit_formatter (~> 0.6.0) rubocop-factory_bot (~> 2.23) diff --git a/app/controllers/application_controller.rb b/app/controllers/application_controller.rb index 13c271fb..6519f8ab 100644 --- a/app/controllers/application_controller.rb +++ b/app/controllers/application_controller.rb @@ -1,4 +1,5 @@ # frozen_string_literal: true class ApplicationController < ActionController::API + include Sagittarius::Loggable end diff --git a/app/controllers/graphql_controller.rb b/app/controllers/graphql_controller.rb index 01e785af..8d0c1239 100644 --- a/app/controllers/graphql_controller.rb +++ b/app/controllers/graphql_controller.rb @@ -25,12 +25,20 @@ def execute context = { current_user: current_user, } - result = SagittariusSchema.execute(query, variables: variables, context: context, operation_name: operation_name) - render json: result - rescue StandardError => e - raise e unless Rails.env.development? - handle_error_in_development(e) + Sagittarius::Context.with_context(user: { id: current_user&.id, username: current_user&.username }) do + result = SagittariusSchema.execute(query, variables: variables, context: context, operation_name: operation_name) + render json: result + rescue StandardError => e + logger.error message: e.message, backtrace: e.backtrace, exception_class: e.class + + if Rails.env.local? + render json: { errors: [{ message: e.message, backtrace: e.backtrace }], data: {} }, + status: :internal_server_error + else + render json: { message: 'Internal server error' }, status: :internal_server_error + end + end end # rubocop:enable Metrics/PerceivedComplexity # rubocop:enable Metrics/CyclomaticComplexity @@ -57,13 +65,6 @@ def prepare_variables(variables_param) end end - def handle_error_in_development(e) - logger.error e.message - logger.error e.backtrace.join("\n") - - render json: { errors: [{ message: e.message, backtrace: e.backtrace }], data: {} }, status: :internal_server_error - end - def find_authorization(authorization) return Authorization.new(:none, nil) if authorization.blank? diff --git a/app/jobs/application_job.rb b/app/jobs/application_job.rb index bef39599..d38becea 100644 --- a/app/jobs/application_job.rb +++ b/app/jobs/application_job.rb @@ -1,6 +1,7 @@ # frozen_string_literal: true class ApplicationJob < ActiveJob::Base + include Sagittarius::Loggable # Automatically retry jobs that encountered a deadlock # retry_on ActiveRecord::Deadlocked diff --git a/config/application.rb b/config/application.rb index 37962d17..1eec1e16 100644 --- a/config/application.rb +++ b/config/application.rb @@ -18,6 +18,26 @@ class Application < Rails::Application # like if you have constraints or database-specific column types config.active_record.schema_format = :sql + # Enable sql log tags + config.active_record.query_log_tags_enabled = true + config.active_record.query_log_tags = [ + :controller, + :job, + { + correlation_id: -> { Sagittarius::Context.correlation_id }, + user_id: -> { Sagittarius::Context.current&.[](:user)&.[](:id) }, + user_name: -> { Sagittarius::Context.current&.[](:user)&.[](:username) }, + application: lambda { + if Rails.const_defined?('Console') + 'console' + else + Sagittarius::Context.current&.[](:application) || 'unknown' + end + }, + } + ] + ActiveRecord::QueryLogs.prepend_comment = true + Rails.application.default_url_options = if ENV['SAGITTARIUS_RAILS_HOSTNAME'].nil? { @@ -37,6 +57,9 @@ class Application < Rails::Application # Common ones are `templates`, `generators`, or `middleware`, for example. config.autoload_lib(ignore: %w[assets tasks]) + # Configure active job to use sidekiq + config.active_job.queue_adapter = :sidekiq + # Generated with 'bin/rails db:encryption:init' # Use some random generated keys, production will override this with the environment variables config.active_record.encryption.primary_key = ENV.fetch('SAGITTARIUS_DATABASE_ENCRYPTION_PRIMARY_KEY', diff --git a/config/environments/production.rb b/config/environments/production.rb index 12617103..899ccded 100644 --- a/config/environments/production.rb +++ b/config/environments/production.rb @@ -1,6 +1,7 @@ # frozen_string_literal: true require 'active_support/core_ext/integer/time' +require_relative '../../lib/sagittarius/utils' Rails.application.configure do # Settings specified here will take precedence over those in config/application.rb. @@ -44,7 +45,7 @@ # config.assume_ssl = true # Force all access to the app over SSL, use Strict-Transport-Security, and use secure cookies. - config.force_ssl = true + config.force_ssl = Sagittarius::Utils.to_boolean(ENV.fetch('RAILS_FORCE_SSL', nil), default: true) # Log to STDOUT by default config.logger = ActiveSupport::Logger.new($stdout) diff --git a/config/initializers/context.rb b/config/initializers/context.rb new file mode 100644 index 00000000..157b748e --- /dev/null +++ b/config/initializers/context.rb @@ -0,0 +1,7 @@ +# frozen_string_literal: true + +require_relative '../../lib/sagittarius/context' +require_relative '../../lib/sagittarius/middleware/rack' + +Rails.application.config.middleware.move(1, ActionDispatch::RequestId) +Rails.application.config.middleware.insert(1, Sagittarius::Middleware::Rack) diff --git a/config/initializers/filter_parameter_logging.rb b/config/initializers/filter_parameter_logging.rb index c416e6a6..b6d5b30b 100644 --- a/config/initializers/filter_parameter_logging.rb +++ b/config/initializers/filter_parameter_logging.rb @@ -6,5 +6,5 @@ # Use this to limit dissemination of sensitive information. # See the ActiveSupport::ParameterFilter documentation for supported notations and behaviors. Rails.application.config.filter_parameters += %i[ - passw secret token _key crypt salt certificate otp ssn + passw secret token _key crypt salt certificate otp ssn query variables ] diff --git a/config/initializers/logger.rb b/config/initializers/logger.rb new file mode 100644 index 00000000..b419f895 --- /dev/null +++ b/config/initializers/logger.rb @@ -0,0 +1,13 @@ +# frozen_string_literal: true + +require_relative '../../lib/sagittarius/logs/json_formatter' + +Rails.application.configure do + config.lograge.enabled = true + config.lograge.base_controller_class = 'ActionController::API' + config.lograge.formatter = Lograge::Formatters::Raw.new # let formatting be done by our own formatter +end + +Rails.logger.formatter = Sagittarius::Logs::JsonFormatter::Tagged.new + +Rails.application.config.colorize_logging = Rails.const_defined? 'Console' diff --git a/config/initializers/sidekiq.rb b/config/initializers/sidekiq.rb index daa7f733..334d7ad7 100644 --- a/config/initializers/sidekiq.rb +++ b/config/initializers/sidekiq.rb @@ -6,10 +6,29 @@ redis_host = "redis://#{redis_host}:#{redis_port}/#{redis_database}" -Sidekiq.configure_server do |config| - config.redis = { url: redis_host } -end +Rails.application.config.to_prepare do + Sidekiq.configure_server do |config| + config.redis = { url: redis_host } + config.server_middleware do |chain| + chain.add Sagittarius::Middleware::Sidekiq::Context::Server + end + + config.logger.formatter = Class.new(Sidekiq::Logger::Formatters::Base) do + def call(severity, time, _progname, message) + @formatter ||= Sagittarius::Logs::JsonFormatter.new + + data = @formatter.data(severity, time, message) + data.merge!(context: ctx) unless ctx.empty? + + Sidekiq.dump_json(data) << "\n" + end + end.new + end -Sidekiq.configure_client do |config| - config.redis = { url: redis_host } + Sidekiq.configure_client do |config| + config.redis = { url: redis_host } + config.client_middleware do |chain| + chain.add Sagittarius::Middleware::Sidekiq::Context::Client + end + end end diff --git a/lib/sagittarius/context.rb b/lib/sagittarius/context.rb new file mode 100644 index 00000000..ac01bd56 --- /dev/null +++ b/lib/sagittarius/context.rb @@ -0,0 +1,131 @@ +# frozen_string_literal: true + +module Sagittarius + class Context + LOG_KEY = 'meta' + CORRELATION_ID_KEY = 'correlation_id' + RAW_KEYS = [CORRELATION_ID_KEY].freeze + + class << self + def with_context(attributes = {}) + context = push(attributes) + + begin + yield(context) + ensure + pop(context) + end + end + + def push(new_attributes = {}) + new_context = current&.merge(new_attributes) || new(new_attributes) + + contexts.push(new_context) + + new_context + end + + def pop(context) + contexts.pop while contexts.include?(context) + end + + def correlation_id + current&.correlation_id + end + + def current + contexts.last + end + + def log_key(key) + key = key.to_s + return key if RAW_KEYS.include?(key) + return key if key.start_with?("#{LOG_KEY}.") + + "#{LOG_KEY}.#{key}" + end + + private + + def contexts + Thread.current[:labkit_contexts] ||= [] + end + end + + def initialize(values = {}) + @data = {} + + assign_attributes(values) + end + + def merge(new_attributes) + new_context = self.class.new(data.dup) + new_context.assign_attributes(new_attributes) + + new_context + end + + def to_h + expand_data + end + + def [](key) + to_h[log_key(key)] + end + + def correlation_id + data[CORRELATION_ID_KEY] + end + + def get_attribute(attribute) + raw = call_or_value(data[log_key(attribute)]) + + call_or_value(raw) + end + + protected + + def assign_attributes(attributes) + attributes = attributes.transform_keys(&method(:log_key)) + + data.merge!(attributes) + + # Remove keys that had their values set to `nil` in the new attributes + data.keep_if { |_, value| valid_data?(value) } + + # Assign a correlation if it was missing in the first context or when + # explicitly removed + data[CORRELATION_ID_KEY] ||= new_id + + data + end + + private + + attr_reader :data + + def log_key(key) + self.class.log_key(key) + end + + def call_or_value(value) + value.respond_to?(:call) ? value.call : value + end + + def expand_data + data.transform_values do |value| + value = call_or_value(value) + + value if valid_data?(value) + end.compact + end + + def new_id + SecureRandom.hex + end + + def valid_data?(value) + value == false || value.present? + end + end +end diff --git a/lib/sagittarius/loggable.rb b/lib/sagittarius/loggable.rb new file mode 100644 index 00000000..d25f1524 --- /dev/null +++ b/lib/sagittarius/loggable.rb @@ -0,0 +1,46 @@ +# frozen_string_literal: true + +module Sagittarius + module Loggable + extend ActiveSupport::Concern + + class_methods do + def logger + Logger.new(Rails.logger, name || '') + end + end + + def logger + Logger.new(Rails.logger, self.class.name || '') + end + + class Logger + def initialize(log, clazz) + @log = log + @clazz = clazz + end + + delegate :debug?, :info?, :warn?, :error?, :fatal?, :formatter, :level, to: :@log + + def with_context(&block) + Context.with_context(class: @clazz, &block) + end + + def debug(message) + with_context { @log.debug(message) } + end + + def error(message) + with_context { @log.error(message) } + end + + def warn(message) + with_context { @log.warn(message) } + end + + def info(message) + with_context { @log.info(message) } + end + end + end +end diff --git a/lib/sagittarius/logs/json_formatter.rb b/lib/sagittarius/logs/json_formatter.rb new file mode 100644 index 00000000..99fced63 --- /dev/null +++ b/lib/sagittarius/logs/json_formatter.rb @@ -0,0 +1,40 @@ +# frozen_string_literal: true + +module Sagittarius + module Logs + class JsonFormatter < ::Logger::Formatter + def call(severity, datetime, _progname, message) + JSON.generate(data(severity, datetime, message)) << "\n" + end + + def data(severity, datetime, message) + data = {} + data[:severity] = severity + data[:time] = datetime.utc.iso8601(3) + + case message + when String + data[:message] = chomp message + when Hash + data.merge!(message) + end + + data.merge!(Context.current.to_h) + end + + def chomp(message) + message.chomp! until message.chomp == message + + message.strip + end + + class Tagged < JsonFormatter + include ActiveSupport::TaggedLogging::Formatter + + def tagged(*_args) + yield self # Ignore tags, they break the json layout as they are prepended to the log line + end + end + end + end +end diff --git a/lib/sagittarius/middleware/rack.rb b/lib/sagittarius/middleware/rack.rb new file mode 100644 index 00000000..b96f29af --- /dev/null +++ b/lib/sagittarius/middleware/rack.rb @@ -0,0 +1,33 @@ +# frozen_string_literal: true + +module Sagittarius + module Middleware + class Rack + def initialize(app) + @app = app + end + + def call(env) + Sagittarius::Context.with_context( + Sagittarius::Context::CORRELATION_ID_KEY => correlation_id(env), + Sagittarius::Context.log_key(:application) => 'puma' + ) do |context| + status, headers, response = @app.call env + headers['X-Sagittarius-Meta'] = context_to_json context + [status, headers, response] + end + end + + def correlation_id(env) + ActionDispatch::Request.new(env).request_id + end + + def context_to_json(context) + context + .to_h + .transform_keys { |k| k.delete_prefix("#{Sagittarius::Context::LOG_KEY}.") } + .to_json + end + end + end +end diff --git a/lib/sagittarius/middleware/sidekiq/context/client.rb b/lib/sagittarius/middleware/sidekiq/context/client.rb new file mode 100644 index 00000000..027cc88c --- /dev/null +++ b/lib/sagittarius/middleware/sidekiq/context/client.rb @@ -0,0 +1,21 @@ +# frozen_string_literal: true + +module Sagittarius + module Middleware + module Sidekiq + module Context + class Client + include ::Sidekiq::ClientMiddleware + + def call(_job_class, job, _queue, _redis_pool) + Sagittarius::Context.with_context do |context| + job.merge!(context.to_h) + + yield + end + end + end + end + end + end +end diff --git a/lib/sagittarius/middleware/sidekiq/context/server.rb b/lib/sagittarius/middleware/sidekiq/context/server.rb new file mode 100644 index 00000000..18910375 --- /dev/null +++ b/lib/sagittarius/middleware/sidekiq/context/server.rb @@ -0,0 +1,25 @@ +# frozen_string_literal: true + +module Sagittarius + module Middleware + module Sidekiq + module Context + class Server + include ::Sidekiq::ServerMiddleware + + def call(_job_instance, job_payload, _queue, &block) + job_name = (job_payload['wrapped'].presence || job_payload['class']).to_s + data = job_payload.merge(Sagittarius::Context.log_key(:caller_id) => job_name, + Sagittarius::Context.log_key(:jid) => job_payload['jid'], + Sagittarius::Context.log_key(:application) => 'sidekiq') + .select do |key, _| + key.start_with?("#{Sagittarius::Context::LOG_KEY}.") || Sagittarius::Context::RAW_KEYS.include?(key.to_s) + end + + Sagittarius::Context.with_context(data, &block) + end + end + end + end + end +end diff --git a/lib/sagittarius/utils.rb b/lib/sagittarius/utils.rb new file mode 100644 index 00000000..4a9fc779 --- /dev/null +++ b/lib/sagittarius/utils.rb @@ -0,0 +1,17 @@ +# frozen_string_literal: true + +module Sagittarius + module Utils + module_function + + def to_boolean(value, default: nil) + value = value.to_s if [0, 1].include?(value) + + return value if [true, false].include?(value) + return true if value =~ /^(true|t|yes|y|1|on)$/i + return false if value =~ /^(false|f|no|n|0|off)$/i + + default + end + end +end diff --git a/spec/lib/sagittarius/context_spec.rb b/spec/lib/sagittarius/context_spec.rb new file mode 100644 index 00000000..c96c75d6 --- /dev/null +++ b/spec/lib/sagittarius/context_spec.rb @@ -0,0 +1,281 @@ +# frozen_string_literal: true + +require 'rails_helper' + +RSpec.describe Sagittarius::Context do + describe '.with_context' do + it 'builds a context with values from the previous one', :aggregate_failures do + inner = nil + outer = nil + + described_class.with_context(described_class::CORRELATION_ID_KEY => 'hello') do |outer_context| + outer = outer_context + described_class.with_context(user: 'username') do |inner_context| + inner = inner_context + end + end + + expect(data_from(outer)).to eq(log_hash(described_class::CORRELATION_ID_KEY => 'hello')) + expect(data_from(inner)).to eq(log_hash(described_class::CORRELATION_ID_KEY => 'hello', 'user' => 'username')) + end + + it 'builds a context with overwritten key/values in the newer context', :aggregate_failures do + inner = nil + outer = nil + + described_class.with_context(caller_id: 'foo') do |outer_context| + outer = outer_context + described_class.with_context(caller_id: 'bar') do |inner_context| + inner = inner_context + end + end + + expect(data_from(outer)).to include(log_hash(caller_id: 'foo')) + expect(data_from(inner)).to include(log_hash(caller_id: 'bar')) + end + + it 'yields the block' do + expect { |b| described_class.with_context(&b) }.to yield_control + end + + it "pushes the context on the stack while it's running" do + described_class.with_context do |outer| + described_class.with_context do |inner| + expect(contexts).to eq([outer, inner]) + end + end + end + + it 'pops the context from the stack when the block fails', :aggregate_failures do + expect { described_class.with_context { |_| raise('broken') } }.to raise_error('broken') + + expect(contexts).to be_empty + end + end + + describe '.push' do + let!(:root_context) { described_class.push } + + after do + described_class.pop(root_context) + end + + it 'pushes a new context on the stack' do + context = described_class.push + + expect(contexts).to eq([root_context, context]) + end + + it 'merges the attributes of the context with the previous one' do + expected_values = { described_class::CORRELATION_ID_KEY => root_context.correlation_id, + 'root_namespace' => 'namespace' } + + context = described_class.push(root_namespace: 'namespace') + + expect(data_from(context)).to eq(log_hash(expected_values)) + end + end + + describe '.pop' do + let!(:root_context) { described_class.push } + + after do + described_class.pop(root_context) + end + + it 'pops all context up to and including the given one' do + second_context = described_class.push + _third_context = described_class.push + + described_class.pop(second_context) + + expect(contexts).to contain_exactly(root_context) + end + end + + describe '.current' do + let!(:root_context) { described_class.push } + + after do + described_class.pop(root_context) + end + + it 'returns the last context', :aggregate_failures do + expect(described_class.current).to eq(root_context) + + new_context = described_class.push + + expect(described_class.current).to eq(new_context) + end + end + + describe '#to_h' do + let(:expected_hash) do + log_hash(user: 'user', + root_namespace: 'namespace', + project: 'project', + 'random.key': 'included') + end + + it 'returns a hash containing the expected values' do + context = described_class.new(user: 'user', + project: 'project', + root_namespace: 'namespace', + 'random.key': 'included') + + expect(context.to_h).to include(expected_hash) + end + + it 'returns a new hash every call' do + context = described_class.new + + expect(context.to_h.object_id).not_to eq(context.to_h.object_id) + end + + it 'loads the lazy values' do + context = described_class.new( + user: -> { 'user' }, + root_namespace: -> { 'namespace' }, + project: -> { 'project' }, + 'random.key': -> { 'included' } + ) + + expect(context.to_h).to include(expected_hash) + end + + it 'does not change the original data' do + context = described_class.new( + user: -> { 'user' }, + root_namespace: -> { 'namespace' }, + project: -> { 'project' } + ) + + expect { context.to_h }.not_to(change { data_from(context) }) + end + + it 'does not include empty values' do + context = described_class.new( + user: -> {}, + root_namespace: nil, + project: '' + ) + + expect(context.to_h.keys).to contain_exactly(described_class::CORRELATION_ID_KEY) + end + end + + describe '#initialize' do + it 'assigns all keys as strings' do + context = described_class.new( # -- deliberately testing asigning symbols and strings as keys + user: 'u', + 'project' => 'p', + something_else: 'nothing' + ) + + expect(data_from(context)).to include(log_hash('user' => 'u', 'project' => 'p', 'something_else' => 'nothing')) + end + + it 'assigns known keys starting with the log key' do + context = described_class.new( + log_hash(project: 'p', root_namespace: 'n', user: 'u', something_else: 'nothing') + ) + + expect(data_from(context)).to include(log_hash('project' => 'p', 'root_namespace' => 'n', 'user' => 'u', + 'something_else' => 'nothing')) + end + + it 'always assigns a correlation id' do + expect(described_class.new.correlation_id).not_to be_empty + end + end + + describe '#merge' do + it 'returns a new context with duplicated data', :aggregate_failures do + context = described_class.new(user: 'user') + + new_context = context.merge({}) + + expect(context.to_h).to eq(new_context.to_h) + expect(context).not_to eq(new_context) + end + + it 'merges values into the existing context' do + context = described_class.new(project: 'p', root_namespace: 'n', user: 'u') + + new_context = context.merge(project: '', root_namespace: 'namespace') + + expect(data_from(new_context)).to include(log_hash('root_namespace' => 'namespace', 'user' => 'u')) + end + + it 'removes empty values', :aggregate_failures do + context = described_class.new(project: 'p', root_namespace: 'n', user: 'u') + + new_context = context.merge(project: '', user: nil) + + expect(data_from(new_context)).to include(log_hash('root_namespace' => 'n')) + expect(data_from(new_context).keys).not_to include(described_class.log_key('project'), + described_class.log_key('user')) + end + + it 'keeps false values', :aggregate_failures do + context = described_class.new(project: 'p', root_namespace: 'n', flag: false) + + new_context = context.merge(project: '', false: nil) # rubocop:disable Lint/BooleanSymbol -- intended for this spec + + expect(data_from(new_context)).to include(log_hash('root_namespace' => 'n', 'flag' => false)) + expect(context.to_h).to include(log_hash('root_namespace' => 'n', 'flag' => false)) + end + + it 'does not overwrite the correlation id' do + context = described_class.new(described_class::CORRELATION_ID_KEY => 'hello') + + new_context = context.merge(user: 'u') + + expect(new_context.correlation_id).to eq('hello') + end + + it 'generates a new correlation id if a blank one was passed', :aggregate_failures do + context = described_class.new + old_correlation_id = context.correlation_id + + new_context = context.merge(described_class::CORRELATION_ID_KEY => '') + + expect(new_context.correlation_id).not_to be_empty + expect(new_context.correlation_id).not_to eq(old_correlation_id) + end + end + + describe '#get_attribute' do + using RSpec::Parameterized::TableSyntax + + where(:set_context, :attribute, :expected_value) do + [ + [{}, :caller_id, nil], + [{ caller_id: 'caller' }, :caller_id, 'caller'], + [{ caller_id: -> { 'caller' } }, :caller_id, 'caller'], + [{ caller_id: -> { 'caller' } }, 'caller_id', 'caller'], + [{ caller_id: -> { 'caller' } }, 'meta.caller_id', 'caller'] + ] + end + + with_them do + it 'returns the expected value for the attribute' do + described_class.with_context(set_context) do |context| + expect(context.get_attribute(attribute)).to eq(expected_value) + end + end + end + end + + def contexts + described_class.__send__(:contexts) + end + + def data_from(context) + context.__send__(:data) + end + + def log_hash(hash) + hash.transform_keys! { |key| described_class.log_key(key) } + end +end diff --git a/spec/lib/sagittarius/loggable_spec.rb b/spec/lib/sagittarius/loggable_spec.rb new file mode 100644 index 00000000..37a4c1fa --- /dev/null +++ b/spec/lib/sagittarius/loggable_spec.rb @@ -0,0 +1,45 @@ +# frozen_string_literal: true + +require 'rails_helper' + +RSpec.describe Sagittarius::Loggable do + let(:clazz) do + Class.new do + include Sagittarius::Loggable + end + end + + context 'with named class' do + around do |example| + Object.const_set('TestClass', clazz) + example.run + Object.send(:remove_const, 'TestClass') + end + + it 'for instantiated class' do + TestClass.new.logger.with_context do |context| + expect(context.to_h).to include(Sagittarius::Context.log_key(:class) => 'TestClass') + end + end + + it 'when called on the class' do + TestClass.logger.with_context do |context| + expect(context.to_h).to include(Sagittarius::Context.log_key(:class) => 'TestClass') + end + end + end + + context 'with anonymous class' do + it 'for instantiated class' do + clazz.new.logger.with_context do |context| + expect(context.to_h).to include(Sagittarius::Context.log_key(:class) => '') + end + end + + it 'when called on the class' do + clazz.logger.with_context do |context| + expect(context.to_h).to include(Sagittarius::Context.log_key(:class) => '') + end + end + end +end diff --git a/spec/lib/sagittarius/middleware/rack_spec.rb b/spec/lib/sagittarius/middleware/rack_spec.rb new file mode 100644 index 00000000..c742b134 --- /dev/null +++ b/spec/lib/sagittarius/middleware/rack_spec.rb @@ -0,0 +1,53 @@ +# frozen_string_literal: true + +require 'rails_helper' + +RSpec.describe Sagittarius::Middleware::Rack do + let(:app) { double('app') } # rubocop:disable RSpec/VerifiedDoubles + let(:correlation_id) { 'the id' } + let(:metadata) { { 'user' => { 'id' => 1 } } } + let(:header_metadata) do + metadata.merge({ + Sagittarius::Context::CORRELATION_ID_KEY => correlation_id, + 'application' => 'puma', + }) + end + let(:env) { {} } + let(:fake_request) { double('request') } # rubocop:disable RSpec/VerifiedDoubles + + before do + allow(ActionDispatch::Request).to receive(:new).with(env).and_return(fake_request) + allow(fake_request).to receive(:request_id).and_return(correlation_id) + end + + describe '#call' do + it 'adds the correlation id from the request to the context' do + allow(Sagittarius::Context).to receive(:with_context) + + described_class.new(app).call(env) + + expect(Sagittarius::Context).to have_received(:with_context).with( + a_hash_including(Sagittarius::Context::CORRELATION_ID_KEY => correlation_id) + ) + end + + it 'calls the app' do + allow(app).to receive(:call).with(env).and_return([nil, {}, nil]) + + described_class.new(app).call(env) + + expect(app).to have_received(:call).with(env) + end + + it 'injects meta headers', :aggregate_failures do + Sagittarius::Context.push(metadata) + + allow(app).to receive(:call).with(env).and_return([nil, {}, nil]) + + _, headers, = described_class.new(app).call(env) + + expect(app).to have_received(:call).with(env) + expect(JSON.parse(headers['X-Sagittarius-Meta'])).to eq(header_metadata) + end + end +end diff --git a/spec/lib/sagittarius/utils_spec.rb b/spec/lib/sagittarius/utils_spec.rb new file mode 100644 index 00000000..76f569a2 --- /dev/null +++ b/spec/lib/sagittarius/utils_spec.rb @@ -0,0 +1,61 @@ +# frozen_string_literal: true + +require 'spec_helper' +require_relative '../../../lib/sagittarius/utils' + +RSpec.describe Sagittarius::Utils do + describe '.to_boolean' do + it 'accepts booleans', :aggregate_failures do + expect(described_class.to_boolean(true)).to be(true) + expect(described_class.to_boolean(false)).to be(false) + end + + it 'converts a valid value to a boolean', :aggregate_failures do + expect(described_class.to_boolean(true)).to be(true) + expect(described_class.to_boolean('true')).to be(true) + expect(described_class.to_boolean('YeS')).to be(true) + expect(described_class.to_boolean('t')).to be(true) + expect(described_class.to_boolean('1')).to be(true) + expect(described_class.to_boolean(1)).to be(true) + expect(described_class.to_boolean('ON')).to be(true) + + expect(described_class.to_boolean('FaLse')).to be(false) + expect(described_class.to_boolean('F')).to be(false) + expect(described_class.to_boolean('NO')).to be(false) + expect(described_class.to_boolean('n')).to be(false) + expect(described_class.to_boolean('0')).to be(false) + expect(described_class.to_boolean(0)).to be(false) + expect(described_class.to_boolean('oFF')).to be(false) + end + + it 'converts an invalid value to nil', :aggregate_failures do + expect(described_class.to_boolean('fals')).to be_nil + expect(described_class.to_boolean('yeah')).to be_nil + expect(described_class.to_boolean('')).to be_nil + expect(described_class.to_boolean(nil)).to be_nil + end + + it 'accepts a default value, and does not return it when a valid value is given', :aggregate_failures do + expect(described_class.to_boolean(true, default: false)).to be(true) + expect(described_class.to_boolean('true', default: false)).to be(true) + expect(described_class.to_boolean('YeS', default: false)).to be(true) + expect(described_class.to_boolean('t', default: false)).to be(true) + expect(described_class.to_boolean('1', default: 'any value')).to be(true) + expect(described_class.to_boolean('ON', default: 42)).to be(true) + + expect(described_class.to_boolean('FaLse', default: true)).to be(false) + expect(described_class.to_boolean('F', default: true)).to be(false) + expect(described_class.to_boolean('NO', default: true)).to be(false) + expect(described_class.to_boolean('n', default: true)).to be(false) + expect(described_class.to_boolean('0', default: 'any value')).to be(false) + expect(described_class.to_boolean('oFF', default: 42)).to be(false) + end + + it 'accepts a default value, and returns it when an invalid value is given', :aggregate_failures do + expect(described_class.to_boolean('fals', default: true)).to be(true) + expect(described_class.to_boolean('yeah', default: false)).to be(false) + expect(described_class.to_boolean('', default: 'any value')).to eq('any value') + expect(described_class.to_boolean(nil, default: 42)).to eq(42) + end + end +end diff --git a/spec/spec_helper.rb b/spec/spec_helper.rb index 143bbdcb..4f01a28f 100644 --- a/spec/spec_helper.rb +++ b/spec/spec_helper.rb @@ -22,6 +22,8 @@ ) end +require 'rspec-parameterized' + # This file was generated by the `rails generate rspec:install` command. Conventionally, all # specs live under a `spec` directory, which RSpec adds to the `$LOAD_PATH`. # The generated `.rspec` file contains `--require spec_helper` which will cause diff --git a/spec/tooling/rubocop/cop/sagittarius/logs/rails_logger_spec.rb b/spec/tooling/rubocop/cop/sagittarius/logs/rails_logger_spec.rb new file mode 100644 index 00000000..59fcecdb --- /dev/null +++ b/spec/tooling/rubocop/cop/sagittarius/logs/rails_logger_spec.rb @@ -0,0 +1,30 @@ +# frozen_string_literal: true + +require 'rubocop_spec_helper' +require_relative '../../../../../../tooling/rubocop/cop/sagittarius/logs/rails_logger' + +RSpec.describe RuboCop::Cop::Sagittarius::Logs::RailsLogger do + described_class::LOG_METHODS.each do |method| + it "flags the use of Rails.logger.#{method} with a constant receiver" do + node = "Rails.logger.#{method}('some error')" + msg = 'Do not use `Rails.logger` directly, include `Sagittarius::Loggable` instead' + + expect_offense(<<~CODE, node: node, msg: msg) + %{node} + ^{node} %{msg} + CODE + end + end + + it 'does not flag the use of Rails.logger with a constant that is not Rails' do + expect_no_offenses("AppLogger.error('some error')") + end + + it 'does not flag the use of logger with a send receiver' do + expect_no_offenses("file_logger.info('important info')") + end + + it 'does not flag the use of Rails.logger.level' do + expect_no_offenses('Rails.logger.level') + end +end diff --git a/tooling/rubocop/cop/sagittarius/logs/rails_logger.rb b/tooling/rubocop/cop/sagittarius/logs/rails_logger.rb new file mode 100644 index 00000000..7a29320a --- /dev/null +++ b/tooling/rubocop/cop/sagittarius/logs/rails_logger.rb @@ -0,0 +1,29 @@ +# frozen_string_literal: true + +module RuboCop + module Cop + module Sagittarius + module Logs + # Cop that checks if 'timestamps' method is called with timezone information. + class RailsLogger < RuboCop::Cop::Base + MSG = 'Do not use `Rails.logger` directly, include `Sagittarius::Loggable` instead' + LOG_METHODS = %i[debug error fatal info warn].freeze + LOG_METHODS_PATTERN = LOG_METHODS.map(&:inspect).join(' ').freeze + + def_node_matcher :rails_logger_log?, <<~PATTERN + (send + (send (const nil? :Rails) :logger) + {#{LOG_METHODS_PATTERN}} ... + ) + PATTERN + + def on_send(node) + return unless rails_logger_log?(node) + + add_offense(node) + end + end + end + end + end +end