Merge branch '251143-add-wait-time-to-job-webhook' into 'master'

Add `Job.queued_duration` to all API output formats

See merge request gitlab-org/gitlab!59901

app/graphql/types/ci/job_type.rb

@@ -23,7 +23,7 @@ module Types
       field :stage, Types::Ci::StageType, null: true,
             description: 'Stage of the job.'
       field :allow_failure, ::GraphQL::BOOLEAN_TYPE, null: false,
-            description: 'Whether this job is allowed to fail.'
+            description: 'Whether the job is allowed to fail.'
       field :duration, GraphQL::INT_TYPE, null: true,
             description: 'Duration of the job in seconds.'
       field :tags, [GraphQL::STRING_TYPE], null: true,
@@ -41,6 +41,12 @@ module Types
       field :scheduled_at, Types::TimeType, null: true,
             description: 'Schedule for the build.'
 
+      # Life-cycle durations:
+      field :queued_duration,
+            type: Types::DurationType,
+            null: true,
+            description: 'How long the job was enqueued before starting.'
+
       field :detailed_status, Types::Ci::DetailedStatusType, null: true,
             description: 'Detailed status of the job.'
       field :artifacts, Types::Ci::JobArtifactType.connection_type, null: true,

app/graphql/types/ci/pipeline_type.rb

@@ -39,6 +39,9 @@ module Types
       field :duration, GraphQL::INT_TYPE, null: true,
             description: 'Duration of the pipeline in seconds.'
 
+      field :queued_duration, Types::DurationType, null: true,
+            description: 'How long the pipeline was queued before starting.'
+
       field :coverage, GraphQL::FLOAT_TYPE, null: true,
             description: 'Coverage percentage.'
 

app/graphql/types/duration_type.rb

+# frozen_string_literal: true
+
+module Types
+  class DurationType < BaseScalar
+    graphql_name 'Duration'
+    description <<~DESC
+      Duration between two instants, represented as a fractional number of seconds.
+
+      For example: 12.3334
+    DESC
+
+    def self.coerce_input(value, ctx)
+      case value
+      when Float
+        value
+      when Integer
+        value.to_f
+      when NilClass
+        raise GraphQL::CoercionError, 'Cannot be nil'
+      else
+        raise GraphQL::CoercionError, "Expected number: got #{value.class}"
+      end
+    end
+
+    def self.coerce_result(value, ctx)
+      value.to_f
+    end
+  end
+end

app/models/ci/build.rb

@@ -1047,7 +1047,7 @@ module Ci
     end
 
     def build_data
-      @build_data ||= Gitlab::DataBuilder::Build.build(self)
+      strong_memoize(:build_data) { Gitlab::DataBuilder::Build.build(self) }
     end
 
     def successful_deployment_status

app/models/commit_status.rb

@@ -214,8 +214,14 @@ class CommitStatus < ApplicationRecord
     allow_failure? && (failed? || canceled?)
   end
 
+  # Time spent running.
   def duration
-    calculate_duration
+    calculate_duration(started_at, finished_at)
+  end
+
+  # Time spent in the pending state.
+  def queued_duration
+    calculate_duration(queued_at, started_at)
   end
 
   def latest?

app/models/concerns/ci/has_status.rb

@@ -122,12 +122,10 @@ module Ci
 
     private
 
-    def calculate_duration
-      if started_at && finished_at
-        finished_at - started_at
-      elsif started_at
-        Time.current - started_at
-      end
+    def calculate_duration(start_time, end_time)
+      return unless start_time
+
+      (end_time || Time.current) - start_time
     end
   end
 end

changelogs/unreleased/251143-add-wait-time-to-job-webhook.yml

+---
+title: Expose job and project queued duration in all APIs
+merge_request: 59901
+author:
+type: changed

doc/api/graphql/reference/index.md

