Awx: changes in inventory are ignored

Created on 21 Sep 2017  路  39Comments  路  Source: ansible/awx
ISSUE TYPE
  • Bug Report
COMPONENT NAME
  • UI
SUMMARY

template job did not relect changes in invenotry

  • hosts
  • groups
  • hostvars
ENVIRONMENT
  • AWX version: e6777577b6b75e1f3e1b064c12432af3101c1f53
  • Ansible version: 2.4.0
  • Operating System: CentOS 7
  • Web Browser: Firefox
STEPS TO REPRODUCE
  • create inventory
  • add 1 host (v1)
  • create template
  • run template (should be OK)
  • add host into inventory(v2)
  • run template
EXPECTED RESULTS

The template should run on all hosts in modified inventory (v2) , but it stll run only on old one (v1).
The same behaviour is when ediing variables or even added project as source toinventory.

ACTUAL RESULTS

The template is ignoring any changes in the inventory since it was created. It somehow remembers the old inventory.

ADDITIONAL INFORMATION

None

api needs_info bug
Source
picture hudecof

All 39 comments

I can't reproduce this. I followed your steps and launching the job template again after adding another host will show it run against both hosts.

Are you sure your playbook is not targeting only one host?

matburt picture matburt on 22 Sep 2017

very simple playbook

---
- hosts: all
  gather_facts: yes
  become: no
  vars:
    skip_hosts: []
  tasks:
  - group_by: key={{ ansible_os_family }}
    when: "inventory_hostname not in skip_hosts"

- hosts: RedHat
  gather_facts: no
  become: yes
  become_user: root
  tasks:
  - name: update for RedHat
    yum :
      name: '*'
      state: latest

- hosts: Debian
  gather_facts: no
  become: yes
  become_user: root
  tasks:
  - name: update for Debian
    apt:
      upgrade: yes
      update_cache: yes
      allow_unauthenticated: yes
      cache_valid_time: 3600
hudecof picture hudecof on 22 Sep 2017

log from inventory sync

2017-09-22 08:36:11,941 INFO awx.main.commands.inventory_import Updating inventory 2: cnc-servers 
2017-09-22 08:36:11,984 INFO awx.main.commands.inventory_import Reading Ansible inventory source: /var/lib/awx/projects/_9__testing_inventory/inventory.ini 
2017-09-22 08:36:14,231 INFO awx.main.commands.inventory_import Processing JSON output... 
2017-09-22 08:36:14,235 INFO awx.main.commands.inventory_import Loaded 2 groups, 9 hosts 
2017-09-22 08:36:14,332 INFO awx.main.commands.inventory_import Inventory variables unmodified 
2017-09-22 08:36:14,337 INFO awx.main.commands.inventory_import Group "network-internal" variables unmodified
2017-09-22 08:36:14,338 INFO awx.main.commands.inventory_import Group "test-cm" variables unmodified
2017-09-22 08:36:14,360 INFO awx.main.commands.inventory_import Host "ditlcm01" variables unmodified
2017-09-22 08:36:14,362 INFO awx.main.commands.inventory_import Host "ditlcm02" variables unmodified
2017-09-22 08:36:14,362 INFO awx.main.commands.inventory_import Host "ditlcm03" variables unmodified
2017-09-22 08:36:14,363 INFO awx.main.commands.inventory_import Host "ditlcm04" variables unmodified
2017-09-22 08:36:14,363 INFO awx.main.commands.inventory_import Host "ditlcm05" variables unmodified
2017-09-22 08:36:14,364 INFO awx.main.commands.inventory_import Host "ditlcm06" variables unmodified
2017-09-22 08:36:14,365 INFO awx.main.commands.inventory_import Host "ditlcm07" variables unmodified
2017-09-22 08:36:14,365 INFO awx.main.commands.inventory_import Host "ditlcm08" variables unmodified
2017-09-22 08:36:14,365 INFO awx.main.commands.inventory_import Host "ditlcm09" variables unmodified
2017-09-22 08:36:14,399 INFO awx.main.commands.inventory_import Host "ditlcm01" already in group "network-internal"
2017-09-22 08:36:14,399 INFO awx.main.commands.inventory_import Host "ditlcm02" already in group "network-internal"
2017-09-22 08:36:14,399 INFO awx.main.commands.inventory_import Host "ditlcm03" already in group "network-internal"
2017-09-22 08:36:14,400 INFO awx.main.commands.inventory_import Host "ditlcm04" already in group "network-internal"
2017-09-22 08:36:14,400 INFO awx.main.commands.inventory_import Host "ditlcm05" already in group "network-internal"
2017-09-22 08:36:14,400 INFO awx.main.commands.inventory_import Host "ditlcm06" already in group "network-internal"
2017-09-22 08:36:14,402 INFO awx.main.commands.inventory_import Host "ditlcm07" already in group "network-internal"
2017-09-22 08:36:14,402 INFO awx.main.commands.inventory_import Host "ditlcm08" already in group "network-internal"
2017-09-22 08:36:14,402 INFO awx.main.commands.inventory_import Host "ditlcm09" already in group "network-internal"
2017-09-22 08:36:14,430 INFO awx.main.commands.inventory_import Host "ditlcm01" already in group "test-cm"
2017-09-22 08:36:14,431 INFO awx.main.commands.inventory_import Host "ditlcm02" already in group "test-cm"
2017-09-22 08:36:14,431 INFO awx.main.commands.inventory_import Host "ditlcm03" already in group "test-cm"
2017-09-22 08:36:14,431 INFO awx.main.commands.inventory_import Host "ditlcm04" already in group "test-cm"
2017-09-22 08:36:14,431 INFO awx.main.commands.inventory_import Host "ditlcm05" already in group "test-cm"
2017-09-22 08:36:14,433 INFO awx.main.commands.inventory_import Host "ditlcm06" already in group "test-cm"
2017-09-22 08:36:14,433 INFO awx.main.commands.inventory_import Host "ditlcm07" already in group "test-cm"
2017-09-22 08:36:14,433 INFO awx.main.commands.inventory_import Host "ditlcm08" already in group "test-cm"
2017-09-22 08:36:14,433 INFO awx.main.commands.inventory_import Host "ditlcm09" already in group "test-cm"
2017-09-22 08:36:14,444 DEBUG awx.main.models.inventory Going to update inventory computed fields
2017-09-22 08:36:14,548 DEBUG awx.main.models.inventory Finished updating inventory computed fields
2017-09-22 08:36:14,550 INFO awx.main.commands.inventory_import Inventory import completed for git in 2.6s
hudecof picture hudecof on 22 Sep 2017

log from template, there is not * diplcm01* in inventory

Enter passphrase for /tmp/awx_58_tF3DJe/credential_2: 
Identity added: /tmp/awx_58_tF3DJe/credential_2 (/tmp/awx_58_tF3DJe/credential_2)
PLAY [all] *********************************************************************
10:41:31
TASK [Gathering Facts] *********************************************************
10:41:31
ok: [diplcm01]
TASK [group_by] ****************************************************************
10:41:33
ok: [diplcm01]
 [WARNING]: Could not match supplied host pattern, ignoring: RedHat
PLAY [RedHat] ******************************************************************
10:41:33
skipping: no hosts matched
PLAY [Debian] ******************************************************************
10:41:33
TASK [update for Debian] *******************************************************
10:41:33
ok: [diplcm01]
PLAY RECAP *********************************************************************
10:41:37
diplcm01                   : ok=3    changed=0    unreachable=0    failed=0
hudecof picture hudecof on 22 Sep 2017

I will try to create new inventory

hudecof picture hudecof on 22 Sep 2017

I created new inventorybesed on the project and replaced the old one with new for a temaple job. It runs the role on all servers.

