system_tracking logging for fact cache

awx/main/models/jobs.py

@@ -46,6 +46,7 @@ from awx.main.consumers import emit_channel_notification
 
 logger = logging.getLogger('awx.main.models.jobs')
 analytics_logger = logging.getLogger('awx.analytics.job_events')
+system_tracking_logger = logging.getLogger('awx.analytics.system_tracking')
 
 __all__ = ['JobTemplate', 'Job', 'JobHostSummary', 'JobEvent', 'SystemJobOptions', 'SystemJobTemplate', 'SystemJob']
 
@@ -774,6 +775,10 @@ class Job(UnifiedJob, JobOptions, SurveyJobMixin, JobNotificationMixin):
                 host.ansible_facts = ansible_facts
                 host.ansible_facts_modified = modified
                 host.save()
+                system_tracking_logger.info('New fact for inventory {} host {}'.format(host.inventory.name, host.name),
+                                            extra=dict(inventory_id=host.inventory.id, host_name=host.name,
+                                                       ansible_facts=host.ansible_facts,
+                                                       ansible_facts_modified=host.ansible_facts_modified.isoformat()))
 
 
 class JobHostSummary(CreatedModifiedModel):

awx/main/tests/unit/models/test_jobs.py

@@ -38,18 +38,18 @@ def new_time():
 
 
 @pytest.fixture
-def hosts(old_time):
+def hosts(old_time, inventory):
     return [
-        Host(name='host1', ansible_facts={"a": 1, "b": 2}, ansible_facts_modified=old_time),
+        Host(name='host1', ansible_facts={"a": 1, "b": 2}, ansible_facts_modified=old_time, inventory=inventory),
-        Host(name='host2', ansible_facts={"a": 1, "b": 2}, ansible_facts_modified=old_time),
+        Host(name='host2', ansible_facts={"a": 1, "b": 2}, ansible_facts_modified=old_time, inventory=inventory),
-        Host(name='host3', ansible_facts={"a": 1, "b": 2}, ansible_facts_modified=old_time),
+        Host(name='host3', ansible_facts={"a": 1, "b": 2}, ansible_facts_modified=old_time, inventory=inventory),
     ]
 
 
 @pytest.fixture
-def hosts2():
+def hosts2(inventory):
     return [
-        Host(name='host2', ansible_facts="foobar", ansible_facts_modified=old_time),
+        Host(name='host2', ansible_facts="foobar", ansible_facts_modified=old_time, inventory=inventory),
     ]
 
 

awx/main/tests/unit/utils/test_handlers.py

@@ -4,6 +4,8 @@ import cStringIO
 import json
 import logging
 import socket
+import datetime
+from dateutil.tz import tzutc
 from uuid import uuid4
 
 import mock
@@ -135,7 +137,7 @@ def test_base_logging_handler_emit(dummy_log_record):
     assert body['message'] == 'User joe logged in'
 
 
-def test_base_logging_handler_emit_one_record_per_fact():
+def test_base_logging_handler_emit_system_tracking():
     handler = BaseHandler(host='127.0.0.1', enabled_flag=True,
                           message_type='logstash', indv_facts=True,
                           enabled_loggers=['awx', 'activity_stream', 'job_events', 'system_tracking'])
@@ -149,27 +151,20 @@ def test_base_logging_handler_emit_one_record_per_fact():
         tuple(), # args,
         None # exc_info
     )
-    record.module_name = 'packages'
+    record.inventory_id = 11
-    record.facts_data = [{
+    record.host_name = 'my_lucky_host'
-        "name": "ansible",
+    record.ansible_facts = {
-        "version": "2.2.1.0"
+        "ansible_kernel": "4.4.66-boot2docker",
-    }, {
+        "ansible_machine": "x86_64",
-        "name": "ansible-tower",
+        "ansible_swapfree_mb": 4663,
-        "version": "3.1.0"
+    }
-    }]
+    record.ansible_facts_modified = datetime.datetime.now(tzutc()).isoformat()
     sent_payloads = handler.emit(record)
 
