Merge pull request #302 from samvera/log_ip

optionally include IP info at start of search/find linked data requests

app/services/qa/linked_data/graph_service.rb

@@ -91,6 +91,7 @@ def at_least_one_object_has_language?(objects, language)
           end
 
           def process_error(e, url)
+            Rails.logger.warn("******** RDF::Graph#load failure: exception=#{e.inspect}, url=#{url}")
             uri = URI(url)
             raise RDF::FormatError, "Unknown RDF format of results returned by #{uri}. (RDF::FormatError)  You may need to include gem 'linkeddata'." if e.is_a? RDF::FormatError
             response_code = ioerror_code(e)

app/services/qa/linked_data/request_header_service.rb

@@ -1,4 +1,5 @@
 # Service to construct a request header that includes optional attributes for search and fetch requests.
+require 'geocoder'
 module Qa
   module LinkedData
     class RequestHeaderService
@@ -16,7 +17,8 @@ class RequestHeaderService
       def initialize(request:, params:)
         @request = request
         @params = params
-        @request_id = assign_request_id
+        @request_id = request.request_id
+        log_request
       end
 
       # Construct request parameters to pass to search_query (linked data module).
@@ -67,9 +69,11 @@ def content_type_for_format
 
       private
 
-        # assign request id
-        def assign_request_id
-          SecureRandom.uuid
+        def log_request
+          gc = request.location
+          msg = "******** #{request.path_parameters[:action].upcase}"
+          msg += " from IP #{request.ip} in {city: #{gc.city}, state: #{gc.state}, country: #{gc.country}}" unless Qa.config.suppress_ip_data_from_log
+          Rails.logger.info(msg)
         end
 
         # filter literals in results to this language

lib/generators/qa/install/templates/config/initializers/qa.rb

@@ -23,4 +23,9 @@
   # When false, properties that do not override default optional behavior will be shown whether or not the property has a value in the graph.
   # When true, properties that do not override default optional behavior will not be shown whn the property does not have a value in the graph.
   # config.property_map_default_for_optional = false
+
+  # IP data including IP address, city, state, and country will be logged with each request.
+  # When false, IP data is logged
+  # When true, IP data will not be logged (default for backward compatibility)
+  # config.suppress_ip_data_from_log = true
 end

lib/qa/authorities/linked_data/find_term.rb

@@ -46,10 +46,10 @@ def initialize(term_config)
       def find(id, request_header: {}, language: nil, replacements: {}, subauth: nil, format: 'json', performance_data: false) # rubocop:disable Metrics/ParameterLists
         request_header = build_request_header(language: language, replacements: replacements, subauth: subauth, format: format, performance_data: performance_data) if request_header.empty?
         unpack_request_header(request_header)
-        raise Qa::InvalidLinkedDataAuthority, "#{request_id} - Unable to initialize linked data term sub-authority #{subauthority}" unless subauthority.nil? || term_subauthority?(subauthority)
+        raise Qa::InvalidLinkedDataAuthority, "Unable to initialize linked data term sub-authority #{subauthority}" unless subauthority.nil? || term_subauthority?(subauthority)
         @id = id
         url = authority_service.build_url(action_config: term_config, action: :term, action_request: normalize_id, request_header: request_header)
-        Rails.logger.info "#{request_id} - QA Linked Data term url: #{url}"
+        Rails.logger.info "QA Linked Data term url: #{url}"
         load_graph(url: url)
         normalize_results
       end
@@ -63,7 +63,7 @@ def load_graph(url:)
 
           access_end_dt = Time.now.utc
           @access_time_s = access_end_dt - access_start_dt
-          Rails.logger.info("#{request_id} - Time to receive data from authority: #{access_time_s}s")
+          Rails.logger.info("Time to receive data from authority: #{access_time_s}s")
         end
 
         def normalize_results
@@ -73,7 +73,7 @@ def normalize_results
 
           normalize_end_dt = Time.now.utc
           @normalize_time_s = normalize_end_dt - normalize_start_dt
-          Rails.logger.info("#{request_id} - Time to normalize data: #{normalize_time_s}s")
+          Rails.logger.info("Time to normalize data: #{normalize_time_s}s")
           results = append_data_outside_results(results)
           results
         end
@@ -316,7 +316,6 @@ def build_request_header(language:, replacements:, subauth:, format:, performanc
             )
           end
           request_header = {}
-          request_header[:request_id] = SecureRandom.uuid
           request_header[:replacements] = replacements || {}
           request_header[:subauthority] = subauth || nil
           request_header[:language] = language || nil

