cloudblue · Jul 12, 2021 · Jul 12, 2021
diff --git a/connect/eaas/logging.py b/connect/eaas/logging.py
@@ -1,3 +1,5 @@
+import json
+
 from logzio.handler import LogzioHandler
 
 
@@ -10,3 +12,48 @@ def extra_fields(self, message):
         extra_fields = super().extra_fields(message)
         extra_fields.update(self.default_extra_fields)
         return extra_fields
+
+
+class RequestLogger:
+
+    def __init__(self, logger):
+        self.logger = logger
+
+    def log_request(self, method, url, kwargs):
+        other_args = {k: v for k, v in kwargs.items() if k not in ('headers', 'json', 'params')}
+
+        if 'params' in kwargs:
+            url += '&' if '?' in url else '?'
+            url += '&'.join([f'{k}={v}' for k, v in kwargs['params'].items()])
+
+        lines = [
+            '--- HTTP Request ---',
+            f'{method.upper()} {url} {other_args if other_args else ""}',
+        ]
+
+        if 'headers' in kwargs:
+            for k, v in kwargs['headers'].items():
+                lines.append(f'{k}: {v}')
+
+        if 'json' in kwargs:
+            lines.append(json.dumps(kwargs['json'], indent=4))
+
+        lines.append('')
+        self.logger.debug('\n'.join(lines))
+
+    def log_response(self, response):
+        reason = response.raw.reason if getattr(response, 'raw', None) else response.reason_phrase
+        lines = [
+            '--- HTTP Response ---',
+            f'{response.status_code} {reason}',
+        ]
+
+        for k, v in response.headers.items():
+            lines.append(f'{k}: {v}')
+
+        if response.headers.get('Content-Type', None) == 'application/json':
+            lines.append(json.dumps(response.json(), indent=4))
+
+        lines.append('')
+
+        self.logger.debug('\n'.join(lines))
diff --git a/connect/eaas/worker.py b/connect/eaas/worker.py
@@ -23,7 +23,7 @@
     get_extension_class,
     get_extension_type,
 )
-from connect.eaas.logging import ExtensionLogHandler
+from connect.eaas.logging import ExtensionLogHandler, RequestLogger
 from connect.eaas.manager import TasksManager
 
 
@@ -103,6 +103,9 @@ def get_client(self):
             self.api_key,
             endpoint=f'https://{self.api_address}/public/v1',
             use_specs=False,
+            logger=RequestLogger(
+                self.get_extension_logger(self.logging_api_key),
+            ),
         )
 
     def get_extension_logger(self, token):
@@ -140,7 +143,12 @@ def ensure_tasks_manager_running(self):
             self.start_tasks_manager()
 
     def get_url(self):
-        return f'{self.base_ws_url}/{self.environment_id}/{self.instance_id}'
+        running_tasks = (
+            self.tasks_manager.running_tasks
+            if self.tasks_manager else 0
+        )
+        url = f'{self.base_ws_url}/{self.environment_id}/{self.instance_id}'
+        return f'{url}?running_tasks={running_tasks}'
 
     def get_extension(self):
         return self.extension_class(
@@ -224,6 +232,7 @@ async def configuration(self, data):
         if data.environment_type:
             self.environment_type = data.environment_type
         if data.log_level:
+            logger.info(f'Change extesion logger level to {data.log_level}')
             logging.getLogger('eaas.extension').setLevel(
                 getattr(logging, data.log_level),
             )
@@ -267,5 +276,5 @@ async def start(self):
         logger.info('Control worker stopped')
 
     def stop(self):
-        logger.info('Stopping control worker.....')
+        logger.info('Stopping control worker...')
         self.run_event.clear()
diff --git a/poetry.lock b/poetry.lock
diff --git a/pyproject.toml b/pyproject.toml
@@ -27,7 +27,7 @@ cextrun = 'connect.eaas.main:main'
 [tool.poetry.dependencies]
 python = "^3.8"
 websockets = "^9.0.1"
-connect-openapi-client = "^22.0.7"
+connect-openapi-client = "^22.0.8"
 logzio-python-handler = "^3.0.0"
 
 [tool.poetry.dev-dependencies]

diff --git a/tests/test_logging.py b/tests/test_logging.py
@@ -1,6 +1,9 @@
 import logging
 
-from connect.eaas.logging import ExtensionLogHandler
+from urllib3.response import HTTPResponse
+from requests.models import Response
+
+from connect.eaas.logging import ExtensionLogHandler, RequestLogger
 
 
 def test_extension_log_handler():
@@ -17,3 +20,154 @@ def test_extension_log_handler():
         None,
     ))
     assert extra_fields['field'] == 'value'
