Job Log Model

nautobot/core/cli.py

@@ -132,6 +132,10 @@ def _configure_settings(config):
     if settings.METRICS_ENABLED and "postgres" in settings.DATABASES["default"]["ENGINE"]:
         settings.DATABASES["default"]["ENGINE"] = "django_prometheus.db.backends.postgresql"
 
+    # Create fake db for job logs. This uses the default db, but allows us to save logs within
+    # transaction.atomic().
+    settings.DATABASES["job_logs"] = settings.DATABASES["default"]
+
     #
     # Media storage
     #

nautobot/docs/additional-features/jobs.md

@@ -289,11 +289,11 @@ Log messages generated by any of these methods will be automatically grouped tog
 
 ### The `post_run()` Method
 
-If your job class implements a `post_run()` method (which must take no arguments other than `self`), this method will be automatically invoked after the `run()` and `test_*()` methods (if any). It will be called even if one of the other methods raises an exception, so this method can be used to handle any necessary cleanup or final events (such as sending an email or triggering a webhook). The status of the overall job is available at this time as `self.failed` and the [`JobResult`](../models/extras/jobresult.md) data object is available as `self.result`.
+If your job class implements a `post_run()` method (which must take no arguments other than `self`), this method will be automatically invoked after the `run()` and `test_*()` methods (if any). It will be called even if one of the other methods raises an exception, so this method can be used to handle any necessary cleanup or final events (such as sending an email or triggering a webhook). The status of the overall job is available at this time as `self.failed` and the associated [`JobResult`](../models/extras/jobresult.md) `data` field is available as `self.results`.
 
 ### Logging
 
-The following instance methods are available to log results from an executing job to be stored into the associated [`JobResult`](../models/extras/jobresult.md) record:
+The following instance methods are available to log results from an executing job to be stored into [`JobLogEntry`](../models/extras/joblogentry.md) records associated with the current [`JobResult`](../models/extras/jobresult.md):
 
 * `self.log(message)`
 * `self.log_debug(message)`
@@ -311,7 +311,6 @@ Markdown rendering is supported for log messages.
 !!! note
     Using `self.log_failure()`, in addition to recording a log message, will flag the overall job as failed, but it will **not** stop the execution of the job. To end a job early, you can use a Python `raise` or `return` as appropriate.
 
-
 ### Accessing Request Data
 
 Details of the current HTTP request (the one being made to execute the job) are available as the instance attribute `self.request`. This can be used to infer, for example, the user executing the job and their client IP address:

nautobot/docs/models/extras/joblogentry.md

@@ -0,0 +1,11 @@
+# Job Log Entry
+
+As of Nautobot 1.2, log messages from jobs are now stored in the JobLogEntry model. This allows more performant querying of log messages and even allows viewing of logs while the job is still running.
+
+Records of this type store the following data:
+
+- A reference to the JobResult object that created the log.
+- Timestamps indicating when the log message was created.
+- The logging level of the log message.
+- The log message.
+- If provided, the string format of the logged object and it's absolute url.

nautobot/docs/models/extras/jobresult.md

@@ -8,4 +8,4 @@ Records of this type store the following data:
 - A reference to the user who initiated the task
 - Timestamps indicating when the task was created and when it completed
 - An overall status such as "pending", "running", "errored", or "completed".
-- A block of structured data (often rendered as JSON); by convention this block is used to store detailed log records of the task execution, but it may in theory be used (such as by a plugin) to store other forms of structured data as well.
+- A block of structured data (often rendered as JSON); Any return values from the `.run()` and any `test` methods go to `output`. In addition any Job or plugin using the JobResult model can store arbitrary structured data here if needed. (Note that prior to Nautobot 1.2, job log records were stored in this field; they are now stored as distinct [`JobLogEntry`](joblogentry.md) records instead.)

nautobot/extras/constants.py

@@ -15,3 +15,8 @@
     "statuses",
     "webhooks",
 ]
+
+# JobLogEntry Truncation Length
+MAX_GROUPING_LENGTH = 100
+MAX_LOG_OBJECT_LENGTH = 200
+MAX_ABSOLUTE_URL_LENGTH = 255

nautobot/extras/datasources/git.py

@@ -27,6 +27,7 @@
     ConfigContextSchema,
     ExportTemplate,
     GitRepository,
+    JobLogEntry,
     JobResult,
     Tag,
 )
@@ -108,7 +109,7 @@ def pull_git_repository_and_refresh_data(repository_pk, request, job_result_pk):
 
     finally:
         if job_result.status not in JobResultStatusChoices.TERMINAL_STATE_CHOICES:
-            if job_result.data["total"][LogLevelChoices.LOG_FAILURE] > 0:
+            if JobLogEntry.objects.filter(job_result__pk=job_result.pk, log_level=LogLevelChoices.LOG_FAILURE).exists():
                 job_result.set_status(JobResultStatusChoices.STATUS_FAILED)
             else:
                 job_result.set_status(JobResultStatusChoices.STATUS_COMPLETED)

