From 901df73c23f0e352f1ea8faaa7a31981a162fe44 Mon Sep 17 00:00:00 2001 From: Katharina Przybill <30441792+kathap@users.noreply.github.com> Date: Mon, 5 Oct 2026 18:41:07 +0200 Subject: [PATCH 1/3] Redact delayed_jobs handler column in query logs The serialized handler column is verbose and clutters the statement log. Strip its value from logged delayed_jobs INSERT/UPDATE statements via a Sequel extension, enabled through DB.connect when query logging is on. --- lib/cloud_controller/db.rb | 2 ++ .../extensions/delayed_jobs_log_redaction.rb | 23 +++++++++++++++++++ 2 files changed, 25 insertions(+) create mode 100644 lib/sequel/extensions/delayed_jobs_log_redaction.rb diff --git a/lib/cloud_controller/db.rb b/lib/cloud_controller/db.rb index 0c5c0ffd3db..bfbb4947b11 100644 --- a/lib/cloud_controller/db.rb +++ b/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| diff --git a/lib/sequel/extensions/delayed_jobs_log_redaction.rb b/lib/sequel/extensions/delayed_jobs_log_redaction.rb new file mode 100644 index 00000000000..c0a29586aa3 --- /dev/null +++ b/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(/'--- !ruby\/object:(?:[^']|'')*'/, REDACTED) + end +end + +Sequel::Database.register_extension(:delayed_jobs_log_redaction, Sequel::DelayedJobsLogRedaction) From c3eb1687d8b73e9c2e178df38283abae5b2a178b Mon Sep 17 00:00:00 2001 From: Katharina Przybill <30441792+kathap@users.noreply.github.com> Date: Tue, 6 Oct 2026 09:22:39 +0200 Subject: [PATCH 2/3] add test --- .../extensions/delayed_jobs_log_redaction.rb | 2 +- .../delayed_jobs_log_redaction_spec.rb | 89 +++++++++++++++++++ 2 files changed, 90 insertions(+), 1 deletion(-) create mode 100644 spec/unit/lib/sequel/extensions/delayed_jobs_log_redaction_spec.rb diff --git a/lib/sequel/extensions/delayed_jobs_log_redaction.rb b/lib/sequel/extensions/delayed_jobs_log_redaction.rb index c0a29586aa3..0b72b08bbb8 100644 --- a/lib/sequel/extensions/delayed_jobs_log_redaction.rb +++ b/lib/sequel/extensions/delayed_jobs_log_redaction.rb @@ -16,7 +16,7 @@ def redact_delayed_jobs(sql) sql = sql.gsub(/("?handler"?\s*=\s*)'(?:[^']|'')*'/i, "\\1#{REDACTED}") - sql.gsub(/'--- !ruby\/object:(?:[^']|'')*'/, REDACTED) + sql.gsub(%r{'--- !ruby/object:(?:[^']|'')*'}, REDACTED) end end diff --git a/spec/unit/lib/sequel/extensions/delayed_jobs_log_redaction_spec.rb b/spec/unit/lib/sequel/extensions/delayed_jobs_log_redaction_spec.rb new file mode 100644 index 00000000000..697cacc0f3a --- /dev/null +++ b/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 From b19f32beb11eecc50c24d08de9899543f23c57a1 Mon Sep 17 00:00:00 2001 From: Katharina Przybill <30441792+kathap@users.noreply.github.com> Date: Tue, 6 Oct 2026 16:28:42 +0200 Subject: [PATCH 3/3] Preserve debugging info from handler value --- app/jobs/enqueuer.rb | 7 +++- app/jobs/logging_context_job.rb | 4 +++ app/jobs/pollable_job_wrapper.rb | 4 +++ app/jobs/reoccurring_job.rb | 18 ++++++++++ app/jobs/timeout_job.rb | 4 +++ app/jobs/v3/create_service_instance_job.rb | 4 +++ app/jobs/v3/update_service_instance_job.rb | 4 +++ app/jobs/wrapping_job.rb | 12 +++++++ lib/cloud_controller/user_audit_info.rb | 5 +++ spec/unit/jobs/enqueuer_spec.rb | 13 +++++++ .../v3/create_service_instance_job_spec.rb | 26 ++++++++++++++ spec/unit/jobs/wrapping_job_spec.rb | 34 +++++++++++++++++++ .../cloud_controller/user_audit_info_spec.rb | 7 ++++ 13 files changed, 141 insertions(+), 1 deletion(-) diff --git a/app/jobs/enqueuer.rb b/app/jobs/enqueuer.rb index fb4c39c426a..89183e9b2b6 100644 --- a/app/jobs/enqueuer.rb +++ b/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 diff --git a/app/jobs/logging_context_job.rb b/app/jobs/logging_context_job.rb index 4cc94344324..0ec72c1aed7 100644 --- a/app/jobs/logging_context_job.rb +++ b/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) || diff --git a/app/jobs/pollable_job_wrapper.rb b/app/jobs/pollable_job_wrapper.rb index b1ea5c482b1..07d40de1a6a 100644 --- a/app/jobs/pollable_job_wrapper.rb +++ b/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) diff --git a/app/jobs/reoccurring_job.rb b/app/jobs/reoccurring_job.rb index 115996f2fae..250f13fbfee 100644 --- a/app/jobs/reoccurring_job.rb +++ b/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 diff --git a/app/jobs/timeout_job.rb b/app/jobs/timeout_job.rb index aad729cdbf7..fc8b5cc31c1 100644 --- a/app/jobs/timeout_job.rb +++ b/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 diff --git a/app/jobs/v3/create_service_instance_job.rb b/app/jobs/v3/create_service_instance_job.rb index f083df50a9d..227e6e1a00b 100644 --- a/app/jobs/v3/create_service_instance_job.rb +++ b/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: {} diff --git a/app/jobs/v3/update_service_instance_job.rb b/app/jobs/v3/update_service_instance_job.rb index 01d5f850986..5959d8386cc 100644 --- a/app/jobs/v3/update_service_instance_job.rb +++ b/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:, diff --git a/app/jobs/wrapping_job.rb b/app/jobs/wrapping_job.rb index 94e001fa8f0..80cd1ac42e2 100644 --- a/app/jobs/wrapping_job.rb +++ b/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 diff --git a/lib/cloud_controller/user_audit_info.rb b/lib/cloud_controller/user_audit_info.rb index 75e67615b2c..d3909bf8539 100644 --- a/lib/cloud_controller/user_audit_info.rb +++ b/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 diff --git a/spec/unit/jobs/enqueuer_spec.rb b/spec/unit/jobs/enqueuer_spec.rb index 5a7a466cca2..c0f3539e083 100644 --- a/spec/unit/jobs/enqueuer_spec.rb +++ b/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) diff --git a/spec/unit/jobs/v3/create_service_instance_job_spec.rb b/spec/unit/jobs/v3/create_service_instance_job_spec.rb index 0602de7db0e..2aa56d7bcce 100644 --- a/spec/unit/jobs/v3/create_service_instance_job_spec.rb +++ b/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 } } diff --git a/spec/unit/jobs/wrapping_job_spec.rb b/spec/unit/jobs/wrapping_job_spec.rb index a6a2ae1e04a..176e1840b23 100644 --- a/spec/unit/jobs/wrapping_job_spec.rb +++ b/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 diff --git a/spec/unit/lib/cloud_controller/user_audit_info_spec.rb b/spec/unit/lib/cloud_controller/user_audit_info_spec.rb index 136fbfe7c23..27b2cf625cb 100644 --- a/spec/unit/lib/cloud_controller/user_audit_info_spec.rb +++ b/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,