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
5import logging, os, re
6from autotest_lib.client.bin import utils
7from autotest_lib.client.common_lib import error
8from 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
17class 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