diff --git a/common/lib/dependabot/shared_helpers.rb b/common/lib/dependabot/shared_helpers.rb index 743c6b3f2ef..6d928084fbb 100644 --- a/common/lib/dependabot/shared_helpers.rb +++ b/common/lib/dependabot/shared_helpers.rb @@ -64,7 +64,7 @@ class HelperSubprocessFailed < Dependabot::DependabotError def initialize(message:, error_context:, error_class: nil, trace: nil) super(message) - @error_class = error_class || "" + @error_class = error_class || "HelperSubprocessFailed" @error_context = error_context @fingerprint = error_context[:fingerprint] || error_context[:command] @trace = trace @@ -82,6 +82,7 @@ def self.escape_command(command) end # rubocop:disable Metrics/MethodLength + # rubocop:disable Metrics/AbcSize def self.run_helper_subprocess(command:, function:, args:, env: nil, stderr_to_stdout: false, allow_unsafe_shell_command: false) @@ -130,19 +131,20 @@ def self.run_helper_subprocess(command:, function:, args:, env: nil, return response["result"] if process.success? raise HelperSubprocessFailed.new( - message: response["error"], + message: "#{response['error']} failed with command (#{error_context[:command]})", error_class: response["error_class"], error_context: error_context, trace: response["trace"] ) rescue JSON::ParserError raise HelperSubprocessFailed.new( - message: stdout || "No output from command", + message: stdout.empty? ? "No output from command (#{error_context[:command]})" : stdout, error_class: "JSON::ParserError", error_context: error_context ) end # rubocop:enable Metrics/MethodLength + # rubocop:enable Metrics/AbcSize def self.check_out_of_memory_error(stderr, error_context) return unless stderr&.include?("JavaScript heap out of memory") diff --git a/common/spec/dependabot/shared_helpers_spec.rb b/common/spec/dependabot/shared_helpers_spec.rb index 62c9738427f..0c522cd6eb8 100644 --- a/common/spec/dependabot/shared_helpers_spec.rb +++ b/common/spec/dependabot/shared_helpers_spec.rb @@ -187,7 +187,7 @@ def existing_tmp_folders it "raises a HelperSubprocessFailed error" do expect { run_subprocess } .to raise_error(Dependabot::SharedHelpers::HelperSubprocessFailed) do |error| - expect(error.message).to eq("Something went wrong: https://www.example.com") + expect(error.message).to include("Something went wrong: https://www.example.com") end end end diff --git a/composer/spec/dependabot/composer/update_checker/version_resolver_spec.rb b/composer/spec/dependabot/composer/update_checker/version_resolver_spec.rb index 2c83d5b3e83..0c4d8d35404 100644 --- a/composer/spec/dependabot/composer/update_checker/version_resolver_spec.rb +++ b/composer/spec/dependabot/composer/update_checker/version_resolver_spec.rb @@ -161,7 +161,7 @@ it "raises a Dependabot::PrivateSourceTimedOut error" do expect { resolver.latest_resolvable_version } .to raise_error(Dependabot::DependencyFileNotResolvable) do |error| - expect(error.message).to start_with( + expect(error.message).to include( 'The "https://github.com/dependabot/composer-not-found/packages.json"' \ " file could not be downloaded" ) diff --git a/python/spec/dependabot/python/file_parser/setup_file_parser_spec.rb b/python/spec/dependabot/python/file_parser/setup_file_parser_spec.rb index 2d69c380ef1..e7e60c97e8b 100644 --- a/python/spec/dependabot/python/file_parser/setup_file_parser_spec.rb +++ b/python/spec/dependabot/python/file_parser/setup_file_parser_spec.rb @@ -257,7 +257,7 @@ expect(error.class) .to eq(Dependabot::DependencyFileNotEvaluatable) expect(error.message) - .to eq("InstallationError(\"Invalid requirement: 'psycopg2==2.6.1raven == 5.32.0'\")") + .to include("InstallationError(\"Invalid requirement: 'psycopg2==2.6.1raven == 5.32.0'\")") end end end diff --git a/updater/lib/dependabot/api_client.rb b/updater/lib/dependabot/api_client.rb index 298ca20f5fe..878a23c2f1e 100644 --- a/updater/lib/dependabot/api_client.rb +++ b/updater/lib/dependabot/api_client.rb @@ -89,6 +89,24 @@ def record_update_job_error(error_type:, error_details:) sleep(rand(3.0..10.0)) && retry end + def record_update_job_unknown_error(error_type: "unknown_error", error_details:) + api_url = "#{base_url}/update_jobs/#{job_id}/record_update_job_unknown_error" + body = { + data: { + "error-type": error_type, + "error-details": error_details + } + } + response = http_client.post(api_url, json: body) + raise ApiError, response.body if response.code >= 400 + rescue HTTP::ConnectionError, OpenSSL::SSL::SSLError + retry_count ||= 0 + retry_count += 1 + raise if retry_count > 3 + + sleep(rand(3.0..10.0)) && retry + end + def mark_job_as_processed(base_commit_sha) api_url = "#{base_url}/update_jobs/#{job_id}/mark_as_processed" body = { data: { "base-commit-sha": base_commit_sha } } diff --git a/updater/lib/dependabot/base_command.rb b/updater/lib/dependabot/base_command.rb index 4c995ab14f5..0392f9c8552 100644 --- a/updater/lib/dependabot/base_command.rb +++ b/updater/lib/dependabot/base_command.rb @@ -64,9 +64,22 @@ def run def handle_exception(err) Dependabot.logger.error(err.message) err.backtrace.each { |line| Dependabot.logger.error(line) } + error_details = { + "error-class" => err.class.to_s, + "error-message" => err.message, + "error-backtrace" => err.backtrace.join("\n"), + "package-manager" => job.package_manager, + "job-id" => job.id, + "job-dependencies" => job.dependencies, + "job-dependency_group" => job.dependency_groups + }.compact service.capture_exception(error: err, job: job) - service.record_update_job_error(error_type: "unknown_error", error_details: { message: err.message }) + service.record_update_job_unknown_error(error_type: "updater_error", error_details: error_details) + service.increment_metric("updater.update_job_unknown_error", tags: { + package_manager: job.package_manager, + class_name: err.class.name + }) end def job_id diff --git a/updater/lib/dependabot/file_fetcher_command.rb b/updater/lib/dependabot/file_fetcher_command.rb index a048d6ac370..a5efd6769a5 100644 --- a/updater/lib/dependabot/file_fetcher_command.rb +++ b/updater/lib/dependabot/file_fetcher_command.rb @@ -161,7 +161,7 @@ def handle_file_fetcher_error(error) # If we get a 500 from GitHub there's very little we can do about it, # and responsibility for fixing it is on them, not us. As a result we # quietly log these as errors - { "error-type": "unknown_error" } + { "error-type": "server_error" } when *Octokit::RATE_LIMITED_ERRORS # If we get a rate-limited error we let dependabot-api handle the # retry by re-enqueing the update job after the reset @@ -174,9 +174,21 @@ def handle_file_fetcher_error(error) else Dependabot.logger.error(error.message) error.backtrace.each { |line| Dependabot.logger.error line } + unknown_error_details = { + "error-class" => error.class.to_s, + "error-message" => error.message, + "error-backtrace" => error.backtrace.join("\n"), + "package-manager" => job.package_manager, + "job-id" => job.id, + "job-dependencies" => job.dependencies, + "job-dependency_group" => job.dependency_groups + }.compact service.capture_exception(error: error, job: job) - { "error-type": "unknown_error" } + { + "error-type": "file_fetcher_error", + "error-detail": unknown_error_details + } end record_error(error_details) if error_details @@ -191,10 +203,17 @@ def rate_limit_error_remaining(error) end def record_error(error_details) - service.record_update_job_error( - error_type: error_details.fetch(:"error-type"), - error_details: error_details[:"error-detail"] - ) + if error_details[:"error-type"] == "file_fetcher_error" + service.record_update_job_unknown_error( + error_type: error_details.fetch(:"error-type"), + error_details: error_details[:"error-detail"] + ) + else + service.record_update_job_error( + error_type: error_details.fetch(:"error-type"), + error_details: error_details[:"error-detail"] + ) + end end # Perform a debug check of connectivity to GitHub/GHES. This also ensures diff --git a/updater/lib/dependabot/service.rb b/updater/lib/dependabot/service.rb index 89768ce2b83..abe2838e360 100644 --- a/updater/lib/dependabot/service.rb +++ b/updater/lib/dependabot/service.rb @@ -49,6 +49,11 @@ def record_update_job_error(error_type:, error_details:, dependency: nil) client.record_update_job_error(error_type: error_type, error_details: error_details) end + def record_update_job_unknown_error(error_type:, error_details:, dependency: nil) + @errors << [error_type.to_s, dependency] + client.record_update_job_unknown_error(error_type: error_type, error_details: error_details) + end + def update_dependency_list(dependency_snapshot:) dependency_payload = dependency_snapshot.dependencies.map do |dep| { diff --git a/updater/lib/dependabot/update_files_command.rb b/updater/lib/dependabot/update_files_command.rb index d2ae4431542..a25ef1ae863 100644 --- a/updater/lib/dependabot/update_files_command.rb +++ b/updater/lib/dependabot/update_files_command.rb @@ -59,6 +59,7 @@ def base_commit_sha end # rubocop:disable Metrics/MethodLength + # rubocop:disable Metrics/AbcSize def handle_parser_error(error) # This happens if the repo gets removed after a job gets kicked off. # The service will handle the removal without any prompt from the updater, @@ -121,7 +122,7 @@ def handle_parser_error(error) # If we get a 500 from GitHub there's very little we can do about it, # and responsibility for fixing it is on them, not us. As a result we # quietly log these as errors - { "error-type": "unknown_error" } + { "error-type": "server_error" } else # Check if the error is a known "run halting" state we should handle if (error_type = Updater::ErrorHandler::RUN_HALTING_ERRORS[error.class]) @@ -131,19 +132,39 @@ def handle_parser_error(error) # tracker know about it Dependabot.logger.error error.message error.backtrace.each { |line| Dependabot.logger.error line } + unknown_error_details = { + "error-class" => error.class.to_s, + "error-message" => error.message, + "error-backtrace" => error.backtrace.join("\n"), + "package-manager" => job.package_manager, + "job-id" => job.id, + "job-dependencies" => job.dependencies, + "job-dependency_group" => job.dependency_groups + }.compact service.capture_exception(error: error, job: job) - # Set an unknown error type to be added to the job - { "error-type": "unknown_error" } + # Set an unknown error type as update_files_error to be added to the job + { + "error-type": "update_files_error", + "error-detail": unknown_error_details + } end end - service.record_update_job_error( - error_type: error_details.fetch(:"error-type"), - error_details: error_details[:"error-detail"] - ) + if error_details.fetch(:"error-type") == "update_files_error" + service.record_update_job_unknown_error( + error_type: "update_files_error", + error_details: error_details[:"error-detail"] + ) + else + service.record_update_job_error( + error_type: error_details.fetch(:"error-type"), + error_details: error_details[:"error-detail"] + ) + end end # rubocop:enable Metrics/MethodLength + # rubocop:enable Metrics/AbcSize end end diff --git a/updater/lib/dependabot/updater/error_handler.rb b/updater/lib/dependabot/updater/error_handler.rb index c312cc3a589..39583754c7e 100644 --- a/updater/lib/dependabot/updater/error_handler.rb +++ b/updater/lib/dependabot/updater/error_handler.rb @@ -44,11 +44,15 @@ def handle_dependency_error(error:, dependency:, dependency_group: nil) raise error if RUN_HALTING_ERRORS.keys.any? { |err| error.is_a?(err) } error_details = error_details_for(error, dependency: dependency, dependency_group: dependency_group) - service.record_update_job_error( - error_type: error_details.fetch(:"error-type"), - error_details: error_details[:"error-detail"], - dependency: dependency - ) + if error_details.fetch(:"error-type") == "unknown_error" + log_unknown_error_with_backtrace(error, dependency) + else + service.record_update_job_error( + error_type: error_details.fetch(:"error-type"), + error_details: error_details[:"error-detail"], + dependency: dependency + ) + end log_dependency_error( dependency: dependency, @@ -62,7 +66,6 @@ def handle_dependency_error(error:, dependency:, dependency_group: nil) def log_dependency_error(dependency:, error:, error_type:, error_detail: nil) if error_type == "unknown_error" Dependabot.logger.error "Error processing #{dependency.name} (#{error.class.name})" - log_unknown_error_with_backtrace(error) else Dependabot.logger.info( "Handled error whilst updating #{dependency.name}: #{error_type} #{error_detail}" @@ -78,10 +81,15 @@ def handle_job_error(error:, dependency_group: nil) raise error if RUN_HALTING_ERRORS.keys.any? { |err| error.is_a?(err) } error_details = error_details_for(error, dependency_group: dependency_group) - service.record_update_job_error( - error_type: error_details.fetch(:"error-type"), - error_details: error_details[:"error-detail"] - ) + if error_details.fetch(:"error-type") == "unknown_error" + log_unknown_error_with_backtrace(error, dependency_group) + else + service.record_update_job_error( + error_type: error_details.fetch(:"error-type"), + error_details: error_details[:"error-detail"] + ) + end + log_job_error( error: error, error_type: error_details.fetch(:"error-type"), @@ -93,7 +101,6 @@ def handle_job_error(error:, dependency_group: nil) def log_job_error(error:, error_type:, error_detail: nil) if error_type == "unknown_error" Dependabot.logger.error "Error processing job (#{error.class.name})" - log_unknown_error_with_backtrace(error) else Dependabot.logger.info( "Handled error whilst processing job: #{error_type} #{error_detail}" @@ -202,9 +209,26 @@ def error_details_for(error, dependency: nil, dependency_group: nil) # rubocop:d end end - def log_unknown_error_with_backtrace(error) + def log_unknown_error_with_backtrace(error, dependency = nil, _dependency_group = nil) Dependabot.logger.error error.message error.backtrace.each { |line| Dependabot.logger.error line } + + error_details = { + "error-class" => error.class.to_s, + "error-message" => error.message, + "error-backtrace" => error.backtrace.join("\n"), + "package-manager" => job.package_manager, + "job-id" => job.id, + "job-dependencies" => job.dependencies, + "job-dependency_group" => job.dependency_groups + }.compact + + service.increment_metric("updater.update_job_unknown_error", tags: { + package_manager: job.package_manager, + class_name: error.class.name + }) + service.record_update_job_unknown_error(error_type: "unknown_error", error_details: error_details, + dependency: dependency) end end end diff --git a/updater/spec/dependabot/api_client_spec.rb b/updater/spec/dependabot/api_client_spec.rb index 519524e5a36..9182071a078 100644 --- a/updater/spec/dependabot/api_client_spec.rb +++ b/updater/spec/dependabot/api_client_spec.rb @@ -349,6 +349,24 @@ end end + describe "record_update_job_unknown_error" do + let(:url) { "http://example.com/update_jobs/1/record_update_job_unknown_error" } + let(:error_type) { "server_error" } + let(:error_detail) { { "message" => "My message" } } + before { stub_request(:post, url).to_return(status: 204) } + + it "hits the correct endpoint" do + client.record_update_job_unknown_error( + error_type: error_type, + error_details: error_detail + ) + + expect(WebMock) + .to have_requested(:post, url) + .with(headers: { "Authorization" => "token" }) + end + end + describe "mark_job_as_processed" do let(:url) { "http://example.com/update_jobs/1/mark_as_processed" } let(:base_commit) { "sha" } diff --git a/updater/spec/dependabot/file_fetcher_command_spec.rb b/updater/spec/dependabot/file_fetcher_command_spec.rb index 4ccd970c549..c2bb8938cc5 100644 --- a/updater/spec/dependabot/file_fetcher_command_spec.rb +++ b/updater/spec/dependabot/file_fetcher_command_spec.rb @@ -98,6 +98,31 @@ end end + context "when the fetcher raises a file fetcher error", vcr: true do + before do + allow_any_instance_of(Dependabot::Bundler::FileFetcher) + .to receive(:commit) + .and_raise(StandardError, "my_branch") + end + + it "tells the backend about the error (and doesn't re-raise it)" do + expect(api_client).to receive(:record_update_job_unknown_error).with( + error_type: "file_fetcher_error", + error_details: { + "error-backtrace" => an_instance_of(String), + "error-message" => "my_branch", + "error-class" => "StandardError", + "package-manager" => "bundler", + "job-id" => "123123", + "job-dependency_group" => [] + } + ) + expect(api_client).to receive(:mark_job_as_processed) + + expect { perform_job }.to output(/Error during file fetching; aborting/).to_stdout_from_any_process + end + end + context "when the fetcher raises a rate limited error", vcr: true do let(:reset_at) { Time.now + 30 } diff --git a/updater/spec/dependabot/integration_spec.rb b/updater/spec/dependabot/integration_spec.rb index e25bbfd2803..8a323d28e26 100644 --- a/updater/spec/dependabot/integration_spec.rb +++ b/updater/spec/dependabot/integration_spec.rb @@ -52,6 +52,7 @@ mark_job_as_processed: nil, update_dependency_list: nil, record_update_job_error: nil, + record_update_job_unknown_error: nil, record_ecosystem_versions: nil, increment_metric: nil) end @@ -208,8 +209,18 @@ end it "notifies Dependabot API of the problem" do - expect(api_client).to receive(:record_update_job_error) - .with({ error_type: "unknown_error", error_details: nil }) + expect(api_client).to receive(:record_update_job_unknown_error) + .with( + { error_type: "unknown_error", + error_details: { + "error-backtrace" => an_instance_of(String), + "error-message" => "oh no!", + "error-class" => "StandardError", + "package-manager" => "bundler", + "job-id" => 1, + "job-dependency_group" => [] + } } + ) expect { run_job }.to output(/oh no!/).to_stdout_from_any_process end diff --git a/updater/spec/dependabot/service_spec.rb b/updater/spec/dependabot/service_spec.rb index cd799452a4e..953e09de0d0 100644 --- a/updater/spec/dependabot/service_spec.rb +++ b/updater/spec/dependabot/service_spec.rb @@ -16,7 +16,8 @@ create_pull_request: nil, update_pull_request: nil, close_pull_request: nil, - record_update_job_error: nil + record_update_job_error: nil, + record_update_job_unknown_error: nil }) end subject(:service) { described_class.new(client: mock_client) } diff --git a/updater/spec/dependabot/update_files_command_spec.rb b/updater/spec/dependabot/update_files_command_spec.rb index db23de03e5d..84654e5f2f2 100644 --- a/updater/spec/dependabot/update_files_command_spec.rb +++ b/updater/spec/dependabot/update_files_command_spec.rb @@ -13,6 +13,7 @@ capture_exception: nil, mark_job_as_processed: nil, record_update_job_error: nil, + record_update_job_unknown_error: nil, update_dependency_list: nil, increment_metric: nil) end @@ -112,16 +113,23 @@ end end - context "with an unknown error" do + context "with an update files error" do let(:error) { StandardError.new("hell") } it_behaves_like "a fast-failed job" it "it captures the exception and records the a job error" do expect(service).to receive(:capture_exception) - expect(service).to receive(:record_update_job_error).with( - error_type: "unknown_error", - error_details: nil + expect(service).to receive(:record_update_job_unknown_error).with( + error_type: "update_files_error", + error_details: { + "error-backtrace" => an_instance_of(String), + "error-message" => "hell", + "error-class" => "StandardError", + "package-manager" => "bundler", + "job-id" => "123123", + "job-dependency_group" => [] + } ) perform_job @@ -293,7 +301,7 @@ it "only records a job error" do expect(service).not_to receive(:capture_exception) expect(service).to receive(:record_update_job_error).with( - error_type: "unknown_error", + error_type: "server_error", error_details: nil ) diff --git a/updater/spec/dependabot/updater/error_handler_spec.rb b/updater/spec/dependabot/updater/error_handler_spec.rb index 13d7bcd6323..53e89057528 100644 --- a/updater/spec/dependabot/updater/error_handler_spec.rb +++ b/updater/spec/dependabot/updater/error_handler_spec.rb @@ -18,11 +18,13 @@ end let(:mock_service) do - instance_double(Dependabot::Service) + instance_double(Dependabot::Service).tap do |service| + allow(service).to receive(:increment_metric) + end end let(:mock_job) do - instance_double(Dependabot::Job) + instance_double(Dependabot::Job, package_manager: "bundler", id: "123123", dependencies: [], dependency_groups: []) end describe "#handle_dependency_error" do @@ -62,9 +64,17 @@ end it "records the error with the service, logs the backtrace and captures the exception" do - expect(mock_service).to receive(:record_update_job_error).with( + expect(mock_service).to receive(:record_update_job_unknown_error).with( error_type: "unknown_error", - error_details: nil, + error_details: { + "error-backtrace" => "bees.rb:5:in `buzz`", + "error-message" => "There are bees everywhere", + "error-class" => "StandardError", + "package-manager" => "bundler", + "job-id" => "123123", + "job-dependencies" => [], + "job-dependency_group" => [] + }, dependency: dependency ) @@ -112,9 +122,17 @@ end it "records the error with the service and logs the backtrace" do - expect(mock_service).to receive(:record_update_job_error).with( + expect(mock_service).to receive(:record_update_job_unknown_error).with( error_type: "unknown_error", - error_details: nil, + error_details: { + "error-backtrace" => "****** ERROR 8335 -- 101", + "error-message" => "the kernal is full of bees", + "error-class" => "Dependabot::SharedHelpers::HelperSubprocessFailed", + "package-manager" => "bundler", + "job-id" => "123123", + "job-dependencies" => [], + "job-dependency_group" => [] + }, dependency: dependency ) @@ -135,7 +153,7 @@ it "sanitizes the error and captures it" do allow(Dependabot.logger).to receive(:error) - allow(mock_service).to receive(:record_update_job_error) + allow(mock_service).to receive(:record_update_job_unknown_error) expect(mock_service).to receive(:capture_exception).with( error: an_instance_of(Dependabot::Updater::SubprocessFailed), job: mock_job ) do |args| @@ -185,9 +203,18 @@ end it "records the error with the service, logs the backtrace and captures the exception" do - expect(mock_service).to receive(:record_update_job_error).with( + expect(mock_service).to receive(:record_update_job_unknown_error).with( error_type: "unknown_error", - error_details: nil + error_details: { + "error-backtrace" => "bees.rb:5:in `buzz`", + "error-message" => "There are bees everywhere", + "error-class" => "StandardError", + "package-manager" => "bundler", + "job-id" => "123123", + "job-dependencies" => [], + "job-dependency_group" => [] + }, + dependency: nil ) expect(mock_service).to receive(:capture_exception).with( diff --git a/updater/spec/dependabot/updater_spec.rb b/updater/spec/dependabot/updater_spec.rb index f1dd17976dc..8bb768f0caa 100644 --- a/updater/spec/dependabot/updater_spec.rb +++ b/updater/spec/dependabot/updater_spec.rb @@ -1605,10 +1605,17 @@ def expect_update_checker_with_ignored_versions(versions, dependency_matcher: an updater = build_updater(service: service, job: job) expect(service) - .to receive(:record_update_job_error) + .to receive(:record_update_job_unknown_error) .with( error_type: "unknown_error", - error_details: nil, + error_details: { + "error-backtrace" => an_instance_of(String), + "error-message" => "hell", + "error-class" => "StandardError", + "package-manager" => "bundler", + "job-id" => 1, + "job-dependency_group" => [] + }, dependency: an_instance_of(Dependabot::Dependency) ) @@ -1916,10 +1923,17 @@ def expect_update_checker_with_ignored_versions(versions, dependency_matcher: an updater = build_updater(service: service, job: job) expect(service) - .to receive(:record_update_job_error) + .to receive(:record_update_job_unknown_error) .with( error_type: "unknown_error", - error_details: nil, + error_details: { + "error-backtrace" => an_instance_of(String), + "error-message" => "Potentially sensitive log content goes here", + "error-class" => "Dependabot::SharedHelpers::HelperSubprocessFailed", + "package-manager" => "bundler", + "job-id" => 1, + "job-dependency_group" => [] + }, dependency: an_instance_of(Dependabot::Dependency) ) updater.run @@ -2346,6 +2360,7 @@ def build_service close_pull_request: nil, mark_job_as_processed: nil, record_update_job_error: nil, + record_update_job_unknown_error: nil, increment_metric: nil ) @@ -2353,6 +2368,7 @@ def build_service client: api_client ) allow(service).to receive(:record_update_job_error) + allow(service).to receive(:record_update_job_unknown_error) service end