Revert implementation of elapsed_time for running jobs

This commit is contained in:
Jeremy Stretch 2026-08-06 13:16:16 -04:00
parent feaa8698a0
commit aed86db7e9
14 changed files with 44 additions and 404 deletions

View File

@ -30,13 +30,7 @@ The date and time at which the job completed (if complete).
### Execution Time
The amount of time the job spent executing, calculated as the difference between its start and completion times. This is populated only once a started job has completed; while a job is still running, NetBox displays the time elapsed since it started instead.
!!! warning "The duration property is deprecated"
The job model's `duration` property, which returned a preformatted string such as `5 minutes, 3.00 seconds`, has been **deprecated** and is planned for removal in NetBox v5.0. Export templates and plugins should reference `elapsed_time` instead, which returns a duration rather than a string and which also reports progress for a job that is still running.
!!! note "Filtering and sorting behave differently"
Filtering on execution time matches only the recorded value, so a job which is still running is never returned: it has no execution time yet. Sorting the jobs list by the **Execution Time** column instead orders by the value displayed, which for a running job is the time elapsed so far. A long-running job therefore appears near the top when sorting in descending order, but is excluded by a filter on the same attribute. Exports likewise carry only the recorded value, in seconds.
The amount of time the job spent executing, calculated as the difference between its start and completion times. This is populated only once a started job has completed.
### User

View File

@ -1,8 +1,6 @@
import logging
import uuid
import warnings
from dataclasses import asdict
from datetime import timedelta
from functools import partial
import django_rq
@ -13,8 +11,6 @@ from django.core.exceptions import ValidationError
from django.core.serializers.json import DjangoJSONEncoder
from django.core.validators import MinValueValidator
from django.db import models, transaction
from django.db.models import Case, ExpressionWrapper, F, When
from django.db.models.functions import Coalesce, Now
from django.urls import reverse
from django.utils import timezone
from django.utils.translation import gettext as _
@ -188,17 +184,6 @@ class Job(models.Model):
@property
def duration(self):
"""
Deprecated: use `elapsed_time` instead, which reports a timedelta and also covers jobs which
are still running. Retained for the benefit of existing export templates and plugins.
"""
warnings.warn(
"Job.duration is deprecated and will be removed in NetBox v5.0; use Job.elapsed_time "
"instead.",
DeprecationWarning,
stacklevel=2,
)
if not self.completed:
return None
@ -210,43 +195,7 @@ class Job(models.Model):
duration = self.completed - start_time
minutes, seconds = divmod(duration.total_seconds(), 60)
return f'{int(minutes)} minutes, {seconds:.2f} seconds'
@property
def elapsed_time(self):
"""
The job's recorded execution time, or the time elapsed so far if it is still running.
Returns None for a job which has not yet started. As this is the value NetBox displays, an
anomalous negative duration (which can result from clock skew) is clamped to zero; the
stored `execution_time` is left as recorded.
"""
if self.execution_time is not None:
elapsed = self.execution_time
elif self.started and not self.completed:
elapsed = timezone.now() - self.started
else:
return None
return max(elapsed, timedelta())
@staticmethod
def elapsed_time_expression():
"""
A queryset expression mirroring the `elapsed_time` property, for use in ordering and
filtering. Resolves to null for jobs which have not yet started, and for jobs which have
completed without recording an execution time.
"""
return Coalesce(
'execution_time',
# Only a job which has yet to complete accrues elapsed time
Case(
When(
completed__isnull=True,
then=ExpressionWrapper(Now() - F('started'), output_field=models.DurationField()),
),
output_field=models.DurationField(),
),
)
return f"{int(minutes)} minutes, {seconds:.2f} seconds"
def delete(self, *args, **kwargs):
# Use the stored queue name, or fall back to get_queue_for_model for legacy jobs

View File

