Merge pull request #22871 from netbox-community/22441-cleanup

#22441: Pre-release QA

netbox/core/forms/filtersets.py

@@ -75,10 +75,10 @@ class JobFilterForm(SavedFiltersMixin, FilterForm):
     model = Job
     fieldsets = (
         FieldSet('q', 'filter_id'),
-        FieldSet('object_type_id', 'status', 'queue_name', name=_('Attributes')),
+        FieldSet('object_type_id', 'status', 'queue_name', 'user', name=_('Attributes')),
         FieldSet(
             'created__before', 'created__after', 'scheduled__before', 'scheduled__after', 'started__before',
-            'started__after', 'completed__before', 'completed__after', 'user', name=_('Creation')
+            'started__after', 'completed__before', 'completed__after', name=_('Scheduling')
         ),
         FieldSet('execution_time__gte', 'execution_time__lte', name=_('Execution')),
     )

netbox/core/migrations/0026_populate_job_execution_time.py

@@ -0,0 +1,46 @@
+from django.db import migrations
+from django.db.models import DurationField, ExpressionWrapper, F
+
+BATCH_SIZE = 5000
+
+
+def populate_execution_time(apps, schema_editor):
+    """
+    Populate execution_time for existing jobs which have both a start and completion time recorded.
+    Updates are performed in batches, as installations which retain job history indefinitely can
+    accumulate a very large number of rows. Rows which already have a value are skipped, so that an
+    interrupted run can simply be resumed.
+    """
+    Job = apps.get_model("core", "Job")
+    queryset = Job.objects.filter(
+        started__isnull=False, completed__isnull=False, execution_time__isnull=True
+    )
+    execution_time = ExpressionWrapper(F("completed") - F("started"), output_field=DurationField())
+
+    last_pk = 0
+    while True:
+        pks = list(
+            queryset.filter(pk__gt=last_pk).order_by("pk").values_list("pk", flat=True)[:BATCH_SIZE]
+        )
+        if not pks:
+            break
+        Job.objects.filter(pk__in=pks).update(execution_time=execution_time)
+        last_pk = pks[-1]
+
+
+class Migration(migrations.Migration):
+    # The backfill is deliberately kept out of the migration which adds the column, so that the
+    # ACCESS EXCLUSIVE lock taken by ALTER TABLE is not held for its duration. Running without a
+    # wrapping transaction is what allows the batching above to bound the work actually held open.
+    atomic = False
+
+    dependencies = [
+        ("core", "0025_add_job_execution_time"),
+    ]
+
+    operations = [
+        migrations.RunPython(
+            code=populate_execution_time,
+            reverse_code=migrations.RunPython.noop,
+        ),
+    ]

netbox/core/tables/jobs.py

@@ -62,10 +62,11 @@ class JobTable(NetBoxTable):
         model = Job
         fields = (
             'pk', 'id', 'object_type', 'object', 'name', 'status', 'created', 'scheduled', 'interval', 'started',
-            'completed', 'user', 'queue_name', 'log_entries', 'error', 'job_id', 'execution_time'
+            'completed', 'execution_time', 'user', 'queue_name', 'log_entries', 'error', 'job_id',
         )
         default_columns = (
-            'pk', 'id', 'object_type', 'object', 'name', 'status', 'created', 'started', 'completed', 'user',
+            'pk', 'id', 'object_type', 'object', 'name', 'status', 'created', 'started', 'completed', 'execution_time',
+            'user',
         )
 
     def render_log_entries(self, value):
@@ -74,6 +75,11 @@ class JobTable(NetBoxTable):
     def render_execution_time(self, value):
         return humanize_duration(value)
 
