Repository: fnndsc/chris_ultron_backend
Issue: JSON string escape sequence length

### tl;dr

Plugin instance producing lots of stdout with special characters and/or colors causes CUBE to get stuck on `status="started"`

### Background

A plugin instance's "summary" field can be no larger than 4000B.

https://github.com/FNNDSC/ChRIS_ultron_backEnd/blob/9ec45e8d5dfd6a6603eefe51504061898608c173/chris_backend/plugininstances/models.py#L39

The logs returned by _pman_ are stored in "summary". As a workaround, if the logs have a `str` length of greater than 3000, then they are truncated.

https://github.com/FNNDSC/ChRIS_ultron_backEnd/blob/9ec45e8d5dfd6a6603eefe51504061898608c173/chris_backend/plugininstances/services/manager.py#L706-L707

However, `str` length is measured prior to JSON serialization, yet it is the serialized JSON that gets stored in DB.

https://github.com/FNNDSC/ChRIS_ultron_backEnd/blob/9ec45e8d5dfd6a6603eefe51504061898608c173/chris_backend/plugininstances/services/manager.py#L708

In some cases, escape sequences can overflow the 4,000 byte limit. Escape sequences have a longer length than expected:

```python
import json
len('"')  # == 1
len(json.dumps('"'))  # == 4
```

Terminal color output is another offender.

### Minimal Example to Reproduce

Consider this valid _ChRIS_ _fs_ plugin:

```python
from chris_plugin import chris_plugin

@chris_plugin
def main(options, outputdir):
    for a in range(2000):
        print('"', end='')
```

A plugin instance of this plugin would create 2,000B of logs, which will serialized to 4,002B of JSON data.

### Actual Result

The plugin instance is stuck on `status="started"`. The worker continues to poll `pfcon` and raising

```
[INFO][manager 10 140188714088256] Current job minichris-jid-2 remote status = finishedSuccessfully
[INFO][manager 10 140188714088256] Current job minichris-jid-2 DB status = started
[ERROR][trace 9 140188714088256] Task plugininstances.tasks.check_plugin_instance_exec_status[e21f300e-72e1-4b0d-a4eb-74410db04779] raised unexpected: DataError('value too long for type character varying(4000)\\n')
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/dist-packages/django/db/backends/utils.py", line 84, in _execute
    return self.cursor.execute(sql, params)
psycopg2.errors.StringDataRightTruncation: value too long for type character varying(4000)


The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.8/dist-packages/celery/app/trace.py", line 450, in trace_task
    R = retval = fun(*args, **kwargs)
  File "/usr/local/lib/python3.8/dist-packages/celery/app/trace.py", line 731, in __protected_call__
    return self.run(*args, **kwargs)
  File "/home/localuser/chris_backend/plugininstances/tasks.py", line 59, in check_plugin_instance_exec_status
    plg_inst_manager.check_plugin_instance_app_exec_status()
  File "/home/localuser/chris_backend/plugininstances/services/manager.py", line 226, in check_plugin_instance_app_exec_status
    PluginInstance.objects.filter(
  File "/usr/local/lib/python3.8/dist-packages/django/db/models/query.py", line 741, in update
    rows = query.get_compiler(self.db).execute_sql(CURSOR)
  File "/usr/local/lib/python3.8/dist-packages/django/db/models/sql/compiler.py", line 1471, in execute_sql
    cursor = super().execute_sql(result_type)
  File "/usr/local/lib/python3.8/dist-packages/django/db/models/sql/compiler.py", line 1142, in execute_sql
    cursor.execute(sql, params)
  File "/usr/local/lib/python3.8/dist-packages/django/db/backends/utils.py", line 67, in execute
    return self._execute_with_wrappers(sql, params, many=False, executor=self._execute)
  File "/usr/local/lib/python3.8/dist-packages/django/db/backends/utils.py", line 76, in _execute_with_wrappers
    return executor(sql, params, many, context)
  File "/usr/local/lib/python3.8/dist-packages/django/db/backends/utils.py", line 84, in _execute
    return self.cursor.execute(sql, params)
  File "/usr/local/lib/python3.8/dist-packages/django/db/utils.py", line 89, in __exit__
    raise dj_exc_value.with_traceback(traceback) from exc_value
  File "/usr/local/lib/python3.8/dist-packages/django/db/backends/utils.py", line 84, in _execute
    return self.cursor.execute(sql, params)
django.db.utils.DataError: value too long for type character varying(4000)

[ERROR][trace 10 140188714088256] Task plugininstances.tasks.check_plugin_instance_exec_status[5bda246f-29c9-4a34-889d-ed429bf92378] raised unexpected: DataError('value too long for type character varying(4000)\\n')
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/dist-packages/django/db/backends/utils.py", line 84, in _execute
    return self.cursor.execute(sql, params)
psycopg2.errors.StringDataRightTruncation: value too long for type character varying(4000)


The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.8/dist-packages/celery/app/trace.py", line 450, in trace_task
    R = retval = fun(*args, **kwargs)
  File "/usr/local/lib/python3.8/dist-packages/celery/app/trace.py", line 731, in __protected_call__
    return self.run(*args, **kwargs)
  File "/home/localuser/chris_backend/plugininstances/tasks.py", line 59, in check_plugin_instance_exec_status
    plg_inst_manager.check_plugin_instance_app_exec_status()
  File "/home/localuser/chris_backend/plugininstances/services/manager.py", line 226, in check_plugin_instance_app_exec_status
    PluginInstance.objects.filter(
  File "/usr/local/lib/python3.8/dist-packages/django/db/models/query.py", line 741, in update
    rows = query.get_compiler(self.db).execute_sql(CURSOR)
  File "/usr/local/lib/python3.8/dist-packages/django/db/models/sql/compiler.py", line 1471, in execute_sql
    cursor = super().execute_sql(result_type)
  File "/usr/local/lib/python3.8/dist-packages/django/db/models/sql/compiler.py", line 1142, in execute_sql
    cursor.execute(sql, params)
  File "/usr/local/lib/python3.8/dist-packages/django/db/backends/utils.py", line 67, in execute
    return self._execute_with_wrappers(sql, params, many=False, executor=self._execute)
  File "/usr/local/lib/python3.8/dist-packages/django/db/backends/utils.py", line 76, in _execute_with_wrappers
    return executor(sql, params, many, context)
  File "/usr/local/lib/python3.8/dist-packages/django/db/backends/utils.py", line 84, in _execute
    return self.cursor.execute(sql, params)
  File "/usr/local/lib/python3.8/dist-packages/django/db/utils.py", line 89, in __exit__
    raise dj_exc_value.with_traceback(traceback) from exc_value
  File "/usr/local/lib/python3.8/dist-packages/django/db/backends/utils.py", line 84, in _execute
    return self.cursor.execute(sql, params)
django.db.utils.DataError: value too long for type character varying(4000)

```

