ara icon indicating copy to clipboard operation
ara copied to clipboard

ara_record fails to decrypt SSL on https endpoint GET /api/v1/results

Open djangoxv opened this issue 4 years ago • 9 comments

The ara_record module seems to have an issue instantiating the results api

Ansible 2.9.1, python 3.6.1, ara and ara[server] 1.3.0 I run the API server in django using nginx proxy+uwsgi on Debian bare metal

I am using a simple playbook to record the local branch

  hosts: 127.0.0.1
  connection: local
  become: no
  vars:
    ara_playbook_name: ara-record
  tasks:
    - name: Lookup local git branch
      command: "git rev-parse --abbrev-ref HEAD"
      register: git_branch
      changed_when: false
      check_mode: no

    - name: Record git branch in ARA
      ara_record:
        key: "active_git_branch"
        value: "{{ git_branch.stdout }}"
      ignore_errors: "{{ ansible_check_mode }}"

This works, tested in 1.2.0 and 1.30 - so thank you - we still can record our git branch

But there is a PYTHON_WARNING thrown on SSL decryption:

TASK [Record git branch in ARA] ****************************************************************************************************
task path: /ansible_2.9.1/playbooks/ara-record.yml:19
changed: [127.0.0.1] => {
    "changed": true,
    "created": "2019-12-07T14:28:50.050584-08:00",
    "key": "active_git_branch",
    "msg": "Record created or updated in ARA",
    "playbook_id": 100,
    "type": "text",
    "updated": "2019-12-07T14:28:50.050629-08:00",
    "value": "master"
}
[WARNING]: Failure using method (v2_runner_on_ok) in callback plugin (<ansible.plugins.callback.ara_default.CallbackModule object
at 0x7fa429e70ef0>): HTTPSConnectionPool(host='verified.site.com', port=443): Max retries exceeded with url: /api/v1/results
(Caused by SSLError(SSLError(1, '[SSL: DECRYPTION_FAILED_OR_BAD_RECORD_MAC] decryption failed or bad record mac (_ssl.c:2178)'),))

Callback Exception:
  File "/ansible_2.9.1/venv/lib/python3.6/site-packages/ansible/executor/task_queue_manager.py", line 323, in send_callback
    method(*new_args, **kwargs)
   File "/ansible_2.9.1/venv/lib/python3.6/site-packages/ara/plugins/callback/ara_default.py", line 261, in v2_runner_on_ok
    self._load_result(result, "ok", **kwargs)
   File "/ansible_2.9.1/venv/lib/python3.6/site-packages/ara/plugins/callback/ara_default.py", line 373, in _load_result
    ignore_errors=kwargs.get("ignore_errors", False) or False,
   File "/ansible_2.9.1/venv/lib/python3.6/site-packages/ara/clients/http.py", line 115, in post
    return self._request("post", endpoint, **kwargs)
   File "/ansible_2.9.1/venv/lib/python3.6/site-packages/ara/clients/http.py", line 93, in _request
    response = func(url, **kwargs)
   File "/ansible_2.9.1/venv/lib/python3.6/site-packages/ara/clients/http.py", line 69, in post
    return self._request("post", url, data=json.dumps(payload))
   File "/ansible_2.9.1/venv/lib/python3.6/site-packages/ara/clients/http.py", line 57, in _request
    return self.http.request(method, self.endpoint + url, timeout=self.timeout, **payload)
   File "/ansible_2.9.1/venv/lib/python3.6/site-packages/requests/sessions.py", line 533, in request
    resp = self.send(prep, **send_kwargs)
   File "/ansible_2.9.1/venv/lib/python3.6/site-packages/requests/sessions.py", line 646, in send
    r = adapter.send(request, **kwargs)
   File "/ansible_2.9.1/venv/lib/python3.6/site-packages/requests/adapters.py", line 514, in send
    raise SSLError(e, request=request)

