Awx: stdout capture is missing - sometimes

Created on 30 Nov 2017  路  2Comments  路  Source: ansible/awx
ISSUE TYPE
  • Bug Report
COMPONENT NAME
  • API
SUMMARY

I run a template and sometimes the stdout is empty. I open the stdout link: /api/v2/jobs/192/stdout/?format=txt_download (which is not working, but deleting the format part:) /api/v2/jobs/192/stdout/ and it shows:

HTTP 200 OK
Allow: GET, HEAD, OPTIONS
Content-Type: text/plain ;utf-8
Vary: Accept
X-API-Node: awx
X-API-Time: 0.017s



stdout capture is missing
ENVIRONMENT
  • AWX version: 1.0.1.203 - 1.0.1.268 (at least)
  • AWX install method: docker on linux (docker-compose deployed to docker swarm)
  • Ansible version: 2.4.x
  • Operating System: Linux (not relevant)
  • Web Browser: Chromium 63 (not relevant)
STEPS TO REPRODUCE

I run playbooks, and after a few runs stdout is always empty. The task is run successfully or with failure as it should.

EXPECTED RESULTS

Stdout is shown every time.

ACTUAL RESULTS

Stdout is empty, downloading stdout shows: "stdout capture is missing"

ADDITIONAL INFORMATION

If I restart the awx_tag container (in my case as it is deployed with Swarm: docker kill ...) the problem disappears for some time.

This is from the awx_tag output (in case of missing stdout):

...
2017-11-30 10:45:33,575 ERROR    awx.main.commands.run_callback_receiver Detail: Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/awx/main/management/commands/run_callback_receiver.py", line 138, in callback_worker
    JobEvent.create_from_data(**body)
  File "/usr/lib/python2.7/site-packages/awx/main/models/jobs.py", line 1288, in create_from_data
    job_event = JobEvent.objects.create(**kwargs)
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/models/manager.py", line 85, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/models/query.py", line 394, in create
    obj.save(force_insert=True, using=self.db)
  File "/usr/lib/python2.7/site-packages/awx/main/models/jobs.py", line 1230, in save
    updated_fields = self._update_from_event_data()
  File "/usr/lib/python2.7/site-packages/awx/main/models/jobs.py", line 1116, in _update_from_event_data
    job = self.job
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/models/fields/related_descriptors.py", line 184, in __get__
    rel_obj = self.get_object(instance)
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/models/fields/related_descriptors.py", line 159, in get_object
    return qs.get(self.field.get_reverse_related_filter(instance))
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/models/query.py", line 374, in get
    num = len(clone)
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/models/query.py", line 232, in __len__
    self._fetch_all()
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/models/query.py", line 1118, in _fetch_all
    self._result_cache = list(self._iterable_class(self))
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/polymorphic/query.py", line 42, in _polymorphic_iterator
    o = next(base_iter)
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/models/query.py", line 53, in __iter__
    results = compiler.execute_sql(chunked_fetch=self.chunked_fetch)
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/models/sql/compiler.py", line 882, in execute_sql
    cursor = self.connection.cursor()
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/backends/base/base.py", line 254, in cursor
    return self._cursor()
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/backends/base/base.py", line 231, in _cursor
    return self._prepare_cursor(self.create_cursor(name))
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/utils.py", line 94, in __exit__
    six.reraise(dj_exc_type, dj_exc_value, traceback)
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/backends/base/base.py", line 231, in _cursor
    return self._prepare_cursor(self.create_cursor(name))
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/backends/postgresql/base.py", line 220, in create_cursor
    cursor = self.connection.cursor()
InterfaceError: connection already closed

