diff --git a/modules/web_shop_shopify/routes.py b/modules/web_shop_shopify/routes.py index fc338d6b33..d93e48231f 100644 --- a/modules/web_shop_shopify/routes.py +++ b/modules/web_shop_shopify/routes.py @@ -35,6 +35,7 @@ def order(request, pool, shop): topic = request.headers.get('X-Shopify-Topic') order = request.get_json() + logger.info("Shopify webhook %s for %s", topic, order['id']) if topic == 'orders/create': if not Sale.search([ ('web_shop', '=', shop.id), @@ -58,7 +59,7 @@ def order(request, pool, shop): sale, = sales Shop.__queue__.update_sale_ids(shop, [sale.id]) else: - logger.info("Unsupported topic '%s'", topic) + logger.warn("Unsupported topic '%s'", topic) return Response(status=HTTPStatus.NO_CONTENT) diff --git a/modules/web_shop_shopify/shopify_retry.py b/modules/web_shop_shopify/shopify_retry.py index 1d57d66a94..a86404fe9b 100644 --- a/modules/web_shop_shopify/shopify_retry.py +++ b/modules/web_shop_shopify/shopify_retry.py @@ -1,6 +1,7 @@ # This file is part of Tryton. The COPYRIGHT file at the top level of # this repository contains the full copyright notices and license terms. import json +import logging import time import urllib @@ -21,6 +22,9 @@ except ImportError: return self._response['errors'] from trytond.protocols.wrappers import HTTPStatus +from trytond.tools.logging import format_args + +logger = logging.getLogger(__name__) def patch(): @@ -32,12 +36,15 @@ def patch(): if e.response.code == HTTPStatus.TOO_MANY_REQUESTS: retry_after = float( e.response.headers.get('Retry-After', 2)) + logger.debug( + "Shopify connection retry after %ss", retry_after) time.sleep(retry_after) else: raise else: try: if Limits.credit_maxed(): + logger.debug("Shopify connection credit maxed") time.sleep(0.5) except Exception: pass @@ -46,24 +53,33 @@ def patch(): open_func = ShopifyConnection._open ShopifyConnection._open = _open - def graphql_execute(*args, **kwargs): + def graphql_execute(self, *args, **kwargs): + log_message = "GraphQL execute %s" + log_args = ( + format_args(args, kwargs, logger.isEnabledFor(logging.DEBUG)),) while True: try: - result = graphql_execute_func(*args, **kwargs) + result = graphql_execute_func(self, *args, **kwargs) except urllib.error.HTTPError as e: if e.code == HTTPStatus.TOO_MANY_REQUESTS: retry_after = float(e.headers.get('Retry-After', 2)) + logger.debug("GraphQL retry after %ss", retry_after) time.sleep(retry_after) else: + logger.exception(log_message, *log_args) raise GraphQLException(json.load(e.fp)) if isinstance(result, str): result = json.loads(result) if result.get('errors'): for error in result['errors']: if error.get('extensions', {}).get('code') == 'THROTTLED': + logger.debug("GraphQL throttled") time.sleep(0.5) continue + logger.exception(log_message, *log_args) raise GraphQLException(result) + logger.info(log_message, *log_args) + logger.debug("GraphQL Result: %r", result) return result if GraphQL.execute != graphql_execute: