Failures with non-ascii characters in filesystem paths

[dmsimard]

Noticed when running ansible integration tests:

+ ansible-playbook test_connection.yml -i ../connection_paramiko_ssh/test_connection.inventory -e target_hosts=paramiko_ssh -e action_prefix= -e local_tmp=/tmp/ansible-local -e remote_tmp=/tmp/ansible-remote
Failed to post on /api/v1/playbooks: {'ansible_version': '2.9.0.dev0', 'arguments': {'version': None, 'verbosity': 0, 'ask_pass': False, 'private_key_file': None, 'remote_user': None, 'connection': 'smart', 'timeout': 10, 'ssh_common_args': '', 'sftp_extra_args': '', 'scp_extra_args': '', 'ssh_extra_args': '', 'force_handlers': True, 'flush_cache': False, 'become': False, 'become_method': 'sudo', 'become_user': None, 'become_ask_pass': False, 'tags': ('all',), 'skip_tags': (), 'check': False, 'syntax': False, 'diff': False, 'inventory': ('/root/.ansible/test/tmp/connection_paramiko_ssh-dd2zu_78-\xc5\xd1\u015a\xcc\u03b2\u0141\xc8/test/integration/targets/connection_paramiko_ssh/test_connection.inventory',), 'listhosts': False, 'subset': None, 'extra_vars': "Not saved by ARA as configured by 'ignored_arguments'", 'vault_ids': (), 'ask_vault_pass': False, 'vault_password_files': (), 'forks': 5, 'module_path': None, 'listtasks': False, 'listtags': False, 'step': False, 'start_at_task': None, 'args': ('test_connection.yml',)}, 'status': 'running', 'path': '/root/.ansible/test/tmp/connection_paramiko_ssh-dd2zu_78-\udcc3\udc85\udcc3\udc91\udcc5\udc9a\udcc3\udc8c\udcce\udcb2\udcc5\udc81\udcc3\udc88/test/integration/targets/connection/test_connection.yml'}
Failed to post on /api/v1/playbooks: {'ansible_version': '2.9.0.dev0', 'arguments': {'version': None, 'verbosity': 0, 'ask_pass': False, 'private_key_file': None, 'remote_user': None, 'connection': 'smart', 'timeout': 10, 'ssh_common_args': '', 'sftp_extra_args': '', 'scp_extra_args': '', 'ssh_extra_args': '', 'force_handlers': True, 'flush_cache': False, 'become': False, 'become_method': 'sudo', 'become_user': None, 'become_ask_pass': False, 'tags': ('all',), 'skip_tags': (), 'check': False, 'syntax': False, 'diff': False, 'inventory': ('/root/.ansible/test/tmp/connection_paramiko_ssh-dd2zu_78-\xc5\xd1\u015a\xcc\u03b2\u0141\xc8/test/integration/targets/connection_paramiko_ssh/test_connection.inventory',), 'listhosts': False, 'subset': None, 'extra_vars': "Not saved by ARA as configured by 'ignored_arguments'", 'vault_ids': (), 'ask_vault_pass': False, 'vault_password_files': (), 'forks': 5, 'module_path': None, 'listtasks': False, 'listtags': False, 'step': False, 'start_at_task': None, 'args': ('test_connection.yml',)}, 'status': 'running', 'path': '/root/.ansible/test/tmp/connection_paramiko_ssh-dd2zu_78-\udcc3\udc85\udcc3\udc91\udcc5\udc9a\udcc3\udc8c\udcce\udcb2\udcc5\udc81\udcc3\udc88/test/integration/targets/connection/test_connection.yml'}
 [WARNING]: Failure using method (v2_playbook_on_start) in callback plugin
(<ansible.plugins.callback./usr/local/lib/python3.6/dist-
packages/ara/plugins/callback/ara_default.CallbackModule object at
0x7f0c8a53f048>): Expecting value: line 1 column 1 (char 0)

PLAY [paramiko_ssh] ************************************************************
 [WARNING]: Failure using method (v2_playbook_on_play_start) in callback plugin
(<ansible.plugins.callback./usr/local/lib/python3.6/dist-
packages/ara/plugins/callback/ara_default.CallbackModule object at
0x7f0c8a53f048>): 'ascii' codec can't encode characters in position 57-63:
ordinal not in range(128)