After that I added new server to the inventory. I see job syncing the inventory and also the server is added into inventory. So I run the template job again, but this new server is missing on the list ;(

So seems that any change in inventory after it was assigned to template did not take affect for given template.

hudecof picture hudecof on 22 Sep 2017

I've been through this process a few times and just can't reproduce it. What type of inventory is this and how did you create it? Is it sourced from a particular location?

In one of your previous messages you said: there is not ** diplcm01** in inventory but it still looks like it showed up in the playbook run, was that true?

matburt picture matburt on 22 Sep 2017

Yes, the diplcm01 is still in jobs task servers, but not in inventory.

I removed all docker containers and images and rebilded it from scratch. It works as expcectd, on the inventory hosts. But the problem remains.Inventory changes are not reflected into job templates.

I'm using inventory sith SOURCES / Sourced From Project (Overwrite, Update on Launch)

But I guess I had this problem also in clean Inventory configured by UI

hudecof picture hudecof on 22 Sep 2017

I'm using inventory sith SOURCES / Sourced From Project (Overwrite, Update on Launch)

There is a good chance this issue is some variation of #248

AlanCoding picture AlanCoding on 22 Sep 2017

I recorded the movie, where you can see the inventory and the job run. There is host ditlcm00-badin job run, but nt in inventory.

https://cloud.apps.hudecof.net/s/dOX8brRzspRLfOW

hudecof picture hudecof on 22 Sep 2017

I am at a loss as to how to explain the behavior in the video. If you look at the global hosts list (/api/v2/hosts/) do you see ditlcm00-bad listed in there? Could you paste the results of /api/v2/inventories/N/script/hostvars=1 (where N is the id of your inventory), or tell us if the output of that contains the bad host (whereas it is not show in the host list for the inventory, as your video shows)? If either of these approaches does show the "ditlcm00-bad" host, then we could firmly pin the problem on AWX.

AlanCoding picture AlanCoding on 22 Sep 2017

```[DEV] [email protected]: ~ # /usr/bin/tower-cli host list
* DETAILS: Getting records. *****************
GET http://127.0.0.1/api/v1/hosts/
Params: {'page': 1}

== ========= ========= =======
id name inventory enabled
== ========= ========= =======
21 ditlcm01 5 true
22 ditlcm02 5 true
23 ditlcm03 5 true
24 ditlcm04 5 true
25 ditlcm05 5 true
26 ditlcm06 5 true
27 ditlcm07 5 true
28 ditlcm08 5 true
29 ditlcm09 5 true
1 localhost 1 true
== ========= ========= =======
```

I tryied alse v2 api, but the result is same.

hudecof picture hudecof on 22 Sep 2017

http://192.168.93.100/api/v2/inventories/5/script/

{
    "test-cm": {
        "hosts": [
            "ditlcm01",
            "ditlcm02",
            "ditlcm03",
            "ditlcm04",
            "ditlcm05",
            "ditlcm06",
            "ditlcm07",
            "ditlcm08",
            "ditlcm09"
        ],
        "children": [],
        "vars": {}
    },
    "network-internal": {
        "hosts": [
            "ditlcm01",
            "ditlcm02",
            "ditlcm03",
            "ditlcm04",
            "ditlcm05",
            "ditlcm06",
            "ditlcm07",
            "ditlcm08",
            "ditlcm09"
        ],
        "children": [],
        "vars": {}
    }
}
hudecof picture hudecof on 22 Sep 2017

I recorded second vidoe to show full steps

  • adding new host to inventory
  • syncing the SCP project
  • syncing the inventory
  • check the host exists in inventory
  • run the job template
  • new host is missing(the old one still there)

https://cloud.apps.hudecof.net/s/7kirT0iEp2cBIwb

hudecof picture hudecof on 22 Sep 2017
😄1

Thanks, this is showing no indication that the host is coming from the normal places in the database. We run ansible-playbook using the script endpoint as the inventory source via -i awxrest.py

@chrismeyersfsu is there any mechanism you could imagine of where the fact caching might be resurrecting zombie hosts?

AlanCoding picture AlanCoding on 22 Sep 2017

@hudecof help me understand where ditlcm00-bad might have come from. You mentioned you did interacted with v1 API. Did you create the host ditlcm00-bad under the v1 API ?

Maybe you could get on our IRC @hudecof #ansible-awx on freenode and we could work through this issue.

chrismeyersfsu picture chrismeyersfsu on 25 Sep 2017

@chrismeyersfsu no, I usedAPI just for listing.

The inventory issource based puled from porject/git/. If I restart th e docker instances,the inventory will be up2date. But any subsequent change willnot be propagated, until nect reboot.

This is about any inventiry I create,by UI, or import from project /git/. I vahe version 1.0.0.528

hudecof picture hudecof on 25 Sep 2017 
[DEV] [email protected]: ~ # telnet 172.17.0.4 11211
Trying 172.17.0.4...
Connected to 172.17.0.4.
Escape character is '^]'.
flush all
ERROR
flush_all
OK
quit

this solved my problem, so the inventory for the jo is from memechahe ?

hudecof picture hudecof on 26 Sep 2017

@hudecof we think this might be an issue related to background deletion of inventory. You can confirm/observe this in two ways.

  1. check your task_system.log file for an entry that looks like 2017-09-26 05:51:10,523 ERROR awx.main.tasks Task awx.main.tasks.delete_inventory encountered exception. with a Traceback below it.
  2. awx-manage shell_plus Inventory.objects.filter(pending_deletion=True) All pending deletions should have been deleted by now. If the query prints anything then there is a problem and the inventory is stuck in a pending delete state.
chrismeyersfsu picture chrismeyersfsu on 26 Sep 2017

where are the logs? the /var/log/tower is empty on awx_web nad awx_task

hudecof picture hudecof on 27 Sep 2017

Sorry @hudecof logs don't go to files in the container setup, I was incorrect. Exec into the container and run the 2. listed above.

chrismeyersfsu picture chrismeyersfsu on 27 Sep 2017

entering the containter, as userid 1000

[DEV] [email protected]: /srv/awx/awx # docker run -it awx_web:1.0.0.528  /bin/bash
bash-4.2$ id
uid=1000 gid=0(root) groups=0(root)

listing users

bash-4.2$ getent passwd
root:x:0:0:root:/root:/bin/bash
bin:x:1:1:bin:/bin:/sbin/nologin
daemon:x:2:2:daemon:/sbin:/sbin/nologin
adm:x:3:4:adm:/var/adm:/sbin/nologin
lp:x:4:7:lp:/var/spool/lpd:/sbin/nologin
sync:x:5:0:sync:/sbin:/bin/sync
shutdown:x:6:0:shutdown:/sbin:/sbin/shutdown
halt:x:7:0:halt:/sbin:/sbin/halt
mail:x:8:12:mail:/var/spool/mail:/sbin/nologin
operator:x:11:0:operator:/root:/sbin/nologin
games:x:12:100:games:/usr/games:/sbin/nologin
ftp:x:14:50:FTP User:/var/ftp:/sbin/nologin
nobody:x:99:99:Nobody:/:/sbin/nologin
systemd-network:x:192:192:systemd Network Management:/:/sbin/nologin
dbus:x:81:81:System message bus:/:/sbin/nologin
nginx:x:999:998:Nginx web server:/var/lib/nginx:/sbin/nologin
saslauth:x:998:76:Saslauthd user:/run/saslauthd:/sbin/nologin
tss:x:59:59:Account used by the trousers package to sandbox the tcsd daemon:/dev/null:/sbin/nologin

running awx

bash-4.2$ awx-manage
Traceback (most recent call last):
  File "/usr/bin/awx-manage", line 9, in <module>
    load_entry_point('awx==1.0.0.528', 'console_scripts', 'awx-manage')()
  File "/usr/lib/python2.7/site-packages/awx/__init__.py", line 107, in manage
    execute_from_command_line(sys.argv)
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/core/management/__init__.py", line 354, in execute_from_command_line
    utility.execute()
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/core/management/__init__.py", line 328, in execute
    django.setup()
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/__init__.py", line 18, in setup
    apps.populate(settings.INSTALLED_APPS)
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/apps/registry.py", line 115, in populate
    app_config.ready()
  File "/usr/lib/python2.7/site-packages/awx/conf/apps.py", line 18, in ready
    configure_external_logger(settings)
  File "/usr/lib/python2.7/site-packages/awx/main/utils/handlers.py", line 342, in configure_external_logger
    is_enabled = settings_module.LOG_AGGREGATOR_ENABLED
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/conf/__init__.py", line 49, in __getattr__
    return getattr(self._wrapped, name)
  File "/usr/lib/python2.7/site-packages/awx/conf/settings.py", line 386, in __getattr__
    value = self._get_local(name)
  File "/usr/lib64/python2.7/contextlib.py", line 35, in __exit__
    self.gen.throw(type, value, traceback)
  File "/usr/lib/python2.7/site-packages/awx/conf/settings.py", line 64, in _log_database_error
    if get_tower_migration_version() < '310':
  File "/usr/lib/python2.7/site-packages/awx/main/utils/db.py", line 13, in get_tower_migration_version
    loader = MigrationLoader(connection, ignore_no_migrations=True)
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/migrations/loader.py", line 47, in __init__
    self.build_graph()
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/migrations/loader.py", line 191, in build_graph
    self.applied_migrations = recorder.applied_migrations()
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/migrations/recorder.py", line 59, in applied_migrations
    self.ensure_schema()
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/migrations/recorder.py", line 49, in ensure_schema
    if self.Migration._meta.db_table in self.connection.introspection.table_names(self.connection.cursor()):
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/backends/base/base.py", line 164, in cursor
    cursor = self.make_cursor(self._cursor())
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/backends/base/base.py", line 135, in _cursor
    self.ensure_connection()
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/backends/base/base.py", line 130, in ensure_connection
    self.connect()
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/utils.py", line 98, 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 130, in ensure_connection
    self.connect()
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/transaction_hooks/mixin.py", line 75, in connect
    super(TransactionHooksDatabaseWrapperMixin, self).connect(*a, **kw)
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/backends/base/base.py", line 119, in connect
    self.connection = self.get_new_connection(conn_params)
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/django/db/backends/postgresql_psycopg2/base.py", line 176, in get_new_connection
    connection = Database.connect(**conn_params)
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/psycopg2/__init__.py", line 130, in connect
    conn = _connect(dsn, connection_factory=connection_factory, **kwasync)
django.db.utils.OperationalError: local user with ID 1000 does not exist```

I guess, that UID 1000 should be AWX user. The same in awx_task container.

I'm going to pull new code and rebuild the containers again

hudecof picture hudecof on 27 Sep 2017

dockker logs -f awx_tasks

it was task 164. I see some stack trace there, celery task failed 

[2017-09-27 18:18:21,830: INFO/MainProcess] Scheduler: Sending due task task_manager (awx.main.scheduler.tasks.run_task_manager)
[2017-09-27 18:18:21,832: DEBUG/MainProcess] awx.main.scheduler.tasks.run_task_manager sent. id->6d3936ea-581b-4d1d-9b3c-0aaf5921009c
[2017-09-27 18:18:21,833: DEBUG/MainProcess] beat: Waking up in 19.83 seconds.
[2017-09-27 18:18:21,836: INFO/MainProcess] Received task: awx.main.scheduler.tasks.run_task_manager[6d3936ea-581b-4d1d-9b3c-0aaf5921009c] expires:[2017-09-27 18:18:41.831973+00:00]
[2017-09-27 18:18:21,836: INFO/MainProcess] Scaling up 1 processes.
[2017-09-27 18:18:21,860: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x612e7d0> (args:(u'awx.main.scheduler.tasks.run_task_manager', u'6d3936ea-581b-4d1d-9b3c-0aaf5921009c', [], {}, {u'utc': True, u'is_eager': False, u'chord': None, u'group': None, u'args': [], u'retries': 0, u'delivery_info': {u'priority': None, u'redelivered': False, u'routing_key': u'tower', u'exchange': u'tower'}, u'expires': u'2017-09-27T18:18:41.831973+00:00', u'hostname': 'celery@localhost', u'task': u'awx.main.scheduler.tasks.run_task_manager', u'callbacks': None, u'correlation_id': u'6d3936ea-581b-4d1d-9b3c-0aaf5921009c', u'errbacks': None, u'timelimit': [None, None], u'taskset': None, u'kwargs': {}, u'eta': None, u'reply_to': u'4d9662dd-80df-318f-990c-375d964b5337', u'id': u'6d3936ea-581b-4d1d-9b3c-0aaf5921009c', u'headers': {}}) kwargs:{})
[2017-09-27 18:18:21,869: DEBUG/MainProcess] basic.qos: prefetch_count->32
[2017-09-27 18:18:21,922: DEBUG/MainProcess] Task accepted: awx.main.scheduler.tasks.run_task_manager[6d3936ea-581b-4d1d-9b3c-0aaf5921009c] pid:2204
2017-09-27 18:18:21,976 DEBUG    awx.main.scheduler Running Tower task manager.
2017-09-27 18:18:21,976 DEBUG    awx.main.scheduler Running Tower task manager.
[2017-09-27 18:18:21,976: DEBUG/Worker-20] Running Tower task manager.
2017-09-27 18:18:22,003 DEBUG    awx.main.scheduler Starting Scheduler
2017-09-27 18:18:22,003 DEBUG    awx.main.scheduler Starting Scheduler
[2017-09-27 18:18:22,003: DEBUG/Worker-20] Starting Scheduler
[2017-09-27 18:18:22,107: INFO/MainProcess] Task awx.main.scheduler.tasks.run_task_manager[6d3936ea-581b-4d1d-9b3c-0aaf5921009c] succeeded in 0.188870643964s: None
[2017-09-27 18:18:41,665: INFO/MainProcess] Scheduler: Sending due task cluster_heartbeat (awx.main.tasks.cluster_node_heartbeat)
[2017-09-27 18:18:41,668: DEBUG/MainProcess] awx.main.tasks.cluster_node_heartbeat sent. id->df2aa45b-042e-4588-9dc1-9f74965e5890
[2017-09-27 18:18:41,670: DEBUG/MainProcess] beat: Waking up now.
[2017-09-27 18:18:41,674: INFO/MainProcess] Received task: awx.main.tasks.cluster_node_heartbeat[df2aa45b-042e-4588-9dc1-9f74965e5890] expires:[2017-09-27 18:19:31.667378+00:00]
[2017-09-27 18:18:41,675: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x612e7d0> (args:(u'awx.main.tasks.cluster_node_heartbeat', u'df2aa45b-042e-4588-9dc1-9f74965e5890', [], {}, {u'utc': True, u'is_eager': False, u'chord': None, u'group': None, u'args': [], u'retries': 0, u'delivery_info': {u'priority': None, u'redelivered': False, u'routing_key': u'awx', u'exchange': u'awx'}, u'expires': u'2017-09-27T18:19:31.667378+00:00', u'hostname': 'celery@localhost', u'task': u'awx.main.tasks.cluster_node_heartbeat', u'callbacks': None, u'correlation_id': u'df2aa45b-042e-4588-9dc1-9f74965e5890', u'errbacks': None, u'timelimit': [None, None], u'taskset': None, u'kwargs': {}, u'eta': None, u'reply_to': u'4d9662dd-80df-318f-990c-375d964b5337', u'id': u'df2aa45b-042e-4588-9dc1-9f74965e5890', u'headers': {}}) kwargs:{})
[2017-09-27 18:18:41,682: DEBUG/MainProcess] Task accepted: awx.main.tasks.cluster_node_heartbeat[df2aa45b-042e-4588-9dc1-9f74965e5890] pid:2204
[2017-09-27 18:18:41,700: INFO/MainProcess] Scheduler: Sending due task tower_scheduler (awx.main.tasks.awx_periodic_scheduler)
[2017-09-27 18:18:41,702: DEBUG/MainProcess] awx.main.tasks.awx_periodic_scheduler sent. id->46dc2336-14ae-4b7f-a497-9bb966727b8b
[2017-09-27 18:18:41,705: DEBUG/MainProcess] beat: Waking up now.
[2017-09-27 18:18:41,707: INFO/MainProcess] Received task: awx.main.tasks.awx_periodic_scheduler[46dc2336-14ae-4b7f-a497-9bb966727b8b] expires:[2017-09-27 18:19:01.702091+00:00]
[2017-09-27 18:18:41,708: INFO/MainProcess] Scaling up 1 processes.
[2017-09-27 18:18:41,738: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x612e7d0> (args:(u'awx.main.tasks.awx_periodic_scheduler', u'46dc2336-14ae-4b7f-a497-9bb966727b8b', [], {}, {u'utc': True, u'is_eager': False, u'chord': None, u'group': None, u'args': [], u'retries': 0, u'delivery_info': {u'priority': None, u'redelivered': False, u'routing_key': u'tower', u'exchange': u'tower'}, u'expires': u'2017-09-27T18:19:01.702091+00:00', u'hostname': 'celery@localhost', u'task': u'awx.main.tasks.awx_periodic_scheduler', u'callbacks': None, u'correlation_id': u'46dc2336-14ae-4b7f-a497-9bb966727b8b', u'errbacks': None, u'timelimit': [None, None], u'taskset': None, u'kwargs': {}, u'eta': None, u'reply_to': u'4d9662dd-80df-318f-990c-375d964b5337', u'id': u'46dc2336-14ae-4b7f-a497-9bb966727b8b', u'headers': {}}) kwargs:{})
[2017-09-27 18:18:41,746: DEBUG/MainProcess] basic.qos: prefetch_count->36
2017-09-27 18:18:41,751 DEBUG    awx.main.tasks Cluster node heartbeat task.
2017-09-27 18:18:41,751 DEBUG    awx.main.tasks Cluster node heartbeat task.
[2017-09-27 18:18:41,751: DEBUG/Worker-20] Cluster node heartbeat task.
[2017-09-27 18:18:41,812: INFO/MainProcess] Task awx.main.tasks.cluster_node_heartbeat[df2aa45b-042e-4588-9dc1-9f74965e5890] succeeded in 0.131635713973s: None
[2017-09-27 18:18:41,820: DEBUG/MainProcess] Task accepted: awx.main.tasks.awx_periodic_scheduler[46dc2336-14ae-4b7f-a497-9bb966727b8b] pid:2204
[2017-09-27 18:18:41,832: INFO/MainProcess] Scheduler: Sending due task task_manager (awx.main.scheduler.tasks.run_task_manager)
[2017-09-27 18:18:41,837: DEBUG/MainProcess] awx.main.scheduler.tasks.run_task_manager sent. id->d04b96b2-b7c8-4f58-b34a-48f8509f19f1
[2017-09-27 18:18:41,838: DEBUG/MainProcess] beat: Waking up in 19.99 seconds.
[2017-09-27 18:18:41,855: INFO/MainProcess] Received task: awx.main.scheduler.tasks.run_task_manager[d04b96b2-b7c8-4f58-b34a-48f8509f19f1] expires:[2017-09-27 18:19:01.835350+00:00]
[2017-09-27 18:18:41,859: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x612e7d0> (args:(u'awx.main.scheduler.tasks.run_task_manager', u'd04b96b2-b7c8-4f58-b34a-48f8509f19f1', [], {}, {u'utc': True, u'is_eager': False, u'chord': None, u'group': None, u'args': [], u'retries': 0, u'delivery_info': {u'priority': None, u'redelivered': False, u'routing_key': u'tower', u'exchange': u'tower'}, u'expires': u'2017-09-27T18:19:01.835350+00:00', u'hostname': 'celery@localhost', u'task': u'awx.main.scheduler.tasks.run_task_manager', u'callbacks': None, u'correlation_id': u'd04b96b2-b7c8-4f58-b34a-48f8509f19f1', u'errbacks': None, u'timelimit': [None, None], u'taskset': None, u'kwargs': {}, u'eta': None, u'reply_to': u'4d9662dd-80df-318f-990c-375d964b5337', u'id': u'd04b96b2-b7c8-4f58-b34a-48f8509f19f1', u'headers': {}}) kwargs:{})
2017-09-27 18:18:41,886 DEBUG    awx.main.tasks Last scheduler run was: 2017-09-27 18:18:11.747102+00:00
2017-09-27 18:18:41,886 DEBUG    awx.main.tasks Last scheduler run was: 2017-09-27 18:18:11.747102+00:00
[2017-09-27 18:18:41,886: DEBUG/Worker-20] Last scheduler run was: 2017-09-27 18:18:11.747102+00:00
[2017-09-27 18:18:41,927: INFO/MainProcess] Task awx.main.tasks.awx_periodic_scheduler[46dc2336-14ae-4b7f-a497-9bb966727b8b] succeeded in 0.113360044081s: None
[2017-09-27 18:18:41,934: DEBUG/MainProcess] Task accepted: awx.main.scheduler.tasks.run_task_manager[d04b96b2-b7c8-4f58-b34a-48f8509f19f1] pid:2204
2017-09-27 18:18:41,984 DEBUG    awx.main.scheduler Running Tower task manager.
2017-09-27 18:18:41,984 DEBUG    awx.main.scheduler Running Tower task manager.
[2017-09-27 18:18:41,984: DEBUG/Worker-20] Running Tower task manager.
2017-09-27 18:18:42,004 DEBUG    awx.main.scheduler Starting Scheduler
2017-09-27 18:18:42,004 DEBUG    awx.main.scheduler Starting Scheduler
[2017-09-27 18:18:42,004: DEBUG/Worker-20] Starting Scheduler
[2017-09-27 18:18:42,083: INFO/MainProcess] Task awx.main.scheduler.tasks.run_task_manager[d04b96b2-b7c8-4f58-b34a-48f8509f19f1] succeeded in 0.150789886946s: None
[2017-09-27 18:18:45,061: INFO/MainProcess] Received task: awx.main.tasks.update_inventory_computed_fields[5fc222d6-7076-41dd-984f-aee8567a67f6]
[2017-09-27 18:18:45,062: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x612e7d0> (args:(u'awx.main.tasks.update_inventory_computed_fields', u'5fc222d6-7076-41dd-984f-aee8567a67f6', [5, True], {}, {u'utc': True, u'is_eager': False, u'chord': None, u'group': None, u'args': [5, True], 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@localhost', u'task': u'awx.main.tasks.update_inventory_computed_fields', u'callbacks': None, u'correlation_id': u'5fc222d6-7076-41dd-984f-aee8567a67f6', u'errbacks': None, u'timelimit': [None, None], u'taskset': None, u'kwargs': {}, u'eta': None, u'reply_to': u'b628d2d0-58b9-3023-b5c6-cd430568be36', u'id': u'5fc222d6-7076-41dd-984f-aee8567a67f6', u'headers': {}}) kwargs:{})
[2017-09-27 18:18:45,068: DEBUG/MainProcess] Task accepted: awx.main.tasks.update_inventory_computed_fields[5fc222d6-7076-41dd-984f-aee8567a67f6] pid:2204
2017-09-27 18:18:45,132 DEBUG    awx.main.models.inventory Going to update inventory computed fields
[2017-09-27 18:18:45,132: DEBUG/Worker-20] Going to update inventory computed fields
2017-09-27 18:18:45,272 DEBUG    awx.main.models.inventory Finished updating inventory computed fields
[2017-09-27 18:18:45,272: DEBUG/Worker-20] Finished updating inventory computed fields
[2017-09-27 18:18:45,286: INFO/MainProcess] Task awx.main.tasks.update_inventory_computed_fields[5fc222d6-7076-41dd-984f-aee8567a67f6] succeeded in 0.221799880965s: None
[2017-09-27 18:18:45,352: INFO/MainProcess] Received task: awx.main.scheduler.tasks.run_job_launch[93fbf1f5-6fb7-4d2e-846c-abc1a51779a5]
[2017-09-27 18:18:45,352: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x612e7d0> (args:(u'awx.main.scheduler.tasks.run_job_launch', u'93fbf1f5-6fb7-4d2e-846c-abc1a51779a5', [164], {}, {u'utc': True, u'is_eager': False, u'chord': None, u'group': None, u'args': [164], u'retries': 0, u'delivery_info': {u'priority': None, u'redelivered': False, u'routing_key': u'tower_scheduler.job.launch', u'exchange': u'scheduler'}, u'expires': None, u'hostname': 'celery@localhost', u'task': u'awx.main.scheduler.tasks.run_job_launch', u'callbacks': None, u'correlation_id': u'93fbf1f5-6fb7-4d2e-846c-abc1a51779a5', u'errbacks': None, u'timelimit': [None, None], u'taskset': None, u'kwargs': {}, u'eta': None, u'reply_to': u'b628d2d0-58b9-3023-b5c6-cd430568be36', u'id': u'93fbf1f5-6fb7-4d2e-846c-abc1a51779a5', u'headers': {}}) kwargs:{})
[2017-09-27 18:18:45,359: DEBUG/MainProcess] Task accepted: awx.main.scheduler.tasks.run_job_launch[93fbf1f5-6fb7-4d2e-846c-abc1a51779a5] pid:2205
2017-09-27 18:18:45,442 DEBUG    awx.main.scheduler Starting Scheduler
2017-09-27 18:18:45,442 DEBUG    awx.main.scheduler Starting Scheduler
[2017-09-27 18:18:45,442: DEBUG/Worker-21] Starting Scheduler
2017-09-27 18:18:46,182 DEBUG    awx.main.scheduler Starting dependent project_update 165 (pending) in group tower
2017-09-27 18:18:46,182 DEBUG    awx.main.scheduler Starting dependent project_update 165 (pending) in group tower
[2017-09-27 18:18:46,182: DEBUG/Worker-21] Starting dependent project_update 165 (pending) in group tower
2017-09-27 18:18:46,184 INFO     awx.main.scheduler Submitting project_update 165 (waiting) to instance group 1.
2017-09-27 18:18:46,184 INFO     awx.main.scheduler Submitting project_update 165 (waiting) to instance group 1.
[2017-09-27 18:18:46,184: INFO/Worker-21] Submitting project_update 165 (waiting) to instance group 1.
2017-09-27 18:18:46,248 DEBUG    awx.main.scheduler project_update 165 (waiting) consumed 20 capacity units from tower with prior total of 0
2017-09-27 18:18:46,248 DEBUG    awx.main.scheduler project_update 165 (waiting) consumed 20 capacity units from tower with prior total of 0
[2017-09-27 18:18:46,248: DEBUG/Worker-21] project_update 165 (waiting) consumed 20 capacity units from tower with prior total of 0
2017-09-27 18:18:46,248 DEBUG    awx.main.scheduler job 164 (pending) is blocked from running
2017-09-27 18:18:46,248 DEBUG    awx.main.scheduler job 164 (pending) is blocked from running
[2017-09-27 18:18:46,248: DEBUG/Worker-21] job 164 (pending) is blocked from running
[2017-09-27 18:18:46,327: DEBUG/Worker-21] 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-2017 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@5650c52f217a', u'platform': u'Erlang/OTP 19.2.1', u'version': u'3.6.12'}, mechanisms: [u'AMQPLAIN', u'PLAIN'], locales: [u'en_US']
[2017-09-27 18:18:46,332: DEBUG/Worker-21] Open OK!
[2017-09-27 18:18:46,333: DEBUG/Worker-21] using channel_id: 1
[2017-09-27 18:18:46,338: DEBUG/Worker-21] Channel open
[2017-09-27 18:18:46,426: DEBUG/Worker-21] 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-2017 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@5650c52f217a', u'platform': u'Erlang/OTP 19.2.1', u'version': u'3.6.12'}, mechanisms: [u'AMQPLAIN', u'PLAIN'], locales: [u'en_US']
[2017-09-27 18:18:46,434: DEBUG/Worker-21] Open OK!
[2017-09-27 18:18:46,434: DEBUG/Worker-21] using channel_id: 1
[2017-09-27 18:18:46,436: DEBUG/Worker-21] Channel open
[2017-09-27 18:18:46,565: DEBUG/Worker-21] 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-2017 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@5650c52f217a', u'platform': u'Erlang/OTP 19.2.1', u'version': u'3.6.12'}, mechanisms: [u'AMQPLAIN', u'PLAIN'], locales: [u'en_US']
[2017-09-27 18:18:46,569: DEBUG/Worker-21] Open OK!
[2017-09-27 18:18:46,570: DEBUG/Worker-21] using channel_id: 1
[2017-09-27 18:18:46,572: DEBUG/Worker-21] Channel open
[2017-09-27 18:18:46,587: INFO/MainProcess] Received task: awx.main.tasks.run_project_update[d369780b-b898-42bb-979d-6345a13fbf01]
[2017-09-27 18:18:46,589: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x612e7d0> (args:(u'awx.main.tasks.run_project_update', u'd369780b-b898-42bb-979d-6345a13fbf01', [165], {}, {u'utc': True, u'is_eager': False, u'chord': None, u'group': None, u'args': [165], 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@localhost', u'task': u'awx.main.tasks.run_project_update', u'callbacks': [{u'chord_size': None, u'task': u'awx.main.tasks.handle_work_success', u'args': [], u'immutable': False, u'subtask_type': None, u'kwargs': {u'task_actual': {u'type': u'project_update', u'id': 165}}, u'options': {}}], u'correlation_id': u'd369780b-b898-42bb-979d-6345a13fbf01', u'errbacks': [{u'chord_size': None, u'task': u'awx.main.tasks.handle_work_error', u'args': [], u'immutable': False, u'subtask_type': None, u'kwargs': {u'subtasks': [{u'type': u'project_update', u'id': 165}, {u'type': u'job', u'id': 164}]}, u'options': {}}], u'timelimit': [None, None], u'taskset': None, u'kwargs': {}, u'eta': None,... kwargs:{})
[2017-09-27 18:18:46,607: DEBUG/MainProcess] Task accepted: awx.main.tasks.run_project_update[d369780b-b898-42bb-979d-6345a13fbf01] pid:2204
[2017-09-27 18:18:46,631: INFO/MainProcess] Task awx.main.scheduler.tasks.run_job_launch[93fbf1f5-6fb7-4d2e-846c-abc1a51779a5] succeeded in 1.274232939s: None
[2017-09-27 18:18:47,230: DEBUG/Worker-20] 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-2017 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@5650c52f217a', u'platform': u'Erlang/OTP 19.2.1', u'version': u'3.6.12'}, mechanisms: [u'AMQPLAIN', u'PLAIN'], locales: [u'en_US']
[2017-09-27 18:18:47,234: DEBUG/Worker-20] Open OK!
[2017-09-27 18:18:47,234: DEBUG/Worker-20] using channel_id: 1
[2017-09-27 18:18:47,236: DEBUG/Worker-20] Channel open
[2017-09-27 18:18:47,271: DEBUG/Worker-20] 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-2017 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@5650c52f217a', u'platform': u'Erlang/OTP 19.2.1', u'version': u'3.6.12'}, mechanisms: [u'AMQPLAIN', u'PLAIN'], locales: [u'en_US']
[2017-09-27 18:18:47,275: DEBUG/Worker-20] Open OK!
[2017-09-27 18:18:47,275: DEBUG/Worker-20] using channel_id: 1
[2017-09-27 18:18:47,276: DEBUG/Worker-20] Channel open
[2017-09-27 18:19:00,690: DEBUG/Worker-20] 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-2017 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@5650c52f217a', u'platform': u'Erlang/OTP 19.2.1', u'version': u'3.6.12'}, mechanisms: [u'AMQPLAIN', u'PLAIN'], locales: [u'en_US']
[2017-09-27 18:19:00,695: DEBUG/Worker-20] Open OK!
[2017-09-27 18:19:00,696: DEBUG/Worker-20] using channel_id: 1
[2017-09-27 18:19:00,697: DEBUG/Worker-20] Channel open
[2017-09-27 18:19:00,708: INFO/MainProcess] Received task: awx.main.tasks.handle_work_success[272a61e0-3c3b-4774-8b7d-18088360a7ae]
[2017-09-27 18:19:00,709: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x612e7d0> (args:(u'awx.main.tasks.handle_work_success', u'272a61e0-3c3b-4774-8b7d-18088360a7ae', [None], {u'task_actual': {u'type': u'project_update', u'id': 165}}, {u'utc': True, u'is_eager': False, u'chord': None, u'group': None, u'args': [None], 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@localhost', u'task': u'awx.main.tasks.handle_work_success', u'callbacks': None, u'correlation_id': u'272a61e0-3c3b-4774-8b7d-18088360a7ae', u'errbacks': None, u'timelimit': [None, None], u'taskset': None, u'kwargs': {u'task_actual': {u'type': u'project_update', u'id': 165}}, u'eta': None, u'reply_to': u'f04b931a-360d-36ba-a7d9-d3d48e91ef54', u'id': u'272a61e0-3c3b-4774-8b7d-18088360a7ae', u'headers': {}}) kwargs:{})
[2017-09-27 18:19:00,717: DEBUG/MainProcess] Task accepted: awx.main.tasks.handle_work_success[272a61e0-3c3b-4774-8b7d-18088360a7ae] pid:2205
[2017-09-27 18:19:00,724: INFO/MainProcess] Task awx.main.tasks.run_project_update[d369780b-b898-42bb-979d-6345a13fbf01] succeeded in 14.129072836s: None
[2017-09-27 18:19:00,830: INFO/MainProcess] Received task: awx.main.scheduler.tasks.run_job_complete[cfbed9e7-125c-44cb-b9da-270a2aabb10e]
[2017-09-27 18:19:00,830: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x612e7d0> (args:(u'awx.main.scheduler.tasks.run_job_complete', u'cfbed9e7-125c-44cb-b9da-270a2aabb10e', [165], {}, {u'utc': True, u'is_eager': False, u'chord': None, u'group': None, u'args': [165], u'retries': 0, u'delivery_info': {u'priority': None, u'redelivered': False, u'routing_key': u'tower_scheduler.job.complete', u'exchange': u'scheduler'}, u'expires': None, u'hostname': 'celery@localhost', u'task': u'awx.main.scheduler.tasks.run_job_complete', u'callbacks': None, u'correlation_id': u'cfbed9e7-125c-44cb-b9da-270a2aabb10e', u'errbacks': None, u'timelimit': [None, None], u'taskset': None, u'kwargs': {}, u'eta': None, u'reply_to': u'6c63246b-853b-3187-876f-3f6cfb40a9f5', u'id': u'cfbed9e7-125c-44cb-b9da-270a2aabb10e', u'headers': {}}) kwargs:{})
[2017-09-27 18:19:00,839: DEBUG/MainProcess] Task accepted: awx.main.scheduler.tasks.run_job_complete[cfbed9e7-125c-44cb-b9da-270a2aabb10e] pid:2204
[2017-09-27 18:19:00,861: INFO/MainProcess] Task awx.main.tasks.handle_work_success[272a61e0-3c3b-4774-8b7d-18088360a7ae] succeeded in 0.148544619908s: None
2017-09-27 18:19:00,920 DEBUG    awx.main.scheduler Starting Scheduler
2017-09-27 18:19:00,920 DEBUG    awx.main.scheduler Starting Scheduler
[2017-09-27 18:19:00,920: DEBUG/Worker-20] Starting Scheduler
2017-09-27 18:19:01,088 DEBUG    awx.main.scheduler Starting job 164 (pending) in group tower (remaining_capacity=125)
2017-09-27 18:19:01,088 DEBUG    awx.main.scheduler Starting job 164 (pending) in group tower (remaining_capacity=125)
[2017-09-27 18:19:01,088: DEBUG/Worker-20] Starting job 164 (pending) in group tower (remaining_capacity=125)
2017-09-27 18:19:01,101 INFO     awx.main.scheduler Submitting job 164 (waiting) to instance group 1.
2017-09-27 18:19:01,101 INFO     awx.main.scheduler Submitting job 164 (waiting) to instance group 1.
[2017-09-27 18:19:01,101: INFO/Worker-20] Submitting job 164 (waiting) to instance group 1.
2017-09-27 18:19:01,181 DEBUG    awx.main.scheduler job 164 (waiting) consumed 50 capacity units from tower with prior total of 0
2017-09-27 18:19:01,181 DEBUG    awx.main.scheduler job 164 (waiting) consumed 50 capacity units from tower with prior total of 0
[2017-09-27 18:19:01,181: DEBUG/Worker-20] job 164 (waiting) consumed 50 capacity units from tower with prior total of 0
[2017-09-27 18:19:01,206: INFO/MainProcess] Received task: awx.main.tasks.run_job[3058327c-af5c-4d1d-aa97-b2c72f1b8e93]
[2017-09-27 18:19:01,210: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x612e7d0> (args:(u'awx.main.tasks.run_job', u'3058327c-af5c-4d1d-aa97-b2c72f1b8e93', [164], {}, {u'utc': True, u'is_eager': False, u'chord': None, u'group': None, u'args': [164], 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@localhost', u'task': u'awx.main.tasks.run_job', u'callbacks': [{u'chord_size': None, u'task': u'awx.main.tasks.handle_work_success', u'args': [], u'immutable': False, u'subtask_type': None, u'kwargs': {u'task_actual': {u'type': u'job', u'id': 164}}, u'options': {}}], u'correlation_id': u'3058327c-af5c-4d1d-aa97-b2c72f1b8e93', u'errbacks': [{u'chord_size': None, u'task': u'awx.main.tasks.handle_work_error', u'args': [], u'immutable': False, u'subtask_type': None, u'kwargs': {u'subtasks': [{u'type': u'job', u'id': 164}]}, u'options': {}}], u'timelimit': [None, None], u'taskset': None, u'kwargs': {}, u'eta': None, u'reply_to': u'f04b931a-360d-36ba-a7d9-d3d48e91ef54', u'id':... kwargs:{})
[2017-09-27 18:19:01,216: DEBUG/MainProcess] Task accepted: awx.main.tasks.run_job[3058327c-af5c-4d1d-aa97-b2c72f1b8e93] pid:2205
[2017-09-27 18:19:01,228: INFO/MainProcess] Task awx.main.scheduler.tasks.run_job_complete[cfbed9e7-125c-44cb-b9da-270a2aabb10e] succeeded in 0.390348867979s: None
[2017-09-27 18:19:01,846: INFO/MainProcess] Scheduler: Sending due task task_manager (awx.main.scheduler.tasks.run_task_manager)
[2017-09-27 18:19:01,849: DEBUG/MainProcess] awx.main.scheduler.tasks.run_task_manager sent. id->970b9651-5af4-40b1-bd69-b17192ea4629
[2017-09-27 18:19:01,850: DEBUG/MainProcess] beat: Waking up in 9.84 seconds.
[2017-09-27 18:19:01,851: INFO/MainProcess] Received task: awx.main.scheduler.tasks.run_task_manager[970b9651-5af4-40b1-bd69-b17192ea4629] expires:[2017-09-27 18:19:21.848287+00:00]
[2017-09-27 18:19:01,852: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x612e7d0> (args:(u'awx.main.scheduler.tasks.run_task_manager', u'970b9651-5af4-40b1-bd69-b17192ea4629', [], {}, {u'utc': True, u'is_eager': False, u'chord': None, u'group': None, u'args': [], u'retries': 0, u'delivery_info': {u'priority': None, u'redelivered': False, u'routing_key': u'tower', u'exchange': u'tower'}, u'expires': u'2017-09-27T18:19:21.848287+00:00', u'hostname': 'celery@localhost', u'task': u'awx.main.scheduler.tasks.run_task_manager', u'callbacks': None, u'correlation_id': u'970b9651-5af4-40b1-bd69-b17192ea4629', u'errbacks': None, u'timelimit': [None, None], u'taskset': None, u'kwargs': {}, u'eta': None, u'reply_to': u'4d9662dd-80df-318f-990c-375d964b5337', u'id': u'970b9651-5af4-40b1-bd69-b17192ea4629', u'headers': {}}) kwargs:{})
[2017-09-27 18:19:01,859: DEBUG/MainProcess] Task accepted: awx.main.scheduler.tasks.run_task_manager[970b9651-5af4-40b1-bd69-b17192ea4629] pid:2204
2017-09-27 18:19:01,902 DEBUG    awx.main.scheduler Running Tower task manager.
2017-09-27 18:19:01,902 DEBUG    awx.main.scheduler Running Tower task manager.
[2017-09-27 18:19:01,902: DEBUG/Worker-20] Running Tower task manager.
2017-09-27 18:19:01,916 DEBUG    awx.main.scheduler Starting Scheduler
2017-09-27 18:19:01,916 DEBUG    awx.main.scheduler Starting Scheduler
[2017-09-27 18:19:01,916: DEBUG/Worker-20] Starting Scheduler
[2017-09-27 18:19:02,132: INFO/MainProcess] Task awx.main.scheduler.tasks.run_task_manager[970b9651-5af4-40b1-bd69-b17192ea4629] succeeded in 0.279067306081s: None
[2017-09-27 18:19:11,706: INFO/MainProcess] Scheduler: Sending due task tower_scheduler (awx.main.tasks.awx_periodic_scheduler)
[2017-09-27 18:19:11,710: DEBUG/MainProcess] awx.main.tasks.awx_periodic_scheduler sent. id->a51a43ba-4025-44a4-b94e-8bc7ea8b20c9
[2017-09-27 18:19:11,711: DEBUG/MainProcess] beat: Waking up in 10.13 seconds.
[2017-09-27 18:19:11,715: INFO/MainProcess] Received task: awx.main.tasks.awx_periodic_scheduler[a51a43ba-4025-44a4-b94e-8bc7ea8b20c9] expires:[2017-09-27 18:19:31.708019+00:00]
[2017-09-27 18:19:11,716: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x612e7d0> (args:(u'awx.main.tasks.awx_periodic_scheduler', u'a51a43ba-4025-44a4-b94e-8bc7ea8b20c9', [], {}, {u'utc': True, u'is_eager': False, u'chord': None, u'group': None, u'args': [], u'retries': 0, u'delivery_info': {u'priority': None, u'redelivered': False, u'routing_key': u'tower', u'exchange': u'tower'}, u'expires': u'2017-09-27T18:19:31.708019+00:00', u'hostname': 'celery@localhost', u'task': u'awx.main.tasks.awx_periodic_scheduler', u'callbacks': None, u'correlation_id': u'a51a43ba-4025-44a4-b94e-8bc7ea8b20c9', u'errbacks': None, u'timelimit': [None, None], u'taskset': None, u'kwargs': {}, u'eta': None, u'reply_to': u'4d9662dd-80df-318f-990c-375d964b5337', u'id': u'a51a43ba-4025-44a4-b94e-8bc7ea8b20c9', u'headers': {}}) kwargs:{})
[2017-09-27 18:19:11,723: DEBUG/MainProcess] Task accepted: awx.main.tasks.awx_periodic_scheduler[a51a43ba-4025-44a4-b94e-8bc7ea8b20c9] pid:2204
2017-09-27 18:19:11,771 DEBUG    awx.main.tasks Last scheduler run was: 2017-09-27 18:18:41.880385+00:00
2017-09-27 18:19:11,771 DEBUG    awx.main.tasks Last scheduler run was: 2017-09-27 18:18:41.880385+00:00
[2017-09-27 18:19:11,771: DEBUG/Worker-20] Last scheduler run was: 2017-09-27 18:18:41.880385+00:00
[2017-09-27 18:19:11,824: INFO/MainProcess] Task awx.main.tasks.awx_periodic_scheduler[a51a43ba-4025-44a4-b94e-8bc7ea8b20c9] succeeded in 0.107114761951s: None
[2017-09-27 18:19:12,983: INFO/MainProcess] Scaling down 1 processes.
[2017-09-27 18:19:12,987: DEBUG/MainProcess] basic.qos: prefetch_count->32
[2017-09-27 18:19:21,849: INFO/MainProcess] Scheduler: Sending due task task_manager (awx.main.scheduler.tasks.run_task_manager)
[2017-09-27 18:19:21,852: DEBUG/MainProcess] awx.main.scheduler.tasks.run_task_manager sent. id->a9929dbd-f2bf-41e1-af02-ea788bddc46f
[2017-09-27 18:19:21,853: DEBUG/MainProcess] beat: Waking up in 19.81 seconds.
[2017-09-27 18:19:21,854: INFO/MainProcess] Received task: awx.main.scheduler.tasks.run_task_manager[a9929dbd-f2bf-41e1-af02-ea788bddc46f] expires:[2017-09-27 18:19:41.851104+00:00]
[2017-09-27 18:19:21,854: INFO/MainProcess] Scaling up 1 processes.
[2017-09-27 18:19:21,880: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x612e7d0> (args:(u'awx.main.scheduler.tasks.run_task_manager', u'a9929dbd-f2bf-41e1-af02-ea788bddc46f', [], {}, {u'utc': True, u'is_eager': False, u'chord': None, u'group': None, u'args': [], u'retries': 0, u'delivery_info': {u'priority': None, u'redelivered': False, u'routing_key': u'tower', u'exchange': u'tower'}, u'expires': u'2017-09-27T18:19:41.851104+00:00', u'hostname': 'celery@localhost', u'task': u'awx.main.scheduler.tasks.run_task_manager', u'callbacks': None, u'correlation_id': u'a9929dbd-f2bf-41e1-af02-ea788bddc46f', u'errbacks': None, u'timelimit': [None, None], u'taskset': None, u'kwargs': {}, u'eta': None, u'reply_to': u'4d9662dd-80df-318f-990c-375d964b5337', u'id': u'a9929dbd-f2bf-41e1-af02-ea788bddc46f', u'headers': {}}) kwargs:{})
[2017-09-27 18:19:21,885: DEBUG/MainProcess] basic.qos: prefetch_count->36
[2017-09-27 18:19:21,942: DEBUG/MainProcess] Task accepted: awx.main.scheduler.tasks.run_task_manager[a9929dbd-f2bf-41e1-af02-ea788bddc46f] pid:2470
2017-09-27 18:19:22,001 DEBUG    awx.main.scheduler Running Tower task manager.
2017-09-27 18:19:22,001 DEBUG    awx.main.scheduler Running Tower task manager.
[2017-09-27 18:19:22,001: DEBUG/Worker-22] Running Tower task manager.
2017-09-27 18:19:22,042 DEBUG    awx.main.scheduler Starting Scheduler
2017-09-27 18:19:22,042 DEBUG    awx.main.scheduler Starting Scheduler
[2017-09-27 18:19:22,042: DEBUG/Worker-22] Starting Scheduler
[2017-09-27 18:19:22,206: INFO/MainProcess] Task awx.main.scheduler.tasks.run_task_manager[a9929dbd-f2bf-41e1-af02-ea788bddc46f] succeeded in 0.266471324023s: None
[2017-09-27 18:19:31,344: DEBUG/Worker-21] 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-2017 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@5650c52f217a', u'platform': u'Erlang/OTP 19.2.1', u'version': u'3.6.12'}, mechanisms: [u'AMQPLAIN', u'PLAIN'], locales: [u'en_US']
[2017-09-27 18:19:31,354: DEBUG/Worker-21] Open OK!
[2017-09-27 18:19:31,355: DEBUG/Worker-21] using channel_id: 1
[2017-09-27 18:19:31,369: DEBUG/Worker-21] Channel open
[2017-09-27 18:19:41,687: INFO/MainProcess] Scheduler: Sending due task cluster_heartbeat (awx.main.tasks.cluster_node_heartbeat)
[2017-09-27 18:19:41,691: DEBUG/MainProcess] awx.main.tasks.cluster_node_heartbeat sent. id->22dba1db-59d9-43ce-8d83-305e8f6cb2af
[2017-09-27 18:19:41,698: DEBUG/MainProcess] beat: Waking up now.
[2017-09-27 18:19:41,709: INFO/MainProcess] Scheduler: Sending due task tower_scheduler (awx.main.tasks.awx_periodic_scheduler)
[2017-09-27 18:19:41,730: INFO/MainProcess] Received task: awx.main.tasks.cluster_node_heartbeat[22dba1db-59d9-43ce-8d83-305e8f6cb2af] expires:[2017-09-27 18:20:31.690268+00:00]
[2017-09-27 18:19:41,743: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x612e7d0> (args:(u'awx.main.tasks.cluster_node_heartbeat', u'22dba1db-59d9-43ce-8d83-305e8f6cb2af', [], {}, {u'utc': True, u'is_eager': False, u'chord': None, u'group': None, u'args': [], u'retries': 0, u'delivery_info': {u'priority': None, u'redelivered': False, u'routing_key': u'awx', u'exchange': u'awx'}, u'expires': u'2017-09-27T18:20:31.690268+00:00', u'hostname': 'celery@localhost', u'task': u'awx.main.tasks.cluster_node_heartbeat', u'callbacks': None, u'correlation_id': u'22dba1db-59d9-43ce-8d83-305e8f6cb2af', u'errbacks': None, u'timelimit': [None, None], u'taskset': None, u'kwargs': {}, u'eta': None, u'reply_to': u'4d9662dd-80df-318f-990c-375d964b5337', u'id': u'22dba1db-59d9-43ce-8d83-305e8f6cb2af', u'headers': {}}) kwargs:{})
[2017-09-27 18:19:41,726: DEBUG/MainProcess] awx.main.tasks.awx_periodic_scheduler sent. id->2fc194c5-1845-452e-a3c1-4a7d2842461c
[2017-09-27 18:19:41,740: DEBUG/MainProcess] beat: Waking up now.
[2017-09-27 18:19:41,758: INFO/MainProcess] Received task: awx.main.tasks.awx_periodic_scheduler[2fc194c5-1845-452e-a3c1-4a7d2842461c] expires:[2017-09-27 18:20:01.725259+00:00]
[2017-09-27 18:19:41,759: INFO/MainProcess] Scaling up 1 processes.
[2017-09-27 18:19:41,876: INFO/MainProcess] Scheduler: Sending due task task_manager (awx.main.scheduler.tasks.run_task_manager)
[2017-09-27 18:19:41,884: DEBUG/MainProcess] awx.main.scheduler.tasks.run_task_manager sent. id->4430c517-b01e-43d0-989b-a565d32dd652
[2017-09-27 18:19:41,896: DEBUG/MainProcess] beat: Waking up in 19.99 seconds.
[2017-09-27 18:19:41,939: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x612e7d0> (args:(u'awx.main.tasks.awx_periodic_scheduler', u'2fc194c5-1845-452e-a3c1-4a7d2842461c', [], {}, {u'utc': True, u'is_eager': False, u'chord': None, u'group': None, u'args': [], u'retries': 0, u'delivery_info': {u'priority': None, u'redelivered': False, u'routing_key': u'tower', u'exchange': u'tower'}, u'expires': u'2017-09-27T18:20:01.725259+00:00', u'hostname': 'celery@localhost', u'task': u'awx.main.tasks.awx_periodic_scheduler', u'callbacks': None, u'correlation_id': u'2fc194c5-1845-452e-a3c1-4a7d2842461c', u'errbacks': None, u'timelimit': [None, None], u'taskset': None, u'kwargs': {}, u'eta': None, u'reply_to': u'4d9662dd-80df-318f-990c-375d964b5337', u'id': u'2fc194c5-1845-452e-a3c1-4a7d2842461c', u'headers': {}}) kwargs:{})
[2017-09-27 18:19:42,022: INFO/MainProcess] Received task: awx.main.scheduler.tasks.run_task_manager[4430c517-b01e-43d0-989b-a565d32dd652] expires:[2017-09-27 18:20:01.883785+00:00]
[2017-09-27 18:19:42,024: INFO/MainProcess] Scaling up 1 processes.
[2017-09-27 18:19:42,184: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x612e7d0> (args:(u'awx.main.scheduler.tasks.run_task_manager', u'4430c517-b01e-43d0-989b-a565d32dd652', [], {}, {u'utc': True, u'is_eager': False, u'chord': None, u'group': None, u'args': [], u'retries': 0, u'delivery_info': {u'priority': None, u'redelivered': False, u'routing_key': u'tower', u'exchange': u'tower'}, u'expires': u'2017-09-27T18:20:01.883785+00:00', u'hostname': 'celery@localhost', u'task': u'awx.main.scheduler.tasks.run_task_manager', u'callbacks': None, u'correlation_id': u'4430c517-b01e-43d0-989b-a565d32dd652', u'errbacks': None, u'timelimit': [None, None], u'taskset': None, u'kwargs': {}, u'eta': None, u'reply_to': u'4d9662dd-80df-318f-990c-375d964b5337', u'id': u'4430c517-b01e-43d0-989b-a565d32dd652', u'headers': {}}) kwargs:{})
[2017-09-27 18:19:42,243: DEBUG/MainProcess] basic.qos: prefetch_count->44
[2017-09-27 18:19:42,276: DEBUG/MainProcess] Task accepted: awx.main.tasks.cluster_node_heartbeat[22dba1db-59d9-43ce-8d83-305e8f6cb2af] pid:2470
2017-09-27 18:19:42,372 DEBUG    awx.main.tasks Cluster node heartbeat task.
2017-09-27 18:19:42,372 DEBUG    awx.main.tasks Cluster node heartbeat task.
[2017-09-27 18:19:42,372: DEBUG/Worker-22] Cluster node heartbeat task.
[2017-09-27 18:19:42,589: INFO/MainProcess] Task awx.main.tasks.cluster_node_heartbeat[22dba1db-59d9-43ce-8d83-305e8f6cb2af] succeeded in 0.342665578937s: None
[2017-09-27 18:19:42,605: DEBUG/MainProcess] Task accepted: awx.main.tasks.awx_periodic_scheduler[2fc194c5-1845-452e-a3c1-4a7d2842461c] pid:2470
2017-09-27 18:19:42,688 DEBUG    awx.main.tasks Last scheduler run was: 2017-09-27 18:19:11.765118+00:00
2017-09-27 18:19:42,688 DEBUG    awx.main.tasks Last scheduler run was: 2017-09-27 18:19:11.765118+00:00
[2017-09-27 18:19:42,688: DEBUG/Worker-22] Last scheduler run was: 2017-09-27 18:19:11.765118+00:00
[2017-09-27 18:19:42,784: INFO/MainProcess] Task awx.main.tasks.awx_periodic_scheduler[2fc194c5-1845-452e-a3c1-4a7d2842461c] succeeded in 0.187130314065s: None
[2017-09-27 18:19:42,807: DEBUG/MainProcess] Task accepted: awx.main.scheduler.tasks.run_task_manager[4430c517-b01e-43d0-989b-a565d32dd652] pid:2470
2017-09-27 18:19:42,883 DEBUG    awx.main.scheduler Running Tower task manager.
2017-09-27 18:19:42,883 DEBUG    awx.main.scheduler Running Tower task manager.
[2017-09-27 18:19:42,883: DEBUG/Worker-22] Running Tower task manager.
2017-09-27 18:19:42,939 DEBUG    awx.main.scheduler Starting Scheduler
2017-09-27 18:19:42,939 DEBUG    awx.main.scheduler Starting Scheduler
[2017-09-27 18:19:42,939: DEBUG/Worker-22] Starting Scheduler
[2017-09-27 18:19:43,313: INFO/MainProcess] Task awx.main.scheduler.tasks.run_task_manager[4430c517-b01e-43d0-989b-a565d32dd652] succeeded in 0.509390862077s: None
[2017-09-27 18:20:01,908: INFO/MainProcess] Scheduler: Sending due task task_manager (awx.main.scheduler.tasks.run_task_manager)
[2017-09-27 18:20:01,911: DEBUG/MainProcess] beat: Synchronizing schedule...
[2017-09-27 18:20:01,924: INFO/MainProcess] Received task: awx.main.scheduler.tasks.run_task_manager[153a8c48-586c-4159-96d3-19faec8af0de] expires:[2017-09-27 18:20:21.910229+00:00]
[2017-09-27 18:20:01,925: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x612e7d0> (args:(u'awx.main.scheduler.tasks.run_task_manager', u'153a8c48-586c-4159-96d3-19faec8af0de', [], {}, {u'utc': True, u'is_eager': False, u'chord': None, u'group': None, u'args': [], u'retries': 0, u'delivery_info': {u'priority': None, u'redelivered': False, u'routing_key': u'tower', u'exchange': u'tower'}, u'expires': u'2017-09-27T18:20:21.910229+00:00', u'hostname': 'celery@localhost', u'task': u'awx.main.scheduler.tasks.run_task_manager', u'callbacks': None, u'correlation_id': u'153a8c48-586c-4159-96d3-19faec8af0de', u'errbacks': None, u'timelimit': [None, None], u'taskset': None, u'kwargs': {}, u'eta': None, u'reply_to': u'4d9662dd-80df-318f-990c-375d964b5337', u'id': u'153a8c48-586c-4159-96d3-19faec8af0de', u'headers': {}}) kwargs:{})
[2017-09-27 18:20:01,946: DEBUG/MainProcess] awx.main.scheduler.tasks.run_task_manager sent. id->153a8c48-586c-4159-96d3-19faec8af0de
[2017-09-27 18:20:01,947: DEBUG/MainProcess] beat: Waking up in 9.75 seconds.
[2017-09-27 18:20:01,942: DEBUG/MainProcess] Task accepted: awx.main.scheduler.tasks.run_task_manager[153a8c48-586c-4159-96d3-19faec8af0de] pid:2637
2017-09-27 18:20:01,998 DEBUG    awx.main.scheduler Running Tower task manager.
2017-09-27 18:20:01,998 DEBUG    awx.main.scheduler Running Tower task manager.
[2017-09-27 18:20:01,998: DEBUG/Worker-23] Running Tower task manager.
2017-09-27 18:20:02,030 DEBUG    awx.main.scheduler Starting Scheduler
2017-09-27 18:20:02,030 DEBUG    awx.main.scheduler Starting Scheduler
[2017-09-27 18:20:02,030: DEBUG/Worker-23] Starting Scheduler
[2017-09-27 18:20:02,235: INFO/MainProcess] Task awx.main.scheduler.tasks.run_task_manager[153a8c48-586c-4159-96d3-19faec8af0de] succeeded in 0.307201721007s: None
2017-09-27 18:20:10,192 DEBUG    awx.main.models.inventory Going to update inventory computed fields
2017-09-27 18:20:10,265 DEBUG    awx.main.models.inventory Finished updating inventory computed fields
[2017-09-27 18:20:10,452: INFO/MainProcess] Received task: awx.main.tasks.update_inventory_computed_fields[aa32bba6-ed3f-462c-93fe-b0306591a476]
[2017-09-27 18:20:10,453: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x612e7d0> (args:(u'awx.main.tasks.update_inventory_computed_fields', u'aa32bba6-ed3f-462c-93fe-b0306591a476', [5, True], {}, {u'utc': True, u'is_eager': False, u'chord': None, u'group': None, u'args': [5, True], 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@localhost', u'task': u'awx.main.tasks.update_inventory_computed_fields', u'callbacks': None, u'correlation_id': u'aa32bba6-ed3f-462c-93fe-b0306591a476', u'errbacks': None, u'timelimit': [None, None], u'taskset': None, u'kwargs': {}, u'eta': None, u'reply_to': u'6c63246b-853b-3187-876f-3f6cfb40a9f5', u'id': u'aa32bba6-ed3f-462c-93fe-b0306591a476', u'headers': {}}) kwargs:{})
[2017-09-27 18:20:10,461: DEBUG/MainProcess] Task accepted: awx.main.tasks.update_inventory_computed_fields[aa32bba6-ed3f-462c-93fe-b0306591a476] pid:2470
2017-09-27 18:20:10,485 WARNING  awx.main.tasks %s encountered an error (rc=%s), please see task stdout for details.
2017-09-27 18:20:10,485 WARNING  awx.main.tasks %s encountered an error (rc=%s), please see task stdout for details.
[2017-09-27 18:20:10,485: WARNING/Worker-21] %s encountered an error (rc=%s), please see task stdout for details.
[2017-09-27 18:20:10,503: INFO/MainProcess] Received task: awx.main.tasks.handle_work_error[da0cdc19-0d91-407b-8090-3d41c4afffdb]
[2017-09-27 18:20:10,504: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x612e7d0> (args:(u'awx.main.tasks.handle_work_error', u'da0cdc19-0d91-407b-8090-3d41c4afffdb', [u'3058327c-af5c-4d1d-aa97-b2c72f1b8e93'], {u'subtasks': [{u'type': u'job', u'id': 164}]}, {u'utc': True, u'is_eager': False, u'chord': None, u'group': u'f9d6e6cb-837d-472c-9cba-f3e733d83d4e', u'args': [u'3058327c-af5c-4d1d-aa97-b2c72f1b8e93'], 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@localhost', u'task': u'awx.main.tasks.handle_work_error', u'callbacks': None, u'correlation_id': u'da0cdc19-0d91-407b-8090-3d41c4afffdb', u'errbacks': None, u'timelimit': [None, None], u'taskset': u'f9d6e6cb-837d-472c-9cba-f3e733d83d4e', u'kwargs': {u'subtasks': [{u'type': u'job', u'id': 164}]}, u'eta': None, u'reply_to': u'6c63246b-853b-3187-876f-3f6cfb40a9f5', u'id': u'da0cdc19-0d91-407b-8090-3d41c4afffdb', u'headers': {}}) kwargs:{})
[2017-09-27 18:20:10,510: DEBUG/MainProcess] Task accepted: awx.main.tasks.handle_work_error[da0cdc19-0d91-407b-8090-3d41c4afffdb] pid:2642
[2017-09-27 18:20:10,532: ERROR/MainProcess] Task awx.main.tasks.run_job[3058327c-af5c-4d1d-aa97-b2c72f1b8e93] raised unexpected: TaskError('%s encountered an error (rc=%s), please see task stdout for details.',)
Traceback (most recent call last):
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/celery/app/trace.py", line 240, in trace_task
    R = retval = fun(*args, **kwargs)
  File "/var/lib/awx/venv/awx/lib/python2.7/site-packages/celery/app/trace.py", line 438, in __protected_call__
    return self.run(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/awx/main/tasks.py", line 470, in _wrapped
    return f(self, *args, **kwargs)
  File "/usr/lib/python2.7/site-packages/awx/main/tasks.py", line 911, in run
    raise TaskError(instance, rc)
TaskError: %s encountered an error (rc=%s), please see task stdout for details.
2017-09-27 18:20:10,548 DEBUG    awx.main.models.inventory Going to update inventory computed fields
[2017-09-27 18:20:10,548: DEBUG/Worker-22] Going to update inventory computed fields
2017-09-27 18:20:10,583 DEBUG    awx.main.tasks Executing error task id da0cdc19-0d91-407b-8090-3d41c4afffdb, subtasks: [{u'type': u'job', u'id': 164}]
2017-09-27 18:20:10,583 DEBUG    awx.main.tasks Executing error task id da0cdc19-0d91-407b-8090-3d41c4afffdb, subtasks: [{u'type': u'job', u'id': 164}]
[2017-09-27 18:20:10,583: DEBUG/Worker-24] Executing error task id da0cdc19-0d91-407b-8090-3d41c4afffdb, subtasks: [{u'type': u'job', u'id': 164}]
[2017-09-27 18:20:10,784: DEBUG/Worker-24] 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-2017 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@5650c52f217a', u'platform': u'Erlang/OTP 19.2.1', u'version': u'3.6.12'}, mechanisms: [u'AMQPLAIN', u'PLAIN'], locales: [u'en_US']
[2017-09-27 18:20:10,794: DEBUG/Worker-24] Open OK!
[2017-09-27 18:20:10,794: DEBUG/Worker-24] using channel_id: 1
[2017-09-27 18:20:10,804: DEBUG/Worker-24] Channel open
2017-09-27 18:20:10,806 DEBUG    awx.main.models.inventory Finished updating inventory computed fields
[2017-09-27 18:20:10,806: DEBUG/Worker-22] Finished updating inventory computed fields
[2017-09-27 18:20:10,849: INFO/MainProcess] Received task: awx.main.scheduler.tasks.run_job_complete[450cb9a5-ac86-4f8d-bad9-b85f11a98df6]
[2017-09-27 18:20:10,849: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x612e7d0> (args:(u'awx.main.scheduler.tasks.run_job_complete', u'450cb9a5-ac86-4f8d-bad9-b85f11a98df6', [164], {}, {u'utc': True, u'is_eager': False, u'chord': None, u'group': None, u'args': [164], u'retries': 0, u'delivery_info': {u'priority': None, u'redelivered': False, u'routing_key': u'tower_scheduler.job.complete', u'exchange': u'scheduler'}, u'expires': None, u'hostname': 'celery@localhost', u'task': u'awx.main.scheduler.tasks.run_job_complete', u'callbacks': None, u'correlation_id': u'450cb9a5-ac86-4f8d-bad9-b85f11a98df6', u'errbacks': None, u'timelimit': [None, None], u'taskset': None, u'kwargs': {}, u'eta': None, u'reply_to': u'df258cc0-b7d5-3793-b634-6ba780ef8950', u'id': u'450cb9a5-ac86-4f8d-bad9-b85f11a98df6', u'headers': {}}) kwargs:{})
[2017-09-27 18:20:10,867: DEBUG/MainProcess] Task accepted: awx.main.scheduler.tasks.run_job_complete[450cb9a5-ac86-4f8d-bad9-b85f11a98df6] pid:2637
[2017-09-27 18:20:10,890: INFO/MainProcess] Task awx.main.tasks.update_inventory_computed_fields[aa32bba6-ed3f-462c-93fe-b0306591a476] succeeded in 0.434342626948s: None
[2017-09-27 18:20:10,961: INFO/MainProcess] Task awx.main.tasks.handle_work_error[da0cdc19-0d91-407b-8090-3d41c4afffdb] succeeded in 0.454032443929s: None
2017-09-27 18:20:11,025 DEBUG    awx.main.scheduler Starting Scheduler
2017-09-27 18:20:11,025 DEBUG    awx.main.scheduler Starting Scheduler
[2017-09-27 18:20:11,025: DEBUG/Worker-23] Starting Scheduler
[2017-09-27 18:20:11,254: INFO/MainProcess] Task awx.main.scheduler.tasks.run_job_complete[450cb9a5-ac86-4f8d-bad9-b85f11a98df6] succeeded in 0.396689206013s: None
[2017-09-27 18:20:11,713: INFO/MainProcess] Scheduler: Sending due task tower_scheduler (awx.main.tasks.awx_periodic_scheduler)
[2017-09-27 18:20:11,716: DEBUG/MainProcess] awx.main.tasks.awx_periodic_scheduler sent. id->a8d8b7ba-44e5-4db3-82d6-7048b8fcb721
[2017-09-27 18:20:11,722: INFO/MainProcess] Received task: awx.main.tasks.awx_periodic_scheduler[a8d8b7ba-44e5-4db3-82d6-7048b8fcb721] expires:[2017-09-27 18:20:31.715620+00:00]
[2017-09-27 18:20:11,723: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x612e7d0> (args:(u'awx.main.tasks.awx_periodic_scheduler', u'a8d8b7ba-44e5-4db3-82d6-7048b8fcb721', [], {}, {u'utc': True, u'is_eager': False, u'chord': None, u'group': None, u'args': [], u'retries': 0, u'delivery_info': {u'priority': None, u'redelivered': False, u'routing_key': u'tower', u'exchange': u'tower'}, u'expires': u'2017-09-27T18:20:31.715620+00:00', u'hostname': 'celery@localhost', u'task': u'awx.main.tasks.awx_periodic_scheduler', u'callbacks': None, u'correlation_id': u'a8d8b7ba-44e5-4db3-82d6-7048b8fcb721', u'errbacks': None, u'timelimit': [None, None], u'taskset': None, u'kwargs': {}, u'eta': None, u'reply_to': u'4d9662dd-80df-318f-990c-375d964b5337', u'id': u'a8d8b7ba-44e5-4db3-82d6-7048b8fcb721', u'headers': {}}) kwargs:{})
[2017-09-27 18:20:11,730: DEBUG/MainProcess] Task accepted: awx.main.tasks.awx_periodic_scheduler[a8d8b7ba-44e5-4db3-82d6-7048b8fcb721] pid:2205
[2017-09-27 18:20:11,734: DEBUG/MainProcess] beat: Waking up in 10.18 seconds.
2017-09-27 18:20:11,779 DEBUG    awx.main.tasks Last scheduler run was: 2017-09-27 18:19:42.681643+00:00
2017-09-27 18:20:11,779 DEBUG    awx.main.tasks Last scheduler run was: 2017-09-27 18:19:42.681643+00:00
[2017-09-27 18:20:11,779: DEBUG/Worker-21] Last scheduler run was: 2017-09-27 18:19:42.681643+00:00
[2017-09-27 18:20:11,817: INFO/MainProcess] Task awx.main.tasks.awx_periodic_scheduler[a8d8b7ba-44e5-4db3-82d6-7048b8fcb721] succeeded in 0.092109938967s: None
[2017-09-27 18:20:12,989: INFO/MainProcess] Scaling down 4 processes.
[2017-09-27 18:20:21,920: INFO/MainProcess] Scheduler: Sending due task task_manager (awx.main.scheduler.tasks.run_task_manager)
[2017-09-27 18:20:21,923: DEBUG/MainProcess] awx.main.scheduler.tasks.run_task_manager sent. id->283f8443-e256-4345-bd26-cf4f2cd21b55
[2017-09-27 18:20:21,924: DEBUG/MainProcess] beat: Waking up in 19.75 seconds.
[2017-09-27 18:20:21,927: INFO/MainProcess] Received task: awx.main.scheduler.tasks.run_task_manager[283f8443-e256-4345-bd26-cf4f2cd21b55] expires:[2017-09-27 18:20:41.922006+00:00]
[2017-09-27 18:20:21,927: INFO/MainProcess] Scaling up 1 processes.
[2017-09-27 18:20:21,950: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x612e7d0> (args:(u'awx.main.scheduler.tasks.run_task_manager', u'283f8443-e256-4345-bd26-cf4f2cd21b55', [], {}, {u'utc': True, u'is_eager': False, u'chord': None, u'group': None, u'args': [], u'retries': 0, u'delivery_info': {u'priority': None, u'redelivered': False, u'routing_key': u'tower', u'exchange': u'tower'}, u'expires': u'2017-09-27T18:20:41.922006+00:00', u'hostname': 'celery@localhost', u'task': u'awx.main.scheduler.tasks.run_task_manager', u'callbacks': None, u'correlation_id': u'283f8443-e256-4345-bd26-cf4f2cd21b55', u'errbacks': None, u'timelimit': [None, None], u'taskset': None, u'kwargs': {}, u'eta': None, u'reply_to': u'4d9662dd-80df-318f-990c-375d964b5337', u'id': u'283f8443-e256-4345-bd26-cf4f2cd21b55', u'headers': {}}) kwargs:{})
[2017-09-27 18:20:21,958: DEBUG/MainProcess] basic.qos: prefetch_count->48
[2017-09-27 18:20:22,012: DEBUG/MainProcess] Task accepted: awx.main.scheduler.tasks.run_task_manager[283f8443-e256-4345-bd26-cf4f2cd21b55] pid:3070
2017-09-27 18:20:22,066 DEBUG    awx.main.scheduler Running Tower task manager.
2017-09-27 18:20:22,066 DEBUG    awx.main.scheduler Running Tower task manager.
[2017-09-27 18:20:22,066: DEBUG/Worker-25] Running Tower task manager.
2017-09-27 18:20:22,095 DEBUG    awx.main.scheduler Starting Scheduler
2017-09-27 18:20:22,095 DEBUG    awx.main.scheduler Starting Scheduler
[2017-09-27 18:20:22,095: DEBUG/Worker-25] Starting Scheduler
[2017-09-27 18:20:22,229: INFO/MainProcess] Task awx.main.scheduler.tasks.run_task_manager[283f8443-e256-4345-bd26-cf4f2cd21b55] succeeded in 0.220079993946s: None
hudecof picture hudecof on 27 Sep 2017 
[DEV] [email protected]: /srv/awx/awx/installer # docker run -u 0 -it  --link postgres ansible/awx_web bash

I needed to export

  • DATABASE_HOST
  • DATABASE_USER
  • DATABASE_PASSWORD
  • DATABASE_NAME
[root@6fcfde840182 awx]# awx-manage shell_plus
# Shell Plus Model Imports
from awx.conf.models import Setting
from awx.main.models.activity_stream import ActivityStream
from awx.main.models.ad_hoc_commands import AdHocCommand, AdHocCommandEvent
from awx.main.models.channels import ChannelGroup
from awx.main.models.credential import Credential, CredentialType
from awx.main.models.fact import Fact
from awx.main.models.ha import Instance, InstanceGroup, JobOrigin, TowerScheduleState
from awx.main.models.inventory import CustomInventoryScript, Group, Host, Inventory, InventorySource, InventoryUpdate, SmartInventoryMembership
from awx.main.models.jobs import Job, JobEvent, JobHostSummary, JobTemplate, SystemJob, SystemJobTemplate
from awx.main.models.label import Label
from awx.main.models.notifications import Notification, NotificationTemplate
from awx.main.models.organization import AuthToken, Organization, Profile, Team
from awx.main.models.projects import Project, ProjectUpdate
from awx.main.models.rbac import Role, RoleAncestorEntry
from awx.main.models.schedules import Schedule
from awx.main.models.unified_jobs import UnifiedJob, UnifiedJobTemplate
from awx.main.models.workflow import WorkflowJob, WorkflowJobNode, WorkflowJobTemplate, WorkflowJobTemplateNode
from awx.sso.models import UserEnterpriseAuth
from django.contrib.auth.models import Group, Permission, User
from django.contrib.contenttypes.models import ContentType
from django.contrib.sessions.models import Session
from django.contrib.sites.models import Site
from djcelery.models import CrontabSchedule, IntervalSchedule, PeriodicTask, PeriodicTasks, TaskMeta, TaskSetMeta, TaskState, WorkerState
from kombu.transport.django.models import Message, Queue
from social.apps.django_app.default.models import Association, Code, Nonce, UserSocialAuth
from taggit.models import Tag, TaggedItem
# Shell Plus Django Imports
from django.utils import timezone
from django.conf import settings
from django.core.cache import cache
from django.contrib.auth import get_user_model
from django.db.models import Avg, Case, Count, F, Max, Min, Prefetch, Q, Sum, When
from django.db import transaction
from django.core.urlresolvers import reverse
Python 2.7.5 (default, Aug  4 2017, 00:39:18)
[GCC 4.8.5 20150623 (Red Hat 4.8.5-16)] on linux2
Type "help", "copyright", "credits" or "license" for more information.
(InteractiveConsole)
>>> Inventory.objects.filter(pending_deletion=True)
[]
>>>
hudecof picture hudecof on 27 Sep 2017

I was able to reproduce the issue having selected the "Use Fact Cache" checkbox in the template settings. Disabling the fact cache made AWX send the updated inventory to Ansible without further issues.

I'm using docker.io/ansible/awx_task:sha256:9810846357ae19f8fac8c16fc22ad2cabd6706203fbba3ed1ff39ccdbbc34021 (latest tag as of today).

bcdonadio picture bcdonadio on 1 Oct 2017

turining off Use Fact Cache solved my problems. I though that it is somethink like facts caching im using in CLI version.

hudecof picture hudecof on 1 Oct 2017

We are unable to reproduce this. @bcdonadio can you provide detailed steps to reproduce?

chrismeyersfsu picture chrismeyersfsu on 2 Oct 2017

I was able to reproduce with Ansible 2.4 This is an issue.

Ansible 2.4 + fact caching don't play nice. Effectively, hosts that were in a inventory (but were since removed) can show up in a JT run. This is because Ansible now uses the fact cache for dynamic inventory scripts. Specifically, they hash the name of the dynamic inventory script that is given on the command line (i.e. ansible-playbook -i ./ec2.py main.yml ec2.py would be the cache value). Combine this with how Tower generates it's inventory, one single awx.py and you have a problem. https://github.com/ansible/ansible/blob/stable-2.4/lib/ansible/plugins/inventory/script.py#L101

chrismeyersfsu picture chrismeyersfsu on 2 Oct 2017

It looks like this is going to be remedied in Ansible 2.4.1 so stay tuned for a few weeks.

matburt picture matburt on 3 Oct 2017

yes, I'm using ansible 2.4, it's latest version in the EPEL directory.
I'm glad, that you are able to reptoduce it and looking forward for the fix.

hudecof picture hudecof on 3 Oct 2017

Related: https://github.com/ansible/ansible/pull/30817

If you re-test with development version of Ansible, this may be fixed.

https://github.com/ansible/ansible/issues/31260

AlanCoding picture AlanCoding on 3 Oct 2017

I verified the fix slated for ansible-2.4.1 https://github.com/ansible/ansible/pull/31262

@hudecof You can use Ansible devel in your container once the above linked PR lands.

You can install the devel version of Ansible by either rebuilding the container to include devel version of ansible or docker exec and pip install ansible. Note that the pop-up in tower that tells you the version of Ansible (or /api/v2/config) is generated by running ansible --version and is cached. So that information may not update. If you wait (5 minutes I think) or clear/delete the memcached container the it will update.

docker exec -it awx_task /bin/bash
pip install git+git://github.com/bcoca/ansible.git@devel

If you do try this let us know if it works, or not, for you!

chrismeyersfsu picture chrismeyersfsu on 4 Oct 2017

@chrismeyersfsu I will try, but I need to downgrade the AWX version, since Ihave another blocking issue https://github.com/ansible/awx/issues/367

hudecof picture hudecof on 5 Oct 2017 
[root@awx awx]# ansible --version
ansible 2.5.0
  config file = /etc/ansible/ansible.cfg
  configured module search path = [u'/root/.ansible/plugins/modules', u'/usr/share/ansible/plugins/modules']
  ansible python module location = /usr/lib/python2.7/site-packages/ansible
  executable location = /usr/bin/ansible
  python version = 2.7.5 (default, Aug  4 2017, 00:39:18) [GCC 4.8.5 20150623 (Red Hat 4.8.5-16)]
  • run the template job
  • add host to inventory

    • update git pore

    • update project

    • update invetory from source

  • run the template job

the nre host did not appear

hudecof picture hudecof on 5 Oct 2017

the API is still showing me the 2.4.0 version

hudecof picture hudecof on 5 Oct 2017

I upgraded the ansible alo in the awx_web. API shows version 2.5.0, but did not helped

hudecof picture hudecof on 5 Oct 2017

I believe this is in 2.4.1 which should release soon... we also have a workaround that will get merged soon. Can you try the latest 2.4.X/RC and let us know what you see?

matburt picture matburt on 11 Oct 2017

i tried latest 1.0.1.13 with ansible 2.4.0.0 with no success. Going to upgrade the ansible

hudecof picture hudecof on 11 Oct 2017

v2.4.1.0-0.3.rc1 seem to be OK

[root@awx awx]# ansible --version
ansible 2.4.1.0
  config file = /etc/ansible/ansible.cfg
  configured module search path = [u'/root/.ansible/plugins/modules', u'/usr/share/ansible/plugins/modules']
  ansible python module location = /usr/lib/python2.7/site-packages/ansible
  executable location = /usr/bin/ansible
  python version = 2.7.5 (default, Aug  4 2017, 00:39:18) [GCC 4.8.5 20150623 (Red Hat 4.8.5-16)]
hudecof picture hudecof on 12 Oct 2017
👍1
Was this page helpful?
0 / 5 - 0 ratings

Related issues

cs35-owncloud picture cs35-owncloud  路  3Comments
darkaxl picture darkaxl  路  3Comments
IshwarKanse picture IshwarKanse  路  3Comments
shortsteps picture shortsteps  路  3Comments
astraios picture astraios  路  3Comments