+
+
+def test_request_logger_request(caplog):
+    rl = RequestLogger(logging.getLogger('eaas.extension'))
+
+    with caplog.at_level(logging.DEBUG):
+        rl.log_request('POST', 'https://example.com', {})
+
+    assert '\n'.join(
+        [
+            '--- HTTP Request ---',
+            "POST https://example.com ",
+            '',
+        ],
+    ) == caplog.records[0].message
+
+
+def test_request_logger_request_params(caplog):
+    rl = RequestLogger(logging.getLogger('eaas.extension'))
+
+    with caplog.at_level(logging.DEBUG):
+        rl.log_request('POST', 'https://example.com', {'params': {'a': 'va'}})
+
+    assert '\n'.join(
+        [
+            '--- HTTP Request ---',
+            "POST https://example.com?a=va ",
+            '',
+        ],
+    ) == caplog.records[0].message
+
+
+def test_request_logger_request_with_qs(caplog):
+    rl = RequestLogger(logging.getLogger('eaas.extension'))
+
+    with caplog.at_level(logging.DEBUG):
+        rl.log_request('GET', 'https://example.com?queryparam=value', {})
+
+    assert '\n'.join(
+        [
+            '--- HTTP Request ---',
+            "GET https://example.com?queryparam=value ",
+            '',
+        ],
+    ) == caplog.records[0].message
+
+
+def test_request_logger_request_with_headers(caplog):
+    rl = RequestLogger(logging.getLogger('eaas.extension'))
+
+    headers = {
+        'Authorization': 'ApiKey SU-000:xxxx',
+    }
+
+    with caplog.at_level(logging.DEBUG):
+        rl.log_request('GET', 'https://example.com', {'headers': headers})
+
+    assert '\n'.join(
+        [
+            '--- HTTP Request ---',
+            "GET https://example.com ",
+            'Authorization: ApiKey SU-000:xxxx',
+            '',
+        ],
+    ) == caplog.records[0].message
+
+
+def test_request_logger_request_with_json_body(caplog):
+    rl = RequestLogger(logging.getLogger('eaas.extension'))
+
+    json = {
+        'test': 'data',
+    }
+
+    with caplog.at_level(logging.DEBUG):
+        rl.log_request('GET', 'https://example.com', {'json': json})
+
+    assert '\n'.join(
+        [
+            '--- HTTP Request ---',
+            "GET https://example.com ",
+            '{',
+            '    "test": "data"',
+            '}',
+            '',
+        ],
+    ) == caplog.records[0].message
+
+
+def test_request_logger_response(caplog):
+    rl = RequestLogger(logging.getLogger('eaas.extension'))
+
+    rsp = Response()
+    rsp.raw = HTTPResponse()
+
+    rsp.status_code = 200
+    rsp.raw.reason = 'OK'
+
+    with caplog.at_level(logging.DEBUG):
+        rl.log_response(rsp)
+
+    assert '\n'.join(
+        [
+            '--- HTTP Response ---',
+            '200 OK',
+            '',
+        ],
+    ) == caplog.records[0].message
+
+    rsp = Response()
+    rsp.status_code = 200
+    rsp.reason_phrase = 'OK'
+
+    with caplog.at_level(logging.DEBUG):
+        rl.log_response(rsp)
+
+    assert '\n'.join(
+        [
+            '--- HTTP Response ---',
+            '200 OK',
+            '',
+        ],
+    ) == caplog.records[0].message
+
+
+def test_request_logger_response_json(mocker, caplog):
+    json = {'id': 'XX-1234', 'name': 'XXX'}
+    mocker.patch('requests.models.Response.json', return_value=json)
+
+    rl = RequestLogger(logging.getLogger('eaas.extension'))
+
+    rsp = Response()
+    rsp.raw = HTTPResponse()
+    rsp.headers = {'Content-Type': 'application/json'}
+    rsp.status_code = 200
+    rsp.raw.reason = 'OK'
+
+    with caplog.at_level(logging.DEBUG):
+        rl.log_response(rsp)
+    assert '\n'.join(
+        [
+            '--- HTTP Response ---',
+            '200 OK',
+            'Content-Type: application/json',
+            '{',
+            '    "id": "XX-1234",',
+            '    "name": "XXX"',
+            '}',
+            '',
+        ],
+    ) == caplog.records[0].message
diff --git a/tests/test_worker.py b/tests/test_worker.py
@@ -63,7 +63,7 @@ def get_descriptor(cls):
     ).to_json()
 
     handler = WSHandler(
-        '/public/v1/devops/ws/ENV-000-0001/INS-000-0002',
+        '/public/v1/devops/ws/ENV-000-0001/INS-000-0002?running_tasks=0',
         data_to_send,
         ['receive', 'send'],
     )
@@ -144,7 +144,7 @@ def process_asset_purchase_request(self, request):
     ]
 
     handler = WSHandler(
-        '/public/v1/devops/ws/ENV-000-0001/INS-000-0002',
+        '/public/v1/devops/ws/ENV-000-0001/INS-000-0002?running_tasks=0',
         data_to_send,
         ['receive', 'send', 'send', 'receive'],
     )
@@ -234,7 +234,7 @@ def process_tier_config_setup_request(self, request):
     ]
 
     handler = WSHandler(
-        '/public/v1/devops/ws/ENV-000-0001/INS-000-0002',
+        '/public/v1/devops/ws/ENV-000-0001/INS-000-0002?running_tasks=0',
         data_to_send,
         ['receive', 'send', 'send', 'receive'],
     )
@@ -307,7 +307,7 @@ def get_descriptor(cls):
     ]
 
     handler = WSHandler(
-        '/public/v1/devops/ws/ENV-000-0001/INS-000-0002',
+        '/public/v1/devops/ws/ENV-000-0001/INS-000-0002?running_tasks=0',
         data_to_send,
         ['receive', 'send', 'send'],
     )
@@ -362,7 +362,7 @@ def get_descriptor(cls):
     ]
 
     handler = WSHandler(
-        '/public/v1/devops/ws/ENV-000-0001/INS-000-0002',
+        '/public/v1/devops/ws/ENV-000-0001/INS-000-0002?running_tasks=0',
         data_to_send,
         ['receive', 'send', 'send', 'send'],
     )
@@ -416,7 +416,7 @@ def get_descriptor(cls):
     ]
 
     handler = WSHandler(
-        '/public/v1/devops/ws/ENV-000-0001/INS-000-0002',
+        '/public/v1/devops/ws/ENV-000-0001/INS-000-0002?running_tasks=0',
         data_to_send,
         ['receive', 'send', 'send'],
     )
@@ -444,7 +444,7 @@ async def test_connection_closed_error(mocker, ws_server, unused_port, caplog):
         },
     )
     handler = WSHandler(
-        '/public/v1/devops/ws/ENV-000-0001/INS-000-0002',
+        '/public/v1/devops/ws/ENV-000-0001/INS-000-0002?running_tasks=0',
         None,
         [],
     )
@@ -461,7 +461,7 @@ async def test_connection_closed_error(mocker, ws_server, unused_port, caplog):
 
     assert (
         f'Disconnected from: ws://127.0.0.1:{unused_port}'
-        '/public/v1/devops/ws/ENV-000-0001/INS-000-0002, retry in 2s'
+        '/public/v1/devops/ws/ENV-000-0001/INS-000-0002?running_tasks=0, retry in 2s'
     ) in caplog.text
 
 
@@ -480,7 +480,7 @@ async def test_connection_websocket_exception(mocker, ws_server, unused_port, ca
         },
     )
     handler = WSHandler(
-        '/public/v1/devops/ws/ENV-000-0001/INS-000-0002',
+        '/public/v1/devops/ws/ENV-000-0001/INS-000-0002?running_tasks=0',
         None,
         [],
     )
@@ -529,7 +529,7 @@ def get_descriptor(cls):
     mocker.patch('connect.eaas.worker.get_extension_type', return_value='sync')
 
     handler = WSHandler(
-        '/public/v1/devops/ws/ENV-000-0001/INS-000-0002',
+        '/public/v1/devops/ws/ENV-000-0001/INS-000-0002?running_tasks=0',
         None,
         ['receive', 'send'],
     )

diff --git a/tests/utils.py b/tests/utils.py
@@ -4,9 +4,13 @@
 # Copyright (c) 2021 Ingram Micro. All Rights Reserved.
 #
 import asyncio
+import logging
 import json
 
 
+logger = logging.getLogger('connect.eaas')
+
+
 class WSHandler:
     def __init__(self, path, data, actions):
         self.path = path
@@ -37,6 +41,7 @@ async def receive_data(self, ws):
         data = await ws.recv()
         if data:
             self.received.append(json.loads(data))
+        logger.info(f'received: {self.received}')
 
     def assert_received(self, data):
         assert data in self.received