2019-05-23 23:07:33,671 ERROR django.request: Internal Server Error: /api/v1/playbooks
Traceback (most recent call last):
  File "/root/virtualenv/lib64/python3.7/site-packages/django/core/handlers/exception.py", line 34, in inner
    response = get_response(request)
  File "/root/virtualenv/lib64/python3.7/site-packages/django/core/handlers/base.py", line 115, in _get_response
    response = self.process_exception_by_middleware(e, request)
  File "/root/virtualenv/lib64/python3.7/site-packages/django/core/handlers/base.py", line 113, in _get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "/root/virtualenv/lib64/python3.7/site-packages/django/views/decorators/csrf.py", line 54, in wrapped_view
    return view_func(*args, **kwargs)
  File "/root/virtualenv/lib64/python3.7/site-packages/rest_framework/viewsets.py", line 116, in view
    return self.dispatch(request, *args, **kwargs)
  File "/root/virtualenv/lib64/python3.7/site-packages/rest_framework/views.py", line 495, in dispatch
    response = self.handle_exception(exc)
  File "/root/virtualenv/lib64/python3.7/site-packages/rest_framework/views.py", line 455, in handle_exception
    self.raise_uncaught_exception(exc)
  File "/root/virtualenv/lib64/python3.7/site-packages/rest_framework/views.py", line 492, in dispatch
    response = handler(request, *args, **kwargs)
  File "/root/virtualenv/lib64/python3.7/site-packages/rest_framework/mixins.py", line 21, in create
    self.perform_create(serializer)
  File "/root/virtualenv/lib64/python3.7/site-packages/rest_framework/mixins.py", line 26, in perform_create
    serializer.save()
  File "/root/virtualenv/lib64/python3.7/site-packages/rest_framework/serializers.py", line 214, in save
    self.instance = self.create(validated_data)
  File "/root/virtualenv/lib64/python3.7/site-packages/rest_framework/serializers.py", line 943, in create
    instance = ModelClass._default_manager.create(**validated_data)
  File "/root/virtualenv/lib64/python3.7/site-packages/django/db/models/manager.py", line 82, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/root/virtualenv/lib64/python3.7/site-packages/django/db/models/query.py", line 422, in create
    obj.save(force_insert=True, using=self.db)
  File "/root/virtualenv/lib64/python3.7/site-packages/django/db/models/base.py", line 741, in save
    force_update=force_update, update_fields=update_fields)
  File "/root/virtualenv/lib64/python3.7/site-packages/django/db/models/base.py", line 779, in save_base
    force_update, using, update_fields,
  File "/root/virtualenv/lib64/python3.7/site-packages/django/db/models/base.py", line 870, in _save_table
    result = self._do_insert(cls._base_manager, using, fields, update_pk, raw)
  File "/root/virtualenv/lib64/python3.7/site-packages/django/db/models/base.py", line 908, in _do_insert
    using=using, raw=raw)
  File "/root/virtualenv/lib64/python3.7/site-packages/django/db/models/manager.py", line 82, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/root/virtualenv/lib64/python3.7/site-packages/django/db/models/query.py", line 1186, in _insert
    return query.get_compiler(using=using).execute_sql(return_id)
  File "/root/virtualenv/lib64/python3.7/site-packages/django/db/models/sql/compiler.py", line 1335, in execute_sql
    cursor.execute(sql, params)
  File "/root/virtualenv/lib64/python3.7/site-packages/django/db/backends/utils.py", line 67, in execute
    return self._execute_with_wrappers(sql, params, many=False, executor=self._execute)
  File "/root/virtualenv/lib64/python3.7/site-packages/django/db/backends/utils.py", line 76, in _execute_with_wrappers
    return executor(sql, params, many, context)
  File "/root/virtualenv/lib64/python3.7/site-packages/django/db/backends/utils.py", line 84, in _execute
    return self.cursor.execute(sql, params)
  File "/root/virtualenv/lib64/python3.7/site-packages/django/db/backends/sqlite3/base.py", line 383, in execute
    return Database.Cursor.execute(self, query, params)
UnicodeEncodeError: 'utf-8' codec can't encode characters in position 48-61: surrogates not allowed
[23/May/2019 23:07:33] "POST /api/v1/playbooks HTTP/1.1" 500 27

[dmsimard]

It's likely that 0.x has a similar issue, @pabelanger shared this trace:

