Log govuk request id in json in whitehall #300

yuetylauiris · 2023-06-22T15:56:55Z

Change Rails logger to log in JSON format including govuk_request_id for traceability.
Remove the $real_stdout, $stdout and $stderr redirection because LOGIT is able to consume not JSON logs now.

Related Trello card: https://trello.com/c/cfTa0MXn/58-story-log-govukrequestid-from-railslogger-in-whitehall-and-its-worker

ollietreend

Edit: oops! I hit 'submit' too soon.

Your changes look good, but I've just added some comments about the format of the changelog.

It'd also be good to include a link to the Trello card in the PR description. That way it'll automatically appear on the Trello card as a checklist item, and will make it easy for others to understand the context of this change within the team's backlog.

CHANGELOG.md

lib/govuk_app_config/govuk_logging.rb

ollietreend

One more thing! (I submitted the other one too soon)

ollietreend · 2023-06-26T17:16:47Z

lib/govuk_app_config/govuk_logging.rb

+        begin
+          message = JSON.parse(msg)
+        rescue JSON::ParserError, TypeError => _e
+          message = msg
+        end


This seems a bit gnarly 😞 so the logged message could maybe be a JSON string, but maybe be plain text? Is that because the log could have come from Logstasher (as a JSON string) or Rails.logger.info (as plain text)?

If so, it might be worth adding a comment here to explain that. It seems like one of those weird little details that people won't be aware of most of the time.

I wonder if we actually need this. I'm expecting we've got it because of:

govuk_app_config/lib/govuk_app_config/rails_ext/action_dispatch/debug_exceptions.rb

Lines 42 to 46 in e615e9b

logger.fatal({

exception_class: exception.class.to_s,

exception_message: exception.message,

stacktrace: trace,

}.to_json)

but we can probably change that from being JSON formatted - I assume there isn't any apps that routinely log in JSON.

So I'd imagine we can get rid of this one bit of JSON logging and then save having to catch an exception for presumably every other log entry

This seems a bit gnarly 😞 so the logged message could maybe be a JSON string, but maybe be plain text? Is that because the log could have come from Logstasher (as a JSON string) or Rails.logger.info (as plain text)?

If so, it might be worth adding a comment here to explain that. It seems like one of those weird little details that people won't be aware of most of the time.

In short yes, the log might be json or not, and no, those logs are separated from logstashers. I totally agree on it is not pretty, maybe we can do a bit refactoring and add some comments

I wonder if we actually need this. I'm expecting we've got it because of:

govuk_app_config/lib/govuk_app_config/rails_ext/action_dispatch/debug_exceptions.rb

Lines 42 to 46 in e615e9b

logger.fatal({

exception_class: exception.class.to_s,

exception_message: exception.message,

stacktrace: trace,

}.to_json)

but we can probably change that from being JSON formatted - I assume there isn't any apps that routinely log in JSON.
So I'd imagine we can get rid of this one bit of JSON logging and then save having to catch an exception for presumably every other log entry

I believe this monkeypatch only works for errors so we still need that piece of code :(

Ah sorry that wasn't what I meant. I'll try rephrase: Excluding debug_exceptions.rb, what's the evidence that we have JSON strings sent to the logger?

Yeah that's a TIL to me that they're different. I wonder if it's because they don't have tagged logging (like my example did with the UUID at the start) and thus have been recognised as JSON.

It seems to be something we must have only got with the recent replatfoming change of Kibana version too, so the parsing looks rather new

Even if we did parse the JSON they'd be in a somewhat weird spot though and be message.exception_class rather than a top level field (as we don't merge them)

Conceptually the message is the content we want to log - the main information of what is happening. It can be string or json and logit is being very clever about it whenever it happens to be json. If it's json the fields become available at the top level and are queriable.

The other fields are just meta-information about the context of the message. If we pull every field in the json-message into the meta-level, then what do we log as "the message"?

We changed the error log output to be a full stack trace as a string, which allows us to remove the gnarly json parsing bit.

the new error log looks like this

lib/govuk_app_config/govuk_logging.rb

spec/lib/govuk_logging_spec.rb