+    def value_execution_time(self, value):
+        # Export the recorded execution time as a raw number of seconds, rather than the humanized
+        # string, as an export is intended for analysis
+        return round(value.total_seconds(), 3)
+
 
 class JobLogEntryTable(BaseTable):
     timestamp = columns.DateTimeColumn(

netbox/core/tests/test_tables.py

@@ -1,4 +1,11 @@
-from core.models import ObjectChange
+import uuid
+from datetime import timedelta
+
+from django.test import TestCase
+from django.utils import timezone
+
+from core.choices import JobStatusChoices
+from core.models import Job, ObjectChange
 from core.tables import *
 from utilities.testing import TableTestCases
 
@@ -15,6 +22,65 @@ class JobTableTestCase(TableTestCases.StandardTableTestCase):
     table = JobTable
 
 
+class JobExecutionTimeColumnTestCase(TestCase):
+    """
+    Test the rendering and export behavior of JobTable's execution_time column.
+    """
+    @classmethod
+    def setUpTestData(cls):
+        now = timezone.now()
+        Job.objects.bulk_create((
+            Job(
+                name='completed-90s', job_id=uuid.uuid4(), status=JobStatusChoices.STATUS_COMPLETED,
+                started=now - timedelta(seconds=90), completed=now, execution_time=timedelta(seconds=90),
+            ),
+            Job(
+                name='completed-subsecond', job_id=uuid.uuid4(), status=JobStatusChoices.STATUS_COMPLETED,
+                started=now - timedelta(milliseconds=430), completed=now,
+                execution_time=timedelta(milliseconds=430),
+            ),
+            Job(
+                name='completed-long', job_id=uuid.uuid4(), status=JobStatusChoices.STATUS_COMPLETED,
+                started=now - timedelta(days=2, hours=3), completed=now,
+                execution_time=timedelta(days=2, hours=3),
+            ),
+            Job(name='pending', job_id=uuid.uuid4(), status=JobStatusChoices.STATUS_PENDING),
+        ))
+
+    def _table(self, name):
+        table = JobTable(Job.objects.filter(name=name))
+        table.columns.show('execution_time')
+        return table
+
+    def _render(self, name):
+        table = self._table(name)
+        return str(next(iter(table.rows)).get_cell('execution_time'))
+
+    def test_render_completed_job(self):
+        self.assertEqual(self._render('completed-90s'), '1m 30s')
+        self.assertEqual(self._render('completed-long'), '2d 3h')
+
+    def test_render_subsecond_job(self):
+        # Sub-second jobs report millisecond precision rather than reading as zero
+        self.assertEqual(self._render('completed-subsecond'), '0.43s')
+
+    def test_render_job_without_execution_time(self):
+        table = self._table('pending')
+        self.assertEqual(str(next(iter(table.rows)).get_cell('execution_time')), table.default)
+
+    def _export_value(self, name):
+        rows = list(self._table(name).as_values())
+        return rows[1][rows[0].index('Execution Time')]
+
+    def test_export_value_is_raw_seconds(self):
+        # Exports carry the recorded duration in seconds, not the humanized string
+        self.assertEqual(self._export_value('completed-90s'), 90.0)
+        self.assertEqual(self._export_value('completed-subsecond'), 0.43)
+
+    def test_export_value_of_job_without_execution_time(self):
+        self.assertIsNone(self._export_value('pending'))
+
+
 class ObjectChangeTableTestCase(TableTestCases.StandardTableTestCase):
     table = ObjectChangeTable
     queryset_sources = [

netbox/utilities/string.py

@@ -11,15 +11,28 @@ __all__ = (
 
 def humanize_duration(value):
     """
-    Express a timedelta in a human-friendly format. Example: 1h 5m 23s. Returns an empty string
-    for None; zero-duration timedeltas render as "0s".
+    Express a timedelta in a human-friendly format. Example: 1h 5m 23s. Durations of a second or
+    more are rounded to whole seconds; shorter durations are rounded to the millisecond (e.g.
+    0.43s). A negative duration is rendered with a leading minus sign, so that an anomalous value
+    remains recognizable as one. Returns an empty string for None; zero renders as "0s".
     """
     if value is None:
         return ''
 
+    total_seconds = value.total_seconds()
+    magnitude = abs(total_seconds)
+
+    # Render sub-second durations to the millisecond, as rounding them to whole seconds would
+    # report every short-lived duration as zero. Trailing zeros are stripped.
+    if 0 < magnitude < 1:
+        rendered = f'{magnitude:.3f}'.rstrip('0').rstrip('.')
+        # A magnitude below a millisecond has no representation here, so fall through to "0s".
+        # Rounding up to a whole second (e.g. 0.9996) likewise falls through, to "1s".
+        if rendered not in ('0', '1'):
+            return f'-{rendered}s' if total_seconds < 0 else f'{rendered}s'
+
     # Round to whole seconds and decompose
-    total_seconds = int(value.total_seconds())
-    days, remainder = divmod(total_seconds, 86400)
+    days, remainder = divmod(round(magnitude), 86400)
     hours, remainder = divmod(remainder, 3600)
     minutes, seconds = divmod(remainder, 60)
 
@@ -32,7 +45,12 @@ def humanize_duration(value):
         ret += f'{minutes}m '
     if seconds or not ret:
         ret += f'{seconds}s'
-    return ret.strip()
+    ret = ret.strip()
+
+    # Zero carries no sign, however the original value was signed
+    if total_seconds < 0 and ret != '0s':
+        ret = f'-{ret}'
+    return ret
 
 
 def enum_key(value):

netbox/utilities/tests/test_string.py

@@ -28,6 +28,32 @@ class HumanizeDurationTest(TestCase):
     def test_whole_minute_omits_seconds(self):
         self.assertEqual(humanize_duration(timedelta(minutes=2)), '2m')
 
-    def test_sub_second_rounds_down_to_zero(self):
-        # Fractional seconds are truncated; a sub-second duration reads as 0s.
-        self.assertEqual(humanize_duration(timedelta(milliseconds=500)), '0s')
+    def test_sub_second_renders_decimal(self):
+        # Sub-second durations retain millisecond precision, with trailing zeros stripped.
+        self.assertEqual(humanize_duration(timedelta(milliseconds=500)), '0.5s')
+        self.assertEqual(humanize_duration(timedelta(milliseconds=430)), '0.43s')
+        self.assertEqual(humanize_duration(timedelta(milliseconds=4)), '0.004s')
+
+    def test_sub_millisecond_rounds_to_zero(self):
+        # Anything below a millisecond has no decimal representation, so it reads as 0s.
+        self.assertEqual(humanize_duration(timedelta(microseconds=400)), '0s')
+
+    def test_fractional_seconds_rounded_above_one_second(self):
+        self.assertEqual(humanize_duration(timedelta(seconds=1, milliseconds=999)), '2s')
+        self.assertEqual(humanize_duration(timedelta(seconds=1, milliseconds=100)), '1s')
+        self.assertEqual(humanize_duration(timedelta(seconds=59, milliseconds=600)), '1m')
+
+    def test_negative_duration_retains_sign(self):
+        # A negative duration is anomalous (e.g. resulting from clock skew), so it is rendered as
+        # such rather than decomposed into a nonsensical value.
+        self.assertEqual(humanize_duration(timedelta(seconds=-5)), '-5s')
+        self.assertEqual(humanize_duration(timedelta(seconds=-1.5)), '-2s')
+        self.assertEqual(humanize_duration(timedelta(days=-2)), '-2d')
+        self.assertEqual(humanize_duration(timedelta(milliseconds=-430)), '-0.43s')
+
+    def test_negative_duration_rounding_to_zero_carries_no_sign(self):
+        self.assertEqual(humanize_duration(timedelta(microseconds=-400)), '0s')
+
+    def test_sub_second_rounding_up_to_one_second(self):
+        # A magnitude which rounds up to a whole second reads as "1s", not "1.0s"
+        self.assertEqual(humanize_duration(timedelta(seconds=0.9996)), '1s')