Skip to content

Emit canonical JSON request log lines via rails_semantic_logger - #2862

Merged
olleolleolle merged 2 commits into
masterfrom
feature/canonical-json-log-lines
Sep 14, 2026
Merged

olleolleolle merged 2 commits 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.

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.
  • Name the app in the lines (application: "planner") instead of the RSL default ("Semantic Logger").
  • Emit through a CanonicalJsonFormatter that drops three redundant fields: duration (string duplicate of duration_ms), level_index (derivable from level), and payload.status_message (derivable from status). duration_ms keeps its raw float value.
  • Declare the stdout appender via config.rails_semantic_logger.appenders instead of the deprecated add_file_appender= writer.

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":"nuc","application":"planner","environment":"production","timestamp":"2026-09-13T14:28:16.336301Z","level":"info","pid":541840,"thread":"puma srv tp 001","duration_ms":1136.7818240225315,"named_tags":{"request_id":"6a804310-1ab7-47cc-81ed-398a6d31ef75"},"name":"DashboardController","message":"Completed #show","payload":{"controller":"DashboardController","action":"show","format":"*/*","method":"GET","path":"/","status":200,"view_runtime":900.07,"db_runtime":28.31,"queries_count":8,"cached_queries_count":0,"path_template":"/","allocations":1495845,"cpu_time":1112.22,"idle_time":24.56,"gc_time":137.32},"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 2 times, most recently 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
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.
Set SemanticLogger.application to planner so canonical lines carry the
app name instead of the RSL default ("Semantic Logger"), and emit stdout
lines through a CanonicalJsonFormatter that drops three redundant fields:
duration (string duplicate of duration_ms), level_index (derivable from
level), and payload.status_message (derivable from status).

Declare the stdout appender via config.rails_semantic_logger.appenders,
the current API, instead of the deprecated add_file_appender= writer.
Declaring appenders also stops RSL building its default file appender.
@mroderick
mroderick force-pushed the feature/canonical-json-log-lines branch from 5cd28b5 to d0e3e4e Compare September 13, 2026 15:08

@olleolleolle olleolleolle left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Excellent!

@olleolleolle
olleolleolle merged commit 3dc13a7 into master Sep 14, 2026
10 checks passed
@olleolleolle
olleolleolle deleted the feature/canonical-json-log-lines branch September 14, 2026 10:17
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.

3 participants