kevindew

Great stuff, this looks almost ready to merge now. I found just a minor thing.

I do have a curveball to throw into the mix though. I don't think we need the monkey patch anymore, as I think - by changing that to output text it now behaves as the code did without the monkeypatch.

Here's an example from me running locally:

With the monkeypatch:

{"@timestamp":"2023-06-29T11:48:13.101Z","message":"\nRuntimeError - Forced error:\n  app/controllers/homepage_controller.rb:6:in `index'\n  actionpack (7.0.5) lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'\n  actionpack (7.0.5) lib/abstract_controller/base.rb:215:in `process_action'\n  actionpack (7.0.5) lib/action_controller/metal/rendering.rb:165:in `process_action'\n  actionpack (7.0.5) lib/abstract_controller/callbacks.rb:234:in `block in process_action'\n  activesupport (7.0.5) lib/active_support/callbacks.rb:107:in `run_callbacks'\n  actionpack (7.0.5) lib/abstract_controller/callbacks.rb:233:in `process_action'\n  actionpack (7.0.5) lib/action_controller/metal/rescue.rb:22:in `process_action'\n  logstasher (2.1.5) lib/logstasher/rails_ext/action_controller/metal/instrumentation.rb:40:in `block in process_action'\n  activesupport (7.0.5) lib/active_support/notifications.rb:206:in `block in instrument'\n  activesupport (7.0.5) lib/active_support/notifications/instrumenter.rb:24:in `instrument'\n  activesupport (7.0.5) lib/active_support/notifications.rb:206:in `instrument'\n  logstasher (2.1.5) lib/logstasher/rails_ext/action_controller/metal/instrumentation.rb:27:in `process_action'\n  actionpack (7.0.5) lib/action_controller/metal/params_wrapper.rb:259:in `process_action'\n  actionpack (7.0.5) lib/abstract_controller/base.rb:151:in `process'\n  actionview (7.0.5) lib/action_view/rendering.rb:39:in `process'\n  actionpack (7.0.5) lib/action_controller/metal.rb:188:in `dispatch'\n  actionpack (7.0.5) lib/action_controller/metal.rb:251:in `dispatch'\n  actionpack (7.0.5) lib/action_dispatch/routing/route_set.rb:49:in `dispatch'\n  actionpack (7.0.5) lib/action_dispatch/routing/route_set.rb:32:in `serve'\n  actionpack (7.0.5) lib/action_dispatch/journey/router.rb:50:in `block in serve'\n  actionpack (7.0.5) lib/action_dispatch/journey/router.rb:32:in `serve'\n  actionpack (7.0.5) lib/action_dispatch/routing/route_set.rb:852:in `call'\n  slimmer (18.1.0) lib/slimmer/app.rb:31:in `call'\n  /Users/kevin.dew/govuk/govuk_app_config/lib/govuk_app_config/govuk_proxy/static_proxy.rb:15:in `perform_request'\n  rack-proxy (0.7.6) lib/rack/proxy.rb:87:in `call'\n  gds-api-adapters (88.2.0) lib/gds_api/middleware/govuk_header_sniffer.rb:12:in `call'\n  gds-api-adapters (88.2.0) lib/gds_api/middleware/govuk_header_sniffer.rb:12:in `call'\n  gds-api-adapters (88.2.0) lib/gds_api/middleware/govuk_header_sniffer.rb:12:in `call'\n  gds-api-adapters (88.2.0) lib/gds_api/middleware/govuk_header_sniffer.rb:12:in `call'\n  gds-api-adapters (88.2.0) lib/gds_api/middleware/govuk_header_sniffer.rb:12:in `call'\n  rack (2.2.7) lib/rack/tempfile_reaper.rb:15:in `call'\n  rack (2.2.7) lib/rack/etag.rb:27:in `call'\n  rack (2.2.7) lib/rack/conditional_get.rb:27:in `call'\n  rack (2.2.7) lib/rack/head.rb:12:in `call'\n  actionpack (7.0.5) lib/action_dispatch/http/permissions_policy.rb:38:in `call'\n  actionpack (7.0.5) lib/action_dispatch/http/content_security_policy.rb:36:in `call'\n  rack (2.2.7) lib/rack/session/abstract/id.rb:266:in `context'\n  rack (2.2.7) lib/rack/session/abstract/id.rb:260:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/cookies.rb:704:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'\n  activesupport (7.0.5) lib/active_support/callbacks.rb:99:in `run_callbacks'\n  actionpack (7.0.5) lib/action_dispatch/middleware/callbacks.rb:26:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/executor.rb:14:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/actionable_exceptions.rb:17:in `call'\n  sentry-rails (5.9.0) lib/sentry/rails/rescued_exception_interceptor.rb:12:in `call'\n  better_errors (2.10.1) lib/better_errors/middleware.rb:87:in `protected_app_call'\n  better_errors (2.10.1) lib/better_errors/middleware.rb:82:in `better_errors_call'\n  better_errors (2.10.1) lib/better_errors/middleware.rb:60:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/debug_exceptions.rb:28:in `call'\n  sentry-ruby (5.9.0) lib/sentry/rack/capture_exceptions.rb:28:in `block (2 levels) in call'\n  sentry-ruby (5.9.0) lib/sentry/hub.rb:220:in `with_session_tracking'\n  sentry-ruby (5.9.0) lib/sentry-ruby.rb:385:in `with_session_tracking'\n  sentry-ruby (5.9.0) lib/sentry/rack/capture_exceptions.rb:19:in `block in call'\n  sentry-ruby (5.9.0) lib/sentry/hub.rb:59:in `with_scope'\n  sentry-ruby (5.9.0) lib/sentry-ruby.rb:365:in `with_scope'\n  sentry-ruby (5.9.0) lib/sentry/rack/capture_exceptions.rb:18:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/show_exceptions.rb:26:in `call'\n  logstasher (2.1.5) lib/logstasher/rails_ext/rack/logger.rb:16:in `call_app'\n  railties (7.0.5) lib/rails/rack/logger.rb:27:in `call'\n  sprockets-rails (3.4.2) lib/sprockets/rails/quiet_assets.rb:13:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/remote_ip.rb:93:in `call'\n  request_store (1.5.1) lib/request_store/middleware.rb:19:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/request_id.rb:26:in `call'\n  rack (2.2.7) lib/rack/method_override.rb:24:in `call'\n  rack (2.2.7) lib/rack/runtime.rb:22:in `call'\n  activesupport (7.0.5) lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/server_timing.rb:61:in `block in call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/server_timing.rb:26:in `collect_events'\n  actionpack (7.0.5) lib/action_dispatch/middleware/server_timing.rb:60:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/executor.rb:14:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/static.rb:23:in `call'\n  rack (2.2.7) lib/rack/sendfile.rb:110:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/host_authorization.rb:137:in `call'\n  invalid_utf8_rejector (0.0.4) lib/invalid_utf8_rejector/middleware.rb:11:in `call'\n  railties (7.0.5) lib/rails/engine.rb:530:in `call'\n  railties (7.0.5) lib/rails/railtie.rb:226:in `method_missing'\n  puma (6.3.0) lib/puma/configuration.rb:270:in `call'\n  puma (6.3.0) lib/puma/request.rb:100:in `block in handle_request'\n  puma (6.3.0) lib/puma/thread_pool.rb:344:in `with_force_shutdown'\n  puma (6.3.0) lib/puma/request.rb:99:in `handle_request'\n  puma (6.3.0) lib/puma/server.rb:443:in `process_client'\n  puma (6.3.0) lib/puma/server.rb:245:in `block in run'\n  puma (6.3.0) lib/puma/thread_pool.rb:151:in `block in spawn_thread'\n","level":"FATAL","tags":["rails"]}

