• 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        if compress_log:
135            self.cmd += ' | gzip -9'
136            self.logf += '.gz'
137
138
139    def __repr__(self):
140        r = "sysinfo.command(%r, %r, %r)"
141        r %= (self.cmd, self.logf, self.log_in_keyval)
142        return r
143
144
145    def __eq__(self, other):
146        if isinstance(other, command):
147            return (self.cmd, self.logf) == (other.cmd, other.logf)
148        elif isinstance(other, loggable):
149            return False
150        return NotImplemented
151
152
153    def __ne__(self, other):
154        result = self.__eq__(other)
155        if result is NotImplemented:
156            return result
157        return not result
158
159
160    def __hash__(self):
161        return hash((self.cmd, self.logf))
162
163
164    def run(self, logdir):
165        """Runs the command.
166
167        @param logdir: The log directory.
168        """
169        env = os.environ.copy()
170        if "PATH" not in env:
171            env["PATH"] = "/usr/bin:/bin"
172        logf_path = os.path.join(logdir, self.logf)
173        stdin = open(os.devnull, "r")
174        stderr = open(os.devnull, "w")
175        stdout = open(logf_path, "w")
176        try:
177            logging.debug('Loggable runs cmd: %s', self.cmd)
178            subprocess.call(self.cmd,
179                            stdin=stdin,
180                            stdout=stdout,
181                            stderr=stderr,
182                            shell=True,
183                            env=env)
184        finally:
185            for f in (stdin, stdout, stderr):
186                f.close()
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.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        self._journal_cursor = None
243
244
245    def serialize(self):
246        """Returns parameters in a dictionary."""
247        return {"boot": self.boot_loggables, "test": self.test_loggables}
248
249
250    def deserialize(self, serialized):
251        """Stores parameters from a dictionary into instance variables.
252
253        @param serialized: A dictionary containing parameters to store as
254            instance variables.
255        """
256        self.boot_loggables = serialized["boot"]
257        self.test_loggables = serialized["test"]
258
259
260    @staticmethod
261    def _get_sysinfodir(resultsdir):
262        sysinfodir = os.path.join(resultsdir, "sysinfo")
263        if not os.path.exists(sysinfodir):
264            os.makedirs(sysinfodir)
265        return sysinfodir
266
267
268    def _get_reboot_count(self):
269        if not glob.glob(os.path.join(self.sysinfodir, "*")):
270            return -1
271        else:
272            return len(glob.glob(os.path.join(self.sysinfodir, "boot.*")))
273
274
275    def _get_boot_subdir(self, next=False):
276        reboot_count = self._get_reboot_count()
277        if next:
278            reboot_count += 1
279        if reboot_count < 1:
280            return self.sysinfodir
281        else:
282            boot_dir = "boot.%d" % (reboot_count - 1)
283            return os.path.join(self.sysinfodir, boot_dir)
284
285
286    def _get_iteration_subdir(self, test, iteration):
287        iter_dir = "iteration.%d" % iteration
288
289        logdir = os.path.join(self._get_sysinfodir(test.outputdir), iter_dir)
290        if not os.path.exists(logdir):
291            os.mkdir(logdir)
292        return logdir
293
294
295    @log.log_and_ignore_errors("post-reboot sysinfo error:")
296    def log_per_reboot_data(self):
297        """Logging hook called when a job starts, and again after any reboot."""
298        logdir = self._get_boot_subdir(next=True)
299        if not os.path.exists(logdir):
300            os.mkdir(logdir)
301
302        _run_loggables_ignoring_errors(
303                self.test_loggables | self.boot_loggables,
304                logdir)
305
306        # also log any installed packages
307        installed_path = os.path.join(logdir, "installed_packages")
308        installed_packages = "\n".join(package.list_all()) + "\n"
309        utils.open_write_close(installed_path, installed_packages)
310
311
312    @log.log_and_ignore_errors("pre-test sysinfo error:")
313    def log_before_each_test(self, test):
314        """Logging hook called before a test starts.
315
316        @param test: A test object.
317        """
318        self._installed_packages = package.list_all()
319        if os.path.exists("/var/log/messages"):
320            stat = os.stat("/var/log/messages")
321            self._messages_size = stat.st_size
322            self._messages_inode = stat.st_ino
323
324        self._journal_cursor = get_journal_cursor()
325        # We want to only log the journal from this point on, not everything.
326        # When you do not filter from the cursor on the journal.gz can be
327        # extremely large and take a very long amount of time to compress.
328        if self._journal_cursor:
329            self.test_loggables.add(command((
330                'journalctl -o export -c "{}"'.format(self._journal_cursor)),
331                logf='journal',
332                compress_log=True))
333
334
335        # log some sysinfo data into the test keyval file in case system crash.
336        test_sysinfodir = self._get_sysinfodir(test.outputdir)
337        keyval = self.log_test_keyvals(test_sysinfodir)
338        test.write_test_keyval(keyval)
339
340    @log.log_and_ignore_errors("post-test sysinfo error:")
341    def log_after_each_test(self, test):
342        """Logging hook called after a test finishs.
343
344        @param test: A test object.
345        """
346        test_sysinfodir = self._get_sysinfodir(test.outputdir)
347
348        # create a symlink in the test sysinfo dir to the current boot
349        reboot_dir = self._get_boot_subdir()
350        assert os.path.exists(reboot_dir)
351        symlink_dest = os.path.join(test_sysinfodir, "reboot_current")
352        symlink_src = utils.get_relative_path(reboot_dir,
353                                              os.path.dirname(symlink_dest))
354        try:
355            os.symlink(symlink_src, symlink_dest)
356        except Exception, e:
357            raise Exception, '%s: whilst linking %s to %s' % (e, symlink_src,
358                                                              symlink_dest)
359
360        # run all the standard logging commands
361        _run_loggables_ignoring_errors(self.test_loggables, test_sysinfodir)
362
363        # grab any new data from /var/log/messages
364        self._log_messages(test_sysinfodir)
365
366        # log some sysinfo data into the test keyval file
367        keyval = self.log_test_keyvals(test_sysinfodir)
368        test.write_test_keyval(keyval)
369
370        # log any changes to installed packages
371        old_packages = set(self._installed_packages)
372        new_packages = set(package.list_all())
373        added_path = os.path.join(test_sysinfodir, "added_packages")
374        added_packages = "\n".join(new_packages - old_packages) + "\n"
375        utils.open_write_close(added_path, added_packages)
376        removed_path = os.path.join(test_sysinfodir, "removed_packages")
377        removed_packages = "\n".join(old_packages - new_packages) + "\n"
378        utils.open_write_close(removed_path, removed_packages)
379
380
381    @log.log_and_ignore_errors("pre-test siteration sysinfo error:")
382    def log_before_each_iteration(self, test, iteration=None):
383        """Logging hook called before a test iteration.
384
385        @param test: A test object.
386        @param iteration: A test iteration.
387        """
388        if not iteration:
389            iteration = test.iteration
390        logdir = self._get_iteration_subdir(test, iteration)
391        _run_loggables_ignoring_errors(self.before_iteration_loggables, logdir)
392        # Start each log with the board name for orientation.
393        board = utils.get_board_with_frequency_and_memory()
394        logging.info('ChromeOS BOARD = %s', board)
395        # Leave some autotest bread crumbs in the system logs.
396        utils.system('logger "autotest starting iteration %s on %s"' % (logdir,
397                                                                        board),
398                     ignore_status=True)
399
400
401    @log.log_and_ignore_errors("post-test siteration sysinfo error:")
402    def log_after_each_iteration(self, test, iteration=None):
403        """Logging hook called after a test iteration.
404
405        @param test: A test object.
406        @param iteration: A test iteration.
407        """
408        if not iteration:
409            iteration = test.iteration
410        logdir = self._get_iteration_subdir(test, iteration)
411        _run_loggables_ignoring_errors(self.after_iteration_loggables, logdir)
412        utils.system('logger "autotest finished iteration %s"' % logdir,
413                     ignore_status=True)
414
415
416    def _log_messages(self, logdir):
417        """Log all of the new data in /var/log/messages."""
418        try:
419            # log all of the new data in /var/log/messages
420            bytes_to_skip = 0
421            if hasattr(self, "_messages_size"):
422                current_inode = os.stat("/var/log/messages").st_ino
423                if current_inode == self._messages_inode:
424                    bytes_to_skip = self._messages_size
425            in_messages = open("/var/log/messages")
426            in_messages.seek(bytes_to_skip)
427            out_messages = open(os.path.join(logdir, "messages"), "w")
428            out_messages.write(in_messages.read())
429            in_messages.close()
430            out_messages.close()
431        except Exception, e:
432            logging.error("/var/log/messages collection failed with %s", e)
433
434
435    @staticmethod
436    def _read_sysinfo_keyvals(loggables, logdir):
437        keyval = {}
438        for log in loggables:
439            if log.log_in_keyval:
440                keyval["sysinfo-" + log.logf] = log.readline(logdir)
441        return keyval
442
443
444    def log_test_keyvals(self, test_sysinfodir):
445        """Generate keyval for the sysinfo.
446
447        Collects keyval entries to be written in the test keyval.
448
449        @param test_sysinfodir: The test's system info directory.
450        """
451        keyval = {}
452
453        # grab any loggables that should be in the keyval
454        keyval.update(self._read_sysinfo_keyvals(self.test_loggables,
455                                                 test_sysinfodir))
456        keyval.update(self._read_sysinfo_keyvals(
457            self.boot_loggables, os.path.join(test_sysinfodir,
458                                              'reboot_current')))
459
460        # remove hostname from uname info
461        #   Linux lpt36 2.6.18-smp-230.1 #1 [4069269] SMP Fri Oct 24 11:30:...
462        if "sysinfo-uname" in keyval:
463            kernel_vers = " ".join(keyval["sysinfo-uname"].split()[2:])
464            keyval["sysinfo-uname"] = kernel_vers
465
466        # grab the total avail memory, not used by sys tables
467        path = os.path.join(test_sysinfodir, "reboot_current", "meminfo")
468        if os.path.exists(path):
469            mem_data = open(path).read()
470            match = re.search(r'^MemTotal:\s+(\d+) kB$', mem_data, re.MULTILINE)
471            if match:
472                keyval["sysinfo-memtotal-in-kb"] = match.group(1)
473
474        # guess the system's total physical memory, including sys tables
475        keyval["sysinfo-phys-mbytes"] = utils.rounded_memtotal()//1024
476
477        # return what we collected
478        return keyval
479
480def _run_loggables_ignoring_errors(loggables, output_dir):
481    """Runs the given loggables robustly.
482
483    In the event of any one of the loggables raising an exception, we print a
484    traceback and continue on.
485
486    @param loggables: An iterable of base_sysinfo.loggable objects.
487    @param output_dir: Path to the output directory.
488    """
489    for log in loggables:
490        try:
491            log.run(output_dir)
492        except Exception:
493            logging.exception(
494                    'Failed to collect loggable %r to %s. Continuing...',
495                    log, output_dir)
496
497def get_journal_cursor():
498    cmd = "/usr/bin/journalctl  -n0 --show-cursor -q"
499    try:
500        cursor = utils.system_output(cmd)
501        prefix = "-- cursor: "
502        pos = cursor.find(prefix) + len(prefix)
503        return cursor[pos:]
504    except Exception, e:
505        logging.error("error running journalctl --show-cursor: %s", e)
506