@ -1,5 +1,5 @@
import django_tables2 as tables
from django.utils.html import conditional_escape, format_html
from django.utils.html import conditional_escape
from django.utils.safestring import mark_safe
from django.utils.translation import gettext_lazy as _
@ -47,8 +47,6 @@ class JobTable(NetBoxTable):
)
execution_time = tables.Column(
verbose_name=_('Execution Time'),
# Render running jobs (which have no recorded execution time yet) rather than the placeholder
empty_values=(),
)
queue_name = tables.Column(
verbose_name=_('Queue'),
@ -73,34 +71,13 @@ class JobTable(NetBoxTable):
def render_log_entries(self, value):
return len(value)
def render_execution_time(self, record):
if (duration := record.elapsed_time) is None:
return self.default
def render_execution_time(self, value):
return humanize_duration(value)
value = humanize_duration(duration)
if not record.completed:
# The job is still running, so distinguish its (provisional) elapsed time from a final one
return format_html(
'<span class="text-primary" title="{}">{}</span>', _('Still running'), value
)
return value
def value_execution_time(self, record):
# Export the recorded execution time verbatim, as a raw number of seconds. A running job's
# provisional elapsed time is deliberately omitted, as is the clamping of anomalous negative
# values applied when rendering: an export is intended for analysis.
if record.execution_time is None:
return None
return round(record.execution_time.total_seconds(), 3)
def order_execution_time(self, queryset, is_descending):
# Order by the value the column actually displays, so that a long-running job is not sorted
# as though it had no execution time. Jobs which never started sort last in either
# direction, and pk breaks ties to keep pagination stable.
elapsed_time = Job.elapsed_time_expression()
ordering = elapsed_time.desc(nulls_last=True) if is_descending else elapsed_time.asc(nulls_last=True)
return queryset.order_by(ordering, 'pk'), True
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):

View File

