Custom script remains in "running" state forever when log raises an exception

[candlerb]

NetBox version

v3.5.8

Python version

3.8

Steps to Reproduce

Upload the following custom script and run it

from ipam.models import Prefix
from extras.scripts import Script

class Bug(Script):
    class Meta:
        name = "Bug reproducer"
        scheduling_enabled = False
        commit_default = False

    def run(self, data, commit):
        prefix = Prefix.objects.first()
        self.log_info(prefix)

Expected Behavior

Either the script to complete successfully, or for it to terminate with an error/exception.

Observed Behavior

The script remains in "running" / "Results pending..." state indefinitely.

If you navigate to the "Jobs" tab at /extras/scripts/bug/Bug/jobs/, you see:

In reality though, the script crashed. The error is visible with journalctl -eu netbox-rq:

Aug 23 09:31:49 netbox3 python3[93660]: 09:31:49 default: extras.scripts.run_script(commit=False, data={}, job=<Job: 3c078c1e-6223-4bfb-b17c-2437bf523c62>, request=<utilities.utils.NetBoxFakeRequest object at 0x7fb3459651f0>) (3c078c1e-6223-4bfb-b17c-2437bf523c62)
Aug 23 09:31:49 netbox3 python3[109979]: 09:31:49 [Job 3c078c1e-6223-4bfb-b17c-2437bf523c62]: exception raised while executing (extras.scripts.run_script)
Aug 23 09:31:49 netbox3 python3[109979]: Traceback (most recent call last):
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/netbox/extras/scripts.py", line 511, in _run_script
Aug 23 09:31:49 netbox3 python3[109979]:     job.terminate()
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/netbox/core/models/jobs.py", line 161, in terminate
Aug 23 09:31:49 netbox3 python3[109979]:     self.save()
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/django/db/models/base.py", line 812, in save
Aug 23 09:31:49 netbox3 python3[109979]:     self.save_base(
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/django/db/models/base.py", line 863, in save_base
Aug 23 09:31:49 netbox3 python3[109979]:     updated = self._save_table(
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/django/db/models/base.py", line 976, in _save_table
Aug 23 09:31:49 netbox3 python3[109979]:     updated = self._do_update(
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/django/db/models/base.py", line 1040, in _do_update
Aug 23 09:31:49 netbox3 python3[109979]:     return filtered._update(values) > 0
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/django/db/models/query.py", line 1216, in _update
Aug 23 09:31:49 netbox3 python3[109979]:     return query.get_compiler(self.db).execute_sql(CURSOR)
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/django/db/models/sql/compiler.py", line 1822, in execute_sql
Aug 23 09:31:49 netbox3 python3[109979]:     cursor = super().execute_sql(result_type)
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/django/db/models/sql/compiler.py", line 1385, in execute_sql
Aug 23 09:31:49 netbox3 python3[109979]:     sql, params = self.as_sql()
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/django/db/models/sql/compiler.py", line 1788, in as_sql
Aug 23 09:31:49 netbox3 python3[109979]:     val = field.get_db_prep_save(val, connection=self.connection)
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/django/db/models/fields/__init__.py", line 925, in get_db_prep_save
Aug 23 09:31:49 netbox3 python3[109979]:     return self.get_db_prep_value(value, connection=connection, prepared=False)
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/django/db/models/fields/__init__.py", line 920, in get_db_prep_value
Aug 23 09:31:49 netbox3 python3[109979]:     value = self.get_prep_value(value)
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/django/db/models/fields/json.py", line 96, in get_prep_value
Aug 23 09:31:49 netbox3 python3[109979]:     return json.dumps(value, cls=self.encoder)
Aug 23 09:31:49 netbox3 python3[109979]:   File "/usr/lib/python3.8/json/__init__.py", line 231, in dumps
Aug 23 09:31:49 netbox3 python3[109979]:     return _default_encoder.encode(obj)
Aug 23 09:31:49 netbox3 python3[109979]:   File "/usr/lib/python3.8/json/encoder.py", line 199, in encode
Aug 23 09:31:49 netbox3 python3[109979]:     chunks = self.iterencode(o, _one_shot=True)
Aug 23 09:31:49 netbox3 python3[109979]:   File "/usr/lib/python3.8/json/encoder.py", line 257, in iterencode
Aug 23 09:31:49 netbox3 python3[109979]:     return _iterencode(o, 0)
Aug 23 09:31:49 netbox3 python3[109979]:   File "/usr/lib/python3.8/json/encoder.py", line 179, in default
Aug 23 09:31:49 netbox3 python3[109979]:     raise TypeError(f'Object of type {o.__class__.__name__} '
Aug 23 09:31:49 netbox3 python3[109979]: TypeError: Object of type Prefix is not JSON serializable
Aug 23 09:31:49 netbox3 python3[109979]: During handling of the above exception, another exception occurred:
Aug 23 09:31:49 netbox3 python3[109979]: Traceback (most recent call last):
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/rq/worker.py", line 1428, in perform_job
Aug 23 09:31:49 netbox3 python3[109979]:     rv = job.perform()
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/rq/job.py", line 1278, in perform
Aug 23 09:31:49 netbox3 python3[109979]:     self._result = self._execute()
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/rq/job.py", line 1315, in _execute
Aug 23 09:31:49 netbox3 python3[109979]:     result = self.func(*self.args, **self.kwargs)
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/netbox/extras/scripts.py", line 533, in run_script
Aug 23 09:31:49 netbox3 python3[109979]:     _run_script()
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/netbox/extras/scripts.py", line 522, in _run_script
Aug 23 09:31:49 netbox3 python3[109979]:     job.terminate(status=JobStatusChoices.STATUS_ERRORED)
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/netbox/core/models/jobs.py", line 161, in terminate
Aug 23 09:31:49 netbox3 python3[109979]:     self.save()
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/django/db/models/base.py", line 812, in save
Aug 23 09:31:49 netbox3 python3[109979]:     self.save_base(
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/django/db/models/base.py", line 863, in save_base
Aug 23 09:31:49 netbox3 python3[109979]:     updated = self._save_table(
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/django/db/models/base.py", line 976, in _save_table
Aug 23 09:31:49 netbox3 python3[109979]:     updated = self._do_update(
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/django/db/models/base.py", line 1040, in _do_update
Aug 23 09:31:49 netbox3 python3[109979]:     return filtered._update(values) > 0
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/django/db/models/query.py", line 1216, in _update
Aug 23 09:31:49 netbox3 python3[109979]:     return query.get_compiler(self.db).execute_sql(CURSOR)
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/django/db/models/sql/compiler.py", line 1822, in execute_sql
Aug 23 09:31:49 netbox3 python3[109979]:     cursor = super().execute_sql(result_type)
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/django/db/models/sql/compiler.py", line 1385, in execute_sql
Aug 23 09:31:49 netbox3 python3[109979]:     sql, params = self.as_sql()
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/django/db/models/sql/compiler.py", line 1788, in as_sql
Aug 23 09:31:49 netbox3 python3[109979]:     val = field.get_db_prep_save(val, connection=self.connection)
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/django/db/models/fields/__init__.py", line 925, in get_db_prep_save
Aug 23 09:31:49 netbox3 python3[109979]:     return self.get_db_prep_value(value, connection=connection, prepared=False)
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/django/db/models/fields/__init__.py", line 920, in get_db_prep_value
Aug 23 09:31:49 netbox3 python3[109979]:     value = self.get_prep_value(value)
Aug 23 09:31:49 netbox3 python3[109979]:   File "/opt/netbox/venv/lib/python3.8/site-packages/django/db/models/fields/json.py", line 96, in get_prep_value
Aug 23 09:31:49 netbox3 python3[109979]:     return json.dumps(value, cls=self.encoder)
Aug 23 09:31:49 netbox3 python3[109979]:   File "/usr/lib/python3.8/json/__init__.py", line 231, in dumps
Aug 23 09:31:49 netbox3 python3[109979]:     return _default_encoder.encode(obj)
Aug 23 09:31:49 netbox3 python3[109979]:   File "/usr/lib/python3.8/json/encoder.py", line 199, in encode
Aug 23 09:31:49 netbox3 python3[109979]:     chunks = self.iterencode(o, _one_shot=True)
Aug 23 09:31:49 netbox3 python3[109979]:   File "/usr/lib/python3.8/json/encoder.py", line 257, in iterencode
Aug 23 09:31:49 netbox3 python3[109979]:     return _iterencode(o, 0)
Aug 23 09:31:49 netbox3 python3[109979]:   File "/usr/lib/python3.8/json/encoder.py", line 179, in default
Aug 23 09:31:49 netbox3 python3[109979]:     raise TypeError(f'Object of type {o.__class__.__name__} '
Aug 23 09:31:49 netbox3 python3[109979]: TypeError: Object of type Prefix is not JSON serializable

But the netbox-rq worker is still running.

[jeremystretch]

The root issue here is that the logging methods are not validating that the message passed is a string. In this instance, the prefix object is being stored directly in the script's log, which triggers the serialization failure. This is caught and handled the first time, however the invalid log data remains in place, and thus causes a repeat exception when we attempt to mark the job as failed.

We could clear out the script's log on failure, but that seems like it would do more harm than good. Instead, we can tweak the script's logging methods to force casting of the message to a string, which ensures it will be serializable.