diff --git a/lib/cloud_controller/blobstore/base_client.rb b/lib/cloud_controller/blobstore/base_client.rb index 585d934f543..bc567732ada 100644 --- a/lib/cloud_controller/blobstore/base_client.rb +++ b/lib/cloud_controller/blobstore/base_client.rb @@ -5,15 +5,39 @@ module CloudController module Blobstore class BaseClient def cp_r_to_blobstore(source_dir) - Find.find(source_dir).each do |path| - next unless File.file?(path) - next unless within_limits?(File.size(path)) - next unless File.stat(path).mode.to_s(8)[3..5].to_i(8) >= 0o600 + counters = new_cp_r_counters + traversal_completed = false - sha1 = Digester.new.digest_path(path) - next if exists?(sha1) + begin + unless File.directory?(source_dir) + logger.error('blobstore.cp_r.source_dir_missing', source_dir: source_dir) + raise Errno::ENOENT.new(source_dir) + end - cp_to_blobstore(path, sha1) + Find.find(source_dir).each do |path| + begin + stat = File.stat(path) + rescue SystemCallError + next + end + next unless stat.file? + next unless within_limits?(stat.size) + next unless stat.mode.to_s(8)[3..5].to_i(8) >= 0o600 + + cp_r_digest_file(path, counters) + sha1 = counters[:last_sha1] + + next unless sha1 + + exists = cp_r_check_exists(sha1, counters) + next if exists.nil? # exists? raised, already logged + next if exists + + cp_r_upload_file(path, sha1, counters) + end + traversal_completed = true + ensure + log_cp_r_phases(counters, traversal_completed) end end @@ -23,6 +47,67 @@ def cp_to_blobstore(_, _) private + def new_cp_r_counters + { digest_duration: 0, exists_duration: 0, upload_duration: 0, + digest_count: 0, exists_count: 0, upload_count: 0, + upload_attempts: 0, exists_errors: 0, last_sha1: nil } + end + + def cp_r_digest_file(path, counters) + t = Time.now.utc + counters[:digest_count] += 1 + counters[:last_sha1] = Digester.new.digest_path(path) + ensure + counters[:digest_duration] += Time.now.utc - t + end + + def cp_r_check_exists(sha1, counters) + t = Time.now.utc + counters[:exists_count] += 1 + exists?(sha1) + rescue StandardError => e + counters[:exists_errors] += 1 + logger.error('blobstore.cp_r.exists.error', sha1: sha1, error: e.message) + nil + ensure + counters[:exists_duration] += Time.now.utc - t + end + + def cp_r_upload_file(path, sha1, counters) + t = Time.now.utc + counters[:upload_attempts] += 1 + cp_to_blobstore(path, sha1) + counters[:upload_count] += 1 + ensure + counters[:upload_duration] += Time.now.utc - t + end + + def log_cp_r_phases(ctrs, completed) + logger.info('blobstore.cp_r.digest', + files_scanned: ctrs[:digest_count], + duration_seconds: ctrs[:digest_duration], + completed: completed) + ec = ctrs[:exists_count] + ea = ctrs[:upload_attempts] + ee = ctrs[:exists_errors] + logger.info('blobstore.cp_r.exists', + files_checked: ec, + duration_seconds: ctrs[:exists_duration], + avg_duration_seconds: ec > 0 ? ctrs[:exists_duration] / ec : 0, + cache_hits: ec - ea - ee, + cache_misses: ea, + cache_hit_rate: (ec - ee) > 0 ? (ec - ea - ee).to_f / (ec - ee) : 0, + process_spawns: ec, + error_count: ee, + completed: completed) + logger.info('blobstore.cp_r.upload', + files_to_upload: ea, + files_uploaded: ctrs[:upload_count], + files_failed: ea - ctrs[:upload_count], + duration_seconds: ctrs[:upload_duration], + completed: completed) + end + def partitioned_key(key) key = key.to_s.downcase partitioned_key = BlobKeyGenerator.full_path_from_key(key) @@ -33,6 +118,10 @@ def partitioned_key(key) def within_limits?(size) size >= @min_size && (@max_size.nil? || size <= @max_size) end + + def logger + @logger ||= Steno.logger('cc.blobstore') + end end end end diff --git a/lib/cloud_controller/blobstore/client_provider.rb b/lib/cloud_controller/blobstore/client_provider.rb index 8e30fa1dbb7..ce858ff7701 100644 --- a/lib/cloud_controller/blobstore/client_provider.rb +++ b/lib/cloud_controller/blobstore/client_provider.rb @@ -4,6 +4,8 @@ require 'cloud_controller/blobstore/local/local_client' require 'cloud_controller/blobstore/safe_delete_client' require 'cloud_controller/blobstore/storage_cli/storage_cli_client' +require 'cloud_controller/execution_context' +require 'cloud_controller/metrics/prometheus_updater' module CloudController module Blobstore @@ -49,7 +51,8 @@ def provide_storage_cli(options, directory_key, root_dir, resource_type) resource_type: resource_type, root_dir: root_dir, min_size: options[:minimum_size], - max_size: options[:maximum_size] + max_size: options[:maximum_size], + metrics_updater: metrics_updater_if_registered ) logger = Steno.logger('cc.blobstore.storage_cli_client') @@ -58,6 +61,13 @@ def provide_storage_cli(options, directory_key, root_dir, resource_type) Client.new(SafeDeleteClient.new(retryable_client, root_dir)) end + + def metrics_updater_if_registered + ctx = VCAP::CloudController::ExecutionContext.from_process_type_env + return nil unless VCAP::CloudController::Metrics::PrometheusUpdater::STORAGE_CLI_METRICS_EXECUTION_CONTEXTS.include?(ctx) + + CloudController::DependencyLocator.instance.prometheus_updater + end end end end diff --git a/lib/cloud_controller/blobstore/storage_cli/storage_cli_client.rb b/lib/cloud_controller/blobstore/storage_cli/storage_cli_client.rb index ff05e1701c9..4fb08670e36 100644 --- a/lib/cloud_controller/blobstore/storage_cli/storage_cli_client.rb +++ b/lib/cloud_controller/blobstore/storage_cli/storage_cli_client.rb @@ -20,7 +20,7 @@ class StorageCliClient < BaseClient # Native storage-cli type names supported by CC STORAGE_CLI_TYPES = %w[azurebs alioss s3 gcs dav].freeze - def initialize(directory_key:, resource_type:, root_dir:, min_size: nil, max_size: nil) + def initialize(directory_key:, resource_type:, root_dir:, min_size: nil, max_size: nil, metrics_updater: nil) raise 'Missing resource_type' if resource_type.nil? config_file_path = config_path_for(resource_type) @@ -40,6 +40,7 @@ def initialize(directory_key:, resource_type:, root_dir:, min_size: nil, max_siz @root_dir = root_dir @min_size = min_size || 0 @max_size = max_size + @metrics_updater = metrics_updater end def fetch_config(resource_type) @@ -102,23 +103,123 @@ def download_from_blobstore(source_key, destination_path, mode: nil) def cp_to_blobstore(source_path, destination_key) start = Time.now.utc log_entry = 'cp-skip' - size = -1 + size = nil logger.info('cp-start', destination_key: destination_key, source_path: source_path, bucket: @directory_key) - File.open(source_path) do |file| - size = file.size - next unless within_limits?(size) + state = new_cp_state + begin + File.open(source_path) do |file| + size = file.size + log_entry = perform_put_or_skip(source_path, destination_key, size, start, state) + end + rescue Interrupt, SignalException + log_entry = 'cp-error' + emit_signal_metric_if_needed(start, state) + raise + rescue StandardError + log_entry = 'cp-error' + safe_emit_metrics('put', -3, Time.now.utc - start, 'cp_to_blobstore') unless run_cli_called?(state) + raise + ensure + safe_log_finish(log_entry, destination_key, start, size) + end + end + + def perform_put_or_skip(source_path, destination_key, size, start, state) + unless within_limits?(size) + safe_emit_metrics('put', -4, Time.now.utc - start, 'cp_to_blobstore skip') + mark_skip_metric_emitted!(state) + return 'cp-skip' + end + + mark_run_cli_called!(state) + run_put_with_fatal_rescue(source_path, destination_key, size, start, state) + mark_run_cli_succeeded!(state) + 'cp-finish' + end - run_cli('put', source_path, partitioned_key(destination_key)) - log_entry = 'cp-finish' + def run_put_with_fatal_rescue(source_path, destination_key, size, start, state) + run_cli('put', source_path, partitioned_key(destination_key), blob_size: size) + rescue StandardError + # run_cli already emitted a metric before re-raising; nothing to do here. + raise + rescue Exception => e # rubocop:disable Lint/RescueException + handle_fatal_put_exception(e, start, state) + raise + end + + def handle_fatal_put_exception(exception, start, state) + # Catches fatal exceptions (NoMemoryError etc.) and signals (Interrupt, SignalException) + # that StandardError does not cover. + # + # For signals: if Interrupt fired after run_cli returned, run_cli already emitted + # exit_code=0, so mark succeeded to avoid emitting a duplicate signal metric. + # For fatal exceptions: run_cli has not emitted, so emit -7 here. + if signal_exception?(exception) + mark_run_cli_succeeded!(state) + else + safe_emit_metrics('put', -7, Time.now.utc - start, 'fatal exception in run_cli') end + end + + def emit_signal_metric_if_needed(start, state) + return if run_cli_succeeded?(state) || skip_metric_emitted?(state) + + # -5: signal before CLI was invoked; -6: signal mid-execution after CLI was invoked. + signal_exit_code = run_cli_called?(state) ? -6 : -5 + safe_emit_metrics('put', signal_exit_code, Time.now.utc - start, 'signal in cp_to_blobstore') + end + + def signal_exception?(exception) + exception.is_a?(Interrupt) || exception.is_a?(SignalException) + end + + def new_cp_state + { + run_cli_called: false, + run_cli_succeeded: false, + skip_metric_emitted: false + } + end + + def mark_run_cli_called!(state) + state[:run_cli_called] = true + end + + def mark_run_cli_succeeded!(state) + state[:run_cli_succeeded] = true + end + + def mark_skip_metric_emitted!(state) + state[:skip_metric_emitted] = true + end + + def run_cli_called?(state) + state[:run_cli_called] + end + + def run_cli_succeeded?(state) + state[:run_cli_succeeded] + end + + def skip_metric_emitted?(state) + state[:skip_metric_emitted] + end - duration = Time.now.utc - start + def safe_emit_metrics(operation, exit_code, duration, context, blob_size: nil) + emit_storage_cli_metrics(operation, exit_code, duration, blob_size: blob_size) + rescue StandardError => e + logger.warn("emit_storage_cli_metrics failed in #{context}: #{e.inspect}") + end + + def safe_log_finish(log_entry, destination_key, start, size) logger.info(log_entry, destination_key: destination_key, - duration_seconds: duration, + duration_seconds: Time.now.utc - start, size: size) + rescue StandardError => e + logger.warn("cp_to_blobstore ensure log failed: #{e.inspect}") end def cp_file_between_keys(source_key, destination_key) @@ -170,25 +271,128 @@ def additional_flags flags_string.split end - def run_cli(command, *args, allow_exit_code_three: false) + def run_cli(command, *args, allow_exit_code_three: false, blob_size: nil) + log_fields = operation_log_fields(command, args, blob_size: blob_size) + logger.debug("running storage-cli: #{@cli_path} -s #{@storage_type} -c #{@config_file} #{additional_flags.join(' ')} #{command} #{args.join(' ')}") - begin - stdout, stderr, status = Open3.capture3(@cli_path, '-s', @storage_type, '-c', @config_file, *additional_flags, command, *args) - stderr.split("\n").each do |line| - logger.info("[INFO] storage-cli: #{line}") - end - rescue StandardError => e - raise BlobstoreError.new(e.inspect) - end + t = Time.now.utc + stdout, stderr, status = capture_cli(command, args, t) + duration = Time.now.utc - t + + stderr.split("\n").each { |line| logger.info("[INFO] storage-cli: #{line}") } - unless status.success? || (allow_exit_code_three && status.exitstatus == 3) - raise "storage-cli #{command} failed with exit code #{status.exitstatus}, output: '#{stdout}', error: '#{stderr}'" + exit_code = resolve_exit_code(status) + success = status.success? || (allow_exit_code_three && status.exitstatus == 3) + + logger.info("storage_cli.call.finish #{command}#{log_message_arg_suffix(command, args)}", + log_fields.merge( + 'duration_seconds' => duration, + 'exit_code' => exit_code, + 'success' => success + )) + + unless success + safe_emit_metrics(command, exit_code, duration, 'run_cli failure', blob_size: blob_size) + raise "storage-cli #{command} failed with exit code #{exit_code.inspect}, output: '#{stdout}', error: '#{stderr}'" end + # Remap allowed exit 3 (e.g. key-not-found on exists) to 0 so Prometheus only + # records non-zero exit_codes for genuine failures. + metric_exit_code = allow_exit_code_three && exit_code == 3 ? 0 : exit_code + safe_emit_metrics(command, metric_exit_code, duration, 'run_cli success', blob_size: blob_size) + [stdout, status] end + def operation_log_fields(command, args, blob_size: nil) + fields = { + 'operation' => command, + 'bucket' => @directory_key, + 'resource_type' => @resource_type + } + + case command + when 'put' + fields['source_path'] = args[0] + fields['destination_key'] = args[1] + when 'get' + fields['source_key'] = args[0] + fields['destination_path'] = args[1] + when 'copy' + fields['source_key'] = args[0] + fields['destination_key'] = args[1] + when 'exists', 'delete', 'properties' + fields['key'] = args[0] + when 'list' + fields['prefix'] = args[0] + when 'delete-recursive' + fields['path'] = args[0] + when 'sign', 'sign-public', 'sign-internal' + fields['key'] = args[0] + fields['verb'] = args[1] + fields['expires_in'] = args[2] + end + + fields['size'] = blob_size if blob_size + fields + end + + def capture_cli(command, args, start_time) + Open3.capture3(@cli_path, '-s', @storage_type, '-c', @config_file, *additional_flags, command, *args) + rescue StandardError => e + # exit_code=-1 is a sentinel for spawn failures (binary missing, permission denied). + duration = Time.now.utc - start_time + logger.error("storage_cli.call.error #{command}#{log_message_arg_suffix(command, args)}", + 'operation' => command, + 'bucket' => @directory_key, + 'resource_type' => @resource_type, + 'duration_seconds' => duration, + 'error' => e.inspect) + safe_emit_metrics(command, -1, duration, 'spawn error') + raise BlobstoreError.new(e.inspect) + end + + def log_message_arg_suffix(command, args) + printable_args = + case command + when 'put', 'copy', 'get' + ["src=#{summarize_log_arg(args[0])}", "dest=#{summarize_log_arg(args[1])}"] + when 'sign', 'sign-public', 'sign-internal' + [ + "key=#{summarize_log_arg(args[0])}", + "verb=#{args[1]}", + "expires_in=#{args[2]}" + ] + when 'exists', 'delete', 'properties' + ["key=#{summarize_log_arg(args[0])}"] + when 'list' + ["prefix=#{summarize_log_arg(args[0])}"] + when 'delete-recursive' + ["path=#{summarize_log_arg(args[0])}"] + else + [] + end + + printable_args = printable_args.compact.map(&:to_s).reject(&:empty?) + printable_args.empty? ? '' : " #{printable_args.join(' ')}" + end + + def summarize_log_arg(arg) + File.basename(arg.to_s) + end + + def resolve_exit_code(status) + if status.exitstatus + status.exitstatus + elsif status.termsig + 128 + status.termsig + else + # exit_code=-2: process exited with neither exitstatus nor termsig (platform anomaly). + -2 + end + end + def sign_url(key, verb:, expires_in_seconds:, use_internal_url: false) command = if @storage_type == 'dav' @@ -228,6 +432,12 @@ def tmpdir def logger @logger ||= Steno.logger('cc.blobstore.storage_cli_client') end + + def emit_storage_cli_metrics(operation, exit_code, duration_seconds, blob_size: nil) + return if @metrics_updater.nil? + + @metrics_updater.report_storage_cli_metrics(operation:, exit_code:, duration_seconds:, blob_size:) + end end end end diff --git a/lib/cloud_controller/metrics/prometheus_updater.rb b/lib/cloud_controller/metrics/prometheus_updater.rb index fc03f27e68a..88d4b24d401 100644 --- a/lib/cloud_controller/metrics/prometheus_updater.rb +++ b/lib/cloud_controller/metrics/prometheus_updater.rb @@ -63,6 +63,39 @@ def self.allow_pid_label { type: :histogram, name: :cc_job_duration_seconds, docstring: 'Job processing time (start to finish)', labels: %i[queue worker], buckets: DELAYED_JOB_METRIC_BUCKETS } ].freeze + STORAGE_CLI_DURATION_BUCKETS = [0.01, 0.05, 0.1, 0.5, 1, 5, 10, 30, 60].freeze + STORAGE_CLI_PUT_OPERATION = 'put'.freeze + STORAGE_CLI_SIZE_BUCKETS = [1_024, 10_240, 102_400, 1_048_576, 10_485_760, 104_857_600, 1_073_741_824].freeze + STORAGE_CLI_METRICS_EXECUTION_CONTEXTS = [ + VCAP::CloudController::ExecutionContext::CC_WORKER, + VCAP::CloudController::ExecutionContext::API_PUMA_MAIN, + VCAP::CloudController::ExecutionContext::API_PUMA_WORKER + ].freeze + + STORAGE_CLI_OPERATIONS_TOTAL_DOCSTRING = + 'Total storage-cli subprocess invocations by operation and exit_code. ' \ + 'exit_code=0: success; exit_code=3: not-found (expected for exists); ' \ + 'exit_code=-1: spawn failure (binary missing or permission denied); ' \ + 'exit_code=-2: process exited with neither exitstatus nor termsig (platform anomaly); ' \ + 'exit_code=-3: source file open/read failure before CLI invocation; ' \ + 'exit_code=-4: upload skipped locally because blob size is outside configured limits; ' \ + 'exit_code=-5: local non-StandardError before CLI invocation (for example Interrupt or SignalException); ' \ + 'exit_code=-6: signal received after CLI invocation began (Interrupt or SignalException mid-execution); ' \ + 'exit_code=-7: fatal non-signal exception escaping run_cli (e.g. NoMemoryError)'.freeze + STORAGE_CLI_METRICS = [ + { type: :counter, name: :cc_storage_cli_operations_total, + docstring: STORAGE_CLI_OPERATIONS_TOTAL_DOCSTRING, + labels: %i[operation exit_code] }, + { type: :histogram, name: :cc_storage_cli_duration_seconds, + docstring: 'Duration of individual storage-cli subprocess invocations. ' \ + 'Counts per-retry, not per logical operation.', + labels: %i[operation exit_code], buckets: STORAGE_CLI_DURATION_BUCKETS }, + { type: :histogram, name: :cc_storage_cli_blob_size_bytes, + docstring: 'Local source file size for storage-cli put operations ' \ + '(only emitted on success; reflects pre-upload size, not remote stored size)', + labels: %i[operation], buckets: STORAGE_CLI_SIZE_BUCKETS } + ].freeze + VITAL_METRICS = [ { type: :gauge, name: :cc_vitals_started_at, docstring: 'CloudController Vitals: started_at', aggregation: :most_recent }, { type: :gauge, name: :cc_vitals_mem_bytes, docstring: 'CloudController Vitals: mem_bytes', aggregation: :most_recent }, @@ -78,8 +111,8 @@ def initialize(registry: Prometheus::Client.registry) @registry = registry @execution_context = VCAP::CloudController::ExecutionContext.from_process_type_env - register_metrics_for_process - return if @execution_context.nil? # In unit tests, the execution context might not be set - thus skip initialization + register_metrics_for_process unless @execution_context.nil? + return if @execution_context.nil? initialize_cc_db_connection_pool_timeouts_total end @@ -92,6 +125,7 @@ def register_metrics_for_process when VCAP::CloudController::ExecutionContext::CC_WORKER DB_CONNECTION_POOL_METRICS.each { |metric| register(metric) } DELAYED_JOB_METRICS.each { |metric| register(metric) } + STORAGE_CLI_METRICS.each { |metric| register(metric) } VITAL_METRICS.each { |metric| register(metric) } when VCAP::CloudController::ExecutionContext::CLOCK, VCAP::CloudController::ExecutionContext::DEPLOYMENT_UPDATER DB_CONNECTION_POOL_METRICS.each { |metric| register(metric) } @@ -99,6 +133,7 @@ def register_metrics_for_process when VCAP::CloudController::ExecutionContext::API_PUMA_MAIN, VCAP::CloudController::ExecutionContext::API_PUMA_WORKER DB_CONNECTION_POOL_METRICS.each { |metric| register(metric) } DELAYED_JOB_METRICS.each { |metric| register(metric) } + STORAGE_CLI_METRICS.each { |metric| register(metric) } VITAL_METRICS.each { |metric| register(metric) } METRICS.each { |metric| register(metric) } PUMA_METRICS.each { |metric| register(metric) } @@ -210,6 +245,34 @@ def report_staging_failure_metrics(duration_ns) update_histogram_metric(:cc_staging_failed_duration_seconds, nanoseconds_to_seconds(duration_ns)) end + def report_storage_cli_metrics(operation:, exit_code:, duration_seconds:, blob_size: nil) + missing_metrics = [] + + if @registry.exist?(:cc_storage_cli_operations_total) + @registry.get(:cc_storage_cli_operations_total).increment(labels: { operation: operation, exit_code: exit_code.to_s }) + else + missing_metrics << :cc_storage_cli_operations_total + end + + if @registry.exist?(:cc_storage_cli_duration_seconds) + update_histogram_metric(:cc_storage_cli_duration_seconds, duration_seconds, labels: { operation: operation, exit_code: exit_code.to_s }) + else + missing_metrics << :cc_storage_cli_duration_seconds + end + + if !blob_size.nil? && exit_code == 0 && operation == STORAGE_CLI_PUT_OPERATION + if @registry.exist?(:cc_storage_cli_blob_size_bytes) + update_histogram_metric(:cc_storage_cli_blob_size_bytes, blob_size, labels: { operation: operation }) + else + missing_metrics << :cc_storage_cli_blob_size_bytes + end + end + + return if missing_metrics.empty? + + Steno.logger('cc.metrics').warn("report_storage_cli_metrics: missing storage_cli metrics #{missing_metrics.join(', ')}") + end + private def register(metric) @@ -230,7 +293,7 @@ def register_metric(type, name, message, labels:, buckets:, aggregation:) when :histogram @registry.histogram(name, docstring: message, labels: labels, buckets: buckets, store_settings: store_settings) else - throw ArgumentError("Metric type #{type} does not exist.") + raise ArgumentError.new("Metric type #{type} does not exist.") end end diff --git a/lib/cloud_controller/packager/local_bits_packer.rb b/lib/cloud_controller/packager/local_bits_packer.rb index 62688d2275b..0532cb982e3 100644 --- a/lib/cloud_controller/packager/local_bits_packer.rb +++ b/lib/cloud_controller/packager/local_bits_packer.rb @@ -20,16 +20,23 @@ def send_package_to_blobstore(blobstore_key, uploaded_package_zip, cached_files_ Dir.mkdir(local_bits_packer_path) + pack_start = Time.now.utc begin complete_package_path = match_resources_and_validate_package(local_bits_packer_path, uploaded_package_zip, cached_files_fingerprints) - package_blobstore.cp_to_blobstore(complete_package_path, blobstore_key) + t = Time.now.utc + begin + package_blobstore.cp_to_blobstore(complete_package_path, blobstore_key) + ensure + logger.info('packer.final-upload', duration_seconds: Time.now.utc - t, blobstore_key: blobstore_key) + end { sha1: Digester.new.digest_path(complete_package_path), sha256: Digester.new(algorithm: OpenSSL::Digest::SHA256).digest_path(complete_package_path) } ensure + logger.info('packer.pack', duration_seconds: Time.now.utc - pack_start, blobstore_key: blobstore_key) FileUtils.remove_dir(local_bits_packer_path) end end diff --git a/lib/cloud_controller/packager/shared_bits_packer.rb b/lib/cloud_controller/packager/shared_bits_packer.rb index 8182a3c8c38..1af296ce466 100644 --- a/lib/cloud_controller/packager/shared_bits_packer.rb +++ b/lib/cloud_controller/packager/shared_bits_packer.rb @@ -1,3 +1,4 @@ +require 'find' require 'shellwords' module CloudController @@ -24,11 +25,22 @@ def copy_uploaded_package(uploaded_package_zip, app_packager) def populate_resource_cache(app_packager, app_contents_path) FileUtils.mkdir(app_contents_path) - app_packager.unzip(app_contents_path) + + t = Time.now.utc + begin + app_packager.unzip(app_contents_path) + ensure + logger.info('packer.unzip', duration_seconds: Time.now.utc - t) + end remove_symlinks(app_contents_path) - global_app_bits_cache.cp_r_to_blobstore(app_contents_path) + t = Time.now.utc + begin + global_app_bits_cache.cp_r_to_blobstore(app_contents_path) + ensure + logger.info('packer.resource-cache-upload', duration_seconds: Time.now.utc - t) + end end def remove_symlinks(app_contents_path) @@ -43,19 +55,35 @@ def append_matched_resources(app_packager, cached_files_fingerprints, root_path) FileUtils.mkdir(cached_resources_dir) checksum_mismatch = false - matched_resources.each do |local_destination, file_sha, mode| - file_path = File.join(cached_resources_dir, local_destination) - global_app_bits_cache.download_from_blobstore(file_sha, file_path, mode:) - - if Digester.new.digest_path(file_path) != file_sha - checksum_mismatch = true - global_app_bits_cache.delete(file_sha) + download_count = 0 + download_attempts = 0 + + t = Time.now.utc + begin + matched_resources.each do |local_destination, file_sha, mode| + file_path = File.join(cached_resources_dir, local_destination) + download_attempts += 1 + global_app_bits_cache.download_from_blobstore(file_sha, file_path, mode:) + + if Digester.new.digest_path(file_path) != file_sha + checksum_mismatch = true + global_app_bits_cache.delete(file_sha) + end + + download_count += 1 end + ensure + logger.info('packer.resource-cache-download', duration_seconds: Time.now.utc - t, files_downloaded: download_count, files_attempted: download_attempts) end raise CloudController::Errors::ApiError.new_from_details('ResourceChecksumMismatch') if checksum_mismatch - app_packager.append_dir_contents(cached_resources_dir) + t = Time.now.utc + begin + app_packager.append_dir_contents(cached_resources_dir) + ensure + logger.info('packer.repackage', duration_seconds: Time.now.utc - t) + end end def match_resources_and_validate_package(root_path, uploaded_package_zip, cached_files_fingerprints) @@ -82,6 +110,10 @@ def max_package_size def global_app_bits_cache CloudController::DependencyLocator.instance.global_app_bits_cache end + + def logger + @logger ||= Steno.logger('cc.packer') + end end end end diff --git a/lib/tasks/jobs.rake b/lib/tasks/jobs.rake index 671e4ec6b05..9c2aa46cf33 100644 --- a/lib/tasks/jobs.rake +++ b/lib/tasks/jobs.rake @@ -32,6 +32,12 @@ namespace :jobs do args.with_defaults(name: queue) RakeConfig.context = :api + VCAP::CloudController::ExecutionContext::API_PUMA_WORKER.set_process_type_env + + require 'prometheus/client/data_stores/direct_file_store' + prometheus_dir = File.join(RakeConfig.config.get(:directories, :tmpdir), 'prometheus') + FileUtils.mkdir_p(prometheus_dir) + Prometheus::Client.config.data_store = Prometheus::Client::DataStores::DirectFileStore.new(dir: prometheus_dir) CloudController::DelayedWorker.new(queues: [queue], name: args.name).start_working diff --git a/spec/unit/lib/cloud_controller/blobstore/client_provider_spec.rb b/spec/unit/lib/cloud_controller/blobstore/client_provider_spec.rb index 6c90ed9c668..50215ae5fc6 100644 --- a/spec/unit/lib/cloud_controller/blobstore/client_provider_spec.rb +++ b/spec/unit/lib/cloud_controller/blobstore/client_provider_spec.rb @@ -28,7 +28,7 @@ module Blobstore allow(StorageCliClient).to receive(:new).and_return(storage_cli_client_mock) ClientProvider.provide(options:, directory_key:, root_dir:, resource_type:) expect(StorageCliClient).to have_received(:new).with(directory_key: directory_key, resource_type: resource_type, root_dir: root_dir, - min_size: 100, max_size: 1000) + min_size: 100, max_size: 1000, metrics_updater: anything) end it 'raises an error if provider is not provided' do diff --git a/spec/unit/lib/cloud_controller/blobstore/error_handling_client_spec.rb b/spec/unit/lib/cloud_controller/blobstore/error_handling_client_spec.rb index d9f77c0c9b7..999b7e057bf 100644 --- a/spec/unit/lib/cloud_controller/blobstore/error_handling_client_spec.rb +++ b/spec/unit/lib/cloud_controller/blobstore/error_handling_client_spec.rb @@ -8,7 +8,7 @@ module Blobstore RSpec.describe ErrorHandlingClient do subject(:client) { ErrorHandlingClient.new(wrapped_client) } let(:wrapped_client) { Blobstore::NullClient.new } - let(:logger) { instance_double(Steno::Logger, error: nil) } + let(:logger) { instance_double(Steno::Logger, error: nil, info: nil) } before do allow(Steno).to receive(:logger).and_return(logger) diff --git a/spec/unit/lib/cloud_controller/blobstore/local/local_client_spec.rb b/spec/unit/lib/cloud_controller/blobstore/local/local_client_spec.rb index 6788bce225d..a94d754ff11 100644 --- a/spec/unit/lib/cloud_controller/blobstore/local/local_client_spec.rb +++ b/spec/unit/lib/cloud_controller/blobstore/local/local_client_spec.rb @@ -104,6 +104,69 @@ module Blobstore end end + describe '#cp_r_to_blobstore' do + it 'logs completed: false when traversal is interrupted before any files are processed' do + allow(Find).to receive(:find).and_raise(Errno::EACCES) + + expect do + client.cp_r_to_blobstore(base_path) + end.to raise_error(Errno::EACCES) + + expect(logger).to have_received(:info).with('blobstore.cp_r.digest', hash_including(files_scanned: 0, completed: false)) + expect(logger).to have_received(:info).with('blobstore.cp_r.exists', hash_including(files_checked: 0, completed: false)) + expect(logger).to have_received(:info).with('blobstore.cp_r.upload', hash_including(files_uploaded: 0, files_to_upload: 0, completed: false)) + end + + it 'skips broken symlinks without aborting traversal' do + source_dir = File.join(base_path, 'source') + FileUtils.mkdir_p(source_dir) + File.write(File.join(source_dir, 'file.txt'), 'contents') + File.symlink(File.join(source_dir, 'missing-target.txt'), File.join(source_dir, 'broken-link.txt')) + + expect do + client.cp_r_to_blobstore(source_dir) + end.not_to raise_error + end + + it 'continues traversal and increments error_count when exists? raises' do + source_dir = File.join(base_path, 'source') + FileUtils.mkdir_p(source_dir) + File.write(File.join(source_dir, 'file1.txt'), 'x' * 100) + File.write(File.join(source_dir, 'file2.txt'), 'y' * 100) + + call_count = 0 + allow(client).to receive(:exists?) do + call_count += 1 + raise StandardError.new('exists failed') if call_count == 1 + + false + end + + expect do + client.cp_r_to_blobstore(source_dir) + end.not_to raise_error + + expect(logger).to have_received(:info).with('blobstore.cp_r.exists', + hash_including(files_checked: 2, error_count: 1, cache_hits: 0, cache_hit_rate: 0.0, completed: true)) + end + + it 'counts a digest attempt even when digest_path raises' do + source_dir = File.join(base_path, 'source') + FileUtils.mkdir_p(source_dir) + File.write(File.join(source_dir, 'file.txt'), 'contents') + + digester = instance_double(Digester) + allow(digester).to receive(:digest_path).and_raise(StandardError.new('digest failed')) + allow(Digester).to receive(:new).and_return(digester) + + expect do + client.cp_r_to_blobstore(source_dir) + end.to raise_error(StandardError, 'digest failed') + + expect(logger).to have_received(:info).with('blobstore.cp_r.digest', hash_including(files_scanned: 1, completed: false)) + end + end + describe '#download_from_blobstore' do it 'downloads a file from the blobstore' do key = 'abcdef123456' diff --git a/spec/unit/lib/cloud_controller/blobstore/storage_cli/storage_cli_client_spec.rb b/spec/unit/lib/cloud_controller/blobstore/storage_cli/storage_cli_client_spec.rb index 41d7a7b5d6c..3927a63a0cb 100644 --- a/spec/unit/lib/cloud_controller/blobstore/storage_cli/storage_cli_client_spec.rb +++ b/spec/unit/lib/cloud_controller/blobstore/storage_cli/storage_cli_client_spec.rb @@ -16,7 +16,7 @@ def stub_config_for_droplets(path) config_double = instance_double(VCAP::CloudController::Config) allow(VCAP::CloudController::Config).to receive(:config).and_return(config_double) allow(config_double).to receive(:get).with(:storage_cli_config_file_droplets).and_return(path) - allow(Steno).to receive(:logger).and_return(double(info: nil, error: nil, debug: nil)) + allow(Steno).to receive(:logger).and_return(double(info: nil, error: nil, debug: nil, warn: nil)) end describe 'client init' do @@ -160,7 +160,7 @@ def stub_config_for_droplets(path) end end - allow(Steno).to receive(:logger).and_return(double(info: nil, error: nil, debug: nil)) + allow(Steno).to receive(:logger).and_return(double(info: nil, error: nil, debug: nil, warn: nil)) end after do @@ -283,6 +283,9 @@ def build_client(resource_type) end it 'returns the default CLI path' do + allow(ENV).to receive(:[]).and_call_original + allow(ENV).to receive(:[]).with('STORAGE_CLI_PATH').and_return(nil) + expect(client.send(:cli_path)).to eq('/var/vcap/packages/storage-cli/bin/storage-cli') end @@ -318,7 +321,7 @@ def build_client(resource_type) tmp_cfg.path end end - allow(Steno).to receive(:logger).and_return(double(info: nil, error: nil, debug: nil)) + allow(Steno).to receive(:logger).and_return(double(info: nil, error: nil, debug: nil, warn: nil)) end after { tmp_cfg.close! } @@ -494,10 +497,76 @@ def build_client(resource_type) end describe '#run_cli' do + let(:logger_double) { instance_double(Steno::Logger, info: nil, error: nil, debug: nil, warn: nil) } + before do + allow(Steno).to receive(:logger).and_return(logger_double) allow(client).to receive(:additional_flags).and_return([]) end + it 'logs structured finish fields for successful calls' do + status = instance_double(Process::Status, success?: true, exitstatus: 0) + allow(Open3).to receive(:capture3).and_return(['ok', '', status]) + + client.send(:run_cli, 'put', 'src-path', 'dest-key', blob_size: 1024) + + expect(logger_double).to have_received(:info).with('storage_cli.call.finish put src=src-path dest=dest-key', hash_including( + 'operation' => 'put', + 'bucket' => directory_key, + 'resource_type' => resource_type, + 'source_path' => 'src-path', + 'destination_key' => 'dest-key', + 'size' => 1024, + 'exit_code' => 0, + 'success' => true, + 'duration_seconds' => a_kind_of(Float) + )) + end + + it 'logs finish fields for failed calls' do + status = instance_double(Process::Status, success?: false, exitstatus: 1) + allow(Open3).to receive(:capture3).and_return(['', 'error message', status]) + + expect do + client.send(:run_cli, 'exists', 'arg1') + end.to raise_error(RuntimeError, /storage-cli exists failed with exit code 1/) + + expect(logger_double).to have_received(:info).with('storage_cli.call.finish exists key=arg1', hash_including( + 'operation' => 'exists', + 'bucket' => directory_key, + 'resource_type' => resource_type, + 'key' => 'arg1', + 'exit_code' => 1, + 'success' => false, + 'duration_seconds' => a_kind_of(Float) + )) + end + + it 'uses basename of key arg in message text with key= label but keeps full structured key' do + status = instance_double(Process::Status, success?: true, exitstatus: 0) + allow(Open3).to receive(:capture3).and_return(['ok', '', status]) + + long_key = 'app_bits_cache/97/d0/97d004b6ef4a8c8f5e3b6a0f4c1d2e3f7a8b9c00112233445566778899aabbcc' + client.send(:run_cli, 'exists', long_key) + + expect(logger_double).to have_received(:info).with( + 'storage_cli.call.finish exists key=97d004b6ef4a8c8f5e3b6a0f4c1d2e3f7a8b9c00112233445566778899aabbcc', + hash_including('key' => long_key, 'success' => true) + ) + end + + it 'labels sign args in message text' do + status = instance_double(Process::Status, success?: true, exitstatus: 0) + allow(Open3).to receive(:capture3).and_return(['ok', '', status]) + + client.send(:run_cli, 'sign', 'abc123def456', 'get', '3600s') + + expect(logger_double).to have_received(:info).with( + 'storage_cli.call.finish sign key=abc123def456 verb=get expires_in=3600s', + hash_including('key' => 'abc123def456', 'verb' => 'get', 'expires_in' => '3600s', 'success' => true) + ) + end + it 'returns output and status on success' do status = instance_double(Process::Status, success?: true, exitstatus: 0) allow(Open3).to receive(:capture3).and_return(['ok', '', status]) @@ -530,6 +599,319 @@ def build_client(resource_type) expect { client.send(:run_cli, 'list', 'arg1') }.to raise_error(BlobstoreError, /Open3 error/) end + + it 'reports 128+signal when the storage-cli process is terminated by a signal' do + metrics_updater = double('metrics_updater') + allow(metrics_updater).to receive(:report_storage_cli_metrics) + signal_client = StorageCliClient.new( + directory_key: directory_key, + resource_type: resource_type, + root_dir: 'bommel', + metrics_updater: metrics_updater + ) + allow(signal_client).to receive(:additional_flags).and_return([]) + + status = instance_double(Process::Status, success?: false, exitstatus: nil, termsig: 9) + allow(Open3).to receive(:capture3).and_return(['', '', status]) + + expect { signal_client.send(:run_cli, 'get', 'some-key') }.to raise_error(RuntimeError, /exit code 137/) + expect(metrics_updater).to have_received(:report_storage_cli_metrics).with( + operation: 'get', exit_code: 137, duration_seconds: a_kind_of(Float), blob_size: nil + ) + end + + it 'reports exit_code=-1 when Open3 raises (spawn failure)' do + metrics_updater = double('metrics_updater') + allow(metrics_updater).to receive(:report_storage_cli_metrics) + spawning_client = StorageCliClient.new( + directory_key: directory_key, + resource_type: resource_type, + root_dir: 'bommel', + metrics_updater: metrics_updater + ) + allow(spawning_client).to receive(:additional_flags).and_return([]) + allow(Open3).to receive(:capture3).and_raise(Errno::ENOENT.new('storage-cli binary not found')) + + expect { spawning_client.send(:run_cli, 'get', 'some-key') }.to raise_error(BlobstoreError) + expect(metrics_updater).to have_received(:report_storage_cli_metrics).with( + operation: 'get', exit_code: -1, duration_seconds: a_kind_of(Float), blob_size: nil + ) + expect(logger_double).to have_received(:error).with('storage_cli.call.error get src=some-key dest=', hash_including( + 'operation' => 'get', + 'bucket' => directory_key, + 'resource_type' => resource_type, + 'duration_seconds' => a_kind_of(Float), + 'error' => a_string_matching(/Errno::ENOENT/) + )) + end + + it 'lets Interrupt propagate from Open3.capture3' do + metrics_updater = double('metrics_updater') + allow(metrics_updater).to receive(:report_storage_cli_metrics) + spawning_client = StorageCliClient.new( + directory_key: directory_key, + resource_type: resource_type, + root_dir: 'bommel', + metrics_updater: metrics_updater + ) + allow(spawning_client).to receive(:additional_flags).and_return([]) + allow(Open3).to receive(:capture3).and_raise(Interrupt) + + expect(metrics_updater).not_to receive(:report_storage_cli_metrics) + expect { spawning_client.send(:run_cli, 'get', 'some-key') }.to raise_error(Interrupt) + end + + context 'metrics' do + let(:metrics_updater) { double('metrics_updater') } + let(:client_with_metrics) do + StorageCliClient.new( + directory_key: directory_key, + resource_type: resource_type, + root_dir: 'bommel', + metrics_updater: metrics_updater + ) + end + + before do + allow(client_with_metrics).to receive(:additional_flags).and_return([]) + allow(metrics_updater).to receive(:report_storage_cli_metrics) + end + + it 'reports metrics with operation and exit_code on success' do + status = instance_double(Process::Status, success?: true, exitstatus: 0) + allow(Open3).to receive(:capture3).and_return(['', '', status]) + + client_with_metrics.send(:run_cli, 'get', 'some-key', 'dest-path') + + expect(metrics_updater).to have_received(:report_storage_cli_metrics).with( + operation: 'get', exit_code: 0, duration_seconds: a_kind_of(Float), blob_size: nil + ) + end + + it 'passes blob_size for put operations' do + status = instance_double(Process::Status, success?: true, exitstatus: 0) + allow(Open3).to receive(:capture3).and_return(['', '', status]) + + client_with_metrics.send(:run_cli, 'put', 'src', 'dest', blob_size: 1024) + + expect(metrics_updater).to have_received(:report_storage_cli_metrics).with( + operation: 'put', exit_code: 0, duration_seconds: a_kind_of(Float), blob_size: 1024 + ) + end + + it 'still reports metrics when the command fails' do + status = instance_double(Process::Status, success?: false, exitstatus: 1) + allow(Open3).to receive(:capture3).and_return(['', 'err', status]) + + expect { client_with_metrics.send(:run_cli, 'put', 'src', 'dest') }.to raise_error(RuntimeError) + expect(metrics_updater).to have_received(:report_storage_cli_metrics).with( + operation: 'put', exit_code: 1, duration_seconds: a_kind_of(Float), blob_size: nil + ) + end + + it 'forwards blob_size to report_storage_cli_metrics even on failure (PrometheusUpdater suppresses the histogram observation)' do + status = instance_double(Process::Status, success?: false, exitstatus: 1) + allow(Open3).to receive(:capture3).and_return(['', 'err', status]) + + # run_cli forwards blob_size to report_storage_cli_metrics regardless of exit_code; + # PrometheusUpdater#report_storage_cli_metrics suppresses histogram observation on failure. + expect { client_with_metrics.send(:run_cli, 'put', 'src', 'dest', blob_size: 2048) }.to raise_error(RuntimeError) + expect(metrics_updater).to have_received(:report_storage_cli_metrics).with( + operation: 'put', exit_code: 1, duration_seconds: a_kind_of(Float), blob_size: 2048 + ) + end + + it 'does not call metrics_updater when nil' do + status = instance_double(Process::Status, success?: true, exitstatus: 0) + allow(Open3).to receive(:capture3).and_return(['', '', status]) + allow(client).to receive(:additional_flags).and_return([]) + + expect { client.send(:run_cli, 'get', 'some-key') }.not_to raise_error + end + end + end + + describe '#cp_to_blobstore' do + let(:logger_double) { double(info: nil, error: nil, debug: nil, warn: nil) } + + before do + allow(Steno).to receive(:logger).and_return(logger_double) + allow(client).to receive(:additional_flags).and_return([]) + end + + it 'logs cp-finish on success' do + source = Tempfile.new('src') + source.write('x' * 1025) + source.flush + + status = instance_double(Process::Status, success?: true, exitstatus: 0) + allow(Open3).to receive(:capture3).and_return(['', '', status]) + + client.cp_to_blobstore(source.path, 'some-key') + + expect(logger_double).to have_received(:info).with('cp-finish', a_hash_including(destination_key: 'some-key')) + ensure + source.close! + end + + it 'logs cp-error when run_cli raises' do + source = Tempfile.new('src') + source.write('x' * 1025) + source.flush + + allow(Open3).to receive(:capture3).and_raise(StandardError.new('blobstore unavailable')) + + expect { client.cp_to_blobstore(source.path, 'some-key') }.to raise_error(BlobstoreError) + expect(logger_double).to have_received(:info).with('cp-error', a_hash_including(destination_key: 'some-key')) + ensure + source.close! + end + + it 'logs cp-skip when file is outside size limits' do + source = Tempfile.new('src') + source.write('x') + source.flush + + small_client = StorageCliClient.new( + directory_key: directory_key, + resource_type: resource_type, + root_dir: 'bommel', + min_size: 1024 + ) + allow(small_client).to receive(:additional_flags).and_return([]) + + small_client.cp_to_blobstore(source.path, 'some-key') + + expect(logger_double).to have_received(:info).with('cp-skip', a_hash_including(destination_key: 'some-key')) + ensure + source.close! + end + + it 'emits exit_code=-4 metric when the file is skipped by size limits' do + source = Tempfile.new('src') + source.write('x') + source.flush + + start_time = Time.utc(2026, 10, 16, 12, 0, 0) + + metrics_updater = double('metrics_updater') + allow(metrics_updater).to receive(:report_storage_cli_metrics) + allow(Time).to receive(:now).and_return(start_time, start_time + 0.125, start_time + 0.250) + + small_client = StorageCliClient.new( + directory_key: directory_key, + resource_type: resource_type, + root_dir: 'bommel', + min_size: 1024, + metrics_updater: metrics_updater + ) + allow(small_client).to receive(:additional_flags).and_return([]) + + small_client.cp_to_blobstore(source.path, 'some-key') + + expect(metrics_updater).to have_received(:report_storage_cli_metrics).with( + operation: 'put', exit_code: -4, duration_seconds: 0.125, blob_size: nil + ) + expect(logger_double).to have_received(:info).with('cp-skip', a_hash_including(destination_key: 'some-key', duration_seconds: 0.25)) + ensure + source.close! + end + + it 'emits exit_code=-3 metric and logs cp-error when File.open fails (missing source)' do + metrics_updater = double('metrics_updater') + allow(metrics_updater).to receive(:report_storage_cli_metrics) + + client_with_metrics = StorageCliClient.new( + directory_key: directory_key, + resource_type: resource_type, + root_dir: 'bommel', + metrics_updater: metrics_updater + ) + allow(client_with_metrics).to receive(:additional_flags).and_return([]) + allow(File).to receive(:open).and_raise(Errno::ENOENT.new('no such file')) + + expect { client_with_metrics.cp_to_blobstore('/nonexistent/path', 'some-key') }.to raise_error(Errno::ENOENT) + expect(metrics_updater).to have_received(:report_storage_cli_metrics).with( + operation: 'put', exit_code: -3, duration_seconds: anything, blob_size: nil + ) + expect(logger_double).to have_received(:info).with('cp-error', a_hash_including(destination_key: 'some-key')) + end + + it 'lets Interrupt propagate when File.open is interrupted' do + source = Tempfile.new('src') + source.write('x' * 1025) + source.flush + + metrics_updater = double('metrics_updater') + allow(metrics_updater).to receive(:report_storage_cli_metrics) + + client_with_metrics = StorageCliClient.new( + directory_key: directory_key, + resource_type: resource_type, + root_dir: 'bommel', + metrics_updater: metrics_updater + ) + allow(client_with_metrics).to receive(:additional_flags).and_return([]) + + allow(File).to receive(:open).and_raise(Interrupt) + + expect { client_with_metrics.cp_to_blobstore(source.path, 'some-key') }.to raise_error(Interrupt) + expect(metrics_updater).to have_received(:report_storage_cli_metrics).with( + operation: 'put', exit_code: -5, duration_seconds: anything, blob_size: nil + ) + ensure + source.close! + end + + it 'does not emit a duplicate signal metric when run_cli raises Interrupt' do + source = Tempfile.new('src') + source.write('x' * 1025) + source.flush + + metrics_updater = double('metrics_updater') + allow(metrics_updater).to receive(:report_storage_cli_metrics) + + client_with_metrics = StorageCliClient.new( + directory_key: directory_key, + resource_type: resource_type, + root_dir: 'bommel', + metrics_updater: metrics_updater + ) + allow(client_with_metrics).to receive(:additional_flags).and_return([]) + allow(client_with_metrics).to receive(:run_cli).and_raise(Interrupt) + + expect { client_with_metrics.cp_to_blobstore(source.path, 'some-key') }.to raise_error(Interrupt) + expect(metrics_updater).not_to have_received(:report_storage_cli_metrics).with( + operation: 'put', exit_code: -6, duration_seconds: anything, blob_size: nil + ) + ensure + source.close! + end + + it 'emits exit_code=-7 when a fatal non-signal exception escapes run_cli' do + source = Tempfile.new('src') + source.write('x' * 1025) + source.flush + + metrics_updater = double('metrics_updater') + allow(metrics_updater).to receive(:report_storage_cli_metrics) + + client_with_metrics = StorageCliClient.new( + directory_key: directory_key, + resource_type: resource_type, + root_dir: 'bommel', + metrics_updater: metrics_updater + ) + allow(client_with_metrics).to receive(:additional_flags).and_return([]) + allow(client_with_metrics).to receive(:run_cli).and_raise(NoMemoryError) + + expect { client_with_metrics.cp_to_blobstore(source.path, 'some-key') }.to raise_error(NoMemoryError) + expect(metrics_updater).to have_received(:report_storage_cli_metrics).with( + operation: 'put', exit_code: -7, duration_seconds: anything, blob_size: nil + ) + ensure + source.close! + end end end end diff --git a/spec/unit/lib/cloud_controller/metrics/prometheus_updater_spec.rb b/spec/unit/lib/cloud_controller/metrics/prometheus_updater_spec.rb index b69d38929ac..bb4260b9399 100644 --- a/spec/unit/lib/cloud_controller/metrics/prometheus_updater_spec.rb +++ b/spec/unit/lib/cloud_controller/metrics/prometheus_updater_spec.rb @@ -23,18 +23,31 @@ module VCAP::CloudController::Metrics end it_behaves_like 'metric registration based on execution context', VCAP::CloudController::ExecutionContext::API_PUMA_MAIN, - [PrometheusUpdater::METRICS, PrometheusUpdater::PUMA_METRICS, PrometheusUpdater::DB_CONNECTION_POOL_METRICS, PrometheusUpdater::DELAYED_JOB_METRICS, PrometheusUpdater::VITAL_METRICS] + [PrometheusUpdater::METRICS, PrometheusUpdater::PUMA_METRICS, PrometheusUpdater::DB_CONNECTION_POOL_METRICS, + PrometheusUpdater::DELAYED_JOB_METRICS, PrometheusUpdater::STORAGE_CLI_METRICS, PrometheusUpdater::VITAL_METRICS] it_behaves_like 'metric registration based on execution context', VCAP::CloudController::ExecutionContext::API_PUMA_WORKER, - [PrometheusUpdater::METRICS, PrometheusUpdater::PUMA_METRICS, PrometheusUpdater::DB_CONNECTION_POOL_METRICS, PrometheusUpdater::DELAYED_JOB_METRICS, PrometheusUpdater::VITAL_METRICS] + [PrometheusUpdater::METRICS, PrometheusUpdater::PUMA_METRICS, PrometheusUpdater::DB_CONNECTION_POOL_METRICS, + PrometheusUpdater::DELAYED_JOB_METRICS, PrometheusUpdater::STORAGE_CLI_METRICS, PrometheusUpdater::VITAL_METRICS] it_behaves_like 'metric registration based on execution context', VCAP::CloudController::ExecutionContext::CC_WORKER, - [PrometheusUpdater::DB_CONNECTION_POOL_METRICS, PrometheusUpdater::DELAYED_JOB_METRICS, PrometheusUpdater::VITAL_METRICS] + [PrometheusUpdater::DB_CONNECTION_POOL_METRICS, PrometheusUpdater::DELAYED_JOB_METRICS, PrometheusUpdater::STORAGE_CLI_METRICS, PrometheusUpdater::VITAL_METRICS] it_behaves_like 'metric registration based on execution context', VCAP::CloudController::ExecutionContext::CLOCK, [PrometheusUpdater::DB_CONNECTION_POOL_METRICS, PrometheusUpdater::VITAL_METRICS] it_behaves_like 'metric registration based on execution context', VCAP::CloudController::ExecutionContext::DEPLOYMENT_UPDATER, [PrometheusUpdater::DB_CONNECTION_POOL_METRICS, PrometheusUpdater::VITAL_METRICS] - it 'raises error when execution context is nil' do + it 'skips metric registration when execution context is nil and PROCESS_TYPE is unset' do allow(VCAP::CloudController::ExecutionContext).to receive(:from_process_type_env).and_return(nil) - expect { updater }.to raise_error('Could not register Prometheus metrics: Unexpected execution context: nil') + allow(ENV).to receive(:fetch).with('PROCESS_TYPE', nil).and_return(nil) + + expect { updater }.not_to raise_error + expect(prom_client.metrics).to be_empty + end + + it 'skips metric registration when execution context is nil even if PROCESS_TYPE is set' do + allow(VCAP::CloudController::ExecutionContext).to receive(:from_process_type_env).and_return(nil) + allow(ENV).to receive(:fetch).with('PROCESS_TYPE', nil).and_return('mystery') + + expect { updater }.not_to raise_error + expect(prom_client.metrics).to be_empty end context 'when execution context is set' do @@ -275,5 +288,68 @@ module VCAP::CloudController::Metrics expect(metric.get).to eq({ '5' => 0.0, '10' => 0.0, '30' => 0.0, '60' => 0.0, '300' => 0.0, '600' => 0.0, '890' => 0.0, 'sum' => 900.0, '+Inf' => 1.0 }) end end + + describe '#report_storage_cli_metrics' do + before do + allow(VCAP::CloudController::ExecutionContext).to receive(:from_process_type_env).and_return( + VCAP::CloudController::ExecutionContext::CC_WORKER + ) + end + + it 'increments the operations counter with operation and exit_code labels' do + updater.report_storage_cli_metrics(operation: 'get', exit_code: 0, duration_seconds: 0.1) + + metric = prom_client.get(:cc_storage_cli_operations_total) + expect(metric.get(labels: { operation: 'get', exit_code: '0' })).to eq(1.0) + end + + it 'observes duration with exit_code label' do + updater.report_storage_cli_metrics(operation: 'put', exit_code: 0, duration_seconds: 1.5) + + metric = prom_client.get(:cc_storage_cli_duration_seconds) + expect(metric.get(labels: { operation: 'put', exit_code: '0' })['sum']).to eq(1.5) + end + + it 'records blob_size when exit_code is 0' do + updater.report_storage_cli_metrics(operation: 'put', exit_code: 0, duration_seconds: 0.2, blob_size: 1_048_576) + + metric = prom_client.get(:cc_storage_cli_blob_size_bytes) + expect(metric.get(labels: { operation: 'put' })['sum']).to eq(1_048_576.0) + end + + it 'does not record blob_size when exit_code is non-zero' do + updater.report_storage_cli_metrics(operation: 'put', exit_code: 1, duration_seconds: 0.2, blob_size: 1_048_576) + + metric = prom_client.get(:cc_storage_cli_blob_size_bytes) + expect(metric.get(labels: { operation: 'put' })['sum']).to eq(0.0) + end + + it 'does not record blob_size when blob_size is nil' do + updater.report_storage_cli_metrics(operation: 'get', exit_code: 0, duration_seconds: 0.1, blob_size: nil) + + metric = prom_client.get(:cc_storage_cli_blob_size_bytes) + expect(metric.get(labels: { operation: 'get' })['sum']).to eq(0.0) + end + + it 'still updates registered storage-cli metrics when one metric is missing' do + allow(prom_client).to receive(:exist?).and_call_original + allow(prom_client).to receive(:exist?).with(:cc_storage_cli_blob_size_bytes).and_return(false) + + updater.report_storage_cli_metrics(operation: 'put', exit_code: 0, duration_seconds: 0.2, blob_size: 1_048_576) + + operations_metric = prom_client.get(:cc_storage_cli_operations_total) + duration_metric = prom_client.get(:cc_storage_cli_duration_seconds) + + expect(operations_metric.get(labels: { operation: 'put', exit_code: '0' })).to eq(1.0) + expect(duration_metric.get(labels: { operation: 'put', exit_code: '0' })['sum']).to eq(0.2) + end + + it 'is a no-op when storage cli metrics are not registered' do + allow(VCAP::CloudController::ExecutionContext).to receive(:from_process_type_env).and_return( + VCAP::CloudController::ExecutionContext::CLOCK + ) + expect { updater.report_storage_cli_metrics(operation: 'get', exit_code: 0, duration_seconds: 0.1) }.not_to raise_error + end + end end end diff --git a/spec/unit/lib/cloud_controller/packager/local_bits_packer_spec.rb b/spec/unit/lib/cloud_controller/packager/local_bits_packer_spec.rb index b8c421a83b8..d0a1be7a9f4 100644 --- a/spec/unit/lib/cloud_controller/packager/local_bits_packer_spec.rb +++ b/spec/unit/lib/cloud_controller/packager/local_bits_packer_spec.rb @@ -368,6 +368,28 @@ module CloudController::Packager end end end + + it 'logs timing for each phase' do + logger = instance_double(Steno::Logger) + allow(Steno).to receive(:logger).and_return(logger) + allow(logger).to receive(:info) + allow(logger).to receive(:debug) + allow(VCAP::CloudController::FeatureFlag).to receive(:disabled?).with(:resource_matching).and_return(false) + global_app_bits_cache.instance_variable_set(:@logger, logger) + package_blobstore.instance_variable_set(:@logger, logger) + + packer.send_package_to_blobstore(blobstore_key, uploaded_files_path, cached_files_fingerprints) + + expect(logger).to have_received(:info).with('packer.unzip', hash_including(:duration_seconds)) + expect(logger).to have_received(:info).with('blobstore.cp_r.digest', hash_including(:duration_seconds, :files_scanned)) + expect(logger).to have_received(:info).with('blobstore.cp_r.exists', hash_including(:duration_seconds, :files_checked)) + expect(logger).to have_received(:info).with('blobstore.cp_r.upload', hash_including(:duration_seconds, :files_uploaded)) + expect(logger).to have_received(:info).with('packer.resource-cache-upload', hash_including(:duration_seconds)) + expect(logger).to have_received(:info).with('packer.resource-cache-download', hash_including(:duration_seconds, :files_downloaded, :files_attempted)) + expect(logger).to have_received(:info).with('packer.repackage', hash_including(:duration_seconds)) + expect(logger).to have_received(:info).with('packer.final-upload', hash_including(:duration_seconds, :blobstore_key)) + expect(logger).to have_received(:info).with('packer.pack', hash_including(:duration_seconds, :blobstore_key)) + end end end end