Add logs to the Github Import process

Currently is very hard to debug a Github Import. This commit logs each
step of the import process to make it easier to debug.

app/workers/concerns/gitlab/github_import/object_importer.rb

@@ -15,17 +15,25 @@ module Gitlab
 
         feature_category :importers
         worker_has_external_dependencies!
+
+        def logger
+          @logger ||= Gitlab::Import::Logger.build
+        end
       end
 
       # project - An instance of `Project` to import the data into.
       # client - An instance of `Gitlab::GithubImport::Client`
       # hash - A Hash containing the details of the object to import.
       def import(project, client, hash)
-        object = representation_class.from_json_hash(hash)
+        info(project.id, message: 'starting importer')
 
+        object = representation_class.from_json_hash(hash)
         importer_class.new(object, project, client).execute
 
         counter.increment
+        info(project.id, message: 'importer finished')
+      rescue => e
+        error(project.id, e)
       end
 
       def counter
@@ -52,6 +60,35 @@ module Gitlab
       def counter_description
         raise NotImplementedError
       end
+
+      private
+
+      def info(project_id, extra = {})
+        logger.info(log_attributes(project_id, extra))
+      end
+
+      def error(project_id, exception)
+        logger.error(
+          log_attributes(
+            project_id,
+            message: 'importer failed',
+            'error.message': exception.message
+          )
+        )
+
+        Gitlab::ErrorTracking.track_and_raise_exception(
+          exception,
+          log_attributes(project_id)
+        )
+      end
+
+      def log_attributes(project_id, extra = {})
+        extra.merge(
+          import_source: :github,
+          project_id: project_id,
+          importer: importer_class.name
+        )
+      end
     end
   end
 end

app/workers/concerns/gitlab/github_import/rescheduling_methods.rb

@@ -6,7 +6,7 @@ module Gitlab
     # importing GitHub projects.
     module ReschedulingMethods
       # project_id - The ID of the GitLab project to import the note into.
-      # hash - A Hash containing the details of the GitHub object to imoprt.
+      # hash - A Hash containing the details of the GitHub object to import.
       # notify_key - The Redis key to notify upon completion, if any.
       # rubocop: disable CodeReuse/ActiveRecord
       def perform(project_id, hash, notify_key = nil)

app/workers/concerns/gitlab/github_import/stage_methods.rb

@@ -5,11 +5,17 @@ module Gitlab
     module StageMethods
       # project_id - The ID of the GitLab project to import the data into.
       def perform(project_id)
+        info(project_id, message: 'starting stage')
+
         return unless (project = find_project(project_id))
 
         client = GithubImport.new_client_for(project)
 
         try_import(client, project)
+
+        info(project_id, message: 'stage finished')
+      rescue => e
+        error(project_id, e)
       end
 
       # client - An instance of Gitlab::GithubImport::Client.
@@ -27,6 +33,39 @@ module Gitlab
         Project.joins_import_state.where(import_state: { status: :started }).find_by(id: id)
       end
       # rubocop: enable CodeReuse/ActiveRecord
+
+      private
+
+      def info(project_id, extra = {})
+        logger.info(log_attributes(project_id, extra))
+      end
+
+      def error(project_id, exception)
+        logger.error(
+          log_attributes(
+            project_id,
+            message: 'stage failed',
+            'error.message': exception.message
+          )
+        )
+
+        Gitlab::ErrorTracking.track_and_raise_exception(
+          exception,
+          log_attributes(project_id)
+        )
+      end
+
+      def log_attributes(project_id, extra = {})
+        extra.merge(
+          import_source: :github,
+          project_id: project_id,
+          import_stage: self.class.name
+        )
+      end
+
+      def logger
+        @logger ||= Gitlab::Import::Logger.build
+      end
     end
   end
 end

app/workers/gitlab/github_import/stage/finish_import_worker.rb

@@ -20,12 +20,15 @@ module Gitlab
 
         def report_import_time(project)
           duration = Time.zone.now - project.created_at
-          path = project.full_path
 
-          histogram.observe({ project: path }, duration)
+          histogram.observe({ project: project.full_path }, duration)
           counter.increment
 
-          logger.info("GitHub importer finished for #{path} in #{duration.round(2)} seconds")
+          info(
+            project.id,
+            message: "GitHub project import finished",
+            duration_s: duration.round(2)
+          )
         end
 
         def histogram

app/workers/gitlab/github_import/stage/import_base_data_worker.rb

@@ -20,6 +20,7 @@ module Gitlab
         # project - An instance of Project.
         def import(client, project)
           IMPORTERS.each do |klass|
+            info(project.id, message: "starting importer", importer: klass.name)
             klass.new(project, client).execute
           end
 

app/workers/gitlab/github_import/stage/import_issues_and_diff_notes_worker.rb

