1 import os, shutil, re, glob, subprocess, logging 2 3 from autotest_lib.client.common_lib import log 4 from autotest_lib.client.cros import constants 5 from 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 31 class 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 52 class 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 95 class 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 152 class 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
