Add CI build trace sections extractor

app/models/ci/build.rb

@@ -11,6 +11,7 @@ module Ci
     has_many :deployments, as: :deployable
     has_one :last_deployment, -> { order('deployments.id DESC') }, as: :deployable, class_name: 'Deployment'
+    has_many :trace_sections, class_name: 'Ci::BuildTraceSection'
     # The "environment" field for builds is a String, and is the unexpanded name
     def persisted_environment
@@ -265,6 +266,27 @@ module Ci
       update_attributes(coverage: coverage) if coverage.present?
     end
+    def parse_trace_sections!
+      return false unless trace_sections.empty?
+
+      sections = trace.extract_sections.map do |attr|
+        name = attr.delete(:name)
+        name_record = begin
+                        project.build_trace_section_names.find_or_create_by!(name: name)
+                      rescue ActiveRecord::RecordInvalid
+                        project.build_trace_section_names.find_by!(name: name)
+                      end
+
+        attr.merge(
+          build_id: self.id,
+          project_id: self.project_id,
+          section_name_id: name_record.id)
+      end
+
+      Gitlab::Database.bulk_insert(Ci::BuildTraceSection.table_name, sections)
+      true
+    end
+
     def trace
       Gitlab::Ci::Trace.new(self)
     end

app/models/ci/build_trace_section.rb

+module Ci
+  class BuildTraceSection < ActiveRecord::Base
+    extend Gitlab::Ci::Model
+
+    belongs_to :build, class_name: 'Ci::Build'
+    belongs_to :project
+    belongs_to :section_name, class_name: 'Ci::BuildTraceSectionName'
+
+    validates :section_name, :build, :project, presence: true, allow_blank: false
+  end
+end

app/models/ci/build_trace_section_name.rb

+module Ci
+  class BuildTraceSectionName < ActiveRecord::Base
+    extend Gitlab::Ci::Model
+
+    belongs_to :project
+    has_many :trace_sections, class_name: 'Ci::BuildTraceSection', foreign_key: :section_name_id
+
+    validates :name, :project, presence: true, allow_blank: false
+    validates :name, uniqueness: { scope: :project_id }
+  end
+end

app/models/project.rb

@@ -179,6 +179,7 @@ class Project < ActiveRecord::Base
   # bulk that doesn't involve loading the rows into memory. As a result we're
   # still using `dependent: :destroy` here.
   has_many :builds, class_name: 'Ci::Build', dependent: :destroy # rubocop:disable Cop/ActiveRecordDependent
+  has_many :build_trace_section_names, class_name: 'Ci::BuildTraceSectionName'
   has_many :runner_projects, class_name: 'Ci::RunnerProject'
   has_many :runners, through: :runner_projects, source: :runner, class_name: 'Ci::Runner'
   has_many :variables, class_name: 'Ci::Variable'

app/workers/build_finished_worker.rb

@@ -6,6 +6,7 @@ class BuildFinishedWorker
   def perform(build_id)
     Ci::Build.find_by(id: build_id).try do |build|
+      BuildTraceSectionsWorker.perform_async(build.id)
       BuildCoverageWorker.new.perform(build.id)
       BuildHooksWorker.new.perform(build.id)
     end

app/workers/build_trace_sections_worker.rb

+class BuildTraceSectionsWorker
+  include Sidekiq::Worker
+  include PipelineQueue
+
+  def perform(build_id)
+    Ci::Build.find_by(id: build_id)&.parse_trace_sections!
+  end
+end

changelogs/unreleased/37970-ci-sections-tracking.yml

+---
+title: Parse and store gitlab-runner timestamped section markers
+merge_request: 14551
+author:
+type: added

db/migrate/20170926102201_create_ci_build_trace_sections.rb

+class CreateCiBuildTraceSections < ActiveRecord::Migration
+  include Gitlab::Database::MigrationHelpers
+
+  DOWNTIME = false
+
+  def change
+    create_table :ci_build_trace_sections do |t|
+      t.datetime_with_timezone :date_start, null: false
+      t.datetime_with_timezone :date_end, null: false
+      t.integer :byte_start, limit: 8, null: false
+      t.integer :byte_end, limit: 8, null: false
+      t.references :project, null: false, index: true, foreign_key: { on_delete: :cascade }
+      t.integer :build_id, null: false
+      t.integer :section_name_id, null: false
+    end
+
+    add_index :ci_build_trace_sections, [:build_id, :section_name_id], unique: true
+  end
+end

