From e68a060d3ee92540ef8d954bd49243e45dbf8da2 Mon Sep 17 00:00:00 2001 From: Philip Jenvey Date: Thu, 13 Feb 2020 17:04:33 -0800 Subject: [PATCH] test: ensure sane logging levels in --release mode fail tests w/ excessive logging levels (unless explicitly stated w/ @max_logs) - fix the Queue import now that python-future is no longer a dependency - update http per RUSTSEC-2019-0033 + 0034 Closes #117 --- Cargo.lock | 16 ++--- tests/test_integration.py | 127 +++++++++++++++++++++++++++----------- 2 files changed, 100 insertions(+), 43 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 45c632c20..8ca9fe965 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -783,7 +783,7 @@ dependencies = [ "bytes 0.4.12 (registry+https://github.com/rust-lang/crates.io-index)", "fnv 1.0.6 (registry+https://github.com/rust-lang/crates.io-index)", "futures 0.1.28 (registry+https://github.com/rust-lang/crates.io-index)", - "http 0.1.18 (registry+https://github.com/rust-lang/crates.io-index)", + "http 0.1.21 (registry+https://github.com/rust-lang/crates.io-index)", "indexmap 1.0.2 (registry+https://github.com/rust-lang/crates.io-index)", "log 0.4.8 (registry+https://github.com/rust-lang/crates.io-index)", "slab 0.4.2 (registry+https://github.com/rust-lang/crates.io-index)", @@ -824,7 +824,7 @@ dependencies = [ [[package]] name = "http" -version = "0.1.18" +version = "0.1.21" source = "registry+https://github.com/rust-lang/crates.io-index" dependencies = [ "bytes 0.4.12 (registry+https://github.com/rust-lang/crates.io-index)", @@ -839,7 +839,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" dependencies = [ "bytes 0.4.12 (registry+https://github.com/rust-lang/crates.io-index)", "futures 0.1.28 (registry+https://github.com/rust-lang/crates.io-index)", - "http 0.1.18 (registry+https://github.com/rust-lang/crates.io-index)", + "http 0.1.21 (registry+https://github.com/rust-lang/crates.io-index)", "tokio-buf 0.1.1 (registry+https://github.com/rust-lang/crates.io-index)", ] @@ -896,7 +896,7 @@ dependencies = [ "futures 0.1.28 (registry+https://github.com/rust-lang/crates.io-index)", "futures-cpupool 0.1.8 (registry+https://github.com/rust-lang/crates.io-index)", "h2 0.1.16 (registry+https://github.com/rust-lang/crates.io-index)", - "http 0.1.18 (registry+https://github.com/rust-lang/crates.io-index)", + "http 0.1.21 (registry+https://github.com/rust-lang/crates.io-index)", "http-body 0.1.0 (registry+https://github.com/rust-lang/crates.io-index)", "httparse 1.3.4 (registry+https://github.com/rust-lang/crates.io-index)", "iovec 0.1.2 (registry+https://github.com/rust-lang/crates.io-index)", @@ -1656,7 +1656,7 @@ dependencies = [ "encoding_rs 0.8.16 (registry+https://github.com/rust-lang/crates.io-index)", "flate2 1.0.9 (registry+https://github.com/rust-lang/crates.io-index)", "futures 0.1.28 (registry+https://github.com/rust-lang/crates.io-index)", - "http 0.1.18 (registry+https://github.com/rust-lang/crates.io-index)", + "http 0.1.21 (registry+https://github.com/rust-lang/crates.io-index)", "hyper 0.12.33 (registry+https://github.com/rust-lang/crates.io-index)", "hyper-tls 0.3.2 (registry+https://github.com/rust-lang/crates.io-index)", "log 0.4.8 (registry+https://github.com/rust-lang/crates.io-index)", @@ -1687,7 +1687,7 @@ dependencies = [ "futures 0.1.28 (registry+https://github.com/rust-lang/crates.io-index)", "hex 0.3.2 (registry+https://github.com/rust-lang/crates.io-index)", "hmac 0.5.0 (registry+https://github.com/rust-lang/crates.io-index)", - "http 0.1.18 (registry+https://github.com/rust-lang/crates.io-index)", + "http 0.1.21 (registry+https://github.com/rust-lang/crates.io-index)", "hyper 0.12.33 (registry+https://github.com/rust-lang/crates.io-index)", "hyper-tls 0.3.2 (registry+https://github.com/rust-lang/crates.io-index)", "lazy_static 1.3.0 (registry+https://github.com/rust-lang/crates.io-index)", @@ -2519,7 +2519,7 @@ dependencies = [ "base64 0.10.1 (registry+https://github.com/rust-lang/crates.io-index)", "byteorder 1.3.1 (registry+https://github.com/rust-lang/crates.io-index)", "bytes 0.4.12 (registry+https://github.com/rust-lang/crates.io-index)", - "http 0.1.18 (registry+https://github.com/rust-lang/crates.io-index)", + "http 0.1.21 (registry+https://github.com/rust-lang/crates.io-index)", "httparse 1.3.4 (registry+https://github.com/rust-lang/crates.io-index)", "input_buffer 0.2.0 (registry+https://github.com/rust-lang/crates.io-index)", "log 0.4.8 (registry+https://github.com/rust-lang/crates.io-index)", @@ -2842,7 +2842,7 @@ dependencies = [ "checksum hex 0.3.2 (registry+https://github.com/rust-lang/crates.io-index)" = "805026a5d0141ffc30abb3be3173848ad46a1b1664fe632428479619a3644d77" "checksum hmac 0.5.0 (registry+https://github.com/rust-lang/crates.io-index)" = "44f3bdb08579d99d7dc761c0e266f13b5f2ab8c8c703b9fc9ef333cd8f48f55e" "checksum hostname 0.1.5 (registry+https://github.com/rust-lang/crates.io-index)" = "21ceb46a83a85e824ef93669c8b390009623863b5c195d1ba747292c0c72f94e" -"checksum http 0.1.18 (registry+https://github.com/rust-lang/crates.io-index)" = "372bcb56f939e449117fb0869c2e8fd8753a8223d92a172c6e808cf123a5b6e4" +"checksum http 0.1.21 (registry+https://github.com/rust-lang/crates.io-index)" = "d6ccf5ede3a895d8856620237b2f02972c1bbc78d2965ad7fe8838d4a0ed41f0" "checksum http-body 0.1.0 (registry+https://github.com/rust-lang/crates.io-index)" = "6741c859c1b2463a423a1dbce98d418e6c3c3fc720fb0d45528657320920292d" "checksum httparse 1.3.4 (registry+https://github.com/rust-lang/crates.io-index)" = "cd179ae861f0c2e53da70d892f5f3029f9594be0c41dc5269cd371691b1dc2f9" "checksum httpdate 0.3.2 (registry+https://github.com/rust-lang/crates.io-index)" = "494b4d60369511e7dea41cf646832512a94e542f68bb9c49e54518e0f468eb47" diff --git a/tests/test_integration.py b/tests/test_integration.py index 3aef0c201..27fbb4ab2 100644 --- a/tests/test_integration.py +++ b/tests/test_integration.py @@ -15,6 +15,7 @@ import time import uuid from contextlib import contextmanager +from functools import wraps from threading import Event, Thread from unittest.case import SkipTest @@ -33,14 +34,14 @@ ConnectionApplication, EndpointApplication, ) -from autopush.tests.support import TestingLogObserver +from autopush.tests.support import _TestingLogObserver from autopush.tests.test_integration import ( Client, _get_vapid, ) from autopush.utils import base64url_encode from cryptography.fernet import Fernet -from queue import Empty, Queue +from Queue import Empty, Queue from twisted.internet.defer import inlineCallbacks, returnValue from twisted.internet.threads import deferToThread from twisted.logger import globalLogPublisher @@ -70,6 +71,7 @@ CN_MP_SERVER = None MOCK_SERVER_THREAD = None CN_QUEUES = [] +STRICT_LOG_COUNTS = True def get_free_port(): @@ -93,6 +95,59 @@ def enqueue_output(out, queue): out.close() +def process_logs(testcase): + """Process (print) the testcase logs (in tearDown). + + Ensures a maximum level of logs allowed to be emitted when running + w/ a `--release` mode connection node + + """ + conn_count = sum(queue.qsize() for queue in CN_QUEUES) + + for queue in CN_QUEUES: + is_empty = False + while not is_empty: + try: + line = queue.get_nowait() + except Empty: + is_empty = True + else: + print(line) + + if not STRICT_LOG_COUNTS: + return + + MSG = "endpoint node emitted excessive log statements, count: {} > max: {}" + endpoint_count = len(testcase.logs) + # Give an extra to endpoint for potential startup log messages + # (e.g. when running tests individually) + max_endpoint_logs = testcase.max_endpoint_logs + 1 + assert endpoint_count <= max_endpoint_logs, MSG.format( + endpoint_count, max_endpoint_logs) + + MSG = "conn node emitted excessive log statements, count: {} > max: {}" + assert conn_count <= testcase.max_conn_logs, MSG.format( + conn_count, testcase.max_conn_logs) + + +def max_logs(endpoint=None, conn=None): + """Adjust max_endpoint/conn_logs values for individual test cases. + + They're utilized by the process_logs function + + """ + def max_logs_decorator(func): + @wraps(func) + def wrapper(self, *args, **kwargs): + if endpoint is not None: + self.max_endpoint_logs = endpoint + if conn is not None: + self.max_conn_logs = conn + return func(self, *args, **kwargs) + return wrapper + return max_logs_decorator + + @bottle.get("/v1/broadcasts") def broadcast_handler(): assert bottle.request.headers["Authorization"] == MOCK_MP_TOKEN @@ -115,7 +170,8 @@ def send_bad_data(self): def setup_module(): - global CN_SERVER, CN_QUEUES, CN_MP_SERVER, MOCK_SERVER_THREAD + global CN_SERVER, CN_QUEUES, CN_MP_SERVER, MOCK_SERVER_THREAD, \ + STRICT_LOG_COUNTS ap_tests.ddb_jar = os.path.join(root_dir, "ddb", "DynamoDBLocal.jar") ap_tests.ddb_lib_dir = os.path.join(root_dir, "ddb", "DynamoDBLocal_lib") ap_tests.setUp() @@ -148,6 +204,10 @@ def setup_module(): while possible_paths and not os.path.exists(rust_bin): # pragma: nocover rust_bin = root_dir + possible_paths.pop(0) + if 'release' not in rust_bin: + # disable checks for chatty debug mode autopush-rs + STRICT_LOG_COUNTS = False + # Setup the environment for key, val in conn_conf.items(): key = "autopush_" + key @@ -237,6 +297,10 @@ class TestRustWebPush(unittest.TestCase): use_cryptography=True, ) + # Max log lines allowed to be emitted by each node type + max_endpoint_logs = 8 + max_conn_logs = 3 + def start_ep(self, ep_conf): # Endpoint HTTP router self.ep = ep = EndpointApplication( @@ -248,7 +312,7 @@ def start_ep(self, ep_conf): self.addCleanup(ep.stopService) def setUp(self): - self.logs = TestingLogObserver() + self.logs = _TestingLogObserver() begin_or_register(self.logs) self.addCleanup(globalLogPublisher.removeObserver, self.logs) @@ -259,15 +323,7 @@ def setUp(self): self.start_ep(self._ep_conf) def tearDown(self): - for queue in CN_QUEUES: - is_empty = False - while not is_empty: - try: - line = queue.get_nowait() - except Empty: - is_empty = True - else: - print(line) + process_logs(self) while not MOCK_SENTRY_QUEUE.empty(): MOCK_SENTRY_QUEUE.get_nowait() @@ -299,6 +355,7 @@ def _ws_url(self): return "ws://localhost:{}/".format(CONNECTION_PORT) @inlineCallbacks + @max_logs(conn=4) def test_sentry_output(self): # Ensure bad data doesn't throw errors client = CustomClient(self._ws_url) @@ -371,6 +428,7 @@ def test_topic_replacement_delivery(self): yield self.shut_down(client) @inlineCallbacks + @max_logs(conn=4) def test_topic_no_delivery_on_reconnect(self): data = str(uuid.uuid4()) client = yield self.quick_register() @@ -584,6 +642,7 @@ def test_topic_expired(self): yield self.shut_down(client) @inlineCallbacks + @max_logs(conn=4) def test_multiple_delivery_with_single_ack(self): data = str(uuid.uuid4()) data2 = str(uuid.uuid4()) @@ -709,6 +768,7 @@ def test_ttl_expired(self): yield self.shut_down(client) @inlineCallbacks + @max_logs(endpoint=28) def test_ttl_batch_expired_and_good_one(self): data = str(uuid.uuid4()) data2 = str(uuid.uuid4()) @@ -731,6 +791,7 @@ def test_ttl_batch_expired_and_good_one(self): yield self.shut_down(client) @inlineCallbacks + @max_logs(endpoint=28) def test_ttl_batch_partly_expired_and_good_one(self): data = str(uuid.uuid4()) data1 = str(uuid.uuid4()) @@ -882,6 +943,7 @@ def test_with_bad_key(self): yield self.shut_down(client) @inlineCallbacks + @max_logs(endpoint=44) def test_msg_limit(self): client = yield self.quick_register() uaid = client.uaid @@ -942,6 +1004,9 @@ class TestRustWebPushBroadcast(unittest.TestCase): human_logs=False, ) + max_endpoint_logs = 4 + max_conn_logs = 1 + def start_ep(self, ep_conf): # Endpoint HTTP router self.ep = ep = EndpointApplication( @@ -953,7 +1018,7 @@ def start_ep(self, ep_conf): self.addCleanup(ep.stopService) def setUp(self): - self.logs = TestingLogObserver() + self.logs = _TestingLogObserver() begin_or_register(self.logs) self.addCleanup(globalLogPublisher.removeObserver, self.logs) @@ -976,15 +1041,7 @@ def setUp(self): conn.setup(rotate_tables=True) def tearDown(self): - for queue in CN_QUEUES: - is_empty = False - while not is_empty: - try: - line = queue.get_nowait() - except Empty: - is_empty = True - else: - print(line) + process_logs(self) def endpoint_kwargs(self): return self._endpoint_defaults @@ -1399,8 +1456,7 @@ def test_webpush_monthly_rotation_old_user_dropped(self): client.uaid, old_month ) - old_message = Message(old_month, - boto_resource=autopush.tests.boto_resource) + _ = Message(old_month, boto_resource=autopush.tests.boto_resource) # Verify the move c = yield deferToThread(self.conn.db.router.get_uaid, client.uaid) @@ -1438,6 +1494,9 @@ class TestRustAndPythonWebPush(unittest.TestCase): human_logs=False, ) + max_endpoint_logs = 1 + max_conn_logs = 3 + def start_ep(self, ep_conf): # Endpoint HTTP router self.ep = ep = EndpointApplication( @@ -1460,7 +1519,7 @@ def start_conn(self, conn_conf): self.addCleanup(conn.stopService) def setUp(self): - self.logs = TestingLogObserver() + self.logs = _TestingLogObserver() begin_or_register(self.logs) self.addCleanup(globalLogPublisher.removeObserver, self.logs) @@ -1477,15 +1536,7 @@ def setUp(self): self.start_conn(self._conn_conf) def tearDown(self): - for queue in CN_QUEUES: - is_empty = False - while not is_empty: - try: - line = queue.get_nowait() - except Empty: - is_empty = True - else: - print(line) + process_logs(self) def endpoint_kwargs(self): return self._endpoint_defaults @@ -1509,6 +1560,7 @@ def shut_down(self, client=None): yield client.disconnect() @inlineCallbacks + @max_logs(endpoint=41) def test_cross_topic_no_delivery_on_reconnect(self): data = str(uuid.uuid4()) client = yield self.quick_register(connection_port=CONNECTION_PORT) @@ -1534,6 +1586,7 @@ def test_cross_topic_no_delivery_on_reconnect(self): yield self.shut_down(client) @inlineCallbacks + @max_logs(endpoint=41) def test_cross_topic_no_delivery_on_reconnect_reverse(self): data = str(uuid.uuid4()) client = yield self.quick_register() @@ -1559,6 +1612,7 @@ def test_cross_topic_no_delivery_on_reconnect_reverse(self): yield self.shut_down(client) @inlineCallbacks + @max_logs(endpoint=10, conn=4) def test_cross_multiple_delivery_with_single_ack(self): data = str(uuid.uuid4()) data2 = str(uuid.uuid4()) @@ -1599,6 +1653,7 @@ def test_cross_multiple_delivery_with_single_ack(self): yield self.shut_down(client) @inlineCallbacks + @max_logs(endpoint=45) def test_cross_multiple_delivery_with_single_ack_reverse(self): data = str(uuid.uuid4()) data2 = str(uuid.uuid4()) @@ -1639,6 +1694,7 @@ def test_cross_multiple_delivery_with_single_ack_reverse(self): yield self.shut_down(client) @inlineCallbacks + @max_logs(endpoint=43) def test_cross_multiple_delivery_with_multiple_ack(self): data = str(uuid.uuid4()) data2 = str(uuid.uuid4()) @@ -1666,6 +1722,7 @@ def test_cross_multiple_delivery_with_multiple_ack(self): yield self.shut_down(client) @inlineCallbacks + @max_logs(endpoint=10) def test_cross_multiple_delivery_with_multiple_ack_reverse(self): data = str(uuid.uuid4()) data2 = str(uuid.uuid4())