diff options
4 files changed, 55 insertions, 7 deletions
diff --git a/changelogs/unreleased/56547-limit-sidekiq-logging-based-on-argument-size.yml b/changelogs/unreleased/56547-limit-sidekiq-logging-based-on-argument-size.yml new file mode 100644 index 00000000000..9ef274f3b49 --- /dev/null +++ b/changelogs/unreleased/56547-limit-sidekiq-logging-based-on-argument-size.yml @@ -0,0 +1,5 @@ +--- +title: Prevent Sidekiq arguments over 10 KB in size from being logged to JSON +merge_request: 24493 +author: +type: changed diff --git a/doc/development/sidekiq_debugging.md b/doc/development/sidekiq_debugging.md index 84b61bd7e61..2b3a9481b93 100644 --- a/doc/development/sidekiq_debugging.md +++ b/doc/development/sidekiq_debugging.md @@ -11,6 +11,11 @@ Example: gitlab_rails['env'] = {"SIDEKIQ_LOG_ARGUMENTS" => "1"} ``` -Please note: It is not recommend to enable this setting in production because some +Please note: It is not recommend to enable this setting in production because some Sidekiq jobs (such as sending a password reset email) take secret arguments (for -example the password reset token).
\ No newline at end of file +example the password reset token). + +When using [Sidekiq JSON logging](../administration/logs.md#sidekiqlog), +arguments logs are limited to a maximum size of 10 kilobytes of text; +any arguments after this limit will be discarded and replaced with a +single argument containing the string `"..."`. diff --git a/lib/gitlab/sidekiq_logging/structured_logger.rb b/lib/gitlab/sidekiq_logging/structured_logger.rb index e86db8db3a1..fdc0d518c59 100644 --- a/lib/gitlab/sidekiq_logging/structured_logger.rb +++ b/lib/gitlab/sidekiq_logging/structured_logger.rb @@ -5,6 +5,7 @@ module Gitlab class StructuredLogger START_TIMESTAMP_FIELDS = %w[created_at enqueued_at].freeze DONE_TIMESTAMP_FIELDS = %w[started_at retried_at failed_at completed_at].freeze + MAXIMUM_JOB_ARGUMENTS_LENGTH = 10.kilobytes def call(job, queue) started_at = current_time @@ -64,6 +65,7 @@ module Gitlab job['pid'] = ::Process.pid job.delete('args') unless ENV['SIDEKIQ_LOG_ARGUMENTS'] + job['args'] = limited_job_args(job['args']) if job['args'] convert_to_iso8601(job, START_TIMESTAMP_FIELDS) @@ -93,6 +95,21 @@ module Gitlab Time.at(timestamp).utc.iso8601(3) end + + def limited_job_args(args) + return unless args.is_a?(Array) + + total_length = 0 + limited_args = args.take_while do |arg| + total_length += arg.to_json.length + + total_length <= MAXIMUM_JOB_ARGUMENTS_LENGTH + end + + limited_args.push('...') if total_length > MAXIMUM_JOB_ARGUMENTS_LENGTH + + limited_args + end end end end diff --git a/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb b/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb index f773f370ee2..a9d15f1d522 100644 --- a/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb +++ b/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb @@ -82,15 +82,36 @@ describe Gitlab::SidekiqLogging::StructuredLogger do end.to raise_error(ArgumentError) end end + + context 'when the job args are bigger than the maximum allowed' do + it 'keeps args from the front until they exceed the limit' do + Timecop.freeze(timestamp) do + job['args'] = [ + 1, + 2, + 'a' * (described_class::MAXIMUM_JOB_ARGUMENTS_LENGTH / 2), + 'b' * (described_class::MAXIMUM_JOB_ARGUMENTS_LENGTH / 2), + 3 + ] + + expected_args = job['args'].take(3) + ['...'] + + expect(logger).to receive(:info).with(start_payload.merge('args' => expected_args)).ordered + expect(logger).to receive(:info).with(end_payload.merge('args' => expected_args)).ordered + expect(subject).to receive(:log_job_start).and_call_original + expect(subject).to receive(:log_job_done).and_call_original + + subject.call(job, 'test_queue') { } + end + end + end end context 'with SIDEKIQ_LOG_ARGUMENTS disabled' do - it 'logs start and end of job' do + it 'logs start and end of job without args' do Timecop.freeze(timestamp) do - start_payload.delete('args') - - expect(logger).to receive(:info).with(start_payload).ordered - expect(logger).to receive(:info).with(end_payload).ordered + expect(logger).to receive(:info).with(start_payload.except('args')).ordered + expect(logger).to receive(:info).with(end_payload.except('args')).ordered expect(subject).to receive(:log_job_start).and_call_original expect(subject).to receive(:log_job_done).and_call_original |