From 3ef6feb394b9f9368b50a59dc39f23a4d1c3aa84 Mon Sep 17 00:00:00 2001 From: Alexis King Date: Thu, 10 Oct 2019 08:40:19 -0500 Subject: [PATCH] server: Fix flaky logging test (#3081) The changes in 0c748399343452fedec21d2d6ad43e0f838d44ca adjusted the format of error logs slightly to omit fields instead of including them with null values. However, this was rarely triggered by this test because it only looks at the first log message, but log messages can sometimes be written out of order. This makes the test order-agnostic. --- server/tests-py/test_logging.py | 116 +++++++++++++++++--------------- 1 file changed, 60 insertions(+), 56 deletions(-) diff --git a/server/tests-py/test_logging.py b/server/tests-py/test_logging.py index d46a0ec246f..8e73cec690b 100644 --- a/server/tests-py/test_logging.py +++ b/server/tests-py/test_logging.py @@ -22,64 +22,64 @@ class TestLogging(): st_code, resp = hge_ctx.v1q_f(self.dir + '/setup.yaml') assert st_code == 200, resp - # make a successful query - q = {'query': 'query { hello {code name} }'} - headers = {} - if hge_ctx.hge_key: - headers['x-hasura-admin-secret'] = hge_ctx.hge_key - resp = hge_ctx.http.post(hge_ctx.hge_url + '/v1/graphql', json=q, - headers=headers) - assert resp.status_code == 200 and 'data' in resp.json() + try: + # make a successful query + q = {'query': 'query { hello {code name} }'} + headers = {'x-request-id': 'successful-query-log-test'} + if hge_ctx.hge_key: + headers['x-hasura-admin-secret'] = hge_ctx.hge_key + resp = hge_ctx.http.post(hge_ctx.hge_url + '/v1/graphql', json=q, + headers=headers) + assert resp.status_code == 200 and 'data' in resp.json() - # make a query where JSON body parsing fails - q = {'quer': 'query { hello {code name} }'} - headers = {'x-request-id': 'json-parse-fail-log-test'} - if hge_ctx.hge_key: - headers['x-hasura-admin-secret'] = hge_ctx.hge_key - resp = hge_ctx.http.post(hge_ctx.hge_url + '/v1/graphql', json=q, - headers=headers) - assert resp.status_code == 200 and 'errors' in resp.json() - - # make an unthorized query where admin secret/access token is empty - q = {'query': 'query { hello {code name} }'} - headers = {'x-request-id': 'unauthorized-query-test'} - resp = hge_ctx.http.post(hge_ctx.hge_url + '/v1/graphql', json=q, - headers=headers) - assert resp.status_code == 200 and 'errors' in resp.json() + # make a query where JSON body parsing fails + q = {'quer': 'query { hello {code name} }'} + headers = {'x-request-id': 'json-parse-fail-log-test'} + if hge_ctx.hge_key: + headers['x-hasura-admin-secret'] = hge_ctx.hge_key + resp = hge_ctx.http.post(hge_ctx.hge_url + '/v1/graphql', json=q, + headers=headers) + assert resp.status_code == 200 and 'errors' in resp.json() - # make an unthorized metadata request where admin secret/access token is empty - q = { - 'query': { - 'type': 'select', - 'args': { - "table": { - "name": "hdb_function", - "schema": "hdb_catalog" - }, - "columns": ["function_name", "function_schema", "is_system_defined"], - "where": { "function_schema": "public" } + # make an unthorized query where admin secret/access token is empty + q = {'query': 'query { hello {code name} }'} + headers = {'x-request-id': 'unauthorized-query-test'} + resp = hge_ctx.http.post(hge_ctx.hge_url + '/v1/graphql', json=q, + headers=headers) + assert resp.status_code == 200 and 'errors' in resp.json() + + # make an unthorized metadata request where admin secret/access token is empty + q = { + 'query': { + 'type': 'select', + 'args': { + "table": { + "name": "hdb_function", + "schema": "hdb_catalog" + }, + "columns": ["function_name", "function_schema", "is_system_defined"], + "where": { "function_schema": "public" } + } } } - } - headers = {'x-request-id': 'unauthorized-metadata-test'} - resp = hge_ctx.http.post(hge_ctx.hge_url + '/v1/query', json=q, - headers=headers) - assert resp.status_code == 401 and 'error' in resp.json() + headers = {'x-request-id': 'unauthorized-metadata-test'} + resp = hge_ctx.http.post(hge_ctx.hge_url + '/v1/query', json=q, + headers=headers) + assert resp.status_code == 401 and 'error' in resp.json() - # gather and parse the logs now - self.logs = self._parse_logs(hge_ctx) - # sometimes the log might take time to buffer - time.sleep(2) - yield - self._teardown(hge_ctx) + # gather and parse the logs now + self.logs = self._parse_logs(hge_ctx) + # sometimes the log might take time to buffer + time.sleep(2) + yield + finally: + self._teardown(hge_ctx) def _parse_logs(self, hge_ctx): # parse the log file into a json list log_file = os.getenv('LOGGING_TEST_LOGFILE_PATH', None) if not log_file: print('Could not determine log file path to test logging!') - # force teardown if setup fails - self._teardown(hge_ctx) assert False loglines = [] with open(log_file, 'r') as f: @@ -133,15 +133,19 @@ class TestLogging(): http_logs = list(filter(_get_http_logs, self.logs)) print('http logs', http_logs) assert len(http_logs) > 0 - http_info = http_logs[0]['detail']['http_info'] - assert 'url' in http_info - assert 'status' in http_info - assert 'ip' in http_info - print(http_logs) - operation = http_logs[0]['detail']['operation'] - assert 'query_execution_time' in operation - assert 'user_vars' in operation - assert 'request_id' in operation + for http_log in http_logs: + print(http_log) + + http_info = http_log['detail']['http_info'] + assert 'url' in http_info + assert 'status' in http_info + assert 'ip' in http_info + + operation = http_log['detail']['operation'] + assert 'request_id' in operation + if operation['request_id'] == 'successful-query-log-test': + assert 'query_execution_time' in operation + assert 'user_vars' in operation def test_query_log(self, hge_ctx): def _get_query_logs(x):