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