Awx: Hosts import fails from inventory when "source from project" is being used

[itcrowdsource]

ISSUE TYPE

SCM update fails from inventory update process

• Bug Report

COMPONENT NAME

• API
• UI

SUMMARY

Configured a project to retrieve configurations from a GIT repository. The project is able to sync properly with the GIT repository.
After that an inventory has been configured to retrieve a list of hosts from the GIT repository. Within inventory the option "Source from project" has been selected and the apropriate hosts file in the GIT folder.
All seems to be configured properly. After that did a sync to retrieve the hostnames. That sync fails

ENVIRONMENT

• AWX version: 1.0.2.75
• AWX install method: docker on linux
• Ansible version: 2.4.2.0
• Operating System: Ubuntu 16.04 Xenial
• Web Browser: Chrome, Firefox

STEPS TO REPRODUCE

• Clean install of the latest AWX version (no database migration from previous versions)
• Follow the steps from the summary above

EXPECTED RESULTS

• Sync should import hosts from the GIT hosts file properly

ACTUAL RESULTS

• Sync fails with a random ID code (stdout file is empty, mail notification provides more information - see results below)
• Error message: SCM Update failed for with ID .

ADDITIONAL INFORMATION

Inventory Update #52 had status failed, view details at http://x.x.x.x/#/inventory_sync/52
{
"status": "failed",
"name": "Inventory - Source from project",
"started": "2018-01-25T13:27:18.123421+00:00",
"traceback": "Traceback (most recent call last):\n File \"/usr/lib/python2.7/site-packages/awx/main/tasks.py\", line 770, in run\n self.pre_run_hook(instance, *kwargs)\n File \"/usr/lib/python2.7/site-packages/awx/main/tasks.py\", line 1934, in pre_run_hook\n task_instance.run(local_project_sync.id)\n File \"/usr/lib/python2.7/site-packages/awx/main/tasks.py\", line 483, in _wrapped\n return f(self, *args, *kwargs)\n File \"/usr/lib/python2.7/site-packages/awx/main/tasks.py\", line 905, in run\n raise AwxTaskError.TaskError(instance, rc)\nException: project_update 53 (failed) encountered an error (rc=2), please see task stdout for details.\n",
"friendly_name": "Inventory Update",
"created_by": "admin",
"url": "http://x.x.x.x/#/inventory_sync/52",
"finished": "2018-01-25T13:27:24.466897+00:00",
"id": 52
}

[matburt]

Can we see the actual stdout and/or detail from the job run?

[itcrowdsource]

The stdout file in the GUI is empty, even with debugging enabled. Also if I query the API I see no results (I am now querying failed job 69) :

Inventory Update Stdout
GET /api/v2/inventory_updates/69/stdout/
HTTP 200 OK
Allow: GET, HEAD, OPTIONS
Content-Type: text/plain ;utf-8
Vary: Accept
X-API-Node: awx
X-API-Time: 0.036s

I am able to query the inventory update process:

HTTP 200 OK
Allow: GET, DELETE, HEAD, OPTIONS
Content-Type: application/json
Vary: Accept
X-API-Node: awx
X-API-Time: 0.054s

