diff --git a/AGENTS.md b/AGENTS.md index db2340c7..1c110c5d 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -180,6 +180,10 @@ You do not need to check if these are defined with `defined?` - they are guarant - When handling objects with as_json method in Rails apps, consider whether ActiveSupport's default implementation or a custom implementation is being used - Use minitest mocks and stubs, not `def`, `Object`, etc. +## Commits and PRs + +- Refer to a GitHub issue as "Addresses #N" in commit messages and PR descriptions, never "Fixes #N" or "Closes #N". GitHub closes an issue when a commit that says "Fixes #N" reaches `main`, before the fix is released and without a reply, so the reporter isn't told which version has the fix. After the release, reply on the issue with the version and close it. + ## Code Comments - Comments should explain why code exists, not what it does diff --git a/CHANGELOG.md b/CHANGELOG.md index 2df6d609..ac9bfc31 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,12 @@ All notable changes to this project will be documented in this file. The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/), and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). +## [0.2.1] - 2026-10-18 + +### Fixed + +- **Lograge**: With `config.exceptions_app = routes`, a request whose action raises has one request line, the action's: the error page's controller no longer logs a second line as `GET /500`. When the error comes before any action (a routing error) or after it (in a middleware), the error page's line has the request's own method and path instead of `GET /404` (#28) + ## [0.2.0] - 2026-10-18 ### Changed diff --git a/Gemfile.lock b/Gemfile.lock index 48c8b6ed..9daa9362 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -1,7 +1,7 @@ PATH remote: . specs: - logstruct (0.2.0) + logstruct (0.2.1) actionpack (>= 7.1) activesupport (>= 7.1) globalid (>= 1.0) diff --git a/docs/app/docs/configuration/page.tsx b/docs/app/docs/configuration/page.tsx index a9ed3883..b6b90703 100644 --- a/docs/app/docs/configuration/page.tsx +++ b/docs/app/docs/configuration/page.tsx @@ -255,6 +255,16 @@ end`} The fields are added at the top level of the request line, and filtered like everything else.

+

+ With config.exceptions_app = routes, Rails renders an error page by sending the + request through your routes again as GET /500 (or /404,{' '} + /422). When an action raises, the request has one line, the action's, with + the error's status: the error page logs none. When the error comes before any action (a + routing error), the error page's line is the request's line, with the + request's own method and path. When a middleware raises after the action has finished, + the request has two lines: the action's, with the status the action returned, and the + error page's, with the error's status and the request's method and path. +

Custom String Scrubbing