@ -381,145 +381,3 @@ class JobTestCase(TestCase):
job.terminate(status=JobStatusChoices.STATUS_COMPLETED)
self.assertIsNone(job.execution_time)
@patch('core.models.jobs.job_end')
def test_elapsed_time_returns_execution_time_once_completed(self, mock_job_end):
"""
For a completed job, elapsed_time should return the recorded execution_time.
"""
job = self._make_job(None, JobNotificationChoices.NOTIFICATION_NEVER)
job.started = timezone.now() - timedelta(seconds=90)
job.save()
job.terminate(status=JobStatusChoices.STATUS_COMPLETED)
self.assertEqual(job.elapsed_time, job.execution_time)
def test_elapsed_time_of_running_job(self):
"""
A running job has no execution_time yet, so elapsed_time should report the time elapsed
since it started.
"""
job = self._make_job(None, JobNotificationChoices.NOTIFICATION_NEVER)
job.started = timezone.now() - timedelta(seconds=90)
job.save()
self.assertEqual(job.status, JobStatusChoices.STATUS_RUNNING)
self.assertIsNone(job.execution_time)
self.assertGreaterEqual(job.elapsed_time, timedelta(seconds=90))
self.assertLess(job.elapsed_time, timedelta(seconds=120))
def test_elapsed_time_none_when_never_started(self):
"""
A job which has not started has no elapsed time to report.
"""
job = self._make_job(None, JobNotificationChoices.NOTIFICATION_NEVER)
self.assertIsNone(job.started)
self.assertIsNone(job.elapsed_time)
def test_elapsed_time_clamps_negative_execution_time(self):
"""
elapsed_time is the value NetBox displays, so an anomalous negative duration (e.g. resulting
from clock skew) is floored at zero. The stored execution_time is left as recorded, so that
the anomaly remains visible to the API and to exports.
"""
job = self._make_job(None, JobNotificationChoices.NOTIFICATION_NEVER)
job.started = timezone.now()
job.completed = timezone.now()
job.execution_time = timedelta(seconds=-5)
job.status = JobStatusChoices.STATUS_COMPLETED
job.save()
self.assertEqual(job.elapsed_time, timedelta())
self.assertEqual(job.execution_time, timedelta(seconds=-5))
def test_duration_is_deprecated(self):
"""
Job.duration is retained for existing export templates and plugins, but must warn.
"""
job = self._make_job(None, JobNotificationChoices.NOTIFICATION_NEVER)
job.started = timezone.now() - timedelta(seconds=90)
job.completed = job.started + timedelta(seconds=90)
job.status = JobStatusChoices.STATUS_COMPLETED
job.save()
with self.assertWarns(DeprecationWarning):
self.assertEqual(job.duration, '1 minutes, 30.00 seconds')
def test_duration_falls_back_to_created(self):
"""
The deprecated property's original behavior must be preserved: a job which completed without
ever starting reports its duration relative to creation.
"""
job = self._make_job(None, JobNotificationChoices.NOTIFICATION_NEVER)
job.started = None
job.completed = job.created + timedelta(seconds=30)
job.status = JobStatusChoices.STATUS_ERRORED
job.save()
with self.assertWarns(DeprecationWarning):
self.assertEqual(job.duration, '0 minutes, 30.00 seconds')
def test_duration_none_when_not_completed(self):
job = self._make_job(None, JobNotificationChoices.NOTIFICATION_NEVER)
with self.assertWarns(DeprecationWarning):
self.assertIsNone(job.duration)
def test_elapsed_time_none_when_completed_without_execution_time(self):
"""
A job which completed without recording an execution time (e.g. one predating the field)
has no elapsed time to report; it must not accrue time indefinitely.
"""
job = self._make_job(None, JobNotificationChoices.NOTIFICATION_NEVER)
job.started = timezone.now() - timedelta(seconds=90)
job.completed = timezone.now()
job.status = JobStatusChoices.STATUS_COMPLETED
job.save()
self.assertIsNone(job.execution_time)
self.assertIsNone(job.elapsed_time)
def test_elapsed_time_expression_matches_property(self):
"""
The elapsed_time_expression() queryset expression should agree with the elapsed_time
property for completed, running, and never-started jobs.
"""
completed = self._make_job(None, JobNotificationChoices.NOTIFICATION_NEVER)
completed.started = timezone.now() - timedelta(seconds=90)
completed.completed = timezone.now()
completed.execution_time = timedelta(seconds=90)
completed.status = JobStatusChoices.STATUS_COMPLETED
completed.save()
# A job which completed without recording an execution time must resolve to null, rather
# than to an ever-growing interval since it started
unrecorded = self._make_job(None, JobNotificationChoices.NOTIFICATION_NEVER)
unrecorded.started = timezone.now() - timedelta(seconds=90)
unrecorded.completed = timezone.now()
unrecorded.status = JobStatusChoices.STATUS_COMPLETED
unrecorded.save()
running = self._make_job(None, JobNotificationChoices.NOTIFICATION_NEVER)
running.started = timezone.now() - timedelta(minutes=5)
running.save()
pending = self._make_job(None, JobNotificationChoices.NOTIFICATION_NEVER)
pending.status = JobStatusChoices.STATUS_PENDING
pending.save()
annotated = {
job.pk: job
for job in Job.objects.annotate(elapsed=Job.elapsed_time_expression())
}
self.assertEqual(annotated[completed.pk].elapsed, timedelta(seconds=90))
self.assertIsNone(annotated[unrecorded.pk].elapsed)
self.assertIsNone(annotated[pending.pk].elapsed)
# The running job's elapsed time is computed at query time, so compare approximately
self.assertAlmostEqual(
annotated[running.pk].elapsed.total_seconds(),
running.elapsed_time.total_seconds(),
delta=5,
)

View File

