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