diff --git a/connect/logger/logger.py b/connect/logger/logger.py index e6dba9a..83ecabf 100644 --- a/connect/logger/logger.py +++ b/connect/logger/logger.py @@ -7,38 +7,37 @@ import json import logging import os - from logging.config import dictConfig -from connect.models.base import BaseModel with open(os.path.join(os.path.dirname(__file__), 'config.json')) as config_file: config = json.load(config_file) dictConfig(config['logging']) + logger = logging.getLogger() -def log_request_data(args): - if len(args) and isinstance(args[0], BaseModel): - global logger - base = " %(levelname)-6s; %(asctime)s; %(name)-6s; %(module)s:%(funcName)s:line"\ - "-%(lineno)d: %(message)s" - sformat = args[0].id + base - if hasattr(args[0], 'asset') and hasattr(args[0].asset, 'id'): - sformat = args[0].asset.id + " " + sformat +def function_log(custom_logger=None): + if not custom_logger: + custom_logger = logging.getLogger() + sformat = " %(levelname)-6s; %(asctime)s; %(name)-6s; %(module)s:%(funcName)s:line" \ + "-%(lineno)d: %(message)s" [handler.setFormatter(logging.Formatter(sformat, "%I:%M:%S")) - for handler in logger.handlers] - - -def function_log(func): - @wraps(func) - def decorator(self, *args, **kwargs): - log_request_data(args) - logger.info('Entering: %s', func.__name__) - logger.debug('Function params: {} {}'.format(args, kwargs)) - result = func(self, *args, **kwargs) - logger.debug( - 'Function `{}.{}` return: {}'.format(self.__class__.__name__, func.__name__, result)) - return result + for handler in custom_logger.handlers] + + # noinspection PyUnusedLocal + def decorator(func, **kwargs): + # noinspection PyShadowingNames + @wraps(func) + def wrapper(self, *args, **kwargs): + custom_logger.info('Entering: %s', func.__name__) + custom_logger.debug('Function params: {} {}'.format(args, kwargs)) + result = func(self, *args, **kwargs) + custom_logger.debug( + 'Function `{}.{}` return: {}'.format( + self.__class__.__name__, func.__name__, result)) + return result + + return wrapper return decorator diff --git a/connect/models/base.py b/connect/models/base.py index 5ef6b07..696c1c2 100644 --- a/connect/models/base.py +++ b/connect/models/base.py @@ -57,8 +57,7 @@ def deserialize_json(cls, json_data): if error: raise TypeError( 'Invalid structure for initialization of `{type}`. \n' - 'Error: {error}. \nJSON data: {data}' - .format( + 'Error: {error}. \nJSON data: {data}'.format( type=cls.__name__, error=error, data=json_data), diff --git a/connect/resources/automation_engine.py b/connect/resources/automation_engine.py index b30d07f..b09c361 100644 --- a/connect/resources/automation_engine.py +++ b/connect/resources/automation_engine.py @@ -3,9 +3,11 @@ # This file is part of the Ingram Micro Cloud Blue Connect SDK. # Copyright (c) 2019 Ingram Micro. All Rights Reserved. +import copy +import logging from typing import Any, Dict -from connect.logger import function_log +from connect.logger import function_log, logger as global_logger from connect.models.activation_tile_response import ActivationTileResponse from connect.models.base import BaseModel from .base import BaseResource @@ -14,6 +16,7 @@ class AutomationEngine(BaseResource): limit = 1000 # type: int + logger = logging.getLogger() def filters(self, status='pending', **kwargs): # type: (str, Dict[str, Any]) -> Dict[str, Any] @@ -33,22 +36,34 @@ def process_request(self, request): raise NotImplementedError('Please implement `{}.process_request` method' .format(self.__class__.__name__)) - @function_log + @function_log(custom_logger=logger) def approve(self, pk, data): # type: (str, dict) -> str return self._api.post(path=pk + '/approve/', json=data)[0] - @function_log + @function_log(custom_logger=logger) def inquire(self, pk): # type: (str) -> str return self._api.post(path=pk + '/inquire/', json={})[0] - @function_log + @function_log(custom_logger=logger) def fail(self, pk, reason): # type: (str, str) -> str return self._api.post(path=pk + '/fail/', json={'reason': reason})[0] - @function_log + @function_log(custom_logger=logger) def render_template(self, pk, template_id): # type: (str, str) -> ActivationTileResponse return TemplateResource(self.config).render(template_id, pk) + + def _set_custom_logger(self, *args): + handlers = [copy.copy(hdlr) for hdlr in global_logger.handlers] + log_level = global_logger.level + self.__class__.logger.setLevel(log_level) + self.__class__.logger.propagate = False + [self.__class__.logger.addHandler(hdlr) for hdlr in handlers] + base = " %(levelname)-6s; %(asctime)s; %(name)-6s; %(module)s:%(funcName)s:line" \ + "-%(lineno)d: %(message)s" + sformat = " ".join(args) + base + [handler.setFormatter(logging.Formatter(sformat, "%I:%M:%S")) + for handler in self.__class__.logger.handlers] diff --git a/connect/resources/base.py b/connect/resources/base.py index 002951d..eaea460 100644 --- a/connect/resources/base.py +++ b/connect/resources/base.py @@ -4,6 +4,7 @@ # Copyright (c) 2019 Ingram Micro. All Rights Reserved. import functools +import logging from typing import Any, List, Dict, Tuple import requests @@ -11,7 +12,7 @@ from connect.config import Config from connect.exceptions import ServerError -from connect.logger import function_log, logger +from connect.logger import function_log from connect.models.base import BaseModel from connect.models.server_error_response import ServerErrorResponse @@ -59,21 +60,21 @@ def urljoin(*args): lambda a, b: compat.urljoin(a + ('' if a.endswith('/') else '/'), b) if b else a, args) - @function_log + @function_log() def get(self, path='', **kwargs): # type: (str, Any) -> Tuple[str, int] kwargs = self._fix_request_kwargs(path, kwargs) response = requests.get(**kwargs) return self._check_and_pack_response(response) - @function_log + @function_log() def post(self, path='', **kwargs): # type: (str, Any) -> Tuple[str, int] kwargs = self._fix_request_kwargs(path, kwargs) response = requests.post(**kwargs) return self._check_and_pack_response(response) - @function_log + @function_log() def put(self, path='', **kwargs): # type: (str, Any) -> Tuple[str, int] kwargs = self._fix_request_kwargs(path, kwargs) @@ -123,6 +124,7 @@ class BaseResource(object): resource = None # type: str limit = 100 # type: int model_class = BaseModel + logger = logging.getLogger() def __init__(self, config=None): # Set client @@ -156,6 +158,6 @@ def filters(self, **kwargs): def list(self, filters=None): # type: (Dict[str, Any]) -> List[Any] filters = filters or self.filters() - logger.info('Get list request with filters - {}'.format(filters)) + self.logger.info('Get list request with filters - {}'.format(filters)) response, _ = self._api.get(params=filters) return self.model_class.deserialize(response) diff --git a/connect/resources/fulfillment_automation.py b/connect/resources/fulfillment_automation.py index 6fa43f4..3533e19 100644 --- a/connect/resources/fulfillment_automation.py +++ b/connect/resources/fulfillment_automation.py @@ -4,12 +4,13 @@ # Copyright (c) 2019 Ingram Micro. All Rights Reserved. from abc import ABCMeta +import logging from deprecation import deprecated from typing import Optional from connect.exceptions import FailRequest, InquireRequest, SkipRequest -from connect.logger import logger, function_log +from connect.logger import function_log from connect.models.activation_template_response import ActivationTemplateResponse from connect.models.activation_tile_response import ActivationTileResponse from connect.models.param import Param @@ -40,6 +41,7 @@ class FulfillmentAutomation(AutomationEngine): __metaclass__ = ABCMeta resource = 'requests' model_class = Fulfillment + logger = logging.getLogger('Fullfilment.logger') def filters(self, status='pending', **kwargs): """ Returns the default set of filters for Fulfillment request, plus any others that you @@ -72,9 +74,10 @@ def filters(self, status='pending', **kwargs): filters['asset.product.id__in'] = ','.join(self.config.products) return filters - @function_log + @function_log(custom_logger=logger) def dispatch(self, request): # type: (Fulfillment) -> str + self._set_custom_logger(request.asset.id, request.id) conversation = request.get_conversation(self.config) @@ -83,11 +86,11 @@ def dispatch(self, request): and request.asset.product.id not in self.config.products: return 'Invalid product' - logger.info('Start request process / ID request - {}'.format(request.id)) + self.logger.info('Start request process / ID request - {}'.format(request.id)) process_result = self.process_request(request) if not process_result: - logger.info('Method `process_request` did not return result') + self.logger.info('Method `process_request` did not return result') return '' if isinstance(process_result, ActivationTileResponse): @@ -125,8 +128,8 @@ def dispatch(self, request): raise except Exception as ex: - logger.warning('Skipping request {} because an exception was raised: {}' - .format(request.id, ex)) + self.logger.warning('Skipping request {} because an exception was raised: {}' + .format(request.id, ex)) return '' def create_request(self, request): @@ -167,7 +170,7 @@ def get_tier_config(self, tier_id, product_id): else: return None - @function_log + @function_log(custom_logger=logger) def update_parameters(self, pk, params): """ Sends a list of Param objects to Connect for updating. @@ -179,18 +182,16 @@ def update_parameters(self, pk, params): list_dict = [] for _ in params: list_dict.append(_.__dict__ if isinstance(_, Param) else _) - return self._api.put( path=pk, json={'asset': {'params': list_dict}}, )[0] - @staticmethod - def _update_conversation_if_exists(conversation, request_id, obj): + def _update_conversation_if_exists(self, conversation, request_id, obj): # type: (Optional[Conversation], str, object) -> None if conversation: try: conversation.add_message(str(obj)) except TypeError as ex: - logger.error('Error updating conversation for request {}: {}' - .format(request_id, ex)) + self.logger.error('Error updating conversation for request {}: {}' + .format(request_id, ex)) diff --git a/connect/resources/tier_config_automation.py b/connect/resources/tier_config_automation.py index 9e26a4c..d1869e5 100644 --- a/connect/resources/tier_config_automation.py +++ b/connect/resources/tier_config_automation.py @@ -4,9 +4,10 @@ # Copyright (c) 2019 Ingram Micro. All Rights Reserved. from abc import ABCMeta +import logging from connect.exceptions import FailRequest, InquireRequest, SkipRequest -from connect.logger import logger, function_log +from connect.logger import function_log from connect.models.activation_template_response import ActivationTemplateResponse from connect.models.activation_tile_response import ActivationTileResponse from connect.models.param import Param @@ -35,6 +36,7 @@ class TierConfigAutomation(AutomationEngine): __metaclass__ = ABCMeta resource = 'tier/config-requests' model_class = TierConfigRequest + logger = logging.getLogger('Tier.logger') def filters(self, status='pending', **kwargs): """ Returns the default set of filters for Tier Config request, plus any others that you @@ -61,20 +63,23 @@ def filters(self, status='pending', **kwargs): filters['configuration__product__id'] = ','.join(self.config.products) return filters - @function_log + @function_log(custom_logger=logger) def dispatch(self, request): # type: (TierConfigRequest) -> str try: + self._set_custom_logger(request.id, request.configuration.id, + request.configuration.account.id) + if self.config.products \ and request.configuration.product.id not in self.config.products: return 'Invalid product' - logger.info( + self.logger.info( 'Start tier config request process / ID request - {}'.format(request.id)) result = self.process_request(request) if not result: - logger.info('Method `process_request` did not return result') + self.logger.info('Method `process_request` did not return result') return '' params = {} @@ -99,13 +104,13 @@ def dispatch(self, request): raise except Exception as ex: - logger.warning('Skipping request {} because an exception was raised: {}' - .format(request.id, ex)) + self.logger.warning('Skipping request {} because an exception was raised: {}' + .format(request.id, ex)) return '' return '' - @function_log + @function_log(custom_logger=logger) def update_parameters(self, pk, params): """ Sends a list of Param objects to Connect for updating. diff --git a/connect/resources/usage_automation.py b/connect/resources/usage_automation.py index bafc5fd..33a1ef0 100644 --- a/connect/resources/usage_automation.py +++ b/connect/resources/usage_automation.py @@ -4,6 +4,7 @@ # Copyright (c) 2019 Ingram Micro. All Rights Reserved. import json +import logging from abc import ABCMeta from tempfile import NamedTemporaryFile @@ -12,7 +13,6 @@ from typing import List, Optional from connect.exceptions import FileCreationError, FileRetrievalError -from connect.logger import logger from connect.models.usage_listing import UsageListing from connect.models.usage_file import UsageFile from connect.models.usage_record import UsageRecord @@ -28,6 +28,7 @@ class UsageAutomation(AutomationEngine): __metaclass__ = ABCMeta resource = 'listings' model_class = UsageFile + logger = logging.getLogger('Usage.logger') def filters(self, status='listed', **kwargs): """ @@ -44,12 +45,14 @@ def filters(self, status='listed', **kwargs): def dispatch(self, request): # type: (UsageListing) -> str + self._set_custom_logger(request.id, request.contract.marketplace.id) + # TODO Shouldn't this raise an exception on ALL automation classes? if self.config.products \ and request.product.id not in self.config.products: return 'Listing not handled by this processor' - logger.info( + self.logger.info( 'Processing Usage for Product {} ({}) '.format(request.product.id, request.product.name) + 'on Contract {} '.format(request.contract.id) + @@ -58,15 +61,15 @@ def dispatch(self, request): try: result = self.process_request(request) except FileCreationError: - logger.info( + self.logger.info( 'Error processing Usage for Product {} ({}) '.format(request.product.id, request.product.name) + 'on Contract {} '.format(request.contract.id) + 'and provider {}({})'.format(request.provider.id, request.provider.name)) return 'failure' - logger.info('Processing result for usage on listing {}: {}' - .format(request.product.id, result)) + self.logger.info('Processing result for usage on listing {}: {}' + .format(request.product.id, result)) return 'success' def get_usage_template(self, product): @@ -80,13 +83,13 @@ def get_usage_template(self, product): location = self._get_usage_template_download_location(product.id) if not location: msg = 'Error obtaining template usage file location' - logger.error(msg) + self.logger.error(msg) raise FileRetrievalError(msg) contents = self._retrieve_usage_template(location) if location else None if not contents: msg = 'Error obtaining template usage file from `{}`'.format(location) - logger.error(msg) + self.logger.error(msg) raise FileRetrievalError(msg) return contents @@ -180,7 +183,7 @@ def _upload_spreadsheet(self, usage_file, spreadsheet): headers['Accept'] = 'application/json' del headers['Content-Type'] # This must NOT be set for multipart post requests multipart = {'usage_file': ('usage_file.xlsx', file_contents)} - logger.info('HTTP Request: {} - {} - {}'.format(url, headers, multipart)) + self.logger.info('HTTP Request: {} - {} - {}'.format(url, headers, multipart)) # Post request try: @@ -190,8 +193,8 @@ def _upload_spreadsheet(self, usage_file, spreadsheet): files=multipart) except requests.RequestException as ex: raise FileCreationError('Error uploading file: {}'.format(ex)) - logger.info('HTTP Code: {}'.format(status)) + self.logger.info('HTTP Code: {}'.format(status)) if status != 201: msg = 'Unexpected server response, returned code {}'.format(status) - logger.error('{} -- Raw response: {}'.format(msg, content)) + self.logger.error('{} -- Raw response: {}'.format(msg, content)) raise FileCreationError(msg) diff --git a/connect/resources/usage_file_automation.py b/connect/resources/usage_file_automation.py index ee70350..fe8ff43 100644 --- a/connect/resources/usage_file_automation.py +++ b/connect/resources/usage_file_automation.py @@ -3,10 +3,10 @@ # This file is part of the Ingram Micro Cloud Blue Connect SDK. # Copyright (c) 2019 Ingram Micro. All Rights Reserved. +import logging from abc import ABCMeta from connect.exceptions import SkipRequest, UsageFileAction -from connect.logger import logger from connect.models.base import BaseModel from connect.models.usage_file import UsageFile from .automation_engine import AutomationEngine @@ -21,6 +21,7 @@ class UsageFileAutomation(AutomationEngine): __metaclass__ = ABCMeta resource = 'usage/files' model_class = UsageFile + logger = logging.getLogger('UsageFile.logger') def filters(self, status='ready', **kwargs): """ @@ -36,6 +37,9 @@ def filters(self, status='ready', **kwargs): def dispatch(self, request): # type: (UsageFile) -> str + + self._set_custom_logger(request.id, request.name) + try: # Validate product if self.config.products \ @@ -43,7 +47,7 @@ def dispatch(self, request): return 'Invalid product' # Process request - logger.info( + self.logger.info( 'Start usage file request process / ID request - {}'.format(request.id)) result = self.process_request(request) @@ -51,7 +55,7 @@ def dispatch(self, request): processing_result = 'UsageFileAutomation.process_request returned {} while ' \ 'is expected to raise UsageFileAction or SkipRequest exception' \ .format(str(result)) - logger.warning(processing_result) + self.logger.warning(processing_result) raise UserWarning(processing_result) # Catch action @@ -67,6 +71,6 @@ def dispatch(self, request): except SkipRequest: processing_result = 'skip' - logger.info('Finished processing of usage file with ID {} with result {}' - .format(request.id, processing_result)) + self.logger.info('Finished processing of usage file with ID {} with result {}' + .format(request.id, processing_result)) return processing_result diff --git a/tests/test_tier_config.py b/tests/test_tier_config.py index f1cd124..7d55fb2 100644 --- a/tests/test_tier_config.py +++ b/tests/test_tier_config.py @@ -6,7 +6,6 @@ import os from datetime import datetime -import pytest from mock import MagicMock, patch from typing import Union @@ -164,13 +163,6 @@ def test_process_no_result(): automation.process() -@patch('requests.get', MagicMock(return_value=_get_response_ok())) -def test_process_not_implemented(): - with pytest.raises(NotImplementedError): - automation = TierConfigAutomation() - automation.process() - - @patch('requests.get', MagicMock(return_value=_get_response_ok_invalid_product())) def test_process_invalid_product(): automation = TierConfigAutomationHelper()