Merge pull request #2088 from mitre/VIRTS-1785-event-log-auto

Auto event log generation when operation finishes

app/objects/c_operation.py

@@ -1,4 +1,5 @@
 import asyncio
+import json
 import logging
 import re
 import uuid
@@ -247,22 +248,40 @@ async def event_logs(self, file_svc, data_svc, output=False):
 
     async def run(self, services):
         # load objective
-        obj = await services.get('data_svc').locate('objectives', match=dict(id=self.adversary.objective))
-        if obj == []:
-            obj = await services.get('data_svc').locate('objectives', match=dict(name='default'))
-        self.objective = deepcopy(obj[0])
+        data_svc = services.get('data_svc')
+        await self._load_objective(data_svc)
         try:
             # Operation cedes control to planner
             planner = await self._get_planning_module(services)
             await planner.execute()
             while not await self.is_closeable():
                 await asyncio.sleep(10)
             await self.close(services)
+
+            # Automatic event log output
+            await self.write_event_logs_to_disk(services.get('file_svc'), data_svc, output=True)
         except Exception as e:
             logging.error(e, exc_info=True)
 
+    async def write_event_logs_to_disk(self, file_svc, data_svc, output=False):
+        event_logs = await self.event_logs(file_svc, data_svc, output=output)
+        event_logs_dir = await file_svc.create_exfil_sub_directory('%s/event_logs' % self.get_config('reports_dir'))
+        file_name = 'operation_%s.json' % self.id
+        await self._write_logs_to_disk(event_logs, file_name, event_logs_dir, file_svc)
+        logging.debug('Wrote event logs for operation %s to disk at %s/%s' % (self.name, event_logs_dir, file_name))
+
     """ PRIVATE """
 
+    async def _write_logs_to_disk(self, logs, file_name, dest_dir, file_svc):
+        logs_dumps = json.dumps(logs)
+        await file_svc.save_file(file_name, logs_dumps.encode(), dest_dir, encrypt=False)
+
+    async def _load_objective(self, data_svc):
+        obj = await data_svc.locate('objectives', match=dict(id=self.adversary.objective))
+        if not obj:
+            obj = await data_svc.locate('objectives', match=dict(name='default'))
+        self.objective = deepcopy(obj[0])
+
     async def _convert_link_to_event_log(self, link, file_svc, data_svc, output=False):
         event_dict = dict(command=link.command,
                           delegated_timestamp=link.decide.strftime('%Y-%m-%d %H:%M:%S'),

tests/objects/test_operation.py

@@ -1,3 +1,5 @@
+import json
+import os
 import pytest
 
 from base64 import b64encode
@@ -11,7 +13,7 @@
 @pytest.fixture
 def operation_agent(agent):
     return agent(sleep_min=30, sleep_max=60, watchdog=0, platform='windows', host='WORKSTATION',
-                 username='testagent', architecture='amd64', group='red', location='C:\\Users\\Public\\test.exe',
+                 username='testagent', architecture='amd64', group='red', location=r'C:\Users\Public\test.exe',
                  pid=1234, ppid=123, executors=['psh'], privilege='User', exe_name='test.exe', contact='unknown',
                  paw='testpaw')
 
@@ -88,7 +90,7 @@ def test_event_logs(self, loop, op_for_event_logs, operation_agent, file_svc, da
             group='red',
             architecture='amd64',
             username='testagent',
-            location='C:\\Users\\Public\\test.exe',
+            location=r'C:\Users\Public\test.exe',
             pid=1234,
             ppid=123,
             privilege='User',
@@ -146,3 +148,78 @@ def test_event_logs(self, loop, op_for_event_logs, operation_agent, file_svc, da
         ]
         event_logs = loop.run_until_complete(op_for_event_logs.event_logs(file_svc, data_svc))
         assert event_logs == want
+
+    def test_writing_event_logs_to_disk(self, loop, op_for_event_logs, operation_agent, file_svc, data_svc):
+        loop.run_until_complete(data_svc.store(operation_agent))
+        start_time = op_for_event_logs.start.strftime('%Y-%m-%d %H:%M:%S')
+        agent_creation_time = operation_agent.created.strftime('%Y-%m-%d %H:%M:%S')
+        want_agent_metadata = dict(
+            paw='testpaw',
+            group='red',
+            architecture='amd64',
+            username='testagent',
+            location=r'C:\Users\Public\test.exe',
+            pid=1234,
+            ppid=123,
+            privilege='User',
+            host='WORKSTATION',
+            contact='unknown',
+            created=agent_creation_time,
+        )
+        want_operation_metadata = dict(
+            operation_name='test',
+            operation_start=start_time,
+            operation_adversary='test adversary',
+        )
+        want_attack_metadata = dict(
+            tactic='test tactic',
+            technique_name='test technique',
+            technique_id='T0000',
+        )
+        want = [
+            dict(
+                command='d2hvYW1p',
+                delegated_timestamp='2021-01-01 08:00:00',
+                collected_timestamp='2021-01-01 08:01:00',
+                finished_timestamp='2021-01-01 08:02:00',
+                status=0,
+                platform='windows',
+                executor='psh',
+                pid=789,
+                agent_metadata=want_agent_metadata,
+                ability_metadata=dict(
+                    ability_id='123',
+                    ability_name='test ability',
+                    ability_description='test ability desc',
+                ),
+                operation_metadata=want_operation_metadata,
+                attack_metadata=want_attack_metadata,
+            ),
+            dict(
+                command='aG9zdG5hbWU=',
+                delegated_timestamp='2021-01-01 09:00:00',
+                collected_timestamp='2021-01-01 09:01:00',
+                finished_timestamp='2021-01-01 09:02:00',
+                status=0,
+                platform='windows',
+                executor='psh',
+                pid=7890,
+                agent_metadata=want_agent_metadata,
+                ability_metadata=dict(
+                    ability_id='456',
+                    ability_name='test ability 2',
+                    ability_description='test ability 2 desc',
+                ),
+                operation_metadata=want_operation_metadata,
+                attack_metadata=want_attack_metadata,
+            ),
+        ]
+        loop.run_until_complete(op_for_event_logs.write_event_logs_to_disk(file_svc, data_svc))
+        target_path = '/tmp/event_logs/operation_%s.json' % op_for_event_logs.id
+        assert os.path.isfile(target_path)
+        try:
+            with open(target_path, 'rb') as log_file:
+                recorded_log = json.load(log_file)
+            assert recorded_log == want
+        finally:
+            os.remove(target_path)