Without the monkeypatch:

{"@timestamp":"2023-06-29T11:47:26.491Z","message":"\nRuntimeError - Forced error:\n  app/controllers/homepage_controller.rb:6:in `index'\n  actionpack (7.0.5) lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'\n  actionpack (7.0.5) lib/abstract_controller/base.rb:215:in `process_action'\n  actionpack (7.0.5) lib/action_controller/metal/rendering.rb:165:in `process_action'\n  actionpack (7.0.5) lib/abstract_controller/callbacks.rb:234:in `block in process_action'\n  activesupport (7.0.5) lib/active_support/callbacks.rb:107:in `run_callbacks'\n  actionpack (7.0.5) lib/abstract_controller/callbacks.rb:233:in `process_action'\n  actionpack (7.0.5) lib/action_controller/metal/rescue.rb:22:in `process_action'\n  logstasher (2.1.5) lib/logstasher/rails_ext/action_controller/metal/instrumentation.rb:40:in `block in process_action'\n  activesupport (7.0.5) lib/active_support/notifications.rb:206:in `block in instrument'\n  activesupport (7.0.5) lib/active_support/notifications/instrumenter.rb:24:in `instrument'\n  activesupport (7.0.5) lib/active_support/notifications.rb:206:in `instrument'\n  logstasher (2.1.5) lib/logstasher/rails_ext/action_controller/metal/instrumentation.rb:27:in `process_action'\n  actionpack (7.0.5) lib/action_controller/metal/params_wrapper.rb:259:in `process_action'\n  actionpack (7.0.5) lib/abstract_controller/base.rb:151:in `process'\n  actionview (7.0.5) lib/action_view/rendering.rb:39:in `process'\n  actionpack (7.0.5) lib/action_controller/metal.rb:188:in `dispatch'\n  actionpack (7.0.5) lib/action_controller/metal.rb:251:in `dispatch'\n  actionpack (7.0.5) lib/action_dispatch/routing/route_set.rb:49:in `dispatch'\n  actionpack (7.0.5) lib/action_dispatch/routing/route_set.rb:32:in `serve'\n  actionpack (7.0.5) lib/action_dispatch/journey/router.rb:50:in `block in serve'\n  actionpack (7.0.5) lib/action_dispatch/journey/router.rb:32:in `serve'\n  actionpack (7.0.5) lib/action_dispatch/routing/route_set.rb:852:in `call'\n  slimmer (18.1.0) lib/slimmer/app.rb:31:in `call'\n  /Users/kevin.dew/govuk/govuk_app_config/lib/govuk_app_config/govuk_proxy/static_proxy.rb:15:in `perform_request'\n  rack-proxy (0.7.6) lib/rack/proxy.rb:87:in `call'\n  gds-api-adapters (88.2.0) lib/gds_api/middleware/govuk_header_sniffer.rb:12:in `call'\n  gds-api-adapters (88.2.0) lib/gds_api/middleware/govuk_header_sniffer.rb:12:in `call'\n  gds-api-adapters (88.2.0) lib/gds_api/middleware/govuk_header_sniffer.rb:12:in `call'\n  gds-api-adapters (88.2.0) lib/gds_api/middleware/govuk_header_sniffer.rb:12:in `call'\n  gds-api-adapters (88.2.0) lib/gds_api/middleware/govuk_header_sniffer.rb:12:in `call'\n  rack (2.2.7) lib/rack/tempfile_reaper.rb:15:in `call'\n  rack (2.2.7) lib/rack/etag.rb:27:in `call'\n  rack (2.2.7) lib/rack/conditional_get.rb:27:in `call'\n  rack (2.2.7) lib/rack/head.rb:12:in `call'\n  actionpack (7.0.5) lib/action_dispatch/http/permissions_policy.rb:38:in `call'\n  actionpack (7.0.5) lib/action_dispatch/http/content_security_policy.rb:36:in `call'\n  rack (2.2.7) lib/rack/session/abstract/id.rb:266:in `context'\n  rack (2.2.7) lib/rack/session/abstract/id.rb:260:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/cookies.rb:704:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'\n  activesupport (7.0.5) lib/active_support/callbacks.rb:99:in `run_callbacks'\n  actionpack (7.0.5) lib/action_dispatch/middleware/callbacks.rb:26:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/executor.rb:14:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/actionable_exceptions.rb:17:in `call'\n  sentry-rails (5.9.0) lib/sentry/rails/rescued_exception_interceptor.rb:12:in `call'\n  better_errors (2.10.1) lib/better_errors/middleware.rb:87:in `protected_app_call'\n  better_errors (2.10.1) lib/better_errors/middleware.rb:82:in `better_errors_call'\n  better_errors (2.10.1) lib/better_errors/middleware.rb:60:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/debug_exceptions.rb:28:in `call'\n  sentry-ruby (5.9.0) lib/sentry/rack/capture_exceptions.rb:28:in `block (2 levels) in call'\n  sentry-ruby (5.9.0) lib/sentry/hub.rb:220:in `with_session_tracking'\n  sentry-ruby (5.9.0) lib/sentry-ruby.rb:385:in `with_session_tracking'\n  sentry-ruby (5.9.0) lib/sentry/rack/capture_exceptions.rb:19:in `block in call'\n  sentry-ruby (5.9.0) lib/sentry/hub.rb:59:in `with_scope'\n  sentry-ruby (5.9.0) lib/sentry-ruby.rb:365:in `with_scope'\n  sentry-ruby (5.9.0) lib/sentry/rack/capture_exceptions.rb:18:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/show_exceptions.rb:26:in `call'\n  logstasher (2.1.5) lib/logstasher/rails_ext/rack/logger.rb:16:in `call_app'\n  railties (7.0.5) lib/rails/rack/logger.rb:27:in `call'\n  sprockets-rails (3.4.2) lib/sprockets/rails/quiet_assets.rb:13:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/remote_ip.rb:93:in `call'\n  request_store (1.5.1) lib/request_store/middleware.rb:19:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/request_id.rb:26:in `call'\n  rack (2.2.7) lib/rack/method_override.rb:24:in `call'\n  rack (2.2.7) lib/rack/runtime.rb:22:in `call'\n  activesupport (7.0.5) lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/server_timing.rb:61:in `block in call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/server_timing.rb:26:in `collect_events'\n  actionpack (7.0.5) lib/action_dispatch/middleware/server_timing.rb:60:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/executor.rb:14:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/static.rb:23:in `call'\n  rack (2.2.7) lib/rack/sendfile.rb:110:in `call'\n  actionpack (7.0.5) lib/action_dispatch/middleware/host_authorization.rb:137:in `call'\n  invalid_utf8_rejector (0.0.4) lib/invalid_utf8_rejector/middleware.rb:11:in `call'\n  railties (7.0.5) lib/rails/engine.rb:530:in `call'\n  railties (7.0.5) lib/rails/railtie.rb:226:in `method_missing'\n  puma (6.3.0) lib/puma/configuration.rb:270:in `call'\n  puma (6.3.0) lib/puma/request.rb:100:in `block in handle_request'\n  puma (6.3.0) lib/puma/thread_pool.rb:344:in `with_force_shutdown'\n  puma (6.3.0) lib/puma/request.rb:99:in `handle_request'\n  puma (6.3.0) lib/puma/server.rb:443:in `process_client'\n  puma (6.3.0) lib/puma/server.rb:245:in `block in run'\n  puma (6.3.0) lib/puma/thread_pool.rb:151:in `block in spawn_thread'\n","level":"FATAL","tags":["rails"]}

