Http logging

ptero_common/celery/http.py

@@ -34,19 +34,21 @@ def run(self, method, url, **kwargs):
                 timeout=10, logger=LOG)
         except ConnectionError:
             delay = DELAYS[self.request.retries]
-            LOG.info(
+            LOG.exception(
                 "A ConnectionError occured for while attempting to send "
                 "%s  %s, retrying in %s seconds. Attempt %d of %d.",
                 method.upper(), url, delay, self.request.retries + 1,
-                self.max_retries + 1)
+                self.max_retries + 1, extra={"method": method.upper(),
+                    "url": url})
             self.retry(throw=False, countdown=delay)
 
         if response.status_code in CODES_TO_RETRY:
             delay = DELAYS[self.request.retries]
-            LOG.info(
+            LOG.warning(
                 "Got response (%s), retrying in %s seconds.  Attempt %d of %d.",
                 response.status_code, delay, self.request.retries + 1,
-                self.max_retries + 1)
+                self.max_retries + 1, extra={"method": method.upper(),
+                    "status_code": response.status_code, "url": url})
             self.retry(throw=False, countdown=delay)
 
         response_info = {
@@ -58,9 +60,10 @@ def run(self, method, url, **kwargs):
             "headers": lowercase_dict(response.headers),
         }
 
-        if response.status_code < 200 or response.status_code >= 300:
-            LOG.info("Got response (%s), returning response info.",
-                     response.status_code)
+        if is_not_200(response.status_code):
+            LOG.warning("Got response (%s), returning response info.",
+                    response.status_code, extra={"method": method.upper(),
+                    "status_code": response.status_code, "url": url})
             return response_info
         elif not self.ignore_result:
             response_info["json"] = response.json()
@@ -72,6 +75,10 @@ def body(self, kwargs):
         return json.dumps(kwargs)
 
 
+def is_not_200(status_code):
+    return status_code < 200 or 300 <= status_code
+
+
 def lowercase_dict(dict_like):
     return {key.lower(): value for key, value in dict_like.iteritems()}
 

ptero_common/logging_configuration.py

@@ -21,6 +21,11 @@ def configure_celery_logging(service_name):
     logging.getLogger('sqlalchemy.engine').setLevel(
         os.environ.get('PTERO_%s_ORM_LOG_LEVEL' % service_name, 'WARN'))
 
+    env_var_name = 'PTERO_%s_HTTP_LOG_LEVEL' % service_name
+    if env_var_name in os.environ:
+        logging.getLogger('ptero_common.celery.http').setLevel(
+                os.environ[env_var_name])
+
 
 def configure_web_logging(service_name):
     configure_logging(

ptero_common/nicer_logging.py

@@ -93,40 +93,59 @@ def wrapper(*args, **kwargs):
         if 'logger' in kwargs:
             del kwargs['logger']
 
-        kwargs_for_constructor = kwargs.copy()
-        if 'timeout' in kwargs_for_constructor:
-            # timout is an argument to requests.get/post/ect but not
-            # Request.__init__
-            del kwargs_for_constructor['timeout']
+        kwargs_for_constructor = get_args_for_request_constructor(kwargs)
         request = Request(kind.upper(), *args, **kwargs_for_constructor)
 
+        def log_with_extra(callable, *_args, **_kwargs):
+            extra = {"method": kind.upper(), "url": request.url}
+
+            if "extra" in _kwargs:
+                extra.update(_kwargs["extra"])
+
+            _kwargs["extra"] = extra
+            return callable(*_args, **_kwargs)
+
         label = '%s %s' % (kind.upper(), request.url)
-        logger.debug("Params for %s: %s", label, _pformat(request.params))
-        logger.debug("Headers for %s: %s", label, _pformat(request.headers))
-        logger.debug("Data for %s: %s", label, _pformat(request.data))
+        log_with_extra(logger.info, "Submitting HTTP %s", label)
+        log_with_extra(logger.debug, "Params for %s: %s", label,
+                _pformat(request.params))
+        log_with_extra(logger.debug, "Headers for %s: %s", label,
+                _pformat(request.headers))
+        log_with_extra(logger.debug, "Data for %s: %s", label,
+                _pformat(request.data))
 
         try:
             response = target(*args, **kwargs)
         except ConnectionError:
             raise
         except Exception:
-            logger.exception(
+            log_with_extra(logger.exception,
                 "Exception while sending %s:\n"
                 "  Args: %s\n"
                 "  Keyword Args: %s",
                 label, _pformat(args), _pformat(kwargs))
             raise
 
-        logger.debug("Got %s from %s", response.status_code, label)
-        logger.debug("Body of response from %s: %s", label,
+        log_with_extra(logger.info, "Got %s from %s", response.status_code,
+                label, extra={"status_code": response.status_code})
+        log_with_extra(logger.debug, "Body of response from %s: %s", label,
                 _pformat(response.text))
-        logger.debug("Headers in response from %s: %s", label,
+        log_with_extra(logger.debug, "Headers in response from %s: %s", label,
                 _pformat(response.headers))
 
         return response
     return wrapper
 
 
+def get_args_for_request_constructor(kwargs):
+    kwargs_for_constructor = kwargs.copy()
+    if 'timeout' in kwargs_for_constructor:
+        # timout is an argument to requests.get/post/ect but not
+        # Request.__init__
+        del kwargs_for_constructor['timeout']
+    return kwargs_for_constructor
+
+
 class LoggedRequest(object):
     def __getattr__(self, name):
         return _log_request(getattr(requests, name), name)