Automatic merge of gitlab-org/gitlab-ce master

app/controllers/graphql_controller.rb

@@ -30,6 +30,10 @@ class GraphqlController < ApplicationController
     render_error(exception.message, status: :unprocessable_entity)
   end
 
+  rescue_from Gitlab::Graphql::Errors::ArgumentError do |exception|
+    render_error(exception.message, status: :unprocessable_entity)
+  end
+
   private
 
   def execute_multiplex

changelogs/unreleased/an-sidekiq-scheduling_latency.yml

+---
+title: Adds Sidekiq scheduling latency structured logging field
+merge_request: 30784
+author:
+type: other

changelogs/unreleased/report-missing-job-dependency.yml

+---
+title: Default dependency job stage index to Infinity, and correctly report it as
+  undefined in prior stages
+merge_request: 31116
+author:
+type: fixed

lib/gitlab/ci/yaml_processor.rb

@@ -144,7 +144,9 @@ module Gitlab
         job[:dependencies].each do |dependency|
           raise ValidationError, "#{name} job: undefined dependency: #{dependency}" unless @jobs[dependency.to_sym]
 
-          unless @stages.index(@jobs[dependency.to_sym][:stage]) < stage_index
+          dependency_stage_index = @stages.index(@jobs[dependency.to_sym][:stage])
+
+          unless dependency_stage_index.present? && dependency_stage_index < stage_index
             raise ValidationError, "#{name} job: dependency #{dependency} is not defined in prior stages"
           end
         end

lib/gitlab/sidekiq_logging/structured_logger.rb

@@ -32,6 +32,12 @@ module Gitlab
         payload['message'] = "#{base_message(payload)}: start"
         payload['job_status'] = 'start'
 
+        # Old gitlab-shell messages don't provide enqueued_at/created_at attributes
+        enqueued_at = payload['enqueued_at'] || payload['created_at']
+        if enqueued_at
+          payload['scheduling_latency_s'] = elapsed(Time.iso8601(enqueued_at).to_f)
+        end
+
         payload
       end
 

spec/controllers/graphql_controller_spec.rb

@@ -7,6 +7,27 @@ describe GraphqlController do
     stub_feature_flags(graphql: true)
   end
 
+  describe 'ArgumentError' do
+    let(:user) { create(:user) }
+    let(:message) { 'green ideas sleep furiously' }
+
+    before do
+      sign_in(user)
+    end
+
+    it 'handles argument errors' do
+      allow(subject).to receive(:execute) do
+        raise Gitlab::Graphql::Errors::ArgumentError, message
+      end
+
+      post :execute
+
+      expect(json_response).to include(
+        'errors' => include(a_hash_including('message' => message))
+      )
+    end
+  end
+
   describe 'POST #execute' do
     context 'when user is logged in' do
       let(:user) { create(:user) }

spec/lib/gitlab/ci/yaml_processor_spec.rb

@@ -1085,6 +1085,31 @@ module Gitlab
 
           it { expect { subject }.to raise_error(Gitlab::Ci::YamlProcessor::ValidationError, 'test1 job: dependency deploy is not defined in prior stages') }
         end
+
+        context 'when a job depends on another job that references a not-yet defined stage' do
+          let(:config) do
+            {
+              "stages" => [
+                "version"
+              ],
+              "version" => {
+                "stage" => "version",
+                "dependencies" => ["release:components:versioning"],
+                "script" => ["./versioning/versioning"]
+              },
+              ".release_go" => {
+                "stage" => "build",
+                "script" => ["cd versioning"]
+              },
+              "release:components:versioning" => {
+                "stage" => "build",
+                "script" => ["cd versioning"]
+              }
+            }
+          end
+
+          it { expect { subject }.to raise_error(Gitlab::Ci::YamlProcessor::ValidationError, /is not defined in prior stages/) }
+        end
       end
 
       describe "Hidden jobs" do

spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb

@@ -2,7 +2,10 @@ require 'spec_helper'
 
 describe Gitlab::SidekiqLogging::StructuredLogger do
   describe '#call' do
-    let(:timestamp) { Time.new('2018-01-01 12:00:00').utc }
+    let(:timestamp) { Time.iso8601('2018-01-01T12:00:00Z') }
+    let(:created_at) { timestamp }
+    let(:scheduling_latency_s) { 0.0 }
+
     let(:job) do
       {
         "class" => "TestWorker",
@@ -11,19 +14,21 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
         "queue" => "cronjob:test_queue",
         "queue_namespace" => "cronjob",
         "jid" => "da883554ee4fe414012f5f42",
-        "created_at" => timestamp.to_f,
-        "enqueued_at" => timestamp.to_f,
+        "created_at" => created_at.to_f,
+        "enqueued_at" => created_at.to_f,
         "correlation_id" => 'cid'
       }
     end
+
     let(:logger) { double }
     let(:start_payload) do
       job.merge(
         'message' => 'TestWorker JID-da883554ee4fe414012f5f42: start',
         'job_status' => 'start',
         'pid' => Process.pid,
-        'created_at' => timestamp.iso8601(3),
-        'enqueued_at' => timestamp.iso8601(3)
+        'created_at' => created_at.iso8601(3),
+        'enqueued_at' => created_at.iso8601(3),
+        'scheduling_latency_s' => scheduling_latency_s
       )
     end
     let(:end_payload) do
@@ -118,6 +123,35 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
           subject.call(job, 'test_queue') { }
         end
       end
+
+      it 'logs without created_at and enqueued_at fields' do
+        Timecop.freeze(timestamp) do
+          excluded_fields = %w(created_at enqueued_at args scheduling_latency_s)
+
+          expect(logger).to receive(:info).with(start_payload.except(*excluded_fields)).ordered
+          expect(logger).to receive(:info).with(end_payload.except(*excluded_fields)).ordered
+          expect(subject).to receive(:log_job_start).and_call_original
+          expect(subject).to receive(:log_job_done).and_call_original
+
+          subject.call(job.except("created_at", "enqueued_at"), 'test_queue') { }
+        end
+      end
+    end
+
+    context 'with latency' do
+      let(:created_at) { Time.iso8601('2018-01-01T10:00:00Z') }
+      let(:scheduling_latency_s) { 7200.0 }
+
+      it 'logs with scheduling latency' do
+        Timecop.freeze(timestamp) do
+          expect(logger).to receive(:info).with(start_payload.except('args')).ordered
+          expect(logger).to receive(:info).with(end_payload.except('args')).ordered
+          expect(subject).to receive(:log_job_start).and_call_original
+          expect(subject).to receive(:log_job_done).and_call_original
+
+          subject.call(job, 'test_queue') { }
+        end
+      end
     end
   end
 end