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