| OLD | NEW |
| (Empty) |
| 1 # Copyright 2015 The Chromium Authors. All rights reserved. | |
| 2 # Use of this source code is governed by a BSD-style license that can be | |
| 3 # found in the LICENSE file. | |
| 4 | |
| 5 import logging | |
| 6 import os | |
| 7 import random | |
| 8 import StringIO | |
| 9 import time | |
| 10 import unittest | |
| 11 | |
| 12 import httplib2 | |
| 13 import mock | |
| 14 | |
| 15 import infra_libs | |
| 16 from infra_libs.event_mon import config | |
| 17 from infra_libs.event_mon import router | |
| 18 from infra_libs.event_mon.protos.chrome_infra_log_pb2 import ChromeInfraEvent | |
| 19 from infra_libs.event_mon.protos.log_request_lite_pb2 import LogRequestLite | |
| 20 import infra_libs.event_mon.monitoring | |
| 21 | |
| 22 | |
| 23 DATA_DIR = os.path.join(os.path.dirname(os.path.realpath(__file__)), 'data') | |
| 24 | |
| 25 | |
| 26 class HttpRouterTests(unittest.TestCase): | |
| 27 def test_without_credentials_smoke(self): | |
| 28 # Use dry_run to avoid code that deals with http. | |
| 29 r = router._HttpRouter({}, 'https://any.where', dry_run=True) | |
| 30 self.assertIsInstance(r._http, infra_libs.InstrumentedHttp) | |
| 31 | |
| 32 def test_with_credentials_smoke(self): | |
| 33 cache = {'service_account_creds': | |
| 34 os.path.join(DATA_DIR, 'valid_creds.json'), | |
| 35 'service_accounts_creds_root': 'whatever.the/other/is/absolute'} | |
| 36 r = router._HttpRouter(cache, 'https://any.where', dry_run=True) | |
| 37 self.assertIsInstance(r._http, infra_libs.InstrumentedHttp) | |
| 38 | |
| 39 def test_with_nonexisting_credentials(self): | |
| 40 cache = {'service_account_creds': | |
| 41 os.path.join(DATA_DIR, 'no-such-file-8531.json'), | |
| 42 'service_accounts_creds_root': 'whatever.the/other/is/absolute'} | |
| 43 # things should work. | |
| 44 r = router._HttpRouter(cache, 'https://any.where', dry_run=True) | |
| 45 self.assertIsInstance(r._http, infra_libs.InstrumentedHttp) | |
| 46 | |
| 47 def test_push_smoke(self): | |
| 48 r = router._HttpRouter({}, 'https://any.where', dry_run=True) | |
| 49 | |
| 50 req = LogRequestLite.LogEventLite() | |
| 51 req.event_time_ms = router.time_ms() | |
| 52 req.event_code = 1 | |
| 53 req.event_flow_id = 2 | |
| 54 self.assertTrue(r.push_event(req)) | |
| 55 | |
| 56 def test_push_invalid_event(self): | |
| 57 r = router._HttpRouter({}, 'https://any.where', dry_run=True) | |
| 58 self.assertFalse(r.push_event(None)) | |
| 59 | |
| 60 def test_invalid_url(self): | |
| 61 event = LogRequestLite.LogEventLite() | |
| 62 event.event_time_ms = router.time_ms() | |
| 63 event.event_code = 1 | |
| 64 event.event_flow_id = 2 | |
| 65 | |
| 66 r = router._HttpRouter({}, 'ftp://any.where', dry_run=True) | |
| 67 self.assertFalse(r.push_event(event)) | |
| 68 | |
| 69 # Below this line, test the send/retry loop. | |
| 70 def test_push_ok(self): | |
| 71 # Successfully push event the first time. | |
| 72 sleep = mock.create_autospec(time.sleep, auto_set=True) | |
| 73 r = router._HttpRouter({}, 'https://bla.bla', _sleep_fn=sleep) | |
| 74 r._http = infra_libs.HttpMock([('https://bla.bla', {'status': 200}, '')]) | |
| 75 | |
| 76 event = LogRequestLite.LogEventLite() | |
| 77 event.event_time_ms = router.time_ms() | |
| 78 event.event_code = 1 | |
| 79 event.event_flow_id = 2 | |
| 80 self.assertTrue(r.push_event(event)) | |
| 81 self.assertEquals(len(sleep.call_args_list), 0) | |
| 82 | |
| 83 def test_push_fail(self): | |
| 84 # Fail to push events even after all retries | |
| 85 sleep = mock.create_autospec(time.sleep, auto_set=True) | |
| 86 r = router._HttpRouter({}, 'https://bla.bla', _sleep_fn=sleep) | |
| 87 r._http = infra_libs.HttpMock([('https://bla.bla', {'status': 403}, '')]) | |
| 88 | |
| 89 event = LogRequestLite.LogEventLite() | |
| 90 event.event_time_ms = router.time_ms() | |
| 91 event.event_code = 1 | |
| 92 event.event_flow_id = 2 | |
| 93 self.assertFalse(r.push_event(event)) | |
| 94 self.assertEquals(len(sleep.call_args_list), r.try_num) | |
| 95 | |
| 96 def test_push_exception(self): | |
| 97 # Fail to push events even after all retries | |
| 98 sleep = mock.create_autospec(time.sleep, auto_set=True) | |
| 99 r = router._HttpRouter({}, 'https://bla.bla', _sleep_fn=sleep) | |
| 100 | |
| 101 class FakeHttp(object): | |
| 102 # pylint: disable=unused-argument | |
| 103 def request(self, *args, **kwargs): | |
| 104 raise ValueError() | |
| 105 | |
| 106 r._http = FakeHttp() | |
| 107 | |
| 108 event = LogRequestLite.LogEventLite() | |
| 109 event.event_time_ms = router.time_ms() | |
| 110 event.event_code = 1 | |
| 111 event.event_flow_id = 2 | |
| 112 self.assertFalse(r.push_event(event)) | |
| 113 self.assertEquals(len(sleep.call_args_list), 3) | |
| 114 | |
| 115 @mock.patch('logging.debug', autospec=True) | |
| 116 def test_logs_success(self, logdebug): | |
| 117 r = router._HttpRouter({}, 'https://bla.bla') | |
| 118 r._http = infra_libs.HttpMock([('https://bla.bla', {'status': 200}, '')]) | |
| 119 | |
| 120 event = LogRequestLite.LogEventLite() | |
| 121 event.event_time_ms = router.time_ms() | |
| 122 event.event_code = 1 | |
| 123 event.event_flow_id = 2 | |
| 124 self.assertTrue(r.push_event(event)) | |
| 125 self.assertIn(mock.call('Succeeded POSTing data after %d attempts', 1), | |
| 126 logdebug.call_args_list) | |
| 127 | |
| 128 | |
| 129 class TextStreamRouterTests(unittest.TestCase): | |
| 130 def test_stdout_smoke(self): | |
| 131 event = LogRequestLite.LogEventLite() | |
| 132 event.event_time_ms = router.time_ms() | |
| 133 event.event_code = 1 | |
| 134 event.event_flow_id = 2 | |
| 135 r = router._TextStreamRouter() | |
| 136 self.assertTrue(r.push_event(event)) | |
| 137 | |
| 138 def test_stringio_stream(self): | |
| 139 config._cache['default_event'] = ChromeInfraEvent() | |
| 140 log_event = infra_libs.event_mon.monitoring._get_service_event( | |
| 141 'START', timestamp_kind='POINT', event_timestamp=1234).log_event() | |
| 142 | |
| 143 stream = StringIO.StringIO() | |
| 144 r = router._TextStreamRouter(stream=stream) | |
| 145 self.assertTrue(r.push_event(log_event)) | |
| 146 stream.seek(0) | |
| 147 output = stream.read() | |
| 148 self.assertGreater(stream.len, 10) | |
| 149 # Minimal checking because if this is printed the rest is printed as well | |
| 150 # unless google.protobuf is completely broken. | |
| 151 self.assertIn('timestamp_kind: POINT', output) | |
| 152 | |
| 153 def test_closed_stream(self): | |
| 154 event = LogRequestLite.LogEventLite() | |
| 155 event.event_time_ms = router.time_ms() | |
| 156 event.event_code = 1 | |
| 157 event.event_flow_id = 2 | |
| 158 stream = StringIO.StringIO() | |
| 159 stream.close() | |
| 160 r = router._TextStreamRouter(stream=stream) | |
| 161 self.assertFalse(r.push_event(event)) | |
| 162 | |
| 163 | |
| 164 class LocalFileRouterTests(unittest.TestCase): | |
| 165 def test_existing_directory(self): | |
| 166 event = LogRequestLite.LogEventLite() | |
| 167 event.event_time_ms = router.time_ms() | |
| 168 event.event_code = 1 | |
| 169 event.event_flow_id = 2 | |
| 170 | |
| 171 with infra_libs.temporary_directory(prefix='event-mon-') as tempdir: | |
| 172 filename = os.path.join(tempdir, 'output.db') | |
| 173 r = router._LocalFileRouter(filename, dry_run=False) | |
| 174 self.assertTrue(r.push_event(event)) | |
| 175 | |
| 176 # Check that the file is readable and contains the right data. | |
| 177 with open(filename, 'rb') as f: | |
| 178 req_read = LogRequestLite.FromString(f.read()) | |
| 179 self.assertEqual(len(req_read.log_event), 1) | |
| 180 event_read = req_read.log_event[0] | |
| 181 self.assertEqual(event_read.event_time_ms, event.event_time_ms) | |
| 182 self.assertEqual(event_read.event_code, event.event_code) | |
| 183 self.assertEqual(event_read.event_flow_id, event.event_flow_id) | |
| 184 | |
| 185 def test_existing_directory_dry_run(self): | |
| 186 event = LogRequestLite.LogEventLite() | |
| 187 event.event_time_ms = router.time_ms() | |
| 188 event.event_code = 1 | |
| 189 event.event_flow_id = 2 | |
| 190 | |
| 191 with infra_libs.temporary_directory(prefix='event-mon-') as tempdir: | |
| 192 filename = os.path.join(tempdir, 'output.db') | |
| 193 r = router._LocalFileRouter(filename, dry_run=True) | |
| 194 self.assertTrue(r.push_event(event)) | |
| 195 | |
| 196 # Check that the file has not been written | |
| 197 self.assertFalse(os.path.exists(filename)) | |
| 198 | |
| 199 def test_non_existing_directory(self): | |
| 200 req = LogRequestLite.LogEventLite() | |
| 201 req.event_time_ms = router.time_ms() | |
| 202 req.event_code = 1 | |
| 203 req.event_flow_id = 2 | |
| 204 r = router._LocalFileRouter( | |
| 205 os.path.join('non_existing_d1r_31401789', 'output.db'), dry_run=False) | |
| 206 self.assertFalse(r.push_event(req)) | |
| 207 | |
| 208 | |
| 209 class BackoffTest(unittest.TestCase): | |
| 210 def test_backoff_time_first_value(self): | |
| 211 t = router.backoff_time(attempt=0, retry_backoff=2.) | |
| 212 random.seed(0) | |
| 213 self.assertTrue(1.5 <= t <= 2.5) | |
| 214 | |
| 215 def test_backoff_time_max_value(self): | |
| 216 t = router.backoff_time(attempt=10, retry_backoff=2., max_delay=5) | |
| 217 self.assertTrue(abs(t - 5.) < 0.0001) | |
| 218 | |
| 219 | |
| 220 class LoggingStreamRouterTests(unittest.TestCase): | |
| 221 @mock.patch('logging.log') | |
| 222 def test_events_are_logged_correctly(self, log_mock): | |
| 223 logger = router._LoggingStreamRouter() | |
| 224 events = [] | |
| 225 for i in range(3): | |
| 226 event = LogRequestLite.LogEventLite() | |
| 227 event.event_time_ms = router.time_ms() | |
| 228 event.event_code = 1 | |
| 229 event.event_flow_id = 2 | |
| 230 infra_event = ChromeInfraEvent() | |
| 231 infra_event.cq_event.issue = str(i + 1) | |
| 232 event.source_extension = infra_event.SerializeToString() | |
| 233 events.append(event) | |
| 234 | |
| 235 self.assertTrue(logger.push_event(events)) | |
| 236 | |
| 237 expected_calls = [ | |
| 238 ((logging.INFO, | |
| 239 'Sending event_mon event:\ncq_event {\n issue: "1"\n}\n'),), | |
| 240 ((logging.INFO, | |
| 241 'Sending event_mon event:\ncq_event {\n issue: "2"\n}\n'),), | |
| 242 ((logging.INFO, | |
| 243 'Sending event_mon event:\ncq_event {\n issue: "3"\n}\n'),)] | |
| 244 self.assertEqual(log_mock.call_args_list, expected_calls) | |
| 245 | |
| 246 @mock.patch('logging.log') | |
| 247 def test_events_are_logged_with_specified_severity(self, log_mock): | |
| 248 logger = router._LoggingStreamRouter(logging.WARN) | |
| 249 event = LogRequestLite.LogEventLite() | |
| 250 event.event_time_ms = router.time_ms() | |
| 251 event.event_code = 1 | |
| 252 event.event_flow_id = 2 | |
| 253 self.assertTrue(logger.push_event(event)) | |
| 254 self.assertEqual(log_mock.call_args[0], (logging.WARN, mock.ANY)) | |
| 255 | |
| 256 @mock.patch('logging.exception') | |
| 257 def test_fails_to_log(self, exception_mock): | |
| 258 logger = router._LoggingStreamRouter(logging.WARN) | |
| 259 event = LogRequestLite.LogEventLite() | |
| 260 event.event_time_ms = router.time_ms() | |
| 261 event.event_code = 1 | |
| 262 event.event_flow_id = 2 | |
| 263 event.source_extension = 'not-a-message' | |
| 264 self.assertFalse(logger.push_event(event)) | |
| 265 self.assertEqual(exception_mock.call_args[0], ('Unable to log the events',)) | |
| OLD | NEW |