cdh.files: various improvements

dev/dev_project/settings.py

@@ -7,7 +7,7 @@
 For the full list of settings and their values, see
 https://docs.djangoproject.com/en/3.2/ref/settings/
 """
-
+import os
 from pathlib import Path
 
 # Build paths inside the project like this: BASE_DIR / 'subdir'.
@@ -177,6 +177,32 @@
     'django.contrib.auth.hashers.PBKDF2PasswordHasher',
 ]
 
+# Logging
+#
+
+DJANGO_LOG_LEVEL = os.getenv('DJANGO_LOG_LEVEL', 'INFO')
+
+LOGGING = {
+    'version': 1,
+    'disable_existing_loggers': False,
+    'handlers': {
+        'console': {
+            'class': 'logging.StreamHandler',
+            'formatter': 'default',
+        },
+    },
+    'formatters': {
+        'default': {
+            'format': '{levelname} {name} {message}',
+            'style': '{',
+        }
+    },
+    'root': {
+        'handlers': ['console'],
+        'level': DJANGO_LOG_LEVEL,
+    },
+}
+
 
 # Internationalization
 # https://docs.djangoproject.com/en/3.2/topics/i18n/

src/cdh/files/db/descriptors.py

@@ -9,6 +9,9 @@
 from cdh.files.db.manager import create_tracked_file_manager
 from cdh.files.db.wrappers import FileWrapper, TrackedFileWrapper
 
+import logging
+logger = logging.getLogger(__name__)
+
 
 class FileDescriptor(ForeignKeyDeferredAttribute):
     """FileDescriptor handles the {field_name}_id field of a FileField"""
@@ -53,6 +56,8 @@ def __get__(self, instance, cls=None):
         if instance is None:
             return self
 
+        logger.debug(f"Getting {self.field.name} for {instance}")
+
         try:
             # See if we have it in cache, raises KeyError if not
             file_wrapper = self.field.get_cached_value(instance)
@@ -66,8 +71,11 @@ def __get__(self, instance, cls=None):
             if file_wrapper is None or file_wrapper._removed:
                 return None
 
+            logger.debug(f"Found {self.field.name} in cache; returning it")
+
             return file_wrapper
         except KeyError:
+            logger.debug(f"No cached value for {self.field.name}; fetching from DB")
             # Try to fetch it from the DB instead
             file_obj = self.get_object(instance)
 
@@ -103,20 +111,27 @@ def __set__(self, instance, value):
 
         Please see the helper methods for detailed info on how they are handled
         """
+        logger.debug(f"Setting {self.field.name} for {instance}")
         if isinstance(value, tuple):
+            logger.debug(f"Got tuple (from widget); processing")
             return_value = self._set_from_tuple(instance, value)
         elif isinstance(
                value,
                self.field.remote_field.model._meta.concrete_model  # NoQA
            ):
+            logger.debug(f"Got File instance; processing")
             return_value = self._set_from_db_instance(instance, value)
         elif isinstance(value, self.field.attr_class):
+            logger.debug(f"Got FileWrapper; processing")
             return_value = self._set_from_file_wrapper(instance, value)
         elif isinstance(value, File):
+            logger.debug(f"Got Django/Python-native File; processing")
             return_value = self._set_from_file_like_object(instance, value)
         elif value is None:
+            logger.debug(f"Got None; processing")
             return_value = self._set_from_none(instance)
         else:
+            logger.error(f"Got unknown type {type(value)}; aborting")
             # We can't be completely inclusive :o
             raise ValueError(
                 'Cannot assign "%r": "%s.%s" must be either a "%s" instance, '
@@ -129,9 +144,11 @@ def __set__(self, instance, value):
                 )
             )
 
+        logger.debug(f"Setting {self.field.name} for {instance} to {return_value}")
         self.field.set_cached_value(instance, return_value)
 
         if return_value is None or return_value._removed:
+            logger.debug(f"After processing, file is to be deleted. Removing ORM links")
             # If we got returned None, or a FileWrapper marked for deletion, we
             # need to clear the fields that the ORM uses to link objects.
             # (In other words, the {field_name}_id field)
@@ -205,6 +222,7 @@ def _set_from_tuple(self, instance, value):
         # say in whether it's actually deleted. (It might be referenced by a
         # different FileField).
         if uuid:
+            logger.debug(f"Marking existing FileWrapper for potential deletion: {uuid}")
             old_obj = self.field.remote_field.model.objects.get(uuid=uuid)
             old_file_wrapper = old_obj.get_file_wrapper(self.field)
             old_file_wrapper._removed = True
@@ -247,6 +265,7 @@ def _set_from_file_wrapper(self, instance, value):
             # removed. (It's going to be overriden by an older version
             # apparently)
             if current_fw != value:
+                logger.debug(f"Marking existing FileWrapper for potential deletion: {current_fw.uuid}")
                 current_fw._removed = True
             # Make sure we won't remove it
             value._removed = False
@@ -258,12 +277,15 @@ def _set_from_file_wrapper(self, instance, value):
         # we are replacing it. We don't need to cache it, as __get__ would
         # have done that for us
         if current_fw and current_fw != value:
+            logger.debug(f"Marking existing FileWrapper for potential deletion: {current_fw.uuid}")
             current_fw._removed = True
         elif current_fw == value:
+            logger.debug(f"We were given the same FileWrapper as before, removing any potential deletion marker")
             value._removed = False
 
         # Create a file instance if one isn't present
         if not value.file_instance:
+            logger.debug(f"Creating new file instance for FileWrapper {value.uuid}")
             value.file_instance = self._create_file_instance()
             # Make sure our new file_instance knows of this wrapper :)
             value.file_instance.set_file_wrapper(value, self.field)
