Redact delayed_jobs handler column in query logs

app/jobs/enqueuer.rb

@@ -71,7 +71,17 @@ def enqueue_job(job, run_at: nil, priority_increment: nil, preserve_priority: fa
         local_opts[:priority] = final_priority if final_priority > 0
         local_opts[:run_at] = run_at if run_at
 
-        Delayed::Job.enqueue(logging_context_job, @opts.merge(local_opts))
+        delayed_job = Delayed::Job.enqueue(logging_context_job, @opts.merge(local_opts))
+        begin
+          Steno.logger('cc.background').info('enqueued background job',
+                                             job_guid: @opts['guid'],
+                                             queue: @opts[:queue],
+                                             **logging_context_job.hash_for_logs)
+        rescue StandardError => e
+          # Logging must never break enqueue (the job is already committed); degrade to a warning.
+          Steno.logger('cc.background').warn('failed to log enqueued background job', error: e.message)
+        end
+        delayed_job
       end
 
       def load_delayed_job_plugins

app/jobs/logging_context_job.rb

@@ -11,6 +11,10 @@ def initialize(handler, request_id)
         @request_id = request_id
       end
 
+      def hash_for_logs
+        super.merge(request_id: request_id).compact
+      end
+
       def before(job)
         # Get guid via root job mixin (as root job) or via `root_job_guid` column (sub-job)
         @root_job_guid = wrapped_handler.try(:root_job_guid) ||

app/jobs/pollable_job_wrapper.rb

@@ -43,6 +43,10 @@ def before_enqueue(job)
         end
       end
 
+      def hash_for_logs
+        super.merge(existing_guid: existing_guid, root_job_guid: @root_job_guid).compact
+      end
+
       def success(job)
         if @handler.respond_to?(:success)
           persist_warnings(job)

app/jobs/reoccurring_job.rb

@@ -38,6 +38,24 @@ def polling_interval_seconds=(interval)
         @polling_interval = interval.clamp(default_polling_interval_seconds, maximum_polling_interval)
       end
 
+      # Non-sensitive identifying fields for structured job logging.
+      def hash_for_logs
+        audit_info = __send__(:user_audit_info) if respond_to?(:user_audit_info, true)
+        {
+          operation: (operation.to_s if respond_to?(:operation)),
+          operation_type: (operation_type if respond_to?(:operation_type)),
+          resource_type: (resource_type if respond_to?(:resource_type)),
+          resource_guid: (resource_guid if respond_to?(:resource_guid)),
+          start_time: start_time,
+          finished: finished,
+          retry_number: retry_number,
+          maximum_duration_seconds: maximum_duration_seconds,
+          polling_interval_seconds: polling_interval_seconds,
+          first_time: (instance_variable_get(:@first_time) if instance_variable_defined?(:@first_time)),
+          user_audit_info: (audit_info.hash_for_logs if audit_info.respond_to?(:hash_for_logs))
+        }.compact
+      end
+
       private
 
       def initialize

app/jobs/timeout_job.rb

@@ -25,6 +25,10 @@ def max_run_time
 
       attr_reader :timeout
 
+      def hash_for_logs
+        super.merge(timeout: timeout).compact
+      end
+
       def job
         @handler
       end

app/jobs/v3/create_service_instance_job.rb

@@ -6,6 +6,10 @@ module V3
     class CreateServiceInstanceJob < VCAP::CloudController::Jobs::ReoccurringJob
       attr_reader :warnings
 
+      def hash_for_logs
+        super.merge(warnings: warnings).compact
+      end
+
       def initialize(
         service_instance_guid,
         user_audit_info:, audit_hash:, arbitrary_parameters: {}

app/jobs/v3/update_service_instance_job.rb

@@ -6,6 +6,10 @@ module V3
     class UpdateServiceInstanceJob < VCAP::CloudController::Jobs::ReoccurringJob
       attr_reader :warnings
 
+      def hash_for_logs
+        super.merge(warnings: warnings).compact
+      end
+
       def initialize(
         service_instance_guid,
         message:,

app/jobs/wrapping_job.rb

@@ -70,6 +70,18 @@ def resource_type
       def resource_guid
         handler.respond_to?(:resource_guid) ? handler.resource_guid : nil
       end
+
+      # Secret-free identifying fields for logging a created job.
+      # Deliberately excludes any user-supplied payload (arbitrary_parameters,
+      # audit_hash). Merges any hash_for_logs the wrapped handler exposes.
+      def hash_for_logs
+        {
+          job_class: wrapped_handler.class.name,
+          display_name: display_name,
+          resource_type: resource_type,
+          resource_guid: resource_guid
+        }.merge(handler.respond_to?(:hash_for_logs) ? handler.hash_for_logs : {}).compact
+      end
     end
   end
 end

lib/cloud_controller/db.rb

@@ -6,6 +6,7 @@
 require 'sequel/extensions/query_length_logging'
 require 'sequel/extensions/request_query_metrics'
 require 'sequel/extensions/default_order_by_id'
+require 'sequel/extensions/delayed_jobs_log_redaction'
 
 module VCAP::CloudController
   class DB
@@ -32,6 +33,7 @@ def self.connect(opts, logger)
       if opts[:log_db_queries]
         db.logger = logger
         db.sql_log_level = opts[:log_level]
+        db.extension(:delayed_jobs_log_redaction)
         db.extension :caller_logging
         db.caller_logging_ignore = /sequel_paginator|query_length_logging|sequel_pg|paginated_collection_renderer|request_query_metrics|default_order_by_id/
         db.caller_logging_formatter = lambda do |caller|

lib/cloud_controller/user_audit_info.rb

@@ -17,5 +17,10 @@ def self.from_context(context)
         user_guid: context.current_user.try(:guid)
       )
     end
+
+    # Non-sensitive identity fields for structured job logging.
+    def hash_for_logs
+      { user_guid: user_guid, user_email: user_email, user_name: user_name }.compact
+    end
   end
 end

lib/sequel/extensions/delayed_jobs_log_redaction.rb

@@ -0,0 +1,54 @@
+# frozen_string_literal: true
+
+module Sequel::DelayedJobsLogRedaction
+  # Redact the serialized job payload (handler) from any logged SQL that writes the
+  # delayed_jobs table. The handler is the only value whose sole log path is the SQL
+  # statement log and that carries user-submitted parameters; it has no debugging value
+  # in a log line. The error columns (cf_api_error/last_error) are intentionally NOT
+  # redacted here — they are needed for debugging and only reach the SQL log when
+  # log_db_queries is enabled.
+  REDACTED = "'[REDACTED]'"
+  DELAYED_JOBS_TABLE = /(?:[`"]?\w+[`"]?\.)?[`"]?delayed_jobs[`"]?/i
+  HANDLER_COLUMN = /[`"]?handler[`"]?/i
+
+  def log_connection_yield(sql, conn, args=nil)
+    if @loggers.any? && sql.downcase.include?('delayed_jobs')
+      sql = redact_delayed_jobs(sql)
+      # Sequel's base logger appends "; #{args.inspect}" to the logged line. If bound args
+      # carry the serialized handler, redact there too.
+      args = redact_args(args) if args && args.inspect.include?('!ruby')
+    end
+    super
+  end
+
+  private
+
+  def redact_delayed_jobs(sql)
+    return sql unless /\b(?:INSERT INTO|UPDATE)\s+#{DELAYED_JOBS_TABLE}/io.match?(sql)
+
+    # UPDATE "handler" = '...'
+    sql = sql.gsub(/(#{HANDLER_COLUMN}\s*=\s*)'(?:[^']|'')*'/io, "\\1#{REDACTED}")
+    # INSERT: the handler is a Psych-serialized Ruby object graph, which always starts
+    # with the '--- !ruby' document marker regardless of the inner tag.
+    sql.gsub(/'--- !ruby(?:[^']|'')*'/i, REDACTED)
+  end
+
+  # Redact only the bound-args element(s) that carry the serialized handler, leaving
+  # non-sensitive values (queue, guid, run_at, ...) intact.
+  def redact_args(args)
+    case args
+    when Array
+      args.map { |a| sensitive_arg?(a) ? '[REDACTED]' : a }
+    when Hash
+      args.transform_values { |v| sensitive_arg?(v) ? '[REDACTED]' : v }
+    else
+      sensitive_arg?(args) ? '[REDACTED]' : args
+    end
+  end
+
+  def sensitive_arg?(value)
+    value.is_a?(String) && value.include?('!ruby')
+  end
+end
+
+Sequel::Database.register_extension(:delayed_jobs_log_redaction, Sequel::DelayedJobsLogRedaction)

spec/unit/jobs/enqueuer_spec.rb

@@ -92,6 +92,19 @@ module VCAP::CloudController::Jobs
         Enqueuer.new(opts).enqueue(wrapped_job)
       end
 
+      it 'logs the created background job without any handler payload' do
+        logger = instance_double(Steno::Logger, info: nil)
+        allow(Steno).to receive(:logger).and_call_original
+        allow(Steno).to receive(:logger).with('cc.background').and_return(logger)
+
+        Enqueuer.new(opts).enqueue(wrapped_job)
+
+        expect(logger).to have_received(:info).with(
+          'enqueued background job',
+          hash_including(job_guid: an_instance_of(String), queue: 'my-queue', job_class: 'VCAP::CloudController::Jobs::Runtime::ModelDeletion')
+        )
+      end
+
       context 'when run_at is provided' do
         it 'enqueues the job with the specified run_at time' do
           original_enqueue = Delayed::Job.method(:enqueue)

spec/unit/jobs/v3/create_service_instance_job_spec.rb

@@ -39,6 +39,32 @@ module V3
 
       it { expect(described_class).to be < VCAP::CloudController::Jobs::ReoccurringJob }
 
+      describe '#hash_for_logs' do
+        let(:params) { { edition: 'cloud', systempassword: 's3cr3t-value' } }
+        let(:audit_hash) { { name: 'my-si', parameters: { systempassword: 's3cr3t-value' }, type: 'managed' } }
+
+        it 'includes non-sensitive identifying fields' do
+          h = job.hash_for_logs
+          expect(h).to include(
+            operation: 'provision',
+            operation_type: 'create',
+            resource_type: 'service_instances',
+            resource_guid: service_instance.guid,
+            retry_number: 0,
+            first_time: true
+          )
+          expect(h).to have_key(:start_time)
+          expect(h).to have_key(:maximum_duration_seconds)
+        end
+
+        it 'never includes the arbitrary_parameters or audit_hash payload' do
+          expect(job.hash_for_logs.to_s).not_to include('s3cr3t-value')
+          expect(job.hash_for_logs).not_to have_key(:arbitrary_parameters)
+          expect(job.hash_for_logs).not_to have_key(:audit_hash)
+          expect(job.hash_for_logs).not_to have_key(:parameters)
+        end
+      end
+
       describe '#perform' do
         let(:provision_response) {}
         let(:poll_response) { { finished: false } }

spec/unit/jobs/v3/update_service_instance_job_spec.rb

@@ -56,6 +56,30 @@ module V3
 
       it { expect(described_class).to be < VCAP::CloudController::Jobs::ReoccurringJob }
 
+      describe '#hash_for_logs' do
+        let(:arbitrary_parameters) { { systempassword: 's3cr3t-value' } }
+        let(:audit_hash) { { name: 'si', parameters: { systempassword: 's3cr3t-value' } } }
+
+        it 'includes non-sensitive identifying fields' do
+          h = job.hash_for_logs
+          expect(h).to include(
+            operation: 'update',
+            operation_type: 'update',
+            resource_type: 'service_instances',
+            resource_guid: service_instance.guid
+          )
+          expect(h).to have_key(:warnings)
+        end
+
+        it 'never includes the message, arbitrary_parameters or audit_hash payload' do
+          expect(job.hash_for_logs.to_s).not_to include('s3cr3t-value')
+          expect(job.hash_for_logs).not_to have_key(:arbitrary_parameters)
+          expect(job.hash_for_logs).not_to have_key(:audit_hash)
+          expect(job.hash_for_logs).not_to have_key(:parameters)
+          expect(job.hash_for_logs).not_to have_key(:message)
+        end
+      end
+
       describe '#perform' do
         let(:update_response) {}
         let(:poll_response) { { finished: false } }

spec/unit/jobs/wrapping_job_spec.rb

@@ -199,6 +199,63 @@ module Jobs
         end
       end
 
+      describe '#hash_for_logs' do
+        context 'when the handler exposes identifying fields' do
+          let(:handler) { double(:job, display_name: 'service_instance.create', resource_type: 'service_instances', resource_guid: 'si-guid') }
+
+          it 'returns the job class and identifying fields' do
+            job = WrappingJob.new(handler)
+            expect(job.hash_for_logs).to eq(
+              job_class: handler.class.name,
+              display_name: 'service_instance.create',
+              resource_type: 'service_instances',
+              resource_guid: 'si-guid'
+            )
+          end
+        end
+
+        context 'when the handler exposes nothing' do
+          it 'returns just the job class, dropping nil fields' do
+            handler = Object.new
+            job = WrappingJob.new(handler)
+            expect(job.hash_for_logs).to eq(job_class: 'Object', display_name: 'Object')
+          end
+        end
+
+        context 'when the handler carries arbitrary parameters' do
+          let(:handler) { double(:job, display_name: 'd', resource_type: 't', resource_guid: 'g', arbitrary_parameters: { systempassword: 's3cr3t' }) }
+
+          it 'never includes user-supplied payload' do
+            job = WrappingJob.new(handler)
+            expect(job.hash_for_logs.to_s).not_to include('s3cr3t')
+            expect(job.hash_for_logs).not_to have_key(:arbitrary_parameters)
+          end
+        end
+
+        context 'when the handler itself responds to hash_for_logs' do
+          let(:handler) { double(:job, display_name: 'd', resource_type: 't', resource_guid: 'g', hash_for_logs: { operation: :provision, retry_number: 2 }) }
+
+          it 'merges the handler fields into the result' do
+            job = WrappingJob.new(handler)
+            expect(job.hash_for_logs).to include(
+              job_class: handler.class.name,
+              display_name: 'd',
+              operation: :provision,
+              retry_number: 2
+            )
+          end
+        end
+
+        context 'when the handler returns a key that also exists on the base hash' do
+          let(:handler) { double(:job, display_name: 'd', resource_type: 't', resource_guid: 'base-g', hash_for_logs: { resource_guid: 'inner-g' }) }
+
+          it 'lets the inner handler value win' do
+            job = WrappingJob.new(handler)
+            expect(job.hash_for_logs[:resource_guid]).to eq('inner-g')
+          end
+        end
+      end
+
       describe '#recover_from_failure' do
         context 'when the wrapped job has the recover_from_failure method defined' do
           it 'delegates to the handler' do

spec/unit/lib/cloud_controller/user_audit_info_spec.rb

@@ -19,6 +19,13 @@ module VCAP::CloudController
       end
     end
 
+    describe '#hash_for_logs' do
+      it 'returns only the non-sensitive identity fields' do
+        info = UserAuditInfo.new(user_email: 'e', user_name: 'n', user_guid: 'g')
+        expect(info.hash_for_logs).to eq(user_guid: 'g', user_email: 'e', user_name: 'n')
+      end
+    end
+
     context 'defaults' do
       let(:security_context) do
         class_double(SecurityContext,