I assume something is lost here, but whatever is lost by not grabbing /api/v1/results

Thanks! P.S. Keep on doing ARA up... glad to see so much movement since 1.x

djangoxv avatar Dec 07 '19 22:12 djangoxv

Haven't looked at this issue yet but wanted to point out that I've been seeing it as well:

TASK [smoke-tests : Record data with no type] **********************************
task path: /home/zuul/src/opendev.org/recordsansible/ara/tests/integration/roles/smoke-tests/tasks/ara-ops.yaml:30
changed: [localhost] => {
    "changed": true,
    "created": "2020-01-30T00:15:25.989098Z",
    "key": "notype",
    "msg": "Record created or updated in ARA",
    "playbook_id": 6,
    "type": "text",
    "updated": "2020-01-30T00:15:25.989138Z",
    "value": "text"
}
[WARNING]: Failure using method (v2_runner_on_ok) in callback plugin
(<ansible.plugins.callback.ara_default.CallbackModule object at
0x7fac33c8f910>): HTTPSConnectionPool(host='api.demo.recordsansible.org',
port=443): Max retries exceeded with url: /api/v1/results (Caused by
SSLError(SSLError(1, '[SSL: DECRYPTION_FAILED_OR_BAD_RECORD_MAC] decryption
failed or bad record mac (_ssl.c:2508)')))
Callback Exception: 
  File "/home/zuul/.ara-tests/virtualenv/lib64/python3.7/site-packages/ansible/executor/task_queue_manager.py", line 324, in send_callback
    method(*new_args, **kwargs)
   File "/home/zuul/.ara-tests/virtualenv/lib/python3.7/site-packages/ara/plugins/callback/ara_default.py", line 283, in v2_runner_on_ok
    self._load_result(result, "ok", **kwargs)
   File "/home/zuul/.ara-tests/virtualenv/lib/python3.7/site-packages/ara/plugins/callback/ara_default.py", line 395, in _load_result
    ignore_errors=kwargs.get("ignore_errors", False) or False,
   File "/home/zuul/.ara-tests/virtualenv/lib64/python3.7/site-packages/ara/clients/http.py", line 115, in post
    return self._request("post", endpoint, **kwargs)
   File "/home/zuul/.ara-tests/virtualenv/lib64/python3.7/site-packages/ara/clients/http.py", line 93, in _request
    response = func(url, **kwargs)
   File "/home/zuul/.ara-tests/virtualenv/lib64/python3.7/site-packages/ara/clients/http.py", line 69, in post
    return self._request("post", url, data=json.dumps(payload))
   File "/home/zuul/.ara-tests/virtualenv/lib64/python3.7/site-packages/ara/clients/http.py", line 57, in _request
    return self.http.request(method, self.endpoint + url, timeout=self.timeout, **payload)
   File "/home/zuul/.ara-tests/virtualenv/lib64/python3.7/site-packages/requests/sessions.py", line 533, in request
    resp = self.send(prep, **send_kwargs)
   File "/home/zuul/.ara-tests/virtualenv/lib64/python3.7/site-packages/requests/sessions.py", line 646, in send
    r = adapter.send(request, **kwargs)
   File "/home/zuul/.ara-tests/virtualenv/lib64/python3.7/site-packages/requests/adapters.py", line 514, in send
    raise SSLError(e, request=request)

dmsimard avatar Jan 30 '20 00:01 dmsimard

I've investigated this a bit but haven't found the root cause yet. It looks like perhaps there could be something wrong with our usage of weakref for re-using the client instance ?

tl;dr:

  1. Client sends POST requests to create the playbook, the play, the task without issues
  2. Client sends POST request to create a record from ara_record without issues
  3. After the ara_record task, the callback gets a SSLError exception when trying to POST the result of the task

The relevant order of events:

  1. callback creates a new http client instance: https://github.com/ansible-community/ara/blob/b1e450b9bd77609c741e4bd667b2fd4f9c5e8e25/ara/plugins/callback/ara_default.py#L187-L194
  2. v2_playbook_on_start runs fine: https://github.com/ansible-community/ara/blob/b1e450b9bd77609c741e4bd667b2fd4f9c5e8e25/ara/plugins/callback/ara_default.py#L196
  3. v2_playbook_on_play_start runs fine: https://github.com/ansible-community/ara/blob/b1e450b9bd77609c741e4bd667b2fd4f9c5e8e25/ara/plugins/callback/ara_default.py#L221
  4. v2_playbook_on_task_start runs fine: https://github.com/ansible-community/ara/blob/b1e450b9bd77609c741e4bd667b2fd4f9c5e8e25/ara/plugins/callback/ara_default.py#L261
  5. the task started is an ara_record task
  6. ara_record recovers the active client instance through weakref: https://github.com/ansible-community/ara/blob/b1e450b9bd77609c741e4bd667b2fd4f9c5e8e25/ara/plugins/action/ara_record.py#L143
  7. ara_record uses client.post to create the new key/value: https://github.com/ansible-community/ara/blob/b1e450b9bd77609c741e4bd667b2fd4f9c5e8e25/ara/plugins/action/ara_record.py#L150
  8. the task completes successfully, invoking v2_runner_on_ok
  9. v2_runner_on_ok raises an SSLError exception when doing a post for the result of the task: https://github.com/ansible-community/ara/blob/b1e450b9bd77609c741e4bd667b2fd4f9c5e8e25/ara/plugins/callback/ara_default.py#L402
  10. The remainder of the playbook runs fine and is recorded properly (aside from the results of ara_record tasks)

dmsimard avatar Feb 04 '20 20:02 dmsimard

Yeah, the issue has something to do with passing the instance weakref back and forth.

If I revert the patch that introduced the weakref, I am unable to reproduce the issue.

dmsimard avatar Feb 04 '20 20:02 dmsimard

I haven't found a definitive fix for this yet and it didn't warrant blocking the release of 1.4, we can fix it in an upcoming dot release.

dmsimard avatar Apr 15 '20 20:04 dmsimard

I haven't revisited this issue in a long time but perhaps this PR could fix it: https://github.com/ansible-community/ara/pull/274

dmsimard avatar May 05 '21 14:05 dmsimard

Hi @dmsimard,

funny, I had exactly that error today when I used lookup('ara_api', '/api/') in a run with more than one host. The solution was to set run_once: true, thus also what you are doing in your PR.

hille721 avatar May 05 '21 20:05 hille721

I still need to analyze it, but I ran it with ANSIBLE_DEBUG=1

TASK [Record in ARA] ************************************************************************************************
task path: /opt/ansible/projects/element-networks/playbooks/.480262.main.yml:19
480273 1635264143.62403: sending task start callback
480273 1635264143.62406: entering _queue_task() for aptproxy.nc.element-networks.nl/ara_record
480273 1635264143.62408: Creating lock for ara_record
480273 1635264143.62597: worker is 2 (out of 3 available)
480273 1635264143.62613: exiting _queue_task() for aptproxy.nc.element-networks.nl/ara_record
480273 1635264143.62615: done queuing things up, now waiting for results queue to drain
480273 1635264143.62616: waiting for pending results...
480313 1635264143.62727: running TaskExecutor() for aptproxy.nc.element-networks.nl/TASK: Record in ARA
480313 1635264143.62760: in run() - task 4abf3276-fafa-b41d-0aaa-00000000004b
480313 1635264143.62772: variable 'ansible_search_path' from source: unknown
480313 1635264143.62790: variable '_ansible_loop_cache' from source: unknown
480313 1635264143.62792: calling self._execute()
480313 1635264143.62824: variable 'ansible_delegated_vars' from source: unknown
480313 1635264143.62831: variable 'ansible_connection' from source: host vars for 'localhost'
480313 1635264143.62837: no remote address found for delegated host localhost
using its name, so success depends on DNS resolution
480313 1635264143.62849: variable 'omit' from source: magic vars
480313 1635264143.62901: variable 'omit' from source: magic vars
480313 1635264143.62915: variable 'omit' from source: magic vars
480313 1635264143.63029: variable 'ansible_role_versions' from source: set_fact
480313 1635264143.63066: variable 'ansible_delegated_vars' from source: unknown
480313 1635264143.63072: variable 'ansible_connection' from source: host vars for 'localhost'
480313 1635264143.63077: variable 'ansible_connection' from source: host vars for 'localhost'
480313 1635264143.63100: trying /usr/lib/python3/dist-packages/ansible/plugins/connection
480313 1635264143.63121: Loading Connection 'local' from /usr/lib/python3/dist-packages/ansible/plugins/connection/local.py (found_in_cache=True, class_only=False)
480313 1635264143.63135: trying /usr/lib/python3/dist-packages/ansible/plugins/shell
480313 1635264143.63150: Loading ShellModule 'sh' from /usr/lib/python3/dist-packages/ansible/plugins/shell/sh.py (found_in_cache=True, class_only=False)
480313 1635264143.63160: Loading ShellModule 'sh' from /usr/lib/python3/dist-packages/ansible/plugins/shell/sh.py (found_in_cache=True, class_only=False)
480313 1635264143.63205: Loading ActionModule 'ara_record' from /opt/ansible/projects/element-networks/library/action/ara_record.py (searched paths: /usr/lib/python3/dist-packages/ansible/plugins/action:/opt/ansible/projects/element-networks/library/action/__pycache__:/opt/ansible/projects/element-networks/library/action) (found_in_cache=True, class_only=False)
480313 1635264143.63216: variable 'omit' from source: magic vars
480313 1635264143.63226: starting attempt loop
480313 1635264143.63232: running the handler
480313 1635264143.65157: handler run complete
480313 1635264143.65172: Evaluated conditional (False): False
480313 1635264143.65180: variable 'ansible_host' from source: unknown
480313 1635264143.65186: variable 'ansible_port' from source: unknown
480313 1635264143.65193: variable 'ansible_user' from source: unknown
480313 1635264143.65199: variable 'ansible_connection' from source: host vars for 'localhost'
480313 1635264143.65205: attempt loop complete, returning result
480313 1635264143.65211: _execute() done
480313 1635264143.65214: dumping result to json
480313 1635264143.65224: done dumping result, returning
480313 1635264143.65234: done running TaskExecutor() for aptproxy.nc.element-networks.nl/TASK: Record in ARA [4abf3276-fafa-b41d-0aaa-00000000004b]
480313 1635264143.65240: sending task result for task 4abf3276-fafa-b41d-0aaa-00000000004b
480313 1635264143.65277: done sending task result for task 4abf3276-fafa-b41d-0aaa-00000000004b
480313 1635264143.65300: WORKER PROCESS EXITING
ok: [aptproxy.nc.element-networks.nl -> localhost] => changed=false 
  created: '2021-10-26T18:02:23.647591+02:00'
  key: ansible_role_versions
  msg: Record created or updated in ARA
  playbook_id: 1953
  type: text
  updated: '2021-10-26T18:02:23.647610+02:00'
  value: |-
    480305 1635264142.78273: starting run
    480305 1635264143.09209: Validate TLS certificates for https://galaxy.ansible.com: True
    # /opt/ansible/projects/element-networks/roles
    480305 1635264143.47176: Validate TLS certificates: True
    480305 1635264143.47192: Validate TLS certificates: True
    - motd, 1.1.3
    480305 1635264143.47407: Validate TLS certificates: True
    - subscription_manager, 1.2.2
    480305 1635264143.47585: Validate TLS certificates: True
    - sshd, 2.5.3
    480305 1635264143.47775: Validate TLS certificates: True
    - odoo, (unknown version)
    480305 1635264143.47932: Validate TLS certificates: True
    480305 1635264143.47940: Validate TLS certificates: True
    - docker_services, master
    480305 1635264143.48176: Validate TLS certificates: True
    - pip, 2.0.0
    480305 1635264143.48444: Validate TLS certificates: True
    - nullmailer, 1.1.0
    480305 1635264143.48636: Validate TLS certificates: True
    - ldap, 2.2.2
    480305 1635264143.48879: Validate TLS certificates: True
    - dns_server, 3.3.1
    480305 1635264143.49051: Validate TLS certificates: True
    - apt, 1.8.0
    480305 1635264143.49269: Validate TLS certificates: True
    - zabbix_agent, 1.6.0
    480305 1635264143.49495: Validate TLS certificates: True
    480305 1635264143.49503: Validate TLS certificates: True
    - proxmox_setup, (unknown version)
    480305 1635264143.49676: Validate TLS certificates: True
    - branding, 1.0.0
    480305 1635264143.49849: Validate TLS certificates: True
    - acme_ssl, 3.7.1
    480305 1635264143.50084: Validate TLS certificates: True
    - ansible_controller, 1.4.3
    480305 1635264143.50314: Validate TLS certificates: True
    - docker, 2.8.1
    480305 1635264143.50591: Validate TLS certificates: True
    - wireguard, 2.1.3
    480305 1635264143.50762: Validate TLS certificates: True
    - nginx_revproxy, 2.0.0
    480305 1635264143.50969: Validate TLS certificates: True
    - postgresql, 3.1.1
[WARNING]: Failure using method (v2_runner_on_ok) in callback plugin
(<ansible.plugins.callback.ara_default.CallbackModule object at 0x7fb967d9f6d0>):
HTTPSConnectionPool(host='ara.zm1.element-networks.nl', port=443): Max retries exceeded with url: /api/v1/results
(Caused by SSLError(SSLError(1, '[SSL: DECRYPTION_FAILED_OR_BAD_RECORD_MAC] decryption failed or bad record mac
(_ssl.c:2622)')))
Callback Exception: 
  File "/usr/lib/python3/dist-packages/ansible/executor/task_queue_manager.py", line 441, in send_callback
    method(*new_args, **kwargs)
   File "/opt/ansible/projects/element-networks/library/callback/ara_default.py", line 385, in v2_runner_on_ok
    self._submit_thread("task", self._load_result, result, "ok", **kwargs)
   File "/opt/ansible/projects/element-networks/library/callback/ara_default.py", line 249, in _submit_thread
    func(*args, **kwargs)
   File "/opt/ansible/projects/element-networks/library/callback/ara_default.py", line 584, in _load_result
    self.result = self.client.post(
   File "/usr/local/lib/python3.9/dist-packages/ara/clients/http.py", line 115, in post
    return self._request("post", endpoint, **kwargs)
   File "/usr/local/lib/python3.9/dist-packages/ara/clients/http.py", line 93, in _request
    response = func(url, **kwargs)
   File "/usr/local/lib/python3.9/dist-packages/ara/clients/http.py", line 69, in post
    return self._request("post", url, data=json.dumps(payload))
   File "/usr/local/lib/python3.9/dist-packages/ara/clients/http.py", line 57, in _request
    return self.http.request(method, self.endpoint + url, timeout=self.timeout, **payload)
   File "/usr/lib/python3/dist-packages/requests/sessions.py", line 542, in request
    resp = self.send(prep, **send_kwargs)
   File "/usr/lib/python3/dist-packages/requests/sessions.py", line 655, in send
    r = adapter.send(request, **kwargs)
   File "/usr/lib/python3/dist-packages/requests/adapters.py", line 514, in send
    raise SSLError(e, request=request)
480273 1635264143.65894: no more pending results, returning what we have
480273 1635264143.65912: results queue empty
480273 1635264143.65914: checking for any_errors_fatal
480273 1635264143.65918: done checking for any_errors_fatal
480273 1635264143.65919: checking for max_fail_percentage
480273 1635264143.65920: done checking for max_fail_percentage
480273 1635264143.65921: checking to see if all hosts have failed and the running result is not ok
480273 1635264143.65922: done checking to see if all hosts have failed
480273 1635264143.65923: getting the remaining hosts for this loop
480273 1635264143.65925: done getting the remaining hosts for this loop
480273 1635264143.65929: building list of next tasks for hosts
480273 1635264143.65931: getting the next task for host aptproxy.nc.element-networks.nl
480273 1635264143.65934: done getting next task for host aptproxy.nc.element-networks.nl
480273 1635264143.65935:  ^ task is: TASK: Collect git repo version
480273 1635264143.65937:  ^ state is: HOST STATE: block=2, task=3, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
480273 1635264143.65938: getting the next task for host aptproxy.nm.element-networks.nl
480273 1635264143.65940: done getting next task for host aptproxy.nm.element-networks.nl
480273 1635264143.65941:  ^ task is: TASK: Collect git repo version
480273 1635264143.65942:  ^ state is: HOST STATE: block=2, task=3, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
480273 1635264143.65944: getting the next task for host aptproxy.zm1.element-networks.nl
480273 1635264143.65945: done getting next task for host aptproxy.zm1.element-networks.nl
480273 1635264143.65946:  ^ task is: TASK: Collect git repo version
480273 1635264143.65947:  ^ state is: HOST STATE: block=2, task=3, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
480273 1635264143.65948: done building task lists
480273 1635264143.65949: counting tasks in each state of execution
480273 1635264143.65951: done counting tasks in each state of execution:
	num_setups: 0
	num_tasks: 3
	num_rescue: 0
	num_always: 0
480273 1635264143.65952: advancing hosts in ITERATING_TASKS
480273 1635264143.65953: starting to advance hosts
480273 1635264143.65954: getting the next task for host aptproxy.nc.element-networks.nl
480273 1635264143.65955: done getting next task for host aptproxy.nc.element-networks.nl
480273 1635264143.65957:  ^ task is: TASK: Collect git repo version
480273 1635264143.65958:  ^ state is: HOST STATE: block=2, task=3, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
480273 1635264143.65959: getting the next task for host aptproxy.nm.element-networks.nl
480273 1635264143.65961: done getting next task for host aptproxy.nm.element-networks.nl
480273 1635264143.65962:  ^ task is: TASK: Collect git repo version
480273 1635264143.65963:  ^ state is: HOST STATE: block=2, task=3, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
480273 1635264143.65964: getting the next task for host aptproxy.zm1.element-networks.nl
480273 1635264143.65965: done getting next task for host aptproxy.zm1.element-networks.nl
480273 1635264143.65966:  ^ task is: TASK: Collect git repo version
480273 1635264143.65967:  ^ state is: HOST STATE: block=2, task=3, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
480273 1635264143.65968: done advancing hosts to next task
480273 1635264143.65969: getting variables
480273 1635264143.65971: in VariableManager get_vars()
480273 1635264143.65984: Calling all_inventory to load vars for aptproxy.nc.element-networks.nl
480273 1635264143.65987: Calling groups_inventory to load vars for aptproxy.nc.element-networks.nl
480273 1635264143.65990: Calling all_plugins_inventory to load vars for aptproxy.nc.element-networks.nl
480273 1635264143.66005: Loading VarsModule 'host_group_vars' from /usr/lib/python3/dist-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
480273 1635264143.66024: Loading data from /opt/ansible/projects/element-networks/inventory/group_vars/all.yml
480273 1635264143.66028: Calling all_plugins_play to load vars for aptproxy.nc.element-networks.nl
480273 1635264143.66036: Loading VarsModule 'host_group_vars' from /usr/lib/python3/dist-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
480273 1635264143.66048: Calling groups_plugins_inventory to load vars for aptproxy.nc.element-networks.nl
480273 1635264143.66056: Loading VarsModule 'host_group_vars' from /usr/lib/python3/dist-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
480273 1635264143.66067: Loading data from /opt/ansible/projects/element-networks/inventory/group_vars/aptproxies.yml
480273 1635264143.66073: Loading data from /opt/ansible/projects/element-networks/inventory/group_vars/loc_nc.yml
480273 1635264143.66078: Loading data from /opt/ansible/projects/element-networks/inventory/group_vars/proxmox_all_lxc.yml
480273 1635264143.66086: Calling groups_plugins_play to load vars for aptproxy.nc.element-networks.nl
480273 1635264143.66094: Loading VarsModule 'host_group_vars' from /usr/lib/python3/dist-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
480273 1635264143.66124: Loading VarsModule 'host_group_vars' from /usr/lib/python3/dist-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
480273 1635264143.66135: Loading data from /opt/ansible/projects/element-networks/inventory/host_vars/aptproxy.nc.element-networks.nl.yml
480273 1635264143.66144: Loading VarsModule 'host_group_vars' from /usr/lib/python3/dist-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
480273 1635264143.66180: in VariableManager get_vars()
480273 1635264143.66188: Calling all_inventory to load vars for localhost
480273 1635264143.66191: Calling groups_inventory to load vars for localhost
480273 1635264143.66192: Calling all_plugins_inventory to load vars for localhost
480273 1635264143.66201: Loading VarsModule 'host_group_vars' from /usr/lib/python3/dist-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
480273 1635264143.66212: Loading data from /opt/ansible/projects/element-networks/inventory/group_vars/all.yml
480273 1635264143.66216: Calling all_plugins_play to load vars for localhost
480273 1635264143.66224: Loading VarsModule 'host_group_vars' from /usr/lib/python3/dist-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
480273 1635264143.66235: Calling groups_plugins_inventory to load vars for localhost
480273 1635264143.66243: Loading VarsModule 'host_group_vars' from /usr/lib/python3/dist-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
480273 1635264143.66251: Calling groups_plugins_play to load vars for localhost
480273 1635264143.66259: Loading VarsModule 'host_group_vars' from /usr/lib/python3/dist-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
480273 1635264143.66274: Loading VarsModule 'host_group_vars' from /usr/lib/python3/dist-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
480273 1635264143.66291: Loading VarsModule 'host_group_vars' from /usr/lib/python3/dist-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
480273 1635264143.66316: done with get_vars()
480273 1635264143.66319: done with get_vars()
480273 1635264143.66324: done getting variables
480273 1635264143.66367: Loading ActionModule 'command' from /usr/lib/python3/dist-packages/ansible/plugins/action/command.py (searched paths: /usr/lib/python3/dist-packages/ansible/plugins/action:/opt/ansible/projects/element-networks/library/action/__pycache__:/opt/ansible/projects/element-networks/library/action) (found_in_cache=False, class_only=True)
480273 1635264143.66371: sending task start callback, copying the task so we can template it temporarily
480273 1635264143.66372: done copying, going to template now
480273 1635264143.66373: done templating
480273 1635264143.66374: here goes the callback...

Thulium-Drake avatar Oct 26 '21 16:10 Thulium-Drake

FYI - when I updated to 1.5.8 recently I noticed that setting the callback_threads=1 in ansible.cfg solved this issue I suspect when you bump to Django 3 you will find it resolved

djangoxv avatar May 05 '22 23:05 djangoxv

Issue still exists in 1.6.1. With setting callback_threads no exception is comming anymore, but still the results are not stored in Ara. With new tasks page this is good visible:

image

hille721 avatar Mar 14 '23 15:03 hille721