Extract log helper methods into a Logger::Formatter, Push the job_id into the Job object

updater/lib/dependabot/api_client.rb

@@ -49,7 +49,7 @@ def fetch_job
           :vendor_dependencies, :security_updates_only
         )
 
-      Job.new(job_data.merge(token: job_token))
+      Job.new(job_data.merge(id: job_id, token: job_token))
     end
 
     # TODO: Make `base_commit_sha` part of Dependabot::DependencyChange

updater/lib/dependabot/base_command.rb

@@ -4,6 +4,7 @@
 require "dependabot/api_client"
 require "dependabot/service"
 require "dependabot/logger"
+require "dependabot/logger/formats"
 require "dependabot/python"
 require "dependabot/terraform"
 require "dependabot/elm"
@@ -46,20 +47,22 @@ def base_commit_sha
     # This means that exceptions in tests can occasionally be swallowed
     # and we must rely on reading RSpec output to detect certain problems.
     def run
-      logger_info("Starting job processing")
+      Dependabot.logger.formatter = Dependabot::Logger::JobFormatter.new(job_id)
+      Dependabot.logger.info("Starting job processing")
       perform_job
-      logger_info("Finished job processing")
+      Dependabot.logger.info("Finished job processing")
     rescue StandardError => e
       handle_exception(e)
       service.mark_job_as_processed(base_commit_sha)
     ensure
+      Dependabot.logger.formatter = Dependabot::Logger::BasicFormatter.new
       Dependabot.logger.info(service.summary) unless service.noop?
       raise Dependabot::RunFailure if Dependabot::Environment.github_actions? && service.failure?
     end
 
     def handle_exception(err)
-      logger_error(err.message)
-      err.backtrace.each { |line| logger_error(line) }
+      Dependabot.logger.error(err.message)
+      err.backtrace.each { |line| Dependabot.logger.error(line) }
 
       Raven.capture_exception(err, raven_context)
 
@@ -88,22 +91,6 @@ def service
 
     private
 
-    def logger_info(message)
-      Dependabot.logger.info(prefixed_log_message(message))
-    end
-
-    def logger_error(message)
-      Dependabot.logger.error(prefixed_log_message(message))
-    end
-
-    def prefixed_log_message(message)
-      message.lines.map { |line| [log_prefix, line].join(" ") }.join
-    end
-
-    def log_prefix
-      "<job_#{job_id}>" if job_id
-    end
-
     def raven_context
       context = { tags: {}, extra: { update_job_id: job_id } }
       context[:tags][:package_manager] = job.package_manager if job

updater/lib/dependabot/environment.rb

@@ -10,9 +10,16 @@ def self.job_token
       @job_token ||= environment_variable("DEPENDABOT_JOB_TOKEN")
     end
 
+    def self.debug_enabled?
+      @debug_enabled ||= job_debug_enabled? || environment_debug_enabled?
+    end
+
+    def self.log_level
+      debug_enabled? ? :debug : :info
+    end
+
     def self.api_url
-      default = "http://localhost:3001"
-      @api_url ||= environment_variable("DEPENDABOT_API_URL", default)
+      @api_url ||= environment_variable("DEPENDABOT_API_URL", "http://localhost:3001")
     end
 
     def self.job_path
@@ -35,14 +42,20 @@ def self.job_definition
       @job_definition ||= JSON.parse(File.read(job_path))
     end
 
-    def self.environment_variable(variable_name, default = :_undefined)
+    private_class_method def self.environment_variable(variable_name, default = :_undefined)
       return ENV.fetch(variable_name, default) unless default == :_undefined
 
       ENV.fetch(variable_name) do
         raise ArgumentError, "Missing environment variable #{variable_name}"
       end
     end
 
-    private_class_method :environment_variable
+    private_class_method def self.job_debug_enabled?
+      !!job_definition.dig("job", "debug")
+    end
+
+    private_class_method def self.environment_debug_enabled?
+      !!environment_variable("DEPENDABOT_DEBUG", false)
+    end
   end
 end

updater/lib/dependabot/file_fetcher_command.rb

@@ -29,10 +29,10 @@ def perform_job
         @base_commit_sha ||= "unknown"
         if Octokit::RATE_LIMITED_ERRORS.include?(e.class)
           remaining = rate_limit_error_remaining(e)
-          logger_error("Repository is rate limited, attempting to retry in " \
-                       "#{remaining}s")
+          Dependabot.logger.error("Repository is rate limited, attempting to retry in " \
+                                  "#{remaining}s")
         else
-          logger_error("Error during file fetching; aborting")
+          Dependabot.logger.error("Error during file fetching; aborting")
         end
         handle_file_fetcher_error(e)
         service.mark_job_as_processed(@base_commit_sha)
@@ -94,7 +94,7 @@ def job
           :commit_message_options, :security_updates_only
         )
 