lib/qa/authorities/linked_data/search_query.rb

@@ -37,9 +37,9 @@ def initialize(search_config)
       def search(query, request_header: {}, language: nil, replacements: {}, subauth: nil, context: false, performance_data: false) # rubocop:disable Metrics/ParameterLists
         request_header = build_request_header(language: language, replacements: replacements, subauth: subauth, context: context, performance_data: performance_data) if request_header.empty?
         unpack_request_header(request_header)
-        raise Qa::InvalidLinkedDataAuthority, "#{request_id} - Unable to initialize linked data search sub-authority #{subauthority}" unless subauthority.nil? || subauthority?(subauthority)
+        raise Qa::InvalidLinkedDataAuthority, "Unable to initialize linked data search sub-authority #{subauthority}" unless subauthority.nil? || subauthority?(subauthority)
         url = authority_service.build_url(action_config: search_config, action: :search, action_request: query, request_header: request_header)
-        Rails.logger.info "#{request_id} - QA Linked Data search url: #{url}"
+        Rails.logger.info "QA Linked Data search url: #{url}"
         load_graph(url: url)
         normalize_results
       end
@@ -53,7 +53,7 @@ def load_graph(url:)
 
           access_end_dt = Time.now.utc
           @access_time_s = access_end_dt - access_start_dt
-          Rails.logger.info("#{request_id} - Time to receive data from authority: #{access_time_s}s")
+          Rails.logger.info("Time to receive data from authority: #{access_time_s}s")
         end
 
         def normalize_results
@@ -65,7 +65,7 @@ def normalize_results
 
           normalize_end_dt = Time.now.utc
           @normalize_time_s = normalize_end_dt - normalize_start_dt
-          Rails.logger.info("#{request_id} - Time to normalize data: #{normalize_time_s}s")
+          Rails.logger.info("Time to normalize data: #{normalize_time_s}s")
           json = append_data_outside_results(json)
           json
         end
@@ -213,7 +213,6 @@ def build_request_header(language:, replacements:, subauth:, context:, performan
             )
           end
           request_header = {}
-          request_header[:request_id] = SecureRandom.uuid
           request_header[:replacements] = replacements || {}
           request_header[:subauthority] = subauth || nil
           request_header[:language] = language || nil

lib/qa/configuration.rb

@@ -54,5 +54,14 @@ def property_map_default_for_optional
       @property_map_default_for_optional = false if @property_map_default_for_optional.nil?
       @property_map_default_for_optional
     end
+
+    # IP data including IP address, city, state, and country will be logged with each request.
+    # When false, IP data is logged
+    # When true, IP data will not be logged (default for backward compatibility)
+    attr_writer :suppress_ip_data_from_log
+    def suppress_ip_data_from_log
+      @suppress_ip_data_from_log = true if @suppress_ip_data_from_log.nil?
+      @suppress_ip_data_from_log
+    end
   end
 end

qa.gemspec

@@ -19,6 +19,7 @@ Gem::Specification.new do |s|
   s.add_dependency 'activerecord-import'
   s.add_dependency 'deprecation'
   s.add_dependency 'faraday'
+  s.add_dependency 'geocoder'
   s.add_dependency 'ldpath'
   s.add_dependency 'nokogiri', '~> 1.6'
   s.add_dependency 'rails', '>= 5.0', "< 6.1"

spec/controllers/linked_data_terms_controller_spec.rb

@@ -2,6 +2,7 @@
 require 'json'
 
 describe Qa::LinkedDataTermsController, type: :controller do