@@ -19,6 +19,7 @@ module Gitlab
         # project - An instance of Project.
         def import(client, project)
           waiters = IMPORTERS.each_with_object({}) do |klass, hash|
+            info(project.id, message: "starting importer", importer: klass.name)
             waiter = klass.new(project, client).execute
             hash[waiter.key] = waiter.jobs_remaining
           end

app/workers/gitlab/github_import/stage/import_lfs_objects_worker.rb

@@ -16,6 +16,8 @@ module Gitlab
 
         # project - An instance of Project.
         def import(project)
+          info(project.id, message: "starting importer", importer: 'Importer::LfsObjectsImporter')
+
           waiter = Importer::LfsObjectsImporter
             .new(project, nil)
             .execute

app/workers/gitlab/github_import/stage/import_notes_worker.rb

@@ -11,6 +11,7 @@ module Gitlab
         # client - An instance of Gitlab::GithubImport::Client.
         # project - An instance of Project.
         def import(client, project)
+          info(project.id, message: "starting importer", importer: 'Importer::NotesImporter')
           waiter = Importer::NotesImporter
             .new(project, client)
             .execute

app/workers/gitlab/github_import/stage/import_pull_requests_worker.rb

@@ -11,6 +11,7 @@ module Gitlab
         # client - An instance of Gitlab::GithubImport::Client.
         # project - An instance of Project.
         def import(client, project)
+          info(project.id, message: "starting importer", importer: 'Importer::PullRequestsImporter')
           waiter = Importer::PullRequestsImporter
             .new(project, client)
             .execute

app/workers/gitlab/github_import/stage/import_repository_worker.rb

@@ -21,6 +21,7 @@ module Gitlab
           # expiration time.
           RefreshImportJidWorker.perform_in_the_future(project.id, jid)
 
+          info(project.id, message: "starting importer", importer: 'Importer::RepositoryImporter')
           importer = Importer::RepositoryImporter.new(project, client)
 
           return unless importer.execute

lib/gitlab/github_import/importer/lfs_objects_importer.rb

@@ -28,11 +28,6 @@ module Gitlab
           lfs_objects.each do |object|
             yield object
           end
-        rescue StandardError => e
-          Gitlab::Import::Logger.error(
-            message: 'The Lfs import process failed',
-            error: e.message
-          )
         end
       end
     end

lib/gitlab/github_import/parallel_scheduling.rb

@@ -26,6 +26,8 @@ module Gitlab
       end
 
       def execute
+        info(project.id, message: "starting importer")
+
         retval =
           if parallel?
             parallel_import
@@ -43,8 +45,11 @@ module Gitlab
         # completed those jobs will just cycle through any remaining pages while
         # not scheduling anything.
         Gitlab::Cache::Import::Caching.expire(already_imported_cache_key, 15.minutes.to_i)
+        info(project.id, message: "importer finished")
 
         retval
+      rescue => e
+        error(project.id, e)
       end
 
       # Imports all the objects in sequence in the current thread.
@@ -157,6 +162,40 @@ module Gitlab
       def collection_options
         {}
       end
+
+      private
+
+      def info(project_id, extra = {})
+        logger.info(log_attributes(project_id, extra))
+      end
+
+      def error(project_id, exception)
+        logger.error(
+          log_attributes(
+            project_id,
+            message: 'importer failed',
+            'error.message': exception.message
+          )
+        )
+
+        Gitlab::ErrorTracking.track_and_raise_exception(
+          exception,
+          log_attributes(project_id)
+        )
+      end
+
+      def log_attributes(project_id, extra = {})
+        extra.merge(
+          import_source: :github,
+          project_id: project_id,
+          importer: importer_class.name,
+          parallel: parallel?
+        )
+      end
+
+      def logger
+        @logger ||= Gitlab::Import::Logger.build
+      end
     end
   end
 end

spec/lib/gitlab/github_import/parallel_scheduling_spec.rb

@@ -7,6 +7,10 @@ RSpec.describe Gitlab::GithubImport::ParallelScheduling do
     Class.new do
       include(Gitlab::GithubImport::ParallelScheduling)
 
+      def importer_class
+        Class
+      end
+
       def collection_method
         :issues
       end
@@ -63,6 +67,82 @@ RSpec.describe Gitlab::GithubImport::ParallelScheduling do
 
       importer.execute
     end