Oh and to save you a bunch of time parsing/comparing these super long lines, the only difference is in the timestamp

CHANGELOG.md

spec/lib/govuk_logging_spec.rb

kevindew · 2023-06-29T17:27:11Z

Just a heads up that I'm out at a conference tomorrow (Friday) and on leave Monday, but you shouldn't need to wait for me to approve as I think you're just about there - though looks like some WIP stuff is in at the mo so didn't want to approve.

I did notice that two of the conversations I've opened have been marked as resolved without the changes applied so assume there was either a communication issue, a mistake or still work-in-progress. I'll just highlight them for clarity:

#300 (comment) requesting: /~https://github.com/alphagov/govuk_app_config/pull/300/files#diff-06572a96a58dc510037d5efa622f9bec8519bc1beab13c9f251e97e657a9d4edR3 to be changed to * Add govuk_request_id to JSON logging for apps with gds-api-adapters ([#300](/~https://github.com/alphagov/govuk_app_config/pull/300))

#300 (comment) requesting the deletion of: /~https://github.com/alphagov/govuk_app_config/pull/300/files#diff-45d9c2f711166ef24efefacb50998affe202ae140a2385005721b33d8af8ab83R141-R145 since we don't need it anymore as the class is stubbed in the test.

kevindew

Just spotted a minor thing too.