db/migrate/20170926134436_add_build_foreign_key_to_ci_build_trace_sections.rb

+class AddBuildForeignKeyToCiBuildTraceSections < ActiveRecord::Migration
+  include Gitlab::Database::MigrationHelpers
+
+  DOWNTIME = false
+
+  disable_ddl_transaction!
+
+  def up
+    add_concurrent_foreign_key(:ci_build_trace_sections, :ci_builds, column: :build_id)
+  end
+
+  def down
+    remove_foreign_key(:ci_build_trace_sections, column: :build_id)
+  end
+end

db/migrate/20170929123651_create_ci_build_trace_section_names.rb

+class CreateCiBuildTraceSectionNames < ActiveRecord::Migration
+  include Gitlab::Database::MigrationHelpers
+
+  DOWNTIME = false
+
+  def up
+    create_table :ci_build_trace_section_names do |t|
+      t.references :project, null: false, foreign_key: { on_delete: :cascade }
+      t.string :name, null: false
+    end
+
+    add_index :ci_build_trace_section_names, [:project_id, :name], unique: true
+  end
+
+  def down
+    remove_foreign_key :ci_build_trace_section_names, column: :project_id
+    drop_table :ci_build_trace_section_names
+  end
+end

db/migrate/20170929123915_add_name_foreign_key_to_ci_build_trace_sections.rb

+class AddNameForeignKeyToCiBuildTraceSections < ActiveRecord::Migration
+  include Gitlab::Database::MigrationHelpers
+
+  DOWNTIME = false
+
+  disable_ddl_transaction!
+
+  def up
+    add_concurrent_foreign_key(:ci_build_trace_sections, :ci_build_trace_section_names, column: :section_name_id)
+  end
+
+  def down
+    remove_foreign_key(:ci_build_trace_sections, column: :section_name_id)
+  end
+end

db/schema.rb

@@ -207,6 +207,26 @@ ActiveRecord::Schema.define(version: 20171004121444) do
   add_index "chat_teams", ["namespace_id"], name: "index_chat_teams_on_namespace_id", unique: true, using: :btree
+  create_table "ci_build_trace_section_names", force: :cascade do |t|
+    t.integer "project_id", null: false
+    t.string "name", null: false
+  end
+
+  add_index "ci_build_trace_section_names", ["project_id", "name"], name: "index_ci_build_trace_section_names_on_project_id_and_name", unique: true, using: :btree
+
+  create_table "ci_build_trace_sections", force: :cascade do |t|
+    t.datetime_with_timezone "date_start", null: false
+    t.datetime_with_timezone "date_end", null: false
+    t.integer "byte_start", limit: 8, null: false
+    t.integer "byte_end", limit: 8, null: false
+    t.integer "project_id", null: false
+    t.integer "build_id", null: false
+    t.integer "section_name_id", null: false
+  end
+
+  add_index "ci_build_trace_sections", ["build_id", "section_name_id"], name: "index_ci_build_trace_sections_on_build_id_and_section_name_id", unique: true, using: :btree
+  add_index "ci_build_trace_sections", ["project_id"], name: "index_ci_build_trace_sections_on_project_id", using: :btree
+
   create_table "ci_builds", force: :cascade do |t|
     t.string "status"
     t.datetime "finished_at"
@@ -1697,6 +1717,10 @@ ActiveRecord::Schema.define(version: 20171004121444) do
   add_foreign_key "boards", "projects", name: "fk_f15266b5f9", on_delete: :cascade
   add_foreign_key "chat_teams", "namespaces", on_delete: :cascade
+  add_foreign_key "ci_build_trace_section_names", "projects", on_delete: :cascade
+  add_foreign_key "ci_build_trace_sections", "ci_build_trace_section_names", column: "section_name_id", name: "fk_264e112c66", on_delete: :cascade
+  add_foreign_key "ci_build_trace_sections", "ci_builds", column: "build_id", name: "fk_4ebe41f502", on_delete: :cascade
+  add_foreign_key "ci_build_trace_sections", "projects", on_delete: :cascade
   add_foreign_key "ci_builds", "ci_pipelines", column: "auto_canceled_by_id", name: "fk_a2141b1522", on_delete: :nullify
   add_foreign_key "ci_builds", "ci_stages", column: "stage_id", name: "fk_3a9eaa254d", on_delete: :cascade
   add_foreign_key "ci_builds", "projects", name: "fk_befce0568a", on_delete: :cascade