+
+    it 'logs the the process' do
+      importer = importer_class.new(project, client, parallel: false)
+
+      expect(importer)
+        .to receive(:sequential_import)
+        .and_return([])
+
+      expect_next_instance_of(Gitlab::Import::Logger) do |logger|
+        expect(logger)
+          .to receive(:info)
+          .with(
+            message: 'starting importer',
+            import_source: :github,
+            parallel: false,
+            project_id: project.id,
+            importer: 'Class'
+          )
+        expect(logger)
+          .to receive(:info)
+          .with(
+            message: 'importer finished',
+            import_source: :github,
+            parallel: false,
+            project_id: project.id,
+            importer: 'Class'
+          )
+      end
+
+      importer.execute
+    end
+
+    it 'logs the error when it fails' do
+      exception = StandardError.new('some error')
+
+      importer = importer_class.new(project, client, parallel: false)
+
+      expect(importer)
+        .to receive(:sequential_import)
+        .and_raise(exception)
+
+      expect_next_instance_of(Gitlab::Import::Logger) do |logger|
+        expect(logger)
+          .to receive(:info)
+          .with(
+            message: 'starting importer',
+            import_source: :github,
+            parallel: false,
+            project_id: project.id,
+            importer: 'Class'
+          )
+        expect(logger)
+          .to receive(:error)
+          .with(
+            message: 'importer failed',
+            import_source: :github,
+            project_id: project.id,
+            parallel: false,
+            importer: 'Class',
+            'error.message': 'some error'
+          )
+      end
+
+      expect(Gitlab::ErrorTracking)
+        .to receive(:track_and_raise_exception)
+        .with(
+          exception,
+          import_source: :github,
+          parallel: false,
+          project_id: project.id,
+          importer: 'Class'
+        )
+        .and_call_original
+
+      expect { importer.execute }.to raise_error(exception)
+    end
   end
 
   describe '#sequential_import' do

spec/workers/concerns/gitlab/github_import/object_importer_spec.rb

@@ -22,20 +22,21 @@ RSpec.describe Gitlab::GithubImport::ObjectImporter do
   end
 
   describe '#import' do
-    it 'imports the object' do
-      representation_class = double(:representation_class)
-      importer_class = double(:importer_class)
-      importer_instance = double(:importer_instance)
-      representation = double(:representation)
-      project = double(:project, full_path: 'foo/bar')
-      client = double(:client)
-
+    let(:representation_class) { double(:representation_class) }
+    let(:importer_class) { double(:importer_class, name: 'klass_name') }
+    let(:importer_instance) { double(:importer_instance) }
+    let(:representation) { double(:representation) }
+    let(:project) { double(:project, full_path: 'foo/bar', id: 1) }
+    let(:client) { double(:client) }
+
+    before do
       expect(worker)
         .to receive(:representation_class)
         .and_return(representation_class)
 
       expect(worker)
         .to receive(:importer_class)
+        .at_least(:once)
         .and_return(importer_class)
 
       expect(representation_class)
@@ -47,7 +48,9 @@ RSpec.describe Gitlab::GithubImport::ObjectImporter do
         .to receive(:new)
         .with(representation, project, client)
         .and_return(importer_instance)
+    end
 
+    it 'imports the object' do
       expect(importer_instance)
         .to receive(:execute)
 
@@ -55,8 +58,61 @@ RSpec.describe Gitlab::GithubImport::ObjectImporter do
         .to receive(:increment)
         .and_call_original
 
+      expect_next_instance_of(Gitlab::Import::Logger) do |logger|
+        expect(logger)
+          .to receive(:info)
+          .with(
+            message: 'starting importer',
+            import_source: :github,
+            project_id: 1,
+            importer: 'klass_name'
+          )
+        expect(logger)
+          .to receive(:info)
+          .with(
+            message: 'importer finished',
+            import_source: :github,
+            project_id: 1,
+            importer: 'klass_name'
+          )
+      end
+
       worker.import(project, client, { 'number' => 10 })
     end
+
+    it 'logs error when the import fails' do
+      exception = StandardError.new('some error')
+      expect(importer_instance)
+        .to receive(:execute)
+        .and_raise(exception)
+
+      expect_next_instance_of(Gitlab::Import::Logger) do |logger|
+        expect(logger)
+          .to receive(:info)
+          .with(
+            message: 'starting importer',
+            import_source: :github,
+            project_id: project.id,
+            importer: 'klass_name'
+          )
+        expect(logger)
+          .to receive(:error)
+          .with(
+            message: 'importer failed',
+            import_source: :github,
+            project_id: project.id,
+            importer: 'klass_name',
+            'error.message': 'some error'
+          )
+      end
+
+      expect(Gitlab::ErrorTracking)
+        .to receive(:track_and_raise_exception)
+        .with(exception, import_source: :github, project_id: 1, importer: 'klass_name')
+        .and_call_original
+
+      expect { worker.import(project, client, { 'number' => 10 }) }.to raise_error(exception)
+    end
   end
 
   describe '#counter' do

spec/workers/concerns/gitlab/github_import/stage_methods_spec.rb