spec/lib/govuk_logging_spec.rb

kevindew

I've made a couple of suggestions to remove the version bump from this because @lauraghiorghisor-tw's PR (#302) should probably go out in the same release, so we can do the releasing of both when things are merging.

Generally we tend to normally merge things into our gems without bumping the version, and just use a bump in a PR for a gem that changes infrequently and the change is small. So you may find it better to start PRs on our gems with instead adding items to an Unreleased list.

CHANGELOG.md

lib/govuk_app_config/version.rb

yuetylauiris · 2023-07-03T09:48:00Z

Just a heads up that I'm out at a conference tomorrow (Friday) and on leave Monday, but you shouldn't need to wait for me to approve as I think you're just about there - though looks like some WIP stuff is in at the mo so didn't want to approve.

I did notice that two of the conversations I've opened have been marked as resolved without the changes applied so assume there was either a communication issue, a mistake or still work-in-progress. I'll just highlight them for clarity:

#300 (comment) requesting: /~https://github.com/alphagov/govuk_app_config/pull/300/files#diff-06572a96a58dc510037d5efa622f9bec8519bc1beab13c9f251e97e657a9d4edR3 to be changed to * Add govuk_request_id to JSON logging for apps with gds-api-adapters ([#300](/~https://github.com/alphagov/govuk_app_config/pull/300))

#300 (comment) requesting the deletion of: /~https://github.com/alphagov/govuk_app_config/pull/300/files#diff-45d9c2f711166ef24efefacb50998affe202ae140a2385005721b33d8af8ab83R141-R145 since we don't need it anymore as the class is stubbed in the test.

Hey you are right, I missed those two changes and added them back now :D

kevindew

Just a few minor things to fix then good to go.

kevindew · 2023-07-04T08:53:33Z

CHANGELOG.md

+* Add govuk_request_id to JSON logging for apps with gds-api-adapters ([#300](/~https://github.com/alphagov/govuk_app_config/pull/300))
+* BREAKING: Remove $stdout, $stderr and $real_stdout redirections ([#300](/~https://github.com/alphagov/govuk_app_config/pull/300))
+* BREAKING: Change error log behaviour from logging JSON to full string ([#300](/~https://github.com/alphagov/govuk_app_config/pull/300))
+* BREAKING: Remove monkeypatch for errors ([#300](/~https://github.com/alphagov/govuk_app_config/pull/300))


Nit: this isn't a breaking change

lib/govuk_app_config/govuk_logging.rb

kevindew · 2023-07-04T11:49:22Z

This looks good, looks you've still got a linting to fix and we noticed in #302 that the readme should be updated: #302 (comment)

@lauraghiorghisor-tw not too sure why you've tagged @theseanything for a review? did you mean to do this on the other PR. If you meant to get a review from the team that owns this repo it's #govuk-platform-security-reliability-team which has @ChrisBAshton as a tech lead.

We added a custom formatter to rails logger so that it logs out in JSON format. By doing this we no longer need to redirect stdout to stderr, so we remove that piece of logic. Thus now logs from both Rails.logger and logstasher are sent to stdout. Co-authored-by: Neamah Al Selwi <neamah.alselwi@digital.cabinet-office.gov.uk>

We have added govuk_request_id to the logs. This is to increase traceability. Also, we changed the logs to log into json format and send them to stdout and show them in kibabna logs and doesn't send the logs into stderr. Co-authored-by: Iris Lau <iris.lau@digital.cabinet-office.gov.uk> Co-authored-by: Tuomas Nylund <tuomas.nylund@digital.cabinet-office.gov.uk>

The redirection was a workaround for log file parsers and it is no longer needed. So we remove that part and simplify the logger settings. Co-authored-by: Neamah Al-Selwi <neamah.alselwi@digital.cabinet-office.gov.uk> Co-authored-by: Tuomas Nylund <tuomas.nylund@digital.cabinet-office.gov.uk>

In order to avoid complexity around parsing JSON, we log errors in one full string now Co-authored-by: Neamah Al-Selwi <neamah.alselwi@digital.cabinet-office.gov.uk> Co-authored-by: Tuomas Nylund <tuomas.nylund@digital.cabinet-office.gov.uk>

A monkeypatch in RailsExt::ActionDispatch existed to convert errors to pretty JSON. Now that we have set the default logger to log in JSON the transformed error message becomes a stringified JSON and not the best for error viewing. By removing the monkeypatch it should logs error nicely via logger we set. Co-authored-by: Neamah Al-Selwi <neamah.alselwi@digital.cabinet-office.gov.uk> Co-authored-by: Tuomas Nylund <tuomas.nylund@digital.cabinet-office.gov.uk>

Co-authored-by: Ollie Treend <ollie.treend@digital.cabinet-office.gov.uk> Co-authored-by: Neamah Al-Selwi <neamah.alselwi@digital.cabinet-office.gov.uk> Co-authored-by: Tuomas Nylund <tuomas.nylund@digital.cabinet-office.gov.uk>

Co-authored-by: Neamah Al-Selwi <neamah.alselwi@digital.cabinet-office.gov.uk> Co-authored-by: Tuomas Nylund <tuomas.nylund@digital.cabinet-office.gov.uk> Co-authored-by: Laura Ghiorghisor <laura.ghiorghisor@digital.cabinet-office.gov.uk>

yuetylauiris force-pushed the Log-GOVUK_REQUEST_ID-in-Json-in-Whitehall branch from 6284094 to 565535d Compare June 26, 2023 14:15

yuetylauiris requested review from kevindew, ChrisBAshton and ollietreend June 26, 2023 14:59

ollietreend reviewed Jun 26, 2023

View reviewed changes

CHANGELOG.md Outdated Show resolved Hide resolved

lib/govuk_app_config/govuk_logging.rb Outdated Show resolved Hide resolved

ollietreend reviewed Jun 26, 2023

View reviewed changes

kevindew reviewed Jun 26, 2023

View reviewed changes

lib/govuk_app_config/govuk_logging.rb Outdated Show resolved Hide resolved

kevindew reviewed Jun 26, 2023

View reviewed changes

spec/lib/govuk_logging_spec.rb Outdated Show resolved Hide resolved

yuetylauiris force-pushed the Log-GOVUK_REQUEST_ID-in-Json-in-Whitehall branch 4 times, most recently from b5a8741 to df574dd Compare June 27, 2023 14:11

kevindew reviewed Jun 29, 2023

View reviewed changes

CHANGELOG.md Outdated Show resolved Hide resolved

spec/lib/govuk_logging_spec.rb Outdated Show resolved Hide resolved

kevindew reviewed Jun 29, 2023

View reviewed changes

spec/lib/govuk_logging_spec.rb Outdated Show resolved Hide resolved

spec/lib/govuk_logging_spec.rb Outdated Show resolved Hide resolved

spec/lib/govuk_logging_spec.rb Outdated Show resolved Hide resolved

kevindew mentioned this pull request Jun 30, 2023

Enable production-like logs if env variable is set #302

Merged

kevindew reviewed Jun 30, 2023

View reviewed changes

CHANGELOG.md Show resolved Hide resolved

lib/govuk_app_config/version.rb Show resolved Hide resolved

yuetylauiris force-pushed the Log-GOVUK_REQUEST_ID-in-Json-in-Whitehall branch from dfeecc7 to 8a88238 Compare July 3, 2023 09:46

kevindew reviewed Jul 4, 2023

View reviewed changes

yuetylauiris force-pushed the Log-GOVUK_REQUEST_ID-in-Json-in-Whitehall branch 2 times, most recently from a7820cf to 5b7aa59 Compare July 4, 2023 10:36

lauraghiorghisor-tw requested a review from theseanything July 4, 2023 10:49

lauraghiorghisor-tw removed the request for review from theseanything July 4, 2023 15:55

yuetylauiris force-pushed the Log-GOVUK_REQUEST_ID-in-Json-in-Whitehall branch from 5b7aa59 to f2d4faa Compare July 4, 2023 15:58

yuetylauiris and others added 2 commits July 5, 2023 10:18

yuetylauiris force-pushed the Log-GOVUK_REQUEST_ID-in-Json-in-Whitehall branch from f2d4faa to 9efd348 Compare July 5, 2023 09:30

yuetylauiris and others added 3 commits July 5, 2023 10:34

Log error in a full string instead of json

e13795b

In order to avoid complexity around parsing JSON, we log errors in one full string now Co-authored-by: Neamah Al-Selwi <neamah.alselwi@digital.cabinet-office.gov.uk> Co-authored-by: Tuomas Nylund <tuomas.nylund@digital.cabinet-office.gov.uk>

Update CHANGELOG.md

3f7a9b9

Co-authored-by: Ollie Treend <ollie.treend@digital.cabinet-office.gov.uk> Co-authored-by: Neamah Al-Selwi <neamah.alselwi@digital.cabinet-office.gov.uk> Co-authored-by: Tuomas Nylund <tuomas.nylund@digital.cabinet-office.gov.uk>

yuetylauiris force-pushed the Log-GOVUK_REQUEST_ID-in-Json-in-Whitehall branch from 9efd348 to 3f7a9b9 Compare July 5, 2023 09:35

tunylund approved these changes Jul 5, 2023

View reviewed changes

Bump version 9.0.0

6408b62

Co-authored-by: Neamah Al-Selwi <neamah.alselwi@digital.cabinet-office.gov.uk> Co-authored-by: Tuomas Nylund <tuomas.nylund@digital.cabinet-office.gov.uk> Co-authored-by: Laura Ghiorghisor <laura.ghiorghisor@digital.cabinet-office.gov.uk>

yuetylauiris merged commit fb46270 into main Jul 5, 2023

yuetylauiris deleted the Log-GOVUK_REQUEST_ID-in-Json-in-Whitehall branch July 5, 2023 11:06

tunylund mentioned this pull request Jul 18, 2023

Add govuk_request_id to logs when available alphagov/gds-api-adapters#1202

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Log govuk request id in json in whitehall #300

Log govuk request id in json in whitehall #300

yuetylauiris commented Jun 22, 2023 •

edited by tunylund

Loading

ollietreend left a comment •

edited

Loading

ollietreend left a comment

ollietreend Jun 26, 2023

kevindew Jun 26, 2023

yuetylauiris Jun 26, 2023

yuetylauiris Jun 26, 2023

kevindew Jun 27, 2023

kevindew Jun 27, 2023

kevindew Jun 27, 2023

tunylund Jun 27, 2023

tunylund Jun 27, 2023

tunylund Jun 28, 2023

kevindew left a comment •

edited

Loading

kevindew commented Jun 29, 2023

kevindew left a comment

kevindew left a comment

yuetylauiris commented Jul 3, 2023

kevindew left a comment

kevindew Jul 4, 2023

kevindew commented Jul 4, 2023 •

edited

Loading

	logger.fatal({
	exception_class: exception.class.to_s,
	exception_message: exception.message,
	stacktrace: trace,
	}.to_json)

Log govuk request id in json in whitehall #300

Log govuk request id in json in whitehall #300

Conversation

yuetylauiris commented Jun 22, 2023 • edited by tunylund Loading

ollietreend left a comment • edited Loading

Choose a reason for hiding this comment

ollietreend left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kevindew left a comment • edited Loading

Choose a reason for hiding this comment

kevindew commented Jun 29, 2023

kevindew left a comment

Choose a reason for hiding this comment

kevindew left a comment

Choose a reason for hiding this comment

yuetylauiris commented Jul 3, 2023

kevindew left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kevindew commented Jul 4, 2023 • edited Loading

yuetylauiris commented Jun 22, 2023 •

edited by tunylund

Loading

ollietreend left a comment •

edited

Loading

kevindew left a comment •

edited

Loading

kevindew commented Jul 4, 2023 •

edited

Loading