nautobot/extras/datasources/registry.py

@@ -19,7 +19,7 @@ def get_datasource_content_choices(model_name):
     )
 
 
-def refresh_datasource_content(model_name, record, request, job_result, delete=False):
+def refresh_datasource_content(model_name, record, request, job_result, delete=False, use_default_db=False):
     """Invoke the refresh callbacks for every content type registered for this model.
 
     Note that these callback functions are invoked regardless of whether a given model instance actually is flagged
@@ -32,44 +32,54 @@ def refresh_datasource_content(model_name, record, request, job_result, delete=F
         request (HttpRequest): Initiating request for this refresh, optional, used for change logging if provided
         job_result (JobResult): Passed through to the callback functions to use with logging their actions.
         delete (bool): True if the record is being deleted; False if it is being created/updated.
+        use_default_db(bool): Logs created should use the default database instead of the "job_logs" database.
     """
     job_result.log(
         f"Refreshing data provided by {record}...",
         level_choice=LogLevelChoices.LOG_INFO,
+        use_default_db=use_default_db,
     )
     job_result.save()
     if request:
         with change_logging(request):
             for entry in get_datasource_contents(model_name):
-                job_result.log(f"Refreshing {entry.name}...", level_choice=LogLevelChoices.LOG_INFO)
+                job_result.log(
+                    f"Refreshing {entry.name}...", level_choice=LogLevelChoices.LOG_INFO, use_default_db=use_default_db
+                )
                 try:
                     entry.callback(record, job_result, delete=delete)
                 except Exception as exc:
                     job_result.log(
                         f"Error while refreshing {entry.name}: {exc}",
                         level_choice=LogLevelChoices.LOG_FAILURE,
+                        use_default_db=use_default_db,
                     )
                     job_result.set_status(JobResultStatusChoices.STATUS_ERRORED)
                 job_result.save()
             job_result.log(
                 f"Data refresh from {record} complete!",
                 level_choice=LogLevelChoices.LOG_INFO,
+                use_default_db=use_default_db,
             )
             job_result.save()
     else:
         for entry in get_datasource_contents(model_name):
-            job_result.log(f"Refreshing {entry.name}...", level_choice=LogLevelChoices.LOG_INFO)
+            job_result.log(
+                f"Refreshing {entry.name}...", level_choice=LogLevelChoices.LOG_INFO, use_default_db=use_default_db
+            )
             try:
                 entry.callback(record, job_result, delete=delete)
             except Exception as exc:
                 job_result.log(
                     f"Error while refreshing {entry.name}: {exc}",
                     level_choice=LogLevelChoices.LOG_FAILURE,
+                    use_default_db=use_default_db,
                 )
                 job_result.set_status(JobResultStatusChoices.STATUS_ERRORED)
             job_result.save()
         job_result.log(
             f"Data refresh from {record} complete!",
             level_choice=LogLevelChoices.LOG_INFO,
+            use_default_db=use_default_db,
         )
         job_result.save()

nautobot/extras/jobs.py

@@ -98,23 +98,11 @@ class Meta:
 
         pass
 
-    @staticmethod
-    def _results_struct():
-        return OrderedDict(
-            [
-                ("success", 0),
-                ("info", 0),
-                ("warning", 0),
-                ("failure", 0),
-                ("log", []),
-            ]
-        )
-
     def __init__(self):
         self.logger = logging.getLogger(f"nautobot.jobs.{self.__class__.__name__}")
 
         self.request = None
-        self.active_test = None
+        self.active_test = "main"
         self.failed = False
         self._job_result = None
 
@@ -224,63 +212,20 @@ def job_result(self):
     def job_result(self, value):
         # Initialize job_result data format for our usage
         value.data = OrderedDict()
-        value.data["total"] = self._results_struct()
-        del value.data["total"]["log"]
-        for method_name in self.test_methods:
-            value.data[method_name] = self._results_struct()
-        # Only initialize results for run and post_run if they're actually implemented
-        if self.run.__func__ != BaseJob.run:
-            value.data["run"] = self._results_struct()
-        if self.post_run.__func__ != BaseJob.post_run:
-            value.data["post_run"] = self._results_struct()
 
         self._job_result = value
 
     @property
     def results(self):
         """
-        The results (log messages and final output) generated by this job.
+        The results generated by this job.
+        ** If you need the logs, you will need to filter on JobLogEntry **
+            Ex.
+            from nautobot.extras.models import JogLogEntry
+
+            JobLogEntry.objects.filter(job_result=self.job_result, <other criteria>)
 
         {
-            "total": {
-                "success": 0,
-                "info": 3,
-                "warning": 6,
-                "failure": 9,
-            }
-            "run": {
-                "success": 0,
-                "info": 1,
-                "warning": 2,
-                "failure": 3,
-                "log": [
-                    (timestamp, level, object_name, object_url, message),
-                    (timestamp, level, object_name, object_url, message),
-                    ...
-                ],
-            },
-            "test_function": {
-                "success": 0,
-                "info": 1,
-                "warning": 2,
-                "failure": 3,
-                "log": [
-                    (timestamp, level, object_name, object_url, message),
-                    (timestamp, level, object_name, object_url, message),
-                    ...
-                ],
-            },
-            "post_run": {
-                "success": 0,
-                "info": 1,
-                "warning": 2,
-                "failure": 3,
-                "log": [
-                    (timestamp, level, object_name, object_url, message),
-                    (timestamp, level, object_name, object_url, message),
-                    ...
-                ],
-            },
             "output": "...",
         }
         """

