• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1import abc
2import glob
3import logging
4import os
5import re
6import shutil
7import subprocess
8
9from distutils import dir_util
10
11from autotest_lib.client.common_lib import log
12from autotest_lib.client.cros import constants
13from autotest_lib.client.bin import utils, package
14
15_DEFAULT_COMMANDS_TO_LOG_PER_TEST = []
16_DEFAULT_COMMANDS_TO_LOG_PER_BOOT = [
17    'lspci -vvn',
18    'gcc --version',
19    'ld --version',
20    'mount',
21    'hostname',
22    'uptime',
23]
24_DEFAULT_COMMANDS_TO_LOG_BEFORE_ITERATION = []
25_DEFAULT_COMMANDS_TO_LOG_AFTER_ITERATION = []
26
27_DEFAULT_FILES_TO_LOG_PER_TEST = []
28_DEFAULT_FILES_TO_LOG_PER_BOOT = [
29    '/proc/pci',
30    '/proc/meminfo',
31    '/proc/slabinfo',
32    '/proc/version',
33    '/proc/cpuinfo',
34    '/proc/modules',
35    '/proc/interrupts',
36    '/proc/partitions',
37    '/var/log/bios_info.txt',
38    '/var/log/messages',
39    '/var/log/storage_info.txt',
40] + list(constants.LOG_PSTORE_DIRS)
41_DEFAULT_FILES_TO_LOG_BEFORE_ITERATION = [
42    '/proc/schedstat', '/proc/meminfo', '/proc/slabinfo', '/proc/interrupts'
43]
44_DEFAULT_FILES_TO_LOG_AFTER_ITERATION = [
45    '/proc/schedstat', '/proc/meminfo', '/proc/slabinfo', '/proc/interrupts'
46]
47
48
49class loggable(object):
50    """ Abstract class for representing all things "loggable" by sysinfo. """
51
52    def __init__(self, logf, log_in_keyval):
53        self.logf = logf
54        self.log_in_keyval = log_in_keyval
55
56    def readline(self, logdir):
57        """Reads one line from the log.
58
59        @param logdir: The log directory.
60        @return A line from the log, or the empty string if the log doesn't
61            exist.
62        """
63        path = os.path.join(logdir, self.logf)
64        if os.path.exists(path):
65            return utils.read_one_line(path)
66        else:
67            return ""
68
69    @abc.abstractmethod
70    def run(self, logdir):
71        """Executes this loggable creating output in logdir.
72
73        @param logdir: The output directory.
74        """
75        raise NotImplementedError()
76
77
78class logfile(loggable):
79    """Represents a log file."""
80    def __init__(self, path, logf=None, log_in_keyval=False):
81        if not logf:
82            logf = os.path.basename(path)
83        super(logfile, self).__init__(logf, log_in_keyval)
84        self.path = path
85
86
87    def __repr__(self):
88        r = "sysinfo.logfile(%r, %r, %r)"
89        r %= (self.path, self.logf, self.log_in_keyval)
90        return r
91
92
93    def __eq__(self, other):
94        if isinstance(other, logfile):
95            return (self.path, self.logf) == (other.path, other.logf)
96        elif isinstance(other, loggable):
97            return False
98        return NotImplemented
99
100
101    def __ne__(self, other):
102        result = self.__eq__(other)
103        if result is NotImplemented:
104            return result
105        return not result
106
107
108    def __hash__(self):
109        return hash((self.path, self.logf))
110
111
112    def run(self, logdir):
113        """Copies the log file or directory to the specified directory.
114
115        @param logdir: The log directory.
116        """
117        if os.path.exists(self.path):
118            if os.path.isdir(self.path):
119                dst = os.path.join(logdir, self.logf, self.path.lstrip('/'))
120                dir_util.copy_tree(self.path, dst)
121            else:
122                dst = os.path.join(logdir, self.logf)
123                shutil.copyfile(self.path, dst)
124            logging.debug('Loggable saves logs to %s', dst)
125
126
127class command(loggable):
128    """Represents a command."""
129    def __init__(self, cmd, logf=None, log_in_keyval=False, compress_log=False):
130        if not logf:
131            logf = cmd.replace(" ", "_")
132        super(command, self).__init__(logf, log_in_keyval)
133        self.cmd = cmd
134        self._compress_log = compress_log
135
136
137    def __repr__(self):
138        r = "sysinfo.command(%r, %r, %r)"
139        r %= (self.cmd, self.logf, self.log_in_keyval)
140        return r
141
142
143    def __eq__(self, other):
144        if isinstance(other, command):
145            return (self.cmd, self.logf) == (other.cmd, other.logf)
146        elif isinstance(other, loggable):
147            return False
148        return NotImplemented
149
150
151    def __ne__(self, other):
152        result = self.__eq__(other)
153        if result is NotImplemented:
154            return result
155        return not result
156
157
158    def __hash__(self):
159        return hash((self.cmd, self.logf))
160
161
162    def run(self, logdir):
163        """Runs the command.
164
165        @param logdir: The log directory.
166        """
167        env = os.environ.copy()
168        if "PATH" not in env:
169            env["PATH"] = "/usr/bin:/bin"
170        logf_path = os.path.join(logdir, self.logf)
171        stdin = open(os.devnull, "r")
172        stderr = open(os.devnull, "w")
173        stdout = open(logf_path, "w")
174        try:
175            logging.debug('Loggable runs cmd: %s', self.cmd)
176            subprocess.call(self.cmd,
177                            stdin=stdin,
178                            stdout=stdout,
179                            stderr=stderr,
180                            shell=True,
181                            env=env)
182        finally:
183            for f in (stdin, stdout, stderr):
184                f.close()
185            if self._compress_log and os.path.exists(logf_path):
186                utils.system('gzip -9 "%s"' % logf_path, ignore_status=True)
187
188
189class base_sysinfo(object):
190    """Represents system info."""
191    def __init__(self, job_resultsdir):
192        self.sysinfodir = self._get_sysinfodir(job_resultsdir)
193
194        # pull in the post-test logs to collect
195        self.test_loggables = set()
196        for cmd in _DEFAULT_COMMANDS_TO_LOG_PER_TEST:
197            self.test_loggables.add(command(cmd))
198        for filename in _DEFAULT_FILES_TO_LOG_PER_TEST:
199            self.test_loggables.add(logfile(filename))
200
201        # pull in the EXTRA post-boot logs to collect
202        self.boot_loggables = set()
203        for cmd in _DEFAULT_COMMANDS_TO_LOG_PER_BOOT:
204            self.boot_loggables.add(command(cmd))
205        for filename in _DEFAULT_FILES_TO_LOG_PER_BOOT:
206            self.boot_loggables.add(logfile(filename))
207
208        # pull in the pre test iteration logs to collect
209        self.before_iteration_loggables = set()
210        for cmd in _DEFAULT_COMMANDS_TO_LOG_BEFORE_ITERATION:
211            self.before_iteration_loggables.add(
212                command(cmd, logf=cmd.replace(" ", "_") + '.before'))
213        for fname in _DEFAULT_FILES_TO_LOG_BEFORE_ITERATION:
214            self.before_iteration_loggables.add(
215                logfile(fname, logf=os.path.basename(fname) + '.before'))
216
217        # pull in the post test iteration logs to collect
218        self.after_iteration_loggables = set()
219        for cmd in _DEFAULT_COMMANDS_TO_LOG_AFTER_ITERATION:
220            self.after_iteration_loggables.add(
221                command(cmd, logf=cmd.replace(" ", "_") + '.after'))
222        for fname in _DEFAULT_FILES_TO_LOG_AFTER_ITERATION:
223            self.after_iteration_loggables.add(
224                logfile(fname, logf=os.path.basename(fname) + '.after'))
225
226        # add in a couple of extra files and commands we want to grab
227        self.test_loggables.add(command("df -mP", logf="df"))
228        # We compress the dmesg because it can get large when kernels are
229        # configured with a large buffer and some tests trigger OOMs or
230        # other large "spam" that fill it up...
231        self.test_loggables.add(command('dmesg -c',
232                                        logf='dmesg',
233                                        compress_log=True))
234        self.test_loggables.add(command('journalctl -o export',
235                                        logf='journal',
236                                        compress_log=True))
237        self.boot_loggables.add(logfile('/proc/cmdline', log_in_keyval=True))
238        # log /proc/mounts but with custom filename since we already
239        # log the output of the "mount" command as the filename "mount"
240        self.boot_loggables.add(logfile('/proc/mounts', logf='proc_mounts'))
241        self.boot_loggables.add(command('uname -a',
242                                        logf='uname',
243                                        log_in_keyval=True))
244        self._installed_packages = []
245
246
247    def serialize(self):
248        """Returns parameters in a dictionary."""
249        return {"boot": self.boot_loggables, "test": self.test_loggables}
250
251
252    def deserialize(self, serialized):
253        """Stores parameters from a dictionary into instance variables.
254
255        @param serialized: A dictionary containing parameters to store as
256            instance variables.
257        """
258        self.boot_loggables = serialized["boot"]
259        self.test_loggables = serialized["test"]
260
261
262    @staticmethod
263    def _get_sysinfodir(resultsdir):
264        sysinfodir = os.path.join(resultsdir, "sysinfo")
265        if not os.path.exists(sysinfodir):
266            os.makedirs(sysinfodir)
267        return sysinfodir
268
269
270    def _get_reboot_count(self):
271        if not glob.glob(os.path.join(self.sysinfodir, "*")):
272            return -1
273        else:
274            return len(glob.glob(os.path.join(self.sysinfodir, "boot.*")))
275
276
277    def _get_boot_subdir(self, next=False):
278        reboot_count = self._get_reboot_count()
279        if next:
280            reboot_count += 1
281        if reboot_count < 1:
282            return self.sysinfodir
283        else:
284            boot_dir = "boot.%d" % (reboot_count - 1)
285            return os.path.join(self.sysinfodir, boot_dir)
286
287
288    def _get_iteration_subdir(self, test, iteration):
289        iter_dir = "iteration.%d" % iteration
290
291        logdir = os.path.join(self._get_sysinfodir(test.outputdir), iter_dir)
292        if not os.path.exists(logdir):
293            os.mkdir(logdir)
294        return logdir
295
296
297    @log.log_and_ignore_errors("post-reboot sysinfo error:")
298    def log_per_reboot_data(self):
299        """Logging hook called when a job starts, and again after any reboot."""
300        logdir = self._get_boot_subdir(next=True)
301        if not os.path.exists(logdir):
302            os.mkdir(logdir)
303
304        _run_loggables_ignoring_errors(
305                self.test_loggables | self.boot_loggables,
306                logdir)
307
308        # also log any installed packages
309        installed_path = os.path.join(logdir, "installed_packages")
310        installed_packages = "\n".join(package.list_all()) + "\n"
311        utils.open_write_close(installed_path, installed_packages)
312
313
314    @log.log_and_ignore_errors("pre-test sysinfo error:")
315    def log_before_each_test(self, test):
316        """Logging hook called before a test starts.
317
318        @param test: A test object.
319        """
320        self._installed_packages = package.list_all()
321        if os.path.exists("/var/log/messages"):
322            stat = os.stat("/var/log/messages")
323            self._messages_size = stat.st_size
324            self._messages_inode = stat.st_ino
325
326        if os.path.exists("/var/log/journal"):
327            # Find the current journal cursor so we later can save new messages.
328            cmd = "/usr/bin/journalctl  -n0 --show-cursor -q"
329            try:
330                cursor = utils.system_output(cmd)
331                prefix = "-- cursor: "
332                pos = cursor.find(prefix) + len(prefix)
333                self._journal_cursor = cursor[pos:]
334            except Exception, e:
335                logging.error("error running journalctl --show-cursor: %s", e)
336
337        # log some sysinfo data into the test keyval file in case system crash.
338        test_sysinfodir = self._get_sysinfodir(test.outputdir)
339        keyval = self.log_test_keyvals(test_sysinfodir)
340        test.write_test_keyval(keyval)
341
342
343    @log.log_and_ignore_errors("post-test sysinfo error:")
344    def log_after_each_test(self, test):
345        """Logging hook called after a test finishs.
346
347        @param test: A test object.
348        """
349        test_sysinfodir = self._get_sysinfodir(test.outputdir)
350
351        # create a symlink in the test sysinfo dir to the current boot
352        reboot_dir = self._get_boot_subdir()
353        assert os.path.exists(reboot_dir)
354        symlink_dest = os.path.join(test_sysinfodir, "reboot_current")
355        symlink_src = utils.get_relative_path(reboot_dir,
356                                              os.path.dirname(symlink_dest))
357        try:
358            os.symlink(symlink_src, symlink_dest)
359        except Exception, e:
360            raise Exception, '%s: whilst linking %s to %s' % (e, symlink_src,
361                                                              symlink_dest)
362
363        # run all the standard logging commands
364        _run_loggables_ignoring_errors(self.test_loggables, test_sysinfodir)
365
366        # grab any new data from /var/log/messages
367        self._log_messages(test_sysinfodir)
368
369        # grab any new data from systemd journal
370        self._log_journal(test_sysinfodir)
371
372        # log some sysinfo data into the test keyval file
373        keyval = self.log_test_keyvals(test_sysinfodir)
374        test.write_test_keyval(keyval)
375
376        # log any changes to installed packages
377        old_packages = set(self._installed_packages)
378        new_packages = set(package.list_all())
379        added_path = os.path.join(test_sysinfodir, "added_packages")
380        added_packages = "\n".join(new_packages - old_packages) + "\n"
381        utils.open_write_close(added_path, added_packages)
382        removed_path = os.path.join(test_sysinfodir, "removed_packages")
383        removed_packages = "\n".join(old_packages - new_packages) + "\n"
384        utils.open_write_close(removed_path, removed_packages)
385
386
387    @log.log_and_ignore_errors("pre-test siteration sysinfo error:")
388    def log_before_each_iteration(self, test, iteration=None):
389        """Logging hook called before a test iteration.
390
391        @param test: A test object.
392        @param iteration: A test iteration.
393        """
394        if not iteration:
395            iteration = test.iteration
396        logdir = self._get_iteration_subdir(test, iteration)
397        _run_loggables_ignoring_errors(self.before_iteration_loggables, logdir)
398        # Start each log with the board name for orientation.
399        board = utils.get_board_with_frequency_and_memory()
400        logging.info('ChromeOS BOARD = %s', board)
401        # Leave some autotest bread crumbs in the system logs.
402        utils.system('logger "autotest starting iteration %s on %s"' % (logdir,
403                                                                        board),
404                     ignore_status=True)
405
406
407    @log.log_and_ignore_errors("post-test siteration sysinfo error:")
408    def log_after_each_iteration(self, test, iteration=None):
409        """Logging hook called after a test iteration.
410
411        @param test: A test object.
412        @param iteration: A test iteration.
413        """
414        if not iteration:
415            iteration = test.iteration
416        logdir = self._get_iteration_subdir(test, iteration)
417        _run_loggables_ignoring_errors(self.after_iteration_loggables, logdir)
418        utils.system('logger "autotest finished iteration %s"' % logdir,
419                     ignore_status=True)
420
421
422    def _log_messages(self, logdir):
423        """Log all of the new data in /var/log/messages."""
424        try:
425            # log all of the new data in /var/log/messages
426            bytes_to_skip = 0
427            if hasattr(self, "_messages_size"):
428                current_inode = os.stat("/var/log/messages").st_ino
429                if current_inode == self._messages_inode:
430                    bytes_to_skip = self._messages_size
431            in_messages = open("/var/log/messages")
432            in_messages.seek(bytes_to_skip)
433            out_messages = open(os.path.join(logdir, "messages"), "w")
434            out_messages.write(in_messages.read())
435            in_messages.close()
436            out_messages.close()
437        except Exception, e:
438            logging.error("/var/log/messages collection failed with %s", e)
439
440
441    def _log_journal(self, logdir):
442        """Log all of the new data in systemd journal."""
443        if not hasattr(self, "_journal_cursor"):
444            return
445
446        cmd = "/usr/bin/journalctl --after-cursor \"%s\"" % (
447            self._journal_cursor)
448        try:
449            with open(os.path.join(logdir, "journal"), "w") as journal:
450              journal.write(utils.system_output(cmd))
451        except Exception, e:
452            logging.error("journal collection failed with %s", e)
453
454
455    @staticmethod
456    def _read_sysinfo_keyvals(loggables, logdir):
457        keyval = {}
458        for log in loggables:
459            if log.log_in_keyval:
460                keyval["sysinfo-" + log.logf] = log.readline(logdir)
461        return keyval
462
463
464    def log_test_keyvals(self, test_sysinfodir):
465        """Generate keyval for the sysinfo.
466
467        Collects keyval entries to be written in the test keyval.
468
469        @param test_sysinfodir: The test's system info directory.
470        """
471        keyval = {}
472
473        # grab any loggables that should be in the keyval
474        keyval.update(self._read_sysinfo_keyvals(self.test_loggables,
475                                                 test_sysinfodir))
476        keyval.update(self._read_sysinfo_keyvals(
477            self.boot_loggables, os.path.join(test_sysinfodir,
478                                              'reboot_current')))
479
480        # remove hostname from uname info
481        #   Linux lpt36 2.6.18-smp-230.1 #1 [4069269] SMP Fri Oct 24 11:30:...
482        if "sysinfo-uname" in keyval:
483            kernel_vers = " ".join(keyval["sysinfo-uname"].split()[2:])
484            keyval["sysinfo-uname"] = kernel_vers
485
486        # grab the total avail memory, not used by sys tables
487        path = os.path.join(test_sysinfodir, "reboot_current", "meminfo")
488        if os.path.exists(path):
489            mem_data = open(path).read()
490            match = re.search(r'^MemTotal:\s+(\d+) kB$', mem_data, re.MULTILINE)
491            if match:
492                keyval["sysinfo-memtotal-in-kb"] = match.group(1)
493
494        # guess the system's total physical memory, including sys tables
495        keyval["sysinfo-phys-mbytes"] = utils.rounded_memtotal()//1024
496
497        # return what we collected
498        return keyval
499
500def _run_loggables_ignoring_errors(loggables, output_dir):
501    """Runs the given loggables robustly.
502
503    In the event of any one of the loggables raising an exception, we print a
504    traceback and continue on.
505
506    @param loggables: An iterable of base_sysinfo.loggable objects.
507    @param output_dir: Path to the output directory.
508    """
509    for log in loggables:
510        try:
511            log.run(output_dir)
512        except Exception:
513            logging.exception(
514                    'Failed to collect loggable %r to %s. Continuing...',
515                    log, output_dir)
516