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