Upgrade logstasher gem to add error notification

We log the postcode_errors with `logstasher` to JSON-style logs so that the errors can be viewed in Kibana. `logstasher` supports subscribing to ActiveSupport::Notifications, which we use to log the postcode errors.
https://github.com/shadabahmed/logstasher#listening-to-activesupportnotifications-events

We upgrade `logstasher` to release `0.6.2`. Initially we attempted to upgrade to the latest release `0.8.6`, but custom fields were not being output in the logs, notification subscription did not work, log messages for rendering view templates were being included and the JSON structure of the output was different (`fields` being deprecated since `0.6.5`). This appears not to be a straight-forward API change but rather changes in the internal architecture. In the interest of time I have settled on `0.6.2` as that includes the `watch` method and does not alter the previous logging output. I have logged an issue against the `logstasher` repo -> shadabahmed/logstasher#92 to ask about the breaking change to notification subscriptions.

The commit adds the following to the JSON output:

`"postcode_error_notification":{
  "postcode_error":"invalidPostcodeFormat"
},`

Gemfile

@@ -29,7 +29,7 @@ else
 end
 
 gem "addressable"
-gem 'logstasher', '0.4.8'
+gem 'logstasher', '0.6.2'
 gem 'airbrake', '3.1.15'
 gem 'invalid_utf8_rejector', '0.0.1'
 gem 'rack_strip_client_ip', '0.0.1'

Gemfile.lock

@@ -114,8 +114,9 @@ GEM
     libv8 (3.16.14.11)
     link_header (0.0.8)
     logstash-event (1.1.5)
-    logstasher (0.4.8)
+    logstasher (0.6.2)
       logstash-event (~> 1.1.0)
+      request_store
     loofah (2.0.3)
       nokogiri (>= 1.5.9)
     lrucache (0.1.4)
@@ -181,6 +182,7 @@ GEM
     raindrops (0.11.0)
     rake (10.4.2)
     ref (1.0.5)
+    request_store (1.2.1)
     rest-client (1.8.0)
       http-cookie (>= 1.0.2, < 2.0)
       mime-types (>= 1.16, < 3.0)
@@ -276,7 +278,7 @@ DEPENDENCIES
   htmlentities (= 4.3.1)
   invalid_utf8_rejector (= 0.0.1)
   launchy
-  logstasher (= 0.4.8)
+  logstasher (= 0.6.2)
   mocha (~> 1.1.0)
   plek (= 1.11.0)
   poltergeist (= 1.3.0)

app/models/location_error.rb

@@ -5,11 +5,11 @@ def initialize(postcode_error = nil, message = nil, message_args = {})
     @postcode_error = postcode_error
     @message = message || 'formats.local_transaction.invalid_postcode'
     @message_args = message_args
-    log_error
+    send_error_notification(postcode_error) if postcode_error
   end
 
-  def log_error
-    Rails.logger.info(postcode_error) if postcode_error
+  def send_error_notification(error)
+    ActiveSupport::Notifications.instrument('postcode_error_notification', postcode_error: error)
   end
 
   def no_location_interaction?

config/environments/production.rb

@@ -62,7 +62,7 @@
   # Enable JSON-style logging
   config.logstasher.enabled = true
   config.logstasher.logger = Logger.new("#{Rails.root}/log/#{Rails.env}.json.log")
-  config.logstasher.supress_app_log = true
+  config.logstasher.suppress_app_log = true
 
   config.eager_load = true
 end

config/initializers/logstasher.rb

@@ -6,4 +6,8 @@
     fields[:govuk_request_id] = request.headers['GOVUK-Request-Id']
     fields[:varnish_id] = request.headers['X-Varnish']
   end
+
+  LogStasher.watch('postcode_error_notification') do |_name, _start, _finish, _id, payload, store|
+    store[:postcode_error] = payload[:postcode_error]
+  end
 end

test/functional/local_transactions_controller_test.rb

@@ -7,6 +7,12 @@ class LocalTransactionsControllerTest < ActionController::TestCase
   tests RootController
   include GdsApi::TestHelpers::Mapit
 
