From 8758c8b0353c63c56275803606487bcb503185e0 Mon Sep 17 00:00:00 2001
From: Chris Banks <chris.banks@digital.cabinet-office.gov.uk>
Date: Sat, 7 Jan 2023 10:38:29 +0000
Subject: [PATCH] Flush log writes to stdout immediately.

Log writes to stdout were being buffered such that log entries could be
delayed indefinitely, which frustrates troubleshooting in production and
can lead to log messages being lost on crash.

Explicitly enable [IO.sync] on stdout/stderr to have Ruby flush writes
immediately to the underlying system.

stderr was actually already unbuffered, but since we need to set stdout
I think it'd be confusing not to specify both.

While we're there, remove a couple of redundant comments and tidy up the
remaining ones.

[IO.sync]: https://ruby-doc.org/2.7.7/IO.html#method-i-sync-3D

```
ruby <<'EOF'
puts "$stdout.sync=#{$stdout.sync}"
puts "$stderr.sync=#{$stderr.sync}"
puts

$real_stdout = $stdout.clone
$stdout.reopen($stderr)
puts "$stdout.sync=#{$stdout.sync}"
puts "$stderr.sync=#{$stderr.sync}"
puts "$real_stdout.sync=#{$real_stdout.sync}"
puts

$real_stdout.sync = true
$stdout.sync = true
puts "$stdout.sync=#{$stdout.sync}"
puts "$stderr.sync=#{$stderr.sync}"
puts "$real_stdout.sync=#{$real_stdout.sync}"
EOF
```

```
$stdout.sync=false
$stderr.sync=true

$stdout.sync=true
$stderr.sync=true
$real_stdout.sync=false

$stdout.sync=true
$stderr.sync=true
$real_stdout.sync=true
```
---
 CHANGELOG.md                          |  4 ++++
 lib/govuk_app_config/govuk_logging.rb | 25 ++++++++++++-------------
 lib/govuk_app_config/version.rb       |  2 +-
 3 files changed, 17 insertions(+), 14 deletions(-)

diff --git a/CHANGELOG.md b/CHANGELOG.md
index 23e6394a..df851164 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -1,3 +1,7 @@
+# 4.13.0
+
+- Flush log writes to stdout immediately so that structured (JSON) logs are not lost on crash or delayed indefinitely.
+
 # 4.12.0
 
 * Allow `https://img.youtube.com` as a CSP image source
diff --git a/lib/govuk_app_config/govuk_logging.rb b/lib/govuk_app_config/govuk_logging.rb
index 9a32f886..49a37da4 100644
--- a/lib/govuk_app_config/govuk_logging.rb
+++ b/lib/govuk_app_config/govuk_logging.rb
@@ -12,36 +12,37 @@ def self.configure
     # `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've directed stdout to stderr, to cover any Rails
+    # 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
+    # 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))
 
-    # Custom that will be added to the Rails request logs
     LogStasher.add_custom_fields do |fields|
-      # Mirrors Nginx request logging, e.g GET /path/here HTTP/1.1
+      # Mirrors Nginx request logging, e.g. GET /path/here HTTP/1.1
       fields[:request] = "#{request.request_method} #{request.fullpath} #{request.headers['SERVER_PROTOCOL']}"
 
-      # Pass request Id to logging
       fields[:govuk_request_id] = request.headers["GOVUK-Request-Id"]
-
       fields[:varnish_id] = request.headers["X-Varnish"]
-
       fields[:govuk_app_config] = GovukAppConfig::VERSION
     end
 
     Rails.application.config.logstasher.enabled = true
 
-    # Log controller actions so that we can graph response times
+    # Log controller actions so that we can graph response times.
     Rails.application.config.logstasher.controller_enabled = true
 
-    # The other loggers are not that interesting in production
+    # The other loggers are not that interesting in production.
     Rails.application.config.logstasher.mailer_enabled = false
     Rails.application.config.logstasher.record_enabled = false
     Rails.application.config.logstasher.view_enabled = false
@@ -59,11 +60,9 @@ def self.configure
     if defined?(GdsApi::Base)
       GdsApi::Base.default_options ||= {}
 
-      # The GDS API Adapters gem logs JSON to describe the requests it
-      # makes and the responses it gets, so direct this to the
-      # logstasher logger
-      GdsApi::Base.default_options[:logger] =
-        Rails.application.config.logstasher.logger
+      # The gds-api-adapters gem logs JSON to describe the requests it makes and
+      # 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?
diff --git a/lib/govuk_app_config/version.rb b/lib/govuk_app_config/version.rb
index 35a4495e..4f44d8bb 100644
--- a/lib/govuk_app_config/version.rb
+++ b/lib/govuk_app_config/version.rb
@@ -1,3 +1,3 @@
 module GovukAppConfig
-  VERSION = "4.12.0".freeze
+  VERSION = "4.13.0".freeze
 end