Redact delayed_jobs handler column in query logs

app/jobs/enqueuer.rb

@@ -71,7 +71,12 @@ 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))
+        Steno.logger('cc.background').info('enqueued background job',
+                                           job_guid: @opts['guid'],
+                                           queue: @opts[:queue],
+                                           **logging_context_job.hash_for_logs)
+        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 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,23 @@
+# frozen_string_literal: true
+
+module Sequel::DelayedJobsLogRedaction
+  # Redact the `handler` column value from any logged SQL that writes the delayed_jobs table.
+  REDACTED = "'[REDACTED]'"
+
+  def log_connection_yield(sql, conn, args=nil)
+    sql = redact_delayed_jobs(sql) if @loggers.any? && sql.include?('delayed_jobs')
+    super
+  end
+
+  private
+
+  def redact_delayed_jobs(sql)
+    return sql unless /\b(?:INSERT INTO|UPDATE)\s+"?delayed_jobs"?/i.match?(sql)
+
+    sql = sql.gsub(/("?handler"?\s*=\s*)'(?:[^']|'')*'/i, "\\1#{REDACTED}")
+
+    sql.gsub(%r{'--- !ruby/object:(?:[^']|'')*'}, REDACTED)
+  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/wrapping_job_spec.rb

@@ -199,6 +199,40 @@ 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
+      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,

spec/unit/lib/sequel/extensions/delayed_jobs_log_redaction_spec.rb

@@ -0,0 +1,89 @@
+require 'spec_helper'
+require 'sequel/extensions/delayed_jobs_log_redaction'
+
+RSpec.describe Sequel::DelayedJobsLogRedaction do
+  let(:db_config) { DbConfig.new }
+  let(:logs) { StringIO.new }
+  let(:logger) { Logger.new(logs) }
+
+  # log_db_queries:true is what makes DB.connect install the redaction extension.
+  let(:db) do
+    VCAP::CloudController::DB.connect(
+      db_config.config.merge(log_db_queries: true, log_level: :info),
+      db_config.db_logger
+    )
+  end
+
+  before do
+    db.loggers << logger
+    db.sql_log_level = :info
+  end
+
+  after { db.disconnect }
+
+  describe 'wiring via DB.connect' do
+    it 'installs the redaction extension when log_db_queries is true' do
+      expect(db.respond_to?(:redact_delayed_jobs, true)).to be(true)
+    end
+
+    it 'does NOT install the redaction extension when log_db_queries is false' do
+      plain = VCAP::CloudController::DB.connect(
+        db_config.config.merge(log_db_queries: false), db_config.db_logger
+      )
+      expect(plain.respond_to?(:redact_delayed_jobs, true)).to be(false)
+    ensure
+      plain&.disconnect
+    end
+  end
+
+  describe 'redaction of logged SQL' do
+    it 'redacts the handler value on INSERT but keeps the table and column name' do
+      handler = "--- !ruby/object:VCAP::CloudController::Jobs::LoggingContextJob\n  " \
+                "arbitrary_parameters:\n    :systempassword: s3cr3t-value\n"
+      sql = %(INSERT INTO "delayed_jobs" ("queue", "handler", "created_at") ) +
+            %(VALUES ('cc-generic', '#{handler}', CURRENT_TIMESTAMP))
+      db.log_connection_yield(sql, nil) {}
+
+      expect(logs.string).to include('INSERT INTO "delayed_jobs"')
+      expect(logs.string).to include('"handler"')
+      expect(logs.string).to include('[REDACTED]')
+      expect(logs.string).not_to include('s3cr3t-value')
+    end
+
+    it 'redacts the handler value on UPDATE (retry path) but keeps other columns' do
+      sql = %(UPDATE "delayed_jobs" SET "handler" = ) +
+            %('--- !ruby/object:Foo :systempassword: s3cr3t-value', "attempts" = 7 WHERE "id" = 71)
+      db.log_connection_yield(sql, nil) {}
+
+      expect(logs.string).to include('[REDACTED]')
+      expect(logs.string).not_to include('s3cr3t-value')
+      expect(logs.string).to include('"attempts" = 7')
+    end
+
+    it 'leaves last_error intact for debugging' do
+      sql = %(UPDATE "delayed_jobs" SET "last_error" = 'RuntimeError: broker returned 500\nbacktrace line 1', ) +
+            %("attempts" = 2 WHERE "id" = 71)
+      db.log_connection_yield(sql, nil) {}
+
+      expect(logs.string).to include('RuntimeError: broker returned 500')
+      expect(logs.string).not_to include('[REDACTED]')
+    end
+
+    it 'leaves statements for other tables untouched' do
+      sql = %(INSERT INTO "apps" ("name", "handler") VALUES ('my-app', 'not-a-secret'))
+      db.log_connection_yield(sql, nil) {}
+
+      expect(logs.string).to include('not-a-secret')
+      expect(logs.string).not_to include('[REDACTED]')
+    end
+
+    it 'handles embedded doubled-quote escapes in the handler literal' do
+      sql = %(INSERT INTO "delayed_jobs" ("handler") ) +
+            %(VALUES ('--- !ruby/object:Foo note: it''s secret s3cr3t-value'))
+      db.log_connection_yield(sql, nil) {}
+
+      expect(logs.string).to include('[REDACTED]')
+      expect(logs.string).not_to include('s3cr3t-value')
+    end
+  end
+end