Merge pull request #50 from nsidc/srch-58

SRCH-58

Author: scott-lewis-nsidc

CHANGELOG.md

@@ -1,3 +1,9 @@
+## Unreleased
+
+  - Adding logging functionality to the code, including the ability
+    to specify log file destination and log level for both the file and
+    console output
+
 ## v6.4.1 (2023-09-15)
 
   - Added GitHub Action workflows for continuous integration features

Gemfile.lock

@@ -4,6 +4,7 @@ PATH
     search_solr_tools (6.4.1)
       ffi-geos (~> 2.4.0)
       iso8601 (~> 0.13.0)
+      logging (~> 2.3.1)
       multi_json (~> 1.15.0)
       nokogiri (~> 1.15.4)
       rest-client (~> 2.1.0)
@@ -65,6 +66,10 @@ GEM
     listen (3.8.0)
       rb-fsevent (~> 0.10, >= 0.10.3)
       rb-inotify (~> 0.9, >= 0.9.10)
+    little-plugger (1.1.4)
+    logging (2.3.1)
+      little-plugger (~> 1.1)
+      multi_json (~> 1.14)
     lumberjack (1.2.9)
     method_source (1.0.0)
     mime-types (3.5.1)

README.md

@@ -101,6 +101,10 @@ the tests whenever the appropriate files are changed.
 
 Please be sure to run them in the `bundle exec` context if you're utilizing bundler.
 