@@ -5,7 +5,13 @@ require 'spec_helper'
 RSpec.describe Gitlab::GithubImport::StageMethods do
   let(:project) { create(:project) }
   let(:worker) do
-    Class.new { include(Gitlab::GithubImport::StageMethods) }.new
+    Class.new do
+      def self.name
+        'DummyStage'
+      end
+
+      include(Gitlab::GithubImport::StageMethods)
+    end.new
   end
 
   describe '#perform' do
@@ -30,8 +36,72 @@ RSpec.describe Gitlab::GithubImport::StageMethods do
           an_instance_of(Project)
         )
 
+      expect_next_instance_of(Gitlab::Import::Logger) do |logger|
+        expect(logger)
+          .to receive(:info)
+          .with(
+            message: 'starting stage',
+            import_source: :github,
+            project_id: project.id,
+            import_stage: 'DummyStage'
+          )
+        expect(logger)
+          .to receive(:info)
+          .with(
+            message: 'stage finished',
+            import_source: :github,
+            project_id: project.id,
+            import_stage: 'DummyStage'
+          )
+      end
+
       worker.perform(project.id)
     end
+
+    it 'logs error when import fails' do
+      exception = StandardError.new('some error')
+
+      allow(worker)
+        .to receive(:find_project)
+        .with(project.id)
+        .and_return(project)
+
+      expect(worker)
+        .to receive(:try_import)
+        .and_raise(exception)
+
+      expect_next_instance_of(Gitlab::Import::Logger) do |logger|
+        expect(logger)
+          .to receive(:info)
+          .with(
+            message: 'starting stage',
+            import_source: :github,
+            project_id: project.id,
+            import_stage: 'DummyStage'
+          )
+        expect(logger)
+          .to receive(:error)
+          .with(
+            message: 'stage failed',
+            import_source: :github,
+            project_id: project.id,
+            import_stage: 'DummyStage',
+            'error.message': 'some error'
+          )
+      end
+
+      expect(Gitlab::ErrorTracking)
+        .to receive(:track_and_raise_exception)
+        .with(
+          exception,
+          import_source: :github,
+          project_id: project.id,
+          import_stage: 'DummyStage'
+        )
+        .and_call_original
+
+      expect { worker.perform(project.id) }.to raise_error(exception)
+    end
   end
 
   describe '#try_import' do

spec/workers/gitlab/github_import/import_diff_note_worker_spec.rb

@@ -7,7 +7,7 @@ RSpec.describe Gitlab::GithubImport::ImportDiffNoteWorker do
 
   describe '#import' do
     it 'imports a diff note' do
-      project = double(:project, full_path: 'foo/bar')
+      project = double(:project, full_path: 'foo/bar', id: 1)
       client = double(:client)
       importer = double(:importer)
       hash = {

spec/workers/gitlab/github_import/import_issue_worker_spec.rb

@@ -7,7 +7,7 @@ RSpec.describe Gitlab::GithubImport::ImportIssueWorker do
 
   describe '#import' do
     it 'imports an issue' do
-      project = double(:project, full_path: 'foo/bar')
+      project = double(:project, full_path: 'foo/bar', id: 1)
       client = double(:client)
       importer = double(:importer)
       hash = {

spec/workers/gitlab/github_import/import_note_worker_spec.rb

@@ -7,7 +7,7 @@ RSpec.describe Gitlab::GithubImport::ImportNoteWorker do
 
   describe '#import' do
     it 'imports a note' do
-      project = double(:project, full_path: 'foo/bar')
+      project = double(:project, full_path: 'foo/bar', id: 1)
       client = double(:client)
       importer = double(:importer)
       hash = {

spec/workers/gitlab/github_import/import_pull_request_worker_spec.rb

@@ -7,7 +7,7 @@ RSpec.describe Gitlab::GithubImport::ImportPullRequestWorker do
 
   describe '#import' do
     it 'imports a pull request' do
-      project = double(:project, full_path: 'foo/bar')
+      project = double(:project, full_path: 'foo/bar', id: 1)
       client = double(:client)
       importer = double(:importer)
       hash = {

spec/workers/gitlab/github_import/stage/finish_import_worker_spec.rb

@@ -26,7 +26,17 @@ RSpec.describe Gitlab::GithubImport::Stage::FinishImportWorker do
         .to receive(:increment)
         .and_call_original
 
-      expect(worker.logger).to receive(:info).with(an_instance_of(String))
+      expect_next_instance_of(Gitlab::Import::Logger) do |logger|
+        expect(logger)
+          .to receive(:info)
+          .with(
+            message: 'GitHub project import finished',
+            import_stage: 'Gitlab::GithubImport::Stage::FinishImportWorker',
+            import_source: :github,
+            project_id: project.id,
+            duration_s: a_kind_of(Numeric)
+          )
+      end
 
       worker.report_import_time(project)
     end