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