Merge branch 'malvarez-group-application-context-logs' into 'master' (3d55b44e) · Commits · GitLab.org / ruby / gems / labkit-ruby

doc/FIELD_STANDARDIZATION.md

+2 −1

Original line number	Diff line number	Diff line
		@@ -18,7 +18,8 @@ For the architectural decision and rationale, see

		Offense
		: A unique combination of file path, deprecated field, and logger class.
		Multiple log calls in the same file using the same deprecated field count as
		Multiple log calls in the same file using the same deprecated field or multiple
		log calls originating from the application context count as
		one offense.
		An offense exists until the deprecated field is entirely removed from the
		file.

lib/labkit/logging/field_validator/log_interceptor.rb

+49 −0

Original line number	Diff line number	Diff line
		@@ -15,6 +15,15 @@ module Labkit
		%r{/.*logger\.rb$}
		].freeze

		DEFAULT_CONTEXT_CALLSITE = "Labkit::Context"

		# Placeholder logger_class used when an offense originates from the Labkit
		# context. The same context fields appear in every logger that runs within
		# the context, so collapsing across loggers prevents one offense per
		# logger x deprecated_field combination, and prevents new offenses being
		# raised whenever a developer adds a new logger class.
		ANY_LOGGER = "*"

		class << self
		def register_wrapper_pattern(pattern)
		wrapper_patterns << pattern
		@@ -33,6 +42,31 @@ module Labkit
		def combined_ignore_pattern
		@combined_ignore_pattern \|\|= Regexp.union(IGNORE_PATHS + wrapper_patterns)
		end

		# The callsite name used for offenses originating from the Labkit context
		# (e.g. ApplicationContext) rather than from the log caller directly.
		# Override this in your application to point to the actual context provider file:
		# Labkit::Logging::FieldValidator::LogInterceptor.context_callsite =
		# "lib/gitlab/application_context.rb"
		def context_callsite
		@context_callsite \|\| DEFAULT_CONTEXT_CALLSITE
		end

		attr_writer :context_callsite

		def reset_context_callsite!
		@context_callsite = nil
		end

		# The context prefix that Labkit::Context applies to every field it
		# stores (see Labkit::Context::LOG_KEY). Any deprecated field with
		# this prefix is by convention a context field, owned by whichever
		# provider populates the context (e.g. ApplicationContext), even
		# when a particular log call happens to pass it directly. Lazily
		# built so the constant is not referenced at load time.
		def context_field_prefix
		@context_field_prefix \|\|= "#{::Labkit::Context::LOG_KEY}."
		end
		end

		def format_data(severity, timestamp, progname, message)
		@@ -46,6 +80,13 @@ module Labkit

		logger_class = self.class.name \|\| 'AnonymousLogger'

		# Keys the caller explicitly passed in the log message. Any deprecated field
		# present in `data` but absent here arrived via Labkit::Context (e.g.
		# ApplicationContext) and should be attributed to the context callsite rather
		# than the individual log call site.
		direct_keys = message.is_a?(Hash) ? message.transform_keys(&:to_s).keys.to_set : Set.new
		context_prefix = LogInterceptor.context_field_prefix

		deprecated_lookup = Labkit::Fields::Deprecated.all
		if data.is_a?(Hash)
		data.each_key do \|key\|
		@@ -53,11 +94,19 @@ module Labkit
		standard_field = deprecated_lookup[key_str]
		next unless standard_field

		# context_prefix is the Labkit::Context namespace. The field is conceptually
		# context-owned even if the caller happens to pass it directly. Otherwise
		# use direct-vs-context based on whether the caller actually included it.
		if direct_keys.include?(key_str) && !key_str.start_with?(context_prefix)
		Registry.instance.record_offense(callsite_path, location.lineno, key_str, standard_field, logger_class)
		else
		Registry.instance.record_offense(LogInterceptor.context_callsite, 0, key_str, standard_field, ANY_LOGGER)
		end
		end
		end

		Registry.instance.check_for_removed_offenses(callsite_path, data, logger_class)
		Registry.instance.check_for_removed_offenses(LogInterceptor.context_callsite, data, ANY_LOGGER)

		data
		end

spec/labkit/logging/field_validator/log_interceptor_spec.rb

+184 −4

