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