From f01760f6e62418bf7b46364bc686569fbda69d75 Mon Sep 17 00:00:00 2001
From: Rebecca Law <rebecca.law@digital.cabinet-office.gov.uk>
Date: Fri, 17 Mar 2017 12:38:24 +0000
Subject: [PATCH 1/2] Update statsd decorator so that it will log on error.
 Added logging for the build_dvla_file task

---
 app/celery/tasks.py      |  3 +++
 app/statsd_decorators.py | 36 +++++++++++++++++++++++-------------
 2 files changed, 26 insertions(+), 13 deletions(-)

diff --git a/app/celery/tasks.py b/app/celery/tasks.py
index 37c17e0f3..fc50e4e0c 100644
--- a/app/celery/tasks.py
+++ b/app/celery/tasks.py
@@ -83,6 +83,8 @@ def process_job(job_id):
     )
     if template.template_type == LETTER_TYPE:
         build_dvla_file.apply_async([str(job.id)], queue='process-job')
+        # temporary logging
+        current_app.logger.info("send job {} to build-dvla-file in the process-job queue".format(job_id))
 
 
 def process_row(row_number, recipient, personalisation, template, job, service):
@@ -277,6 +279,7 @@ def build_dvla_file(self, job_id):
                  bucket_name=current_app.config['DVLA_UPLOAD_BUCKET_NAME'],
                  file_location="{}-dvla-job.text".format(job_id))
     else:
+        current_app.logger.info("All notifications for job {} are not persisted".format(job_id))
         self.retry(queue="retry", exc="All notifications for job {} are not persisted".format(job_id))
 
 
diff --git a/app/statsd_decorators.py b/app/statsd_decorators.py
index 2f83f13b6..677d7cb79 100644
--- a/app/statsd_decorators.py
+++ b/app/statsd_decorators.py
@@ -10,20 +10,30 @@ def statsd(namespace):
         @functools.wraps(func)
         def wrapper(*args, **kwargs):
             start_time = monotonic()
-            res = func(*args, **kwargs)
-            elapsed_time = monotonic() - start_time
-            current_app.logger.info(
-                "{namespace} call {func} took {time}".format(
-                    namespace=namespace, func=func.__name__, time="{0:.4f}".format(elapsed_time)
+            try:
+                res = func(*args, **kwargs)
+                elapsed_time = monotonic() - start_time
+
+            except Exception as e:
+                current_app.logger.error(
+                    "{namespace} call {func} failed".format(
+                        namespace=namespace, func=func.__name__
+                    )
                 )
-            )
-            statsd_client.incr('{namespace}.{func}'.format(
-                namespace=namespace, func=func.__name__)
-            )
-            statsd_client.timing('{namespace}.{func}'.format(
-                namespace=namespace, func=func.__name__), elapsed_time
-            )
-            return res
+                raise e
+            else:
+                current_app.logger.info(
+                    "{namespace} call {func} took {time}".format(
+                        namespace=namespace, func=func.__name__, time="{0:.4f}".format(elapsed_time)
+                    )
+                )
+                statsd_client.incr('{namespace}.{func}'.format(
+                    namespace=namespace, func=func.__name__)
+                )
+                statsd_client.timing('{namespace}.{func}'.format(
+                    namespace=namespace, func=func.__name__), elapsed_time
+                )
+                return res
         wrapper.__wrapped__.__name__ = func.__name__
         return wrapper
 

From 26576622b12d42f3d19b23fa13a61dee68d3b9b3 Mon Sep 17 00:00:00 2001
From: Rebecca Law <rebecca.law@digital.cabinet-office.gov.uk>
Date: Fri, 17 Mar 2017 13:33:57 +0000
Subject: [PATCH 2/2] Only record the statsd timing on success.

---
 app/statsd_decorators.py | 12 ++++++------
 1 file changed, 6 insertions(+), 6 deletions(-)

diff --git a/app/statsd_decorators.py b/app/statsd_decorators.py
index 677d7cb79..bb21a0562 100644
--- a/app/statsd_decorators.py
+++ b/app/statsd_decorators.py
@@ -13,6 +13,12 @@ def statsd(namespace):
             try:
                 res = func(*args, **kwargs)
                 elapsed_time = monotonic() - start_time
+                statsd_client.incr('{namespace}.{func}'.format(
+                    namespace=namespace, func=func.__name__)
+                )
+                statsd_client.timing('{namespace}.{func}'.format(
+                    namespace=namespace, func=func.__name__), elapsed_time
+                )
 
             except Exception as e:
                 current_app.logger.error(
@@ -27,12 +33,6 @@ def statsd(namespace):
                         namespace=namespace, func=func.__name__, time="{0:.4f}".format(elapsed_time)
                     )
                 )
-                statsd_client.incr('{namespace}.{func}'.format(
-                    namespace=namespace, func=func.__name__)
-                )
-                statsd_client.timing('{namespace}.{func}'.format(
-                    namespace=namespace, func=func.__name__), elapsed_time
-                )
                 return res
         wrapper.__wrapped__.__name__ = func.__name__
         return wrapper