[npm] Add additional logging to VulnerabilityAuditor

npm_and_yarn/lib/dependabot/npm_and_yarn/update_checker/vulnerability_auditor.rb

@@ -44,6 +44,8 @@ def initialize(dependency_files:, credentials:, allow_removal: false)
         #     dependency on the dependency
         #   * :explanation [String] an explanation for why the project failed the vulnerability auditor run
         def audit(dependency:, security_advisories:)
+          Dependabot.logger.info("VulnerabilityAuditor: starting audit")
+
           fix_unavailable = {
             "dependency_name" => dependency.name,
             "fix_available" => false,
@@ -62,7 +64,10 @@ def audit(dependency:, security_advisories:)
             # `npm-shrinkwrap.js`, if present, takes precedence over `package-lock.js`.
             # Both files use the same format. See https://bit.ly/3lDIAJV for more.
             lockfile = (dependency_files_builder.shrinkwraps + dependency_files_builder.package_locks).first
-            return fix_unavailable unless lockfile
+            unless lockfile
+              Dependabot.logger.info("VulnerabilityAuditor: missing lockfile")
+              return fix_unavailable
+            end
 
             vuln_versions = security_advisories.map do |a|
               {
@@ -78,11 +83,13 @@ def audit(dependency:, security_advisories:)
             )
 
             validation_result = validate_audit_result(audit_result, security_advisories)
-            unless viable_audit_result?(validation_result)
+            if validation_result != :viable
+              Dependabot.logger.info("VulnerabilityAuditor: audit result not viable: #{validation_result}")
               fix_unavailable["explanation"] = explain_fix_unavailable(validation_result, dependency)
               return fix_unavailable
             end
 
+            Dependabot.logger.info("VulnerabilityAuditor: audit result viable")
             audit_result
           end
         rescue SharedHelpers::HelperSubprocessFailed => e
@@ -105,13 +112,6 @@ def explain_fix_unavailable(validation_result, dependency)
           end
         end
 
-        def viable_audit_result?(validation_result)
-          return true if validation_result == :viable
-
-          Dependabot.logger.info("VulnerabilityAuditor: audit result not viable: #{validation_result}")
-          false
-        end
-
         def validate_audit_result(audit_result, security_advisories)
           return :fix_unavailable unless audit_result["fix_available"]
           return :vulnerable_dependency_removed if !@allow_removal && vulnerable_dependency_removed?(audit_result)

npm_and_yarn/spec/dependabot/npm_and_yarn/update_checker/vulnerability_auditor_spec.rb

@@ -22,6 +22,10 @@
     described_class.new(dependency_files: dependency_files, credentials: credentials, allow_removal: allow_removal)
   end
 
+  before do
+    allow(Dependabot.logger).to receive(:info)
+  end
+
   describe "#audit" do
     let(:dependency) do
       Dependabot::Dependency.new(
@@ -37,10 +41,19 @@
       )
     end
 
+    context "logging" do
+      let(:dependency_files) { project_dependency_files("npm8/simple") }
+
+      it "logs audit start" do
+        expect(Dependabot.logger).to receive(:info).with(/starting audit/i)
+        subject.audit(dependency: dependency, security_advisories: [])
+      end
+    end
+
     context "when a fix is available" do
       let(:dependency_files) { project_dependency_files("npm8/transitive_dependency_locked_by_intermediate") }
 
-      it "returns a hash with the top-level ancestors, target version, and transitive updates to make" do
+      it "logs viable result and returns fix_available => true" do
         security_advisories = [
           Dependabot::SecurityAdvisory.new(
             dependency_name: dependency.name,
@@ -50,6 +63,7 @@
           )
         ]
 
+        expect(Dependabot.logger).to receive(:info).with(/audit result viable/i)
         expect(subject.audit(dependency: dependency, security_advisories: security_advisories)).
           to include(
             "dependency_name" => dependency.name,
@@ -98,7 +112,7 @@
       context "when removal is disabled" do
         let(:allow_removal) { false }
 
-        it "returns fix_available => false" do
+        it "logs vulnerable_dependency_removed and returns fix_available => false" do
           security_advisories = [
             Dependabot::SecurityAdvisory.new(
               dependency_name: dependency.name,
@@ -122,7 +136,7 @@
     context "when a fix doesn't resolve the vulnerability" do
       let(:dependency_files) { project_dependency_files("npm8/locked_transitive_dependency") }
 
-      it "returns fix_available => false" do
+      it "logs dependency_still_vulnerable and returns fix_available => false" do
         security_advisories = [
           Dependabot::SecurityAdvisory.new(
             dependency_name: dependency.name,
@@ -151,7 +165,7 @@
     context "when a fix would downgrade a dependency" do
       let(:dependency_files) { project_dependency_files("npm8/locked_transitive_dependency") }
 
-      it "returns fix_available => false" do
+      it "logs downgrades_dependencies and returns fix_available => false" do
         security_advisories = [
           Dependabot::SecurityAdvisory.new(
             dependency_name: dependency.name,
@@ -189,7 +203,8 @@
     context "in a project with no lockfile" do
       let(:dependency_files) { project_dependency_files("npm6/no_lockfile") }
 
-      it "returns fix_available => false" do
+      it "logs missing lockfile and returns fix_available => false" do
+        expect(Dependabot.logger).to receive(:info).with(/missing lockfile/i)
         expect(subject.audit(dependency: dependency, security_advisories: [])).
           to include("fix_available" => false)
       end
@@ -198,7 +213,7 @@
     context "when the native helper raises" do
       let(:dependency_files) { project_dependency_files("npm8/simple") }
 
-      it "returns fix_available => false and logs the failure" do
+      it "logs the failure and returns fix_available => false" do
         # Stub native helper path with the `false` builtin in order to get a
         # non-zero exit status from the helper subprocess and cause
         # `Dependabot::SharedHelpers::HelperSubprocessFailed` to be raised.