ara_record fails unless you specify run_once and delegate_to localhost

[Alvaro-Campesino]

What is the issue ?

When launching a playbook for logging information in ara_record an error is received stopping the playbook execution:

This is the received error message:

TASK [Define ara values for ara_records] *****************************************************************
task path: /ansible/playbooks/precheck.yml:6
» Friday 01 April 2022  10:52:53 +0000 (0:00:00.568)       0:00:01.563 ******** 
fatal: [kube-node-ey04mxwj]: FAILED! => changed=false 
  msg: 'Record failed to be created or updated in ARA: ''value'''
Failed to post on /api/v1/results: {'playbook': 28, 'task': 7204, 'host': 157, 'delegated_to': [], 'play': 169, 'content': {'changed': False, 'msg': "Record failed to be created or updated in ARA: 'value'"}, 'status': 'failed', 'started': '2022-04-01T10:52:53.987750+00:00', 'ended': '2022-04-01T10:52:54.068562+00:00', 'changed': False, 'ignore_errors': False}
fatal: [kube-node-e14m35zv]: FAILED! => changed=false 
  msg: 'Record failed to be created or updated in ARA: ''key'''
fatal: [kube-control-plane-gx03l92v]: FAILED! => changed=false 
  msg: 'Record failed to be created or updated in ARA: ''count'''
Failed to post on /api/v1/results: {'playbook': 28, 'task': 7204, 'host': 156, 'delegated_to': [], 'play': 169, 'content': {'changed': False, 'msg': "Record failed to be created or updated in ARA: 'count'"}, 'status': 'failed', 'started': '2022-04-01T10:52:53.971039+00:00', 'ended': '2022-04-01T10:52:54.201169+00:00', 'changed': False, 'ignore_errors': False}
The full traceback is:
Traceback (most recent call last):
  File "/usr/lib/python3.9/site-packages/ansible/executor/task_executor.py", line 158, in run
    res = self._execute()
  File "/usr/lib/python3.9/site-packages/ansible/executor/task_executor.py", line 582, in _execute
    result = self._handler.run(task_vars=variables)
  File "/usr/share/ansible/plugins/action/ara_record.py", line 199, in run
    playbook_id = play["results"][0]["playbook"]
KeyError: 'results'
fatal: [kube-node-dz6jnyww]: FAILED! => 
  msg: Unexpected failure during module execution.
  stdout: ''
The full traceback is:
Traceback (most recent call last):
  File "/usr/lib/python3.9/site-packages/ansible/executor/task_executor.py", line 158, in run
    res = self._execute()
  File "/usr/lib/python3.9/site-packages/ansible/executor/task_executor.py", line 582, in _execute
    result = self._handler.run(task_vars=variables)
  File "/usr/share/ansible/plugins/action/ara_record.py", line 199, in run
    playbook_id = play["results"][0]["playbook"]
KeyError: 'results'
fatal: [kube-node-d24n35wq]: FAILED! => 
  msg: Unexpected failure during module execution.
  stdout: ''
fatal: [kube-node-g04l3809]: FAILED! => changed=false 
  msg: 'Record failed to be created or updated in ARA: ''value'''

This is the playbook I am running:

- hosts: all
  tasks:
    - name: Define ara values for ara_records
      ara_record:
        key: "run"
        value: "test-run"

    - name: Pre-check cluster
      import_role:
        name: precheck
      tags: precheck
                            

On the gunicorn It is logging the following error:

