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