lib/gitlab/ci/ansi2html.rb

@@ -155,7 +155,7 @@ module Gitlab
           stream.each_line do |line|
             s = StringScanner.new(line)
             until s.eos?
-              if s.scan(/section_((?:start)|(?:end)):(\d+):([^\r]+)\r\033\[0K/)
+              if s.scan(Gitlab::Regex.build_trace_section_regex)
                 handle_section(s)
               elsif s.scan(/\e([@-_])(.*?)([@-~])/)
                 handle_sequence(s)

lib/gitlab/ci/trace.rb

@@ -27,6 +27,12 @@ module Gitlab
         end
       end
+      def extract_sections
+        read do |stream|
+          stream.extract_sections
+        end
+      end
+
       def set(data)
         write do |stream|
           data = job.hide_secrets(data)

lib/gitlab/ci/trace/section_parser.rb

+module Gitlab
+  module Ci
+    class Trace
+      class SectionParser
+        def initialize(lines)
+          @lines = lines
+        end
+
+        def parse!
+          @markers = {}
+
+          @lines.each do |line, pos|
+            parse_line(line, pos)
+          end
+        end
+
+        def sections
+          sanitize_markers.map do |name, markers|
+            start_, end_ = markers
+
+            {
+              name: name,
+              byte_start: start_[:marker],
+              byte_end: end_[:marker],
+              date_start: start_[:timestamp],
+              date_end: end_[:timestamp]
+            }
+          end
+        end
+
+        private
+
+        def parse_line(line, line_start_position)
+          s = StringScanner.new(line)
+          until s.eos?
+            find_next_marker(s) do |scanner|
+              marker_begins_at = line_start_position + scanner.pointer
+
+              if scanner.scan(Gitlab::Regex.build_trace_section_regex)
+                marker_ends_at = line_start_position + scanner.pointer
+                handle_line(scanner[1], scanner[2].to_i, scanner[3], marker_begins_at, marker_ends_at)
+                true
+              else
+                false
+              end
+            end
+          end
+        end
+
+        def sanitize_markers
+          @markers.select do |_, markers|
+            markers.size == 2 && markers[0][:action] == :start && markers[1][:action] == :end
+          end
+        end
+
+        def handle_line(action, time, name, marker_start, marker_end)
+          action = action.to_sym
+          timestamp = Time.at(time).utc
+          marker = if action == :start
+                     marker_end
+                   else
+                     marker_start
+                   end
+
+          @markers[name] ||= []
+          @markers[name] << {
+            name: name,
+            action: action,
+            timestamp: timestamp,
+            marker: marker
+          }
+        end
+
+        def beginning_of_section_regex
+          @beginning_of_section_regex ||= /section_/.freeze
+        end
+
+        def find_next_marker(s)
+          beginning_of_section_len = 8
+          maybe_marker = s.exist?(beginning_of_section_regex)
+
+          if maybe_marker.nil?
+            s.terminate
+          else
+            # repositioning at the beginning of the match
+            s.pos += maybe_marker - beginning_of_section_len
+            if block_given?
+              good_marker = yield(s)
+              # if not a good marker: Consuming the matched beginning_of_section_regex
+              s.pos += beginning_of_section_len unless good_marker
+            end
+          end
+        end
+      end
+    end
+  end
+end

lib/gitlab/ci/trace/stream.rb

@@ -90,8 +90,25 @@ module Gitlab
           # so we just silently ignore error for now
         end
+        def extract_sections
+          return [] unless valid?
+
+          lines = to_enum(:each_line_with_pos)
+          parser = SectionParser.new(lines)
+
+          parser.parse!
+          parser.sections
+        end
+
         private
+        def each_line_with_pos
+          stream.seek(0, IO::SEEK_SET)
+          stream.each_line do |line|
+            yield [line, stream.pos - line.bytesize]
+          end
+        end
+
         def read_last_lines(limit)
           to_enum(:reverse_line).first(limit).reverse.join
         end

lib/gitlab/regex.rb

@@ -65,5 +65,9 @@ module Gitlab
       "can contain only lowercase letters, digits, and '-'. " \
       "Must start with a letter, and cannot end with '-'"
     end
+
+    def build_trace_section_regex
+      @build_trace_section_regexp ||= /section_((?:start)|(?:end)):(\d+):([^\r]+)\r\033\[0K/.freeze
+    end
   end
 end

spec/factories/ci/build_trace_section_names.rb

+FactoryGirl.define do
+  factory :ci_build_trace_section_name, class: Ci::BuildTraceSectionName do
+    sequence(:name) { |n| "section_#{n}" }
+    project factory: :project
+  end
+end

spec/fixtures/trace/trace_with_sections

+Running with gitlab-runner dev (HEAD)
+  on kitsune minikube (a21b584f)
+WARNING: Namespace is empty, therefore assuming 'default'.
+Using Kubernetes namespace: default
+Using Kubernetes executor with image alpine:3.4 ...
+section_start:1506004954:prepare_script
Waiting for pod default/runner-a21b584f-project-1208199-concurrent-0sg03f to be running, status is Pending
+Running on runner-a21b584f-project-1208199-concurrent-0sg03f via kitsune.local...
+section_end:1506004957:prepare_script
section_start:1506004957:get_sources
Cloning repository...
+Cloning into '/nolith/ci-tests'...
+Checking out dddd7a6e as master...
+Skipping Git submodules setup
+section_end:1506004958:get_sources
section_start:1506004958:restore_cache
section_end:1506004958:restore_cache
section_start:1506004958:download_artifacts
section_end:1506004958:download_artifacts
section_start:1506004958:build_script
$ whoami
+root
+section_end:1506004959:build_script
section_start:1506004959:after_script
section_end:1506004959:after_script
section_start:1506004959:archive_cache
section_end:1506004959:archive_cache
section_start:1506004959:upload_artifacts
section_end:1506004959:upload_artifacts
Job succeeded
+

spec/lib/gitlab/ci/trace/section_parser_spec.rb

+require 'spec_helper'
+
+describe Gitlab::Ci::Trace::SectionParser do
+  def lines_with_pos(text)
+    pos = 0
+    StringIO.new(text).each_line do |line|
+      yield line, pos
+      pos += line.bytesize + 1 # newline
+    end
+  end
+
+  def build_lines(text)
+    to_enum(:lines_with_pos, text)
+  end
+
+  def section(name, start, duration, text)
+    end_ = start + duration
+    "section_start:#{start.to_i}:#{name}\r\033[0K#{text}section_end:#{end_.to_i}:#{name}\r\033[0K"
+  end
+
+  let(:lines) { build_lines('') }
+  subject { described_class.new(lines) }
+
+  describe '#sections' do
+    before do
+      subject.parse!
+    end
+
+    context 'empty trace' do
+      let(:lines) { build_lines('') }
+
+      it { expect(subject.sections).to be_empty }
+    end
+
+    context 'with a sectionless trace' do
+      let(:lines) { build_lines("line 1\nline 2\n") }
+
+      it { expect(subject.sections).to be_empty }
+    end
+
+    context 'with trace markers' do
+      let(:start_time) { Time.new(2017, 10, 5).utc }
+      let(:section_b_duration) { 1.second }
+      let(:section_a) { section('a', start_time, 0, 'a line') }
+      let(:section_b) { section('b', start_time, section_b_duration, "another line\n") }
+      let(:lines) { build_lines(section_a + section_b) }
+
+      it { expect(subject.sections.size).to eq(2) }
+      it { expect(subject.sections[1][:name]).to eq('b') }
+      it { expect(subject.sections[1][:date_start]).to eq(start_time) }
+      it { expect(subject.sections[1][:date_end]).to eq(start_time + section_b_duration) }
+    end
+  end
+
+  describe '#parse!' do
+    context 'multiple "section_" but no complete markers' do
+      let(:lines) { build_lines('section_section_section_') }
+
+      it 'must find 3 possible section start but no complete sections' do
+        expect(subject).to receive(:find_next_marker).exactly(3).times.and_call_original
+
+        subject.parse!
+
+        expect(subject.sections).to be_empty
+      end
+    end
+
+    context 'trace with UTF-8 chars' do
+      let(:line) { 'GitLab ❤️ 狸 (tanukis)\n' }
+      let(:trace) { section('test_section', Time.new(2017, 10, 5).utc, 3.seconds, line) }
+      let(:lines) { build_lines(trace) }
+
+      it 'must handle correctly byte positioning' do
+        expect(subject).to receive(:find_next_marker).exactly(2).times.and_call_original
+
+        subject.parse!
+
+        sections = subject.sections
+
+        expect(sections.size).to eq(1)
+        s = sections[0]
+        len = s[:byte_end] - s[:byte_start]
+        expect(trace.byteslice(s[:byte_start], len)).to eq(line)
+      end
+    end
+  end
+end