server: Fix flaky logging test (#3081)

The changes in 0c74839934 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.
This commit is contained in:
Alexis King 2019-10-10 08:40:19 -05:00 committed by GitHub
parent ae145c587f
commit 3ef6feb394
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23

View File

@ -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):