@@ -279,6 +301,7 @@ def _set_from_file_wrapper(self, instance, value):
         # the only reason you don't receive a FW with a file_instance is if a
         # programmer created an empty (non field-attached) FileWrapper)
         elif value.field != self.field:
+            logger.warning(f"We were given a FileWrapper for a different field ({value.field.name}); this is programmer error. Fixing by creating a new FileWrapper for this field.")
             file = value.file
             value = value.file_instance.get_file_wrapper(self.field, False)
             value.file = file
@@ -297,6 +320,7 @@ def _set_from_file_like_object(self, instance, value):
             try:
                 current_fw = self.__get__(instance)
                 if current_fw is not None:
+                    logger.debug(f"Marking existing FileWrapper for potential deletion: {current_fw.uuid}")
                     current_fw._removed = True
             except self.RelatedObjectDoesNotExist:
                 pass
@@ -316,9 +340,6 @@ def _set_from_none(self, instance):
         # First, see if we have a value
         try:
             obj = self.__get__(instance)
-            # If we got a result, mark it as to be removed
-            if obj:
-                obj._removed = True
         except self.RelatedObjectDoesNotExist:
             # If we get this exception, we are not allowed to set None because
             # the field does not allow it
@@ -338,6 +359,7 @@ def _set_from_none(self, instance):
         # 2) It's against normal Django behaviour to alter ANY data before
         #    calling .save() (or .remove() for that matter). Thus, we need to
         #    wait till the programmer expects things to change.
+        logger.debug(f"Marking existing FileWrapper for potential deletion: {obj.uuid}")
         obj._removed = True
         return obj
 

src/cdh/files/db/fields.py

@@ -21,6 +21,9 @@
 from .models import BaseFile, File
 from .wrappers import FileWrapper, TrackedFileWrapper
 
+import logging
+logger = logging.getLogger(__name__)
+
 NOT_PROVIDED = object()
 
 
@@ -197,6 +200,10 @@ def __init__(self, to=None, on_delete=None, to_field=None, db_constraint=True,
         self.db_constraint = db_constraint
         self.url_pattern = url_pattern
 
+    @property
+    def full_name(self):
+        return f"{self.model._meta.app_label}.{self.model._meta.model_name}.{self.name}"
+
     def check(self, **kwargs):
         return [
             *super().check(**kwargs),
@@ -417,10 +424,12 @@ def pre_save(self, model_instance, add):
         """Make sure we save our file when saving the model this field is
         attached to"""
         ret = super().pre_save(model_instance, add)
+        logger.debug(f"pre_save called for FileField {self.full_name}")
 
         file = getattr(model_instance, self.name, None)
         # If we have a file and it's marked as not-saved (committed)
         if file is not None and not file._committed:
+            logger.debug(f"File not saved yet, committing it now: {file}")
             # Commit the file to storage prior to saving the model
             # This will also save the File instance
             file.save()
@@ -429,8 +438,10 @@ def pre_save(self, model_instance, add):
 
     def post_save(self, sender, instance, created, **kwargs):
         """Handle deletion of a file"""
+        logger.debug(f"post_save called for FileField {self.full_name}")
         # If we have something in cache
         if self.is_cached(instance):
+            logger.debug(f"FileField {self.full_name} is cached, checking for any to-delete files")
             # Get all values
             # The cache can contain multiple values, in which case all but
             # the last of them should be marked for deletion
@@ -441,6 +452,7 @@ def post_save(self, sender, instance, created, **kwargs):
                 # referenced by a different FileField, in which case
                 # value.delete() will simple stop execution
                 if value is not None and value._removed:
+                    logger.info(f"File marked for deletion, starting delete for {value}")
                     # Terminate this file
                     value.delete()
             # And clear our cached value
@@ -455,22 +467,27 @@ def pre_delete(self, sender, instance, **kwargs):
         # we simply force our file into the cache if it exists so we can delete
         # it after the instance is deleted.
         getattr(instance, self.name, None)
+        logger.debug(f"pre_delete called for FileField {self.full_name}; prepopulating cache")
 
     def post_delete(self, sender, instance, **kwargs):
         # When our model was deleted, we should see if our cache contains files
         # that need to be deleted
+        logger.debug(f"post_delete called for FileField {self.full_name}; checking for any to-delete files")
         if self.is_cached(instance):
+            logger.debug(f"FileField {self.name} is cached, continue checking for any to-delete files")
             value = self.get_cached_value(instance, None)
             num_references = value.file_instance._num_child_instances
             # Delete the File if no other object is referencing it
             if value is not None and num_references == 0:
+                logger.info(f"FileField {self.full_name} has no more references, starting delete for {value}")
                 value.delete()
 
     def contribute_to_class(self, *args, **kwargs):
         super().contribute_to_class(*args, **kwargs)
         # Connect ourselves to some signals;
         # Fields really ought to have these methods themselves Django,
         # you already provide the pre_save method!
+        logger.debug(f"Connecting signals for FileField {self.full_name}")
         post_save.connect(self.post_save, sender=self.model)
         pre_delete.connect(self.pre_delete, sender=self.model)
         post_delete.connect(self.post_delete, sender=self.model)
@@ -668,6 +685,8 @@ def __init__(self, to=None, related_name=None, related_query_name=None,
         if file_kwargs is None:
             file_kwargs = {}
 
+        logger.warning("TrackedFileField is semi-deprecated; behavior is no longer tested")
+
         self.url_pattern = url_pattern
         file_kwargs['url_pattern'] = url_pattern