[2017-11-30 10:45:33,855: INFO/MainProcess] Received task: awx.main.tasks.update_inventory_computed_fields[415ee508-ea5d-4438-b01e-d8893c695195]  
[2017-11-30 10:45:33,856: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x398cc80> (args:('awx.main.tasks.update_inventory_computed_fields', '415ee508-ea5d-4438-b01e-d8893c695195', {'origin': 'gen1300@awx', 'lang': 'py', 'task': 'awx.main.tasks.update_inventory_computed_fields', 'group': None, 'root_id': 'e2d017d1-af7e-4055-a2fa-abc9d00b7cc0', u'delivery_info': {u'priority': None, u'redelivered': False, u'routing_key': u'tower', u'exchange': u''}, 'expires': None, u'correlation_id': '415ee508-ea5d-4438-b01e-d8893c695195', 'retries': 0, 'timelimit': [None, None], 'argsrepr': '(2, True)', 'eta': None, 'parent_id': 'b9a32fd8-85a0-41f3-913d-18eb131efef8', u'reply_to': '0d3e5470-35b1-31a3-bb7b-2d6394e29252', 'id': '415ee508-ea5d-4438-b01e-d8893c695195', 'kwargsrepr': '{}'}, u'[[2, true], {}, {"chord": null, "callbacks": null, "errbacks": null, "chain": null}]', 'application/json', 'utf-8') kwargs:{})
[2017-11-30 10:45:33,857: DEBUG/MainProcess] Task accepted: awx.main.tasks.update_inventory_computed_fields[415ee508-ea5d-4438-b01e-d8893c695195] pid:1465
[2017-11-30 10:45:33,864: INFO/MainProcess] Received task: awx.main.tasks.handle_work_success[da5909e7-b979-4937-b060-9a3ab0524f04]  
[2017-11-30 10:45:33,865: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x398cc80> (args:('awx.main.tasks.handle_work_success', 'da5909e7-b979-4937-b060-9a3ab0524f04', {'origin': 'gen1300@awx', 'lang': 'py', 'task': 'awx.main.tasks.handle_work_success', 'group': None, 'root_id': 'e2d017d1-af7e-4055-a2fa-abc9d00b7cc0', u'delivery_info': {u'priority': None, u'redelivered': False, u'routing_key': u'tower', u'exchange': u''}, 'expires': None, u'correlation_id': 'da5909e7-b979-4937-b060-9a3ab0524f04', 'retries': 0, 'timelimit': [None, None], 'argsrepr': '(None,)', 'eta': None, 'parent_id': 'b9a32fd8-85a0-41f3-913d-18eb131efef8', u'reply_to': '0d3e5470-35b1-31a3-bb7b-2d6394e29252', 'id': 'da5909e7-b979-4937-b060-9a3ab0524f04', 'kwargsrepr': "{'task_actual': {'type': 'job', 'id': 194}}"}, u'[[null], {"task_actual": {"type": "job", "id": 194}}, {"chord": null, "callbacks": null, "errbacks": null, "chain": null}]', 'application/json', 'utf-8') kwargs:{})
[2017-11-30 10:45:33,871: DEBUG/MainProcess] Task accepted: awx.main.tasks.handle_work_success[da5909e7-b979-4937-b060-9a3ab0524f04] pid:1463
2017-11-30 10:45:33,873 DEBUG    awx.main.models.inventory Going to update inventory computed fields
[2017-11-30 10:45:33,873: DEBUG/ForkPoolWorker-378] Going to update inventory computed fields
[2017-11-30 10:45:33,890: INFO/ForkPoolWorker-375] Task awx.main.tasks.run_job[b9a32fd8-85a0-41f3-913d-18eb131efef8] succeeded in 18.663942109s: None
2017-11-30 10:45:33,926 DEBUG    awx.main.models.inventory Finished updating inventory computed fields
[2017-11-30 10:45:33,926: DEBUG/ForkPoolWorker-378] Finished updating inventory computed fields
[2017-11-30 10:45:33,929: DEBUG/ForkPoolWorker-377] Start from server, version: 0.9, properties: {'information': 'Licensed under the MPL.  See http://www.rabbitmq.com/', 'product': 'RabbitMQ', 'copyright': 'Copyright (C) 2007-2017 Pivotal Software, Inc.', 'capabilities': {'exchange_exchange_bindings': True, 'connection.blocked': True, 'authentication_failure_close': True, 'direct_reply_to': True, 'basic.nack': True, 'per_consumer_qos': True, 'consumer_priorities': True, 'consumer_cancel_notify': True, 'publisher_confirms': True}, 'cluster_name': 'rabbit@b3ced9c88a6b', 'platform': 'Erlang/OTP 19.2.1', 'version': '3.6.14'}, mechanisms: ['AMQPLAIN', 'PLAIN'], locales: [u'en_US']
[2017-11-30 10:45:33,931: DEBUG/ForkPoolWorker-377] using channel_id: 1
[2017-11-30 10:45:33,932: DEBUG/ForkPoolWorker-377] Channel open
[2017-11-30 10:45:33,933: INFO/ForkPoolWorker-378] Task awx.main.tasks.update_inventory_computed_fields[415ee508-ea5d-4438-b01e-d8893c695195] succeeded in 0.0754506569992s: None
[2017-11-30 10:45:33,938: INFO/MainProcess] Received task: awx.main.scheduler.tasks.run_job_complete[018be77a-9f63-4436-95a1-f017e5b4c404]  
[2017-11-30 10:45:33,938: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x398cc80> (args:('awx.main.scheduler.tasks.run_job_complete', '018be77a-9f63-4436-95a1-f017e5b4c404', {'origin': 'gen1463@awx', 'lang': 'py', 'task': 'awx.main.scheduler.tasks.run_job_complete', 'group': None, 'root_id': 'e2d017d1-af7e-4055-a2fa-abc9d00b7cc0', u'delivery_info': {u'priority': 0, u'redelivered': False, u'routing_key': u'tower_scheduler.job.complete', u'exchange': u'scheduler'}, 'expires': None, u'correlation_id': '018be77a-9f63-4436-95a1-f017e5b4c404', 'retries': 0, 'timelimit': [None, None], 'argsrepr': '(194,)', 'eta': None, 'parent_id': 'da5909e7-b979-4937-b060-9a3ab0524f04', u'reply_to': '2eab75a3-a7dd-31de-b662-b6874d21acf1', 'id': '018be77a-9f63-4436-95a1-f017e5b4c404', 'kwargsrepr': '{}'}, u'[[194], {}, {"chord": null, "callbacks": null, "errbacks": null, "chain": null}]', 'application/json', 'utf-8') kwargs:{})
[2017-11-30 10:45:33,942: DEBUG/MainProcess] Task accepted: awx.main.scheduler.tasks.run_job_complete[018be77a-9f63-4436-95a1-f017e5b4c404] pid:1300
[2017-11-30 10:45:33,944: INFO/ForkPoolWorker-377] Task awx.main.tasks.handle_work_success[da5909e7-b979-4937-b060-9a3ab0524f04] succeeded in 0.0770123319999s: None
2017-11-30 10:45:33,955 DEBUG    awx.main.scheduler Starting Scheduler
2017-11-30 10:45:33,955 DEBUG    awx.main.scheduler Starting Scheduler
[2017-11-30 10:45:33,955: DEBUG/ForkPoolWorker-375] Starting Scheduler
[2017-11-30 10:45:33,978: INFO/ForkPoolWorker-375] Task awx.main.scheduler.tasks.run_job_complete[018be77a-9f63-4436-95a1-f017e5b4c404] succeeded in 0.0385397499995s: None

The "connection already closed" error is not present when the stdout is working - maybe this helps.

When the stdout is lost it is no longer working on any template (including project update/pull) so I think the problem is not because of the template. The missing stdout is not necessary large, it is not a size limit or something.

api bug
Source
picture DBLaci

Most helpful comment

Hey @DBLaci,

This is an issue we've know about, and we're actively working on a fix. Stay tuned!

picture ryanpetrello on 30 Nov 2017
🎉2

All 2 comments

Hey @DBLaci,

This is an issue we've know about, and we're actively working on a fix. Stay tuned!

ryanpetrello picture ryanpetrello on 30 Nov 2017
🎉2

This will be fixed here: https://github.com/ansible/awx/issues/200

matburt picture matburt on 1 Dec 2017
Was this page helpful?
0 / 5 - 0 ratings

Related issues

astraios picture astraios  路  3Comments
marshmalien picture marshmalien  路  3Comments
IshwarKanse picture IshwarKanse  路  3Comments
worsco picture worsco  路  3Comments
Gui13 picture Gui13  路  3Comments