@ -24,7 +24,7 @@ class JobTableTestCase(TableTestCases.StandardTableTestCase):
class JobExecutionTimeColumnTestCase(TestCase):
"""
Test the rendering, export, and ordering behavior of JobTable's execution_time column.
Test the rendering and export behavior of JobTable's execution_time column.
"""
@classmethod
def setUpTestData(cls):
@ -44,24 +44,16 @@ class JobExecutionTimeColumnTestCase(TestCase):
started=now - timedelta(days=2, hours=3), completed=now,
execution_time=timedelta(days=2, hours=3),
),
Job(
name='negative', job_id=uuid.uuid4(), status=JobStatusChoices.STATUS_COMPLETED,
started=now, completed=now, execution_time=timedelta(seconds=-5),
),
Job(
name='unrecorded', job_id=uuid.uuid4(), status=JobStatusChoices.STATUS_COMPLETED,
started=now - timedelta(seconds=90), completed=now,
),
Job(
name='running', job_id=uuid.uuid4(), status=JobStatusChoices.STATUS_RUNNING,
started=now - timedelta(minutes=5),
),
Job(name='pending', job_id=uuid.uuid4(), status=JobStatusChoices.STATUS_PENDING),
))
def _render(self, name):
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):
@ -72,92 +64,22 @@ class JobExecutionTimeColumnTestCase(TestCase):
# Sub-second jobs report millisecond precision rather than reading as zero
self.assertEqual(self._render('completed-subsecond'), '0.43s')
def test_render_negative_execution_time(self):
# A negative stored value (e.g. from clock skew) never renders as negative
self.assertEqual(self._render('negative'), '0s')
def test_render_running_job(self):
"""
A running job has no recorded execution time, so the column shows the time elapsed so far,
visually distinguished from a completed job's final value.
"""
rendered = self._render('running')
self.assertIn('5m', rendered)
self.assertIn('text-primary', rendered)
def test_render_job_never_started(self):
table = JobTable(Job.objects.filter(name='pending'))
table.columns.show('execution_time')
row = next(iter(table.rows))
self.assertEqual(str(row.get_cell('execution_time')), table.default)
def test_render_job_completed_without_execution_time(self):
# A completed job with no recorded execution time shows the placeholder, rather than
# accruing time since it started
table = JobTable(Job.objects.filter(name='unrecorded'))
table.columns.show('execution_time')
row = next(iter(table.rows))
self.assertEqual(str(row.get_cell('execution_time')), table.default)
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):
table = JobTable(Job.objects.filter(name=name))
table.columns.show('execution_time')
rows = list(table.as_values())
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_never_started(self):
def test_export_value_of_job_without_execution_time(self):
self.assertIsNone(self._export_value('pending'))
def test_export_value_of_running_job(self):
# Only the recorded execution time is exported; a running job has none yet
self.assertIsNone(self._export_value('running'))
def test_export_value_is_not_clamped(self):
# An anomalous negative value is clamped when rendered, but exported verbatim so that it
# remains visible to analysis
self.assertEqual(self._export_value('negative'), -5.0)
def test_ordering_matches_displayed_values(self):
"""
Sorting must order by the value the column displays which for a running job is its elapsed
time, not a null so that a long-running job is not buried. Jobs with no elapsed time to
display sort last in both directions, in pk order.
"""
# 'running' has been going 5 minutes, so it sorts between the 90s and 2d3h jobs
ascending = ['negative', 'completed-subsecond', 'completed-90s', 'running', 'completed-long']
# Neither a job which never started nor one which completed without recording an execution
# time has a value to sort by
no_value = ['unrecorded', 'pending']
for descending, expected in (
(False, ascending),
(True, list(reversed(ascending))),
):
with self.subTest(descending=descending):
table = JobTable(Job.objects.all())
queryset, modified = table.columns['execution_time'].order(Job.objects.all(), descending)
self.assertTrue(modified)
names = list(queryset.values_list('name', flat=True))
self.assertEqual(names, expected + no_value)
def test_ordering_breaks_ties_on_pk(self):
"""
Tied rows need a stable secondary sort, or paginating through them can skip or repeat rows.
"""
Job.objects.bulk_create(
Job(name=f'tied-{i}', job_id=uuid.uuid4(), status=JobStatusChoices.STATUS_PENDING)
for i in range(4)
)
table = JobTable(Job.objects.all())
queryset, _modified = table.columns['execution_time'].order(Job.objects.filter(
name__startswith='tied-'
), True)
pks = list(queryset.values_list('pk', flat=True))
self.assertEqual(pks, sorted(pks))
class ObjectChangeTableTestCase(TableTestCases.StandardTableTestCase):
table = ObjectChangeTable