+  let(:graph_load_failure) { /^\*\*\*\*\*\*\*\* RDF\:\:Graph\#load failure/ }
   before do
     @routes = Qa::Engine.routes
   end
@@ -140,6 +141,7 @@
             .to_return(status: 500)
         end
         it 'returns 500' do
+          expect(Rails.logger).to receive(:warn).with(graph_load_failure)
           expect(Rails.logger).to receive(:warn).with("Internal Server Error - Search query my_query unsuccessful for authority OCLC_FAST")
           get :search, params: { q: 'my_query', vocab: 'OCLC_FAST', maximumRecords: '3' }
           expect(response.code).to eq('500')
@@ -154,6 +156,7 @@
         end
         it 'returns 500' do
           msg = "RDF Format Error - Results from search query my_query for authority OCLC_FAST was not identified as a valid RDF format.  You may need to include the linkeddata gem."
+          expect(Rails.logger).to receive(:warn).with(graph_load_failure)
           expect(Rails.logger).to receive(:warn).with(msg)
           get :search, params: { q: 'my_query', vocab: 'OCLC_FAST', maximumRecords: '3' }
           expect(response.code).to eq('500')
@@ -166,6 +169,7 @@
             .to_return(status: 501)
         end
         it 'returns 500' do
+          expect(Rails.logger).to receive(:warn).with(graph_load_failure)
           expect(Rails.logger).to receive(:warn).with("Internal Server Error - Search query my_query unsuccessful for authority OCLC_FAST")
           get :search, params: { q: 'my_query', vocab: 'OCLC_FAST', maximumRecords: '3' }
           expect(response.code).to eq('500')
@@ -179,6 +183,7 @@
           .to_return(status: 503)
       end
       it 'returns 503' do
+        expect(Rails.logger).to receive(:warn).with(graph_load_failure)
         expect(Rails.logger).to receive(:warn).with("Service Unavailable - Search query my_query unsuccessful for authority OCLC_FAST")
         get :search, params: { q: 'my_query', vocab: 'OCLC_FAST', maximumRecords: '3' }
         expect(response.code).to eq('503')
@@ -355,6 +360,7 @@
           stub_request(:get, 'http://id.worldcat.org/fast/530369').to_return(status: 500)
         end
         it 'returns 500' do
+          expect(Rails.logger).to receive(:warn).with(graph_load_failure)
           expect(Rails.logger).to receive(:warn).with("Internal Server Error - Fetch term 530369 unsuccessful for authority OCLC_FAST")
           get :show, params: { id: '530369', vocab: 'OCLC_FAST' }
           expect(response.code).to eq('500')
@@ -380,6 +386,7 @@
         end
         it 'returns 500' do
           msg = "RDF Format Error - Results from fetch term 530369 for authority OCLC_FAST was not identified as a valid RDF format.  You may need to include the linkeddata gem."
+          expect(Rails.logger).to receive(:warn).with(graph_load_failure)
           expect(Rails.logger).to receive(:warn).with(msg)
           get :show, params: { id: '530369', vocab: 'OCLC_FAST' }
           expect(response.code).to eq('500')
@@ -391,6 +398,7 @@
           stub_request(:get, 'http://id.worldcat.org/fast/530369').to_return(status: 501)
         end
         it 'returns 500' do
+          expect(Rails.logger).to receive(:warn).with(graph_load_failure)
           expect(Rails.logger).to receive(:warn).with("Internal Server Error - Fetch term 530369 unsuccessful for authority OCLC_FAST")
           get :show, params: { id: '530369', vocab: 'OCLC_FAST' }
           expect(response.code).to eq('500')
@@ -403,6 +411,7 @@
         stub_request(:get, 'http://id.worldcat.org/fast/530369').to_return(status: 503)
       end
       it 'returns 503' do
+        expect(Rails.logger).to receive(:warn).with(graph_load_failure)
         expect(Rails.logger).to receive(:warn).with("Service Unavailable - Fetch term 530369 unsuccessful for authority OCLC_FAST")
         get :show, params: { id: '530369', vocab: 'OCLC_FAST' }
         expect(response.code).to eq('503')
@@ -414,6 +423,7 @@
         stub_request(:get, 'http://id.worldcat.org/fast/FAKE_ID').to_return(status: 404, body: '', headers: {})
       end
       it 'returns 404' do
+        expect(Rails.logger).to receive(:warn).with(graph_load_failure)
         expect(Rails.logger).to receive(:warn).with('Term Not Found - Fetch term FAKE_ID unsuccessful for authority OCLC_FAST')
         get :show, params: { id: 'FAKE_ID', vocab: 'OCLC_FAST' }
         expect(response.code).to eq('404')
@@ -566,6 +576,7 @@
           stub_request(:get, 'http://localhost/test_default/term?uri=http://id.worldcat.org/fast/530369').to_return(status: 500)
         end
         it 'returns 500' do
+          expect(Rails.logger).to receive(:warn).with(graph_load_failure)
           expect(Rails.logger).to receive(:warn).with("Internal Server Error - Fetch term http://id.worldcat.org/fast/530369 unsuccessful for authority LOD_TERM_URI_PARAM_CONFIG")
           get :fetch, params: { vocab: 'LOD_TERM_URI_PARAM_CONFIG', uri: 'http://id.worldcat.org/fast/530369' }
           expect(response.code).to eq('500')
@@ -580,6 +591,7 @@
         it 'returns 500' do
           msg = "RDF Format Error - Results from fetch term http://id.worldcat.org/fast/530369 for authority LOD_TERM_URI_PARAM_CONFIG was not identified as a valid RDF format.  " \
                 "You may need to include the linkeddata gem."
+          expect(Rails.logger).to receive(:warn).with(graph_load_failure)
           expect(Rails.logger).to receive(:warn).with(msg)
           get :fetch, params: { uri: 'http://id.worldcat.org/fast/530369', vocab: 'LOD_TERM_URI_PARAM_CONFIG' }
           expect(response.code).to eq('500')
@@ -591,6 +603,7 @@
           stub_request(:get, 'http://localhost/test_default/term?uri=http://id.worldcat.org/fast/530369').to_return(status: 501)
         end
         it 'returns 500' do
+          expect(Rails.logger).to receive(:warn).with(graph_load_failure)
           expect(Rails.logger).to receive(:warn).with("Internal Server Error - Fetch term http://id.worldcat.org/fast/530369 unsuccessful for authority LOD_TERM_URI_PARAM_CONFIG")
           get :fetch, params: { uri: 'http://id.worldcat.org/fast/530369', vocab: 'LOD_TERM_URI_PARAM_CONFIG' }
           expect(response.code).to eq('500')
@@ -603,6 +616,7 @@
         stub_request(:get, 'http://localhost/test_default/term?uri=http://id.worldcat.org/fast/530369').to_return(status: 503)
       end
       it 'returns 503' do
+        expect(Rails.logger).to receive(:warn).with(graph_load_failure)
         expect(Rails.logger).to receive(:warn).with("Service Unavailable - Fetch term http://id.worldcat.org/fast/530369 unsuccessful for authority LOD_TERM_URI_PARAM_CONFIG")
         get :fetch, params: { uri: 'http://id.worldcat.org/fast/530369', vocab: 'LOD_TERM_URI_PARAM_CONFIG' }
         expect(response.code).to eq('503')
@@ -614,6 +628,7 @@
         stub_request(:get, 'http://localhost/test_default/term?uri=http://test.org/FAKE_ID').to_return(status: 404, body: '', headers: {})
       end
       it 'returns 404' do
+        expect(Rails.logger).to receive(:warn).with(graph_load_failure)
         expect(Rails.logger).to receive(:warn).with('Term Not Found - Fetch term http://test.org/FAKE_ID unsuccessful for authority LOD_TERM_URI_PARAM_CONFIG')
         get :fetch, params: { uri: 'http://test.org/FAKE_ID', vocab: 'LOD_TERM_URI_PARAM_CONFIG' }
         expect(response.code).to eq('404')

spec/services/linked_data/request_header_service_spec.rb

@@ -2,7 +2,40 @@
 
 RSpec.describe Qa::LinkedData::RequestHeaderService do
   let(:request) { double }
-  before { allow(SecureRandom).to receive(:uuid).and_return(request_id) }
+  let(:request_id) { 'anID' }
+  let(:some_params) { double }
+  let(:location) { double }
+  let(:fake_ip) { '111.22.33.4444' }
+  let(:city) { 'Ithaca' }
+  let(:state) { 'New York' }
+  let(:country) { 'US' }
+  before do
+    allow(request).to receive(:request_id).and_return(request_id)
+    allow(request).to receive_message_chain(:path_parameters, :[]).with(:action).and_return('search') # rubocop:disable RSpec/MessageChain
+    allow(request).to receive(:location).and_return(location)
+    allow(request).to receive(:ip).and_return(fake_ip)
+    allow(location).to receive(:city).and_return(city)
+    allow(location).to receive(:state).and_return(state)
+    allow(location).to receive(:country).and_return(country)
+  end
+
+  describe '#initialize' do
+    context 'when Qa.config.suppress_ip_data_from_log is true' do
+      before { allow(Qa).to receive_message_chain(:config, :suppress_ip_data_from_log).and_return(true) } # rubocop:disable RSpec/MessageChain
+      it 'does not include IP info in log message' do
+        expect(Rails.logger).to receive(:info).with("******** SEARCH")
+        described_class.new(request: request, params: some_params)
+      end
+    end
+
+    context 'when Qa.config.suppress_ip_data_from_log is false' do
+      before { allow(Qa).to receive_message_chain(:config, :suppress_ip_data_from_log).and_return(false) } # rubocop:disable RSpec/MessageChain
+      it 'does include IP info in log message' do
+        expect(Rails.logger).to receive(:info).with("******** SEARCH from IP #{fake_ip} in {city: #{city}, state: #{state}, country: #{country}}")
+        described_class.new(request: request, params: some_params)
+      end
+    end
+  end
 
   describe '#search_header' do
     let(:request_id) { 's1' }