Skip to content

Emit canonical JSON request log lines via rails_semantic_logger - #2862

Open
mroderick wants to merge 1 commit into
masterfrom
feature/canonical-json-log-lines
Open

Emit canonical JSON request log lines via rails_semantic_logger#2862
mroderick wants to merge 1 commit into
masterfrom
feature/canonical-json-log-lines

Conversation

@mroderick

@mroderick mroderick commented Sep 9, 2026

Copy link
Copy Markdown
Collaborator

Planner's request logging is multi-line and unstructured, which makes request-level analysis (latency percentiles, error rates per controller) impractical outside the app. This PR emits one JSON log line per request, using the already-installed rails_semantic_logger.

Four files change: config/application.rb, config/environments/production.rb,
config/initializers/canonical_log.rb, and spec/requests/canonical_log_line_spec.rb.

Change:

  • Switch the stdout appender to JSON when RAILS_LOG_TO_STDOUT is set, and tag requests with the request id as a named tag, so it lands as a log field.
  • Add path_template to the request-completion payload. The value is the route's URI
    pattern including its optional format segment: /faq logs as /faq(.:format),
    /unsubscribe/:token as /unsubscribe/:token(.:format). payload.path still carries
    the raw path, so group on path_template.
  • Drop the production config.logger override; rails_semantic_logger replaces Rails.logger regardless, so the line was dead code.

Filtered request params stay in the lines; the log destination retains them for just over a year. The pipeline side flattens the nested JSON to its field contract.

Log line example

GET / on the dashboard, anonymous user, production config (RAILS_LOG_TO_STDOUT set).

Before (master), Ruby hash syntax -- not machine-parseable:

Before
2026-09-09T20:12:36 I [4744:puma srv tp 002] [1479b087-4a08-4264-9656-c8a52a0c768b] (136.3ms) DashboardController -- Completed #show -- {controller: "DashboardController", action: "show", format: "*/*", method: "GET", path: "/", status: 200, view_runtime: 42.77, db_runtime: 13.2, queries_count: 17, cached_queries_count: 0, allocations: 293512, cpu_time: 124.79, idle_time: 11.49, gc_time: 11.15, status_message: "OK"}

After, one JSON line per request:

After
{"host":"MacBookAir.localdomain","application":"Semantic Logger","environment":"production","timestamp":"2026-09-09T18:12:58.178703Z","level":"info","level_index":2,"pid":4792,"thread":"puma srv tp 002","duration_ms":142.09,"duration":"142.1ms","named_tags":{"request_id":"ba7e6e85-4e92-4986-b0ce-aaf920da6da5"},"name":"DashboardController","message":"Completed #show","payload":{"controller":"DashboardController","action":"show","format":"*/*","method":"GET","path":"/","status":200,"view_runtime":41.33,"db_runtime":17.64,"queries_count":17,"cached_queries_count":0,"path_template":"/","allocations":293522,"cpu_time":126.35,"idle_time":15.74,"gc_time":10.62,"status_message":"OK"},"metric":"rails.controller.process_action"}

Review notes

  • The payload patch (config/initializers/canonical_log.rb) prepends onto ActionController::Base and runs from the ensure in Rails' process_action, so failing requests also emit a line (status derived from the exception). That makes it global; it must also never raise while an exception is in flight. It only reads request.route_uri_pattern, which returns nil for unmatched routes.
  • config/environments/production.rb removes the config.logger override; rails_semantic_logger replaces Rails.logger in its own initializer. Verified that nothing in the app or its gems uses TaggedLogging-specific APIs: the only consumer, ActiveJob's logger.tagged, is API-compatible and covered by the suite, and a production-mode boot confirms Rails.logger is a SemanticLogger with working tagged. SemanticLogger does implement push_tags/pop_tags; nothing in the app calls them.
  • Filtered params stay in the log lines by decision. The filter list in config/initializers/filter_parameter_logging.rb is the privacy boundary; check you are comfortable with it (passwords, emails, tokens masked; free-text params not).
  • Deliberately not done: stripping params at the appender, capturing unmatched routes (they never reach a controller), and drain-silence alerting. All deferred to the pipeline side or follow-ups.
  • Test coverage is partial: spec/requests/canonical_log_line_spec.rb asserts the log event's fields, not the emitted JSON line, and does not cover the raising-request path.

Post-Deploy Monitoring & Validation

  • After enabling the Heroku log drain, confirm Completed lines arrive with named_tags.request_id and payload.path_template present.
  • Stream silent for more than 15 minutes: check the drain and Vector. No alerting in v1.
  • Rollback: revert this PR; app behaviour without RAILS_LOG_TO_STDOUT is unchanged from master.

@mroderick
mroderick force-pushed the feature/canonical-json-log-lines branch from 157c05e to 7a6dc73 Compare September 9, 2026 14:33
Planner's request logging is multi-line and unstructured, which makes
request-level analysis (latency percentiles, error rates per controller)
impractical outside the app. Emit one JSON line per request instead.

Switch the stdout appender to JSON when RAILS_LOG_TO_STDOUT is set and
tag requests with the request id as a named tag, so it lands as a log
field. Add path_template (the normalized route pattern, e.g.
/workshops/:id) to the request-completion payload so lines carry no raw
IDs or query strings.

Drop the production config.logger override: rails_semantic_logger
replaces Rails.logger regardless, so the TaggedLogging line was dead
code that obscured where logging is configured.
@mroderick
mroderick force-pushed the feature/canonical-json-log-lines branch from 8c77cf2 to 5cd28b5 Compare September 10, 2026 11:32
@mroderick
mroderick marked this pull request as ready for review September 10, 2026 11:39
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants