Merge branch 'log-unexpected-sidekiq-status-users' into 'master'

Log when SidekiqStatus is used unexpectedly

See merge request gitlab-org/gitlab!74815

config/feature_flags/development/log_implicit_sidekiq_status_calls.yml

+---
+name: log_implicit_sidekiq_status_calls
+introduced_by_url: https://gitlab.com/gitlab-org/gitlab/-/merge_requests/74815
+rollout_issue_url: https://gitlab.com/gitlab-org/gitlab/-/issues/343964
+milestone: '14.6'
+type: development
+group: group::scalability
+default_enabled: false

ee/spec/workers/geo/repository_shard_sync_worker_spec.rb

@@ -63,7 +63,7 @@ RSpec.describe Geo::RepositoryShardSyncWorker, :geo, :clean_gitlab_redis_cache,
 
     context 'number of scheduled jobs exceeds capacity' do
       it 'schedules 0 jobs' do
-        is_expected.to receive(:scheduled_job_ids).and_return(1..1000).at_least(:once)
+        is_expected.to receive(:scheduled_job_ids).and_return((1..1000).to_a).at_least(:once)
         is_expected.not_to receive(:schedule_job)
 
         Sidekiq::Testing.inline! { subject.perform(shard_name) }

ee/spec/workers/geo/repository_verification/primary/shard_worker_spec.rb

@@ -170,7 +170,7 @@ RSpec.describe Geo::RepositoryVerification::Primary::ShardWorker, :clean_gitlab_
     it 'does not schedule jobs when number of scheduled jobs exceeds capacity' do
       create(:project)
 
-      is_expected.to receive(:scheduled_job_ids).and_return(1..1000).at_least(:once)
+      is_expected.to receive(:scheduled_job_ids).and_return((1..1000).to_a).at_least(:once)
       is_expected.not_to receive(:schedule_job)
 
       Sidekiq::Testing.inline! { subject.perform(shard_name) }

ee/spec/workers/geo/repository_verification/secondary/shard_worker_spec.rb

@@ -64,7 +64,7 @@ RSpec.describe Geo::RepositoryVerification::Secondary::ShardWorker, :geo, :reque
     it 'does not schedule jobs when number of scheduled jobs exceeds capacity' do
       create(:project)
 
-      is_expected.to receive(:scheduled_job_ids).and_return(1..1000).at_least(:once)
+      is_expected.to receive(:scheduled_job_ids).and_return((1..1000).to_a).at_least(:once)
       is_expected.not_to receive(:schedule_job)
 
       Sidekiq::Testing.inline! { subject.perform(shard_name) }

lib/gitlab/sidekiq_status.rb

@@ -29,13 +29,16 @@ module Gitlab
     # for most jobs.
     DEFAULT_EXPIRATION = 30.minutes.to_i
 
+    DEFAULT_VALUE = 1
+    DEFAULT_VALUE_MESSAGE = 'Keys using the default value for SidekiqStatus detected'
+
     # Starts tracking of the given job.
     #
     # jid - The Sidekiq job ID
     # expire - The expiration time of the Redis key.
-    def self.set(jid, expire = DEFAULT_EXPIRATION)
+    def self.set(jid, expire = DEFAULT_EXPIRATION, value: DEFAULT_VALUE)
       Sidekiq.redis do |redis|
-        redis.set(key_for(jid), 1, ex: expire)
+        redis.set(key_for(jid), value, ex: expire)
       end
     end
 
@@ -88,13 +91,20 @@ module Gitlab
     # true = job is still running or enqueued
     # false = job completed
     def self.job_status(job_ids)
+      return [] if job_ids.empty?
+
       keys = job_ids.map { |jid| key_for(jid) }
+      results = Sidekiq.redis { |redis| redis.mget(*keys) }
 
-      Sidekiq.redis do |redis|
-        redis.pipelined do
-          keys.each { |key| redis.exists(key) }
-        end
+      if Feature.enabled?(:log_implicit_sidekiq_status_calls, default_enabled: :yaml)
+        to_log = keys.zip(results).select do |_key, result|
+          result == DEFAULT_VALUE.to_s
+        end.map(&:first)
+
+        Sidekiq.logger.info(message: DEFAULT_VALUE_MESSAGE, keys: to_log) if to_log.any?
       end
+
+      results.map { |result| !result.nil? }
     end
 
     # Returns the JIDs that are completed

lib/gitlab/sidekiq_status/client_middleware.rb

@@ -5,8 +5,9 @@ module Gitlab
     class ClientMiddleware
       def call(_, job, _, _)
         status_expiration = job['status_expiration'] || Gitlab::SidekiqStatus::DEFAULT_EXPIRATION
+        value = job['status_expiration'] ? 2 : Gitlab::SidekiqStatus::DEFAULT_VALUE
 
