Add logging for Shopify GraphQL queries and webhooks

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)
 
 

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: