Merge branch 'sh-enable-sidekiq-arg-logging-default' into 'master'

Enable Sidekiq argument logging by default

See merge request gitlab-org/gitlab!44853

app/workers/post_receive.rb

@@ -20,7 +20,7 @@ class PostReceive # rubocop:disable Scalability/IdempotentWorker
     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?

changelogs/unreleased/sh-enable-sidekiq-arg-logging-default.yml

+---
+title: Enable Sidekiq argument logging by default
+merge_request: 44853
+author:
+type: changed

config/initializers/sidekiq.rb

 # 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 @@ Sidekiq.configure_server do |config|
 
   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
   }))
 

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

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

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

lib/gitlab/sidekiq_logging/logs_jobs.rb

@@ -16,7 +16,7 @@ module Gitlab
         # Add process id params
         job['pid'] = ::Process.pid
 
-        job.delete('args') unless ENV['SIDEKIQ_LOG_ARGUMENTS']
+        job.delete('args') unless SidekiqLogArguments.enabled?
 
         job
       end

spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb

@@ -119,6 +119,10 @@ RSpec.describe Gitlab::SidekiqLogging::StructuredLogger do
     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 @@ RSpec.describe Gitlab::SidekiqLogging::StructuredLogger do
 
       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 @@ RSpec.describe Gitlab::SidekiqLogging::StructuredLogger do
       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 @@ RSpec.describe Gitlab::SidekiqLogging::StructuredLogger do
         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 @@ RSpec.describe Gitlab::SidekiqLogging::StructuredLogger do
     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