View File

@ -1,7 +1,7 @@
import json
import urllib.parse
import uuid
from datetime import UTC, datetime, timedelta
from datetime import UTC, datetime
from django.contrib.contenttypes.models import ContentType
from django.urls import reverse
@ -151,40 +151,6 @@ class JobTestCase(
]
)
def test_execution_time_on_detail_view(self):
"""
The job detail view must present execution time consistently with the jobs list: the recorded
value for a completed job, the elapsed time (visually distinguished) for a running one, and a
placeholder for a job which never started.
"""
self.add_permissions('core.view_job')
now = timezone.now()
completed = Job.objects.get(name='Job 3')
completed.started = now - timedelta(seconds=90)
completed.completed = now
completed.execution_time = timedelta(seconds=90)
completed.save()
response = self.client.get(completed.get_absolute_url())
self.assertHttpStatus(response, 200)
content = str(response.content)
self.assertIn('1m 30s', content)
# The panel must use the same label as the list column, filter form, and API field
self.assertIn('Execution Time', content)
running = Job.objects.get(name='Job 2')
running.started = now - timedelta(hours=2)
running.save()
response = self.client.get(running.get_absolute_url())
self.assertHttpStatus(response, 200)
content = str(response.content)
self.assertIn('2h', content)
self.assertIn('Still running', content)
pending = Job.objects.get(name='Job 1')
response = self.client.get(pending.get_absolute_url())
self.assertHttpStatus(response, 200)
class JobLogViewTestCase(TestCase):
user_permissions = (

View File

@ -62,11 +62,7 @@ class JobSchedulingPanel(panels.ObjectAttributesPanel):
scheduled = attrs.TemplatedAttr('scheduled', template_name='core/job/attrs/scheduled.html')
started = attrs.DateTimeAttr('started')
completed = attrs.DateTimeAttr('completed')
elapsed_time = attrs.TemplatedAttr(
'elapsed_time',
label=_('Execution Time'),
template_name='core/job/attrs/elapsed_time.html',
)
execution_time = attrs.DurationAttr('execution_time')
queue = attrs.TextAttr('queue_name', label=_('Queue'))

View File

@ -9,7 +9,6 @@ from extras.jobs import ScriptJob
from extras.scripts import get_module_and_script
from users.models import User
from utilities.request import NetBoxFakeRequest
from utilities.string import humanize_duration
class Command(BaseCommand):
@ -107,4 +106,4 @@ class Command(BaseCommand):
commit=commit,
)
logger.info(f"Script completed in {humanize_duration(job.elapsed_time)}")
logger.info(f"Script completed in {job.duration}")

View File

