Merge branch '349968-log-linter' into 'master'

Log CI linter times

See merge request gitlab-org/gitlab!80593

lib/gitlab/ci/lint.rb

@@ -18,6 +18,8 @@ module Gitlab
         end
       end
 
+      LOG_MAX_DURATION_THRESHOLD = 2.seconds
+
       def initialize(project:, current_user:, sha: nil)
         @project = project
         @current_user = current_user
@@ -49,12 +51,9 @@ module Gitlab
       end
 
       def static_validation(content)
-        result = Gitlab::Ci::YamlProcessor.new(
-          content,
-          project: @project,
-          user: @current_user,
-          sha: @sha
-        ).execute
+        logger = build_logger
+
+        result = yaml_processor_result(content, logger)
 
         Result.new(
           jobs: static_validation_convert_to_jobs(result),
@@ -62,6 +61,17 @@ module Gitlab
           errors: result.errors,
           warnings: result.warnings.take(::Gitlab::Ci::Warnings::MAX_LIMIT) # rubocop: disable CodeReuse/ActiveRecord
         )
+      ensure
+        logger.commit(pipeline: ::Ci::Pipeline.new, caller: self.class.name)
+      end
+
+      def yaml_processor_result(content, logger)
+        logger.instrument(:yaml_process) do
+          Gitlab::Ci::YamlProcessor.new(content, project: @project,
+                                                 user: @current_user,
+                                                 sha: @sha,
+                                                 logger: logger).execute
+        end
       end
 
       def dry_run_convert_to_jobs(stages)
@@ -109,6 +119,17 @@ module Gitlab
 
         jobs
       end
+
+      def build_logger
+        Gitlab::Ci::Pipeline::Logger.new(project: @project) do |l|
+          l.log_when do |observations|
+            values = observations['yaml_process_duration_s']
+            next false if values.empty?
+
+            values.max >= LOG_MAX_DURATION_THRESHOLD
+          end
+        end
+      end
     end
   end
 end

lib/gitlab/ci/pipeline/logger.rb

@@ -59,7 +59,7 @@ module Gitlab
           attributes = {
             class: self.class.name.to_s,
             pipeline_creation_caller: caller,
-            project_id: project.id,
+            project_id: project&.id, # project is not available when called from `/ci/lint`
             pipeline_persisted: pipeline.persisted?,
             pipeline_source: pipeline.source,
             pipeline_creation_service_duration_s: age

spec/lib/gitlab/ci/lint_spec.rb

@@ -322,4 +322,102 @@ RSpec.describe Gitlab::Ci::Lint do
       end
     end
   end
+
+  context 'pipeline logger' do
+    let(:counters) do
+      {
+        'count' => a_kind_of(Numeric),
+        'avg'   => a_kind_of(Numeric),
+        'max'   => a_kind_of(Numeric),
+        'min'   => a_kind_of(Numeric)
+      }
+    end
+
+    let(:loggable_data) do
+      {
+        'class' => 'Gitlab::Ci::Pipeline::Logger',
+        'config_build_context_duration_s' => counters,
+        'config_build_variables_duration_s' => counters,
+        'config_compose_duration_s' => counters,
+        'config_expand_duration_s' => counters,
+        'config_external_process_duration_s' => counters,
+        'config_stages_inject_duration_s' => counters,
+        'config_tags_resolve_duration_s' => counters,
+        'config_yaml_extend_duration_s' => counters,
+        'config_yaml_load_duration_s' => counters,
+        'pipeline_creation_caller' => 'Gitlab::Ci::Lint',
+        'pipeline_creation_service_duration_s' => a_kind_of(Numeric),
+        'pipeline_persisted' => false,
+        'pipeline_source' => 'unknown',
+        'project_id' => project&.id,
+        'yaml_process_duration_s' => counters
+      }
+    end
+
+    let(:content) do
+      <<~YAML
+      build:
+        script: echo
+      YAML
+    end
+
+    subject(:validate) { lint.validate(content, dry_run: false) }
+
+    before do
+      project&.add_developer(user)
+    end
+
+    context 'when the duration is under the threshold' do
+      it 'does not create a log entry' do
+        expect(Gitlab::AppJsonLogger).not_to receive(:info)
+
+        validate
+      end
+    end
+
+    context 'when the durations exceeds the threshold' do
+      let(:timer) do
+        proc do
+          @timer = @timer.to_i + 30
+        end
+      end
+
+      before do
+        allow(Gitlab::Ci::Pipeline::Logger)
+          .to receive(:current_monotonic_time) { timer.call }
+      end
+
+      it 'creates a log entry' do
+        expect(Gitlab::AppJsonLogger).to receive(:info).with(loggable_data)
+
+        validate
+      end
+
+      context 'when the feature flag is disabled' do
+        before do
+          stub_feature_flags(ci_pipeline_creation_logger: false)
+        end
+
+        it 'does not create a log entry' do
+          expect(Gitlab::AppJsonLogger).not_to receive(:info)
+
+          validate
+        end
+      end
+
+      context 'when project is not provided' do
+        let(:project) { nil }
+
+        let(:project_nil_loggable_data) do
+          loggable_data.except('project_id')
+        end
+
+        it 'creates a log entry without project_id' do
+          expect(Gitlab::AppJsonLogger).to receive(:info).with(project_nil_loggable_data)
+
+          validate
+        end
+      end
+    end
+  end
 end

spec/lib/gitlab/ci/pipeline/logger_spec.rb

@@ -203,6 +203,35 @@ RSpec.describe ::Gitlab::Ci::Pipeline::Logger do
           expect(commit).to be_truthy
         end
       end
+
+      context 'when project is not passed and pipeline is not persisted' do
+        let(:project) {}
+        let(:pipeline) { build(:ci_pipeline) }
+
+        let(:loggable_data) do
+          {
+            'class' => described_class.name.to_s,
+            'pipeline_persisted' => false,
+            'pipeline_creation_service_duration_s' => a_kind_of(Numeric),
+            'pipeline_creation_caller' => 'source',
+            'pipeline_save_duration_s' => {
+              'avg' => 60, 'count' => 1, 'max' => 60, 'min' => 60
+            },
+            'pipeline_creation_duration_s' => {
+              'avg' => 20, 'count' => 2, 'max' => 30, 'min' => 10
+            }
+          }
+        end
+
+        it 'logs to application.json' do
+          expect(Gitlab::AppJsonLogger)
+            .to receive(:info)
+            .with(a_hash_including(loggable_data))
+            .and_call_original
+
+          expect(commit).to be_truthy
+        end
+      end
     end
 
     context 'when the feature flag is disabled' do