{
"id": 69,
"type": "inventory_update",
"url": "/api/v2/inventory_updates/69/",
"related": {
"created_by": "/api/v2/users/1/",
"unified_job_template": "/api/v2/inventory_sources/10/",
"stdout": "/api/v2/inventory_updates/69/stdout/",
"inventory_source": "/api/v2/inventory_sources/10/",
"cancel": "/api/v2/inventory_updates/69/cancel/",
"notifications": "/api/v2/inventory_updates/69/notifications/",
"events": "/api/v2/inventory_updates/69/events/",
"source_project_update": "/api/v2/project_updates/70/"
},
"summary_fields": {
"instance_group": {
"id": 1,
"name": "tower"
},
"inventory_source": {
"source": "scm",
"last_updated": "2018-01-26T13:48:32.161331Z",
"status": "failed"
},
"unified_job_template": {
"id": 10,
"name": "Source from project",
"description": "Source from project",
"unified_job_type": "inventory_update"
},
"created_by": {
"id": 1,
"username": "admin",
"first_name": "xxx",
"last_name": "xxx"
},
"user_capabilities": {
"start": true,
"delete": true
}
},
"created": "2018-01-26T13:48:24.581862Z",
"modified": "2018-01-26T13:48:32.368631Z",
"name": "Inventory - Source from project",
"description": "Source from project",
"source": "scm",
"source_path": "hosts",
"source_script": null,
"source_vars": "",
"credential": null,
"source_regions": "",
"instance_filters": "",
"group_by": "",
"overwrite": true,
"overwrite_vars": true,
"timeout": 0,
"verbosity": 2,
"unified_job_template": 10,
"launch_type": "manual",
"status": "failed",
"failed": true,
"started": "2018-01-26T13:48:25.443652Z",
"finished": "2018-01-26T13:48:32.161331Z",
"elapsed": 6.718,
"job_args": "",
"job_cwd": "",
"job_env": {},
"job_explanation": "Previous Task Failed: {\"job_type\": \"project_update\", \"job_name\": \"GIT source\", \"job_id\": \"70\"}",
"execution_node": "awx",
"result_traceback": "Traceback (most recent call last):\n File \"/usr/lib/python2.7/site-packages/awx/main/tasks.py\", line 770, in run\n self.pre_run_hook(instance, *kwargs)\n File \"/usr/lib/python2.7/site-packages/awx/main/tasks.py\", line 1934, in pre_run_hook\n task_instance.run(local_project_sync.id)\n File \"/usr/lib/python2.7/site-packages/awx/main/tasks.py\", line 483, in _wrapped\n return f(self, *args, *kwargs)\n File \"/usr/lib/python2.7/site-packages/awx/main/tasks.py\", line 905, in run\n raise AwxTaskError.TaskError(instance, rc)\nException: project_update 70 (failed) encountered an error (rc=2), please see task stdout for details.\n",
"inventory_source": 10,
"license_error": false,
"source_project_update": 70
}

[flabatut]

i can reproduce the same behavior with a git project containing only the following files :

• hosts
• roles/requirements.yml

and files filled with the following content:

$ more hosts 
localhost                       ansible_connection=local

$ more roles/requirements.yml 
---

the culprit element being requirements.yml apparently.
Whatever if requirements.yml contains valid content or remains empty.
As soon as requirements.yml is detected by inventory source update mechanism, the tasks returns a failure
As soon as you remove the file requirements.yml, problem vanishes
deploying awx, using prebuilt images with docker-compose, awx 1.0.2.89 freshly tested

[itcrowdsource]

@matburt I can confirm what @flabatut says. It is indeed related to the requirements.yml file.

[flabatut]

surprisingly :

pwd

/var/lib/awx/projects/_8__test

awx-manage inventory_import --inventory-name test --source hosts

2018-02-01 19:41:58,627 INFO awx.main.commands.inventory_import Updating inventory 3: test
2018-02-01 19:41:59,039 INFO awx.main.commands.inventory_import Reading Ansible inventory source: /var/lib/awx/projects/_8__test/hosts
2018-02-01 19:42:00,169 INFO awx.main.commands.inventory_import Processing JSON output...
2018-02-01 19:42:00,170 INFO awx.main.commands.inventory_import Loaded 0 groups, 1 hosts
2018-02-01 19:42:00,176 INFO awx.main.commands.inventory_import Inventory variables unmodified
2018-02-01 19:42:00,205 INFO awx.main.commands.inventory_import Host "localhost" variables unmodified
2018-02-01 19:42:00,229 DEBUG awx.main.models.inventory Going to update inventory computed fields
2018-02-01 19:42:00,514 DEBUG awx.main.models.inventory Finished updating inventory computed fields
2018-02-01 19:42:00,516 INFO awx.main.commands.inventory_import Inventory import completed for (test - 13) in 1.9s

