Merge pull request #300 from alphagov/Log-GOVUK_REQUEST_ID-in-Json-in…

…-Whitehall

Log govuk request id in json in whitehall

CHANGELOG.md

@@ -1,6 +1,10 @@
-# Unreleased
+# 9.0.0
 
 * BREAKING: JSON logs are no longer configured automatically for production Rails apps and are turned on with the GOVUK_RAILS_JSON_LOGGING environment variable ([#302](https://github.com/alphagov/govuk_app_config/pull/302))
+* 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))
+* Remove monkeypatch for errors ([#300](https://github.com/alphagov/govuk_app_config/pull/300))
 
 # 8.1.1
 

README.md

@@ -142,9 +142,6 @@ check docs](docs/healthchecks.md) for more information on how to use it.
 
 ## Rails logging
 
-In Rails applications, the application will be configured to send JSON-formatted
-logs to `STDOUT` and unstructured logs to `STDERR`.
-
 To enable production-like logging, an env variable `GOVUK_RAILS_JSON_LOGGING`
 is set in the `govuk-helm-charts` and then checked in `railtie.rb`. This will
 allow JSON format logs and `Govuk-Request-Id` to be visible.

lib/govuk_app_config/govuk_json_logging.rb

@@ -1,32 +1,31 @@
+require "json"
 require "logstasher"
 require "action_controller"
-require_relative "rails_ext/action_dispatch/debug_exceptions"
 
 module GovukJsonLogging
   def self.configure
-    # GOV.UK Rails applications are expected to output JSON to stdout which is
-    # then indexed in a Kibana instance. These log outputs are created by the
-    # logstasher gem.
-    #
-    # Rails applications will typically write other things to stdout such as
-    # `Rails.logger` calls or 'puts' statements. However these are not in a
-    # JSON format which causes problems for the log file parsers.
-    #
-    # To resolve this we redirect stdout to stderr, to cover any Rails
-    # writing. This frees up the normal stdout for the logstasher logs.
-    #
-    # We also disable buffering, so that logs aren't lost on crash or delayed
+    # We disable buffering, so that logs aren't lost on crash or delayed
     # indefinitely while troubleshooting.
-
-    # rubocop:disable Style/GlobalVars
-    $real_stdout = $stdout.clone
-    $real_stdout.sync = true
-    $stdout.reopen($stderr)
     $stdout.sync = true
-    # rubocop:enable Style/GlobalVars
 
-    # Send Rails' logs to STDERR because they're not JSON formatted.
-    Rails.logger = ActiveSupport::TaggedLogging.new(Logger.new($stderr, level: Rails.logger.level))
+    Rails.logger = Logger.new(
+      $stdout,
+      level: Rails.logger.level,
+      formatter: proc { |severity, datetime, _progname, msg|
+        hash = {
+          "@timestamp": datetime.utc.iso8601(3),
+          message: msg,
+          level: severity,
+          tags: %w[rails],
+        }
+
+        if defined?(GdsApi::GovukHeaders) && !GdsApi::GovukHeaders.headers[:govuk_request_id].nil?
+          hash[:govuk_request_id] = GdsApi::GovukHeaders.headers[:govuk_request_id]
+        end
+
+        "#{hash.to_json}\n"
+      },
+    )
 
     LogStasher.add_custom_fields do |fields|
       # Mirrors Nginx request logging, e.g. GET /path/here HTTP/1.1
@@ -53,7 +52,7 @@ def self.configure
     Rails.application.config.logstasher.source = {}
 
     Rails.application.config.logstasher.logger = Logger.new(
-      $real_stdout, # rubocop:disable Style/GlobalVars
+      $stdout,
       level: Rails.logger.level,
       formatter: proc { |_severity, _datetime, _progname, msg|
         "#{msg.is_a?(String) ? msg : msg.inspect}\n"
@@ -68,7 +67,5 @@ def self.configure
       # the responses it gets, so direct this to the logstasher logger.
       GdsApi::Base.default_options[:logger] = Rails.application.config.logstasher.logger
     end
-
-    RailsExt::ActionDispatch.monkey_patch_log_error if RailsExt::ActionDispatch.should_monkey_patch_log_error?
   end
 end

lib/govuk_app_config/version.rb

@@ -1,3 +1,3 @@
 module GovukAppConfig
-  VERSION = "8.1.1".freeze
+  VERSION = "9.0.0".freeze
 end

spec/lib/govuk_json_logging_spec.rb

@@ -4,6 +4,13 @@
 require "rack/test"
 
 RSpec.describe GovukJsonLogging do
+  let(:govuk_headers_class) do
+    Class.new do
+      def self.headers
+        { govuk_request_id: "some-value" }
+      end
+    end
+  end
   before do
     stub_const("DummyLoggingRailsApp", Class.new(Rails::Application) do
       config.hosts.clear
@@ -15,21 +22,28 @@
 
   after { Rails.application = nil }
 
-  old_stderr = nil
+  # By storing origin stdout in a constant and redirect `$stdout` to a fake one,
+  # We are able to inspect and test what is printed
+  # BUT it also suppress all the normal log outputs
+  # I.E. puts doesn't work anymore :D
+  original_stderr = nil
+  original_stdout = nil
 
   let(:fake_stdout) { StringIO.new }
+  let(:fake_stderr) { StringIO.new }
   let(:info_log_level) { 1 }
 
   before do
-    old_stderr = $stderr
-    $stderr = StringIO.new
-    allow($stdout).to receive(:clone).and_return(fake_stdout)
-    allow($stdout).to receive(:reopen)
+    original_stderr = $stderr
+    original_stdout = $stdout
+    $stderr = fake_stderr
+    $stdout = fake_stdout
     Rails.logger = Logger.new(fake_stdout, level: info_log_level)
   end
 
   after do
-    $stderr = old_stderr
+    $stderr = original_stderr
+    $stdout = original_stdout
   end
 
   describe ".configure" do
@@ -59,9 +73,9 @@
       GovukJsonLogging.configure
       logger = Rails.logger
       logger.info("test default log entry")
-      $stderr.rewind
+      fake_stdout.rewind
 
-      expect($stderr.read).to match(/test default log entry/)
+      expect(fake_stdout.read).to match(/test default log entry/)
     end
 
     describe "when making requests to the application" do
@@ -71,21 +85,53 @@ def app
         Rails.application
       end
 
-      it "logs errors thrown by the application" do
+      it "logs errors thrown by the application with govuk_request_id" do
+        stub_const("GdsApi::GovukHeaders", govuk_headers_class)
         GovukJsonLogging.configure
         get "/error"
-        $stderr.rewind
-        lines = $stderr.read.split("\n")
+        fake_stdout.rewind
+        lines = fake_stdout.read.split("\n")
         expect(lines).to include(/default exception/)
         error_log_line = lines.find { |log| log.match?(/default exception/) }
         expect(error_log_line).not_to be_empty
+
         error_log_json = JSON.parse(error_log_line)
         expect(error_log_json).to match(hash_including(
-                                          "exception_class" => "StandardError",
-                                          "exception_message" => "default exception",
+                                          "govuk_request_id" => "some-value",
                                         ))
-        expect(error_log_json).to have_key("stacktrace")
-        expect(error_log_json["stacktrace"]).to be_a(Array)
+
+        error_log_json_msg = error_log_json["message"]
+        expect(error_log_json_msg).to include("StandardError")
+        expect(error_log_json_msg).to include("default exception")
+        expect(error_log_json_msg).to match(/[a-zA-Z]+.*:[0-9]+:in.*/)
+      end
+
+      it "logs errors thrown by the application with no govuk_request_id" do
+        GovukJsonLogging.configure
+        get "/error"
+        fake_stdout.rewind
+        lines = fake_stdout.read.split("\n")
+        expect(lines).to include(/default exception/)
+        error_log_line = lines.find { |log| log.match?(/default exception/) }
+        expect(error_log_line).not_to be_empty
+        error_log_json = JSON.parse(error_log_line)
+        error_log_json_msg = error_log_json["message"]
+        expect(error_log_json_msg).to include("StandardError")
+        expect(error_log_json_msg).to include("default exception")
+        expect(error_log_json_msg).to match(/[a-zA-Z].*:[0-9]+:in.*/)
+      end
+
+      it "logs to stdout in JSON format with govuk_request_id" do
+        stub_const("GdsApi::GovukHeaders", govuk_headers_class)
+        GovukJsonLogging.configure
+        logger = Rails.logger
+        logger.info("test default log entry")
+        fake_stdout.rewind
+        log_line = fake_stdout.read
+        log_json = JSON.parse(log_line)
+
+        expect(log_json).to include("message" => "test default log entry")
+        expect(log_json).to include("govuk_request_id" => "some-value")
       end
     end
   end