From 970907f28866a09a9fe95da48dffa6cd34ab4dca Mon Sep 17 00:00:00 2001 From: Tom Clegg Date: Fri, 7 Aug 2015 13:55:33 -0400 Subject: [PATCH] 6844: Clean up websocket tests, fix possible deadlock, reduce unnecessary sleep(). * Use onevent=q.put_nowait, so "too many events" raises Queue.Full instead of blocking the websocket thread. * Simplify test strategy: get the events we expect (waiting <5s for each), then make sure no more events arrive for >2s. * Delete "no logs arrive from 1 day in the future" test: indistinguishable from "no logs arrive from 1 hour in the future". * Delete "use today's date, with no time, as a threshold" test: indistinguishable from "can fetch logs 1 hour in the past" * De-duplicate strftime(), datetime arithmetic, and "how to ask for logs starting at time X" logic. * Express timestamp thresholds in ISO8601. Existing tests continue to use localtime. Two new tests use UTC. --- sdk/python/tests/test_websockets.py | 129 +++++++++++++--------------- 1 file changed, 61 insertions(+), 68 deletions(-) diff --git a/sdk/python/tests/test_websockets.py b/sdk/python/tests/test_websockets.py index d7285aabf3..37b644aaf1 100644 --- a/sdk/python/tests/test_websockets.py +++ b/sdk/python/tests/test_websockets.py @@ -1,6 +1,6 @@ import arvados import arvados.events -from datetime import datetime, timedelta +from datetime import datetime, timedelta, tzinfo import mock import Queue import run_test_server @@ -11,6 +11,9 @@ import unittest class WebsocketTest(run_test_server.TestCaseWithServers): MAIN_SERVER = {} + TIME_PAST = time.time()-3600 + TIME_FUTURE = time.time()+3600 + def setUp(self): self.ws = None @@ -20,7 +23,7 @@ class WebsocketTest(run_test_server.TestCaseWithServers): super(WebsocketTest, self).tearDown() run_test_server.reset() - def _test_subscribe(self, poll_fallback, expect_type, last_log_id=None, additional_filters=None, expected=1): + def _test_subscribe(self, poll_fallback, expect_type, start_time=None, expected=1): run_test_server.authorize_with('active') events = Queue.Queue(100) @@ -28,102 +31,92 @@ class WebsocketTest(run_test_server.TestCaseWithServers): # When listening with start_time in the past, this should also be retrieved. # However, when start_time is omitted in subscribe, this should not be fetched. ancestor = arvados.api('v1').humans().create(body={}).execute() - time.sleep(5) filters = [['object_uuid', 'is_a', 'arvados#human']] - if additional_filters: - filters = filters + additional_filters + if start_time: + filters.append(['created_at', '>=', start_time]) self.ws = arvados.events.subscribe( arvados.api('v1'), filters, - events.put, poll_fallback=poll_fallback, last_log_id=last_log_id) + events.put_nowait, + poll_fallback=poll_fallback, + last_log_id=(1 if start_time else None)) self.assertIsInstance(self.ws, expect_type) self.assertEqual(200, events.get(True, 5)['status']) human = arvados.api('v1').humans().create(body={}).execute() - if last_log_id == None or expected == 0: - self.assertEqual(human['uuid'], events.get(True, 5)['object_uuid']) - self.assertTrue(events.empty(), "got more events than expected") - else: - log_events = [] - for i in range(0, 20): - try: - event = events.get(True, 5) - self.assertTrue(event['object_uuid'] is not None) - log_events.append(event['object_uuid']) - except: - break; - - self.assertTrue(len(log_events)>1) - self.assertTrue(human['uuid'] in log_events) - self.assertTrue(ancestor['uuid'] in log_events) + log_object_uuids = [] + for i in range(0, expected): + log_object_uuids.append(events.get(True, 5)['object_uuid']) + + if expected > 0: + self.assertIn(human['uuid'], log_object_uuids) + + if expected > 1: + self.assertIn(ancestor['uuid'], log_object_uuids) + + with self.assertRaises(Queue.Empty): + # assertEqual just serves to show us what unexpected thing + # comes out of the queue when the assertRaises fails; when + # the test passes, this assertEqual doesn't get called. + self.assertEqual(events.get(True, 2), None) def test_subscribe_websocket(self): self._test_subscribe( - poll_fallback=False, expect_type=arvados.events.EventClient) + poll_fallback=False, expect_type=arvados.events.EventClient, expected=1) @mock.patch('arvados.events.EventClient.__init__') def test_subscribe_poll(self, event_client_constr): event_client_constr.side_effect = Exception('All is well') self._test_subscribe( - poll_fallback=1, expect_type=arvados.events.PollClient) + poll_fallback=0.25, expect_type=arvados.events.PollClient, expected=1) - def test_subscribe_websocket_with_start_time_date_only(self): - lastHour = datetime.today() - timedelta(hours = 1) + def test_subscribe_websocket_with_start_time_past(self): self._test_subscribe( - poll_fallback=False, expect_type=arvados.events.EventClient, last_log_id=1, - additional_filters=[['created_at', '>=', lastHour.strftime('%Y-%m-%d')]]) + poll_fallback=False, expect_type=arvados.events.EventClient, + start_time=self.localiso(self.TIME_PAST), + expected=2) @mock.patch('arvados.events.EventClient.__init__') - def test_poll_with_start_time_date_only(self, event_client_constr): + def test_subscribe_poll_with_start_time_past(self, event_client_constr): event_client_constr.side_effect = Exception('All is well') - lastHour = datetime.today() - timedelta(hours = 1) self._test_subscribe( - poll_fallback=1, expect_type=arvados.events.PollClient, last_log_id=1, - additional_filters=[['created_at', '>=', lastHour.strftime('%Y-%m-%d')]]) + poll_fallback=0.25, expect_type=arvados.events.PollClient, + start_time=self.localiso(self.TIME_PAST), + expected=2) - def test_subscribe_websocket_with_start_time_last_hour(self): - lastHour = datetime.today() - timedelta(hours = 1) + def test_subscribe_websocket_with_start_time_future(self): self._test_subscribe( - poll_fallback=False, expect_type=arvados.events.EventClient, last_log_id=1, - additional_filters=[['created_at', '>=', lastHour.strftime('%Y-%m-%d %H:%M:%S')]]) + poll_fallback=False, expect_type=arvados.events.EventClient, + start_time=self.localiso(self.TIME_FUTURE), + expected=0) @mock.patch('arvados.events.EventClient.__init__') - def test_subscribe_poll_with_start_time_last_hour(self, event_client_constr): + def test_subscribe_poll_with_start_time_future(self, event_client_constr): event_client_constr.side_effect = Exception('All is well') - lastHour = datetime.today() - timedelta(hours = 1) self._test_subscribe( - poll_fallback=1, expect_type=arvados.events.PollClient, last_log_id=1, - additional_filters=[['created_at', '>=', lastHour.strftime('%Y-%m-%d %H:%M:%S')]]) + poll_fallback=0.25, expect_type=arvados.events.PollClient, + start_time=self.localiso(self.TIME_FUTURE), + expected=0) - def test_subscribe_websocket_with_start_time_next_hour(self): - nextHour = datetime.today() + timedelta(hours = 1) - with self.assertRaises(Queue.Empty): - self._test_subscribe( - poll_fallback=False, expect_type=arvados.events.EventClient, last_log_id=1, - additional_filters=[['created_at', '>=', nextHour.strftime('%Y-%m-%d %H:%M:%S')]], expected=0) + def test_subscribe_websocket_with_start_time_past_utc(self): + self._test_subscribe( + poll_fallback=False, expect_type=arvados.events.EventClient, + start_time=self.utciso(self.TIME_PAST), + expected=2) - @mock.patch('arvados.events.EventClient.__init__') - def test_subscribe_poll_with_start_time_next_hour(self, event_client_constr): - event_client_constr.side_effect = Exception('All is well') - nextHour = datetime.today() + timedelta(hours = 1) - with self.assertRaises(Queue.Empty): - self._test_subscribe( - poll_fallback=1, expect_type=arvados.events.PollClient, last_log_id=1, - additional_filters=[['created_at', '>=', nextHour.strftime('%Y-%m-%d %H:%M:%S')]], expected=0) + def test_subscribe_websocket_with_start_time_future_utc(self): + self._test_subscribe( + poll_fallback=False, expect_type=arvados.events.EventClient, + start_time=self.utciso(self.TIME_FUTURE), + expected=0) - def test_subscribe_websocket_with_start_time_tomorrow(self): - tomorrow = datetime.today() + timedelta(hours = 24) - with self.assertRaises(Queue.Empty): - self._test_subscribe( - poll_fallback=False, expect_type=arvados.events.EventClient, last_log_id=1, - additional_filters=[['created_at', '>=', tomorrow.strftime('%Y-%m-%d')]], expected=0) + def utciso(self, t): + return time.strftime('%Y-%m-%dT%H:%M:%SZ', time.gmtime(t)) - @mock.patch('arvados.events.EventClient.__init__') - def test_subscribe_poll_with_start_time_tomorrow(self, event_client_constr): - event_client_constr.side_effect = Exception('All is well') - tomorrow = datetime.today() + timedelta(hours = 24) - with self.assertRaises(Queue.Empty): - self._test_subscribe( - poll_fallback=1, expect_type=arvados.events.PollClient, last_log_id=1, - additional_filters=[['created_at', '>=', tomorrow.strftime('%Y-%m-%d')]], expected=0) + def localiso(self, t): + return time.strftime('%Y-%m-%dT%H:%M:%S', time.localtime(t)) + self.isotz(-time.timezone/60) + + def isotz(self, offset): + """Convert minutes-east-of-UTC to ISO8601 time zone designator""" + return '{:+03d}{:02d}'.format(offset/60, offset%60) -- 2.30.2