furthermore, i could reproduce the issue on tags :
1.0.2.89 (from dockerhub)
1.0.0.591 ( from dockerhub)
1.0.0.395 (self built images)

@matburt : any suggestions for troubleshooting such issue ? your bet regarding the relation with requirements.yml ?
thanks

[Matz13]

Hi,
It turns out ansible-galaxy doesn't like empty requirements.yml

Doing some troubleshooting il the Job_status folder, in the failed jobs I found this:

TASK [fetch galaxy roles from requirements.yml] ********************************
fatal: [localhost]: FAILED! => {"changed": true, "cmd": ["ansible-galaxy", "install", "-r", "requirements.yml", 
"-p", "/var/lib/awx/projects/_6__test_awx/roles/", "--force"], "delta": "0:00:00.594390", 
"end": "2018-02-08 17:22:38.659771", "failed": true, "rc": 1, "start": "2018-02-08 17:22:38.065381", 
"stderr": "\u001b[0;31mERROR! No roles found in file: requirements.yml\u001b[0m", 
"stderr_lines": ["\u001b[0;31mERROR! No roles found in file: requirements.yml\u001b[0m"], 
"stdout": "", "stdout_lines": []}

So I added a small galaxy role, did an SCM update in AWX an the job now runs properly.

My 2 cents: an empty requirement file should not be blocking (even if it's useless) and even less be blocking _silently_.
If someone could add an explicit stdout for this kind of error, this would help with troubleshooting a lot!

@matburt can you confirm the issue is the same for you?

Regards,
Matt

[ryanpetrello]

Great detective work, @Matz13 and @flabatut; it looks like our project update needs to be more resilient to empty requirements.txt files here.

[ryanpetrello]

This looks to me like something that could _arguably_ be a bug in ansible-galaxy's behavior. I'm hesitant to change this task in awx's project update playbook to be non-critical, because it's entirely possible that you _want_ your project updates to fail if - for example - your galaxy roles fail to fetch for legitimate reasons (like network unavailability).

If ansible-galaxy encounters an empty requirements.txt file, it seems to me like it would make more sense for it to not exit in a critical way but to instead just _not install anything_.

I'd recommend filing an issue describing what you've found here:
https://github.com/ansible/ansible/issues/new

...and seeing what the Ansible core team thinks.

[itcrowdsource]

My requirements.yml isn't empty and the SCM update still fails if I trigger a SCM update when using "Source from a project" in the Inventory. The SCM update does works properly if I start the job from the project itself. @ryanpetrello @Matz13 @matburt @flabatut

[Matz13]

@itcrowdsource sorry to hear your issue is not solved. I can suggest you to go directly where your task handler stores the job_status files. This is where I found the answer to my issue.
If your run awx with docker, you can find them in the awx_tasks container in job_status/<jobid+1>_<hash>.out

@flabatut @matburt @ryanpetrello : I just opened an issue in Ansible git: https://github.com/ansible/ansible/issues/35966

[itcrowdsource]

Ok I figured out that there was a small error in the markup of the requirements.yml file. The weird thing is that the same file had worked in previous versions of AWX. I guess it is a good idea to generate a proper error message if the file is missing or if something is wrong with the content of the file.

[daswars]

Hi,
I have the same or similar problem.

AWX Version (AWX 1.0.5.23)

i habe a project with a roles/requirements.yml file and an inventory.ini file.

Without error at str out:
STATUS
Error
EXPLANATION
SCM Update failed for ansible-playbook-fusion with ID 352.
LICENSE ERROR
False

And this infos at awx task docker logs

awx_task_1     | [2018-04-17 08:55:13,381: DEBUG/Worker-808] Open OK!
awx_task_1     | [2018-04-17 08:55:13,381: DEBUG/Worker-808] using channel_id: 1
awx_task_1     | [2018-04-17 08:55:13,382: DEBUG/Worker-808] Channel open
awx_task_1     | 2018-04-17 08:55:17,318 INFO     awx.main.tasks project_update 352 (running) finished running, producing 16 events.
awx_task_1     | 2018-04-17 08:55:17,320 INFO     awx.main.commands.run_callback_receiver Event processing is finished for Job 352, sending notifications
awx_task_1     | 2018-04-17 08:55:17,320 INFO     awx.main.commands.run_callback_receiver Event processing is finished for Job 352, sending notifications
awx_task_1     | 2018-04-17 08:55:17,393 DEBUG    awx.main.models.inventory Going to update inventory computed fields
awx_task_1     | [2018-04-17 08:55:17,393: DEBUG/Worker-808] Going to update inventory computed fields
awx_task_1     | 2018-04-17 08:55:17,405 DEBUG    awx.main.models.inventory Finished updating inventory computed fields
awx_task_1     | [2018-04-17 08:55:17,405: DEBUG/Worker-808] Finished updating inventory computed fields
awx_task_1     | 2018-04-17 08:55:17,407 ERROR    awx.main.tasks Error flushing job stdout and saving event count.
awx_task_1     | Traceback (most recent call last):
awx_task_1     |   File "/usr/lib/python2.7/site-packages/awx/main/tasks.py", line 975, in run
awx_task_1     |     stdout_handle.flush()
awx_task_1     | UnboundLocalError: local variable 'stdout_handle' referenced before assignment
awx_task_1     | 2018-04-17 08:55:17,461 DEBUG    awx.main.models.inventory Going to update inventory computed fields
awx_task_1     | [2018-04-17 08:55:17,461: DEBUG/Worker-808] Going to update inventory computed fields
awx_task_1     | 2018-04-17 08:55:17,474 DEBUG    awx.main.models.inventory Finished updating inventory computed fields
awx_task_1     | [2018-04-17 08:55:17,474: DEBUG/Worker-808] Finished updating inventory computed fields
awx_task_1     | 2018-04-17 08:55:17,487 WARNING  awx.main.tasks inventory_update 351 (error) encountered an error (rc=None), please see task stdout for details.
awx_task_1     | [2018-04-17 08:55:17,501: DEBUG/Worker-808] Start from server, version: 0.9, properties: {u'information': u'Licensed under the MPL.  See http://www.rabbitmq.com/', u'product': u'RabbitMQ', u'copyright': u'Copyright (C) 2007-2018 Pivotal Software, Inc.', u'capabilities': {u'exchange_exchange_bindings': True, u'connection.blocked': True, u'authentication_failure_close': True, u'direct_reply_to': True, u'basic.nack': True, u'per_consumer_qos': True, u'consumer_priorities': True, u'consumer_cancel_notify': True, u'publisher_confirms': True}, u'cluster_name': u'rabbit@eac48efcdd50', u'platform': u'Erlang/OTP 20.2.4', u'version': u'3.7.4'}, mechanisms: [u'AMQPLAIN', u'PLAIN'], locales: [u'en_US']
awx_task_1     | [2018-04-17 08:55:17,503: DEBUG/Worker-808] Open OK!
awx_task_1     | [2018-04-17 08:55:17,503: DEBUG/Worker-808] using channel_id: 1
awx_task_1     | [2018-04-17 08:55:17,504: DEBUG/Worker-808] Channel open
awx_task_1     | [2018-04-17 08:55:17,508: INFO/MainProcess] Received task: awx.main.tasks.handle_work_error[5cf34932-ba4c-45ba-8992-04f667be1054]
awx_task_1     | [2018-04-17 08:55:17,509: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x1a60b18> (args:(u'awx.main.tasks.handle_work_error', u'5cf34932-ba4c-45ba-8992-04f667be1054', [u'd2ea2f8d-5d67-4780-b104-6176367ca294'], {u'subtasks': [{u'type': u'inventory_update', u'id': 351}]}, {u'utc': True, u'is_eager': False, u'chord': None, u'group': u'7716a430-e85a-4ca9-83b8-b23badd7751e', u'args': [u'd2ea2f8d-5d67-4780-b104-6176367ca294'], u'retries': 0, u'delivery_info': {u'priority': None, u'redelivered': False, u'routing_key': u'tower', u'exchange': u'tower'}, u'expires': None, u'hostname': 'celery@awx', u'task': u'awx.main.tasks.handle_work_error', u'callbacks': None, u'correlation_id': u'5cf34932-ba4c-45ba-8992-04f667be1054', u'errbacks': None, u'timelimit': [None, None], u'taskset': u'7716a430-e85a-4ca9-83b8-b23badd7751e', u'kwargs': {u'subtasks': [{u'type': u'inventory_update', u'id': 351}]}, u'eta': None, u'reply_to': u'a11905de-acd9-388a-b281-e2411580f795', u'id': u'5cf34932-ba4c-45ba-8992-04f667be1054', u'headers': {}}) kwargs:{})
awx_task_1     | [2018-04-17 08:55:17,511: DEBUG/MainProcess] Task accepted: awx.main.tasks.handle_work_error[5cf34932-ba4c-45ba-8992-04f667be1054] pid:4210
awx_task_1     | [2018-04-17 08:55:17,511: DEBUG/Worker-808] Closed channel #1
awx_task_1     | [2018-04-17 08:55:17,515: ERROR/MainProcess] Task awx.main.tasks.run_inventory_update[d2ea2f8d-5d67-4780-b104-6176367ca294] raised unexpected: Exception('inventory_update 351 (error) encountered an error (rc=None), please see task stdout for details.',)
awx_task_1     | Traceback (most recent call last):
awx_task_1     |   File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/celery/app/trace.py", line 240, in trace_task
awx_task_1     |     R = retval = fun(*args, **kwargs)
awx_task_1     |   File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/celery/app/trace.py", line 438, in __protected_call__
awx_task_1     |     return self.run(*args, **kwargs)
awx_task_1     |   File "/usr/lib/python2.7/site-packages/awx/main/tasks.py", line 564, in _wrapped
awx_task_1     |     return f(self, *args, **kwargs)
awx_task_1     |   File "/usr/lib/python2.7/site-packages/awx/main/tasks.py", line 1006, in run
awx_task_1     |     raise AwxTaskError.TaskError(instance, rc)
awx_task_1     | Exception: inventory_update 351 (error) encountered an error (rc=None), please see task stdout for details.
awx_task_1     | 2018-04-17 08:55:17,543 DEBUG    awx.main.tasks Executing error task id d2ea2f8d-5d67-4780-b104-6176367ca294, subtasks: [{u'type': u'inventory_update', u'id': 351}]
awx_task_1     | [2018-04-17 08:55:17,565: DEBUG/Worker-809] Start from server, version: 0.9, properties: {u'information': u'Licensed under the MPL.  See http://www.rabbitmq.com/', u'product': u'RabbitMQ', u'copyright': u'Copyright (C) 2007-2018 Pivotal Software, Inc.', u'capabilities': {u'exchange_exchange_bindings': True, u'connection.blocked': True, u'authentication_failure_close': True, u'direct_reply_to': True, u'basic.nack': True, u'per_consumer_qos': True, u'consumer_priorities': True, u'consumer_cancel_notify': True, u'publisher_confirms': True}, u'cluster_name': u'rabbit@eac48efcdd50', u'platform': u'Erlang/OTP 20.2.4', u'version': u'3.7.4'}, mechanisms: [u'AMQPLAIN', u'PLAIN'], locales: [u'en_US']

A import with "awx-manage inventory_import --inventory-name test --source hosts" works

[daswars]

ok i have the solutions for my problem.

In my requirements.yml configuration I have 14 roles (to my own gitlab).
one of the git link had no permissions
With the assignment of the rights in our Gitlab it worked now.

[MrMEEE]

Seeing same issue here...

[MrMEEE]

To me it seems to fail, because ansible-galaxy is not present...

Running the rpms.. but might be the same problem in docker...