few logging and ux improvements

README.md

@@ -41,7 +41,7 @@ $ mbedls
 To run a test set for Device Management Client, go to the `/tests` folder and use the command:
 
 ```bash
-pytest dev-client-tests.py -v -log_cli=true --log-cli-level=INFO --html=results.html
+pytest dev-client-tests.py
 ```
 When the test run starts, reset the board to trigger the bootstrap.
 
@@ -50,14 +50,13 @@ When the test run starts, reset the board to trigger the bootstrap.
 To run a single test from the set, use the [`-k` argument](https://docs.pytest.org/en/latest/example/markers.html?highlight=keyword#using-k-expr-to-select-tests-based-on-their-name) to set the test name as a keyword:
 
 ```bash
-pytest dev-client-tests.py -v -log_cli=true --log-cli-level=INFO --html=results.html -k test_03_get_resource
+pytest dev-client-tests.py -k test_03_get_resource
 ```
 
 ### Results output
 
-Use the startup arguments to adjust the generated output:
-- `-log-cli=true` enables the output logging directly into the console
-- `--log-cli-level= DEBUG` adds more details
+Add the startup arguments to adjust the generated output:
+- `--log-cli-level=DEBUG` adds more details
 - `--html=results.html` generates an HTML report
 - `--junitxml=junit.xml` provides output for CI systems, for example Jenkins
 

pelion_test_lib/cloud/libraries/account.py

@@ -11,8 +11,6 @@
 limitations under the License.
 """
 
-import json
-
 
 class AccountManagementAPI:
     """
@@ -38,7 +36,7 @@ def create_api_key(self, request_data, headers=None, expected_status_code=None):
         :return: POST /api-key response
         """
         api_url = '/{}/api-keys'.format(self.api_version)
-        r = self.cloud_api.post(api_url, json.dumps(request_data), headers, expected_status_code)
+        r = self.cloud_api.post(api_url, request_data, headers, expected_status_code)
         return r
 
     def delete_api_key(self, api_key_id, headers=None, expected_status_code=None):

pelion_test_lib/cloud/libraries/connect.py

@@ -68,8 +68,9 @@ def set_device_resource_value(self, device_id, resource_path, resource_data, hea
         api_url = '/{}/endpoints/{}/{}'.format(self.api_version, device_id, resource_path)
 
         # Set text/plain to be default content type for this request - content type from parameters will override this
+        if not headers:
+            headers = dict()
         headers = {**{'Content-type': 'text/plain'}, **headers}
-
         r = self.cloud_api.put(api_url, resource_data, headers, expected_status_code)
         return r
 

pelion_test_lib/cloud/libraries/rest_api/rest_api.py

@@ -12,6 +12,7 @@
 """
 
 import inspect
+import json
 import logging
 import requests
 from pelion_test_lib.tools.utils import assert_status
@@ -55,6 +56,31 @@ def set_default_api_key(self, key):
         self._api_key = key
         self.headers['Authorization'] = 'Bearer {}'.format(self._api_key)
 
+    @staticmethod
+    def _clean_request_body(req_body):
+        """
+        Cleans the password and binary data from request body for logging
+        :param req_body: request body
+        :return:
+        """
+        if req_body is not None:
+            if isinstance(req_body, str):
+                split_body = req_body.split('&')
+                for param in split_body:
+                    if 'password=' in param:
+                        pwd = param.split('=')[1]
+                        req_body = req_body.replace('password={}'.format(pwd), 'password=*')
+            if isinstance(req_body, bytes):
+                req_body = 'body content in binary data - removed from the log'
+        return req_body
+
+    @staticmethod
+    def _data_content(headers, data):
+        if 'Content-type' in headers and data:
+            if headers['Content-type'] == 'application/json':
+                return json.dumps(data)
+        return data
+
     @staticmethod
     def _write_log_response(method, api_url, r):
         """
@@ -76,7 +102,9 @@ def _combine_headers(self, additional_header):
         :param additional_header: Headers to merge with default ones
         :return: Merged header dictionary
         """
-        return {**self.headers, **additional_header}
+        if additional_header:
+            return {**self.headers, **additional_header}
+        return self.headers
 
     def get(self, api_url, headers=None, expected_status_code=None, **kwargs):
         """
@@ -88,11 +116,7 @@ def get(self, api_url, headers=None, expected_status_code=None, **kwargs):
         :return: Request response
         """
         url = self.api_gw + api_url
-        if headers is not None:
-            request_headers = self._combine_headers(headers)
-        else:
-            request_headers = self.headers
-
+        request_headers = self._combine_headers(headers)
         r = requests.get(url, headers=request_headers, **kwargs)
         self._write_log_response('GET', api_url, r)
         if expected_status_code is not None:
@@ -111,12 +135,9 @@ def put(self, api_url, data=None, headers=None, expected_status_code=None, **kwa
         :return: Request response
         """
         url = self.api_gw + api_url
-        if headers is not None:
-            request_headers = self._combine_headers(headers)
-        else:
-            request_headers = self.headers
-
-        r = requests.put(url, headers=request_headers, data=data, **kwargs)
+        request_headers = self._combine_headers(headers)
+        request_data = self._data_content(request_headers, data)
+        r = requests.put(url, headers=request_headers, data=request_data, **kwargs)
         self._write_log_response('PUT', api_url, r)
         if expected_status_code is not None:
             assert_status(r, inspect.stack()[1][3], expected_status_code)
@@ -134,12 +155,11 @@ def post(self, api_url, data=None, headers=None, expected_status_code=None, **kw
         :return: Request response
         """
         url = self.api_gw + api_url
-        if headers is not None:
-            request_headers = self._combine_headers(headers)
-        else:
-            request_headers = self.headers
-
-        r = requests.post(url, headers=request_headers, data=data, **kwargs)
+        request_headers = self._combine_headers(headers)
+        if 'files' in kwargs:
+            request_headers.pop('Content-type')
+        request_data = self._data_content(request_headers, data)
+        r = requests.post(url, headers=request_headers, data=request_data, **kwargs)
         self._write_log_response('POST', api_url, r)
         if expected_status_code is not None:
             assert_status(r, inspect.stack()[1][3], expected_status_code)
@@ -156,11 +176,7 @@ def delete(self, api_url, headers=None, expected_status_code=None, **kwargs):
         :return: Request response
         """
         url = self.api_gw + api_url
-        if headers is not None:
-            request_headers = self._combine_headers(headers)
-        else:
-            request_headers = self.headers
-
+        request_headers = self._combine_headers(headers)
         r = requests.delete(url, headers=request_headers, **kwargs)
         self._write_log_response('DELETE', api_url, r)
         if expected_status_code is not None:

pelion_test_lib/fixtures/client_fixtures.py

@@ -41,7 +41,7 @@ def client(request):
             assert False, err_msg
     sleep(2)
     cli = Client(conn)
-    cli.wait_for_output(b'Client registered', 300)
+    cli.wait_for_output('Client registered', 300)
     ep_id = cli.endpoint_id(120)
 
     yield cli

pelion_test_lib/fixtures/cloud_fixtures.py

@@ -31,16 +31,16 @@ def cloud():
     log.debug("Initializing Cloud API fixture")
 
     api_gw = os.environ.get('PELION_CLOUD_API_GW', 'https://api.us-east-1.mbedcloud.com')
-    if os.environ.get('PELION_CLOUD_API_KEY'):
-        api_key = os.environ.get('PELION_CLOUD_API_KEY')
-    else:
+    if os.environ.get('CLOUD_SDK_API_KEY'):
         api_key = os.environ.get('CLOUD_SDK_API_KEY')
+    else:
+        api_key = os.environ.get('PELION_CLOUD_API_KEY')
 
     if not api_gw or not api_key:
         pytest.exit('Set missing API gateway url and/or API key via environment variables before running tests!\n'
                     'API GW: PELION_CLOUD_API_GW={}\n'
                     'API KEY: CLOUD_SDK_API_KEY={} or '
-                    'PELION_CLOUD_API_KEY={}'.format(api_gw if api_gw != '' else 'MISSING!',
+                    'PELION_CLOUD_API_KEY={}'.format(os.environ.get('PELION_CLOUD_API_GW', 'MISSING!'),
                                                      os.environ.get('CLOUD_SDK_API_KEY', 'MISSING!'),
                                                      os.environ.get('PELION_CLOUD_API_KEY', 'MISSING!')))
 

pelion_test_lib/helpers/connect_helper.py

@@ -34,7 +34,7 @@ def get_async_device_request(cloud, path, device_id, headers):
     async_id = str(uuid.uuid4())
     request_params = {'async-id': async_id}
     request_payload = {'method': 'GET', 'uri': path}
-    cloud.connect.send_device_request(device_id, json.dumps(request_payload), request_params, headers=headers,
+    cloud.connect.send_device_request(device_id, request_payload, request_params, headers=headers,
                                       expected_status_code=202)
     return async_id
 
@@ -56,6 +56,6 @@ def put_async_device_request(cloud, path, device_id, request_data, headers, cont
     request_params = {"async-id": async_id}
     request_payload = {"method": "PUT", "uri": path, "content-type": content_type,
                        "payload-b64": payload_data}
-    cloud.connect.send_device_request(device_id, json.dumps(request_payload), request_params, headers=headers,
+    cloud.connect.send_device_request(device_id, request_payload, request_params, headers=headers,
                                       expected_status_code=202)
     return async_id

pelion_test_lib/tools/client_runner.py

@@ -56,12 +56,9 @@ def _input_thread(self):
             line = self.dut.readline()
             if line:
                 plain_line = utils.strip_escape(line)
-                # Testapp uses \r to print characters to the same line, strip those and return only the last part
-                # If there is only one \r, don't remove anything.
                 if b'\r' in line and line.count(b'\r') > 1:
                     plain_line = plain_line.split(b'\r')[-2]
-                # Debug traces use tabulator characters, change those to spaces for readability
-                plain_line = plain_line.replace(b'\t', b'  ')
+                plain_line = plain_line.replace(b'\t', b'  ').decode('utf-8')
                 flog.info('<--|D{}| {}'.format(self.name, plain_line.strip()))
                 if self.trace:
                     log.debug('Raw output: {}'.format(line))
@@ -88,21 +85,20 @@ def endpoint_id(self, wait_for_response=10):
         :return: Endpoint id
         """
         if self._ep_id is None:
-            ep_id = self.wait_for_output(b'Device Id:', wait_for_response)
+            ep_id = self.wait_for_output('Device Id:', wait_for_response)
             if ep_id is not None:
-                log.debug(ep_id)
                 ep_array = ep_id.split()
                 if len(ep_array) > 1:
-                    self._ep_id = ep_array[2].decode('UTF-8')
-
+                    self._ep_id = ep_array[2]
         return self._ep_id
 
-    def wait_for_output(self, search, timeout=60, assert_errors=True):
+    def wait_for_output(self, search, timeout=60, assert_errors=True, ignore_case=True):
         """
         Wait for expected output response
         :param search: Expected response string
         :param timeout: Response waiting time
         :param assert_errors: Assert on error situations
+        :param ignore_case: Ignore client output's casing
         :return: Response line with expected string
         """
         start = time()
@@ -114,6 +110,9 @@ def wait_for_output(self, search, timeout=60, assert_errors=True):
             try:
                 line = self._read_line(1)
                 if line:
+                    if ignore_case:
+                        search = search.lower()
+                        line = line.lower()
                     if search in line:
                         end = time()
                         log.debug('Expected string "{}" found! [time][{:.4f} s]'.format(search, end - start))

tests/conftest.py

@@ -11,11 +11,15 @@
 limitations under the License.
 """
 
+import logging
 import pytest
 
 pytest_plugins = ['pelion_test_lib.fixtures.client_fixtures',
                   'pelion_test_lib.fixtures.cloud_fixtures']
 
+log = logging.getLogger(__name__)
+pytest.global_test_results = []
+
 
 def pytest_addoption(parser):
     """
@@ -26,3 +30,54 @@ def pytest_addoption(parser):
     parser.addoption('--target_id', action='store', help='mbed device target id')
     parser.addoption('--update_bin', action='store', help='mbed device update binary')
     parser.addoption('--ext_conn', action='store_true', default=False, help='use external connection')
+
+
+def pytest_report_teststatus(report):
+    """
+    Hook for collecting test results during the test run for the summary
+    :param report: pytest test report
+    :return:
+    """
+    error_rep = ''
+    test_result = {'test_name': report.nodeid,
+                   'result': report.outcome,
+                   'when': report.when,
+                   'duration': report.duration,
+                   'error_msg': error_rep}
+    if report.outcome == 'failed':
+        if report.longrepr:
+            for line in str(report.longrepr).splitlines():
+                if line.startswith('E       '):
+                    error_rep += '{}\n'.format(line)
+            error_rep += '{}\n'.format(str(report.longrepr).splitlines()[-1])
+        test_result['error_msg'] = error_rep
+        if report.when == 'teardown':
+            pytest.global_test_results.pop()
+        pytest.global_test_results.append(test_result)
+    else:
+        if report.when == 'call':
+            pytest.global_test_results.append(test_result)
+
+
+def pytest_sessionfinish():
+    """
+    Hook for writing the test result summary to console log after the test run
+    """
+    if pytest.global_test_results != []:
+        log.info('-----  TEST RESULTS SUMMARY  -----')
+        log.info('[ check the complete fail reasons and code locations from this log or html report ]')
+        for resp in pytest.global_test_results:
+            result = resp['result']
+            if result == 'failed':
+                result = result.upper()
+            log.info('[{}] - {} - ({:.3f}s)'.format(result, resp['test_name'], resp['duration']))
+            if resp['error_msg'] != '':
+                take_these = 3
+                for line in resp['error_msg'].splitlines():
+                    if take_these > 0:
+                        log.info(line)
+                    else:
+                        log.info('E ---8<--- Error log summary cut down to few lines, '
+                                 'check full log above or from html report ---8<---\n')
+                        break
+                    take_these -= 1

tests/dev-client-tests.py

@@ -30,7 +30,7 @@ def test_01_get_device_id(cloud, client):
 def test_02_subscribe_resource(cloud, client):
     r = cloud.connect.set_subscription_for_resource(client.endpoint_id(), '3200/0/5501', expected_status_code=202)
     log.info('Set subscription for resource "3200/0/5501". Async-id: "{}"'.format(r.json()['async-response-id']))
-    client.wait_for_output(b'Message status callback: (3200/0/5501) subscribed', timeout=60)
+    client.wait_for_output('Message status callback: (3200/0/5501) subscribed', timeout=60)
 
 
 def test_03_get_resource(cloud, client, websocket, temp_api_key):
@@ -47,7 +47,7 @@ def test_04_put_resource(cloud, client, websocket, temp_api_key):
     async_id = put_async_device_request(cloud, RESOURCE_PATH, client.endpoint_id(), PATTERN, headers)
     log.info('Put value "{}" to resource "{}". Async-id: "{}"'.format(PATTERN, RESOURCE_PATH, async_id))
 
-    client.wait_for_output('PUT received, new value: {}'.format(PATTERN).encode('ascii'), 60)
+    client.wait_for_output('PUT received, new value: {}'.format(PATTERN), 60)
     async_response = websocket.wait_for_async_response(async_response_id=async_id, timeout=30, assert_errors=True)
     assert async_response['decoded_payload'] == b'', 'Invalid payload received from the device!'
 

tests/pytest.ini

@@ -1,4 +1,11 @@
 [pytest]
-log_level = DEBUG
-log_format = %(asctime)s.%(msecs)03d   %(levelname)s   %(message)s
-log_cli_format = %(asctime)s.%(msecs)03d   %(levelname)s   %(message)s
+log_level = INFO
+log_format = %(asctime)s.%(msecs)03d  %(levelname)8s   %(message)s
+log_cli = 1
+log_cli_level = INFO
+log_cli_format = %(asctime)s.%(msecs)03d  %(levelname)8s   %(message)s
+log_cli_date_format=%Y-%m-%d %H:%M:%S
+log_file = pytest.log
+log_file_level = DEBUG
+log_file_format = %(asctime)s.%(msecs)03d  [%(levelname)8s]   %(message)s    (%(filename)s:%(lineno)s)
+log_file_date_format=%Y-%m-%d %H:%M:%S