+By default, tests are run with minimal logging - no log file and only fatal errors
+written to the console.  This can be changed by setting the environment variables 
+as described in [Logging](#logging) below.
+
 ### Creating Releases (NSIDC devs only)
 
 Requirements:
@@ -208,6 +212,47 @@ which can be modified, or additional environments can be added by just adding a
 new YAML stanza with the right keys; this new environment can then be used with
 the `--environment` flag when running `search_solr_tools harvest`.
 
+#### Logging
+
+By default, when running the harvest, harvest logs are written to the file
+`/var/log/search-solr-tools.log` (set to `warn` level), as well as to the console
+at `info` level.  These settings are configured in the `environments.yaml` config
+file, in the `common` section. 
+
+The keys in the `environments.yaml` file to consider are as follows:
+
+* `log_file` - The full name and path of the file to which log output will be written
+  to.  If set to the special value `none`, no log file will be written to at all.
+  Log output will be **appended** to the file, if it exists; otherwise, the file will
+  be created.
+* `log_file_level` - Indicates the level of logging which should be written to the log file.
+* `log_stdout_level` - Indicates the level of logging which should be written to the console.
+  This can be different than the level written to the log file.
+
+You can also override the configuration file settings at the command line with the
+following environment variables (useful when for doing development work):
+
+* `SEARCH_SOLR_LOG_FILE` - Overrides the `log_file` setting
+* `SEARCH_SOLR_LOG_LEVEL` - Overrides the `log_file_level` setting
+* `SEARCH_SOLR_STDOUT_LEVEL` - Overrides the `log_stdout_level` setting
+
+When running the spec tests, `SEARCH_SOLR_LOG_FILE` is set to `none` and
+`SEARCH_SOLR_STDOUT_LEVEL` is set to `fatal`, unless you manually set those
+environment variables prior to running the tests.  This is to keep the test output
+clean unless you need more detail for debugging.
+
+The following are the levels of logging that can be specified.  These levels are
+cumulative; for example, `error` will also output `fatal` log entries, and `debug`
+will output **all** log entries.
+
+* `none` - No logging outputs will be written.
+* `fatal` - Only outputs errors which result in a crash.
+* `error` - Outputs any error that occurs while harvesting.
+* `warn` - Outputs warnings that occur that do not cause issues with the harvesting,
+  but might indicate things that may need to be addressed (such as deprecations, etc)
+* `info` - Outputs general information, such as harvesting status
+* `debug` - Outputs detailed information that can be used for debugging and code tracing.
+
 ## Organization Info
 
 ### How to contact NSIDC

bin/search_solr_tools

@@ -6,8 +6,14 @@ require 'thor'
 
 # rubocop:disable Metrics/AbcSize
 class SolrHarvestCLI < Thor
+  include SSTLogger
+
   map %w[--version -v] => :__print_version
 
+  def self.exit_on_failure?
+    false
+  end
+
   desc '--version, -v', 'print the version'
   def __print_version
     puts SearchSolrTools::VERSION
@@ -39,10 +45,11 @@ class SolrHarvestCLI < Thor
       rescue StandardError => e
         solr_status = false
         source_status = false
-        puts "Error trying to ping for #{target}: #{e}"
+        logger.error "Ping failed for #{target}: #{e}}"
       end
       solr_success &&= solr_status
       source_success &&= source_status
+
       puts "Target: #{target}, Solr ping OK? #{solr_status}, data center ping OK? #{source_status}"
     end
 
@@ -61,7 +68,7 @@ class SolrHarvestCLI < Thor
   option :die_on_failure, type: :boolean
   def harvest(die_on_failure = options[:die_on_failure] || false)
     options[:data_center].each do |target|
-      puts "Target: #{target}"
+      logger.info "Target: #{target}"
       begin
         harvest_class = get_harvester_class(target)
         harvester = harvest_class.new(options[:environment], die_on_failure:)
@@ -73,12 +80,12 @@ class SolrHarvestCLI < Thor
 
         harvester.harvest_and_delete
       rescue SearchSolrTools::Errors::HarvestError => e
-        puts "THERE WERE HARVEST STATUS ERRORS:\n#{e.message}"
+        logger.error "THERE WERE HARVEST STATUS ERRORS:\n#{e.message}"
         exit e.exit_code
       rescue StandardError => e
         # If it gets here, there is an error that we aren't expecting.
-        puts "harvest failed for #{target}: #{e.message}"
-        puts e.backtrace
+        logger.error "harvest failed for #{target}: #{e.message}"
+        logger.error e.backtrace
         exit SearchSolrTools::Errors::HarvestError::ERRCODE_OTHER
       end
     end
@@ -93,28 +100,34 @@ class SolrHarvestCLI < Thor
   option :environment, required: true
   def delete_all
     env = SearchSolrTools::SolrEnvironments[options[:environment]]
+    logger.info('DELETE ALL started')
     `curl 'http://#{env[:host]}:#{env[:port]}/solr/update' -H 'Content-Type: text/xml; charset=utf-8' --data '<delete><query>*:*</query></delete>'`
     `curl 'http://#{env[:host]}:#{env[:port]}/solr/update' -H 'Content-Type: text/xml; charset=utf-8' --data '<commit/>'`
+    logger.info('DELETE ALL complete')
   end
 
   desc 'delete_all_auto_suggest', 'Delete all documents from the auto_suggest index'
   option :environment, required: true
   def delete_all_auto_suggest
     env = SearchSolrTools::SolrEnvironments[options[:environment]]
+    logger.info('DELETE ALL AUTO_SUGGEST started')
     `curl 'http://#{env[:host]}:#{env[:port]}/solr/update' -H 'Content-Type: text/xml; charset=utf-8' --data '<delete><query>*:*</query></delete>'`
     `curl 'http://#{env[:host]}:#{env[:port]}/solr/update' -H 'Content-Type: text/xml; charset=utf-8' --data '<commit/>'`
+    logger.info('DELETE ALL AUTO_SUGGEST complete')
   end
 
   desc 'delete_by_data_center', 'Force deletion of documents for a specific data center with timestamps before the passed timestamp in format iso8601 (2014-07-14T21:49:21Z)'
   option :timestamp, required: true
   option :environment, required: true
   option :data_center, required: true
   def delete_by_data_center
+    logger.info("DELETE ALL for data center '#{options[:data_center]}' started")
     harvester = get_harvester_class(options[:data_center]).new options[:environment]
     harvester.delete_old_documents(options[:timestamp],
                                    "data_centers:\"#{SearchSolrTools::Helpers::SolrFormat::DATA_CENTER_NAMES[options[:data_center].upcase.to_sym][:long_name]}\"",
                                    SearchSolrTools::SolrEnvironments[harvester.environment][:collection_name],
                                    true)
+    logger.info("DELETE ALL for data center '#{options[:data_center]}' complete")
   end
 
   no_tasks do

lib/search_solr_tools.rb

@@ -6,6 +6,8 @@
 require_relative 'search_solr_tools/helpers/harvest_status'
 require_relative 'search_solr_tools/errors/harvest_error'
 
+require_relative 'search_solr_tools/logging/sst_logger'
+
 %w[harvesters translators].each do |subdir|
   Dir[File.join(__dir__, 'search_solr_tools', subdir, '*.rb')].each { |file| require file }
 end

lib/search_solr_tools/config/environments.rb

@@ -5,10 +5,10 @@
 module SearchSolrTools
   # configuration to work with solr locally, or on integration/qa/staging/prod
   module SolrEnvironments
-    YAML_ENVS = YAML.load_file(File.expand_path('environments.yaml', __dir__))
+    YAML_ENVS = YAML.load_file(File.expand_path('environments.yaml', __dir__), aliases: true)
 
     def self.[](env = :development)
-      YAML_ENVS[:common].merge(YAML_ENVS[env.to_sym])
+      YAML_ENVS[env.to_sym]
     end
   end
 end

lib/search_solr_tools/config/environments.yaml

@@ -1,4 +1,4 @@
-:common:
+:common: &common
   :auto_suggest_collection_name: auto_suggest
   :collection_name: nsidc_oai
   :collection_path: solr
@@ -9,33 +9,48 @@
   # should be. GLA01.018 will show up if we use DCS API v2.
   :nsidc_oai_identifiers_url: oai?verb=ListIdentifiers&metadataPrefix=dif&retired=false
 
+  # Log details.  Can be overridden by environment-specific values
+  :log_file: /var/log/search-solr-tools.log
+  :log_file_level: warn
+  :log_stdout_level: info
+
 :local:
+  <<: *common
   :host: localhost
   :nsidc_dataset_metadata_url: http://integration.nsidc.org/api/dataset/metadata/
 
-:dev:
+:dev: &dev
+  <<: *common
   ## For the below, you'll need to instantiate your own search-solr instance, and point host to that.
   :host: dev.search-solr.USERNAME.dev.int.nsidc.org
   ## For the metadata content, either set up your own instance of dataset-catalog-services
   ## or change the URL below to point to integration
   :nsidc_dataset_metadata_url: http://dev.dcs.USERNAME.dev.int.nsidc.org:1580/api/dataset/metadata/
 
+:development:
+  <<: *dev
+
 :integration:
+  <<: *common
   :host: integration.search-solr.apps.int.nsidc.org
   :nsidc_dataset_metadata_url: http://integration.nsidc.org/api/dataset/metadata/
 
 :qa:
+  <<: *common
   :host: qa.search-solr.apps.int.nsidc.org
   :nsidc_dataset_metadata_url: http://qa.nsidc.org/api/dataset/metadata/
 
 :staging:
+  <<: *common
   :host: staging.search-solr.apps.int.nsidc.org
   :nsidc_dataset_metadata_url: http://staging.nsidc.org/api/dataset/metadata/
 
 :blue:
+  <<: *common
   :host: blue.search-solr.apps.int.nsidc.org
   :nsidc_dataset_metadata_url: http://nsidc.org/api/dataset/metadata/
 
 :production:
+  <<: *common
   :host: search-solr.apps.int.nsidc.org
   :nsidc_dataset_metadata_url: http://nsidc.org/api/dataset/metadata/

lib/search_solr_tools/errors/harvest_error.rb

@@ -1,8 +1,12 @@
 # frozen_string_literal: true
 
+require_relative '../logging/sst_logger'
+
 module SearchSolrTools
   module Errors
     class HarvestError < StandardError
+      include SSTLogger
+
       ERRCODE_SOLR_PING = 1
       ERRCODE_SOURCE_PING = 2
       ERRCODE_SOURCE_NO_RESULTS = 4
@@ -73,11 +77,11 @@ def initialize(status, message = nil)
       # rubocop:disable Metrics/AbcSize
       def exit_code
         if @status_data.nil?
-          puts "OTHER ERROR REPORTED: #{@other_message}"
+          logger.error "OTHER ERROR REPORTED: #{@other_message}"
           return ERRCODE_OTHER
         end
 
-        puts "EXIT CODE STATUS:\n#{@status_data.status}"
+        logger.error "EXIT CODE STATUS:\n#{@status_data.status}"
 
         code = 0
         code += ERRCODE_SOLR_PING unless @status_data.ping_solr

lib/search_solr_tools/harvesters/auto_suggest.rb

@@ -51,10 +51,10 @@ def add_documents_to_solr(add_docs)
         status = insert_solr_doc add_docs, Base::JSON_CONTENT_TYPE, @env_settings[:auto_suggest_collection_name]
 
         if status == Helpers::HarvestStatus::INGEST_OK
-          puts "Added #{add_docs.size} auto suggest documents in one commit"
+          logger.info "Added #{add_docs.size} auto suggest documents in one commit"
           Helpers::HarvestStatus.new(Helpers::HarvestStatus::INGEST_OK => add_docs)
         else
-          puts "Failed adding #{add_docs.size} documents in single commit, retrying one by one"
+          logger.error "Failed adding #{add_docs.size} documents in single commit, retrying one by one"
           new_add_docs = []
           add_docs.each do |doc|
             new_add_docs << { 'add' => { 'doc' => doc } }

lib/search_solr_tools/harvesters/base.rb

@@ -15,6 +15,8 @@ module SearchSolrTools
   module Harvesters
     # base class for solr harvesters
     class Base
+      include SSTLogger
+
       attr_accessor :environment
 
       DELETE_DOCUMENTS_RATIO = 0.1
@@ -50,10 +52,10 @@ def ping_solr(core = SolrEnvironments[@environment][:collection_name])
         begin
           RestClient.get(url) do |response, _request, _result|
             success = response.code == 200
-            puts "Error in ping request: #{response.body}" unless success
+            logger.error "Error in ping request: #{response.body}" unless success
           end
         rescue StandardError => e
-          puts "Rest exception while pinging Solr: #{e}"
+          logger.error "Rest exception while pinging Solr: #{e}"
         end
         success
       end
@@ -62,7 +64,7 @@ def ping_solr(core = SolrEnvironments[@environment][:collection_name])
       # to "ping" the data center.  Returns true if the ping is successful (or, as
       # in this default, no ping method was defined)
       def ping_source
-        puts 'Harvester does not have ping method defined, assuming true'
+        logger.info 'Harvester does not have ping method defined, assuming true'
         true
       end
 
@@ -81,9 +83,9 @@ def delete_old_documents(timestamp, constraints, solr_core, force: false)
         solr = RSolr.connect url: solr_url + "/#{solr_core}"
         unchanged_count = (solr.get 'select', params: { wt: :ruby, q: delete_query, rows: 0 })['response']['numFound'].to_i
         if unchanged_count.zero?
-          puts "All documents were updated after #{timestamp}, nothing to delete"
+          logger.info "All documents were updated after #{timestamp}, nothing to delete"
         else
-          puts "Begin removing documents older than #{timestamp}"
+          logger.info "Begin removing documents older than #{timestamp}"
           remove_documents(solr, delete_query, constraints, force, unchanged_count)
         end
       end
@@ -99,13 +101,13 @@ def sanitize_data_centers_constraints(query_string)
       def remove_documents(solr, delete_query, constraints, force, numfound)
         all_response_count = (solr.get 'select', params: { wt: :ruby, q: constraints, rows: 0 })['response']['numFound']
         if force || (numfound / all_response_count.to_f < DELETE_DOCUMENTS_RATIO)
-          puts "Deleting #{numfound} documents for #{constraints}"
+          logger.info "Deleting #{numfound} documents for #{constraints}"
           solr.delete_by_query delete_query
           solr.commit
         else
-          puts "Failed to delete records older than current harvest start because they exceeded #{DELETE_DOCUMENTS_RATIO} of the total records for this data center."
-          puts "\tTotal records: #{all_response_count}"
-          puts "\tNon-updated records: #{numfound}"
+          logger.info "Failed to delete records older than current harvest start because they exceeded #{DELETE_DOCUMENTS_RATIO} of the total records for this data center."
+          logger.info "\tTotal records: #{all_response_count}"
+          logger.info "\tNon-updated records: #{numfound}"
         end
       end
 
@@ -121,8 +123,8 @@ def insert_solr_docs(docs, content_type = XML_CONTENT_TYPE, core = SolrEnvironme
           status.record_status doc_status
           doc_status == Helpers::HarvestStatus::INGEST_OK ? success += 1 : failure += 1
         end
-        puts "#{success} document#{success == 1 ? '' : 's'} successfully added to Solr."
-        puts "#{failure} document#{failure == 1 ? '' : 's'} not added to Solr."
+        logger.info "#{success} document#{success == 1 ? '' : 's'} successfully added to Solr."
+        logger.info "#{failure} document#{failure == 1 ? '' : 's'} not added to Solr."
 
         status
       end
@@ -146,14 +148,14 @@ def insert_solr_doc(doc, content_type = XML_CONTENT_TYPE, core = SolrEnvironment
           RestClient.post(url, doc_serialized, content_type:) do |response, _request, _result|
             success = response.code == 200
             unless success
-              puts "Error for #{doc_serialized}\n\n response: #{response.body}"
+              logger.error "Error for #{doc_serialized}\n\n response: #{response.body}"
               status = Helpers::HarvestStatus::INGEST_ERR_SOLR_ERROR
             end
           end
         rescue StandardError => e
           # TODO: Need to provide more detail re: this failure so we know whether to
           #  exit the job with a status != 0
-          puts "Rest exception while POSTing to Solr: #{e}, for doc: #{doc_serialized}"
+          logger.error "Rest exception while POSTing to Solr: #{e}, for doc: #{doc_serialized}"
           status = Helpers::HarvestStatus::INGEST_ERR_SOLR_ERROR
         end
         status
@@ -177,11 +179,11 @@ def get_results(request_url, metadata_path, content_type = 'application/xml')
         request_url = encode_data_provider_url(request_url)
 
         begin
-          puts "Request: #{request_url}"
+          logger.debug "Request: #{request_url}"
           response = URI.parse(request_url).open(read_timeout: timeout, 'Content-Type' => content_type)
         rescue OpenURI::HTTPError, Timeout::Error, Errno::ETIMEDOUT => e
           retries_left -= 1
-          puts "## REQUEST FAILED ## #{e.class} ## Retrying #{retries_left} more times..."
+          logger.error "## REQUEST FAILED ## #{e.class} ## Retrying #{retries_left} more times..."
 
           retry if retries_left.positive?