From 50b4329787c32b3eb860467307d560a89bec8338 Mon Sep 17 00:00:00 2001 From: "E. Lynette Rayle" Date: Fri, 13 Dec 2019 14:38:42 -0500 Subject: [PATCH 1/2] optionally include IP info at start of search/find linked data requests MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Marks the start of each linked data search/find request. Unless `Qa.config.suppress_ip_data_from_log`, this marker will include IP address, city, state, and country as reported by the `geocoder` gem. NOTE: This also removes inclusion of the request_id directly in the logging messages. To include request_id, it is recommended that you set up the logger to do this automatically in `config/environments/development.rb` (or relevant env file) using… ``` config.log_tags = [:request_id] ``` --- .../qa/linked_data/request_header_service.rb | 12 ++++--- .../templates/config/initializers/qa.rb | 5 +++ lib/qa/authorities/linked_data/find_term.rb | 9 +++-- .../authorities/linked_data/search_query.rb | 9 +++-- lib/qa/configuration.rb | 9 +++++ qa.gemspec | 1 + .../request_header_service_spec.rb | 35 ++++++++++++++++++- 7 files changed, 65 insertions(+), 15 deletions(-) diff --git a/app/services/qa/linked_data/request_header_service.rb b/app/services/qa/linked_data/request_header_service.rb index b2b36dc7..20a5cbc6 100644 --- a/app/services/qa/linked_data/request_header_service.rb +++ b/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 diff --git a/lib/generators/qa/install/templates/config/initializers/qa.rb b/lib/generators/qa/install/templates/config/initializers/qa.rb index 1381a767..76632309 100644 --- a/lib/generators/qa/install/templates/config/initializers/qa.rb +++ b/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 diff --git a/lib/qa/authorities/linked_data/find_term.rb b/lib/qa/authorities/linked_data/find_term.rb index 405c6d35..6644e472 100644 --- a/lib/qa/authorities/linked_data/find_term.rb +++ b/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 diff --git a/lib/qa/authorities/linked_data/search_query.rb b/lib/qa/authorities/linked_data/search_query.rb index c94df472..cc0fb1ed 100644 --- a/lib/qa/authorities/linked_data/search_query.rb +++ b/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 diff --git a/lib/qa/configuration.rb b/lib/qa/configuration.rb index 850c4b54..496de1c2 100644 --- a/lib/qa/configuration.rb +++ b/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 diff --git a/qa.gemspec b/qa.gemspec index dd6a9f56..b21ceb1b 100644 --- a/qa.gemspec +++ b/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" diff --git a/spec/services/linked_data/request_header_service_spec.rb b/spec/services/linked_data/request_header_service_spec.rb index 40f36d55..f09c5ad9 100644 --- a/spec/services/linked_data/request_header_service_spec.rb +++ b/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' } From 5e115ec5c9299dab167bceb7afac096cddbe5c20 Mon Sep 17 00:00:00 2001 From: "E. Lynette Rayle" Date: Fri, 13 Dec 2019 18:20:34 -0500 Subject: [PATCH 2/2] log graph load failures for linked data module --- app/services/qa/linked_data/graph_service.rb | 1 + .../linked_data_terms_controller_spec.rb | 15 +++++++++++++++ 2 files changed, 16 insertions(+) diff --git a/app/services/qa/linked_data/graph_service.rb b/app/services/qa/linked_data/graph_service.rb index 65dd4406..98ccee32 100644 --- a/app/services/qa/linked_data/graph_service.rb +++ b/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) diff --git a/spec/controllers/linked_data_terms_controller_spec.rb b/spec/controllers/linked_data_terms_controller_spec.rb index 4050f2d1..a86c90cf 100644 --- a/spec/controllers/linked_data_terms_controller_spec.rb +++ b/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')