2019-06-13 14:15:12.491754 | TASK [Generate ARA HTML output]
[2019-06-13 14:15:21,132] ERROR in app: Exception on /result/e7ea405b-e824-4969-995f-45207985e7e7/ [GET]
Traceback (most recent call last):
  File "/home/zuul/src/github.com/ansible/ansible-zuul-jobs/.tox/venv/lib/python3.6/site-packages/flask/app.py", line 2311, in wsgi_app
    response = self.full_dispatch_request()
  File "/home/zuul/src/github.com/ansible/ansible-zuul-jobs/.tox/venv/lib/python3.6/site-packages/flask/app.py", line 1835, in full_dispatch_request
    return self.finalize_request(rv)
  File "/home/zuul/src/github.com/ansible/ansible-zuul-jobs/.tox/venv/lib/python3.6/site-packages/flask/app.py", line 1850, in finalize_request
    response = self.make_response(rv)
  File "/home/zuul/src/github.com/ansible/ansible-zuul-jobs/.tox/venv/lib/python3.6/site-packages/flask/app.py", line 1987, in make_response
    rv = self.response_class(rv, status=status, headers=headers)
  File "/home/zuul/src/github.com/ansible/ansible-zuul-jobs/.tox/venv/lib/python3.6/site-packages/werkzeug/wrappers/base_response.py", line 212, in __init__
    self.set_data(response)
  File "/home/zuul/src/github.com/ansible/ansible-zuul-jobs/.tox/venv/lib/python3.6/site-packages/werkzeug/wrappers/base_response.py", line 353, in set_data
    value = value.encode(self.charset)
UnicodeEncodeError: 'utf-8' codec can't encode character '\udcd2' in position 11126: surrogates not allowed
Exception on /result/e7ea405b-e824-4969-995f-45207985e7e7/ [GET]
Traceback (most recent call last):
  File "/home/zuul/src/github.com/ansible/ansible-zuul-jobs/.tox/venv/lib/python3.6/site-packages/flask/app.py", line 2311, in wsgi_app
    response = self.full_dispatch_request()
  File "/home/zuul/src/github.com/ansible/ansible-zuul-jobs/.tox/venv/lib/python3.6/site-packages/flask/app.py", line 1835, in full_dispatch_request
    return self.finalize_request(rv)
  File "/home/zuul/src/github.com/ansible/ansible-zuul-jobs/.tox/venv/lib/python3.6/site-packages/flask/app.py", line 1850, in finalize_request
    response = self.make_response(rv)
  File "/home/zuul/src/github.com/ansible/ansible-zuul-jobs/.tox/venv/lib/python3.6/site-packages/flask/app.py", line 1987, in make_response
    rv = self.response_class(rv, status=status, headers=headers)
  File "/home/zuul/src/github.com/ansible/ansible-zuul-jobs/.tox/venv/lib/python3.6/site-packages/werkzeug/wrappers/base_response.py", line 212, in __init__
    self.set_data(response)
  File "/home/zuul/src/github.com/ansible/ansible-zuul-jobs/.tox/venv/lib/python3.6/site-packages/werkzeug/wrappers/base_response.py", line 353, in set_data
    value = value.encode(self.charset)
UnicodeEncodeError: 'utf-8' codec can't encode character '\udcd2' in position 11126: surrogates not allowed
ERROR
{
  "delta": "0:00:08.167555",
  "end": "2019-06-13 14:15:21.248915",
  "msg": "non-zero return code",
  "rc": 1,
  "start": "2019-06-13 14:15:13.081360"
}

[pabelanger]

I don't mind looking into this, do you have a general idea where I would focus on?

[dmsimard]

@pabelanger The failure case for 0.x is different than the one from 1.x. In 0.x, the data is saved properly to the database by the callback and you get the error when doing the html generation. This means you'd be able to reproduce this exception when running the web application off of the database.

The trace is occuring on a specific result /result/e7ea405b-e824-4969-995f-45207985e7e7/ which is routed here: https://github.com/ansible-community/ara/blob/474e83710c0c5429fd1ef520884af6890bc04cda/ara/views/result.py#L47-L53

The template used to render that is here: https://github.com/ansible-community/ara/blob/stable/0.x/ara/templates/task_result.html

This is where the files are saved by the callback: https://github.com/ansible-community/ara/blob/474e83710c0c5429fd1ef520884af6890bc04cda/ara/plugins/callbacks/log_ara.py#L108-L136