-    assert len(sent_payloads) == 2
+    assert len(sent_payloads) == 1
-    sent_payloads.sort(key=lambda payload: payload['version'])
+    assert sent_payloads[0]['ansible_facts'] == record.ansible_facts
-
     assert sent_payloads[0]['level'] == 'INFO'
     assert sent_payloads[0]['logger_name'] == 'awx.analytics.system_tracking'
-    assert sent_payloads[0]['name'] == 'ansible'
-    assert sent_payloads[0]['version'] == '2.2.1.0'
-    assert sent_payloads[1]['level'] == 'INFO'
-    assert sent_payloads[1]['logger_name'] == 'awx.analytics.system_tracking'
-    assert sent_payloads[1]['name'] == 'ansible-tower'
-    assert sent_payloads[1]['version'] == '3.1.0'
 
 
 @pytest.mark.parametrize('host, port, normalized, hostname_only', [

awx/main/utils/formatters.py

@@ -44,7 +44,7 @@ class LogstashFormatter(LogstashFormatterVersion1):
             'processName', 'relativeCreated', 'thread', 'threadName', 'extra',
             'auth_token', 'tags', 'host', 'host_id', 'level', 'port', 'uuid'))
         if kind == 'system_tracking':
-            data = copy(raw_data['facts_data'])
+            data = copy(raw_data['ansible_facts'])
         elif kind == 'job_events':
             data = copy(raw_data['event_model_data'])
         else:
@@ -99,17 +99,14 @@ class LogstashFormatter(LogstashFormatterVersion1):
                     val = self.format_timestamp(time_float)
                 data_for_log[key] = val
         elif kind == 'system_tracking':
-            module_name = raw_data['module_name']
+            data.pop('ansible_python_version', None)
-            if module_name in ['services', 'packages', 'files']:
+            if 'ansible_python' in data:
-                data_for_log[module_name] = index_by_name(data)
+                data['ansible_python'].pop('version_info', None)
-            elif module_name == 'ansible':
+
-                data_for_log['ansible'] = data
+            data_for_log['ansible_facts'] = data
-                # Remove sub-keys with data type conflicts in elastic search
+            data_for_log['ansible_facts_modified'] = raw_data['ansible_facts_modified']
-                data_for_log['ansible'].pop('ansible_python_version', None)
+            data_for_log['inventory_id'] = raw_data['inventory_id']
-                data_for_log['ansible']['ansible_python'].pop('version_info', None)
+            data_for_log['host_name'] = raw_data['host_name']
-            else:
-                data_for_log['facts'] = data
-            data_for_log['module_name'] = module_name
         elif kind == 'performance':
             request = raw_data['python_objects']['request']
             response = raw_data['python_objects']['response']

awx/main/utils/handlers.py

@@ -112,28 +112,10 @@ class BaseHandler(logging.Handler):
         """
         return payload
 
-    def _send_and_queue_system_tracking(self, payload_data):
-        # Special action for System Tracking, queue up multiple log messages
-        ret = []
-        module_name = payload_data['module_name']
-        if module_name in ['services', 'packages', 'files']:
-            facts_dict = payload_data.pop(module_name)
-            for key in facts_dict:
-                fact_payload = copy(payload_data)
-                fact_payload.update(facts_dict[key])
-                ret.append(self._send(fact_payload))
-        return ret
-
     def _format_and_send_record(self, record):
-        ret = []
-        payload = self.format(record)
         if self.indv_facts:
-            payload_data = json.loads(payload)
+            return [self._send(json.loads(self.format(record)))]
-            if record.name.startswith('awx.analytics.system_tracking'):
+        return [self._send(self.format(record))]
-                ret.extend(self._send_and_queue_system_tracking(payload_data))
-        if len(ret) == 0:
-            ret.append(self._send(payload))
-        return ret
 
     def _skip_log(self, logger_name):
         if self.host == '' or (not self.enabled_flag):