Merge a52a94f into 6fac79e

elcid/settings.py

@@ -220,6 +220,8 @@
         'intrahospital_api': 'intrahospital_api.nomigrations'
     }
 
+V_FORMAT = '%(asctime)s %(process)d %(thread)d %(filename)s %(funcName)s \
+%(levelname)s %(message)s'
 
 LOGGING = {
     'version': 1,
@@ -231,7 +233,7 @@
     },
     'formatters': {
         'verbose': {
-            'format': '%(asctime)s %(levelname)s %(message)s'
+            'format': V_FORMAT
         }
     },
     'handlers': {
@@ -269,7 +271,7 @@
             'propagate': True,
         },
         'intrahospital_api': {
-            'handlers': ['console'],
+            'handlers': ['console_detailed'],
             'level': 'INFO',
             'propagate': True,
         },

elcid/test/test_utils.py

@@ -0,0 +1,36 @@
+import datetime
+from mock import patch
+from opal.core.test import OpalTestCase
+from elcid import utils
+
+
+class ModelMethodLoggingTestCase(OpalTestCase):
+
+    def test_logging_method(self):
+        class LoggingTest(object):
+            id = 1
+
+            @utils.model_method_logging
+            def some_method(self):
+                return "some_var"
+        a = LoggingTest()
+        with patch.object(utils.logger, "info") as info:
+            with patch("elcid.utils.timezone.now") as now:
+                first_call = datetime.datetime(2018, 2, 3, 10, 21)
+                second_call = first_call + datetime.timedelta(minutes=1)
+                now.side_effect = [first_call, second_call]
+                result = a.some_method()
+        first_call = info.call_args_list[0][0][0]
+        second_call = info.call_args_list[1][0][0]
+        self.assertEqual(
+            first_call, "2018-02-03 10:21:00 starting LoggingTest.some_method \
+(id 1)"
+        )
+        self.assertEqual(
+            second_call,
+            "2018-02-03 10:22:00 finishing LoggingTest.some_method (id 1) for \
+2018-02-03 10:21:00"
+        )
+        self.assertEqual(
+            result, "some_var"
+        )

elcid/utils.py

@@ -1,3 +1,4 @@
+from django.utils import timezone
 import logging
 from functools import wraps
 from time import time
@@ -16,3 +17,25 @@ def wrap(*args, **kw):
         ))
         return result
     return wrap
+
+
+def model_method_logging(f):
+    @wraps(f)
+    def wrap(self, *args, **kw):
+        start_timestamp = timezone.now()
+        logger.info("{} starting {}.{} (id {})".format(
+            start_timestamp,
+            self.__class__.__name__,
+            f.__name__,
+            self.id
+        ))
+        result = f(self, *args, **kw)
+        logger.info("{} finishing {}.{} (id {}) for {}".format(
+            timezone.now(),
+            self.__class__.__name__,
+            f.__name__,
+            self.id,
+            start_timestamp
+        ))
+        return result
+    return wrap

intrahospital_api/apis/prod_api.py

@@ -1,4 +1,5 @@
 import datetime
+import json
 import logging
 from functools import wraps
 import pytds
@@ -297,8 +298,12 @@ def execute_query(self, query, params=None):
             as_dict=True
         ) as conn:
             with conn.cursor() as cur:
+                logger.info(
+                    "Running upstream query {} {}".format(query, params)
+                )
                 cur.execute(query, params)
                 result = cur.fetchall()
+        logger.info(result)
         return result
 
     @property

intrahospital_api/loader.py

@@ -41,6 +41,7 @@
 import datetime
 import logging
 import traceback
+import json
 from django.db import transaction
 from django.utils import timezone
 from django.db.models import Q
@@ -107,8 +108,9 @@ def any_loads_running():
     batch_loading = models.BatchPatientLoad.objects.filter(
         state=models.BatchPatientLoad.RUNNING
     ).exists()
-
-    return patient_loading or batch_loading
+    result = patient_loading or batch_loading
+    logger.info("Checking loads are running {}".format(result))
+    return result
 
 
 @timing
