Merge pull request #277 from alphagov/sengi/setvbuf

Flush log writes to stdout immediately.

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

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?

lib/govuk_app_config/version.rb

@@ -1,3 +1,3 @@
 module GovukAppConfig
-  VERSION = "4.12.0".freeze
+  VERSION = "4.13.0".freeze
 end