[pabelanger]

That is indeed helpful, so my first step here, is to start collecting the ara.sqlite file, so we have something to reproduce with.

[berendt]

PLAY [Run preparations] *****************************************************************************************************************************************************************************************************************
 [WARNING]: Failure using method (v2_playbook_on_play_start) in callback plugin (<ansible.plugins.callback./usr/local/lib/python3.6/dist-packages/ara/plugins/callback/ara_default.CallbackModule object at 0x7f5f510f0e10>): 'ascii'
codec can't decode byte 0xc3 in position 28: ordinal not in range(128)

This failed not because of the filename but because of the content of the file.

In this example, a metafile of a role with the following content is read. This will cause it to fail.

---
galaxy_info:
  author: Sébastien Han
[...]

The affected method appears to be _get_or_create_file in plugins/callback/ara_default.py.

[berendt]

It was tested with the current version of ARA 1.1.0 with Ansible 2.6 and Python 3.6.8.

[dmsimard]

@berendt thanks! We actually try to test for this in the integration tests: https://github.com/ansible-community/ara/blob/a0cf0cb8371aa7f6071a9a35e8d1bf5c7c9551c7/tests/integration/smoke.yaml#L53-L66

As far as the tests go, that particular file is saved properly in:

• 2.8: https://8fb6a822ac8726bcc0af-1f01c4de10139c366cbd7ac49c7ab3d8.ssl.cf1.rackcdn.com/691260/1/check/ansible-role-ara-api-fedora-2.8/e363d60/logs/static/file/1.html
• 2.7: https://9e9c4a0b77badcd04222-fa9050fbccbc1b8e2fcd252255e35175.ssl.cf5.rackcdn.com/691260/1/check/ansible-role-ara-api-ubuntu-2.7/e39f2fd/logs/static/file/1.html
• 2.6: https://c15d161aa166386e5680-f95fc25bff3a61ae232d3b95f165c0d8.ssl.cf1.rackcdn.com/691260/1/check/ansible-role-ara-api-ubuntu-2.6/c508bb7/logs/static/file/1.html

I don't know what could be causing this yet and I don't think there's anything in the upcoming release of 1.2 that would help with this. Do you get any hints if you turn up the verbosity ? For example:

• export ARA_DEBUG=true; export ARA_LOG_LEVEL=DEBUG
• ansible-playbook -vvv

The full stack trace could be helpful.

[berendt]

I suspect rather an encoding problem of the file itself. Take a look at it. But this is not a blocker for a release.

[dmsimard]

