Commit eb80ca99 authored by Peter Leitzen's avatar Peter Leitzen
Browse files

Merge branch 'dbarrett/field_validator' into 'master'

Implement field validator for logging standardization

Closes gitlab-org/quality/quality-engineering/team-tasks#4094

See merge request !213

Merged-by: default avatarPeter Leitzen <pleitzen@gitlab.com>
Approved-by: default avatarPeter Leitzen <pleitzen@gitlab.com>
Reviewed-by: Bob Van Landuyt's avatarBob Van Landuyt <bob@gitlab.com>
Reviewed-by: default avatarPeter Leitzen <pleitzen@gitlab.com>
Reviewed-by: default avatarGitLab Duo <gitlab-duo@gitlab.com>
Co-authored-by: default avatardbarrett <dbarrett@gitlab.com>
parents 52f77a47 5ba33c34
Loading
Loading
Loading
Loading
Loading
+249 −0
Original line number Diff line number Diff line
# LabKit Field Standardization

## Overview

The LabKit Field Validator detects when your code uses deprecated logging field names and helps you migrate to standardized fields. This supports the [Observability Field Standardisation initiative](https://handbook.gitlab.com/handbook/engineering/architecture/design-documents/observability_field_standardisation/).

**Goal:** Standardize logging field names across GitLab so logs are queryable and actionable across all systems.

**How it works:** The validator intercepts logging calls during development and testing, detects deprecated fields, and compares them against a frozen baseline. New offenses fail CI; known offenses are tracked in `.labkit_logging_todo.yml`. The validator is **not** active in production environments.

For the architectural decision and rationale, see [ADR: Dynamic Runtime Linting](./architecture/decisions/001_field_standardization_dynamic_runtime_linting.md).

## Key Concepts

**Offense**
- A unique combination of [File Path] + [Deprecated Field] + [Logger Class]
- Multiple log calls in the same file using the same deprecated field = 1 offense
- Offenses exist until the deprecated field is entirely removed from the file

**TODO Baseline**
- A list of known offenses tracked in `.labkit_logging_todo.yml`
- Existing offenses in this baseline are allowed
- Any new offenses detected during development raise an error
- Prevents regression while allowing incremental cleanup

## Quick Start

### First-Time Setup

1. **Initialize the todo file:**

   ```bash
   bundle exec labkit-logging init
   ```

   This creates `.labkit_logging_todo.yml` with `skip_ci_failure: true`, which allows CI to pass while collecting the initial baseline.

2. **Commit and push:**

   ```bash
   git add .labkit_logging_todo.yml
   git commit -m "Add LabKit logging todo baseline"
   git push
   ```

3. **Wait for CI to complete**, then fetch the baseline:

   ```bash
   bundle exec labkit-logging fetch <project> <pipeline_id>
   ```

   For example:
   ```bash
   bundle exec labkit-logging fetch gitlab-org/gitlab 12345
   ```

   This fetches all detected offenses from the CI pipeline logs and populates the todo file. The `skip_ci_failure` flag is automatically removed.

4. **Commit the populated baseline:**

   ```bash
   git add .labkit_logging_todo.yml
   git commit -m "Populate LabKit logging todo baseline"
   git push
   ```

Future CI runs will now enforce this baseline—new offenses will fail the pipeline.

## Developer Workflow

### Fixing Offenses (Recommended)

Replace deprecated fields with standard constants:

```ruby
# Before
logger.info(user_id: current_user.id)

# After
logger.info(Labkit::Fields::GL_USER_ID => current_user.id)
```

When you fix an offense, it's automatically removed from the baseline on the next test run. Run your tests locally to verify:

```bash
LABKIT_LOGGING_TODO_UPDATE=true bundle exec rspec
```

### Adding Offenses Temporarily

If you can't fix an offense immediately, add it to the baseline:

```bash
LABKIT_LOGGING_TODO_UPDATE=true bundle exec rspec
```

This updates `.labkit_logging_todo.yml` with any new offenses found during the test run. Commit the updated file with your changes.

**Note:** Justify in your MR why you can't fix immediately. Keep the baseline as small as possible.

### Regenerating the Baseline

To regenerate the entire baseline from scratch:

```bash
rm .labkit_logging_todo.yml
bundle exec labkit-logging init
# Run CI, then:
bundle exec labkit-logging fetch <project> <pipeline_id>
```

## CI Behavior

### Baseline Generation Mode

When `skip_ci_failure: true` is set in the todo file:

- CI passes even when deprecated fields are detected
- Offenses are logged for collection via `labkit-logging fetch`
- Use this mode only during initial setup

### Enforcement Mode

When `skip_ci_failure` is not set (normal operation):

- **New offenses fail the pipeline** with a detailed error message
- **Known offenses** (in the baseline) are allowed
- **Fixed offenses** are automatically detected and can be removed from the baseline

Example CI failure output:

```
================================================================================
LabKit Logging Field Standardization: New Offenses Detected
================================================================================

app/services/user_service.rb:42: 'user_id' is deprecated. Use 'Labkit::Fields::GL_USER_ID' instead.
app/models/project.rb:15: 'project_id' is deprecated. Use 'Labkit::Fields::GL_PROJECT_ID' instead.

================================================================================
Total: 2 new offense(s) in 2 file(s)
================================================================================
```

### When Offenses Are Fixed

When you fix offenses that were in the baseline, you'll see a message indicating which offenses were resolved. Update the baseline locally to remove them:

```bash
LABKIT_LOGGING_TODO_UPDATE=true bundle exec rspec
git add .labkit_logging_todo.yml
git commit -m "Remove fixed logging offenses from baseline"
```

## CLI Reference

The `labkit-logging` command provides subcommands for managing the field validator.

```bash
bundle exec labkit-logging <command> [options]
```

### labkit-logging init

Creates a new `.labkit_logging_todo.yml` file with `skip_ci_failure: true`.

```bash
bundle exec labkit-logging init
```

### labkit-logging fetch

Fetches offense logs from a GitLab CI pipeline and updates the todo file.

```bash
bundle exec labkit-logging fetch <project> <pipeline_id>
```

**Arguments:**
- `project` - GitLab project ID or path (e.g., `278964` or `gitlab-org/gitlab`)
- `pipeline_id` - CI pipeline ID number

**Environment Variables:**
- `GITLAB_TOKEN` - GitLab API token (required)
- `CI_API_V4_URL` - GitLab API URL (default: `https://gitlab.com/api/v4`)

**Examples:**

```bash
# Using project path
bundle exec labkit-logging fetch gitlab-org/gitlab 12345

# Using project ID
bundle exec labkit-logging fetch 278964 12345
```

## Environment Variables

| Variable | Description |
|----------|-------------|
| `LABKIT_LOGGING_TODO_UPDATE=true` | Update the baseline with new offenses (local development) |
| `GITLAB_TOKEN` | GitLab API token for fetching CI logs |
| `CI_API_V4_URL` | GitLab API URL (defaults to gitlab.com) |

## Troubleshooting

**"New Offenses Detected" in CI**
- Fix the deprecated fields in your code, or
- Update the baseline locally: `LABKIT_LOGGING_TODO_UPDATE=true bundle exec rspec`
- Commit the updated `.labkit_logging_todo.yml`

**Offenses not detected**
- Ensure `.labkit_logging_todo.yml` exists in your project root
- Verify you're using `Labkit::Logging::JsonLogger`
- Check you're logging with a Hash (not String)
- Verify the code path is executed during tests

**Pipeline not found when fetching**
- Verify the project path/ID is correct
- Ensure the pipeline has completed (not still running)
- Check your `GITLAB_TOKEN` has read access to the project

**No offenses found in pipeline**
- Ensure `skip_ci_failure: true` was set during the CI run
- Verify the pipeline ran tests that exercise the logging code
- Check job logs are accessible with your token

## TODO File Format

```yaml
# LabKit Logging Field Standardization TODO
# AUTO-GENERATED FILE. DO NOT EDIT MANUALLY.

offenses:
  - logger_class: "Labkit::Logging::JsonLogger"
    callsite: "app/services/user_service.rb"
    deprecated_field: "user_id"
    standard_field: "Labkit::Fields::GL_USER_ID"
  - logger_class: "Labkit::Logging::JsonLogger"
    callsite: "app/models/project.rb"
    deprecated_field: "project_id"
    standard_field: "Labkit::Fields::GL_PROJECT_ID"
```

## References

- [ADR: Dynamic Runtime Linting](./architecture/decisions/001_field_standardization_dynamic_runtime_linting.md)
- [Observability Field Standardisation](https://handbook.gitlab.com/handbook/engineering/architecture/design-documents/observability_field_standardisation/)
- [Quality Epic](https://gitlab.com/groups/gitlab-org/quality/-/epics/235)

exe/labkit-logging

0 → 100755
+198 −0
Original line number Diff line number Diff line
#!/usr/bin/env ruby
# frozen_string_literal: true

require 'net/http'
require 'uri'
require 'json'
require 'yaml'
require 'set'
require 'labkit/fields'
require 'labkit/logging/field_validator/config'

module Labkit
  module Logging
    module FieldValidator
      class CLI
        THREAD_POOL_SIZE = 10
        DETECTED_OFFENSE_PREFIX = 'LABKIT_LOGGING_OFFENSE'

        def run(args)
          case args.shift
          when 'init' then init_todo_file
          when 'fetch' then fetch(args)
          else puts "Usage: labkit-logging <init|fetch> [options]\n\n  init   Initialize .labkit_logging_todo.yml\n  fetch  Fetch offenses: labkit-logging fetch <project> <pipeline_id>"
          end
        end

        def init_todo_file
          Config.init_file!
          warn "Created #{Config.file_name} with skip_ci_failure enabled.\n\nNext steps:\n1. Commit this file\n2. Push and let CI run\n3. Run: labkit-logging fetch <project> <pipeline_id>"
        end

        private

        def fetch(args)
          @project = args[0]
          @pipeline = args[1]
          abort "Usage: labkit-logging fetch <project> <pipeline_id>" unless @project && @pipeline&.match?(/^\d+$/)
          abort "GITLAB_TOKEN environment variable is required" unless token

          warn "Fetching offenses from pipeline #{@pipeline}..."
          validate_pipeline!
          jobs = fetch_jobs

          detected = process_jobs(jobs)
          new_off, removed_off = compute_diff(detected)

          if new_off.empty? && removed_off.empty?
            warn "\nNo changes detected."
            return
          end

          save_results(new_off, removed_off)
        end

        def validate_pipeline!
          resp = api_get("/projects/#{enc(@project)}/pipelines/#{@pipeline}")
          abort "Pipeline not found" unless resp.is_a?(Net::HTTPSuccess)
          status = JSON.parse(resp.body)['status']
          abort "Pipeline still running" if status == 'running'
          abort "Pipeline status: #{status}" unless %w[success failed].include?(status)
        end

        def fetch_jobs
          jobs = []
          page = 1
          loop do
            resp = api_get("/projects/#{enc(@project)}/pipelines/#{@pipeline}/jobs?per_page=100&page=#{page}")
            abort "Failed to fetch jobs" unless resp.is_a?(Net::HTTPSuccess)
            batch = JSON.parse(resp.body)
            break if batch.empty?

            jobs.concat(batch)
            page += 1
          end
          jobs
        end

        def process_jobs(jobs)
          detected = []
          mutex = Mutex.new
          queue = Queue.new
          jobs.each { |j| queue << j }
          total = jobs.size
          done = 0

          threads = Array.new(THREAD_POOL_SIZE) do
            Thread.new do
              loop do
                job = begin
                  queue.pop(true)
                rescue StandardError
                  nil
                end
                break unless job

                begin
                  resp = api_get("/projects/#{enc(@project)}/jobs/#{job['id']}/trace")
                  if resp.is_a?(Net::HTTPSuccess)
                    offenses = parse_log(resp.body)
                    mutex.synchronize { detected.concat(offenses) }
                  end
                rescue StandardError => e
                  mutex.synchronize { warn "\nWarning: #{job['name']}: #{e.message}" }
                ensure
                  mutex.synchronize do
                    done += 1
                    $stderr.print "\rProcessing jobs: #{done}/#{total}"
                  end
                end
              end
            end
          end
          threads.each(&:join)
          warn ""

          dedupe(detected)
        end

        def parse_log(log)
          offenses = []
          log.each_line do |line|
            clean = line.gsub(/\e\[[0-9;]*[a-zA-Z]/, '').strip
            next unless clean.include?(DETECTED_OFFENSE_PREFIX)

            idx = clean.index(DETECTED_OFFENSE_PREFIX)
            next unless idx

            json = clean[(idx + DETECTED_OFFENSE_PREFIX.length)..].sub(/^[:\s]+/, '')
            offense = begin
              JSON.parse(json)
            rescue StandardError
              nil
            end
            offenses << offense if offense
          end
          offenses
        end

        def compute_diff(detected)
          baseline = Config.load.fetch('offenses', [])

          baseline_keys = baseline.to_set { |o| [o['callsite'], o['deprecated_field'], o['logger_class']] }
          detected_keys = detected.to_set { |o| [o['callsite'], o['deprecated_field'], o['logger_class']] }

          new_offenses = detected.reject do |o|
            key = [o['callsite'], o['deprecated_field'], o['logger_class']]
            baseline_keys.include?(key)
          end

          removed_offenses = baseline.select do |o|
            key = [o['callsite'], o['deprecated_field'], o['logger_class']]
            !detected_keys.include?(key) # rubocop:disable Rails/NegateInclude -- Set has no exclude? method
          end

          [new_offenses, removed_offenses]
        end

        def dedupe(offenses)
          offenses.uniq { |o| [o['callsite'], o['deprecated_field'], o['logger_class']] }
        end

        def save_results(new_off, removed_off)
          skip_removed = Config.load.fetch('skip_ci_failure', false)
          updated = Config.update!(new_off, removed_off)
          warn "\n✓ Added #{new_off.size} new offenses" if new_off.any?
          warn "✓ Removed #{removed_off.size} fixed offenses" if removed_off.any?
          warn "✓ Removed skip_ci_failure flag" if skip_removed
          warn "✓ Total: #{updated.size} offenses\n\nCommit the updated #{Config.file_name} file."
        end

        def api_get(path)
          uri = URI.parse("#{api_url}#{path}")
          http = Net::HTTP.new(uri.host, uri.port)
          http.use_ssl = uri.scheme == 'https'
          http.open_timeout = 10
          http.read_timeout = 30
          req = Net::HTTP::Get.new(uri.request_uri)
          req['PRIVATE-TOKEN'] = token
          http.request(req)
        end

        def token
          ENV['GITLAB_API_PRIVATE_TOKEN'] || ENV['GITLAB_TOKEN'] || ENV.fetch('CI_JOB_TOKEN', nil)
        end

        def api_url
          ENV['GITLAB_API_ENDPOINT'] || ENV['CI_API_V4_URL'] || 'https://gitlab.com/api/v4'
        end

        def enc(str)
          URI.encode_www_form_component(str.to_s)
        end
      end
    end
  end
end

Labkit::Logging::FieldValidator::CLI.new.run(ARGV)
+2 −0
Original line number Diff line number Diff line
@@ -16,6 +16,8 @@ Gem::Specification.new do |spec|
  spec.license = "MIT"

  spec.files = `git ls-files -z`.split("\x0").reject { |f| f.match(%r{^(spec|tools)/}) }
  spec.bindir = "exe"
  spec.executables = %w[labkit-logging]
  spec.require_paths = ["lib"]
  spec.required_ruby_version = "~> 3.2"

+4 −0
Original line number Diff line number Diff line
@@ -7,5 +7,9 @@ module Labkit
    autoload :GRPC, "labkit/logging/grpc"
    autoload :Sanitizer, "labkit/logging/sanitizer"
    autoload :JsonLogger, "labkit/logging/json_logger"

    # Eagerly load FieldValidator in non-production environments
    # This ensures injection happens before JsonLogger instances are created
    require "labkit/logging/field_validator" unless ENV['RAILS_ENV'] == 'production'
  end
end
+178 −0
Original line number Diff line number Diff line
# frozen_string_literal: true

require 'set'
require 'json'
require 'yaml'

require_relative 'field_validator/config'
require_relative 'field_validator/log_interceptor'
require_relative 'field_validator/registry'

module Labkit
  module Logging
    ##
    # Runtime validator for logging fields.
    # Validates logged fields against standard and deprecated field lists.
    # This validator is automatically injected in non-production environments.
    # Offenses are collected during test runs and development.
    module FieldValidator
      class << self
        # Inject the validator into JsonLogger
        def inject!
          return if @injected

          # If the config file does not exist, we don't inject the validator.
          # To enable field validation in a repository, a config file must exist.
          return unless Config.config_file_exists?

          ::Labkit::Logging::JsonLogger.prepend(LogInterceptor)
          Kernel.at_exit { FieldValidator.process_violations }
          @injected = true
        end

        def initialize_todo_file
          Config.init_file!
          warn "Created .labkit_logging_todo.yml with skip_ci_failure enabled."
          warn ""
          warn "Next steps:"
          warn "1. Commit this file to source control"
          warn "2. Push and let CI run to generate offense logs"
          warn "3. Run: bundle exec labkit-logging fetch <project> <pipeline_id>"
          warn "4. Commit the populated todo file (skip_ci_failure will be removed automatically)"
        end

        def process_violations
          detected_offenses, new_offenses, removed_offenses = Registry.instance.finalize

          return if detected_offenses.empty? && new_offenses.empty? && removed_offenses.empty?

          in_ci = ENV['CI'] == 'true'

          output_ndjson(detected_offenses) if in_ci

          # Auto-remove fixed offenses (not in CI to avoid race conditions)
          handle_removed_offenses(removed_offenses) if removed_offenses.any? && !in_ci

          if ENV['LABKIT_LOGGING_TODO_UPDATE'] == 'true'
            handle_update(new_offenses)
          elsif new_offenses.any?
            handle_new_offenses(new_offenses)
          end
        end

        def clear_offenses!
          Registry.instance.clear!
        end

        private

        def handle_removed_offenses(removed_offenses)
          Config.update!([], removed_offenses)

          warn thank_you_message(removed_offenses)
        end

        def thank_you_message(removed_offenses)
          lines = [
            "",
            "=" * 80,
            "Thank you for improving our logging standards!",
            "=" * 80,
            "",
            "You fixed #{removed_offenses.size} deprecated field offense(s):",
            ""
          ]

          removed_offenses.each do |o|
            lines << "  - #{o['callsite']}: '#{o['deprecated_field']}' -> '#{format_standard_field(o['standard_field'])}'"
          end

          lines << ""
          lines << "#{Config.file_name} has been automatically updated."
          lines << "Please commit the changes to complete the cleanup."
          lines << ""
          lines << ("=" * 80)
          lines << ""

          lines.join("\n")
        end

        def handle_new_offenses(new_offenses)
          if ENV['CI'] == 'true' && Config.skip_ci_failure?
            warn baseline_generation_message(new_offenses)
          else
            warn report_new_offenses(new_offenses)
            raise "New LabKit logging offenses detected"
          end
        end

        def baseline_generation_message(offenses)
          lines = [
            "",
            "ℹ️  LabKit Logging: Baseline generation mode active",
            "",
            "Deprecated fields detected but skip_ci_failure is enabled.",
            "Offenses are being logged for collection.",
            "",
            "To establish baseline:",
            "  bundle exec labkit-logging fetch <project> <pipeline_id>",
            "",
            "Documentation: https://gitlab.com/gitlab-org/ruby/gems/labkit-ruby/-/blob/master/doc/FIELD_STANDARDIZATION.md",
            "",
            "--- Offenses Summary ---",
            "Total offenses: #{offenses.size} across #{offenses.map { |o| o['callsite'] }.uniq.size} file(s)",
            ""
          ]
          lines.join("\n")
        end

        def output_ndjson(detected_offenses)
          detected_offenses.each do |offense|
            puts "LABKIT_LOGGING_OFFENSE: #{JSON.generate(offense)}"
          end
        end

        def handle_update(new_offenses)
          updated_offenses = Config.update!(new_offenses)

          warn "\n✓ Updated .labkit_logging_todo.yml"
          warn "\n  Added #{new_offenses.size} new offenses ✓" if new_offenses.any?

          warn "Total: #{updated_offenses.size} offenses"
          warn "\nCommit the updated #{Config.file_name}."
        end

        def report_new_offenses(new_offenses)
          lines = [
            "",
            "=" * 80,
            "LabKit Logging Field Standardization: New Offenses Detected",
            "=" * 80,
            ""
          ]

          new_offenses.each do |o|
            lines << "#{o['callsite']}:#{o['lineno']}: '#{o['deprecated_field']}' is deprecated. Use '#{format_standard_field(o['standard_field'])}' instead."
          end

          lines << ""
          lines << ("=" * 80)
          lines << "Total: #{new_offenses.size} new offense(s) in #{new_offenses.map { |o| o['callsite'] }.uniq.size} file(s)"
          lines << ""
          lines << "See https://gitlab.com/gitlab-org/ruby/gems/labkit-ruby/-/blob/master/doc/FIELD_STANDARDIZATION.md"
          lines << ("=" * 80)
          lines << ""

          lines.join("\n")
        end

        def format_standard_field(standard_field)
          const_name = Labkit::Fields.constant_name_for(standard_field)
          const_name ? "Labkit::Fields::#{const_name}" : standard_field
        end
      end
    end
  end
end

Labkit::Logging::FieldValidator.inject!
Loading