Original line number	Diff line number	Diff line
		@@ -20,7 +20,10 @@ RSpec.describe Labkit::Logging::FieldValidator::LogInterceptor do

		before do
		registry.clear!
		allow(Labkit::Fields::Deprecated).to receive(:all).and_return({ 'meta.user_id' => 'gl_user_id' })
		allow(Labkit::Fields::Deprecated).to receive(:all).and_return({
		'meta.user_id' => 'gl_user_id', # context-namespace field
		'old_field' => 'new_field' # non-namespace field
		})
		end

		around do \|example\|
		@@ -49,8 +52,8 @@ RSpec.describe Labkit::Logging::FieldValidator::LogInterceptor do
		expect(offense['deprecated_field']).to eq('meta.user_id')
		end

		it 'records the logger class' do
		test_logger.format_message('INFO', Time.now.utc, 'test', { 'meta.user_id' => 123 })
		it 'records the logger class for non-meta direct-message offenses' do
		test_logger.format_message('INFO', Time.now.utc, 'test', { 'old_field' => 123 })

		offense = registry.offenses.first
		# Anonymous classes use 'AnonymousLogger' as fallback
		@@ -98,14 +101,121 @@ RSpec.describe Labkit::Logging::FieldValidator::LogInterceptor do
		end
		end

		context 'when deprecated field originates from Labkit context (not the message)' do
		before do
		allow(test_logger).to receive(:determine_callsite).and_return(mock_location)
		end

		it 'attributes the offense to the context callsite, not the log callsite' do
		Labkit::Context.with_context('meta.user_id' => 456) do
		test_logger.format_message('INFO', Time.now.utc, 'test', { message: 'hello' })
		end

		expect(registry.offenses).not_to be_empty
		offense = registry.offenses.first
		expect(offense['callsite']).to eq(described_class.context_callsite)
		expect(offense['deprecated_field']).to eq('meta.user_id')
		end

		it 'records the offense under the ANY_LOGGER placeholder, not the actual class' do
		Labkit::Context.with_context('meta.user_id' => 456) do
		test_logger.format_message('INFO', Time.now.utc, 'test', { message: 'hello' })
		end

		expect(registry.offenses.first['logger_class'])
		.to eq(Labkit::Logging::FieldValidator::LogInterceptor::ANY_LOGGER)
		end

		it 'produces a single entry across multiple logger classes' do
		other_logger_class = Class.new(Labkit::Logging::JsonLogger) do
		prepend Labkit::Logging::FieldValidator::LogInterceptor
		end
		other_logger = other_logger_class.new(File::NULL)
		allow(other_logger).to receive(:determine_callsite).and_return(mock_location)

		Labkit::Context.with_context('meta.user_id' => 456) do
		test_logger.format_message('INFO', Time.now.utc, 'test', { message: 'hello' })
		other_logger.format_message('INFO', Time.now.utc, 'test', { message: 'hello' })
		end

		context_offenses = registry.offenses.select do \|o\|
		o['callsite'] == Labkit::Logging::FieldValidator::LogInterceptor.context_callsite
		end
		expect(context_offenses.size).to eq(1)
		end

		it 'records lineno 0 for context-originated offenses' do
		Labkit::Context.with_context('meta.user_id' => 456) do
		test_logger.format_message('INFO', Time.now.utc, 'test', { message: 'hello' })
		end

		expect(registry.offenses.first['lineno']).to eq(0)
		end

		it 'produces a single offense entry regardless of how many log calls occur' do
		Labkit::Context.with_context('meta.user_id' => 456) do
		3.times { test_logger.format_message('INFO', Time.now.utc, 'test', { message: 'hello' }) }
		end

		context_offenses = registry.offenses.select do \|o\|
		o['callsite'] == Labkit::Logging::FieldValidator::LogInterceptor.context_callsite
		end
		expect(context_offenses.size).to eq(1)
		end
		end

		context 'when a non-meta deprecated field is passed directly in the message' do
		before do
		allow(test_logger).to receive(:determine_callsite).and_return(mock_location)
		end

		it 'attributes the offense to the actual callsite with the actual logger class' do
		test_logger.format_message('INFO', Time.now.utc, 'test', { 'old_field' => 123 })

		expect(registry.offenses).not_to be_empty
		offense = registry.offenses.first
		expect(offense['callsite']).to eq('app/test.rb')
		expect(offense['deprecated_field']).to eq('old_field')
		expect(offense['logger_class']).to eq('AnonymousLogger')
		end
		end

		context 'when a meta.* deprecated field is passed directly in the message' do
		before do
		allow(test_logger).to receive(:determine_callsite).and_return(mock_location)
		end

		it 'attributes the offense to the context callsite (meta.* is the Labkit context namespace)' do
		test_logger.format_message('INFO', Time.now.utc, 'test', { 'meta.user_id' => 123 })

		expect(registry.offenses).not_to be_empty
		offense = registry.offenses.first
		expect(offense['callsite']).to eq(described_class.context_callsite)
		expect(offense['logger_class']).to eq(described_class::ANY_LOGGER)
		end

		it 'attributes the offense to the context callsite even when the same key is also in the context' do
		Labkit::Context.with_context('meta.user_id' => 456) do
		test_logger.format_message('INFO', Time.now.utc, 'test', { 'meta.user_id' => 123 })
		end

		expect(registry.offenses.size).to eq(1)
		expect(registry.offenses.first['callsite']).to eq(described_class.context_callsite)
		end
		end

		context 'when detecting removed offenses' do
		before do
		allow(test_logger).to receive(:determine_callsite).and_return(mock_location)
		end

		it 'calls check_for_removed_offenses with data hash' do
		it 'calls check_for_removed_offenses for both the callsite and the context callsite with the data hash' do
		expect(registry).to receive(:check_for_removed_offenses)
		.with('app/test.rb', hash_including('gl_user_id' => 123, 'message' => 'hello'), 'AnonymousLogger')
		expect(registry).to receive(:check_for_removed_offenses)
		.with(described_class.context_callsite,
		hash_including('gl_user_id' => 123, 'message' => 'hello'),
		Labkit::Logging::FieldValidator::LogInterceptor::ANY_LOGGER)

		test_logger.format_message('INFO', Time.now.utc, 'test', { 'gl_user_id' => 123, 'message' => 'hello' })
		end
		@@ -133,6 +243,29 @@ RSpec.describe Labkit::Logging::FieldValidator::LogInterceptor do
		expect(removed.size).to eq(1)
		expect(removed.first['deprecated_field']).to eq('meta.user_id')
		end

		it 'detects removed offenses for context-attributed baseline entries' do
		# Baseline entry attributed to the context callsite (the new format)
		File.write(config_path, {
		'offenses' => [
		{
		'callsite' => described_class.context_callsite,
		'deprecated_field' => 'meta.user_id',
		'standard_field' => 'Labkit::Fields::GL_USER_ID',
		'logger_class' => described_class::ANY_LOGGER
		}
		]
		}.to_yaml)

		allow(Labkit::Fields).to receive(:constant_name_for).and_return(nil)
		allow(Labkit::Fields).to receive(:constant_name_for).with('gl_user_id').and_return('GL_USER_ID')

		test_logger.format_message('INFO', Time.now.utc, 'test', { 'gl_user_id' => 123 })

		_detected, _new, removed = registry.finalize
		expect(removed.size).to eq(1)
		expect(removed.first['callsite']).to eq(described_class.context_callsite)
		end
		end
		end

		@@ -164,6 +297,53 @@ RSpec.describe Labkit::Logging::FieldValidator::LogInterceptor do
		end
		end

		describe 'context callsite' do
		describe '.context_callsite' do
		after do
		described_class.reset_context_callsite!
		end

		it 'returns the default value' do
		expect(described_class.context_callsite).to eq(Labkit::Logging::FieldValidator::LogInterceptor::DEFAULT_CONTEXT_CALLSITE)
		end

		it 'returns a custom value when set' do
		described_class.context_callsite = 'lib/gitlab/application_context.rb'

		expect(described_class.context_callsite).to eq('lib/gitlab/application_context.rb')
		end
		end

		describe '.reset_context_callsite!' do
		it 'restores the default value after customization' do
		described_class.context_callsite = 'lib/gitlab/application_context.rb'

		described_class.reset_context_callsite!

		expect(described_class.context_callsite).to eq(Labkit::Logging::FieldValidator::LogInterceptor::DEFAULT_CONTEXT_CALLSITE)
		end
		end

		context 'when a custom context callsite is configured' do
		before do
		described_class.context_callsite = 'lib/gitlab/application_context.rb'
		allow(test_logger).to receive(:determine_callsite).and_return(mock_location)
		end

		after do
		described_class.reset_context_callsite!
		end

		it 'uses the custom callsite for context-originated offenses' do
		Labkit::Context.with_context('meta.user_id' => 456) do
		test_logger.format_message('INFO', Time.now.utc, 'test', { message: 'hello' })
		end

		expect(registry.offenses.first['callsite']).to eq('lib/gitlab/application_context.rb')
		end
		end
		end

		describe 'wrapper patterns' do
		describe '.register_wrapper_pattern' do
		after do