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 # log some sysinfo data into the test keyval file in case system crash. 338 test_sysinfodir = self._get_sysinfodir(test.outputdir) 339 keyval = self.log_test_keyvals(test_sysinfodir) 340 test.write_test_keyval(keyval) 341 342 343 @log.log_and_ignore_errors("post-test sysinfo error:") 344 def log_after_each_test(self, test): 345 """Logging hook called after a test finishs. 346 347 @param test: A test object. 348 """ 349 test_sysinfodir = self._get_sysinfodir(test.outputdir) 350 351 # create a symlink in the test sysinfo dir to the current boot 352 reboot_dir = self._get_boot_subdir() 353 assert os.path.exists(reboot_dir) 354 symlink_dest = os.path.join(test_sysinfodir, "reboot_current") 355 symlink_src = utils.get_relative_path(reboot_dir, 356 os.path.dirname(symlink_dest)) 357 try: 358 os.symlink(symlink_src, symlink_dest) 359 except Exception, e: 360 raise Exception, '%s: whilst linking %s to %s' % (e, symlink_src, 361 symlink_dest) 362 363 # run all the standard logging commands 364 _run_loggables_ignoring_errors(self.test_loggables, test_sysinfodir) 365 366 # grab any new data from /var/log/messages 367 self._log_messages(test_sysinfodir) 368 369 # grab any new data from systemd journal 370 self._log_journal(test_sysinfodir) 371 372 # log some sysinfo data into the test keyval file 373 keyval = self.log_test_keyvals(test_sysinfodir) 374 test.write_test_keyval(keyval) 375 376 # log any changes to installed packages 377 old_packages = set(self._installed_packages) 378 new_packages = set(package.list_all()) 379 added_path = os.path.join(test_sysinfodir, "added_packages") 380 added_packages = "\n".join(new_packages - old_packages) + "\n" 381 utils.open_write_close(added_path, added_packages) 382 removed_path = os.path.join(test_sysinfodir, "removed_packages") 383 removed_packages = "\n".join(old_packages - new_packages) + "\n" 384 utils.open_write_close(removed_path, removed_packages) 385 386 387 @log.log_and_ignore_errors("pre-test siteration sysinfo error:") 388 def log_before_each_iteration(self, test, iteration=None): 389 """Logging hook called before a test iteration. 390 391 @param test: A test object. 392 @param iteration: A test iteration. 393 """ 394 if not iteration: 395 iteration = test.iteration 396 logdir = self._get_iteration_subdir(test, iteration) 397 _run_loggables_ignoring_errors(self.before_iteration_loggables, logdir) 398 # Start each log with the board name for orientation. 399 board = utils.get_board_with_frequency_and_memory() 400 logging.info('ChromeOS BOARD = %s', board) 401 # Leave some autotest bread crumbs in the system logs. 402 utils.system('logger "autotest starting iteration %s on %s"' % (logdir, 403 board), 404 ignore_status=True) 405 406 407 @log.log_and_ignore_errors("post-test siteration sysinfo error:") 408 def log_after_each_iteration(self, test, iteration=None): 409 """Logging hook called after a test iteration. 410 411 @param test: A test object. 412 @param iteration: A test iteration. 413 """ 414 if not iteration: 415 iteration = test.iteration 416 logdir = self._get_iteration_subdir(test, iteration) 417 _run_loggables_ignoring_errors(self.after_iteration_loggables, logdir) 418 utils.system('logger "autotest finished iteration %s"' % logdir, 419 ignore_status=True) 420 421 422 def _log_messages(self, logdir): 423 """Log all of the new data in /var/log/messages.""" 424 try: 425 # log all of the new data in /var/log/messages 426 bytes_to_skip = 0 427 if hasattr(self, "_messages_size"): 428 current_inode = os.stat("/var/log/messages").st_ino 429 if current_inode == self._messages_inode: 430 bytes_to_skip = self._messages_size 431 in_messages = open("/var/log/messages") 432 in_messages.seek(bytes_to_skip) 433 out_messages = open(os.path.join(logdir, "messages"), "w") 434 out_messages.write(in_messages.read()) 435 in_messages.close() 436 out_messages.close() 437 except Exception, e: 438 logging.error("/var/log/messages collection failed with %s", e) 439 440 441 def _log_journal(self, logdir): 442 """Log all of the new data in systemd journal.""" 443 if not hasattr(self, "_journal_cursor"): 444 return 445 446 cmd = "/usr/bin/journalctl --after-cursor \"%s\"" % ( 447 self._journal_cursor) 448 try: 449 with open(os.path.join(logdir, "journal"), "w") as journal: 450 journal.write(utils.system_output(cmd)) 451 except Exception, e: 452 logging.error("journal collection failed with %s", e) 453 454 455 @staticmethod 456 def _read_sysinfo_keyvals(loggables, logdir): 457 keyval = {} 458 for log in loggables: 459 if log.log_in_keyval: 460 keyval["sysinfo-" + log.logf] = log.readline(logdir) 461 return keyval 462 463 464 def log_test_keyvals(self, test_sysinfodir): 465 """Generate keyval for the sysinfo. 466 467 Collects keyval entries to be written in the test keyval. 468 469 @param test_sysinfodir: The test's system info directory. 470 """ 471 keyval = {} 472 473 # grab any loggables that should be in the keyval 474 keyval.update(self._read_sysinfo_keyvals(self.test_loggables, 475 test_sysinfodir)) 476 keyval.update(self._read_sysinfo_keyvals( 477 self.boot_loggables, os.path.join(test_sysinfodir, 478 'reboot_current'))) 479 480 # remove hostname from uname info 481 # Linux lpt36 2.6.18-smp-230.1 #1 [4069269] SMP Fri Oct 24 11:30:... 482 if "sysinfo-uname" in keyval: 483 kernel_vers = " ".join(keyval["sysinfo-uname"].split()[2:]) 484 keyval["sysinfo-uname"] = kernel_vers 485 486 # grab the total avail memory, not used by sys tables 487 path = os.path.join(test_sysinfodir, "reboot_current", "meminfo") 488 if os.path.exists(path): 489 mem_data = open(path).read() 490 match = re.search(r'^MemTotal:\s+(\d+) kB$', mem_data, re.MULTILINE) 491 if match: 492 keyval["sysinfo-memtotal-in-kb"] = match.group(1) 493 494 # guess the system's total physical memory, including sys tables 495 keyval["sysinfo-phys-mbytes"] = utils.rounded_memtotal()//1024 496 497 # return what we collected 498 return keyval 499 500 def _run_loggables_ignoring_errors(loggables, output_dir): 501 """Runs the given loggables robustly. 502 503 In the event of any one of the loggables raising an exception, we print a 504 traceback and continue on. 505 506 @param loggables: An iterable of base_sysinfo.loggable objects. 507 @param output_dir: Path to the output directory. 508 """ 509 for log in loggables: 510 try: 511 log.run(output_dir) 512 except Exception: 513 logging.exception( 514 'Failed to collect loggable %r to %s. Continuing...', 515 log, output_dir) 516