nautobot/extras/management/commands/runjob.py

@@ -7,8 +7,8 @@
 from django.test.client import RequestFactory
 from django.utils import timezone
 
-from nautobot.extras.choices import JobResultStatusChoices
-from nautobot.extras.models import JobResult
+from nautobot.extras.choices import LogLevelChoices, JobResultStatusChoices
+from nautobot.extras.models import JobLogEntry, JobResult
 from nautobot.extras.jobs import get_job, run_job
 from nautobot.utilities.utils import copy_safe_request
 
@@ -74,23 +74,26 @@ def handle(self, *args, **options):
             job_result = JobResult.objects.get(pk=job_result.pk)
 
         # Report on success/failure
-        for test_name, attrs in job_result.data.items():
-
-            if test_name in ["total", "output"]:
-                continue
+        groups = set(JobLogEntry.objects.filter(job_result=job_result).values_list("grouping", flat=True))
+        for group in sorted(groups):
+            logs = JobLogEntry.objects.filter(job_result__pk=job_result.pk, grouping=group)
+            success_count = logs.filter(log_level=LogLevelChoices.LOG_SUCCESS).count()
+            info_count = logs.filter(log_level=LogLevelChoices.LOG_INFO).count()
+            warning_count = logs.filter(log_level=LogLevelChoices.LOG_WARNING).count()
+            failure_count = logs.filter(log_level=LogLevelChoices.LOG_FAILURE).count()
 
             self.stdout.write(
                 "\t{}: {} success, {} info, {} warning, {} failure".format(
-                    test_name,
-                    attrs["success"],
-                    attrs["info"],
-                    attrs["warning"],
-                    attrs["failure"],
+                    group,
+                    success_count,
+                    info_count,
+                    warning_count,
+                    failure_count,
                 )
             )
 
-            for log_entry in attrs["log"]:
-                status = log_entry[1]
+            for log_entry in logs:
+                status = log_entry.log_level
                 if status == "success":
                     status = self.style.SUCCESS(status)
                 elif status == "info":
@@ -100,10 +103,10 @@ def handle(self, *args, **options):
                 elif status == "failure":
                     status = self.style.NOTICE(status)
 
-                if log_entry[2]:  # object associated with log entry
-                    self.stdout.write(f"\t\t{status}: {log_entry[2]}: {log_entry[-1]}")
+                if log_entry.log_object:
+                    self.stdout.write(f"\t\t{status}: {log_entry.log_object}: {log_entry.message}")
                 else:
-                    self.stdout.write(f"\t\t{status}: {log_entry[-1]}")
+                    self.stdout.write(f"\t\t{status}: {log_entry.message}")
 
         if job_result.data["output"]:
             self.stdout.write(job_result.data["output"])

nautobot/extras/migrations/0017_joblogentry.py

@@ -0,0 +1,37 @@
+# Generated by Django 3.1.13 on 2021-10-18 02:47
+
+from django.db import migrations, models
+import django.db.models.deletion
+import django.utils.timezone
+import uuid
+
+
+class Migration(migrations.Migration):
+
+    dependencies = [
+        ("extras", "0016_secret"),
+    ]
+
+    operations = [
+        migrations.CreateModel(
+            name="JobLogEntry",
+            fields=[
+                (
+                    "id",
+                    models.UUIDField(
+                        default=uuid.uuid4, editable=False, primary_key=True, serialize=False, unique=True
+                    ),
+                ),
+                ("log_level", models.CharField(default="default", max_length=32)),
+                ("grouping", models.CharField(default="main", max_length=100)),
+                ("message", models.TextField(blank=True)),
+                ("created", models.DateTimeField(default=django.utils.timezone.now)),
+                ("log_object", models.CharField(blank=True, max_length=200, null=True)),
+                ("absolute_url", models.CharField(blank=True, max_length=255, null=True)),
+                ("job_result", models.ForeignKey(on_delete=django.db.models.deletion.CASCADE, to="extras.jobresult")),
+            ],
+            options={
+                "abstract": False,
+            },
+        ),
+    ]