diff --git a/lib/log_struct/integrations/lograge.rb b/lib/log_struct/integrations/lograge.rb index f748d451..12aea7fe 100644 --- a/lib/log_struct/integrations/lograge.rb +++ b/lib/log_struct/integrations/lograge.rb @@ -36,6 +36,20 @@ module Lograge T::Array[Symbol] ) + # With config.exceptions_app = routes, Rails renders an error page by sending the request through the app again + # as GET /, and keeps the request's own method and path in these headers + ORIGINAL_METHOD_HEADER = "action_dispatch.original_request_method" + ORIGINAL_PATH_HEADER = "action_dispatch.original_path" + # Set when the request's action logged a line with its error, so the error page for it logs none + ACTION_ERROR_LOGGED_HEADER = "logstruct.action_error_logged" + + # A Proc, not a Method: sorbet-runtime replaces a method with sig checks on its first call, so a Method taken + # before then isn't equal to one taken after, and setup couldn't tell it had added the test already + IGNORE_REPEATED_ERROR_PAGE = T.let( + ->(event) { Lograge.repeated_error_page?(event) }, + T.proc.params(event: ActiveSupport::Notifications::Event).returns(T::Boolean) + ) + class << self extend T::Sig @@ -77,6 +91,9 @@ def configure_lograge(logstruct_config) Integrations::Lograge.unsubscribe_rails_request_lines unless app.config.lograge.keep_original_rails_log end end + + # Lograge.setup adds the app's own ignore tests to the same list + ::Lograge.ignore(IGNORE_REPEATED_ERROR_PAGE) unless ::Lograge.ignore_tests.include?(IGNORE_REPEATED_ERROR_PAGE) end # Rails' "Processing by", "Completed 200 OK" and "Rendered" lines, which the request line replaces @@ -98,6 +115,7 @@ def lograge_default_options(event) :source_ip ).compact add_request_address(event.payload[:request], options) + add_error_page_request(event, options) if event.payload[:params].present? options[:params] = event.payload[:params].except("controller", "action") @@ -127,6 +145,29 @@ def add_request_address(request, options) end end + # An error page's line has the method and path of the request it's for, not GET /500 + sig { params(event: ActiveSupport::Notifications::Event, options: T::Hash[Symbol, T.untyped]).void } + def add_error_page_request(event, options) + request = event.payload[:request] + return unless request.is_a?(::ActionDispatch::Request) + + if request.has_header?(ORIGINAL_PATH_HEADER) + options[:method] = request.get_header(ORIGINAL_METHOD_HEADER) + options[:path] = "#{request.script_name}#{request.get_header(ORIGINAL_PATH_HEADER)}" + elsif event.payload[:exception] + request.set_header(ACTION_ERROR_LOGGED_HEADER, true) + end + end + + # The error page for an error its action's line logged would log the request a second time. A request whose + # error came before any action (a routing error) or after it (in a middleware) keeps its error page's line. + sig { params(event: ActiveSupport::Notifications::Event).returns(T::Boolean) } + def repeated_error_page?(event) + request = event.payload[:request] + request.is_a?(::ActionDispatch::Request) && request.has_header?(ORIGINAL_PATH_HEADER) && + request.get_header(ACTION_ERROR_LOGGED_HEADER) == true + end + # Process headers from the event payload sig { params(event: ActiveSupport::Notifications::Event, options: T::Hash[Symbol, T.untyped]).void } def process_headers(event, options) diff --git a/lib/log_struct/version.rb b/lib/log_struct/version.rb index 878fce15..f80d4665 100644 --- a/lib/log_struct/version.rb +++ b/lib/log_struct/version.rb @@ -2,5 +2,5 @@ # frozen_string_literal: true module LogStruct - VERSION = "0.2.0" + VERSION = "0.2.1" end diff --git a/rails_test_app/templates/app/controllers/errors_controller.rb b/rails_test_app/templates/app/controllers/errors_controller.rb new file mode 100644 index 00000000..814ed29c --- /dev/null +++ b/rails_test_app/templates/app/controllers/errors_controller.rb @@ -0,0 +1,11 @@ +# typed: true +# frozen_string_literal: true + +# The app's own error pages, for config.exceptions_app = routes (ErrorPagesTest turns them on). Rails sends the +# request here as GET /. +class ErrorsController < ApplicationController + def show + status = request.path_info.delete_prefix("/").to_i + render json: {status: status}, status: status + end +end diff --git a/rails_test_app/templates/config/application.rb.erb b/rails_test_app/templates/config/application.rb.erb index 8defd574..b811a4bb 100644 --- a/rails_test_app/templates/config/application.rb.erb +++ b/rails_test_app/templates/config/application.rb.erb @@ -24,6 +24,14 @@ module LogstructTestApp # Only use API mode config.api_only = true + # Rails' default error pages, or the app's own from its routes (config.exceptions_app = routes), which + # ErrorPagesTest turns on. An unset config.x setting is an empty, truthy OrderedOptions. + config.x.error_pages_from_routes = false + config.exceptions_app = lambda do |env| + exceptions_app = config.x.error_pages_from_routes ? routes : ActionDispatch::PublicExceptions.new(Rails.public_path) + exceptions_app.call(env) + end + # Use test adapter for ActiveJob in all environments for testing config.active_job.queue_adapter = :test diff --git a/rails_test_app/templates/config/routes.rb b/rails_test_app/templates/config/routes.rb index 37cc346b..ef578308 100644 --- a/rails_test_app/templates/config/routes.rb +++ b/rails_test_app/templates/config/routes.rb @@ -18,6 +18,9 @@ post "/security/submit", to: "security#submit" get "/security/remote_ip", to: "security#remote_ip" + # Error pages, for config.exceptions_app = routes + %w[400 404 422 500].each { |status| match "/#{status}", to: "errors#show", via: :all } + # Healthcheck route get "/health", to: proc { [200, {}, ["OK"]] } end diff --git a/rails_test_app/templates/test/integration/error_pages_test.rb b/rails_test_app/templates/test/integration/error_pages_test.rb new file mode 100644 index 00000000..0594f017 --- /dev/null +++ b/rails_test_app/templates/test/integration/error_pages_test.rb @@ -0,0 +1,56 @@ +# typed: true +# frozen_string_literal: true + +require "test_helper" + +# With config.exceptions_app = routes, Rails renders the error page by sending the request through the routes again +# as GET /, so the error page's controller logs a request line of its own +class ErrorPagesTest < ActionDispatch::IntegrationTest + # Rails' settings these tests change + SETTINGS = %w[action_dispatch.show_exceptions action_dispatch.show_detailed_exceptions].freeze + + setup do + @log_output = StringIO.new + ::SemanticLogger.clear_appenders! + ::SemanticLogger.add_appender(io: @log_output, formatter: LogStruct::SemanticLogger::Formatter.new, async: false) + @saved_env_config = Rails.application.env_config.slice(*SETTINGS) + Rails.application.env_config["action_dispatch.show_exceptions"] = :all + Rails.application.env_config["action_dispatch.show_detailed_exceptions"] = false + Rails.application.config.x.error_pages_from_routes = true + end + + teardown do + Rails.application.env_config.merge!(@saved_env_config) + Rails.application.config.x.error_pages_from_routes = false + end + + test "an action that raises logs one request line, its own" do + get "/logging/error" + + assert_response :internal_server_error + assert_equal({"status" => 500}, response.parsed_body) + assert_equal [["GET", "/logging/error", "LoggingController", "test_error", 500]], request_lines + end + + test "a POST whose action raises logs its own method and path" do + post "/security/submit" + + assert_response :unprocessable_entity + assert_equal [["POST", "/security/submit", "SecurityController", "submit", 422]], request_lines + end + + test "an error raised before any action logs the error page's line with the request's method and path" do + post "/no/such/route?page=2" + + assert_response :not_found + assert_equal [["POST", "/no/such/route", "ErrorsController", "show", 404]], request_lines + end + + private + + def request_lines + ::SemanticLogger.flush + @log_output.string.lines.map { |line| JSON.parse(line) }.select { |line| line["evt"] == "request" } + .map { |line| line.values_at("method", "path", "controller", "action", "status") } + end +end diff --git a/test/log_struct/integrations/lograge_error_pages_test.rb b/test/log_struct/integrations/lograge_error_pages_test.rb new file mode 100644 index 00000000..59bc693d --- /dev/null +++ b/test/log_struct/integrations/lograge_error_pages_test.rb @@ -0,0 +1,60 @@ +# typed: true +# frozen_string_literal: true + +require "test_helper" + +module LogStruct + module Integrations + # Error pages from the app's own controller (config.exceptions_app = routes). The Rails test app's ErrorPagesTest + # sends real requests through them. + class LogrageErrorPagesTest < ActiveSupport::TestCase + setup do + @request = ActionDispatch::Request.new(Rack::MockRequest.env_for("/orders/42", method: "POST")) + end + + test "an error the action's line logged makes the error page's line a repeat" do + Lograge.lograge_default_options(event(exception: ["RuntimeError", "Test error"])) + render_error_page + + assert Lograge.repeated_error_page?(event) + end + + test "an error after an action's line that logged none, such as a middleware's, keeps the error page's line" do + Lograge.lograge_default_options(event) + render_error_page + + refute Lograge.repeated_error_page?(event) + end + + test "an error page's line has the request's method, and its path under the app's mount point" do + @request.script_name = "/shop" + render_error_page + + assert_equal ["POST", "/shop/orders/42"], Lograge.lograge_default_options(event).values_at(:method, :path) + end + + test "only error pages are repeats" do + refute Lograge.repeated_error_page?(event(exception: ["RuntimeError", "Test error"])) + refute Lograge.repeated_error_page?(ActiveSupport::Notifications::Event.new("perform_action.action_cable", nil, nil, "id", {})) + end + + test "Lograge ignores repeated error pages, with one ignore test" do + assert_equal 1, ::Lograge.ignore_tests.count(Lograge::IGNORE_REPEATED_ERROR_PAGE) + end + + private + + # What ActionDispatch::ShowExceptions does before it calls the exceptions app + def render_error_page + @request.set_header("action_dispatch.original_path", @request.path_info) + @request.set_header("action_dispatch.original_request_method", @request.raw_request_method) + @request.path_info = "/500" + @request.request_method = "GET" + end + + def event(**payload) + ActiveSupport::Notifications::Event.new("process_action.action_controller", nil, nil, "id", {request: @request, **payload}) + end + end + end +end