-      @job ||= Job.new(attrs)
+      @job ||= Job.new(attrs.merge(id: job_id))
     end
 
     def file_fetcher
@@ -167,8 +167,8 @@ def handle_file_fetcher_error(error)
             }
           }
         else
-          logger_error error.message
-          error.backtrace.each { |line| logger_error line }
+          Dependabot.logger.error(error.message)
+          error.backtrace.each { |line| Dependabot.logger.error line }
           Raven.capture_exception(error, raven_context)
 
           { "error-type": "unknown_error" }
@@ -196,11 +196,11 @@ def record_error(error_details)
     # connectivity through the proxy is established which can take 10-15s on
     # the first request in some customer's environments.
     def connectivity_check
-      logger_info("Connectivity check starting")
+      Dependabot.logger.info("Connectivity check starting")
       github_connectivity_client(job).repository(job.source.repo)
-      logger_info("Connectivity check successful")
+      Dependabot.logger.info("Connectivity check successful")
     rescue StandardError => e
-      logger_error("Connectivity check failed: #{e.message}")
+      Dependabot.logger.error("Connectivity check failed: #{e.message}")
     end
 
     def github_connectivity_client(job)

updater/lib/dependabot/job.rb

@@ -18,14 +18,15 @@ module Dependabot
   class Job
     TOP_LEVEL_DEPENDENCY_TYPES = %w(direct production development).freeze
 
-    attr_reader :token, :dependencies, :package_manager, :ignore_conditions,
+    attr_reader :id, :token, :dependencies, :package_manager, :ignore_conditions,
                 :existing_pull_requests, :source, :credentials,
                 :requirements_update_strategy, :security_advisories,
                 :allowed_updates, :vendor_dependencies, :security_updates_only
 
-    # NOTE: "attributes" are fetched and injected at run time from both
-    # dependabot-api and dependabot-backend using the UpdateJobPrivateSerializer
+    # NOTE: "attributes" are fetched and injected at run time from
+    # dependabot-api using the UpdateJobPrivateSerializer
     def initialize(attributes)
+      @id                           = attributes.fetch(:id)
       @allowed_updates              = attributes.fetch(:allowed_updates)
       @commit_message_options       = attributes.fetch(:commit_message_options, {})
       @credentials                  = attributes.fetch(:credentials, [])

updater/lib/dependabot/logger/formats.rb

@@ -0,0 +1,46 @@
+# frozen_string_literal: true
+
+require "logger"
+
+# Provides Logger::Formatter classes specific to the Updater project to augment
+# the global log helper defined in common/lib/dependabot/logger.rb
+module Dependabot
+  module Logger
+    class BasicFormatter < ::Logger::Formatter
+      # Strip out timestamps as these are included in the runner's logger
+      def call(severity, _datetime, _progname, msg)
+        "#{severity} #{msg2str(msg)}\n"
+      end
+    end
+
+    class JobFormatter < ::Logger::Formatter
+      CLI_ID = "cli"
+      UNKNOWN_ID = "unknown_id"
+
+      def initialize(job_id)
+        @job_id = job_id
+      end
+
+      def call(severity, _datetime, _progname, msg)
+        [
+          severity,
+          job_prefix,
+          msg2str(msg)
+        ].compact.join(" ") + "\n"
+      end
+
+      private
+
+      def job_prefix
+        return @job_prefix if defined? @job_prefix
+        # The dependabot/cli tool uses a placeholder value since it does not
+        # have an actual Job ID issued by the service.
+        #
+        # Let's just omit the prefix if this is the case.
+        return @job_prefix = nil if @job_id == CLI_ID
+
+        @job_prefix = "<job_#{@job_id || UNKNOWN_ID}>"
+      end
+    end
+  end
+end

updater/lib/dependabot/setup.rb

@@ -30,18 +30,13 @@
   config.processors += [ExceptionSanitizer]
 end
 
-require "logger"
 require "dependabot/logger"
-
-class LoggerFormatter < Logger::Formatter
-  # Strip out timestamps as these are included in the runner's logger
-  def call(severity, _datetime, _progname, msg)
-    "#{severity} #{msg2str(msg)}\n"
-  end
-end
+require "dependabot/logger/formats"
+require "dependabot/environment"
 
 Dependabot.logger = Logger.new($stdout).tap do |logger|
-  logger.formatter = LoggerFormatter.new
+  logger.level = Dependabot::Environment.log_level
+  logger.formatter = Dependabot::Logger::BasicFormatter.new
 end
 
 # We configure `Dependabot::Utils.register_always_clone` for some ecosystems. In

updater/lib/dependabot/update_files_command.rb

@@ -34,7 +34,7 @@ def job
           :commit_message_options, :security_updates_only
         )
 
-      @job ||= Job.new(attrs)
+      @job ||= Job.new(attrs.merge(id: job_id))
     end
 
     def dependency_files