@@ -7162,7 +7162,7 @@ Represents the total number of issues and their weights for a particular day.
 | Name | Type | Description |
 | ---- | ---- | ----------- |
 | <a id="cijobactive"></a>`active` | [`Boolean!`](#boolean) | Indicates the job is active. |
-| <a id="cijoballowfailure"></a>`allowFailure` | [`Boolean!`](#boolean) | Whether this job is allowed to fail. |
+| <a id="cijoballowfailure"></a>`allowFailure` | [`Boolean!`](#boolean) | Whether the job is allowed to fail. |
 | <a id="cijobartifacts"></a>`artifacts` | [`CiJobArtifactConnection`](#cijobartifactconnection) | Artifacts generated by the job. |
 | <a id="cijobcancelable"></a>`cancelable` | [`Boolean!`](#boolean) | Indicates the job can be canceled. |
 | <a id="cijobcommitpath"></a>`commitPath` | [`String`](#string) | Path to the commit that triggered the job. |
@@ -7179,6 +7179,7 @@ Represents the total number of issues and their weights for a particular day.
 | <a id="cijobpipeline"></a>`pipeline` | [`Pipeline`](#pipeline) | Pipeline the job belongs to. |
 | <a id="cijobplayable"></a>`playable` | [`Boolean!`](#boolean) | Indicates the job can be played. |
 | <a id="cijobqueuedat"></a>`queuedAt` | [`Time`](#time) | When the job was enqueued and marked as pending. |
+| <a id="cijobqueuedduration"></a>`queuedDuration` | [`Duration`](#duration) | How long the job was enqueued before starting. |
 | <a id="cijobrefname"></a>`refName` | [`String`](#string) | Ref name of the job. |
 | <a id="cijobrefpath"></a>`refPath` | [`String`](#string) | Path to the ref. |
 | <a id="cijobretryable"></a>`retryable` | [`Boolean!`](#boolean) | Indicates the job can be retried. |
@@ -10354,6 +10355,7 @@ Information about pagination in a connection.
 | <a id="pipelineiid"></a>`iid` | [`String!`](#string) | Internal ID of the pipeline. |
 | <a id="pipelinepath"></a>`path` | [`String`](#string) | Relative path to the pipeline's page. |
 | <a id="pipelineproject"></a>`project` | [`Project`](#project) | Project the pipeline belongs to. |
+| <a id="pipelinequeuedduration"></a>`queuedDuration` | [`Duration`](#duration) | How long the pipeline was queued before starting. |
 | <a id="pipelineretryable"></a>`retryable` | [`Boolean!`](#boolean) | Specifies if a pipeline can be retried. |
 | <a id="pipelinesecurityreportsummary"></a>`securityReportSummary` | [`SecurityReportSummary`](#securityreportsummary) | Vulnerability and scanned resource counts for each security scanner of the pipeline. |
 | <a id="pipelinesha"></a>`sha` | [`String!`](#string) | SHA of the pipeline's commit. |
@@ -14464,6 +14466,12 @@ A `DiscussionID` is a global ID. It is encoded as a string.
 
 An example `DiscussionID` is: `"gid://gitlab/Discussion/1"`.
 
+### `Duration`
+
+Duration between two instants, represented as a fractional number of seconds.
+
+For example: 12.3334.
+
 ### `EnvironmentID`
 
 A `EnvironmentID` is a global ID. It is encoded as a string.

doc/api/jobs.md

@@ -43,6 +43,7 @@ Example of response
     "started_at": "2015-12-24T17:54:27.722Z",
     "finished_at": "2015-12-24T17:54:27.895Z",
     "duration": 0.173,
+    "queued_duration": 0.010,
     "artifacts_file": {
       "filename": "artifacts.zip",
       "size": 1000
@@ -107,6 +108,7 @@ Example of response
     "started_at": "2015-12-24T17:54:24.729Z",
     "finished_at": "2015-12-24T17:54:24.921Z",
     "duration": 0.192,
+    "queued_duration": 0.023,
     "artifacts_expire_at": "2016-01-23T17:54:24.921Z",
     "tag_list": [
       "docker runner", "win10-2004"
@@ -187,6 +189,7 @@ Example of response
     "started_at": "2015-12-24T17:54:24.729Z",
     "finished_at": "2015-12-24T17:54:24.921Z",
     "duration": 0.192,
+    "queued_duration": 0.023,
     "artifacts_expire_at": "2016-01-23T17:54:24.921Z",
     "tag_list": [
       "docker runner", "ubuntu18"
@@ -241,6 +244,7 @@ Example of response
     "started_at": "2015-12-24T17:54:27.722Z",
     "finished_at": "2015-12-24T17:54:27.895Z",
     "duration": 0.173,
+    "queued_duration": 0.023,
     "artifacts_file": {
       "filename": "artifacts.zip",
       "size": 1000
@@ -339,6 +343,7 @@ Example of response
     "started_at": "2015-12-24T17:54:27.722Z",
     "finished_at": "2015-12-24T17:58:27.895Z",
     "duration": 240,
+    "queued_duration": 0.123,
     "id": 7,
     "name": "teaspoon",
     "pipeline": {
@@ -422,6 +427,7 @@ Example of response
   "started_at": "2015-12-24T17:54:30.733Z",
   "finished_at": "2015-12-24T17:54:31.198Z",
   "duration": 0.465,
+  "queued_duration": 0.123,
   "artifacts_expire_at": "2016-01-23T17:54:31.198Z",
   "id": 8,
   "name": "rubocop",
@@ -575,6 +581,7 @@ Example of response
   "started_at": "2015-12-24T17:54:30.733Z",
   "finished_at": "2015-12-24T17:54:31.198Z",
   "duration": 0.465,
+  "queued_duration": 0.010,
   "artifacts_expire_at": "2016-01-23T17:54:31.198Z",
   "tag_list": [
       "docker runner", "macos-10.15"
@@ -675,6 +682,7 @@ Example of response
   "started_at": "2016-01-11T10:14:09.526Z",
   "finished_at": null,
   "duration": 8,
+  "queued_duration": 0.010,
   "id": 42,
   "name": "rubocop",
   "ref": "master",
@@ -724,6 +732,7 @@ Example of response
   "started_at": null,
   "finished_at": null,
   "duration": null,
+  "queued_duration": 0.010,
   "id": 42,
   "name": "rubocop",
   "ref": "master",
@@ -784,6 +793,7 @@ Example of response
   "started_at": "2016-01-11T10:13:33.506Z",
   "finished_at": "2016-01-11T10:15:10.506Z",
   "duration": 97.0,
+  "queued_duration": 0.010,
   "status": "failed",
   "tag": false,
   "web_url": "https://example.com/foo/bar/-/jobs/42",
@@ -827,13 +837,14 @@ Example of response
   "started_at": null,
   "finished_at": null,
   "duration": null,
+  "queued_duration": 0.010,
   "id": 42,
   "name": "rubocop",
   "ref": "master",
   "artifacts": [],
   "runner": null,
   "stage": "test",
-  "status": "started",
+  "status": "pending",
   "tag": false,
   "web_url": "https://example.com/foo/bar/-/jobs/42",
   "user": null

doc/api/pipelines.md

@@ -117,7 +117,8 @@ Example of response
   "started_at": null,
   "finished_at": "2016-08-11T11:32:35.145Z",
   "committed_at": null,
-  "duration": null,
+  "duration": 123.65,
+  "queued_duration": 0.010,
   "coverage": "30.0",
   "web_url": "https://example.com/foo/bar/pipelines/46"
 }
@@ -254,6 +255,7 @@ Example of response
   "finished_at": null,
   "committed_at": null,
   "duration": null,
+  "queued_duration": 0.010,
   "coverage": null,
   "web_url": "https://example.com/foo/bar/pipelines/61"
 }
@@ -302,6 +304,7 @@ Response:
   "finished_at": "2016-08-11T11:32:35.145Z",
   "committed_at": null,
   "duration": null,
+  "queued_duration": 0.010,
   "coverage": null,
   "web_url": "https://example.com/foo/bar/pipelines/46"
 }
@@ -350,6 +353,7 @@ Response:
   "finished_at": "2016-08-11T11:32:35.145Z",
   "committed_at": null,
   "duration": null,
+  "queued_duration": 0.010,
   "coverage": null,
   "web_url": "https://example.com/foo/bar/pipelines/46"
 }

lib/api/entities/ci/job_basic.rb

@@ -6,7 +6,10 @@ module API
       class JobBasic < Grape::Entity
         expose :id, :status, :stage, :name, :ref, :tag, :coverage, :allow_failure
         expose :created_at, :started_at, :finished_at
-        expose :duration
+        expose :duration,
+               documentation: { type: 'Floating', desc: 'Time spent running' }
+        expose :queued_duration,
+               documentation: { type: 'Floating', desc: 'Time spent enqueued' }
         expose :user, with: ::API::Entities::User
         expose :commit, with: ::API::Entities::Commit
         expose :pipeline, with: ::API::Entities::Ci::PipelineBasic

lib/api/entities/ci/pipeline.rb

@@ -9,6 +9,7 @@ module API
         expose :user, with: Entities::UserBasic
         expose :created_at, :updated_at, :started_at, :finished_at, :committed_at
         expose :duration
+        expose :queued_duration
         expose :coverage
         expose :detailed_status, using: DetailedStatusEntity do |pipeline, options|
           pipeline.detailed_status(options[:current_user])

lib/gitlab/data_builder/build.rb

@@ -30,6 +30,7 @@ module Gitlab
           build_started_at: build.started_at,
           build_finished_at: build.finished_at,
           build_duration: build.duration,
+          build_queued_duration: build.queued_duration,
           build_allow_failure: build.allow_failure,
           build_failure_reason: build.failure_reason,
           pipeline_id: commit.id,

lib/gitlab/data_builder/pipeline.rb

@@ -31,6 +31,7 @@ module Gitlab
           created_at: pipeline.created_at,
           finished_at: pipeline.finished_at,
           duration: pipeline.duration,
+          queued_duration: pipeline.queued_duration,
           variables: pipeline.variables.map(&:hook_attrs)
         }
       end
@@ -59,6 +60,8 @@ module Gitlab
           created_at: build.created_at,
           started_at: build.started_at,
           finished_at: build.finished_at,
+          duration: build.duration,
+          queued_duration: build.queued_duration,
           when: build.when,
           manual: build.action?,
           allow_failure: build.allow_failure,

spec/fixtures/api/schemas/public_api/v4/job.json

@@ -12,6 +12,7 @@
     "started_at",
     "finished_at",
     "duration",
+    "queued_duration",
     "user",
     "commit",
     "pipeline",
@@ -34,6 +35,7 @@
     "started_at": { "type": ["null", "string"] },
     "finished_at": { "type": ["null", "string"] },
     "duration": { "type": ["null", "number"] },
+    "queued_duration": { "type": ["null", "number"] },
     "user": { "$ref": "user/basic.json" },
     "commit": {
       "oneOf": [

spec/graphql/types/ci/job_type_spec.rb

@@ -26,6 +26,7 @@ RSpec.describe Types::Ci::JobType do
       pipeline
       playable
       queued_at
+      queued_duration
       refName
       refPath
       retryable

spec/graphql/types/ci/pipeline_type_spec.rb

@@ -9,7 +9,8 @@ RSpec.describe Types::Ci::PipelineType do
 
   it 'contains attributes related to a pipeline' do
     expected_fields = %w[
-      id iid sha before_sha status detailed_status config_source duration
+      id iid sha before_sha status detailed_status config_source
+      duration queued_duration
       coverage created_at updated_at started_at finished_at committed_at
       stages user retryable cancelable jobs source_job job downstream
       upstream path project active user_permissions warnings commit_path uses_needs

spec/graphql/types/duration_type_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+RSpec.describe GitlabSchema.types['Duration'] do
+  let(:duration) { 17.minutes }
+
+  it 'presents information as a floating point number' do
+    expect(described_class.coerce_isolated_result(duration)).to eq(duration.to_f)
+  end
+
+  it 'accepts integers as input' do
+    expect(described_class.coerce_isolated_input(100)).to eq(100.0)
+  end
+
+  it 'accepts floats as input' do
+    expect(described_class.coerce_isolated_input(0.5)).to eq(0.5)
+  end
+
+  it 'rejects invalid input' do
+    expect { described_class.coerce_isolated_input('not valid') }
+      .to raise_error(GraphQL::CoercionError)
+  end
+
+  it 'rejects nil' do
+    expect { described_class.coerce_isolated_input(nil) }
+      .to raise_error(GraphQL::CoercionError)
+  end
+end

spec/lib/gitlab/data_builder/build_spec.rb

@@ -9,6 +9,10 @@ RSpec.describe Gitlab::DataBuilder::Build do
   let(:build) { create(:ci_build, :running, runner: runner, user: user) }
 
   describe '.build' do
+    around do |example|
+      travel_to(Time.current) { example.run }
+    end
+
     let(:data) do
       described_class.build(build)
     end
@@ -22,6 +26,8 @@ RSpec.describe Gitlab::DataBuilder::Build do
     it { expect(data[:build_created_at]).to eq(build.created_at) }
     it { expect(data[:build_started_at]).to eq(build.started_at) }
     it { expect(data[:build_finished_at]).to eq(build.finished_at) }
+    it { expect(data[:build_duration]).to eq(build.duration) }
+    it { expect(data[:build_queued_duration]).to eq(build.queued_duration) }
     it { expect(data[:build_allow_failure]).to eq(false) }
     it { expect(data[:build_failure_reason]).to eq(build.failure_reason) }
     it { expect(data[:project_id]).to eq(build.project.id) }

spec/models/ci/build_spec.rb

@@ -4679,25 +4679,30 @@ RSpec.describe Ci::Build do
   end
 
   describe '#execute_hooks' do
+    before do
+      build.clear_memoization(:build_data)
+    end
+
     context 'with project hooks' do
+      let(:build_data) { double(:BuildData, dup: double(:DupedData)) }
+
       before do
         create(:project_hook, project: project, job_events: true)
       end
 
-      it 'execute hooks' do
-        expect_any_instance_of(ProjectHook).to receive(:async_execute)
+      it 'calls project.execute_hooks(build_data, :job_hooks)' do
+        expect(::Gitlab::DataBuilder::Build)
+          .to receive(:build).with(build).and_return(build_data)
+        expect(build.project)
+          .to receive(:execute_hooks).with(build_data.dup, :job_hooks)
 
         build.execute_hooks
       end
     end
 
-    context 'without relevant project hooks' do
-      before do
-        create(:project_hook, project: project, job_events: false)
-      end
-
-      it 'does not execute a hook' do
-        expect_any_instance_of(ProjectHook).not_to receive(:async_execute)
+    context 'without project hooks' do
+      it 'does not call project.execute_hooks' do
+        expect(build.project).not_to receive(:execute_hooks)
 
         build.execute_hooks
       end
@@ -4708,8 +4713,10 @@ RSpec.describe Ci::Build do
         create(:service, active: true, job_events: true, project: project)
       end
 
-      it 'execute services' do
-        expect_any_instance_of(Service).to receive(:async_execute)
+      it 'executes services' do
+        allow_next_found_instance_of(Service) do |service|
+          expect(service).to receive(:async_execute)
+        end
 
         build.execute_hooks
       end
@@ -4720,8 +4727,10 @@ RSpec.describe Ci::Build do
         create(:service, active: true, job_events: false, project: project)
       end
 
-      it 'execute services' do
-        expect_any_instance_of(Service).not_to receive(:async_execute)
+      it 'does not execute services' do
+        allow_next_found_instance_of(Service) do |service|
+          expect(service).not_to receive(:async_execute)
+        end
 
         build.execute_hooks
       end

spec/models/commit_status_spec.rb

@@ -259,6 +259,40 @@ RSpec.describe CommitStatus do
     end
   end
 
+  describe '#queued_duration' do
+    subject { commit_status.queued_duration }
+
+    around do |example|
+      travel_to(Time.current) { example.run }
+    end
+
+    context 'when created, then enqueued, then started' do
+      before do
+        commit_status.queued_at = 30.seconds.ago
+        commit_status.started_at = 25.seconds.ago
+      end
+
+      it { is_expected.to eq(5.0) }
+    end
+
+    context 'when created but not yet enqueued' do
+      before do
+        commit_status.queued_at = nil
+      end
+
+      it { is_expected.to be_nil }
+    end
+
+    context 'when enqueued, but not started' do
+      before do
+        commit_status.queued_at = Time.current - 1.minute
+        commit_status.started_at = nil
+      end
+
+      it { is_expected.to eq(1.minute) }
+    end
+  end
+
   describe '.latest' do
     subject { described_class.latest.order(:id) }
 

spec/requests/api/ci/pipelines_spec.rb

@@ -362,6 +362,25 @@ RSpec.describe API::Ci::Pipelines do
         it do
           expect(response).to have_gitlab_http_status(:ok)
           expect(json_response).to be_an Array
+
+          expect(json_response).to all match a_hash_including(
+            'duration' => be_nil,
+            'queued_duration' => (be >= 0.0)
+          )
+        end
+      end
+
+      context 'when filtering to only running jobs' do
+        let(:query) { { 'scope' => 'running' } }
+
+        it do
+          expect(response).to have_gitlab_http_status(:ok)
+          expect(json_response).to be_an Array
+
+          expect(json_response).to all match a_hash_including(
+            'duration' => (be >= 0.0),
+            'queued_duration' => (be >= 0.0)
+          )
         end
       end
 

spec/requests/api/graphql/ci/job_spec.rb

@@ -5,6 +5,10 @@ require 'spec_helper'
 RSpec.describe 'Query.project(fullPath).pipelines.job(id)' do
   include GraphqlHelpers
 
+  around do |example|
+    travel_to(Time.current) { example.run }
+  end
+
   let_it_be(:user) { create_default(:user) }
   let_it_be(:project) { create(:project, :repository, :public) }
   let_it_be(:pipeline) { create(:ci_pipeline, project: project) }
@@ -35,13 +39,20 @@ RSpec.describe 'Query.project(fullPath).pipelines.job(id)' do
     let(:terminal_type) { 'CiJob' }
 
     it 'retrieves scalar fields' do
+      job_2.update!(
+        created_at: 40.seconds.ago,
+        queued_at: 32.seconds.ago,
+        started_at: 30.seconds.ago,
+        finished_at: 5.seconds.ago
+      )
       post_graphql(query, current_user: user)
 
       expect(graphql_data_at(*path)).to match a_hash_including(
         'id' => global_id_of(job_2),
         'name' => job_2.name,
         'allowFailure' => job_2.allow_failure,
-        'duration' => job_2.duration,
+        'duration' => 25,
+        'queuedDuration' => 2.0,
         'status' => job_2.status.upcase
       )
     end

spec/requests/api/graphql/ci/pipelines_spec.rb

@@ -8,6 +8,49 @@ RSpec.describe 'Query.project(fullPath).pipelines' do
   let_it_be(:project) { create(:project, :repository, :public) }
   let_it_be(:user) { create(:user) }
 
+  around do |example|
+    travel_to(Time.current) { example.run }
+  end
+
+  describe 'duration fields' do
+    let_it_be(:pipeline) do
+      create(:ci_pipeline, project: project)
+    end
+
+    let(:query_path) do
+      [
+        [:project, { full_path: project.full_path }],
+        [:pipelines],
+        [:nodes]
+      ]
+    end
+
+    let(:query) do
+      wrap_fields(query_graphql_path(query_path, 'queuedDuration duration'))
+    end
+
+    before do
+      pipeline.update!(
+        created_at: 1.minute.ago,
+        started_at: 55.seconds.ago
+      )
+      create(:ci_build, :success,
+             pipeline: pipeline,
+             started_at: 55.seconds.ago,
+             finished_at: 10.seconds.ago)
+      pipeline.update_duration
+      pipeline.save!
+
+      post_graphql(query, current_user: user)
+    end
+
+    it 'includes the duration fields' do
+      path = query_path.map(&:first)
+      expect(graphql_data_at(*path, :queued_duration)).to eq [5.0]
+      expect(graphql_data_at(*path, :duration)).to eq [45]
+    end
+  end
+
   describe '.jobs' do
     let(:first_n) { var('Int') }
     let(:query_path) do