feat(observability): add high-level request and job logs for package …

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,29 +23,46 @@ 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!
 
         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

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

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

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

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'] },

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

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
 

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