Changed files:
chris_backend/plugininstances/services/manager.py

diff --git a/chris_backend/plugininstances/services/manager.py b/chris_backend/plugininstances/services/manager.py
index 2566090..6371614 100755
--- a/chris_backend/plugininstances/services/manager.py
+++ b/chris_backend/plugininstances/services/manager.py
@@ -70,6 +70,8 @@ logger = logging.getLogger(__name__)
 
 class PluginInstanceManager(object):
 
+    __NONASCII = re.compile(r'[^\\x00-\\x7F]')
+
     def __init__(self, plugin_instance):
 
         self.c_plugin_inst = plugin_instance
@@ -670,8 +672,8 @@ class PluginInstanceManager(object):
                 total_size += plg_inst_file.fname.size
         self.c_plugin_inst.size += total_size
 
-    @staticmethod
-    def get_job_status_summary(d_response=None):
+    @classmethod
+    def get_job_status_summary(cls, d_response=None):
         """
         Get a job status summary JSON string from pfcon response.
         """
@@ -704,5 +706,15 @@ class PluginInstanceManager(object):
             logs = d_jobStatusSummary['compute']['return']['job_logs'] = d_c['logs']
 
             if len(logs) > 3000:
-                d_jobStatusSummary['compute']['return']['job_logs'] = logs[-3000:]
+                # Workaround which fixes https://github.com/FNNDSC/ChRIS_ultron_backEnd/issues/364
+                # Better solution discussed in https://github.com/FNNDSC/ChRIS_ultron_backEnd/issues/374
+                #
+                # JSON serialization causes string to be longer than you might expect
+                # because of escape sequences, e.g. json.dumps('\\n') -> '"\\\\n"'
+
+                # replace non-ASCII characters, such as emojis and Chinese characters
+                logs_ascii = cls.__NONASCII.sub('?', logs)
+
+                # truncate logs, assuming worst case where every character needs to be escaped
+                d_jobStatusSummary['compute']['return']['job_logs'] = logs_ascii[-1800:]
         return json.dumps(d_jobStatusSummary)