added some ims i/o performance logging

inventory_provider/db/ims.py

+from enum import Enum
+import functools
 import logging
+import time
 
 import requests
-import time
 
-from enum import Enum
+from inventory_provider import environment
 
 
 # Navigation Properties
@@ -11,6 +13,9 @@ from enum import Enum
 from requests import HTTPError
 
 logger = logging.getLogger(__name__)
+log_entry_and_exit = functools.partial(
+    environment.log_entry_and_exit, logger=logger)
+
 
 # http://149.210.162.190:81/ImsVersions/21.9/html/50e6a1b1-3910-2091-63d5-e13777b2194e.htm  # noqa
 CIRCUIT_CUSTOMER_RELATION = {
@@ -317,6 +322,7 @@ class IMS(object):
                     IMS.cache[cache_key] = return_value
                 return return_value
 
+    @log_entry_and_exit
     def get_entity_by_id(
             self,
             entity_type,
@@ -328,6 +334,7 @@ class IMS(object):
         return \
             self._get_entity(url, None, navigation_properties, use_cache)
 
+    @log_entry_and_exit
     def get_entity_by_name(
             self,
             entity,
@@ -337,6 +344,7 @@ class IMS(object):
         url = f'{entity}/byname/"{name}"'
         return self._get_entity(url, None, navigation_properties, use_cache)
 
+    @log_entry_and_exit
     def get_filtered_entities(
             self,
             entity,
@@ -372,6 +380,7 @@ class IMS(object):
                 start_entity += step_count
                 yield from entities
 
+    @log_entry_and_exit
     def get_all_entities(
             self,
             entity,

inventory_provider/db/ims_data.py

+import functools
 import logging
 import re
 from collections import defaultdict
@@ -9,10 +10,9 @@ from inventory_provider.db import ims
 from inventory_provider.db.ims import InventoryStatus, IMS, \
     CUSTOMER_RELATED_CONTACT_PROPERTIES, EXTRA_FIELD_VALUE_PROPERTIES
 
-environment.setup_logging()
 logger = logging.getLogger(__name__)
-
-# Dashboard V3
+log_entry_and_exit = functools.partial(
+    environment.log_entry_and_exit, logger=logger)
 
 IMS_OPSDB_STATUS_MAP = {
     InventoryStatus.PLANNED: 'planned',
@@ -83,6 +83,7 @@ def get_flexils_by_circuitid(ds: IMS):
     return dict(by_circuit)
 
 
+@log_entry_and_exit
 def get_non_monitored_circuit_ids(ds: IMS):
     # note the id for the relevant field is hard-coded. I didn't want to use
     # the name of the field as this can be changed by users
@@ -94,6 +95,7 @@ def get_non_monitored_circuit_ids(ds: IMS):
         yield d['extrafieldvalueobjectinfo']['objectid']
 
 
+@log_entry_and_exit
 def get_monitored_circuit_ids(ds: IMS):
     # note the id for the relevant field is hard-coded. I didn't want to use
     # the name of the field as this can be changed by users
@@ -106,6 +108,7 @@ def get_monitored_circuit_ids(ds: IMS):
         yield d['extrafieldvalueobjectinfo']['objectid']
 
 
+@log_entry_and_exit
 def get_ids_and_sids(ds: IMS):
     for sid_circuit in ds.get_filtered_entities(
         'ExtraFieldValue',
@@ -115,6 +118,7 @@ def get_ids_and_sids(ds: IMS):
         yield sid_circuit['objectid'], sid_circuit['value']
 
 
+@log_entry_and_exit
 def get_service_types(ds: IMS):
     for d in ds.get_filtered_entities(
             'ComboBoxData',
@@ -122,6 +126,7 @@ def get_service_types(ds: IMS):
         yield d['selection']
 
 
+@log_entry_and_exit
 def get_customer_tts_contacts(ds: IMS):
 
     customer_contacts = defaultdict(set)
@@ -137,6 +142,7 @@ def get_customer_tts_contacts(ds: IMS):
         yield k, sorted(list(v))
 
 
+@log_entry_and_exit
 def get_customer_planned_work_contacts(ds: IMS):
 
     customer_contacts = defaultdict(set)
@@ -152,6 +158,7 @@ def get_customer_planned_work_contacts(ds: IMS):
         yield k, sorted(list(v))
 
 
+@log_entry_and_exit
 def get_circuit_related_customers(ds: IMS):
 
     return_value = defaultdict(list)
@@ -169,6 +176,7 @@ def get_circuit_related_customers(ds: IMS):
     return return_value
 
 
+@log_entry_and_exit
 def get_port_id_services(ds: IMS):
     circuit_nav_props = [
         ims.CIRCUIT_PROPERTIES['Ports'],
@@ -300,6 +308,7 @@ def get_port_id_services(ds: IMS):
             }
 
 
+@log_entry_and_exit
 def get_port_sids(ds: IMS):
     """
     This function fetches SIDs for external ports that have them defined,
@@ -313,6 +322,7 @@ def get_port_sids(ds: IMS):
             step_count=10000)}
 
 
+@log_entry_and_exit
 def get_internal_port_sids(ds: IMS):
     """
     This function fetches SIDs for external ports that have them defined,
@@ -326,6 +336,7 @@ def get_internal_port_sids(ds: IMS):
             step_count=10000)}
 
 
+@log_entry_and_exit
 def get_port_details(ds: IMS):
     port_nav_props = [
         ims.PORT_PROPERTIES['Node'],
@@ -381,6 +392,7 @@ def get_port_details(ds: IMS):
         'internalport', internal_port_nav_props, step_count=2000), 'internal')
 
 
+@log_entry_and_exit
 def get_circuit_hierarchy(ds: IMS):
     circuit_nav_props = [
         ims.CIRCUIT_PROPERTIES['Customer'],
@@ -425,6 +437,7 @@ def get_circuit_hierarchy(ds: IMS):
         }
 
 
+@log_entry_and_exit
 def get_node_locations(ds: IMS):
     """
     return location info for all Site nodes
@@ -498,6 +511,7 @@ INTERNAL_POP_NAMES = {
 }
 
 
+@log_entry_and_exit
 def lookup_lg_routers(ds: IMS):
     pattern = re.compile("vpn-proxy|vrr|taas", re.IGNORECASE)
 
@@ -562,6 +576,7 @@ def lookup_lg_routers(ds: IMS):
             yield eq
 
 
+@log_entry_and_exit
 def lookup_geant_nodes(ds: IMS):
 
     return (n["name"]for n in ds.get_filtered_entities(

inventory_provider/environment.py

+import functools
 import json
 import logging.config
 import os
+import time
+
+
+def log_entry_and_exit(f, logger):
+    # cf. https://stackoverflow.com/a/47663642
+    # cf. https://stackoverflow.com/a/59098957/6708581
+    @functools.wraps(f)
+    def _w(*args, **kwargs):
+        logger.debug(f'>>> {f.__name__}{args}')
+        start_time = time.time()
+        try:
+            return f(*args, **kwargs)
+        finally:
+            end_time = time.time()
+            duration = end_time - start_time
+            logger.debug(f'<<< {f.__name__}{args} -- duration {duration}')
+    return _w
 
 
 def setup_logging():

inventory_provider/tasks/worker.py

@@ -4,7 +4,6 @@ import json
 import logging
 import os
 import re
-import time
 from typing import List
 
 from celery import Task, states, chord
@@ -36,24 +35,9 @@ FINALIZER_TIMEOUT_S = 300
 # TODO: error callback (cf. http://docs.celeryproject.org/en/latest/userguide/calling.html#linking-callbacks-errbacks)  # noqa: E501
 
 environment.setup_logging()
-
 logger = logging.getLogger(__name__)
-
-
-def log_task_entry_and_exit(f):
-    # cf. https://stackoverflow.com/a/47663642
-    # cf. https://stackoverflow.com/a/59098957/6708581
-    @functools.wraps(f)
-    def _w(*args, **kwargs):
-        logger.debug(f'>>> {f.__name__}{args}')
-        start_time = time.time()
-        try:
-            return f(*args, **kwargs)
-        finally:
-            end_time = time.time()
-            duration = end_time - start_time
-            logger.debug(f'<<< {f.__name__}{args} -- duration {duration}')
-    return _w
+log_task_entry_and_exit = functools.partial(
+    environment.log_entry_and_exit, logger=logger)
 
 
 class InventoryTaskError(Exception):