• 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
338    @log.log_and_ignore_errors("post-test sysinfo error:")
339    def log_after_each_test(self, test):
340        """Logging hook called after a test finishs.
341
342        @param test: A test object.
343        """
344        test_sysinfodir = self._get_sysinfodir(test.outputdir)
345
346        # create a symlink in the test sysinfo dir to the current boot
347        reboot_dir = self._get_boot_subdir()
348        assert os.path.exists(reboot_dir)
349        symlink_dest = os.path.join(test_sysinfodir, "reboot_current")
350        symlink_src = utils.get_relative_path(reboot_dir,
351                                              os.path.dirname(symlink_dest))
352        try:
353            os.symlink(symlink_src, symlink_dest)
354        except Exception, e:
355            raise Exception, '%s: whilst linking %s to %s' % (e, symlink_src,
356                                                              symlink_dest)
357
358        # run all the standard logging commands
359        _run_loggables_ignoring_errors(self.test_loggables, test_sysinfodir)
360
361        # grab any new data from /var/log/messages
362        self._log_messages(test_sysinfodir)
363
364        # grab any new data from systemd journal
365        self._log_journal(test_sysinfodir)
366
367        # log some sysinfo data into the test keyval file
368        keyval = self.log_test_keyvals(test_sysinfodir)
369        test.write_test_keyval(keyval)
370
371        # log any changes to installed packages
372        old_packages = set(self._installed_packages)
373        new_packages = set(package.list_all())
374        added_path = os.path.join(test_sysinfodir, "added_packages")
375        added_packages = "\n".join(new_packages - old_packages) + "\n"
376        utils.open_write_close(added_path, added_packages)
377        removed_path = os.path.join(test_sysinfodir, "removed_packages")
378        removed_packages = "\n".join(old_packages - new_packages) + "\n"
379        utils.open_write_close(removed_path, removed_packages)
380
381
382    @log.log_and_ignore_errors("pre-test siteration sysinfo error:")
383    def log_before_each_iteration(self, test, iteration=None):
384        """Logging hook called before a test iteration.
385
386        @param test: A test object.
387        @param iteration: A test iteration.
388        """
389        if not iteration:
390            iteration = test.iteration
391        logdir = self._get_iteration_subdir(test, iteration)
392        _run_loggables_ignoring_errors(self.before_iteration_loggables, logdir)
393        # Start each log with the board name for orientation.
394        board = utils.get_board_with_frequency_and_memory()
395        logging.info('ChromeOS BOARD = %s', board)
396        # Leave some autotest bread crumbs in the system logs.
397        utils.system('logger "autotest starting iteration %s on %s"' % (logdir,
398                                                                        board),
399                     ignore_status=True)
400
401
402    @log.log_and_ignore_errors("post-test siteration sysinfo error:")
403    def log_after_each_iteration(self, test, iteration=None):
404        """Logging hook called after a test iteration.
405
406        @param test: A test object.
407        @param iteration: A test iteration.
408        """
409        if not iteration:
410            iteration = test.iteration
411        logdir = self._get_iteration_subdir(test, iteration)
412        _run_loggables_ignoring_errors(self.after_iteration_loggables, logdir)
413        utils.system('logger "autotest finished iteration %s"' % logdir,
414                     ignore_status=True)
415
416
417    def _log_messages(self, logdir):
418        """Log all of the new data in /var/log/messages."""
419        try:
420            # log all of the new data in /var/log/messages
421            bytes_to_skip = 0
422            if hasattr(self, "_messages_size"):
423                current_inode = os.stat("/var/log/messages").st_ino
424                if current_inode == self._messages_inode:
425                    bytes_to_skip = self._messages_size
426            in_messages = open("/var/log/messages")
427            in_messages.seek(bytes_to_skip)
428            out_messages = open(os.path.join(logdir, "messages"), "w")
429            out_messages.write(in_messages.read())
430            in_messages.close()
431            out_messages.close()
432        except Exception, e:
433            logging.error("/var/log/messages collection failed with %s", e)
434
435
436    def _log_journal(self, logdir):
437        """Log all of the new data in systemd journal."""
438        if not hasattr(self, "_journal_cursor"):
439            return
440
441        cmd = "/usr/bin/journalctl --after-cursor \"%s\"" % (
442            self._journal_cursor)
443        try:
444            with open(os.path.join(logdir, "journal"), "w") as journal:
445              journal.write(utils.system_output(cmd))
446        except Exception, e:
447            logging.error("journal collection failed with %s", e)
448
449
450    @staticmethod
451    def _read_sysinfo_keyvals(loggables, logdir):
452        keyval = {}
453        for log in loggables:
454            if log.log_in_keyval:
455                keyval["sysinfo-" + log.logf] = log.readline(logdir)
456        return keyval
457
458
459    def log_test_keyvals(self, test_sysinfodir):
460        """Logging hook called by log_after_each_test.
461
462        Collects keyval entries to be written in the test keyval.
463
464        @param test_sysinfodir: The test's system info directory.
465        """
466        keyval = {}
467
468        # grab any loggables that should be in the keyval
469        keyval.update(self._read_sysinfo_keyvals(self.test_loggables,
470                                                 test_sysinfodir))
471        keyval.update(self._read_sysinfo_keyvals(
472            self.boot_loggables, os.path.join(test_sysinfodir,
473                                              'reboot_current')))
474
475        # remove hostname from uname info
476        #   Linux lpt36 2.6.18-smp-230.1 #1 [4069269] SMP Fri Oct 24 11:30:...
477        if "sysinfo-uname" in keyval:
478            kernel_vers = " ".join(keyval["sysinfo-uname"].split()[2:])
479            keyval["sysinfo-uname"] = kernel_vers
480
481        # grab the total avail memory, not used by sys tables
482        path = os.path.join(test_sysinfodir, "reboot_current", "meminfo")
483        if os.path.exists(path):
484            mem_data = open(path).read()
485            match = re.search(r'^MemTotal:\s+(\d+) kB$', mem_data, re.MULTILINE)
486            if match:
487                keyval["sysinfo-memtotal-in-kb"] = match.group(1)
488
489        # guess the system's total physical memory, including sys tables
490        keyval["sysinfo-phys-mbytes"] = utils.rounded_memtotal()//1024
491
492        # return what we collected
493        return keyval
494
495def _run_loggables_ignoring_errors(loggables, output_dir):
496    """Runs the given loggables robustly.
497
498    In the event of any one of the loggables raising an exception, we print a
499    traceback and continue on.
500
501    @param loggables: An iterable of base_sysinfo.loggable objects.
502    @param output_dir: Path to the output directory.
503    """
504    for log in loggables:
505        try:
506            log.run(output_dir)
507        except Exception:
508            logging.exception(
509                    'Failed to collect loggable %r to %s. Continuing...',
510                    log, output_dir)
511