diff --git a/app/services/import/github_service.rb b/app/services/import/github_service.rb index 2f808d45ffd76644a332e7905062ed5c4f66efc9..2aaab88e7789d0cdfb6888fccacc777349ba56eb 100644 --- a/app/services/import/github_service.rb +++ b/app/services/import/github_service.rb @@ -111,7 +111,7 @@ def blocked_url? private def log_error(exception) - Gitlab::Import::Logger.error( + Gitlab::GithubImport::Logger.error( message: 'Import failed due to a GitHub error', status: exception.response_status, error: exception.response_body diff --git a/app/workers/concerns/gitlab/github_import/object_importer.rb b/app/workers/concerns/gitlab/github_import/object_importer.rb index 1eff53cea0117557e2a73f6f8408db54500cac03..e5a224c1d6bed8bee27fd85a430e3b02ba50ca39 100644 --- a/app/workers/concerns/gitlab/github_import/object_importer.rb +++ b/app/workers/concerns/gitlab/github_import/object_importer.rb @@ -17,10 +17,6 @@ module ObjectImporter 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. @@ -63,11 +59,11 @@ def importer_class attr_accessor :github_id def info(project_id, extra = {}) - logger.info(log_attributes(project_id, extra)) + Logger.info(log_attributes(project_id, extra)) end def error(project_id, exception, data = {}) - logger.error( + Logger.error( log_attributes( project_id, message: 'importer failed', @@ -78,13 +74,12 @@ def error(project_id, exception, data = {}) Gitlab::ErrorTracking.track_and_raise_exception( exception, - log_attributes(project_id) + log_attributes(project_id, import_source: :github) ) end def log_attributes(project_id, extra = {}) extra.merge( - import_source: :github, project_id: project_id, importer: importer_class.name, github_id: github_id diff --git a/app/workers/concerns/gitlab/github_import/queue.rb b/app/workers/concerns/gitlab/github_import/queue.rb index 05eb7fbc2cb93d5de9aa46cafe71571c72537aef..1ec6250952830ad3d5626ec8ec45c0435432f429 100644 --- a/app/workers/concerns/gitlab/github_import/queue.rb +++ b/app/workers/concerns/gitlab/github_import/queue.rb @@ -17,7 +17,7 @@ module Queue sidekiq_options dead: false, retry: 5 sidekiq_retries_exhausted do |msg, e| - Gitlab::Import::Logger.error( + Logger.error( event: :github_importer_exhausted, message: msg['error_message'], class: msg['class'], diff --git a/app/workers/concerns/gitlab/github_import/stage_methods.rb b/app/workers/concerns/gitlab/github_import/stage_methods.rb index 916b273a28f27bea69aa97db31b11c9101798cf0..0671dcf4e727ebe939cd876f19cb383baf61a6b2 100644 --- a/app/workers/concerns/gitlab/github_import/stage_methods.rb +++ b/app/workers/concerns/gitlab/github_import/stage_methods.rb @@ -37,11 +37,11 @@ def find_project(id) private def info(project_id, extra = {}) - logger.info(log_attributes(project_id, extra)) + Logger.info(log_attributes(project_id, extra)) end def error(project_id, exception) - logger.error( + Logger.error( log_attributes( project_id, message: 'stage failed', @@ -51,21 +51,16 @@ def error(project_id, exception) Gitlab::ErrorTracking.track_and_raise_exception( exception, - log_attributes(project_id) + log_attributes(project_id, import_source: :github) ) 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 diff --git a/doc/development/github_importer.md b/doc/development/github_importer.md index 14fd8f6bf728cb4e945467ba547d5dd7f625be84..c4f4c2d87d855822e1be77342a9a7f3ff5945121 100644 --- a/doc/development/github_importer.md +++ b/doc/development/github_importer.md @@ -237,6 +237,7 @@ The code for this resides in: > - [Introduced](https://gitlab.com/gitlab-org/gitlab/-/merge_requests/48512/diffs) in GitLab 13.7. > - Number of imported objects [introduced](https://gitlab.com/gitlab-org/gitlab/-/merge_requests/64256) in GitLab 14.1. +> - `Gitlab::GithubImport::Logger` [introduced](https://gitlab.com/gitlab-org/gitlab/-/merge_requests/65968) in GitLab 14.2. The import progress can be checked in the `logs/importer.log` file. Each relevant import is logged with `"import_source": "github"` and the `"project_id"`. diff --git a/lib/gitlab/github_import/logger.rb b/lib/gitlab/github_import/logger.rb new file mode 100644 index 0000000000000000000000000000000000000000..f234ab290c5a8d7f6806c745321e66d2036cd168 --- /dev/null +++ b/lib/gitlab/github_import/logger.rb @@ -0,0 +1,11 @@ +# frozen_string_literal: true + +module Gitlab + module GithubImport + class Logger < ::Gitlab::Import::Logger + def default_attributes + super.merge(import_source: :github) + end + end + end +end diff --git a/lib/gitlab/github_import/parallel_scheduling.rb b/lib/gitlab/github_import/parallel_scheduling.rb index 4598429d568dc1a841766a249c86d3d05455bbdd..c002dc750e7009fa45d12f5f01538f6da5c2f4d9 100644 --- a/lib/gitlab/github_import/parallel_scheduling.rb +++ b/lib/gitlab/github_import/parallel_scheduling.rb @@ -174,11 +174,11 @@ def collection_options private def info(project_id, extra = {}) - logger.info(log_attributes(project_id, extra)) + Logger.info(log_attributes(project_id, extra)) end def error(project_id, exception) - logger.error( + Logger.error( log_attributes( project_id, message: 'importer failed', @@ -188,22 +188,17 @@ def error(project_id, exception) Gitlab::ErrorTracking.track_exception( exception, - log_attributes(project_id) + log_attributes(project_id, import_source: :github) ) 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 diff --git a/lib/gitlab/import/logger.rb b/lib/gitlab/import/logger.rb index ab3e822a4e95714af489d6d5e67aa0bb9f8b7395..bd34aff734acfdd162ac1161d0a1237ece185358 100644 --- a/lib/gitlab/import/logger.rb +++ b/lib/gitlab/import/logger.rb @@ -6,6 +6,10 @@ class Logger < ::Gitlab::JsonLogger def self.file_name_noext 'importer' end + + def default_attributes + super.merge(feature_category: :importers) + end end end end diff --git a/lib/gitlab/json_logger.rb b/lib/gitlab/json_logger.rb index 3a74df8dc8f68d39bfb9be96d040db8a2315910f..d0dcd232ecc372d2f785cf399b0922b870102454 100644 --- a/lib/gitlab/json_logger.rb +++ b/lib/gitlab/json_logger.rb @@ -7,7 +7,7 @@ def self.file_name_noext end def format_message(severity, timestamp, progname, message) - data = {} + data = default_attributes data[:severity] = severity data[:time] = timestamp.utc.iso8601(3) data[Labkit::Correlation::CorrelationId::LOG_KEY] = Labkit::Correlation::CorrelationId.current_id @@ -21,5 +21,11 @@ def format_message(severity, timestamp, progname, message) Gitlab::Json.dump(data) + "\n" end + + protected + + def default_attributes + {} + end end end diff --git a/spec/lib/gitlab/github_import/importer/lfs_objects_importer_spec.rb b/spec/lib/gitlab/github_import/importer/lfs_objects_importer_spec.rb index 8ee534734f040e37ecf6fc679e6c6f81635bd226..eb2ee0d877948e41dbf89d9f4a602ec6ffa3fce5 100644 --- a/spec/lib/gitlab/github_import/importer/lfs_objects_importer_spec.rb +++ b/spec/lib/gitlab/github_import/importer/lfs_objects_importer_spec.rb @@ -61,18 +61,15 @@ .and_raise(exception) end - expect_next_instance_of(Gitlab::Import::Logger) do |logger| - expect(logger) - .to receive(:error) - .with( - message: 'importer failed', - import_source: :github, - project_id: project.id, - parallel: false, - importer: 'Gitlab::GithubImport::Importer::LfsObjectImporter', - 'error.message': 'Invalid Project URL' - ) - end + expect(Gitlab::GithubImport::Logger) + .to receive(:error) + .with( + message: 'importer failed', + project_id: project.id, + parallel: false, + importer: 'Gitlab::GithubImport::Importer::LfsObjectImporter', + 'error.message': 'Invalid Project URL' + ) expect(Gitlab::ErrorTracking) .to receive(:track_exception) diff --git a/spec/lib/gitlab/github_import/logger_spec.rb b/spec/lib/gitlab/github_import/logger_spec.rb new file mode 100644 index 0000000000000000000000000000000000000000..e7e095057477a847306fd61ba564b2305436f63e --- /dev/null +++ b/spec/lib/gitlab/github_import/logger_spec.rb @@ -0,0 +1,41 @@ +# frozen_string_literal: true + +require 'spec_helper' + +RSpec.describe Gitlab::GithubImport::Logger do + subject(:logger) { described_class.new('/dev/null') } + + let(:now) { Time.zone.now } + + describe '#format_message' do + before do + allow(Labkit::Correlation::CorrelationId).to receive(:current_id).and_return('new-correlation-id') + end + + it 'formats strings' do + output = subject.format_message('INFO', now, 'test', 'Hello world') + + expect(Gitlab::Json.parse(output)).to eq({ + 'severity' => 'INFO', + 'time' => now.utc.iso8601(3), + 'message' => 'Hello world', + 'correlation_id' => 'new-correlation-id', + 'feature_category' => 'importers', + 'import_source' => 'github' + }) + end + + it 'formats hashes' do + output = subject.format_message('INFO', now, 'test', { hello: 1 }) + + expect(Gitlab::Json.parse(output)).to eq({ + 'severity' => 'INFO', + 'time' => now.utc.iso8601(3), + 'hello' => 1, + 'correlation_id' => 'new-correlation-id', + 'feature_category' => 'importers', + 'import_source' => 'github' + }) + end + end +end diff --git a/spec/lib/gitlab/github_import/parallel_scheduling_spec.rb b/spec/lib/gitlab/github_import/parallel_scheduling_spec.rb index d56d4708385d38d0147c5106b55c5c5914af6d1c..0ea8f8697d9b6ff19913768c7d6fbe2449bf22a7 100644 --- a/spec/lib/gitlab/github_import/parallel_scheduling_spec.rb +++ b/spec/lib/gitlab/github_import/parallel_scheduling_spec.rb @@ -79,26 +79,23 @@ def collection_method .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 + expect(Gitlab::GithubImport::Logger) + .to receive(:info) + .with( + message: 'starting importer', + parallel: false, + project_id: project.id, + importer: 'Class' + ) + + expect(Gitlab::GithubImport::Logger) + .to receive(:info) + .with( + message: 'importer finished', + parallel: false, + project_id: project.id, + importer: 'Class' + ) importer.execute end @@ -112,35 +109,32 @@ def collection_method .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::GithubImport::Logger) + .to receive(:info) + .with( + message: 'starting importer', + parallel: false, + project_id: project.id, + importer: 'Class' + ) + + expect(Gitlab::GithubImport::Logger) + .to receive(:error) + .with( + message: 'importer failed', + project_id: project.id, + parallel: false, + importer: 'Class', + 'error.message': 'some error' + ) expect(Gitlab::ErrorTracking) .to receive(:track_exception) .with( exception, - import_source: :github, parallel: false, project_id: project.id, + import_source: :github, importer: 'Class' ) .and_call_original diff --git a/spec/lib/gitlab/import/logger_spec.rb b/spec/lib/gitlab/import/logger_spec.rb new file mode 100644 index 0000000000000000000000000000000000000000..60978aaa25c69da0b7013f788b3655776dd47276 --- /dev/null +++ b/spec/lib/gitlab/import/logger_spec.rb @@ -0,0 +1,39 @@ +# frozen_string_literal: true + +require 'spec_helper' + +RSpec.describe Gitlab::Import::Logger do + subject { described_class.new('/dev/null') } + + let(:now) { Time.zone.now } + + describe '#format_message' do + before do + allow(Labkit::Correlation::CorrelationId).to receive(:current_id).and_return('new-correlation-id') + end + + it 'formats strings' do + output = subject.format_message('INFO', now, 'test', 'Hello world') + + expect(Gitlab::Json.parse(output)).to eq({ + 'severity' => 'INFO', + 'time' => now.utc.iso8601(3), + 'message' => 'Hello world', + 'correlation_id' => 'new-correlation-id', + 'feature_category' => 'importers' + }) + end + + it 'formats hashes' do + output = subject.format_message('INFO', now, 'test', { hello: 1 }) + + expect(Gitlab::Json.parse(output)).to eq({ + 'severity' => 'INFO', + 'time' => now.utc.iso8601(3), + 'hello' => 1, + 'correlation_id' => 'new-correlation-id', + 'feature_category' => 'importers' + }) + end + end +end diff --git a/spec/workers/concerns/gitlab/github_import/object_importer_spec.rb b/spec/workers/concerns/gitlab/github_import/object_importer_spec.rb index ce02100ebfca3cde1afa91bf1e43ad9539763f2f..ddcf922ad688d9db63f8f5ef83a0c0a4068c3e7f 100644 --- a/spec/workers/concerns/gitlab/github_import/object_importer_spec.rb +++ b/spec/workers/concerns/gitlab/github_import/object_importer_spec.rb @@ -60,26 +60,23 @@ def initialize(attributes) expect(importer_instance) .to receive(:execute) - expect_next_instance_of(Gitlab::Import::Logger) do |logger| - expect(logger) - .to receive(:info) - .with( - github_id: 1, - message: 'starting importer', - import_source: :github, - project_id: 1, - importer: 'klass_name' - ) - expect(logger) - .to receive(:info) - .with( - github_id: 1, - message: 'importer finished', - import_source: :github, - project_id: 1, - importer: 'klass_name' - ) - end + expect(Gitlab::GithubImport::Logger) + .to receive(:info) + .with( + github_id: 1, + message: 'starting importer', + project_id: 1, + importer: 'klass_name' + ) + + expect(Gitlab::GithubImport::Logger) + .to receive(:info) + .with( + github_id: 1, + message: 'importer finished', + project_id: 1, + importer: 'klass_name' + ) worker.import(project, client, { 'number' => 10, 'github_id' => 1 }) @@ -100,31 +97,28 @@ def initialize(attributes) .to receive(:execute) .and_raise(exception) - expect_next_instance_of(Gitlab::Import::Logger) do |logger| - expect(logger) - .to receive(:info) - .with( - github_id: 1, - message: 'starting importer', - import_source: :github, - project_id: project.id, - importer: 'klass_name' - ) - expect(logger) - .to receive(:error) - .with( - github_id: 1, - message: 'importer failed', - import_source: :github, - project_id: project.id, - importer: 'klass_name', - 'error.message': 'some error', - 'github.data': { - 'github_id' => 1, - 'number' => 10 - } - ) - end + expect(Gitlab::GithubImport::Logger) + .to receive(:info) + .with( + github_id: 1, + message: 'starting importer', + project_id: project.id, + importer: 'klass_name' + ) + + expect(Gitlab::GithubImport::Logger) + .to receive(:error) + .with( + github_id: 1, + message: 'importer failed', + project_id: project.id, + importer: 'klass_name', + 'error.message': 'some error', + 'github.data': { + 'github_id' => 1, + 'number' => 10 + } + ) expect(Gitlab::ErrorTracking) .to receive(:track_and_raise_exception) @@ -143,21 +137,18 @@ def initialize(attributes) it 'logs error when representation does not have a github_id' do expect(importer_class).not_to receive(:new) - expect_next_instance_of(Gitlab::Import::Logger) do |logger| - expect(logger) - .to receive(:error) - .with( - github_id: nil, - message: 'importer failed', - import_source: :github, - project_id: project.id, - importer: 'klass_name', - 'error.message': 'key not found: :github_id', - 'github.data': { - 'number' => 10 - } - ) - end + expect(Gitlab::GithubImport::Logger) + .to receive(:error) + .with( + github_id: nil, + message: 'importer failed', + project_id: project.id, + importer: 'klass_name', + 'error.message': 'key not found: :github_id', + 'github.data': { + 'number' => 10 + } + ) expect(Gitlab::ErrorTracking) .to receive(:track_and_raise_exception) diff --git a/spec/workers/concerns/gitlab/github_import/stage_methods_spec.rb b/spec/workers/concerns/gitlab/github_import/stage_methods_spec.rb index 651ea77a71c9ac4c167e51ad98866b425ca53756..c0e2df6f9856350acc118e1911f72e7ed4d75660 100644 --- a/spec/workers/concerns/gitlab/github_import/stage_methods_spec.rb +++ b/spec/workers/concerns/gitlab/github_import/stage_methods_spec.rb @@ -36,24 +36,21 @@ def self.name 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 + expect(Gitlab::GithubImport::Logger) + .to receive(:info) + .with( + message: 'starting stage', + project_id: project.id, + import_stage: 'DummyStage' + ) + + expect(Gitlab::GithubImport::Logger) + .to receive(:info) + .with( + message: 'stage finished', + project_id: project.id, + import_stage: 'DummyStage' + ) worker.perform(project.id) end @@ -70,25 +67,22 @@ def self.name .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::GithubImport::Logger) + .to receive(:info) + .with( + message: 'starting stage', + project_id: project.id, + import_stage: 'DummyStage' + ) + + expect(Gitlab::GithubImport::Logger) + .to receive(:error) + .with( + message: 'stage failed', + project_id: project.id, + import_stage: 'DummyStage', + 'error.message': 'some error' + ) expect(Gitlab::ErrorTracking) .to receive(:track_and_raise_exception) diff --git a/spec/workers/gitlab/github_import/stage/finish_import_worker_spec.rb b/spec/workers/gitlab/github_import/stage/finish_import_worker_spec.rb index 8dea24dc74f1e34069a3d9463c1179e105e20e80..132fe1dc618bec693020d47bd669803bcb6e7c4e 100644 --- a/spec/workers/gitlab/github_import/stage/finish_import_worker_spec.rb +++ b/spec/workers/gitlab/github_import/stage/finish_import_worker_spec.rb @@ -26,21 +26,18 @@ .to receive(:increment) .and_call_original - 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, - object_counts: { - 'fetched' => {}, - 'imported' => {} - }, - project_id: project.id, - duration_s: a_kind_of(Numeric) - ) - end + expect(Gitlab::GithubImport::Logger) + .to receive(:info) + .with( + message: 'GitHub project import finished', + import_stage: 'Gitlab::GithubImport::Stage::FinishImportWorker', + object_counts: { + 'fetched' => {}, + 'imported' => {} + }, + project_id: project.id, + duration_s: a_kind_of(Numeric) + ) worker.report_import_time(project) end