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