1 # Copyright (c) 2011 The Chromium OS 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, os, re 6 from autotest_lib.client.bin import utils 7 from autotest_lib.client.common_lib import error 8 from autotest_lib.client.cros.crash import crash_test 9 10 11 _25_HOURS_AGO = -25 * 60 * 60 12 _CRASH_SENDER_CRON_PATH = '/etc/cron.hourly/crash_sender.hourly' 13 _DAILY_RATE_LIMIT = 32 14 _MIN_UNIQUE_TIMES = 4 15 _SECONDS_SEND_SPREAD = 3600 16 17 class logging_CrashSender(crash_test.CrashTest): 18 """ 19 End-to-end test of crash_sender. 20 """ 21 version = 1 22 23 24 def _check_hardware_info(self, result): 25 # Get board name 26 lsb_release = utils.read_file('/etc/lsb-release') 27 board_match = re.search(r'CHROMEOS_RELEASE_BOARD=(.*)', lsb_release) 28 if not ('Board: %s' % board_match.group(1)) in result['output']: 29 raise error.TestFail('Missing board name %s in output' % 30 board_match.group(1)) 31 # Get hwid 32 with os.popen("crossystem hwid 2>/dev/null", "r") as hwid_proc: 33 hwclass = hwid_proc.read() 34 if not hwclass: 35 hwclass = 'undefined' 36 if not ('HWClass: %s' % hwclass) in result['output']: 37 raise error.TestFail('Expected hwclass %s in output' % hwclass) 38 39 40 def _check_simple_minidump_send(self, report, log_path=None): 41 result = self._call_sender_one_crash(report=report) 42 if (result['report_exists'] or 43 result['rate_count'] != 1 or 44 not result['send_attempt'] or 45 not result['send_success'] or 46 result['sleep_time'] < 0 or 47 result['sleep_time'] >= _SECONDS_SEND_SPREAD or 48 result['report_kind'] != 'minidump' or 49 result['report_payload'] != self.get_crash_dir_name( 50 '%s.dmp' % self._FAKE_TEST_BASENAME) or 51 result['exec_name'] != 'fake' or 52 not 'Version: my_ver' in result['output']): 53 raise error.TestFail('Simple minidump send failed') 54 if log_path and not ('log: @%s' % log_path) in result['output']: 55 raise error.TestFail('Minidump send missing log') 56 self._check_hardware_info(result) 57 # Also test "Image type" field. Note that it will not be "dev" even 58 # on a dev build because crash-test-in-progress will exist. 59 if result['image_type']: 60 raise error.TestFail('Image type "%s" should not exist' % 61 result['image_type']) 62 # Also test "Boot mode" field. Note that it will not be "dev" even 63 # when booting in dev mode because crash-test-in-progress will exist. 64 if result['boot_mode']: 65 raise error.TestFail('Boot mode "%s" should not exist' % 66 result['boot_mode']) 67 68 69 def _test_sender_simple_minidump(self): 70 """Test sending a single minidump crash report.""" 71 self._check_simple_minidump_send(None) 72 73 74 def _test_sender_simple_minidump_with_log(self): 75 """Test that a minidump report with an auxiliary log is sent.""" 76 dmp_path = self.write_crash_dir_entry( 77 '%s.dmp' % self._FAKE_TEST_BASENAME, '') 78 log_path = self.write_crash_dir_entry( 79 '%s.log' % self._FAKE_TEST_BASENAME, '') 80 meta_path = self.write_fake_meta( 81 '%s.meta' % self._FAKE_TEST_BASENAME, 'fake', dmp_path, 82 log=log_path) 83 self._check_simple_minidump_send(meta_path, log_path) 84 85 86 def _shift_file_mtime(self, path, delta): 87 statinfo = os.stat(path) 88 os.utime(path, (statinfo.st_atime, 89 statinfo.st_mtime + delta)) 90 91 92 def _test_sender_simple_old_minidump(self): 93 """Test that old minidumps and metadata are sent.""" 94 dmp_path = self.write_crash_dir_entry( 95 '%s.dmp' % self._FAKE_TEST_BASENAME, '') 96 meta_path = self.write_fake_meta( 97 '%s.meta' % self._FAKE_TEST_BASENAME, 'fake', dmp_path) 98 self._shift_file_mtime(dmp_path, _25_HOURS_AGO) 99 self._shift_file_mtime(meta_path, _25_HOURS_AGO) 100 self._check_simple_minidump_send(meta_path) 101 102 103 def _test_sender_simple_kernel_crash(self): 104 """Test sending a single kcrash report.""" 105 kcrash_fake_report = self.write_crash_dir_entry( 106 'kernel.today.kcrash', '') 107 self.write_fake_meta('kernel.today.meta', 108 'kernel', 109 kcrash_fake_report) 110 result = self._call_sender_one_crash(report=kcrash_fake_report) 111 if (result['report_exists'] or 112 result['rate_count'] != 1 or 113 not result['send_attempt'] or 114 not result['send_success'] or 115 result['sleep_time'] < 0 or 116 result['sleep_time'] >= _SECONDS_SEND_SPREAD or 117 result['report_kind'] != 'kcrash' or 118 (result['report_payload'] != 119 self.get_crash_dir_name('kernel.today.kcrash')) or 120 result['exec_name'] != 'kernel'): 121 raise error.TestFail('Simple kcrash send failed') 122 self._check_hardware_info(result) 123 124 125 def _test_sender_pausing(self): 126 """Test the sender returns immediately when the pause file is present. 127 128 This is testing the sender's test functionality - if this regresses, 129 other tests can become flaky because the cron-started sender may run 130 asynchronously to these tests. Disable child sending as normally 131 this environment configuration allows our children to run in spite of 132 the pause file.""" 133 self._set_system_sending(False) 134 self._set_child_sending(False) 135 result = self._call_sender_one_crash(should_fail=True) 136 if (not result['report_exists'] or 137 not 'Exiting early due to' in result['output'] or 138 result['send_attempt']): 139 raise error.TestFail('Sender did not pause') 140 141 142 def _test_sender_reports_disabled(self): 143 """Test that when reporting is disabled, we don't send.""" 144 result = self._call_sender_one_crash(reports_enabled=False) 145 if (result['report_exists'] or 146 not 'Crash reporting is disabled' in result['output'] or 147 result['send_attempt']): 148 raise error.TestFail('Sender did not handle reports disabled') 149 150 151 def _test_sender_rate_limiting(self): 152 """Test the sender properly rate limits and sends with delay.""" 153 sleep_times = [] 154 for i in range(1, _DAILY_RATE_LIMIT + 1): 155 result = self._call_sender_one_crash() 156 if not result['send_attempt'] or not result['send_success']: 157 raise error.TestFail('Crash uploader did not send on #%d' % i) 158 if result['rate_count'] != i: 159 raise error.TestFail('Did not properly persist rate on #%d' % i) 160 sleep_times.append(result['sleep_time']) 161 logging.debug('Sleeps between sending crashes were: %s', sleep_times) 162 unique_times = {} 163 for i in range(0, _DAILY_RATE_LIMIT): 164 unique_times[sleep_times[i]] = True 165 if len(unique_times) < _MIN_UNIQUE_TIMES: 166 raise error.TestFail('Expected at least %d unique times: %s' % 167 _MIN_UNIQUE_TIMES, sleep_times) 168 # Now the _DAILY_RATE_LIMIT ^ th send request should fail. 169 result = self._call_sender_one_crash() 170 if (not result['report_exists'] or 171 not 'Cannot send more crashes' in result['output'] or 172 result['rate_count'] != _DAILY_RATE_LIMIT): 173 raise error.TestFail('Crash rate limiting did not take effect') 174 175 # Set one rate file a day earlier and verify can send 176 rate_files = os.listdir(self._CRASH_SENDER_RATE_DIR) 177 rate_path = os.path.join(self._CRASH_SENDER_RATE_DIR, rate_files[0]) 178 self._shift_file_mtime(rate_path, _25_HOURS_AGO) 179 utils.system('ls -l ' + self._CRASH_SENDER_RATE_DIR) 180 result = self._call_sender_one_crash() 181 if (not result['send_attempt'] or 182 not result['send_success'] or 183 result['rate_count'] != _DAILY_RATE_LIMIT): 184 raise error.TestFail('Crash not sent even after 25hrs pass') 185 186 187 def _test_sender_single_instance(self): 188 """Test the sender fails to start when another instance is running.""" 189 with self.hold_crash_lock(): 190 result = self._call_sender_one_crash(should_fail=True) 191 if (not 'Already running; quitting.' in result['output'] or 192 result['send_attempt'] or not result['report_exists']): 193 raise error.TestFail('Allowed multiple instances to run') 194 195 196 def _test_sender_send_fails(self): 197 """Test that when the send fails we try again later.""" 198 result = self._call_sender_one_crash(send_success=False) 199 if not result['send_attempt'] or result['send_success']: 200 raise error.TestError('Did not properly cause a send failure') 201 if result['rate_count'] != 1: 202 raise error.TestFail('Did not count a failed send against rate ' 203 'limiting') 204 if not result['report_exists']: 205 raise error.TestFail('Expected minidump to be saved for later ' 206 'sending') 207 208 # Also test "Image type" field. For testing purposes, we set it upon 209 # mock failure. Note that it will not be "dev" even on a dev build 210 # because crash-test-in-progress will exist. 211 if not result['image_type']: 212 raise error.TestFail('Missing image type on mock failure') 213 if result['image_type'] != 'mock-fail': 214 raise error.TestFail('Incorrect image type on mock failure ' 215 '("%s" != "mock-fail")' % 216 result['image_type']) 217 218 219 def _test_sender_orphaned_files(self): 220 """Test that payload and unknown files that are old are removed.""" 221 core_file = self.write_crash_dir_entry('random1.core', '') 222 unknown_file = self.write_crash_dir_entry('.unknown', '') 223 # As new files, we expect crash_sender to leave these alone. 224 results = self._call_sender_one_crash() 225 if ('Removing old orphaned file' in results['output'] or 226 not os.path.exists(core_file) or 227 not os.path.exists(unknown_file)): 228 raise error.TestFail('New orphaned files were removed') 229 self._shift_file_mtime(core_file, _25_HOURS_AGO) 230 self._shift_file_mtime(unknown_file, _25_HOURS_AGO) 231 results = self._call_sender_one_crash() 232 if (not 'Removing old orphaned file' in results['output'] or 233 os.path.exists(core_file) or os.path.exists(unknown_file)): 234 raise error.TestFail( 235 'Old orphaned files were not removed') 236 237 238 def _test_sender_incomplete_metadata(self): 239 """Test that incomplete metadata file is removed once old.""" 240 dmp_file = self.write_crash_dir_entry('incomplete.1.2.3.dmp', '') 241 meta_file = self.write_fake_meta('incomplete.1.2.3.meta', 242 'unknown', 243 dmp_file, 244 complete=False) 245 # As new files, we expect crash_sender to leave these alone. 246 results = self._call_sender_one_crash() 247 if ('Removing recent incomplete report' in results['output'] or 248 not os.path.exists(meta_file) or 249 not os.path.exists(dmp_file)): 250 raise error.TestFail('New unknown files were removed') 251 self._shift_file_mtime(meta_file, _25_HOURS_AGO) 252 results = self._call_sender_one_crash() 253 if (not 'Removing old incomplete metadata' in results['output'] or 254 os.path.exists(meta_file) or os.path.exists(dmp_file)): 255 raise error.TestFail( 256 'Old unknown/incomplete files were not removed') 257 258 259 def _test_sender_missing_payload(self): 260 meta_file = self.write_fake_meta('bad.meta', 261 'unknown', 262 'bad.dmp') 263 other_file = self.write_crash_dir_entry('bad.other', '') 264 results = self._call_sender_one_crash(report=meta_file) 265 # Should remove this file. 266 if (not 'Missing payload' in results['output'] or 267 os.path.exists(meta_file) or 268 os.path.exists(other_file)): 269 raise error.TestFail('Missing payload case handled wrong') 270 271 272 def _test_sender_error_type(self): 273 dmp_file = self.write_crash_dir_entry('error_type.dmp', '') 274 meta_file = self.write_fake_meta('error_type.meta', 'fake', dmp_file, 275 complete=False) 276 utils.write_keyval(meta_file, {"error_type": "system-issue"}) 277 utils.write_keyval(meta_file, {"done": "1"}) 278 self._set_force_official(True) # also test this 279 self._set_mock_developer_mode(True) # also test "boot_mode" field 280 result = self._call_sender_one_crash(report=meta_file) 281 if not result['error_type']: 282 raise error.TestFail('Missing error type') 283 if result['error_type'] != 'system-issue': 284 raise error.TestFail('Incorrect error type "%s"' % 285 result['error_type']) 286 287 # Also test force-official override by checking the image type. Note 288 # that it will not be "dev" even on a dev build because 289 # crash-test-in-progress will exist. 290 if not result['image_type']: 291 raise error.TestFail('Missing image type when forcing official') 292 if result['image_type'] != 'force-official': 293 raise error.TestFail('Incorrect image type ("%s" != ' 294 '"force-official")' % result['image_type']) 295 296 # Also test "Boot mode" field. For testing purposes, it should 297 # have been set to "dev" mode. 298 if not result['boot_mode']: 299 raise error.TestFail('Missing boot mode when mocking dev mode') 300 if result['boot_mode'] != 'dev': 301 raise error.TestFail('Incorrect boot mode when mocking dev mode ' 302 '("%s" != "dev")' % result['boot_mode']) 303 304 305 def run_once(self): 306 self.run_crash_tests([ 307 'sender_simple_minidump', 308 'sender_simple_old_minidump', 309 'sender_simple_minidump_with_log', 310 'sender_simple_kernel_crash', 311 'sender_pausing', 312 'sender_reports_disabled', 313 'sender_rate_limiting', 314 'sender_single_instance', 315 'sender_send_fails', 316 'sender_orphaned_files', 317 'sender_incomplete_metadata', 318 'sender_missing_payload', 319 'sender_error_type']); 320
