Merge pull request #479 from swirlai/logging-v2

Overhaul logging, move current info to debug, remove rescore

swirl/connectors/bigquery.py

@@ -37,7 +37,7 @@ class BigQuery(DBConnector):
 
     def execute_search(self, session=None):
 
-        logger.info(f"{self}: execute_search()")
+        logger.debug(f"{self}: execute_search()")
 
         if self.provider.credentials:
             environ["GOOGLE_APPLICATION_CREDENTIALS"] = self.provider.credentials
@@ -83,7 +83,7 @@ def execute_search(self, session=None):
 
     def normalize_response(self):
 
-        logger.info(f"{self}: normalize_response()")
+        logger.debug(f"{self}: normalize_response()")
 
         rows = self.response
         found = self.found

swirl/connectors/chatgpt.py

@@ -39,7 +39,7 @@ def __init__(self, provider_id, search_id, update, request_id=''):
 
     def execute_search(self, session=None):
 
-        logger.info(f"{self}: execute_search()")
+        logger.debug(f"{self}: execute_search()")
 
         if self.provider.credentials:
             openai.api_key = self.provider.credentials
@@ -90,7 +90,7 @@ def execute_search(self, session=None):
 
     def normalize_response(self):
 
-        logger.info(f"{self}: normalize_response()")
+        logger.debug(f"{self}: normalize_response()")
 
         self.results = [
                 {

swirl/connectors/connector.py

@@ -161,7 +161,7 @@ def process_query(self):
         Invoke the specified query_processor for this provider on search.query_string_processed, store the result in self.query_string_to_provider
         '''
 
-        logger.info(f"{self}: process_query()")
+        logger.debug(f"{self}: process_query()")
         processor_list = []
         processor_list = self.provider.query_processors
 
@@ -171,7 +171,7 @@ def process_query(self):
 
         query_temp = self.search.query_string_processed
         for processor in processor_list:
-            logger.info(f"{self}: invoking query processor: {processor}")
+            logger.debug(f"{self}: invoking query processor: {processor}")
             try:
                 processed_query = get_query_processor_or_transform(processor, query_temp, self.provider.query_mappings, self.provider.tags, self.search_user).process()
             except (NameError, TypeError, ValueError) as err:
@@ -197,7 +197,7 @@ def construct_query(self):
         Copy query_string_processed to query_to_provider
         '''
 
-        logger.info(f"{self}: construct_query()")
+        logger.debug(f"{self}: construct_query()")
         self.query_to_provider = self.query_string_to_provider
         return
 
@@ -209,7 +209,7 @@ def validate_query(self, session=None):
         Validate the query_to_provider, and return True or False
         '''
 
-        logger.info(f"{self}: validate_query()")
+        logger.debug(f"{self}: validate_query()")
         if self.query_to_provider == "":
             self.error("query_to_provider is blank or missing")
             return False
@@ -223,7 +223,7 @@ def execute_search(self, session=None):
         Connect to, query and save the response from this provider
         '''
 
-        logger.info(f"{self}: execute_search()")
+        logger.debug(f"{self}: execute_search()")
         self.found = 1
         self.retrieved = 1
         self.response = [
@@ -244,7 +244,7 @@ def normalize_response(self):
         Transform the response from the provider into a json (list) and store as self.results
         '''
 
-        logger.info(f"{self}: normalize_response()")
+        logger.debug(f"{self}: normalize_response()")
         if self.response:
             if len(self.response) == 0:
                 # no results, not an error
@@ -290,7 +290,7 @@ def process_results(self):
         Each processor is expected to MODIFY self.results and RETURN the number of records modified
         '''
 
-        logger.info(f"{self}: process_results()")
+        logger.debug(f"{self}: process_results()")
 
         if self.found == 0:
             return
@@ -313,9 +313,9 @@ def process_results(self):
 
         for processor in processor_list:
             if processor in processors_to_skip:
-                logger.info(f"{self}: skipping processor: process results {processor} becasue it was in a skip tag of the search")
+                logger.debug(f"{self}: skipping processor: process results {processor} becasue it was in a skip tag of the search")
                 continue
-            logger.info(f"{self}: invoking processor: process results {processor}")
+            logger.debug(f"{self}: invoking processor: process results {processor}")
             last_results = copy.deepcopy(self.results)
             try:
                 proc = alloc_processor(processor=processor)(self.results, self.provider, self.query_string_to_provider, request_id=self.request_id,
@@ -352,7 +352,7 @@ def save_results(self):
         Store the transformed results as a Result object in the database, linked to the search_id
         '''
 
-        logger.info(f"{self}: save_results()")
+        logger.debug(f"{self}: save_results()")
         # timing
         end_time = time.time()
 
@@ -388,18 +388,18 @@ def save_results(self):
                 result.query_processors = query_processors
                 result.result_processors = result_processors
                 result.status = 'UPDATED'
-                logger.info(f"{self}: Result.save()")
+                logger.debug(f"{self}: Result.save()")
                 result.save()
             except Error as err:
                 self.error(f'save_results() update failed: {err.args}, {err}', save_results=False)
                 return False
-            logger.info(f"{self}: Update: added {len(self.processed_results)} new items to result {result.id}")
+            logger.debug(f"{self}: Update: added {len(self.processed_results)} new items to result {result.id}")
             self.message(f"Retrieved {len(self.processed_results)} new results from: {result.searchprovider}")
             return True
         # end if
 
         try:
-            logger.info(f"{self}: Result.create()")
+            logger.debug(f"{self}: Result.create()")
             new_result = Result.objects.create(search_id=self.search, searchprovider=self.provider.name, provider_id=self.provider.id,
                                                query_string_to_provider=self.query_string_to_provider, query_to_provider=self.query_to_provider,
                                                query_processors=query_processors, result_processors=result_processors, messages=self.messages,

swirl/connectors/db_connector.py

@@ -38,7 +38,7 @@ def __init__(self, provider_id, search_id, update, request_id=''):
 
     def construct_query(self):
 
-        logger.info(f"{self}: construct_query()")
+        logger.debug(f"{self}: construct_query()")
 
         # handle ;
         if not self.provider.query_template.endswith(';'):
@@ -103,7 +103,7 @@ def construct_query(self):
 
     def validate_query(self, session=None):
 
-        logger.info(f"{self}: validate_query()")
+        logger.debug(f"{self}: validate_query()")
 
         if '{' in self.count_query or '}' in self.count_query:
             self.warning(f"found braces in count_query after template mapping")

swirl/connectors/elastic.py

@@ -42,7 +42,7 @@ def __init__(self, provider_id, search_id, update, request_id=''):
 
     def construct_query(self):
 
-        logger.info(f"{self}: construct_query()")
+        logger.debug(f"{self}: construct_query()")
 
         query_to_provider = bind_query_mappings(self.provider.query_template, self.provider.query_mappings)
 
@@ -76,7 +76,7 @@ def construct_query(self):
 
     def execute_search(self, session=None):
 
-        logger.info(f"{self}: execute_search()")
+        logger.debug(f"{self}: execute_search()")
 
         auth = None
         if self.provider.credentials:
@@ -156,7 +156,7 @@ def execute_search(self, session=None):
 
     def normalize_response(self):
 
-        logger.info(f"{self}: normalize_response()")
+        logger.debug(f"{self}: normalize_response()")
 
         if len(self.response) == 0:
             self.error("search succeeded, but found no json data in response")

swirl/connectors/opensearch.py

@@ -40,7 +40,7 @@ def __init__(self, provider_id, search_id, update, request_id=''):
 
     def construct_query(self):
 
-        logger.info(f"{self}: construct_query()")
+        logger.debug(f"{self}: construct_query()")
 
         base_query = bind_query_mappings(self.provider.query_template, self.provider.query_mappings)
         logger.debug(f"base_query: {base_query}")
@@ -75,7 +75,7 @@ def construct_query(self):
 
     def execute_search(self, session=None):
 
-        logger.info(f"{self}: execute_search()")
+        logger.debug(f"{self}: execute_search()")
 
         parsed_url = urlparse(self.provider.url)
         host = parsed_url.hostname
@@ -177,7 +177,7 @@ def execute_search(self, session=None):
 
     def normalize_response(self):
 
-        logger.info(f"{self}: normalize_response()")
+        logger.debug(f"{self}: normalize_response()")
 
         if len(self.response) == 0:
             self.error("search succeeded, but found no json data in response")

swirl/connectors/postgresql.py

@@ -38,7 +38,7 @@ class PostgreSQL(DBConnector):
 
     def execute_search(self, session=None):
 
-        logger.info(f"{self}: execute_search()")
+        logger.debug(f"{self}: execute_search()")
 
         # connect to the db
         config = self.provider.url.split(':')
@@ -119,7 +119,7 @@ def execute_search(self, session=None):
 
     def normalize_response(self):
 
-        logger.info(f"{self}: normalize_response()")
+        logger.debug(f"{self}: normalize_response()")
 
         rows = self.response
         found = self.found

swirl/connectors/requests.py

@@ -69,7 +69,7 @@ def construct_query(self):
         the query to provider.
         """
 
-        logger.info(f"{self}: construct_query()")
+        logger.debug(f"{self}: construct_query()")
 
         # to do: migrate this to Connector base class?
         query_to_provider = ""
@@ -103,7 +103,7 @@ def construct_query(self):
 
     def validate_query(self, session=None):
 
-        logger.info(f"{self}: validate_query()")
+        logger.debug(f"{self}: validate_query()")
 
         query_to_provider = self.query_to_provider
         if '{' in query_to_provider or '}' in query_to_provider:
@@ -125,7 +125,7 @@ def _put_configured_headers(self, headers = None):
 
     def execute_search(self, session=None):
 
-        logger.info(f"{self}: execute_search()")
+        logger.debug(f"{self}: execute_search()")
 
         # determine if paging is required
         pages = 1
@@ -192,7 +192,7 @@ def execute_search(self, session=None):
                             headers = {
                                 "X-Api-Key": f"{self.provider.credentials.split('X-Api-Key=')[1]}"
                             }
-                            logger.info(f"{self}: sending request with auth header X-Api-Key")
+                            logger.debug(f"{self}: sending request with auth header X-Api-Key")
                             response = self.send_request(page_query, headers=self._put_configured_headers(headers), query=self.query_string_to_provider)
                             # all others
                         else:

swirl/connectors/requestspost.py

@@ -39,7 +39,7 @@ def __init__(self, provider_id, search_id, update, request_id=''):
     ########################################
 
     def validate_query(self, session=None):
-        logger.info(f"{self}: https post request validate_query() returning true")
+        logger.debug(f"{self}: https post request validate_query() returning true")
         try:
             json_object = json.loads(json.dumps(self.provider.post_query_template))
         except ValueError as e:

swirl/connectors/sqlite3.py

@@ -37,7 +37,7 @@ class Sqlite3(DBConnector):
 
     def execute_search(self, session=None):
 
-        logger.info(f"{self}: execute_search()")
+        logger.debug(f"{self}: execute_search()")
 
         # connect to the db
         db_path = self.provider.url
@@ -111,7 +111,7 @@ def execute_search(self, session=None):
 
     def normalize_response(self):
 
-        logger.info(f"{self}: normalize_response()")
+        logger.debug(f"{self}: normalize_response()")
 
         rows = self.response
         found = self.found

swirl/expirer.py

@@ -34,7 +34,7 @@ def expirer():
     # security review for 1.7 - OK - system function
     searches = Search.objects.filter(retention__gt=0)
     for search in searches:
-        logger.info(f"{module_name}: expirer checking: {search.id}")
+        logger.debug(f"{module_name}: expirer checking: {search.id}")
         if search.retention == 0:
             # don't delete - this should not happen because of the filter above
             logger.warning(f"{module_name}: filter error, reviewed a search with retention = {search.retention}")
@@ -54,7 +54,7 @@ def expirer():
                 logger.error(f"{module_name}: unexpected retention setting: {search.retention}")
             if expired:
                 # to do: fix this to show local time, someday P4
-                logger.info(f"{module_name}: expirer deleted: {search.id}")
+                logger.info(f"{module_name}: expirer deleted {search.id}")
                 search.delete()
             # end if
         # end if

swirl/mixers/mixer.py

@@ -11,6 +11,7 @@
 import django
 from django.core.exceptions import ObjectDoesNotExist
 from django.conf import settings
+from django.contrib.auth.models import User
 
 from swirl.utils import swirl_setdir
 path.append(swirl_setdir()) # path to settings.py file
@@ -264,3 +265,7 @@ def finalize(self):
                 self.mix_wrapper['messages'].append(f"[{datetime.now()}] Results ordered by: {self.result_mixer}")
             else:
                 self.mix_wrapper['messages'].append(f"[{datetime.now()}] Results ordered by: {self.type}")
+
+        # log info
+        user = User.objects.get(id=self.search.owner.id)
+        logger.info(f"{user} results {self.search_id} {self.type} {self.mix_wrapper['info']['results']['retrieved_total']}")

swirl/perfomance_logger.py

@@ -17,14 +17,14 @@ def put_providers(self, providers):
 
     def complete_execution(self):
         elapsed_time = time.time() - self.start_time
-        logger.info(f'PLG_QXC|{self.request_id}|{round(elapsed_time,4)}|{self.query}|{self.providers}')
+        logger.debug(f'PLG_QXC|{self.request_id}|{round(elapsed_time,4)}|{self.query}|{self.providers}')
 
     def timeout_execution(self):
-        logger.info(f'PLG_QXT|{self.request_id}|{getattr(settings, "SWIRL_TIMEOUT", 10)}|{self.query}|{self.providers}')
+        logger.debug(f'PLG_QXT|{self.request_id}|{getattr(settings, "SWIRL_TIMEOUT", 10)}|{self.query}|{self.providers}')
 
     def error_execution(self, msg):
         elapsed_time = time.time() - self.start_time
-        logger.info(f'PLG_QXE|{self.request_id}|{round(elapsed_time,4)}|{self.query}|{self.providers}|{msg}')
+        logger.debug(f'PLG_QXE|{self.request_id}|{round(elapsed_time,4)}|{self.query}|{self.providers}|{msg}')
 
 class ProviderQueryRequestLogger:
     def __init__(self, name, id):
@@ -36,7 +36,7 @@ def __enter__(self):
 
     def __exit__(self, type, value, traceback):
         elapsed_time = time.time() - self.start_time
-        logger.info(f'PLG_PXC|{self.request_id}|{round(elapsed_time,4)}|{self.name}')
+        logger.debug(f'PLG_PXC|{self.request_id}|{round(elapsed_time,4)}|{self.name}')
 
 class SwirlRelevancyLogger:
     def __init__(self,  request_id, name="anonymous",log_sim=False):
@@ -45,7 +45,7 @@ def __init__(self,  request_id, name="anonymous",log_sim=False):
         self.log_sim = log_sim
 
     def _log_elapsed(self, t, p):
-        logger.info(f'PLG_RP{p}|{self.request_id}|{t}|{self.name}')
+        logger.debug(f'PLG_RP{p}|{self.request_id}|{t}|{self.name}')
 
     def start_pass_1(self):
         self.pass_1_start_time = time.time()
@@ -68,12 +68,12 @@ def start_nlp(self, flen):
     def end_nlp(self):
         elapsed_time = time.time() - self.nlp_start_time
         if self.log_sim:
-            logger.info(f'PLG_NLP|{self.request_id}|{round(elapsed_time,4)}|{self.nlp_field_len}')
+            logger.debug(f'PLG_NLP|{self.request_id}|{round(elapsed_time,4)}|{self.nlp_field_len}')
 
     def start_sim(self):
         self.sim_start_time = time.time()
 
     def end_sim(self):
         elapsed_time = time.time() - self.sim_start_time
         if self.log_sim:
-            logger.info(f'PLG_SIM|{self.request_id}|{round(elapsed_time,4)}|')
+            logger.debug(f'PLG_SIM|{self.request_id}|{round(elapsed_time,4)}|')

swirl/processors/dedupe.py

@@ -63,7 +63,7 @@ def process(self):
         deduped_item_list = []
         dupes = 0
         dupes = dupes + _dedup_results(results, dedupe_key_dict, deduped_item_list, self.provider.result_grouping_field)
-        logger.info(f'removed {dupes} using field {provider.result_grouping_field} from result with length : {len(results)}')
+        logger.debug(f'removed {dupes} using field {provider.result_grouping_field} from result with length : {len(results)}')
         self.processed_results = deduped_item_list
         return dupes > 0
 
@@ -127,7 +127,7 @@ def process(self):
                 # end if
             # end for
             result.json_results = deduped_item_list
-            logger.info(f"{self}: result.save()")
+            logger.debug(f"{self}: result.save()")
             result.save()
         # end for