Add a debug logger around rendition generation (#7391)

This allows insight into which images are taking the longest to generate, which fail to render at all, and potentially which images are causing crashes (as in they start, but never stop).

The logging is intentionally only on DEBUG level, so it's opt-in, and is also reasonably quiet so it doesn't bloat logs.

CHANGELOG.txt

@@ -9,6 +9,7 @@ Changelog
  * Support `min_num` / `max_num` options on ListBlock (Matt Westcott)
  * Added a `background_position_style` property to renditions (Karl Hobley)
  * Added a distinct `wagtail.copy_for_translation` log action type (Karl Hobley)
+ * Add a debug logger around image rendition generation (Jake Howard)
  * Fix: Delete button is now correct colour on snippets and modeladmin listings (Brandon Murch)
  * Fix: Ensure that StreamBlock / ListBlock-level validation errors are counted towards error counts (Matt Westcott)
  * Fix: InlinePanel add button is now keyboard navigatable (Jesse Menn)

docs/releases/2.15.rst

@@ -21,6 +21,7 @@ Other features
  * Support ``min_num`` / ``max_num`` options on ListBlock (Matt Westcott)
  * Added a `background_position_style` property to renditions. This can be used to crop images using its focal point in the browser. See :ref:`rendition_background_position_style` (Karl Hobley)
  * Added a distinct ``wagtail.copy_for_translation`` log action type (Karl Hobley)
+ * Add a debug logger around image rendition generation (Jake Howard)
 
 Bug fixes
 ~~~~~~~~~

wagtail/images/models.py

@@ -1,5 +1,7 @@
 import hashlib
+import logging
 import os.path
+import time
 
 from collections import OrderedDict
 from contextlib import contextmanager
@@ -29,6 +31,9 @@ from wagtail.search import index
 from wagtail.search.queryset import SearchableQuerySetMixin
 
 
+logger = logging.getLogger("wagtail.images")
+
+
 class SourceImageIOError(IOError):
     """
     Custom exception to distinguish IOErrors that were thrown while opening the source image
@@ -303,7 +308,23 @@ class AbstractImage(CollectionMember, index.Indexed, models.Model):
             )
         except Rendition.DoesNotExist:
             # Generate the rendition image
-            generated_image = filter.run(self, BytesIO())
+            try:
+                logger.debug("Generating '%s' rendition for image %d", (
+                    filter.spec,
+                    self.pk,
+                ))
+
+                start_time = time.time()
+                generated_image = filter.run(self, BytesIO())
+
+                logger.debug("Generated '%s' rendition for image %d in %.1fms", (
+                    filter.spec,
+                    self.pk,
+                    (time.time() - start_time) * 1000
+                ))
+            except:  # noqa:B901,E722
+                logger.debug("Failed to generate '%s' rendition for image %d: %s", filter.spec, self.pk)
+                raise
 
             # Generate filename
             input_filename = os.path.basename(self.file.name)