Apr 01 13:08:36 ara.labs.com gunicorn[50413]: --- Logging error ---
Apr 01 13:08:36 ara.labs.com gunicorn[50413]: Traceback (most recent call last):
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:   File "/usr/lib64/python3.6/logging/handlers.py", line 942, in emit
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:     self.socket.sendto(msg, self.address)
Apr 01 13:08:36 ara.labs.com gunicorn[50413]: OSError: [Errno 9] Bad file descriptor
Apr 01 13:08:36 ara.labs.com gunicorn[50413]: Call stack:
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:   File "/opt/ara/virtualenv/bin/gunicorn", line 11, in <module>
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:     sys.exit(run())
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:   File "/opt/ara/virtualenv/lib64/python3.6/site-packages/gunicorn/app/wsgiapp.py", line 67, in run
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:     WSGIApplication("%(prog)s [OPTIONS] [APP_MODULE]").run()
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:   File "/opt/ara/virtualenv/lib64/python3.6/site-packages/gunicorn/app/base.py", line 231, in run
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:     super().run()
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:   File "/opt/ara/virtualenv/lib64/python3.6/site-packages/gunicorn/app/base.py", line 72, in run
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:     Arbiter(self).run()
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:   File "/opt/ara/virtualenv/lib64/python3.6/site-packages/gunicorn/arbiter.py", line 202, in run
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:     self.manage_workers()
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:   File "/opt/ara/virtualenv/lib64/python3.6/site-packages/gunicorn/arbiter.py", line 551, in manage_workers
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:     self.spawn_workers()
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:   File "/opt/ara/virtualenv/lib64/python3.6/site-packages/gunicorn/arbiter.py", line 622, in spawn_workers
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:     self.spawn_worker()
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:   File "/opt/ara/virtualenv/lib64/python3.6/site-packages/gunicorn/arbiter.py", line 589, in spawn_worker
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:     worker.init_process()
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:   File "/opt/ara/virtualenv/lib64/python3.6/site-packages/gunicorn/workers/base.py", line 142, in init_process
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:     self.run()
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:   File "/opt/ara/virtualenv/lib64/python3.6/site-packages/gunicorn/workers/sync.py", line 125, in run
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:     self.run_for_one(timeout)
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:   File "/opt/ara/virtualenv/lib64/python3.6/site-packages/gunicorn/workers/sync.py", line 69, in run_for_one
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:     self.accept(listener)
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:   File "/opt/ara/virtualenv/lib64/python3.6/site-packages/gunicorn/workers/sync.py", line 31, in accept
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:     self.handle(listener, client, addr)
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:   File "/opt/ara/virtualenv/lib64/python3.6/site-packages/gunicorn/workers/sync.py", line 136, in handle
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:     self.handle_request(listener, req, client, addr)
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:   File "/opt/ara/virtualenv/lib64/python3.6/site-packages/gunicorn/workers/sync.py", line 188, in handle_request
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:     self.log.access(resp, req, environ, request_time)
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:   File "/opt/ara/virtualenv/lib64/python3.6/site-packages/gunicorn/glogging.py", line 349, in access
Apr 01 13:08:36 ara.labs.com gunicorn[50413]:     self.access_log.info(self.cfg.access_log_format, safe_atoms)
Apr 01 13:08:36 ara.labs.com gunicorn[50413]: Message: '%(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s"'
Apr 01 13:08:36 ara.labs.com gunicorn[50413]: Arguments: {'h': '', 'l': '-', 'u': '-', 't': '[01/Apr/2022:11:08:36 +0000]', 'r': 'PATCH /api/v1/hosts/166 HTTP/1.0', 's': '200', 'm': 'PATCH', 'U': '/api/v1/hosts/166', 'q': '', 'H': 'HTTP/1.0', 'b': '201', 'B': 201, 'f': '-', 'a': 'ara-http-client_1.5.7', 'T': 0, 'D': 13258, 'M': 13, 'L': '0.013258', 'p': '<50420>', '{x-forwarded-for}i': '10.110.1.22', '{x-forwarded-proto}i': 'http', '{host}i': 'ara.labs.com', '{connection}i': 'close', '{content-length}i': '68', '{user-agent}i': 'ara-http-client_1.5.7', '{accept-encoding}i': 'gzip, deflate', '{accept}i': 'application/json', '{content-type}i': 'application/json', '{content-type}o': 'application/json', '{vary}o': 'Accept, Origin', '{allow}o': 'GET, PUT, PATCH, DELETE, HEAD, OPTIONS', '{x-frame-options}o': 'SAMEORIGIN', '{content-length}o': '201', '{wsgi.errors}e': <gunicorn.http.wsgi.WSGIErrorsWrapper object at 0x7faac718fa58>, '{wsgi.version}e': (1, 0), '{wsgi.multithread}e': False, '{wsgi.multiprocess}e': True, '{wsgi.run_once}e': False, '{wsgi.file_wrapper}e': <class 'gunicorn.http.wsgi.FileWrapper'>, '{wsgi.input_terminated}e': True, '{server_software}e': 'gunicorn/20.1.0', '{wsgi.input}e': <gunicorn.http.body.Body object at 0x7faac718f898>, '{gunicorn.socket}e': <socket.socket fd=4, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0, laddr=/opt/ara/socket>, '{request_method}e': 'PATCH', '{query_string}e': '', '{raw_uri}e': '/api/v1/hosts/166', '{server_protocol}e': 'HTTP/1.0', '{http_x_forwarded_for}e': '10.110.1.22', '{http_x_forwarded_proto}e': 'http', '{http_host}e': 'ara.labs.com', '{http_connection}e': 'close', '{content_length}e': '68', '{http_user_agent}e': 'ara-http-client_1.5.7', '{http_accept_encoding}e': 'gzip, deflate', '{http_accept}e': 'application/json', '{content_type}e': 'application/json', '{wsgi.url_scheme}e': 'http', '{remote_addr}e': '', '{server_name}e': 'ara.labs.com', '{server_port}e': '80', '{path_info}e': '/api/v1/hosts/166', '{script_name}e': ''}

I am able to make it work by specifying in the play run_once: True and delegate_to: localhost

What should be happening ?

It should not be failing or it should be explained in the docs

[dmsimard]

This is a known issue and it is discussed in https://github.com/ansible-community/ara/issues/101 and https://github.com/ansible-community/ara/pull/274.

I would say that when I first developed ara_record, my use case didn't consider running it N times across N hosts -- it was to record something once, probably from localhost.

I don't have a solution for it right now, #274 was an attempt to fix it but it would break other use cases.

[gcilleruelobeltran]

Hi guys,

I may come up with a GOOD SOLUTION for this. I have a use case where I need to record a specific info in every host so I have two ways for doing so:

1. Record once at the end play where I iterate through every host using 'ansible_play_hosts_all' var and retrieve the info I want from hostvars or...
2. Record N times across N hosts.

I'm using second solution by just adding the option 'throttle' and set it to 1. Option 'throttle' force the task to run one thread per host and really make it work.

This is an example: - name: Record example ara_record: key: "{{ some_var_info_key }}" value: "{{ some_var_info }}" delegate_to: localhost throttle: 1 ignore_errors: True

As you can see I still use it to run it on localhost and ignore_errors in case of failing.

Hope this is useful for you all.

Regards.