Update documentation

docs/configuration/system.md

@@ -158,6 +158,7 @@ LOGGING = {
 * `netbox.<app>.<model>` - Generic form for model-specific log messages
 * `netbox.auth.*` - Authentication events
 * `netbox.api.views.*` - Views which handle business logic for the REST API
+* `netbox.jobs.*` - Background jobs
 * `netbox.reports.*` - Report execution (`module.name`)
 * `netbox.scripts.*` - Custom script execution (`module.name`)
 * `netbox.views.*` - Views which handle business logic for the web UI

docs/plugins/development/background-jobs.md

@@ -38,6 +38,27 @@ You can schedule the background job from within your code (e.g. from a model's `
 
 This is the human-friendly names of your background job. If omitted, the class name will be used.
 
+### Logging
+
+!!! info "This feature was introduced in NetBox v4.4."
+
+A Python logger is instantiated by the runner for each job. It can be utilized within a job's `run()` method as needed:
+
+```python
+def run(self, *args, **kwargs):
+    obj = MyModel.objects.get(pk=kwargs.get('pk'))
+    self.logger.info("Retrieved object {obj}")
+```
+
+Four of the standard Python logging levels are supported:
+
+* `debug()`
+* `info()`
+* `warning()`
+* `error()`
+
+Log entries recorded using the runner's logger will be saved in the job's log in the database in addition to being processed by other [system logging handlers](../../configuration/system.md#logging).
+
 ### Scheduled Jobs
 
 As described above, jobs can be scheduled for immediate execution or at any later time using the `enqueue()` method. However, for management purposes, the `enqueue_once()` method allows a job to be scheduled exactly once avoiding duplicates. If a job is already scheduled for a particular instance, a second one won't be scheduled, respecting thread safety. An example use case would be to schedule a periodic task that is bound to an instance in general, but not to any event of that instance (such as updates). The parameters of the `enqueue_once()` method are identical to those of `enqueue()`.

netbox/core/constants.py

@@ -4,23 +4,31 @@ from django.utils.translation import gettext_lazy as _
 from rq.job import JobStatus
 
 __all__ = (
+    'JOB_LOG_ENTRY_LEVELS',
     'RQ_TASK_STATUSES',
 )
 
 
 @dataclass
-class Status:
+class Badge:
     label: str
     color: str
 
 
 RQ_TASK_STATUSES = {
-    JobStatus.QUEUED: Status(_('Queued'), 'cyan'),
-    JobStatus.FINISHED: Status(_('Finished'), 'green'),
-    JobStatus.FAILED: Status(_('Failed'), 'red'),
-    JobStatus.STARTED: Status(_('Started'), 'blue'),
-    JobStatus.DEFERRED: Status(_('Deferred'), 'gray'),
-    JobStatus.SCHEDULED: Status(_('Scheduled'), 'purple'),
-    JobStatus.STOPPED: Status(_('Stopped'), 'orange'),
-    JobStatus.CANCELED: Status(_('Cancelled'), 'yellow'),
+    JobStatus.QUEUED: Badge(_('Queued'), 'cyan'),
+    JobStatus.FINISHED: Badge(_('Finished'), 'green'),
+    JobStatus.FAILED: Badge(_('Failed'), 'red'),
+    JobStatus.STARTED: Badge(_('Started'), 'blue'),
+    JobStatus.DEFERRED: Badge(_('Deferred'), 'gray'),
+    JobStatus.SCHEDULED: Badge(_('Scheduled'), 'purple'),
+    JobStatus.STOPPED: Badge(_('Stopped'), 'orange'),
+    JobStatus.CANCELED: Badge(_('Cancelled'), 'yellow'),
+}
+
+JOB_LOG_ENTRY_LEVELS = {
+    'debug': Badge(_('Debug'), 'gray'),
+    'info': Badge(_('Info'), 'blue'),
+    'warning': Badge(_('Warning'), 'orange'),
+    'error': Badge(_('Error'), 'red'),
 }

netbox/core/dataclasses.py

@@ -3,6 +3,8 @@ import logging
 from dataclasses import dataclass, field
 from datetime import datetime
 
+from django.utils import timezone
+
 __all__ = (
     'JobLogEntry',
 )
@@ -12,7 +14,7 @@ __all__ = (
 class JobLogEntry:
     level: str
     message: str
-    timestamp: datetime = field(default_factory=datetime.now)
+    timestamp: datetime = field(default_factory=timezone.now)
 
     @classmethod
     def from_logrecord(cls, record: logging.LogRecord):

netbox/core/jobs.py

@@ -7,7 +7,6 @@ from netbox.jobs import JobRunner, system_job
 from netbox.search.backends import search_backend
 from utilities.proxy import resolve_proxies
 from .choices import DataSourceStatusChoices, JobIntervalChoices
-from .exceptions import SyncError
 from .models import DataSource
 
 logger = logging.getLogger(__name__)
@@ -23,19 +22,23 @@ class SyncDataSourceJob(JobRunner):
 
     def run(self, *args, **kwargs):
         datasource = DataSource.objects.get(pk=self.job.object_id)
+        self.logger.debug(f"Found DataSource ID {datasource.pk}")
 
         try:
+            self.logger.info(f"Syncing data source {datasource}")
             datasource.sync()
 
             # Update the search cache for DataFiles belonging to this source
+            self.logger.debug("Updating search cache for data files")
             search_backend.cache(datasource.datafiles.iterator())
 
         except Exception as e:
+            self.logger.error(f"Error syncing data source: {e}")
             DataSource.objects.filter(pk=datasource.pk).update(status=DataSourceStatusChoices.FAILED)
-            if type(e) is SyncError:
-                logging.error(e)
             raise e
 
+        self.logger.info("Syncing completed successfully")
+
 
 @system_job(interval=JobIntervalChoices.INTERVAL_DAILY)
 class SystemHousekeepingJob(JobRunner):

netbox/core/migrations/0016_job_log_entries.py

@@ -2,6 +2,8 @@ import django.contrib.postgres.fields
 import django.core.serializers.json
 from django.db import migrations, models
 
+import utilities.json
+
 
 class Migration(migrations.Migration):
 
@@ -15,6 +17,7 @@ class Migration(migrations.Migration):
             name='log_entries',
             field=django.contrib.postgres.fields.ArrayField(
                 base_field=models.JSONField(
+                    decoder=utilities.json.JobLogDecoder,
                     encoder=django.core.serializers.json.DjangoJSONEncoder
                 ),
                 blank=True,

netbox/core/models/jobs.py

@@ -20,6 +20,7 @@ from core.choices import JobStatusChoices
 from core.dataclasses import JobLogEntry
 from core.models import ObjectType
 from core.signals import job_end, job_start
+from utilities.json import JobLogDecoder
 from utilities.querysets import RestrictedQuerySet
 from utilities.rqworker import get_queue_for_model
 
@@ -109,9 +110,10 @@ class Job(models.Model):
         unique=True
     )
     log_entries = ArrayField(
+        verbose_name=_('log entries'),
         base_field=models.JSONField(
             encoder=DjangoJSONEncoder,
-            # TODO: Specify a decoder to handle ISO 8601 timestamps
+            decoder=JobLogDecoder,
         ),
         blank=True,
         default=list,
@@ -217,6 +219,13 @@ class Job(models.Model):
         # Send signal
         job_end.send(self)
 
+    def log(self, record: logging.LogRecord):
+        """
+        Record a LogRecord from Python's native logging in the job's log.
+        """
+        entry = JobLogEntry.from_logrecord(record)
+        self.log_entries.append(asdict(entry))
+
     @classmethod
     def enqueue(
             cls,
@@ -283,10 +292,3 @@ class Job(models.Model):
             transaction.on_commit(callback)
 
         return job
-
-    def log(self, record: logging.LogRecord):
-        """
-        Record a Python LogRecord in the job's log.
-        """
-        entry = JobLogEntry.from_logrecord(record)
-        self.log_entries.append(asdict(entry))

netbox/core/tables/columns.py

@@ -1,12 +1,11 @@
 import django_tables2 as tables
 from django.utils.safestring import mark_safe
 
-from core.constants import RQ_TASK_STATUSES
 from netbox.registry import registry
 
 __all__ = (
     'BackendTypeColumn',
-    'RQJobStatusColumn',
+    'BadgeColumn',
 )
 
 
@@ -23,14 +22,21 @@ class BackendTypeColumn(tables.Column):
         return value
 
 
-class RQJobStatusColumn(tables.Column):
+class BadgeColumn(tables.Column):
     """
-    Render a colored label for the status of an RQ job.
+    Render a colored badge for a value.
+
+    Args:
+        badges: A dictionary mapping of values to core.constants.Badge instances.
     """
+    def __init__(self, badges, *args, **kwargs):
+        super().__init__(*args, **kwargs)
+        self.badges = badges
+
     def render(self, value):
-        status = RQ_TASK_STATUSES.get(value)
-        return mark_safe(f'<span class="badge text-bg-{status.color}">{status.label}</span>')
+        badge = self.badges.get(value)
+        return mark_safe(f'<span class="badge text-bg-{badge.color}">{badge.label}</span>')
 
     def value(self, value):
-        status = RQ_TASK_STATUSES.get(value)
-        return status.label
+        badge = self.badges.get(value)
+        return badge.label

netbox/core/tables/jobs.py

@@ -2,7 +2,9 @@ import django_tables2 as tables
 from django.utils.translation import gettext_lazy as _
 
 from netbox.tables import BaseTable, NetBoxTable, columns
-from ..models import Job
+from core.constants import JOB_LOG_ENTRY_LEVELS
+from core.models import Job
+from core.tables.columns import BadgeColumn
 
 
 class JobTable(NetBoxTable):
@@ -62,10 +64,12 @@ class JobTable(NetBoxTable):
 
 
 class JobLogEntryTable(BaseTable):
-    timestamp = tables.Column(
+    timestamp = columns.DateTimeColumn(
+        timespec='milliseconds',
         verbose_name=_('Time'),
     )
-    level = tables.Column(
+    level = BadgeColumn(
+        badges=JOB_LOG_ENTRY_LEVELS,
         verbose_name=_('Level'),
     )
     message = tables.Column(

netbox/core/tables/tasks.py

@@ -2,7 +2,8 @@ import django_tables2 as tables
 from django.utils.translation import gettext_lazy as _
 from django_tables2.utils import A
 
-from core.tables.columns import RQJobStatusColumn
+from core.constants import RQ_TASK_STATUSES
+from core.tables.columns import BadgeColumn
 from netbox.tables import BaseTable, columns
 
 
@@ -84,7 +85,8 @@ class BackgroundTaskTable(BaseTable):
     ended_at = columns.DateTimeColumn(
         verbose_name=_("Ended")
     )
-    status = RQJobStatusColumn(
+    status = BadgeColumn(
+        badges=RQ_TASK_STATUSES,
         verbose_name=_("Status"),
         accessor='get_status'
     )

netbox/core/views.py

@@ -188,7 +188,7 @@ class JobView(generic.ObjectView):
 class JobLogView(generic.ObjectView):
     queryset = Job.objects.all()
     actions = (DeleteObject,)
-    template_name = 'core/job_log.html'
+    template_name = 'core/job/log.html'
     tab = ViewTab(
         label=_('Log'),
         badge=lambda obj: len(obj.log_entries),

netbox/netbox/jobs.py

@@ -35,7 +35,9 @@ def system_job(interval):
 
 
 class JobLogHandler(logging.Handler):
-
+    """
+    A logging handler which records entries on a Job.
+    """
     def __init__(self, job, *args, **kwargs):
         super().__init__(*args, **kwargs)
         self.job = job

netbox/netbox/tests/test_jobs.py

@@ -11,7 +11,10 @@ from core.choices import JobStatusChoices
 
 class TestJobRunner(JobRunner):
     def run(self, *args, **kwargs):
-        pass
+        self.logger.debug("Debug message")
+        self.logger.info("Info message")
+        self.logger.warning("Warning message")
+        self.logger.error("Error message")
 
 
 class JobRunnerTestCase(TestCase):
@@ -47,8 +50,16 @@ class JobRunnerTest(JobRunnerTestCase):
     def test_handle(self):
         job = TestJobRunner.enqueue(immediate=True)
 
+        # Check job status
         self.assertEqual(job.status, JobStatusChoices.STATUS_COMPLETED)
 
+        # Check logging
+        self.assertEqual(len(job.log_entries), 4)
+        self.assertEqual(job.log_entries[0]['message'], "Debug message")
+        self.assertEqual(job.log_entries[1]['message'], "Info message")
+        self.assertEqual(job.log_entries[2]['message'], "Warning message")
+        self.assertEqual(job.log_entries[3]['message'], "Error message")
+
     def test_handle_errored(self):
         class ErroredJobRunner(TestJobRunner):
             EXP = Exception('Test error')

netbox/templates/core/job.html

@@ -1,27 +1,6 @@
-{% extends 'generic/object.html' %}
-{% load buttons %}
-{% load helpers %}
-{% load perms %}
+{% extends 'core/job/base.html' %}
 {% load i18n %}
 
-{% block breadcrumbs %}
-  {{ block.super }}
-  {% if object.object %}
-    <li class="breadcrumb-item">
-      <a href="{% url 'core:job_list' %}?object_type={{ object.object_type_id }}">{{ object.object|meta:"verbose_name_plural"|bettertitle }}</a>
-    </li>
-    {% with parent_jobs_viewname=object.object|viewname:"jobs" %}
-      <li class="breadcrumb-item">
-        <a href="{% url parent_jobs_viewname pk=object.object.pk %}">{{ object.object }}</a>
-      </li>
-    {% endwith %}
-  {% else %}
-    <li class="breadcrumb-item">
-      <a href="{% url 'core:job_list' %}?name={{ object.name|urlencode }}">{{ object.name }}</a>
-    </li>
-  {% endif %}
-{% endblock breadcrumbs %}
-
 {% block content %}
   <div class="row mb-3">
     <div class="col col-12 col-md-6">

netbox/templates/core/job/base.html

@@ -3,7 +3,6 @@
 {% load helpers %}
 {% load perms %}
 {% load i18n %}
-{% load render_table from django_tables2 %}
 
 {% block breadcrumbs %}
   {{ block.super }}
@@ -22,13 +21,3 @@
     </li>
   {% endif %}
 {% endblock breadcrumbs %}
-
-{% block content %}
-  <div class="row mb-3">
-    <div class="col">
-      <div class="card">
-        {% render_table table %}
-      </div>
-    </div>
-  </div>
-{% endblock %}

netbox/templates/core/job/log.html

@@ -0,0 +1,12 @@
+{% extends 'core/job/base.html' %}
+{% load render_table from django_tables2 %}
+
+{% block content %}
+  <div class="row mb-3">
+    <div class="col">
+      <div class="card">
+        {% render_table table %}
+      </div>
+    </div>
+  </div>
+{% endblock %}

netbox/utilities/json.py

@@ -1,10 +1,14 @@
 import decimal
+import json
 
 from django.core.serializers.json import DjangoJSONEncoder
 
+from utilities.datetime import datetime_from_timestamp
+
 __all__ = (
     'ConfigJSONEncoder',
     'CustomFieldJSONEncoder',
+    'JobLogDecoder',
 )
 
 
@@ -29,3 +33,21 @@ class ConfigJSONEncoder(DjangoJSONEncoder):
             return type(o).__name__
 
         return super().default(o)
+
+
+class JobLogDecoder(json.JSONDecoder):
+    """
+    Deserialize JobLogEntry timestamps.
+    """
+    def __init__(self, *args, **kwargs):
+        kwargs['object_hook'] = self._deserialize_entry
+        super().__init__(*args, **kwargs)
+
+    def _deserialize_entry(self, obj: dict) -> dict:
+        if obj.get('timestamp'):
+            # Deserialize a timestamp string to a native datetime object
+            try:
+                obj['timestamp'] = datetime_from_timestamp(obj['timestamp'])
+            except ValueError:
+                pass
+        return obj