Not fixed in 1.0 despite adding an integration test (that hasn't failed?)

2019-11-18 20:58:54,224 ERROR django.request: Internal Server Error: /api/v1/results
Traceback (most recent call last):
  File "/tmp/zuul/lib64/python3.6/site-packages/django/core/handlers/exception.py", line 34, in inner
    response = get_response(request)
  File "/tmp/zuul/lib64/python3.6/site-packages/django/core/handlers/base.py", line 145, in _get_response
    response = self.process_exception_by_middleware(e, request)
  File "/tmp/zuul/lib64/python3.6/site-packages/django/core/handlers/base.py", line 143, in _get_response
    response = response.render()
  File "/tmp/zuul/lib64/python3.6/site-packages/django/template/response.py", line 106, in render
    self.content = self.rendered_content
  File "/tmp/zuul/lib64/python3.6/site-packages/rest_framework/response.py", line 70, in rendered_content
    ret = renderer.render(self.data, accepted_media_type, context)
  File "/tmp/zuul/lib64/python3.6/site-packages/rest_framework/renderers.py", line 111, in render
    return ret.encode()
UnicodeEncodeError: 'utf-8' codec can't encode character '\udc80' in position 467: surrogates not allowed
2019-11-18 20:58:54,240 ERROR ara.clients.http: Failed to post on /api/v1/results: {'playbook': 7, 'task': 165, 'host': 11, 'play': 15, 'content': {'changed': False, 'cmd': ['echo', '-e', '\\x80abc'], 'delta': '0:00:00.001269', 'end': '2019-11-18 20:58:54.183919', 'invocation': {'module_args': {'_raw_params': "echo -e '\\x80abc'", '_uses_shell': False, 'argv': None, 'chdir': None, 'creates': None, 'executable': None, 'removes': None, 'stdin': None, 'stdin_add_newline': True, 'strip_empty_ends': True, 'warn': True}}, 'rc': 0, 'start': '2019-11-18 20:58:54.182650', 'stderr': '', 'stderr_lines': [], 'stdout': '\udc80abc', 'stdout_lines': ['\udc80abc']}, 'status': 'ok', 'started': '2019-11-18T20:58:53.816646-05:00', 'ended': '2019-11-18T20:58:54.200620', 'changed': False, 'ignore_errors': False}
2019-11-18 20:58:54,241 ERROR ara.clients.http: Failed to post on /api/v1/results: {'playbook': 7, 'task': 165, 'host': 11, 'play': 15, 'content': {'changed': False, 'cmd': ['echo', '-e', '\\x80abc'], 'delta': '0:00:00.001269', 'end': '2019-11-18 20:58:54.183919', 'invocation': {'module_args': {'_raw_params': "echo -e '\\x80abc'", '_uses_shell': False, 'argv': None, 'chdir': None, 'creates': None, 'executable': None, 'removes': None, 'stdin': None, 'stdin_add_newline': True, 'strip_empty_ends': True, 'warn': True}}, 'rc': 0, 'start': '2019-11-18 20:58:54.182650', 'stderr': '', 'stderr_lines': [], 'stdout': '\udc80abc', 'stdout_lines': ['\udc80abc']}, 'status': 'ok', 'started': '2019-11-18T20:58:53.816646-05:00', 'ended': '2019-11-18T20:58:54.200620', 'changed': False, 'ignore_errors': False}
[WARNING]: Failure using method (v2_runner_on_ok) in callback plugin (<ansible.plugins.callback./tmp/zuul/lib/python3.6/site-packages/ara/plugins/callback/ara_default.CallbackModule object at 0x7fdb47b02f98>): Expecting value: line 1 column 1 (char 0)

Callback Exception: 
  File "/tmp/zuul/lib64/python3.6/site-packages/ansible/executor/task_queue_manager.py", line 333, in send_callback
    method(*new_args, **kwargs)
   File "/tmp/zuul/lib/python3.6/site-packages/ara/plugins/callback/ara_default.py", line 246, in v2_runner_on_ok
    self._load_result(result, "ok", **kwargs)
   File "/tmp/zuul/lib/python3.6/site-packages/ara/plugins/callback/ara_default.py", line 358, in _load_result
    ignore_errors=kwargs.get("ignore_errors", False) or False,
   File "/tmp/zuul/lib64/python3.6/site-packages/ara/clients/http.py", line 108, in post
    return self._request("post", endpoint, **kwargs)
   File "/tmp/zuul/lib64/python3.6/site-packages/ara/clients/http.py", line 99, in _request
    return response.json()
   File "/tmp/zuul/lib64/python3.6/site-packages/requests/models.py", line 897, in json
    return complexjson.loads(self.text, **kwargs)
   File "/usr/lib64/python3.6/json/__init__.py", line 354, in loads
    return _default_decoder.decode(s)
   File "/usr/lib64/python3.6/json/decoder.py", line 339, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
   File "/usr/lib64/python3.6/json/decoder.py", line 357, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None

[berendt]

@dmsimard Think this is different. Not general UTF-8.

surrogates not allowed

Stackoverflow means you should try decode('utf8', 'surrogateescape').

[dmsimard]

@berendt yes, you're right. It was getting late and I wanted to keep a note of that trace :) I might end up splitting that into another issue.

The problem for decoding results specifically is that they are often nested in lists or dictionaries. Going through each list item and dictionary key to decode them could be expensive. I need to spend some time on this -- maybe we can get away by decoding the json string like in https://stackoverflow.com/a/18337754/6072068.

[adaemmer]

maybe not a fix, but a "works for me"

--- ara_default.py      2022-10-14 14:18:19.102689775 +0000
+++ ara_default.py        2022-10-14 14:22:51.006757559 +0000
@@ -526,7 +526,7 @@
                    content = "Not saved by ARA as configured by 'ignored_files'"
            if content is None:
                try:
-                    with open(path, "r") as fd:
+                    with open(path, "rU", encoding="utf-8") as fd:
                        content = fd.read()
                except IOError as e:
                    self.log.error("Unable to open {0} for reading: {1}".format(path, str(e)))

on version 1.5.8