base_sysinfo.py revision a4ac7a8f67d61f8a616724f9426dbc0fce71ce69 
1import os, shutil, re, glob, subprocess, logging
2
3from autotest_lib.client.common_lib import log
4from autotest_lib.client.common_lib.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',
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.boot_loggables.add(logfile("/proc/cmdline",
197                                             log_in_keyval=True))
198        # log /proc/mounts but with custom filename since we already
199        # log the output of the "mount" command as the filename "mount"
200        self.boot_loggables.add(logfile('/proc/mounts', logf='proc_mounts'))
201        self.boot_loggables.add(command("uname -a", logf="uname",
202                                             log_in_keyval=True))
203        self._installed_packages = []
204
205
206    def serialize(self):
207        """Returns parameters in a dictionary."""
208        return {"boot": self.boot_loggables, "test": self.test_loggables}
209
210
211    def deserialize(self, serialized):
212        """Stores parameters from a dictionary into instance variables.
213
214        @param serialized: A dictionary containing parameters to store as
215            instance variables.
216        """
217        self.boot_loggables = serialized["boot"]
218        self.test_loggables = serialized["test"]
219
220
221    @staticmethod
222    def _get_sysinfodir(resultsdir):
223        sysinfodir = os.path.join(resultsdir, "sysinfo")
224        if not os.path.exists(sysinfodir):
225            os.makedirs(sysinfodir)
226        return sysinfodir
227
228
229    def _get_reboot_count(self):
230        if not glob.glob(os.path.join(self.sysinfodir, "*")):
231            return -1
232        else:
233            return len(glob.glob(os.path.join(self.sysinfodir, "boot.*")))
234
235
236    def _get_boot_subdir(self, next=False):
237        reboot_count = self._get_reboot_count()
238        if next:
239            reboot_count += 1
240        if reboot_count < 1:
241            return self.sysinfodir
242        else:
243            boot_dir = "boot.%d" % (reboot_count - 1)
244            return os.path.join(self.sysinfodir, boot_dir)
245
246
247    def _get_iteration_subdir(self, test, iteration):
248        iter_dir = "iteration.%d" % iteration
249
250        logdir = os.path.join(self._get_sysinfodir(test.outputdir), iter_dir)
251        if not os.path.exists(logdir):
252            os.mkdir(logdir)
253        return logdir
254
255
256    @log.log_and_ignore_errors("post-reboot sysinfo error:")
257    def log_per_reboot_data(self):
258        """Logging hook called when a job starts, and again after any reboot."""
259        logdir = self._get_boot_subdir(next=True)
260        if not os.path.exists(logdir):
261            os.mkdir(logdir)
262
263        for log in (self.test_loggables | self.boot_loggables):
264            log.run(logdir)
265
266        # also log any installed packages
267        installed_path = os.path.join(logdir, "installed_packages")
268        installed_packages = "\n".join(package.list_all()) + "\n"
269        utils.open_write_close(installed_path, installed_packages)
270
271
272    @log.log_and_ignore_errors("pre-test sysinfo error:")
273    def log_before_each_test(self, test):
274        """Logging hook called before a test starts.
275
276        @param test: A test object.
277        """
278        self._installed_packages = package.list_all()
279        if os.path.exists("/var/log/messages"):
280            stat = os.stat("/var/log/messages")
281            self._messages_size = stat.st_size
282            self._messages_inode = stat.st_ino
283
284
285    @log.log_and_ignore_errors("post-test sysinfo error:")
286    def log_after_each_test(self, test):
287        """Logging hook called after a test finishs.
288
289        @param test: A test object.
290        """
291        test_sysinfodir = self._get_sysinfodir(test.outputdir)
292
293        # create a symlink in the test sysinfo dir to the current boot
294        reboot_dir = self._get_boot_subdir()
295        assert os.path.exists(reboot_dir)
296        symlink_dest = os.path.join(test_sysinfodir, "reboot_current")
297        symlink_src = utils.get_relative_path(reboot_dir,
298                                              os.path.dirname(symlink_dest))
299        try:
300            os.symlink(symlink_src, symlink_dest)
301        except Exception, e:
302            raise Exception, '%s: whilst linking %s to %s' % (e, symlink_src,
303                                                              symlink_dest)
304
305        # run all the standard logging commands
306        for log in self.test_loggables:
307            log.run(test_sysinfodir)
308
309        # grab any new data from /var/log/messages
310        self._log_messages(test_sysinfodir)
311
312        # log some sysinfo data into the test keyval file
313        keyval = self.log_test_keyvals(test_sysinfodir)
314        test.write_test_keyval(keyval)
315
316        # log any changes to installed packages
317        old_packages = set(self._installed_packages)
318        new_packages = set(package.list_all())
319        added_path = os.path.join(test_sysinfodir, "added_packages")
320        added_packages = "\n".join(new_packages - old_packages) + "\n"
321        utils.open_write_close(added_path, added_packages)
322        removed_path = os.path.join(test_sysinfodir, "removed_packages")
323        removed_packages = "\n".join(old_packages - new_packages) + "\n"
324        utils.open_write_close(removed_path, removed_packages)
325
326
327    @log.log_and_ignore_errors("pre-test siteration sysinfo error:")
328    def log_before_each_iteration(self, test, iteration=None):
329        """Logging hook called before a test iteration.
330
331        @param test: A test object.
332        @param iteration: A test iteration.
333        """
334        if not iteration:
335            iteration = test.iteration
336        logdir = self._get_iteration_subdir(test, iteration)
337
338        for log in self.before_iteration_loggables:
339            log.run(logdir)
340
341
342    @log.log_and_ignore_errors("post-test siteration sysinfo error:")
343    def log_after_each_iteration(self, test, iteration=None):
344        """Logging hook called after a test iteration.
345
346        @param test: A test object.
347        @param iteration: A test iteration.
348        """
349        if not iteration:
350            iteration = test.iteration
351        logdir = self._get_iteration_subdir(test, iteration)
352
353        for log in self.after_iteration_loggables:
354            log.run(logdir)
355
356
357    def _log_messages(self, logdir):
358        """ Log all of the new data in /var/log/messages. """
359        try:
360            # log all of the new data in /var/log/messages
361            bytes_to_skip = 0
362            if hasattr(self, "_messages_size"):
363                current_inode = os.stat("/var/log/messages").st_ino
364                if current_inode == self._messages_inode:
365                    bytes_to_skip = self._messages_size
366            in_messages = open("/var/log/messages")
367            in_messages.seek(bytes_to_skip)
368            out_messages = open(os.path.join(logdir, "messages"), "w")
369            out_messages.write(in_messages.read())
370            in_messages.close()
371            out_messages.close()
372        except Exception, e:
373            logging.error("/var/log/messages collection failed with %s", e)
374
375
376    @staticmethod
377    def _read_sysinfo_keyvals(loggables, logdir):
378        keyval = {}
379        for log in loggables:
380            if log.log_in_keyval:
381                keyval["sysinfo-" + log.logf] = log.readline(logdir)
382        return keyval
383
384
385    def log_test_keyvals(self, test_sysinfodir):
386        """Logging hook called by log_after_each_test.
387
388        Collects keyval entries to be written in the test keyval.
389
390        @param test_sysinfodir: The test's system info directory.
391        """
392        keyval = {}
393
394        # grab any loggables that should be in the keyval
395        keyval.update(self._read_sysinfo_keyvals(
396            self.test_loggables, test_sysinfodir))
397        keyval.update(self._read_sysinfo_keyvals(
398            self.boot_loggables,
399            os.path.join(test_sysinfodir, "reboot_current")))
400
401        # remove hostname from uname info
402        #   Linux lpt36 2.6.18-smp-230.1 #1 [4069269] SMP Fri Oct 24 11:30:...
403        if "sysinfo-uname" in keyval:
404            kernel_vers = " ".join(keyval["sysinfo-uname"].split()[2:])
405            keyval["sysinfo-uname"] = kernel_vers
406
407        # grab the total avail memory, not used by sys tables
408        path = os.path.join(test_sysinfodir, "reboot_current", "meminfo")
409        if os.path.exists(path):
410            mem_data = open(path).read()
411            match = re.search(r"^MemTotal:\s+(\d+) kB$", mem_data,
412                              re.MULTILINE)
413            if match:
414                keyval["sysinfo-memtotal-in-kb"] = match.group(1)
415
416        # guess the system's total physical memory, including sys tables
417        keyval["sysinfo-phys-mbytes"] = utils.rounded_memtotal()//1024
418
419        # return what we collected
420        return keyval
421