From 098b4e54cb2a0cbd8f922dd819555324cbf35696 Mon Sep 17 00:00:00 2001 From: Stan Hu Date: Sat, 10 Oct 2020 15:57:36 -0700 Subject: [PATCH] Enable Sidekiq argument logging by default Now that https://gitlab.com/gitlab-org/gitlab/-/merge_requests/33967 filters sensitive arguments, having Sidekiq argument logging on by default will significantly help troubleshoot customer issues. We tell many customers to enable this in any case. --- app/workers/post_receive.rb | 2 +- .../sh-enable-sidekiq-arg-logging-default.yml | 5 ++++ config/initializers/sidekiq.rb | 7 ++++- doc/administration/troubleshooting/sidekiq.md | 29 ++++++++++--------- doc/development/sidekiq_style_guide.md | 4 +-- doc/user/gitlab_com/index.md | 2 +- lib/gitlab/sidekiq_logging/logs_jobs.rb | 2 +- .../sidekiq_logging/structured_logger_spec.rb | 20 ++++++++----- 8 files changed, 44 insertions(+), 27 deletions(-) create mode 100644 changelogs/unreleased/sh-enable-sidekiq-arg-logging-default.yml diff --git a/app/workers/post_receive.rb b/app/workers/post_receive.rb index 0b224b88e4d7..9fe7dd31e686 100644 --- a/app/workers/post_receive.rb +++ b/app/workers/post_receive.rb @@ -20,7 +20,7 @@ def perform(gl_repository, identifier, changes, push_options = {}) changes = Base64.decode64(changes) unless changes.include?(' ') # Use Sidekiq.logger so arguments can be correlated with execution # time and thread ID's. - Sidekiq.logger.info "changes: #{changes.inspect}" if ENV['SIDEKIQ_LOG_ARGUMENTS'] + Sidekiq.logger.info "changes: #{changes.inspect}" if SidekiqLogArguments.enabled? post_received = Gitlab::GitPostReceive.new(container, identifier, changes, push_options) if repo_type.wiki? diff --git a/changelogs/unreleased/sh-enable-sidekiq-arg-logging-default.yml b/changelogs/unreleased/sh-enable-sidekiq-arg-logging-default.yml new file mode 100644 index 000000000000..913e890d5bae --- /dev/null +++ b/changelogs/unreleased/sh-enable-sidekiq-arg-logging-default.yml @@ -0,0 +1,5 @@ +--- +title: Enable Sidekiq argument logging by default +merge_request: 44853 +author: +type: changed diff --git a/config/initializers/sidekiq.rb b/config/initializers/sidekiq.rb index 72e2b94fe078..8e3241a2e4c8 100644 --- a/config/initializers/sidekiq.rb +++ b/config/initializers/sidekiq.rb @@ -1,4 +1,9 @@ # frozen_string_literal: true +module SidekiqLogArguments + def self.enabled? + Gitlab::Utils.to_boolean(ENV['SIDEKIQ_LOG_ARGUMENTS'], default: true) + end +end def enable_reliable_fetch? return true unless Feature::FlipperFeature.table_exists? @@ -35,7 +40,7 @@ def enable_semi_reliable_fetch_mode? config.server_middleware(&Gitlab::SidekiqMiddleware.server_configurator({ metrics: Settings.monitoring.sidekiq_exporter, - arguments_logger: ENV['SIDEKIQ_LOG_ARGUMENTS'] && !enable_json_logs, + arguments_logger: SidekiqLogArguments.enabled? && !enable_json_logs, memory_killer: enable_sidekiq_memory_killer && use_sidekiq_legacy_memory_killer })) diff --git a/doc/administration/troubleshooting/sidekiq.md b/doc/administration/troubleshooting/sidekiq.md index a9a0e6ea2aa4..d415aa0d9800 100644 --- a/doc/administration/troubleshooting/sidekiq.md +++ b/doc/administration/troubleshooting/sidekiq.md @@ -26,19 +26,11 @@ preventing other threads from continuing. ## Log arguments to Sidekiq jobs -If you want to see what arguments are being passed to Sidekiq jobs you can set -the `SIDEKIQ_LOG_ARGUMENTS` [environment variable](https://docs.gitlab.com/omnibus/settings/environment-variables.html) to `1` (true). - -Example: - -```ruby -gitlab_rails['env'] = {"SIDEKIQ_LOG_ARGUMENTS" => "1"} -``` - -This does not log all job arguments. To avoid logging sensitive -information (for instance, password reset tokens), it logs numeric -arguments for all workers, with overrides for some specific workers -where their arguments are not sensitive. +[In GitLab 13.6 and later](https://gitlab.com/gitlab-org/gitlab/-/merge_requests/44853) +some arguments passed to Sidekiq jobs are logged by default. +To avoid logging sensitive information (for instance, password reset tokens), +GitLab logs numeric arguments for all workers, with overrides for some specific +workers where their arguments are not sensitive. Example log output: @@ -53,6 +45,17 @@ 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 `"..."`. +You can set `SIDEKIQ_LOG_ARGUMENTS` [environment variable](https://docs.gitlab.com/omnibus/settings/environment-variables.html) +to `0` (false) to disable argument logging. + +Example: + +```ruby +gitlab_rails['env'] = {"SIDEKIQ_LOG_ARGUMENTS" => "0"} +``` + +In GitLab 13.5 and earlier, set `SIDEKIQ_LOG_ARGUMENTS` to `1` to start logging arguments passed to Sidekiq. + ## Thread dump Send the Sidekiq process ID the `TTIN` signal and it will output thread diff --git a/doc/development/sidekiq_style_guide.md b/doc/development/sidekiq_style_guide.md index dbd69543f9c5..ff4606923b15 100644 --- a/doc/development/sidekiq_style_guide.md +++ b/doc/development/sidekiq_style_guide.md @@ -696,8 +696,8 @@ blocks: ## Arguments logging -When [`SIDEKIQ_LOG_ARGUMENTS`](../administration/troubleshooting/sidekiq.md#log-arguments-to-sidekiq-jobs) -is enabled, Sidekiq job arguments will be logged. +As of GitLab 13.6, Sidekiq job arguments will be logged by default, unless [`SIDEKIQ_LOG_ARGUMENTS`](../administration/troubleshooting/sidekiq.md#log-arguments-to-sidekiq-jobs) +is disabled. By default, the only arguments logged are numeric arguments, because arguments of other types could contain sensitive information. To diff --git a/doc/user/gitlab_com/index.md b/doc/user/gitlab_com/index.md index 66c8fd9402b0..996aae4c780d 100644 --- a/doc/user/gitlab_com/index.md +++ b/doc/user/gitlab_com/index.md @@ -432,7 +432,7 @@ and the following environment variables: | `SIDEKIQ_MEMORY_KILLER_CHECK_INTERVAL` | - | `3` | | `SIDEKIQ_MEMORY_KILLER_GRACE_TIME` | - | `900` | | `SIDEKIQ_MEMORY_KILLER_SHUTDOWN_WAIT` | - | `30` | -| `SIDEKIQ_LOG_ARGUMENTS` | `1` | - | +| `SIDEKIQ_LOG_ARGUMENTS` | `1` | `1` | NOTE: **Note:** The `SIDEKIQ_MEMORY_KILLER_MAX_RSS` setting is `16000000` on Sidekiq import diff --git a/lib/gitlab/sidekiq_logging/logs_jobs.rb b/lib/gitlab/sidekiq_logging/logs_jobs.rb index 326dfdae6616..dc81c34c4d0b 100644 --- a/lib/gitlab/sidekiq_logging/logs_jobs.rb +++ b/lib/gitlab/sidekiq_logging/logs_jobs.rb @@ -16,7 +16,7 @@ def parse_job(job) # Add process id params job['pid'] = ::Process.pid - job.delete('args') unless ENV['SIDEKIQ_LOG_ARGUMENTS'] + job.delete('args') unless SidekiqLogArguments.enabled? job end diff --git a/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb b/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb index ad106837c47a..b99a53527170 100644 --- a/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb +++ b/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb @@ -119,6 +119,10 @@ end context 'with SIDEKIQ_LOG_ARGUMENTS disabled' do + before do + stub_env('SIDEKIQ_LOG_ARGUMENTS', '0') + end + it 'logs start and end of job without args' do Timecop.freeze(timestamp) do expect(logger).to receive(:info).with(start_payload.except('args')).ordered @@ -150,8 +154,8 @@ it 'logs with scheduling latency' do Timecop.freeze(timestamp) do - expect(logger).to receive(:info).with(start_payload.except('args')).ordered - expect(logger).to receive(:info).with(end_payload.except('args')).ordered + expect(logger).to receive(:info).with(start_payload).ordered + expect(logger).to receive(:info).with(end_payload).ordered expect(subject).to receive(:log_job_start).and_call_original expect(subject).to receive(:log_job_done).and_call_original @@ -173,12 +177,12 @@ end let(:expected_end_payload) do - end_payload.except('args').merge(timing_data) + end_payload.merge(timing_data) end it 'logs with Gitaly and Rugged timing data' do Timecop.freeze(timestamp) do - expect(logger).to receive(:info).with(start_payload.except('args')).ordered + expect(logger).to receive(:info).with(start_payload).ordered expect(logger).to receive(:info).with(expected_end_payload).ordered subject.call(job, 'test_queue') do @@ -194,10 +198,10 @@ allow(Process).to receive(:clock_gettime).and_call_original end - let(:expected_start_payload) { start_payload.except('args') } + let(:expected_start_payload) { start_payload } let(:expected_end_payload) do - end_payload.except('args').merge('cpu_s' => a_value >= 0) + end_payload.merge('cpu_s' => a_value >= 0) end let(:expected_end_payload_with_db) do @@ -228,10 +232,10 @@ end context 'when there is extra metadata set for the done log' do - let(:expected_start_payload) { start_payload.except('args') } + let(:expected_start_payload) { start_payload } let(:expected_end_payload) do - end_payload.except('args').merge("#{ApplicationWorker::LOGGING_EXTRA_KEY}.key1" => 15, "#{ApplicationWorker::LOGGING_EXTRA_KEY}.key2" => 16) + end_payload.merge("#{ApplicationWorker::LOGGING_EXTRA_KEY}.key1" => 15, "#{ApplicationWorker::LOGGING_EXTRA_KEY}.key2" => 16) end it 'logs it in the done log' do -- GitLab