Commit 664aea24 authored by Bob Van Landuyt's avatar Bob Van Landuyt 💬
Browse files

Merge branch 'feat-covered-experience-logs' into 'master'

feat: Covered Experience logging

See merge request !168

Merged-by: Bob Van Landuyt's avatarBob Van Landuyt <bob@gitlab.com>
Approved-by: Bob Van Landuyt's avatarBob Van Landuyt <bob@gitlab.com>
Reviewed-by: Bob Van Landuyt's avatarBob Van Landuyt <bob@gitlab.com>
Reviewed-by: Hercules Merscher's avatarHercules Merscher <hmerscher@gitlab.com>
Co-authored-by: Hercules Merscher's avatarHercules Merscher <hmerscher@gitlab.com>
parents 98c2897d f7677ed6
Loading
Loading
Loading
Loading
Loading
+1 −0
Original line number Diff line number Diff line
@@ -5,6 +5,7 @@ require "securerandom"
require "active_support/core_ext/module/delegation"
require "active_support/core_ext/string/starts_ends_with"
require "active_support/core_ext/string/inflections"
require "active_support/core_ext/object/blank"

module Labkit
  # A context can be used to provide structured information on what resources
+22 −0
Original line number Diff line number Diff line
@@ -4,6 +4,7 @@ require 'labkit/covered_experience/error'
require 'labkit/covered_experience/experience'
require 'labkit/covered_experience/null'
require 'labkit/covered_experience/registry'
require 'labkit/logging/json_logger'

module Labkit
  # Labkit::CoveredExperience namespace module.
@@ -12,7 +13,28 @@ module Labkit
  # specific events or activities within the application that are measured
  # and reported for performance monitoring and analysis.
  module CoveredExperience
    # Configuration class for CoveredExperience
    class Configuration
      attr_accessor :logger

      def initialize
        @logger = Labkit::Logging::JsonLogger.new($stdout)
      end
    end

    class << self
      def configuration
        @configuration ||= Configuration.new
      end

      def reset_configuration
        @configuration = nil
      end

      def configure
        yield(configuration) if block_given?
      end

      def registry
        @registry ||= Registry.new
      end
+14 −0
Original line number Diff line number Diff line
@@ -4,6 +4,20 @@ This module covers the definition for Covered Experiences, as described in the [

## Configuration

### Logger Configuration

By default, `Labkit::CoveredExperience` uses `Labkit::Logging::JsonLogger.new($stdout)` for logging. You can configure a custom logger:

```ruby
Labkit::CoveredExperience.configure do |config|
  config.logger = Labkit::Logging::JsonLogger.new($stdout)
end
```

This configuration affects all Covered Experience instances and their logging output.

### Covered Experience Definitions

Covered experience definitions will be lazy loaded from the default directory (`config/covered_experiences`).

Create a new covered experience file in the registry directory, e.g. config/covered_experiences/merge_request_creation.yaml
+56 −10
Original line number Diff line number Diff line
# frozen_string_literal: true

require 'labkit/logging/json_logger'
require 'labkit/context'
require 'labkit/covered_experience/error'

module Labkit
@@ -24,6 +24,7 @@ module Labkit
      # Start the Covered Experience.
      #
      # @yield [self] When a block is provided, the experience will be completed automatically.
      # @param extra [Hash] Additional data to include in the log event
      # @return [self]
      # @raise [CoveredExperienceError] If the block raises an error.
      #
@@ -38,9 +39,10 @@ module Labkit
      #  experience.start
      #  experience.checkpoint
      #  experience.complete
      def start
        @started = Time.now.utc
      def start(**extra, &)
        @start_time = Time.now.utc
        checkpoint_counter.increment(checkpoint: "start")
        log_event("start", **extra)

        return self unless block_given?

@@ -51,34 +53,40 @@ module Labkit
          error!(e)
          raise
        ensure
          complete
          complete(**extra)
        end
      end

      # Checkpoint the Covered Experience.
      #
      # @param extra [Hash] Additional data to include in the log event
      # @raise [UnstartedError] If the experience has not been started and RAILS_ENV is development or test.
      # @return [self]
      def checkpoint
      def checkpoint(**extra)
        return unless ensure_started!

        @checkpoint_time = Time.now.utc
        checkpoint_counter.increment(checkpoint: "intermediate")
        log_event("intermediate", **extra)

        self
      end

      # Complete the Covered Experience.
      #
      # @param extra [Hash] Additional data to include in the log event
      # @raise [UnstartedError] If the experience has not been started and RAILS_ENV is development or test.
      # @return [self]
      def complete
      def complete(**extra)
        return unless ensure_started!

        begin
          elapsed = Time.now.utc - @started
          @end_time = Time.now.utc
        ensure
          checkpoint_counter.increment(checkpoint: "end")
          total_counter.increment(error: has_error?)
          apdex_counter.increment(success: elapsed <= urgency_threshold) unless has_error?
          apdex_counter.increment(success: apdex_success?) unless has_error?
          log_event("end", **extra)
        end

        self
@@ -104,7 +112,7 @@ module Labkit
      end

      def ensure_started!
        return @started unless @started.nil?
        return @start_time unless @start_time.nil?

        err = UnstartedError.new("Covered Experience #{@definition.covered_experience} not started")

@@ -116,6 +124,15 @@ module Labkit
        URGENCY_THRESHOLDS_IN_SECONDS[@definition.urgency.to_sym]
      end

      def elapsed_time
        last_time = @end_time || @checkpoint_time || @start_time
        last_time - @start_time
      end

      def apdex_success?
        elapsed_time <= urgency_threshold
      end

      def checkpoint_counter
        @checkpoint_counter ||= Labkit::Metrics::Client.counter(
          :gitlab_covered_experience_checkpoint_total,
@@ -140,12 +157,41 @@ module Labkit
        )
      end

      def log_event(event_type, **extra)
        log_data = build_log_data(event_type, **extra)
        logger.info(log_data)
      end

      def build_log_data(event_type, **extra)
        log_data = {
          checkpoint: event_type,
          covered_experience: @definition.covered_experience,
          feature_category: @definition.feature_category,
          urgency: @definition.urgency,
          start_time: @start_time,
          checkpoint_time: @checkpoint_time,
          end_time: @end_time,
          elapsed_time_s: elapsed_time,
          urgency_threshold_s: urgency_threshold
        }
        log_data.merge!(extra) if extra

        if has_error?
          log_data[:error] = true
          log_data[:error_message] = @error.inspect
        end

        log_data.compact!

        log_data
      end

      def warn(exception)
        logger.warn(component: self.class.name, message: exception.message)
      end

      def logger
        @logger ||= Labkit::Logging::JsonLogger.new($stdout)
        Labkit::CoveredExperience.configuration.logger
      end
    end
  end
+1 −2
Original line number Diff line number Diff line
@@ -4,7 +4,6 @@ require 'forwardable'
require 'json-schema'
require 'pathname'
require 'yaml'
require 'labkit/logging/json_logger'

module Labkit
  module CoveredExperience
@@ -99,7 +98,7 @@ module Labkit
      end

      def logger
        @logger ||= Labkit::Logging::JsonLogger.new($stdout)
        Labkit::CoveredExperience.configuration.logger
      end
    end
  end
Loading