@@ -138,6 +140,7 @@ def load_patient(patient, async=None):
 
         it will default to settings.ASYNC_API.
     """
+    logger.info("starting to load patient {}".format(patient.id))
     if async is None:
         async = settings.ASYNC_API
 
@@ -146,8 +149,10 @@ def load_patient(patient, async=None):
     )
     patient_load.start()
     if async:
+        logger.info("loading patient {} asynchronously".format(patient.id))
         async_task(patient, patient_load)
     else:
+        logger.info("loading patient {} synchronously".format(patient.id))
         _load_patient(patient, patient_load)
 
 
@@ -226,6 +231,7 @@ def good_to_go():
 
 
 def batch_load(force=False):
+    logger.info("starting batch load")
     all_set = None
 
     # validate that we can run without exception
@@ -238,6 +244,7 @@ def batch_load(force=False):
         if not all_set:
             return
 
+    logger.info("good to go, commencing batch load")
     batch = models.BatchPatientLoad()
     batch.start()
     try:
@@ -293,10 +300,13 @@ def get_batch_start_time():
 def _batch_load():
     started = get_batch_start_time()
 
+    logging.info("start loading batch")
     # update the non reconciled
     update_demographics.reconcile_all_demographics()
+    logging.info("reconciled demographics")
 
     data_deltas = api.data_deltas(started)
+    logging.info("calcualted data deltas")
     update_from_batch(data_deltas)
 
 
@@ -309,16 +319,28 @@ def update_patient_from_batch(demographics_set, data_delta):
     if not patient_demographics_set.exists():
         # this patient is not in our reconcile list,
         # move on, nothing to see here.
+        logging.info("unable to find a patient for {}".format(
+            upstream_demographics["hospital_number"]
+        ))
         return
 
     patient = patient_demographics_set.first().patient
+    logging.info("updating patient demographics for {}".format(
+        patient.id
+    ))
+    logging.info(json.dumps(upstream_demographics, indent=2))
     update_demographics.update_patient_demographics(
         patient, upstream_demographics
     )
+    logging.info("updating patient results for {}".format(
+        patient.id
+    ))
+    logging.info(json.dumps(data_delta["lab_tests"], indent=2))
     update_lab_tests.update_tests(
         patient,
         data_delta["lab_tests"],
     )
+    logging.info("batch patient {} update complete".format(patient.id))
 
 
 @timing
@@ -333,6 +355,7 @@ def update_from_batch(data_deltas):
         patient__initialpatientload__state=models.InitialPatientLoad.SUCCESS
     )
     for data_delta in data_deltas:
+        logging.info("batch updating with {}".format(data_delta))
         update_patient_from_batch(demographics_set, data_delta)
 
 
@@ -348,6 +371,9 @@ def async_load_patient(patient_id, patient_load_id):
 
 @transaction.atomic
 def _load_patient(patient, patient_load):
+    logger.info(
+        "started patient {} ipl {}".format(patient.id, patient_load.id)
+    )
     try:
         hospital_number = patient.demographics_set.first().hospital_number
         patient.labtest_set.filter(
@@ -356,10 +382,27 @@ def _load_patient(patient, patient_load):
                 emodels.UpstreamLabTest.get_display_name()
             ]
         ).delete()
+        logger.info(
+            "deleted patient {} {}".format(patient.id, patient_load.id)
+        )
 
         results = api.results_for_hospital_number(hospital_number)
+        logger.info(
+            "loaded results for patient {} {}".format(
+                patient.id, patient_load.id
+            )
+        )
+        logger.info(json.dumps(results, indent=2))
         update_lab_tests.update_tests(patient, results)
+        logging.info(
+            "tests updated for {} {}".format(patient.id, patient_load.id)
+        )
         update_demographics.update_patient_demographics(patient)
+        logging.info(
+            "demographics updated for {} {}".format(
+                patient.id, patient_load.id
+            )
+        )
     except:
         patient_load.failed()
         raise

intrahospital_api/models.py

@@ -1,6 +1,6 @@
 from django.db import models
 from django.utils import timezone
-from django.conf import settings
+from elcid.utils import model_method_logging
 import opal.models as omodels
 from opal.models import PatientSubrecord
 from opal.core.fields import ForeignKeyOrFreeText
@@ -44,6 +44,7 @@ class PatientLoad(models.Model):
     def verbose_name(self):
         return self.__class__._meta.verbose_name
 
+    @model_method_logging
     def start(self):
         self.started = timezone.now()
         self.state = self.RUNNING
@@ -57,11 +58,13 @@ def duration(self):
             )
         return self.stopped - self.started
 
+    @model_method_logging
     def complete(self):
         self.stopped = timezone.now()
         self.state = self.SUCCESS
         self.save()
 
+    @model_method_logging
     def failed(self):
         self.stopped = timezone.now()
         self.state = self.FAILURE
@@ -76,6 +79,7 @@ class InitialPatientLoad(PatientLoad, PatientSubrecord):
     """ this model is the initial load of a patient
         future loads are done by the cron batch load
     """
+
     def __unicode__(self):
         hospital_number = self.patient.demographics_set.first().hospital_number
         if self.stopped:
@@ -97,6 +101,7 @@ class BatchPatientLoad(PatientLoad):
     """ This is the batch load of all reconciled patients
         every 5 mins
     """
+
     def __unicode__(self):
         if self.stopped:
             return "{} {} {} {}".format(

intrahospital_api/tasks.py

@@ -1,10 +1,16 @@
 from __future__ import absolute_import
+import logging
 
 from celery import shared_task
 
+logger = logging.getLogger('intrahospital_api')
+
 
 @shared_task
 def load(patient_id, patient_load_id):
+    logger.info("starting async load patient for {} {}".format(
+        patient_id, patient_load_id
+    ))
     from intrahospital_api import loader
     fname = loader.async_load_patient(
         patient_id, patient_load_id