From bb0d950b70bdc72e8072c2c1ced26b9f0f7bb022 Mon Sep 17 00:00:00 2001 From: Wei Quan Date: Wed, 4 Nov 2026 15:40:16 +0100 Subject: [PATCH] feat(observability): add high-level request and job logs for package upload, resource matching, and package download - package_upload.request.start/accepted/failed in packages_controller.rb - package_upload.action.start/enqueued/failed in package_upload.rb (queue from config, no extra DB query) - package_upload.job.start/done/failed in package_bits.rb - resource_match.request.start/done in resource_matches_controller.rb - resource_match.exists.call downgraded to logger.debug to avoid O(n) log spam - resource_match done log includes cache_hits, cache_misses, cache_hit_rate, avg_resource_match_time - download_start_time measured before audit event recording - ResourceMatchPresenter accepts pre-parsed array to avoid double Oj.load per request --- app/actions/package_upload.rb | 31 +++++++++-- app/controllers/v3/packages_controller.rb | 55 +++++++++++++++---- .../v3/resource_matches_controller.rb | 26 ++++++++- app/jobs/v3/package_bits.rb | 30 +++++++++- app/presenters/v3/resource_match_presenter.rb | 2 +- lib/cloud_controller/resource_match.rb | 33 ++++++++--- spec/unit/actions/package_upload_spec.rb | 21 +++++++ spec/unit/jobs/v3/package_bits_spec.rb | 24 ++++++++ .../cloud_controller/resource_match_spec.rb | 5 ++ 9 files changed, 200 insertions(+), 27 deletions(-) diff --git a/app/actions/package_upload.rb b/app/actions/package_upload.rb index d25b85ce08e..05305830f72 100644 --- a/app/actions/package_upload.rb +++ b/app/actions/package_upload.rb @@ -3,13 +3,13 @@ class PackageUpload class InvalidPackage < StandardError; end def upload_async(message:, package:, config:, user_audit_info:, record_event: true) - enqueue(message: message, package: package, config: config, enqueue_as_pollable: true) do + enqueue(message: message, package: package, config: config, enqueue_as_pollable: true, record_event: record_event) do record_upload(package, user_audit_info) if record_event end end def upload_async_without_event(message:, package:, config:) - enqueue(message: message, package: package, config: config, enqueue_as_pollable: false) + enqueue(message: message, package: package, config: config, enqueue_as_pollable: false, record_event: false) end def upload_sync_without_event(message, package) @@ -23,11 +23,14 @@ def upload_sync_without_event(message, package) private - def enqueue(message:, package:, config:, enqueue_as_pollable:) - logger.info("uploading package bits for package #{package.guid}") + def enqueue(message:, package:, config:, enqueue_as_pollable:, record_event:) + start_time = Time.now + log_ctx = { package_guid: package.guid, app_guid: package.app_guid } + logger.info('package_upload.action.start', log_ctx) upload_job = build_job(message, package) enqueued_job = nil + queue = Jobs::Queues.local(config).to_s package.db.transaction do package.lock! @@ -35,17 +38,31 @@ def enqueue(message:, package:, config:, enqueue_as_pollable:) package.state = PackageModel::PENDING_STATE package.save - enqueuer = Jobs::Enqueuer.new(queue: Jobs::Queues.local(config)) + enqueuer = Jobs::Enqueuer.new(queue: queue) enqueued_job = enqueue_as_pollable ? enqueuer.enqueue_pollable(upload_job) : enqueuer.enqueue(upload_job) yield if block_given? end + logger.info('package_upload.action.enqueued', log_ctx.merge( + queue: queue, + job_guid: enqueued_job&.guid, + delayed_job_guid: delayed_job_guid(enqueued_job), + record_event: record_event, + duration_ms: elapsed_ms(start_time) + )) enqueued_job rescue Sequel::ValidationFailed => e + logger.info('package_upload.action.failed', log_ctx.merge(error: e.message)) raise InvalidPackage.new(e.message) end + def delayed_job_guid(job) + return job.delayed_job_guid if job.respond_to?(:delayed_job_guid) + + job&.guid + end + def record_upload(package, user_audit_info) Repositories::PackageEventRepository.record_app_package_upload( package, @@ -69,5 +86,9 @@ def randomize_file_name(filepath) def logger @logger ||= Steno.logger('cc.action.package_upload') end + + def elapsed_ms(start_time) + ((Time.now - start_time) * 1000).round + end end end diff --git a/app/controllers/v3/packages_controller.rb b/app/controllers/v3/packages_controller.rb index 00504190e17..96a505fdf66 100644 --- a/app/controllers/v3/packages_controller.rb +++ b/app/controllers/v3/packages_controller.rb @@ -64,16 +64,18 @@ def upload unprocessable!('Package type must be bits.') unless package.type == 'bits' bits_already_uploaded! if package.state != PackageModel::CREATED_STATE - begin - PackageUpload.new.upload_async( - message: message, - package: package, - config: configuration, - user_audit_info: user_audit_info - ) - rescue PackageUpload::InvalidPackage => e - unprocessable!(e.message) - end + upload_start_time = Time.now + observability_logger.info('package_upload.request.start', package_log_context(package).merge( + has_bits_path: message.bits_path.present?, + resource_count: message.resources&.size || 0 + )) + + enqueued_job = enqueue_package_upload(message, package) + + observability_logger.info('package_upload.request.accepted', package_log_context(package).merge( + job_guid: enqueued_job&.guid, + duration_ms: elapsed_ms(upload_start_time) + )) TelemetryLogger.v3_emit( 'upload-package', @@ -94,12 +96,21 @@ def download unprocessable!('Package type must be bits.') unless package.type == 'bits' unprocessable!('Package has no bits to download.') unless package.state == 'READY' + observability_logger.info('package_download.request.start', package_log_context(package)) + + download_start_time = Time.now VCAP::CloudController::Repositories::PackageEventRepository.record_app_package_download( package, user_audit_info ) send_package_blob(package) + + observability_logger.info('package_download.request.done', package_log_context(package).merge( + http_status: response.status, + redirected: response.redirect?, + duration_ms: elapsed_ms(download_start_time) + )) end def show @@ -221,4 +232,28 @@ def unprocessable_app! def unprocessable_source_package! unprocessable!('Source package is invalid. Ensure it exists and you have access to it.') end + + def enqueue_package_upload(message, package) + PackageUpload.new.upload_async( + message: message, + package: package, + config: configuration, + user_audit_info: user_audit_info + ) + rescue PackageUpload::InvalidPackage => e + observability_logger.info('package_upload.request.failed', package_log_context(package).merge(error: e.message)) + unprocessable!(e.message) + end + + def observability_logger + @observability_logger ||= Steno.logger('cc.api.packages') + end + + def package_log_context(package) + { package_guid: package.guid, app_guid: package.app_guid, user_guid: current_user.guid } + end + + def elapsed_ms(start_time) + ((Time.now - start_time) * 1000).round + end end diff --git a/app/controllers/v3/resource_matches_controller.rb b/app/controllers/v3/resource_matches_controller.rb index b345c0a312c..56d621f590c 100644 --- a/app/controllers/v3/resource_matches_controller.rb +++ b/app/controllers/v3/resource_matches_controller.rb @@ -9,12 +9,36 @@ def create message = VCAP::CloudController::ResourceMatchCreateMessage.new(hashed_params) unprocessable!(message.errors.full_messages) unless message.valid? + resource_count = message.resources&.size || 0 + logger.info('resource_match.request.start', { + user_guid: current_user.guid, + resource_count: resource_count + }) + + start_time = Time.now fingerprints_v2_response = if FeatureFlag.enabled?(:resource_matching) CloudController::DependencyLocator.instance.resource_pool_wrapper.new(message.v2_fingerprints_body).call else [].to_json end - render status: :created, json: Presenters::V3::ResourceMatchPresenter.new(fingerprints_v2_response) + matched_fingerprints = Oj.load(fingerprints_v2_response) + matched_count = matched_fingerprints.size + + logger.info('resource_match.request.done', { + user_guid: current_user.guid, + resource_count: resource_count, + matched_count: matched_count, + missing_count: resource_count - matched_count, + duration_ms: elapsed_ms(start_time) + }) + + render status: :created, json: Presenters::V3::ResourceMatchPresenter.new(matched_fingerprints) + end + + private + + def elapsed_ms(start_time) + ((Time.now - start_time) * 1000).round end end diff --git a/app/jobs/v3/package_bits.rb b/app/jobs/v3/package_bits.rb index c4e1b829f20..30be39f5d53 100644 --- a/app/jobs/v3/package_bits.rb +++ b/app/jobs/v3/package_bits.rb @@ -14,9 +14,27 @@ def initialize(package_guid, package_zip_path, fingerprints) end def perform - Steno.logger('cc.background').info("Packing the app bits for package '#{@package_guid}'") + start_time = Time.now + logger.info('package_upload.job.start', { + package_guid: @package_guid, + package_zip_path_present: @package_zip_path.present?, + fingerprint_count: @fingerprints.size + }) CloudController::Packager::PackageUploadHandler.new(@package_guid, @package_zip_path, @fingerprints).pack + + logger.info('package_upload.job.done', { + package_guid: @package_guid, + duration_ms: elapsed_ms(start_time) + }) + rescue StandardError => e + logger.info('package_upload.job.failed', { + package_guid: @package_guid, + duration_ms: elapsed_ms(start_time), + error_class: e.class.name, + error: e.message + }) + raise end def job_name_in_configuration @@ -34,6 +52,16 @@ def display_name def resource_type 'package' end + + private + + def logger + Steno.logger('cc.background') + end + + def elapsed_ms(start_time) + ((Time.now - start_time) * 1000).round + end end end end diff --git a/app/presenters/v3/resource_match_presenter.rb b/app/presenters/v3/resource_match_presenter.rb index fd469d7e51c..db086a9ced9 100644 --- a/app/presenters/v3/resource_match_presenter.rb +++ b/app/presenters/v3/resource_match_presenter.rb @@ -12,7 +12,7 @@ def to_hash private def v3ify(resource) - fingerprints = Oj.load(resource) + fingerprints = resource.is_a?(Array) ? resource : Oj.load(resource) fingerprints.map do |r| { checksum: { value: r['sha1'] }, diff --git a/lib/cloud_controller/resource_match.rb b/lib/cloud_controller/resource_match.rb index 9041469acc4..5d68697a6c8 100644 --- a/lib/cloud_controller/resource_match.rb +++ b/lib/cloud_controller/resource_match.rb @@ -16,7 +16,8 @@ def initialize(descriptors) end def match_resources - before_match_log + count_by_size = resource_count_by_filesize + before_match_log(count_by_size) time_by_bucket = FILE_SIZE_GROUPS.keys.index_with do |_key| 0 @@ -26,11 +27,19 @@ def match_resources resources_by_filesize.each do |name, resources| resources.each do |resource| start_time = Time.now - known_resources << resource if resource_pool.resource_known?(resource) - time_by_bucket[name] += Time.now - start_time + exists = resource_pool.resource_known?(resource) + duration = Time.now - start_time + known_resources << resource if exists + time_by_bucket[name] += duration + logger.debug('resource_match.exists.call', { + sha1: resource['sha1'], + size: resource['size'], + exists: exists, + duration_seconds: duration.round(4) + }) end end - after_match_log(time_by_bucket) + after_match_log(time_by_bucket, known_resources.count, count_by_size) known_resources end @@ -50,19 +59,25 @@ def resources_by_filesize end end - def before_match_log + def before_match_log(count_by_size) logger.info('starting resource matching', { total_resources_to_match: allowed_resources.count, - resource_count_by_size: resource_count_by_filesize + resource_count_by_size: count_by_size }) end - def after_match_log(time_by_bucket) + def after_match_log(time_by_bucket, cache_hits, count_by_size) total_time = time_by_bucket.sum { |_bucket, count| count } + total = allowed_resources.count + cache_misses = total - cache_hits logger.info('done matching resources', { - total_resources_to_match: allowed_resources.count, + total_resources_to_match: total, + cache_hits: cache_hits, + cache_misses: cache_misses, + cache_hit_rate: total > 0 ? (cache_hits.to_f / total).round(4) : 0, + avg_resource_match_time: total > 0 ? "#{(total_time / total).round(4)} seconds" : '0 seconds', total_resource_match_time: "#{total_time.to_f.round(2)} seconds", - resource_count_by_size: resource_count_by_filesize, + resource_count_by_size: count_by_size, resource_match_time_by_size: time_by_bucket.transform_values { |count| "#{count.to_f.round(2)} seconds" } }) end diff --git a/spec/unit/actions/package_upload_spec.rb b/spec/unit/actions/package_upload_spec.rb index 8e71fedd47a..2d9cbbedfba 100644 --- a/spec/unit/actions/package_upload_spec.rb +++ b/spec/unit/actions/package_upload_spec.rb @@ -5,8 +5,12 @@ module VCAP::CloudController RSpec.describe PackageUpload do subject(:package_upload) { PackageUpload.new } + let(:action_logger) { instance_double(Steno::Logger, info: nil) } + before do allow(File).to receive(:rename) + allow(Steno).to receive(:logger).and_call_original + allow(Steno).to receive(:logger).with('cc.action.package_upload').and_return(action_logger) end describe '#upload_async' do @@ -109,6 +113,14 @@ module VCAP::CloudController end end + it 'logs start and enqueue details' do + package_upload.upload_async(message:, package:, config:, user_audit_info:) + + expect(action_logger).to have_received(:info).with('package_upload.action.start', hash_including(package_guid: package.guid, app_guid: package.app_guid)) + expect(action_logger).to have_received(:info).with('package_upload.action.enqueued', + hash_including(package_guid: package.guid, app_guid: package.app_guid, queue: 'cc-local-1', record_event: true)) + end + context 'when the package is invalid' do before do allow(package).to receive(:save).and_raise(Sequel::ValidationFailed.new('message')) @@ -119,6 +131,15 @@ module VCAP::CloudController package_upload.upload_async(message:, package:, config:, user_audit_info:) end.to raise_error(PackageUpload::InvalidPackage) end + + it 'logs the failure details' do + expect do + package_upload.upload_async(message:, package:, config:, user_audit_info:) + end.to raise_error(PackageUpload::InvalidPackage) + + expect(action_logger).to have_received(:info).with('package_upload.action.failed', + hash_including(package_guid: package.guid, app_guid: package.app_guid, error: 'message')) + end end end diff --git a/spec/unit/jobs/v3/package_bits_spec.rb b/spec/unit/jobs/v3/package_bits_spec.rb index 67317c9f123..d6b2e872221 100644 --- a/spec/unit/jobs/v3/package_bits_spec.rb +++ b/spec/unit/jobs/v3/package_bits_spec.rb @@ -6,11 +6,16 @@ module Jobs::V3 let(:uploaded_path) { 'tmp/uploaded.zip' } let(:package_guid) { SecureRandom.uuid } let(:fingerprints) { [:fingerprint] } + let(:background_logger) { instance_double(Steno::Logger, info: nil) } subject(:job) do PackageBits.new(package_guid, uploaded_path, fingerprints) end + before do + allow(Steno).to receive(:logger).with('cc.background').and_return(background_logger) + end + it { is_expected.to be_a_valid_job } describe '#perform' do @@ -25,6 +30,25 @@ module Jobs::V3 job.perform end + it 'logs start and completion' do + allow_any_instance_of(CloudController::Packager::PackageUploadHandler).to receive(:pack) + + job.perform + + expect(background_logger).to have_received(:info).with('package_upload.job.start', + hash_including(package_guid: package_guid, package_zip_path_present: true, fingerprint_count: 1)) + expect(background_logger).to have_received(:info).with('package_upload.job.done', hash_including(package_guid: package_guid, duration_ms: be >= 0)) + end + + it 'logs failure details and re-raises' do + allow_any_instance_of(CloudController::Packager::PackageUploadHandler).to receive(:pack).and_raise(StandardError.new('boom')) + + expect { job.perform }.to raise_error(StandardError, 'boom') + + expect(background_logger).to have_received(:info).with('package_upload.job.failed', + hash_including(package_guid: package_guid, error_class: 'StandardError', error: 'boom')) + end + it 'knows its job name' do expect(job.job_name_in_configuration).to equal(:package_bits) end diff --git a/spec/unit/lib/cloud_controller/resource_match_spec.rb b/spec/unit/lib/cloud_controller/resource_match_spec.rb index ae291d85e99..bd800626331 100644 --- a/spec/unit/lib/cloud_controller/resource_match_spec.rb +++ b/spec/unit/lib/cloud_controller/resource_match_spec.rb @@ -68,6 +68,7 @@ module VCAP::CloudController Timecop.freeze(2.seconds.from_now) true end + expect(Steno.logger('cc.resource_pool')).to receive(:debug).exactly(6).times.with('resource_match.exists.call', hash_including(:sha1, :size, :exists, :duration_seconds)) expect(Steno.logger('cc.resource_pool')).to receive(:info).once.with('starting resource matching', { total_resources_to_match: 6, resource_count_by_size: { @@ -82,6 +83,10 @@ module VCAP::CloudController expect(Steno.logger('cc.resource_pool')).to receive(:info).once.with('done matching resources', { total_resources_to_match: 6, + cache_hits: 6, + cache_misses: 0, + cache_hit_rate: 1.0, + avg_resource_match_time: '2.0 seconds', total_resource_match_time: '12.0 seconds', resource_count_by_size: { '1KB or less': 0,