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