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