@ -1,4 +1,3 @@
from datetime import timedelta
from io import BytesIO, StringIO
from types import SimpleNamespace
from unittest.mock import MagicMock, patch
@ -274,7 +273,7 @@ class RunScriptTestCase(TestCase):
return form
script_obj = SimpleNamespace(python_class=TestScript)
job = SimpleNamespace(elapsed_time=timedelta(0))
job = SimpleNamespace(duration='0 seconds')
with (
patch(
@ -359,7 +358,7 @@ class RunScriptTestCase(TestCase):
return form
script_obj = SimpleNamespace(python_class=TestScript)
job = SimpleNamespace(elapsed_time=timedelta(0))
job = SimpleNamespace(duration='0 seconds')
with (
patch(
@ -399,7 +398,7 @@ class RunScriptTestCase(TestCase):
return form
script_obj = SimpleNamespace(python_class=TestScript)
job = SimpleNamespace(elapsed_time=timedelta(0))
job = SimpleNamespace(duration='0 seconds')
with (
patch(

View File

@ -5,6 +5,7 @@ from django.utils.translation import gettext_lazy as _
from netbox.config import get_config
from netbox.ui.utils import build_coords_url, is_coordinate_map_url
from utilities.data import resolve_attr_path
from utilities.string import humanize_duration
__all__ = (
'AddressAttr',
@ -15,6 +16,7 @@ __all__ = (
'DateTimeAttr',
'DiameterAttr',
'DistanceAttr',
'DurationAttr',
'FlowRateAttr',
'GPSCoordinatesAttr',
'GenericForeignKeyAttr',
@ -564,6 +566,15 @@ class TimezoneAttr(ObjectAttribute):
template_name = 'ui/attrs/timezone.html'
class DurationAttr(TextAttr):
"""
A duration (timedelta) value, rendered in a human-friendly format (e.g. 1h 5m 23s).
"""
def get_value(self, obj):
value = resolve_attr_path(obj, self.accessor)
return humanize_duration(value) or None
class TemplatedAttr(ObjectAttribute):
"""
Renders an attribute using a custom template.

View File

@ -1,8 +0,0 @@
{% load helpers %}
{% load i18n %}
{% if object.completed %}
{{ value|humanize_duration }}
{% else %}
{# The job is still running, so its elapsed time is provisional #}
<span class="text-primary" title="{% trans "Still running" %}">{{ value|humanize_duration }}</span>
{% endif %}

View File

@ -11,13 +11,9 @@
{% else %}
{% trans "Created" %}: <strong>{{ job.created|isodatetime }}</strong>
{% endif %}
{# For a running job this reflects the time elapsed so far; the container refreshes every 5s #}
{% with execution_time=job.elapsed_time|humanize_duration %}
{% if execution_time %}
{% trans "Execution time" %}:
<strong{% if not job.completed %} class="text-primary" title="{% trans "Still running" %}"{% endif %}>{{ execution_time }}</strong>
{% endif %}
{% endwith %}
{% if job.completed %}
{% trans "Duration" %}: <strong>{{ job.duration }}</strong>
{% endif %}
<span id="pending-result-label">{% badge job.get_status_display job.get_status_color %}</span>
</p>
{% if job.completed %}

View File

@ -17,7 +17,6 @@ from netbox.ui.attrs import (
)
from utilities.forms import TableConfigForm, get_selected_values
from utilities.forms.mixins import FORM_FIELD_LOOKUPS
from utilities.string import humanize_duration
from utilities.views import get_action_url, get_viewname
__all__ = (
@ -32,7 +31,6 @@ __all__ = (
'get_item',
'get_key',
'humanize_disk_capacity',
'humanize_duration_filter',
'humanize_ram_capacity',
'humanize_speed',
'icon_from_status',
@ -213,23 +211,6 @@ def _format_speed(speed, divisor, unit):
return f'{whole}.{fraction} {unit}'
@register.filter('humanize_duration')
def humanize_duration_filter(value):
"""
Express a timedelta in a human-friendly format, always using the largest appropriate units.
Sub-second durations are rendered with millisecond precision. A negative duration is rendered
with a leading minus sign rather than being suppressed.
Examples:
timedelta(seconds=90) => "1m 30s"
timedelta(hours=1, minutes=5, seconds=23) => "1h 5m 23s"
timedelta(milliseconds=430) => "0.43s"
timedelta(seconds=-5) => "-5s"
"""
return humanize_duration(value)
@register.filter()
def humanize_speed(speed):
"""

View File

@ -44,8 +44,8 @@ class HumanizeDurationTest(TestCase):
self.assertEqual(humanize_duration(timedelta(seconds=59, milliseconds=600)), '1m')
def test_negative_duration_retains_sign(self):
# A negative duration is anomalous, so it is rendered as such rather than suppressed here.
# Callers which need a floor of zero (e.g. Job.elapsed_time) apply one themselves.
# 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')