Merge pull request #18 from RockefellerArchiveCenter/logging

Implements logging using structlog

bagdiscovery/cron.py

@@ -1,7 +1,12 @@
 from django_cron import CronJobBase, Schedule
+import logging
+from structlog import wrap_logger
+from uuid import uuid4
 from .library import BagDiscovery
 from .models import Bag
 
+logger = wrap_logger(logger=logging.getLogger(__name__))
+
 
 class BagStore(CronJobBase):
     RUN_EVERY_MINS = 0
@@ -10,7 +15,9 @@ class BagStore(CronJobBase):
     code = 'bagdiscovery.bagcron'
 
     def do(self):
-            try:
-                BagDiscovery().run()
-            except Exception as e:
-                print(e)
+        self.log = logger.new(transaction_id=str(uuid4()))
+        try:
+            BagDiscovery().run()
+        except Exception as e:
+            self.log.error(e)
+            print(e)

bagdiscovery/library.py

@@ -1,16 +1,22 @@
 import json
+import logging
 import os
 import shutil
+from structlog import wrap_logger
+from uuid import uuid4
 import tarfile
 from .models import Bag
 from ursa_major import settings
 
+logger = wrap_logger(logger=logging.getLogger(__name__))
+
 
 class BagDiscoveryException(Exception): pass
 
 
 class BagDiscovery:
     def __init__(self, dirs=None):
+        self.log = logger
         if dirs:
             self.landing_dir = dirs['landing']
             self.storage_dir = dirs['storage']
@@ -21,24 +27,33 @@ def __init__(self, dirs=None):
             os.makedirs(os.path.join(settings.BASE_DIR, self.storage_dir))
 
     def run(self):
+        self.log.bind(request_id=str(uuid4()))
+        self.log.debug("Found {} bags to process".format(len(Bag.objects.filter(bag_path__isnull=True))))
         bags = Bag.objects.filter(bag_path__isnull=True)
         for bag in bags:
             self.bag_name = "{}.tar.gz".format(bag.bag_identifier)
+            self.log.bind(object=bag.bag_identifier)
 
             if os.path.exists(os.path.join(self.landing_dir, self.bag_name)):
                 try:
                     self.unpack_bag()
+                    self.log.debug("Bag unpacked")
                 except Exception as e:
+                    self.log.error("Error unpacking bag: {}".format(e))
                     raise BagDiscoveryException("Error unpacking bag: {}".format(e))
 
                 try:
                     self.save_bag_data(bag)
+                    self.log.debug("Bag data saved")
                 except Exception as e:
+                    self.log.error("Error saving bag data: {}".format(e))
                     raise BagDiscoveryException("Error saving bag data: {}".format(e))
 
                 try:
                     self.move_bag(bag)
+                    self.log.debug("Bag moved to storage")
                 except Exception as e:
+                    self.log.error("Error moving bag: {}".format(e))
                     raise BagDiscoveryException("Error moving bag: {}".format(e))
             else:
                 continue
@@ -63,7 +78,6 @@ def move_bag(self, bag):
             os.path.join(settings.BASE_DIR, new_path))
         bag.bag_path = new_path
         bag.save()
-        print("Bag {} has been moved".format(self.bag_name))
 
 
 def isdatavalid(data):

bagdiscovery/tests.py

@@ -26,6 +26,7 @@ def setUp(self):
                 shutil.rmtree(d)
 
     def createobjects(self):
+        print('*** Creating objects ***')
         accession_count = 0
         transfer_count = 0
         for f in listdir(data_fixture_dir):
@@ -34,13 +35,13 @@ def createobjects(self):
                 request = self.factory.post(reverse('accession-list'), accession_data, format='json')
                 response = AccessionViewSet.as_view(actions={"post": "create"})(request)
                 self.assertEqual(response.status_code, 200, "Wrong HTTP code")
-                print('Created accession')
                 accession_count += 1
                 transfer_count += len(accession_data['transfers'])
         self.assertEqual(len(Accession.objects.all()), accession_count, "Wrong number of accessions created")
         self.assertEqual(len(Bag.objects.all()), transfer_count, "Wrong number of transfers created")
 
     def processbags(self):
+        print('*** Test BagDiscovery routine ***')
         shutil.copytree(bag_fixture_dir, settings.TEST_LANDING_DIR)
         processor = BagDiscovery(dirs={"landing": settings.TEST_LANDING_DIR, "storage": settings.TEST_STORAGE_DIR}).run()
         self.assertTrue(processor)

bagdiscovery/views.py

@@ -1,12 +1,17 @@
+import logging
 from django.shortcuts import render
 from rest_framework.views import APIView
 from rest_framework.viewsets import ModelViewSet
 from rest_framework.response import Response
+from structlog import wrap_logger
+from uuid import uuid4
 from .library import BagDiscovery, isdatavalid
 from .models import Accession, Bag
 from .serializers import AccessionSerializer, AccessionListSerializer, BagSerializer, BagListSerializer
 from ursa_major import settings
 
+logger = wrap_logger(logger=logging.getLogger(__name__))
+
 
 class AccessionViewSet(ModelViewSet):
     """
@@ -31,19 +36,23 @@ def get_serializer_class(self):
         return AccessionSerializer
 
     def create(self, request):
+        self.log = logger
+        self.log.bind(transaction_id=str(uuid4()), request_id=str(uuid4()))
         if isdatavalid(request.data):
             accession = Accession.objects.create(
                 data=request.data
             )
-
+            self.log.debug("Accession saved", object=accession)
             for transfer in request.data['transfers']:
                 transfer = Bag.objects.create(
                     bag_identifier=transfer['identifier'],
                     accession=accession,
                 )
+                self.log.debug("Bag saved", object=transfer)
             serialized = AccessionSerializer(accession, context={'request': request})
             return Response(serialized.data)
         else:
+            self.log.error("Invalid accession data")
             return Response({"detail": "Invalid accession data"}, status=500)
 
 

requirements.txt

@@ -31,6 +31,7 @@ ruamel.yaml==0.15.74
 six==1.11.0
 smmap2==2.0.5
 strict-rfc3339==0.7
+structlog==18.2.0
 swagger-spec-validator==2.4.1
 uritemplate==3.0.0
 urllib3==1.23

ursa_major/settings.py

@@ -11,6 +11,7 @@
 """
 
 import os
+import structlog
 from . import config as CF
 
 # Build paths inside the project like this: os.path.join(BASE_DIR, ...)
@@ -136,3 +137,16 @@
 STORAGE_DIR = CF.STORAGE_DIR
 TEST_LANDING_DIR = CF.TEST_LANDING_DIR
 TEST_STORAGE_DIR = CF.TEST_STORAGE_DIR
+
+structlog.configure(
+    processors=[
+        structlog.stdlib.add_logger_name,
+        structlog.stdlib.add_log_level,
+        structlog.stdlib.PositionalArgumentsFormatter(),
+        structlog.processors.StackInfoRenderer(),
+        structlog.processors.format_exc_info,
+        structlog.processors.UnicodeDecoder(),
+        structlog.processors.TimeStamper(fmt='iso', utc=True),
+        structlog.processors.JSONRenderer()
+    ],
+)