diff --git a/app/workers/post_receive.rb b/app/workers/post_receive.rb index 0b224b88e4d755e5292e65d0180b201eeb33470d..9fe7dd31e6868d655be7fbca16d7f268c03aba96 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 0000000000000000000000000000000000000000..913e890d5bae47c4f2e9b4d4499f2b78620f23f3 --- /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 72e2b94fe078ff82cd9c8899071209c7a476edca..8e3241a2e4c87b3062d755ab5859e9bd59368cfd 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 a9a0e6ea2aa4d4d95be34948a595ba8fe83e0627..d415aa0d9800a6015aef18994f82ef091343ac40 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 dbd69543f9c5ae0c81008fd5dc6a582067d5cbb9..ff4606923b1519a6fc78ba30a3c5c7dcdc758892 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 66c8fd9402b03a98d1d078ef5a396384d329111e..996aae4c780dc0204ef4aecde83a416dfdd8eeaf 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 326dfdae6616c6351f9758fb38cf17478ee2db88..dc81c34c4d0ba62f5b22e828ce97b88568966ff7 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 ad106837c47abef476a0d9b3213a71b7d87894ab..b99a53527170f3b3ece8cc402c5f705b3e44fe70 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