From 08a48a3364b632a551c88ed63ce7368555478c7f Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Fri, 23 Jan 2026 02:52:46 +1300 Subject: [PATCH 1/2] Add support for LogStruct --- exe/log_bench | 64 +++++++++---- lib/log_bench.rb | 19 +++- lib/log_bench/configuration.rb | 30 +++++- lib/log_bench/configuration_validator.rb | 76 +++++++++++++-- lib/log_bench/log/entry.rb | 17 +++- lib/log_bench/log/job_enqueue_entry.rb | 20 +++- lib/log_bench/log/parser.rb | 35 ++++++- lib/log_bench/log/query_entry.rb | 28 ++++++ lib/log_bench/log/request.rb | 7 +- lib/log_bench/railtie.rb | 13 ++- test/support/fixtures.rb | 29 ++++++ test/test_job_enqueue_tracking.rb | 52 +++++++++++ test/test_log_bench.rb | 113 +++++++++++++++++++++++ test/test_query_summary.rb | 34 +++++++ 14 files changed, 492 insertions(+), 45 deletions(-) diff --git a/exe/log_bench b/exe/log_bench index d4b96d6..09007cc 100755 --- a/exe/log_bench +++ b/exe/log_bench @@ -1,6 +1,7 @@ #!/usr/bin/env ruby # frozen_string_literal: true +require "optparse" require_relative "../lib/log_bench" def show_help @@ -8,14 +9,20 @@ def show_help LogBench - Rails Log Viewer Usage: - log_bench [log_file] + log_bench [options] [log_file] log_bench --help log_bench --version + Options: + --logger_type=TYPE Logger type: lograge (default) or logstruct + -h, --help Show this help message + -v, --version Show version + Examples: - log_bench # View log/development.log - log_bench log/production.log # View specific log file - log_bench /path/to/app/log/test.log # View log from another app + log_bench # View log/development.log + log_bench log/production.log # View specific log file + log_bench --logger_type=logstruct # Use LogStruct format + log_bench log/production.log --logger_type=logstruct Setup (for Rails apps): LogBench is automatically enabled in development! @@ -32,18 +39,41 @@ def show_version puts "LogBench #{LogBench::VERSION}" end -# Handle command line arguments -case ARGV[0] -when "--help", "-h" - show_help - exit 0 -when "--version", "-v" - show_version - exit 0 +def parse_options + options = {logger_type: :lograge} + + # Separate options from positional arguments + args = ARGV.dup + positional_args = [] + + while args.any? + arg = args.shift + case arg + when "--help", "-h" + show_help + exit 0 + when "--version", "-v" + show_version + exit 0 + when /\A--logger_type=(.+)\z/ + options[:logger_type] = ::Regexp.last_match(1).to_sym + when "--logger_type" + options[:logger_type] = args.shift&.to_sym + else + positional_args << arg + end + end + + log_file = positional_args.first || "log/development.log" + + [log_file, options] end begin - log_file = ARGV[0] || "log/development.log" + log_file, options = parse_options + + # Set logger type for CLI usage (this is used by the TUI, not Rails config) + LogBench.cli_logger_type = options[:logger_type] # Check if log file exists unless File.exist?(log_file) @@ -52,7 +82,7 @@ begin puts "Make sure:" puts " 1. You're in a Rails application directory" puts " 2. The log file exists and has content" - puts " 3. Lograge is configured (see README.md for setup)" + puts " 3. Your logger is configured (lograge or logstruct)" puts puts "For help: log_bench --help" exit 1 @@ -61,7 +91,7 @@ begin LogBench::App::Main.new(log_file).run rescue Interrupt Curses.close_screen if defined?(Curses) - puts "\nGoodbye! 👋" + puts "\nGoodbye!" exit 0 rescue => e Curses.close_screen if defined?(Curses) @@ -69,8 +99,8 @@ rescue => e puts puts "Common issues:" puts " - Log file doesn't exist or is empty" - puts " - Lograge not configured (see README.md for setup)" - puts " - Log format not supported (LogBench requires lograge JSON format)" + puts " - Logger not configured (see README.md for setup)" + puts " - Log format not supported (LogBench requires lograge or logstruct JSON format)" puts puts "For help: log_bench --help" exit 1 diff --git a/lib/log_bench.rb b/lib/log_bench.rb index 733a97a..23ee5bd 100644 --- a/lib/log_bench.rb +++ b/lib/log_bench.rb @@ -13,11 +13,15 @@ module LogBench class Error < StandardError; end class << self - attr_accessor :configuration + attr_accessor :configuration, :cli_logger_type def setup self.configuration ||= Configuration.new yield(configuration) if block_given? + # Auto-detect LogStruct if enabled + if defined?(LogStruct) && LogStruct.respond_to?(:enabled?) && LogStruct.enabled? + configuration.logger_type = :logstruct + end configuration end @@ -25,6 +29,19 @@ def logger @logger ||= create_debug_logger end + # Returns the effective logger type (CLI flag takes precedence over config) + def logger_type + cli_logger_type || configuration&.logger_type || :lograge + end + + def logstruct? + logger_type == :logstruct + end + + def lograge? + logger_type == :lograge + end + private def create_debug_logger diff --git a/lib/log_bench/configuration.rb b/lib/log_bench/configuration.rb index 5d25d77..b8a6075 100644 --- a/lib/log_bench/configuration.rb +++ b/lib/log_bench/configuration.rb @@ -2,13 +2,37 @@ module LogBench class Configuration - attr_accessor :show_init_message, :enabled, :base_controller_classes, :configure_lograge_automatically + VALID_LOGGER_TYPES = %i[lograge logstruct].freeze + + attr_accessor :show_init_message, :enabled, :base_controller_classes, :configure_logger_automatically + attr_reader :logger_type def initialize @show_init_message = :full - @enabled = Rails.env.development? + @enabled = (defined?(Rails) && Rails.respond_to?(:env)) ? Rails.env.development? : false @base_controller_classes = %w[ApplicationController ActionController::Base] - @configure_lograge_automatically = true # Configure lograge by default + @configure_logger_automatically = true # Configure logger by default + @logger_type = :lograge # Default to lograge for backward compatibility + end + + # Backward compatibility alias + alias_method :configure_lograge_automatically, :configure_logger_automatically + alias_method :configure_lograge_automatically=, :configure_logger_automatically= + + def logger_type=(value) + value = value.to_sym if value.is_a?(String) + unless VALID_LOGGER_TYPES.include?(value) + raise ArgumentError, "Invalid logger_type: #{value}. Valid options: #{VALID_LOGGER_TYPES.join(", ")}" + end + @logger_type = value + end + + def logstruct? + @logger_type == :logstruct + end + + def lograge? + @logger_type == :lograge end end end diff --git a/lib/log_bench/configuration_validator.rb b/lib/log_bench/configuration_validator.rb index 0f55b37..36e2d77 100644 --- a/lib/log_bench/configuration_validator.rb +++ b/lib/log_bench/configuration_validator.rb @@ -1,10 +1,11 @@ # frozen_string_literal: true module LogBench - # Validates that lograge is properly configured for LogBench + # Validates that the logger is properly configured for LogBench class ConfigurationValidator class ConfigurationError < StandardError; end - ERROR_CONFIGS = { + + LOGRAGE_ERROR_CONFIGS = { enabled: { title: "Lograge is not enabled", description: "LogBench requires lograge to be enabled in your Rails application." @@ -23,6 +24,17 @@ class ConfigurationError < StandardError; end } }.freeze + LOGSTRUCT_ERROR_CONFIGS = { + not_installed: { + title: "LogStruct gem is not installed", + description: "LogBench with logger_type: :logstruct requires the logstruct gem." + }, + not_enabled: { + title: "LogStruct is not enabled", + description: "LogStruct must be enabled for LogBench to work." + } + }.freeze + def self.validate_rails_config! new.validate_rails_config! end @@ -31,32 +43,60 @@ def validate_rails_config! return true unless defined?(Rails) && Rails.application return true unless LogBench.configuration.enabled + if LogBench.configuration.logstruct? + validate_logstruct_config! + else + validate_lograge_config! + end + + true + end + + private + + def validate_logstruct_config! + validate_logstruct_installed! + validate_logstruct_enabled! + end + + def validate_lograge_config! validate_lograge_enabled! validate_custom_options! validate_lograge_formatter! validate_logger_formatter! + end - true + def validate_logstruct_installed! + unless defined?(LogStruct) + raise ConfigurationError, build_logstruct_error_message(:not_installed) + end end - private + def validate_logstruct_enabled! + return if LogStruct.config.enabled + + raise ConfigurationError, build_logstruct_error_message(:not_enabled) + rescue NoMethodError + # LogStruct might not have config method in older versions + nil + end def validate_lograge_enabled! unless lograge_config&.enabled - raise ConfigurationError, build_error_message(:enabled) + raise ConfigurationError, build_lograge_error_message(:enabled) end end def validate_custom_options! unless lograge_config&.custom_options - raise ConfigurationError, build_error_message(:options) + raise ConfigurationError, build_lograge_error_message(:options) end end def validate_lograge_formatter! formatter = lograge_config&.formatter unless formatter.is_a?(Lograge::Formatters::Json) - raise ConfigurationError, build_error_message(:lograge_formatter) + raise ConfigurationError, build_lograge_error_message(:lograge_formatter) end end @@ -67,7 +107,7 @@ def validate_logger_formatter! # Allow LogBench::JsonFormatter or any custom JSON formatter # Users might have their own JSON formatters that work with LogBench unless formatter.is_a?(LogBench::JsonFormatter) - raise ConfigurationError, build_error_message(:logger_formatter) + raise ConfigurationError, build_lograge_error_message(:logger_formatter) end end @@ -76,8 +116,8 @@ def lograge_config Rails.application.config.lograge end - def build_error_message(error_type) - config = ERROR_CONFIGS[error_type] + def build_lograge_error_message(error_type) + config = LOGRAGE_ERROR_CONFIGS[error_type] <<~ERROR ❌ #{config[:title]} @@ -89,5 +129,21 @@ def build_error_message(error_type) For complete setup: https://github.com/silva96/log_bench#configuration ERROR end + + def build_logstruct_error_message(error_type) + config = LOGSTRUCT_ERROR_CONFIGS[error_type] + + <<~ERROR + ❌ #{config[:title]} + + #{config[:description]} + + Make sure you have: + 1. Added 'logstruct' to your Gemfile + 2. LogStruct is enabled in your environment + + For complete setup: https://github.com/DocSpring/logstruct + ERROR + end end end diff --git a/lib/log_bench/log/entry.rb b/lib/log_bench/log/entry.rb index 0b2491e..45b8357 100644 --- a/lib/log_bench/log/entry.rb +++ b/lib/log_bench/log/entry.rb @@ -7,9 +7,10 @@ class Entry def initialize(json_data) self.json_data = json_data - self.timestamp = parse_timestamp(json_data["timestamp"]) - self.request_id = json_data["request_id"] - self.content = Parser.normalize_message(json_data["message"]) + self.timestamp = parse_timestamp(extract_timestamp(json_data)) + # LogStruct uses "req_id", lograge/standard uses "request_id" + self.request_id = json_data["req_id"] || json_data["request_id"] + self.content = Parser.normalize_message(extract_message(json_data)) self.type = :other end @@ -32,6 +33,16 @@ def parse_timestamp(timestamp_str) rescue ArgumentError Time.now end + + def extract_timestamp(json_data) + # LogStruct uses "ts", lograge/standard uses "timestamp" + json_data["ts"] || json_data["timestamp"] + end + + def extract_message(json_data) + # LogStruct uses "msg", lograge/standard uses "message" + json_data["msg"] || json_data["message"] + end end end end diff --git a/lib/log_bench/log/job_enqueue_entry.rb b/lib/log_bench/log/job_enqueue_entry.rb index 678d78a..519a72b 100644 --- a/lib/log_bench/log/job_enqueue_entry.rb +++ b/lib/log_bench/log/job_enqueue_entry.rb @@ -9,6 +9,7 @@ def initialize(json_data) super self.type = :job_enqueue self.job_id = extract_job_id + build_content_for_logstruct if logstruct_format? end private @@ -16,7 +17,24 @@ def initialize(json_data) attr_writer :job_id def extract_job_id - Parser.extract_job_id_from_enqueue(content) + # LogStruct has job_id as a direct field + json_data["job_id"] || Parser.extract_job_id_from_enqueue(content) + end + + def logstruct_format? + json_data["evt"] == "schedule" && json_data["src"] == "job" + end + + def build_content_for_logstruct + job_class = json_data["job_class"] || "Job" + queue = json_data["queue_name"] + scheduled_at = json_data["scheduled_at"] + + parts = ["Enqueued #{job_class} (Job ID: #{job_id})"] + parts << "to #{queue}" if queue + parts << "at #{scheduled_at}" if scheduled_at + + @content = parts.join(" ") end end end diff --git a/lib/log_bench/log/parser.rb b/lib/log_bench/log/parser.rb index a16a016..62bd838 100644 --- a/lib/log_bench/log/parser.rb +++ b/lib/log_bench/log/parser.rb @@ -70,7 +70,7 @@ def self.find_related_logs(entries) end def self.determine_json_type(data) - return :http_request if lograge_request?(data) + return :http_request if http_request?(data) return :cache if cache_message?(data) return :sql if sql_message?(data) return :sql_call_line if call_stack_message?(data) @@ -79,10 +79,23 @@ def self.determine_json_type(data) :other end + def self.http_request?(data) + lograge_request?(data) || logstruct_request?(data) + end + def self.lograge_request?(data) data["method"] && data["path"] && data["status"] end + def self.logstruct_request?(data) + # LogStruct uses "evt" field with value "request" or "req" + evt = data["evt"] + return false unless evt + + evt_str = evt.to_s.downcase + evt_str == "request" || evt_str == "req" + end + def self.normalize_message(message) case message when String @@ -96,23 +109,35 @@ def self.normalize_message(message) end end + def self.extract_message(data) + # LogStruct uses "msg", lograge/standard uses "message" + data["msg"] || data["message"] + end + def self.sql_message?(data) - message = normalize_message(data["message"]) + # LogStruct uses evt:"database" for structured SQL events + return true if data["evt"] == "database" + + message = normalize_message(extract_message(data)) %w[SELECT INSERT UPDATE DELETE TRANSACTION BEGIN COMMIT ROLLBACK SAVEPOINT].any? { |op| message.include?(op) } end def self.cache_message?(data) - message = normalize_message(data["message"]) + message = normalize_message(extract_message(data)) message.include?("CACHE") end def self.call_stack_message?(data) - message = normalize_message(data["message"]) + message = normalize_message(extract_message(data)) message.include?("↳") end def self.job_enqueue_message?(data) - message = normalize_message(data["message"]) + # LogStruct uses evt:"schedule" with src:"job" + return true if data["evt"] == "schedule" && data["src"] == "job" + + # Lograge format + message = normalize_message(extract_message(data)) message.match?(/Enqueued .+ \(Job ID: .+\)/) end diff --git a/lib/log_bench/log/query_entry.rb b/lib/log_bench/log/query_entry.rb index c041656..0542ff0 100644 --- a/lib/log_bench/log/query_entry.rb +++ b/lib/log_bench/log/query_entry.rb @@ -19,6 +19,7 @@ def initialize(json_data, cached: false) self.type = cached ? :cache : :sql self.timing = extract_timing self.operation = extract_operation + build_content_for_logstruct if logstruct_database_event? end def duration_ms @@ -74,14 +75,41 @@ def hit? attr_accessor :operation, :cached def extract_timing + # LogStruct has duration_ms as a direct field + if json_data["duration_ms"] + return "#{json_data["duration_ms"]}ms" + end + match = clean_content.match(/\(([0-9.]+ms)\)/) match ? match[1] : nil end def extract_operation + # LogStruct has op_type as a direct field + if json_data["op_type"] + return json_data["op_type"].to_s.upcase + end + SQL_OPERATIONS.find { |op| clean_content.include?(op) } end + def logstruct_database_event? + json_data["evt"] == "database" && json_data["sql"] + end + + def build_content_for_logstruct + sql = json_data["sql"] + name = json_data["name"] + timing_str = timing || "0.0ms" + + parts = [] + parts << name if name + parts << "(#{timing_str})" + parts << sql + + @content = parts.join(" ") + end + def clean_content @clean_content ||= content&.gsub(/\e\[[0-9;]*m/, "") || "" end diff --git a/lib/log_bench/log/request.rb b/lib/log_bench/log/request.rb index 7ce333a..32c2527 100644 --- a/lib/log_bench/log/request.rb +++ b/lib/log_bench/log/request.rb @@ -12,7 +12,7 @@ def initialize(json_data, orphan: false) self.method = json_data["method"] self.path = json_data["path"] self.status = json_data["status"] - self.duration = json_data["duration"] + self.duration = extract_duration(json_data) self.controller = json_data["controller"] self.action = json_data["action"] self.params = parse_params(json_data["params"]) @@ -95,6 +95,11 @@ def parse_params(params_data) rescue JSON::ParserError params_data.to_s end + + def extract_duration(json_data) + # LogStruct uses "duration_ms", lograge uses "duration" + json_data["duration_ms"] || json_data["duration"] + end end end end diff --git a/lib/log_bench/railtie.rb b/lib/log_bench/railtie.rb index 264f46b..d1b761d 100644 --- a/lib/log_bench/railtie.rb +++ b/lib/log_bench/railtie.rb @@ -37,16 +37,20 @@ class Railtie < Rails::Railtie puts LINE end - # Configure lograge after the gem was already configured + # Configure lograge after the gem was already configured (only for lograge mode) initializer "log_bench.configure_lograge", after: "log_bench.configure" do |app| - if LogBench.configuration.enabled + if LogBench.configuration.enabled && LogBench.configuration.lograge? LogBench::Railtie.setup_lograge(app) end end config.after_initialize do if LogBench.configuration.enabled - LogBench::Railtie.setup_rails_logger_final + # Only set up custom Rails logger for lograge mode + # LogStruct handles its own logger formatting + if LogBench.configuration.lograge? + LogBench::Railtie.setup_rails_logger_final + end LogBench::Railtie.setup_current_attributes LogBench::Railtie.setup_sidekiq_middleware LogBench::Railtie.validate_configuration! @@ -55,7 +59,7 @@ class Railtie < Rails::Railtie class << self def setup_lograge(app) - return unless LogBench.configuration.configure_lograge_automatically + return unless LogBench.configuration.configure_logger_automatically app.config.lograge.enabled = true app.config.lograge.formatter = Lograge::Formatters::Json.new @@ -121,6 +125,7 @@ def validate_configuration! puts "LogBench will be disabled until this is fixed." puts LINE end + end private diff --git a/test/support/fixtures.rb b/test/support/fixtures.rb index 45d989e..843dab6 100644 --- a/test/support/fixtures.rb +++ b/test/support/fixtures.rb @@ -70,4 +70,33 @@ def self.log_entry_with_missing_message def self.request_with_null_message_logs [lograge_get_request, log_entry_with_null_message, log_entry_with_missing_message] end + + # LogStruct fixtures (uses "req_id" not "request_id") + def self.logstruct_get_request + '{"src":"rails","evt":"request","lvl":"info","ts":"2025-01-01T10:00:00.000Z","method":"GET","path":"/users","status":200,"duration_ms":45.2,"controller":"UsersController","action":"index","req_id":"abc123"}' + end + + def self.logstruct_post_request + '{"src":"rails","evt":"request","lvl":"info","ts":"2025-01-01T10:01:00.000Z","method":"POST","path":"/users","status":201,"duration_ms":150.5,"controller":"UsersController","action":"create","req_id":"def456","params":{"user":{"name":"John"}}}' + end + + def self.logstruct_plain_log + '{"src":"app","evt":"log","lvl":"info","ts":"2025-01-01T10:00:01.000Z","msg":"Processing user request","req_id":"abc123"}' + end + + def self.logstruct_sql_log + '{"src":"app","evt":"log","lvl":"debug","ts":"2025-01-01T10:00:01.000Z","msg":"User Load (1.5ms) SELECT `users`.* FROM `users` WHERE `users`.`id` = 1","req_id":"abc123"}' + end + + def self.logstruct_cache_log + '{"src":"app","evt":"log","lvl":"debug","ts":"2025-01-01T10:00:02.000Z","msg":"CACHE User Load (0.1ms) SELECT `users`.* FROM `users`","req_id":"abc123"}' + end + + def self.logstruct_request_with_sql + [logstruct_get_request, logstruct_sql_log] + end + + def self.logstruct_request_with_cache + [logstruct_get_request, logstruct_cache_log] + end end diff --git a/test/test_job_enqueue_tracking.rb b/test/test_job_enqueue_tracking.rb index 0135f6a..6c09310 100644 --- a/test/test_job_enqueue_tracking.rb +++ b/test/test_job_enqueue_tracking.rb @@ -293,6 +293,58 @@ def test_nested_job_enqueues_chain_request_id end end + # LogStruct format tests + def test_logstruct_job_schedule_detection + # LogStruct uses evt:"schedule" with src:"job" + data = {"src" => "job", "evt" => "schedule", "job_id" => "abc-123", "job_class" => "TestJob"} + assert LogBench::Log::Parser.job_enqueue_message?(data) + + # Should not detect other job events as enqueue + start_data = {"src" => "job", "evt" => "start", "job_id" => "abc-123"} + refute LogBench::Log::Parser.job_enqueue_message?(start_data) + + finish_data = {"src" => "job", "evt" => "finish", "job_id" => "abc-123"} + refute LogBench::Log::Parser.job_enqueue_message?(finish_data) + end + + def test_logstruct_job_enqueue_extracts_job_id + # LogStruct has job_id as a direct field + logstruct_log = '{"src":"job","evt":"schedule","job_id":"79729d72-f0df-468e-a6da-9064ec9e845e","job_class":"TestJob","queue_name":"default","req_id":"8cc2f6c7-6fd9-4d41-8626-847a6f1c5bb9","ts":"2026-01-23T19:36:20.129+13:00"}' + + entry = LogBench::Log::Parser.parse_line(logstruct_log) + + assert_instance_of LogBench::Log::JobEnqueueEntry, entry + assert_equal "79729d72-f0df-468e-a6da-9064ec9e845e", entry.job_id + assert_equal "8cc2f6c7-6fd9-4d41-8626-847a6f1c5bb9", entry.request_id + end + + def test_logstruct_job_enqueue_builds_readable_content + logstruct_log = '{"src":"job","evt":"schedule","job_id":"79729d72-f0df-468e-a6da-9064ec9e845e","job_class":"TestJob","queue_name":"default","scheduled_at":"2026-01-23T06:36:22Z","req_id":"8cc2f6c7-6fd9-4d41-8626-847a6f1c5bb9","ts":"2026-01-23T19:36:20.129+13:00"}' + + entry = LogBench::Log::Parser.parse_line(logstruct_log) + + assert_instance_of LogBench::Log::JobEnqueueEntry, entry + assert_equal "Enqueued TestJob (Job ID: 79729d72-f0df-468e-a6da-9064ec9e845e) to default at 2026-01-23T06:36:22Z", entry.content + end + + def test_logstruct_job_enqueue_with_request + request_log = '{"src":"rails","evt":"request","method":"GET","path":"/","status":200,"duration_ms":62.57,"controller":"HomeController","action":"index","req_id":"8cc2f6c7-6fd9-4d41-8626-847a6f1c5bb9","ts":"2026-01-23T19:36:20.157+13:00"}' + schedule_log = '{"src":"job","evt":"schedule","job_id":"79729d72-f0df-468e-a6da-9064ec9e845e","job_class":"TestJob","queue_name":"default","req_id":"8cc2f6c7-6fd9-4d41-8626-847a6f1c5bb9","ts":"2026-01-23T19:36:20.129+13:00"}' + + collection = LogBench::Log::Collection.new([request_log, schedule_log]) + requests = collection.requests + + assert_equal 1, requests.size + request = requests.first + + job_enqueue_entries = request.related_logs.select { |log| log.is_a?(LogBench::Log::JobEnqueueEntry) } + assert_equal 1, job_enqueue_entries.size + + job_enqueue = job_enqueue_entries.first + assert_equal "79729d72-f0df-468e-a6da-9064ec9e845e", job_enqueue.job_id + assert_equal "8cc2f6c7-6fd9-4d41-8626-847a6f1c5bb9", job_enqueue.request_id + end + def test_deeply_nested_jobs_chain_request_id # Scenario: HTTP request → JobA → JobB → JobC (3 levels deep) request_id = "req-999" diff --git a/test/test_log_bench.rb b/test/test_log_bench.rb index be5970f..57a92df 100644 --- a/test/test_log_bench.rb +++ b/test/test_log_bench.rb @@ -515,6 +515,119 @@ def test_normalize_message_handles_other_types assert_equal "true", LogBench::Log::Parser.normalize_message(true) end + # LogStruct format tests + def test_parse_logstruct_request + collection = LogBench::Log::Collection.new([TestFixtures.logstruct_get_request]) + requests = collection.requests + + assert_equal 1, requests.size + request = requests.first + assert_instance_of LogBench::Log::Request, request + assert_equal "GET", request.method + assert_equal "/users", request.path + assert_equal 200, request.status + assert_equal 45.2, request.duration # duration_ms is mapped to duration + assert_equal "UsersController", request.controller + assert_equal "index", request.action + assert_equal "abc123", request.request_id + end + + def test_parse_logstruct_post_request_with_params + collection = LogBench::Log::Collection.new([TestFixtures.logstruct_post_request]) + requests = collection.requests + + assert_equal 1, requests.size + request = requests.first + assert_equal "POST", request.method + assert_equal "/users", request.path + assert_equal 201, request.status + assert_equal 150.5, request.duration + refute_nil request.params + assert_equal "John", request.params["user"]["name"] + end + + def test_parse_logstruct_sql_query + collection = LogBench::Log::Collection.new(TestFixtures.logstruct_request_with_sql) + requests = collection.requests + + assert_equal 1, requests.size + request = requests.first + assert_equal 1, request.queries.size + + query = request.queries.first + assert_instance_of LogBench::Log::QueryEntry, query + assert query.select? + end + + def test_parse_logstruct_cache_entry + collection = LogBench::Log::Collection.new(TestFixtures.logstruct_request_with_cache) + requests = collection.requests + + assert_equal 1, requests.size + request = requests.first + assert_equal 1, request.cache_operations.size + + cache_op = request.cache_operations.first + assert_instance_of LogBench::Log::QueryEntry, cache_op + assert cache_op.cached? + end + + def test_logstruct_timestamp_parsing + collection = LogBench::Log::Collection.new([TestFixtures.logstruct_get_request]) + request = collection.requests.first + + assert_instance_of Time, request.timestamp + assert_equal 2025, request.timestamp.year + assert_equal 1, request.timestamp.month + assert_equal 1, request.timestamp.day + end + + def test_logstruct_plain_log_message + entry = LogBench::Log::Parser.parse_line(TestFixtures.logstruct_plain_log) + + assert_instance_of LogBench::Log::Entry, entry + assert_equal "Processing user request", entry.content + assert_equal "abc123", entry.request_id + end + + def test_logstruct_request_detection + # Test that LogStruct request format is detected correctly + data = JSON.parse(TestFixtures.logstruct_get_request) + assert LogBench::Log::Parser.logstruct_request?(data) + assert LogBench::Log::Parser.http_request?(data) + end + + def test_lograge_request_detection + # Test that lograge format is still detected correctly + data = JSON.parse(TestFixtures.lograge_get_request) + assert LogBench::Log::Parser.lograge_request?(data) + assert LogBench::Log::Parser.http_request?(data) + refute LogBench::Log::Parser.logstruct_request?(data) + end + + def test_configuration_logger_type + config = LogBench::Configuration.new + assert_equal :lograge, config.logger_type # default + assert config.lograge? + refute config.logstruct? + + config.logger_type = :logstruct + assert_equal :logstruct, config.logger_type + assert config.logstruct? + refute config.lograge? + + # Test string coercion + config.logger_type = "lograge" + assert_equal :lograge, config.logger_type + end + + def test_configuration_invalid_logger_type + config = LogBench::Configuration.new + assert_raises(ArgumentError) do + config.logger_type = :invalid + end + end + def test_sql_message_detection_with_array # Should detect SQL messages when message is an Array data1 = {"message" => ["SELECT", "*", "FROM", "users"]} diff --git a/test/test_query_summary.rb b/test/test_query_summary.rb index d7ebce9..ab28f22 100644 --- a/test/test_query_summary.rb +++ b/test/test_query_summary.rb @@ -1,6 +1,40 @@ require "test_helper" class TestQuerySummary < Minitest::Test + # LogStruct database event tests + def test_logstruct_database_event_detection + data = {"evt" => "database", "sql" => "SELECT * FROM users", "duration_ms" => 1.5} + assert LogBench::Log::Parser.sql_message?(data) + end + + def test_logstruct_database_event_parsing + logstruct_log = '{"src":"app","evt":"database","sql":"SELECT * FROM users WHERE id = 1","name":"User Load","duration_ms":1.5,"op_type":"select","req_id":"abc123","ts":"2026-01-23T19:36:20.053+13:00"}' + + entry = LogBench::Log::Parser.parse_line(logstruct_log) + + assert_instance_of LogBench::Log::QueryEntry, entry + assert_equal "1.5ms", entry.timing + assert_equal 1.5, entry.duration_ms + assert entry.select? + assert_includes entry.content, "User Load" + assert_includes entry.content, "SELECT * FROM users WHERE id = 1" + end + + def test_logstruct_database_event_with_request + request_log = '{"src":"rails","evt":"request","method":"GET","path":"/users","status":200,"duration_ms":45.2,"controller":"UsersController","action":"index","req_id":"abc123","ts":"2026-01-23T19:36:20.157+13:00"}' + sql_log = '{"src":"app","evt":"database","sql":"SELECT * FROM users","name":"User Load","duration_ms":1.5,"op_type":"select","req_id":"abc123","ts":"2026-01-23T19:36:20.053+13:00"}' + + collection = LogBench::Log::Collection.new([request_log, sql_log]) + requests = collection.requests + + assert_equal 1, requests.size + request = requests.first + + sql_entries = request.related_logs.select { |log| log.is_a?(LogBench::Log::QueryEntry) } + assert_equal 1, sql_entries.size + assert sql_entries.first.select? + end + def setup # Create a request with multiple query types @request_lines = [ From a0e405416307c1e50dafbbf9c8b586e24582b10e Mon Sep 17 00:00:00 2001 From: Reef Date: Sat, 31 Jan 2026 13:09:25 +0000 Subject: [PATCH 2/2] feat: Add job execution tracking (start/finish events) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Add support for LogStruct job execution events: - JobStartEntry for evt:start with src:job - JobFinishEntry for evt:finish with src:job These entries are linked to requests via the job_id → request_id mapping, allowing the full job lifecycle (enqueue → start → finish) to be tracked and grouped with the originating HTTP request. Also adds evt:enqueue detection for immediate job enqueues (in addition to existing evt:schedule for delayed jobs). --- lib/log_bench/log/job_finish_entry.rb | 39 ++++++ lib/log_bench/log/job_start_entry.rb | 39 ++++++ lib/log_bench/log/parser.rb | 32 ++++- test/test_job_execution_tracking.rb | 185 ++++++++++++++++++++++++++ 4 files changed, 293 insertions(+), 2 deletions(-) create mode 100644 lib/log_bench/log/job_finish_entry.rb create mode 100644 lib/log_bench/log/job_start_entry.rb create mode 100644 test/test_job_execution_tracking.rb diff --git a/lib/log_bench/log/job_finish_entry.rb b/lib/log_bench/log/job_finish_entry.rb new file mode 100644 index 0000000..13a9f63 --- /dev/null +++ b/lib/log_bench/log/job_finish_entry.rb @@ -0,0 +1,39 @@ +# frozen_string_literal: true + +module LogBench + module Log + class JobFinishEntry < Entry + attr_reader :job_id, :job_class, :duration_ms + + def initialize(json_data) + super + self.type = :job_finish + @job_id = extract_job_id + @job_class = json_data["job_class"] + @duration_ms = json_data["duration_ms"] + build_content_for_logstruct if logstruct_format? + end + + private + + def extract_job_id + json_data["job_id"] + end + + def logstruct_format? + json_data["evt"] == "finish" && json_data["src"] == "job" + end + + def build_content_for_logstruct + job_class = @job_class || "Job" + queue = json_data["queue_name"] + duration = @duration_ms ? " in #{@duration_ms.round(2)}ms" : "" + + parts = ["Finished #{job_class} (Job ID: #{@job_id})#{duration}"] + parts << "from #{queue}" if queue + + @content = parts.join(" ") + end + end + end +end diff --git a/lib/log_bench/log/job_start_entry.rb b/lib/log_bench/log/job_start_entry.rb new file mode 100644 index 0000000..dc9925e --- /dev/null +++ b/lib/log_bench/log/job_start_entry.rb @@ -0,0 +1,39 @@ +# frozen_string_literal: true + +module LogBench + module Log + class JobStartEntry < Entry + attr_reader :job_id, :job_class, :attempt + + def initialize(json_data) + super + self.type = :job_start + @job_id = extract_job_id + @job_class = json_data["job_class"] + @attempt = json_data["attempt"] + build_content_for_logstruct if logstruct_format? + end + + private + + def extract_job_id + json_data["job_id"] + end + + def logstruct_format? + json_data["evt"] == "start" && json_data["src"] == "job" + end + + def build_content_for_logstruct + job_class = @job_class || "Job" + queue = json_data["queue_name"] + attempt_info = @attempt && @attempt > 1 ? " (attempt #{@attempt})" : "" + + parts = ["Started #{job_class} (Job ID: #{@job_id})#{attempt_info}"] + parts << "from #{queue}" if queue + + @content = parts.join(" ") + end + end + end +end diff --git a/lib/log_bench/log/parser.rb b/lib/log_bench/log/parser.rb index 62bd838..e14ab99 100644 --- a/lib/log_bench/log/parser.rb +++ b/lib/log_bench/log/parser.rb @@ -39,6 +39,10 @@ def self.build_specific_entry(data) CallLineEntry.new(data) when :job_enqueue JobEnqueueEntry.new(data) + when :job_start + JobStartEntry.new(data) + when :job_finish + JobFinishEntry.new(data) else Entry.new(data) end @@ -75,6 +79,8 @@ def self.determine_json_type(data) return :sql if sql_message?(data) return :sql_call_line if call_stack_message?(data) return :job_enqueue if job_enqueue_message?(data) + return :job_start if job_start_message?(data) + return :job_finish if job_finish_message?(data) :other end @@ -133,14 +139,24 @@ def self.call_stack_message?(data) end def self.job_enqueue_message?(data) - # LogStruct uses evt:"schedule" with src:"job" - return true if data["evt"] == "schedule" && data["src"] == "job" + # LogStruct uses evt:"schedule" or evt:"enqueue" with src:"job" + return true if (data["evt"] == "schedule" || data["evt"] == "enqueue") && data["src"] == "job" # Lograge format message = normalize_message(extract_message(data)) message.match?(/Enqueued .+ \(Job ID: .+\)/) end + def self.job_start_message?(data) + # LogStruct uses evt:"start" with src:"job" + data["evt"] == "start" && data["src"] == "job" + end + + def self.job_finish_message?(data) + # LogStruct uses evt:"finish" with src:"job" + data["evt"] == "finish" && data["src"] == "job" + end + def self.extract_job_id_from_enqueue(message) normalized_message = normalize_message(message) match = normalized_message.match(/Job ID: ([^\)]+)/) @@ -170,6 +186,18 @@ def self.register_job_enqueue(entry) def self.enrich_job_entry(entry) return unless entry.respond_to?(:json_data) + # For JobStartEntry and JobFinishEntry, use job_id directly + if entry.is_a?(JobStartEntry) || entry.is_a?(JobFinishEntry) + job_id = entry.job_id + job_class = entry.job_class + if job_id + add_job_prefix_to_entry(entry, job_id, job_class) + add_request_id_to_entry(entry, job_id) + end + return + end + + # For other entries, try to extract job info from tags tags = entry.json_data["tags"] job_id, job_class = extract_job_info_from_tags(tags) return unless job_id diff --git a/test/test_job_execution_tracking.rb b/test/test_job_execution_tracking.rb new file mode 100644 index 0000000..25b2e29 --- /dev/null +++ b/test/test_job_execution_tracking.rb @@ -0,0 +1,185 @@ +# frozen_string_literal: true + +require "test_helper" + +class TestJobExecutionTracking < Minitest::Test + # LogStruct job execution event tests + def test_logstruct_job_start_detection + # LogStruct uses evt:"start" with src:"job" + data = {"src" => "job", "evt" => "start", "job_id" => "abc-123", "job_class" => "TestJob"} + assert LogBench::Log::Parser.job_start_message?(data) + + # Should not detect other events as start + enqueue_data = {"src" => "job", "evt" => "enqueue", "job_id" => "abc-123"} + refute LogBench::Log::Parser.job_start_message?(enqueue_data) + + finish_data = {"src" => "job", "evt" => "finish", "job_id" => "abc-123"} + refute LogBench::Log::Parser.job_start_message?(finish_data) + end + + def test_logstruct_job_finish_detection + # LogStruct uses evt:"finish" with src:"job" + data = {"src" => "job", "evt" => "finish", "job_id" => "abc-123", "job_class" => "TestJob", "duration_ms" => 123.45} + assert LogBench::Log::Parser.job_finish_message?(data) + + # Should not detect other events as finish + enqueue_data = {"src" => "job", "evt" => "enqueue", "job_id" => "abc-123"} + refute LogBench::Log::Parser.job_finish_message?(enqueue_data) + + start_data = {"src" => "job", "evt" => "start", "job_id" => "abc-123"} + refute LogBench::Log::Parser.job_finish_message?(start_data) + end + + def test_logstruct_job_start_entry_parsing + logstruct_log = '{"src":"job","evt":"start","job_id":"79729d72-f0df-468e-a6da-9064ec9e845e","job_class":"TestJob","queue_name":"default","attempt":1,"req_id":"8cc2f6c7-6fd9-4d41-8626-847a6f1c5bb9","ts":"2026-01-23T19:36:20.129+13:00"}' + + entry = LogBench::Log::Parser.parse_line(logstruct_log) + + assert_instance_of LogBench::Log::JobStartEntry, entry + assert_equal "79729d72-f0df-468e-a6da-9064ec9e845e", entry.job_id + assert_equal "TestJob", entry.job_class + assert_equal 1, entry.attempt + assert_equal "8cc2f6c7-6fd9-4d41-8626-847a6f1c5bb9", entry.request_id + end + + def test_logstruct_job_start_entry_content + logstruct_log = '{"src":"job","evt":"start","job_id":"79729d72-f0df-468e-a6da-9064ec9e845e","job_class":"TestJob","queue_name":"default","attempt":1,"req_id":"8cc2f6c7-6fd9-4d41-8626-847a6f1c5bb9","ts":"2026-01-23T19:36:20.129+13:00"}' + + entry = LogBench::Log::Parser.parse_line(logstruct_log) + + assert_match(/Started TestJob/, entry.content) + assert_match(/Job ID: 79729d72-f0df-468e-a6da-9064ec9e845e/, entry.content) + end + + def test_logstruct_job_start_entry_with_retry_attempt + logstruct_log = '{"src":"job","evt":"start","job_id":"79729d72-f0df-468e-a6da-9064ec9e845e","job_class":"TestJob","queue_name":"default","attempt":3,"req_id":"8cc2f6c7-6fd9-4d41-8626-847a6f1c5bb9","ts":"2026-01-23T19:36:20.129+13:00"}' + + entry = LogBench::Log::Parser.parse_line(logstruct_log) + + assert_instance_of LogBench::Log::JobStartEntry, entry + assert_equal 3, entry.attempt + assert_match(/attempt 3/, entry.content) + end + + def test_logstruct_job_finish_entry_parsing + logstruct_log = '{"src":"job","evt":"finish","job_id":"79729d72-f0df-468e-a6da-9064ec9e845e","job_class":"TestJob","queue_name":"default","duration_ms":123.45,"req_id":"8cc2f6c7-6fd9-4d41-8626-847a6f1c5bb9","ts":"2026-01-23T19:36:20.129+13:00"}' + + entry = LogBench::Log::Parser.parse_line(logstruct_log) + + assert_instance_of LogBench::Log::JobFinishEntry, entry + assert_equal "79729d72-f0df-468e-a6da-9064ec9e845e", entry.job_id + assert_equal "TestJob", entry.job_class + assert_equal 123.45, entry.duration_ms + assert_equal "8cc2f6c7-6fd9-4d41-8626-847a6f1c5bb9", entry.request_id + end + + def test_logstruct_job_finish_entry_content + logstruct_log = '{"src":"job","evt":"finish","job_id":"79729d72-f0df-468e-a6da-9064ec9e845e","job_class":"TestJob","queue_name":"default","duration_ms":123.45,"req_id":"8cc2f6c7-6fd9-4d41-8626-847a6f1c5bb9","ts":"2026-01-23T19:36:20.129+13:00"}' + + entry = LogBench::Log::Parser.parse_line(logstruct_log) + + assert_match(/Finished TestJob/, entry.content) + assert_match(/Job ID: 79729d72-f0df-468e-a6da-9064ec9e845e/, entry.content) + assert_match(/123\.45ms/, entry.content) + end + + def test_logstruct_full_job_lifecycle_with_request + request_id = "8cc2f6c7-6fd9-4d41-8626-847a6f1c5bb9" + job_id = "79729d72-f0df-468e-a6da-9064ec9e845e" + + # HTTP request + request_log = %({"src":"rails","evt":"request","method":"GET","path":"/","status":200,"duration_ms":62.57,"controller":"HomeController","action":"index","req_id":"#{request_id}","ts":"2026-01-23T19:36:20.157+13:00"}) + + # Job scheduled (enqueued) + schedule_log = %({"src":"job","evt":"schedule","job_id":"#{job_id}","job_class":"TestJob","queue_name":"default","req_id":"#{request_id}","ts":"2026-01-23T19:36:20.129+13:00"}) + + # Job started + start_log = %({"src":"job","evt":"start","job_id":"#{job_id}","job_class":"TestJob","queue_name":"default","attempt":1,"req_id":"#{request_id}","ts":"2026-01-23T19:36:22.000+13:00"}) + + # Job finished + finish_log = %({"src":"job","evt":"finish","job_id":"#{job_id}","job_class":"TestJob","queue_name":"default","duration_ms":1500.25,"req_id":"#{request_id}","ts":"2026-01-23T19:36:23.500+13:00"}) + + # Parse all logs + state = test_state + collection = LogBench::Log::Collection.new([request_log, schedule_log, start_log, finish_log]) + requests = collection.requests + + # Should have one request + assert_equal 1, requests.size + request = requests.first + assert_equal request_id, request.request_id + + # Should have 3 related logs: schedule, start, finish + assert_equal 3, request.related_logs.size + + # Verify each entry type + enqueue_entries = request.related_logs.select { |log| log.is_a?(LogBench::Log::JobEnqueueEntry) } + start_entries = request.related_logs.select { |log| log.is_a?(LogBench::Log::JobStartEntry) } + finish_entries = request.related_logs.select { |log| log.is_a?(LogBench::Log::JobFinishEntry) } + + assert_equal 1, enqueue_entries.size, "Should have 1 enqueue entry" + assert_equal 1, start_entries.size, "Should have 1 start entry" + assert_equal 1, finish_entries.size, "Should have 1 finish entry" + + # All should have the same job_id + assert_equal job_id, enqueue_entries.first.job_id + assert_equal job_id, start_entries.first.job_id + assert_equal job_id, finish_entries.first.job_id + + # All should have the same request_id + assert_equal request_id, enqueue_entries.first.request_id + assert_equal request_id, start_entries.first.request_id + assert_equal request_id, finish_entries.first.request_id + end + + def test_job_execution_linked_via_job_id_mapping + # This tests the scenario where job execution logs don't have request_id + # but can be linked via the job_id → request_id mapping + request_id = "req-abc-123" + job_id = "job-xyz-789" + + # HTTP request + request_log = %({"method":"POST","path":"/users","status":200,"request_id":"#{request_id}","timestamp":"2025-01-01T10:00:00Z"}) + + # Job enqueued (has request_id) + enqueue_log = %({"src":"job","evt":"schedule","job_id":"#{job_id}","job_class":"TestJob","req_id":"#{request_id}","ts":"2025-01-01T10:00:01Z"}) + + # Job started (NO request_id - simulating async execution) + start_log = %({"src":"job","evt":"start","job_id":"#{job_id}","job_class":"TestJob","attempt":1,"ts":"2025-01-01T10:00:05Z"}) + + # Job finished (NO request_id - simulating async execution) + finish_log = %({"src":"job","evt":"finish","job_id":"#{job_id}","job_class":"TestJob","duration_ms":500.0,"ts":"2025-01-01T10:00:05Z"}) + + # Parse all logs + state = test_state + collection = LogBench::Log::Collection.new([request_log, enqueue_log, start_log, finish_log]) + requests = collection.requests + + # Should have one request with all logs grouped + assert_equal 1, requests.size + request = requests.first + assert_equal request_id, request.request_id + + # Should have 3 related logs: enqueue, start, finish + assert_equal 3, request.related_logs.size + + # The start and finish entries should have been enriched with request_id + start_entries = request.related_logs.select { |log| log.is_a?(LogBench::Log::JobStartEntry) } + finish_entries = request.related_logs.select { |log| log.is_a?(LogBench::Log::JobFinishEntry) } + + assert_equal 1, start_entries.size + assert_equal 1, finish_entries.size + + # They should have request_id from the mapping + assert_equal request_id, start_entries.first.request_id, "Start entry should have request_id from job mapping" + assert_equal request_id, finish_entries.first.request_id, "Finish entry should have request_id from job mapping" + end + + private + + def test_state + # Reset and return fresh State for testing + LogBench::App::State.instance.instance_variable_set(:@job_ids_map, {}) + LogBench::App::State.instance + end +end