+  def subscribe_logstasher_to_postcode_error_notification
+    LogStasher.watch('postcode_error_notification') do |_name, _start, _finish, _id, payload, store|
+      store[:postcode_error] = payload[:postcode_error]
+    end
+  end
+
   context "given a local transaction exists in content api" do
     setup do
       @artefact = {
@@ -63,39 +69,57 @@ class LocalTransactionsControllerTest < ActionController::TestCase
       setup do
         mapit_does_not_have_a_bad_postcode("BLAH")
 
+        subscribe_logstasher_to_postcode_error_notification
+
         post :publication, slug: "send-a-bear-to-your-local-council", postcode: "BLAH"
       end
 
-      should "log the invalid postcode error" do
+      should "expose the 'invalid postcode format' error to the view" do
         location_error = assigns(:location_error)
         assert_equal location_error.postcode_error, "invalidPostcodeFormat"
       end
+
+      should "log the 'invalid postcode format' error to the view" do
+        assert_equal(LogStasher.store["postcode_error_notification"], { postcode_error: "invalidPostcodeFormat" })
+      end
     end
 
     context "loading the local transaction when posting a postcode with no matching areas" do
       setup do
         mapit_does_not_have_a_postcode("WC1E 9ZZ")
 
+        subscribe_logstasher_to_postcode_error_notification
+
         post :publication, slug: "send-a-bear-to-your-local-council", postcode: "WC1E 9ZZ"
       end
 
-      should "log the invalid postcode error" do
+      should "expose the 'no mapit match' error to the view" do
         location_error = assigns(:location_error)
         assert_equal location_error.postcode_error, "fullPostcodeNoMapitMatch"
       end
+
+      should "log the 'no mapit match' error to the view" do
+        assert_equal(LogStasher.store["postcode_error_notification"], { postcode_error: "fullPostcodeNoMapitMatch" })
+      end
     end
 
     context "loading the local transaction when posting a location that has no matching local authority" do
       setup do
         mapit_has_a_postcode_and_areas("AB1 2CD", [0, 0], [])
 
+        subscribe_logstasher_to_postcode_error_notification
+
         post :publication, slug: "send-a-bear-to-your-local-council", postcode: "AB1 2CD"
       end
 
-      should "log the missing local authority error" do
+      should "expose the 'missing local authority' error to the view" do
         location_error = assigns(:location_error)
         assert_equal "noLaMatchLinkToFindLa", location_error.postcode_error
       end
+
+      should "log the 'missing local authority' error to the view" do
+        assert_equal(LogStasher.store["postcode_error_notification"], { postcode_error: "noLaMatchLinkToFindLa" })
+      end
     end
 
     context "loading the local transaction for an authority" do
@@ -137,7 +161,7 @@ class LocalTransactionsControllerTest < ActionController::TestCase
     end
   end
 
-  context "given a local transaction without an interaction exists in content api" do
+  context "loading a local transaction without an interaction that exists in content api" do
     setup do
       @artefact = {
         "title" => "Report a bear on a local road",
@@ -167,22 +191,23 @@ class LocalTransactionsControllerTest < ActionController::TestCase
 
       content_api_has_an_artefact('report-a-bear-on-a-local-road', @artefact)
       content_api_has_an_artefact_with_snac_code('report-a-bear-on-a-local-road', "41UH", @artefact)
+
+      subscribe_logstasher_to_postcode_error_notification
+      get :publication, slug: "report-a-bear-on-a-local-road", part: "staffordshire-moorlands"
     end
 
-    context "loading the local interaction" do
-      setup do
-        get :publication, slug: "report-a-bear-on-a-local-road", part: "staffordshire-moorlands"
-      end
+    should "show error message" do
+      assert response.ok?
+      assert response.body.include?("application-notice help-notice")
+    end
 
-      should "show error message" do
-        assert response.ok?
-        assert response.body.include?("application-notice help-notice")
-      end
+    should "expose the 'missing interaction' error to the view" do
+      location_error = assigns(:location_error)
+      assert_equal "laMatchNoLink", location_error.postcode_error
+    end
 
-      should "log the missing interaction error" do
-        location_error = assigns(:location_error)
-        assert_equal "laMatchNoLink", location_error.postcode_error
-      end
+    should "log the 'missing interaction' error to the view" do
+      assert_equal(LogStasher.store["postcode_error_notification"], { postcode_error: "laMatchNoLink" })
     end
   end
 end

test/unit/models/location_error_test.rb

@@ -0,0 +1,24 @@
+class LocationErrorTest < ActiveSupport::TestCase
+  context '#initialize' do
+    should 'default to default message when no message given' do
+      error = LocationError.new(postcode_error = 'some_error', message = nil)
+      assert_equal(error.message, 'formats.local_transaction.invalid_postcode')
+    end
+
+    context 'when given a postcode_error' do
+      should 'send the postcode error as a notification' do
+        ActiveSupport::Notifications.expects(:instrument).with('postcode_error_notification', postcode_error: "some_error")
+
+        error = LocationError.new(postcode_error = 'some_error')
+      end
+    end
+
+    context 'when not given a postcode_error' do
+      should 'not send a postcode_error notification' do
+        ActiveSupport::Notifications.expects(:instrument).never
+
+        error = LocationError.new
+      end
+    end
+  end
+end