-        Gitlab::SidekiqStatus.set(job['jid'], status_expiration)
+        Gitlab::SidekiqStatus.set(job['jid'], status_expiration, value: value)
         yield
       end
     end

spec/lib/gitlab/sidekiq_status/client_middleware_spec.rb

 # frozen_string_literal: true
 
-require 'spec_helper'
+require 'fast_spec_helper'
 
 RSpec.describe Gitlab::SidekiqStatus::ClientMiddleware do
   describe '#call' do
-    it 'tracks the job in Redis' do
-      expect(Gitlab::SidekiqStatus).to receive(:set).with('123', Gitlab::SidekiqStatus::DEFAULT_EXPIRATION)
+    context 'when the job has status_expiration set' do
+      it 'tracks the job in Redis with a value of 2' do
+        expect(Gitlab::SidekiqStatus).to receive(:set).with('123', 1.hour.to_i, value: 2)
+
+        described_class.new
+          .call('Foo', { 'jid' => '123', 'status_expiration' => 1.hour.to_i }, double(:queue), double(:pool)) { nil }
+      end
+    end
+
+    context 'when the job does not have status_expiration set' do
+      it 'tracks the job in Redis with a value of 1' do
+        expect(Gitlab::SidekiqStatus).to receive(:set).with('123', Gitlab::SidekiqStatus::DEFAULT_EXPIRATION, value: 1)
 
         described_class.new
           .call('Foo', { 'jid' => '123' }, double(:queue), double(:pool)) { nil }
       end
     end
+  end
 end

spec/lib/gitlab/sidekiq_status_spec.rb

@@ -12,6 +12,31 @@ RSpec.describe Gitlab::SidekiqStatus, :clean_gitlab_redis_queues, :clean_gitlab_
       Sidekiq.redis do |redis|
         expect(redis.exists(key)).to eq(true)
         expect(redis.ttl(key) > 0).to eq(true)
+        expect(redis.get(key)).to eq(described_class::DEFAULT_VALUE.to_s)
+      end
+    end
+
+    it 'allows overriding the expiration time' do
+      described_class.set('123', described_class::DEFAULT_EXPIRATION * 2)
+
+      key = described_class.key_for('123')
+
+      Sidekiq.redis do |redis|
+        expect(redis.exists(key)).to eq(true)
+        expect(redis.ttl(key) > described_class::DEFAULT_EXPIRATION).to eq(true)
+        expect(redis.get(key)).to eq(described_class::DEFAULT_VALUE.to_s)
+      end
+    end
+
+    it 'allows overriding the default value' do
+      described_class.set('123', value: 2)
+
+      key = described_class.key_for('123')
+
+      Sidekiq.redis do |redis|
+        expect(redis.exists(key)).to eq(true)
+        expect(redis.ttl(key) > 0).to eq(true)
+        expect(redis.get(key)).to eq('2')
       end
     end
   end
@@ -88,7 +113,7 @@ RSpec.describe Gitlab::SidekiqStatus, :clean_gitlab_redis_queues, :clean_gitlab_
     end
   end
 
-  describe 'completed' do
+  describe '.completed_jids' do
     it 'returns the completed job' do
       expect(described_class.completed_jids(%w(123))).to eq(['123'])
     end
@@ -100,4 +125,46 @@ RSpec.describe Gitlab::SidekiqStatus, :clean_gitlab_redis_queues, :clean_gitlab_
       expect(described_class.completed_jids(%w(123 456 789))).to eq(['789'])
     end
   end
+
+  describe '.job_status' do
+    it 'returns an array of boolean values' do
+      described_class.set('123')
+      described_class.set('456')
+      described_class.unset('123')
+
+      expect(described_class.job_status(%w(123 456 789))).to eq([false, true, false])
+    end
+
+    it 'handles an empty array' do
+      expect(described_class.job_status([])).to eq([])
+    end
+
+    context 'when log_implicit_sidekiq_status_calls is enabled' do
+      it 'logs keys that contained the default value' do
+        described_class.set('123', value: 2)
+        described_class.set('456')
+        described_class.set('012')
+
+        expect(Sidekiq.logger).to receive(:info).with(message: described_class::DEFAULT_VALUE_MESSAGE,
+                                                      keys: [described_class.key_for('456'), described_class.key_for('012')])
+
+        expect(described_class.job_status(%w(123 456 789 012))).to eq([true, true, false, true])
+      end
+    end
+
+    context 'when log_implicit_sidekiq_status_calls is disabled' do
+      before do
+        stub_feature_flags(log_implicit_sidekiq_status_calls: false)
+      end
+
+      it 'does not perform any logging' do
+        described_class.set('123', value: 2)
+        described_class.set('456')
+
+        expect(Sidekiq.logger).not_to receive(:info)
+
+        expect(described_class.job_status(%w(123 456 789))).to eq([true, true, false])
+      end
+    end
+  end
 end