1import json 2import math 3import os 4import re 5 6import common 7from autotest_lib.tko import models 8from autotest_lib.tko import status_lib 9from autotest_lib.tko import utils as tko_utils 10from autotest_lib.tko.parsers import base 11from autotest_lib.tko.parsers import version_0 12 13 14class job(version_0.job): 15 """Represents a job.""" 16 17 def exit_status(self): 18 """Returns the string exit status of this job.""" 19 20 # Find the .autoserv_execute path. 21 top_dir = tko_utils.find_toplevel_job_dir(self.dir) 22 if not top_dir: 23 return 'ABORT' 24 execute_path = os.path.join(top_dir, '.autoserv_execute') 25 26 # If for some reason we can't read the status code, assume disaster. 27 if not os.path.exists(execute_path): 28 return 'ABORT' 29 lines = open(execute_path).readlines() 30 if len(lines) < 2: 31 return 'ABORT' 32 try: 33 status_code = int(lines[1]) 34 except ValueError: 35 return 'ABORT' 36 37 if not os.WIFEXITED(status_code): 38 # Looks like a signal - an ABORT. 39 return 'ABORT' 40 elif os.WEXITSTATUS(status_code) != 0: 41 # Looks like a non-zero exit - a failure. 42 return 'FAIL' 43 else: 44 # Looks like exit code == 0. 45 return 'GOOD' 46 47 48class kernel(models.kernel): 49 """Represents a kernel.""" 50 51 def __init__(self, base, patches): 52 if base: 53 patches = [patch(*p.split()) for p in patches] 54 hashes = [p.hash for p in patches] 55 kernel_hash = self.compute_hash(base, hashes) 56 else: 57 base = 'UNKNOWN' 58 patches = [] 59 kernel_hash = 'UNKNOWN' 60 super(kernel, self).__init__(base, patches, kernel_hash) 61 62 63class test(models.test): 64 """Represents a test.""" 65 66 @staticmethod 67 def load_iterations(keyval_path): 68 return iteration.load_from_keyval(keyval_path) 69 70 71 @staticmethod 72 def load_perf_values(perf_values_file): 73 return perf_value_iteration.load_from_perf_values_file( 74 perf_values_file) 75 76 77class iteration(models.iteration): 78 """Represents an iteration.""" 79 80 @staticmethod 81 def parse_line_into_dicts(line, attr_dict, perf_dict): 82 key, val_type, value = "", "", "" 83 84 # Figure out what the key, value and keyval type are. 85 typed_match = re.search('^([^=]*)\{(\w*)\}=(.*)$', line) 86 if typed_match: 87 key, val_type, value = typed_match.groups() 88 else: 89 # Old-fashioned untyped match, assume perf. 90 untyped_match = re.search('^([^=]*)=(.*)$', line) 91 if untyped_match: 92 key, value = untyped_match.groups() 93 val_type = 'perf' 94 95 # Parse the actual value into a dict. 96 try: 97 if val_type == 'attr': 98 attr_dict[key] = value 99 elif val_type == 'perf': 100 perf_dict[key] = float(value) 101 else: 102 raise ValueError 103 except ValueError: 104 msg = ('WARNING: line "%s" found in test ' 105 'iteration keyval could not be parsed') 106 msg %= line 107 tko_utils.dprint(msg) 108 109 110class perf_value_iteration(models.perf_value_iteration): 111 """Represents a perf value iteration.""" 112 113 @staticmethod 114 def parse_line_into_dict(line): 115 """ 116 Parse a perf measurement text line into a dictionary. 117 118 The line is assumed to be a JSON-formatted string containing key/value 119 pairs, where each pair represents a piece of information associated 120 with a measured perf metric: 121 122 'description': a string description for the perf metric. 123 'value': a numeric value, or list of numeric values. 124 'units': the string units associated with the perf metric. 125 'higher_is_better': a boolean whether a higher value is considered 126 better. If False, a lower value is considered better. 127 'graph': a string indicating the name of the perf dashboard graph 128 on which the perf data will be displayed. 129 130 The resulting dictionary will also have a standard deviation key/value 131 pair, 'stddev'. If the perf measurement value is a list of values 132 instead of a single value, then the average and standard deviation of 133 the list of values is computed and stored. If a single value, the 134 value itself is used, and is associated with a standard deviation of 0. 135 136 @param line: A string line of JSON text from a perf measurements output 137 file. 138 139 @return A dictionary containing the parsed perf measurement information 140 along with a computed standard deviation value (key 'stddev'), or 141 an empty dictionary if the inputted line cannot be parsed. 142 """ 143 try: 144 perf_dict = json.loads(line) 145 except ValueError: 146 msg = 'Could not parse perf measurements line as json: "%s"' % line 147 tko_utils.dprint(msg) 148 return {} 149 150 def mean_and_standard_deviation(data): 151 """ 152 Computes the mean and standard deviation of a list of numbers. 153 154 @param data: A list of numbers. 155 156 @return A 2-tuple (mean, standard_deviation) computed from the list 157 of numbers. 158 159 """ 160 n = len(data) 161 if n == 0: 162 return 0.0, 0.0 163 if n == 1: 164 return data[0], 0.0 165 mean = float(sum(data)) / n 166 # Divide by n-1 to compute "sample standard deviation". 167 variance = sum([(elem - mean) ** 2 for elem in data]) / (n - 1) 168 return mean, math.sqrt(variance) 169 170 value = perf_dict['value'] 171 perf_dict['stddev'] = 0.0 172 if isinstance(value, list): 173 value, stddev = mean_and_standard_deviation(map(float, value)) 174 perf_dict['value'] = value 175 perf_dict['stddev'] = stddev 176 177 return perf_dict 178 179 180class status_line(version_0.status_line): 181 """Represents a status line.""" 182 183 def __init__(self, indent, status, subdir, testname, reason, 184 optional_fields): 185 # Handle INFO fields. 186 if status == 'INFO': 187 self.type = 'INFO' 188 self.indent = indent 189 self.status = self.subdir = self.testname = self.reason = None 190 self.optional_fields = optional_fields 191 else: 192 # Everything else is backwards compatible. 193 super(status_line, self).__init__(indent, status, subdir, 194 testname, reason, 195 optional_fields) 196 197 198 def is_successful_reboot(self, current_status): 199 """ 200 Checks whether the status represents a successful reboot. 201 202 @param current_status: A string representing the current status. 203 204 @return True, if the status represents a successful reboot, or False 205 if not. 206 207 """ 208 # Make sure this is a reboot line. 209 if self.testname != 'reboot': 210 return False 211 212 # Make sure this was not a failure. 213 if status_lib.is_worse_than_or_equal_to(current_status, 'FAIL'): 214 return False 215 216 # It must have been a successful reboot. 217 return True 218 219 220 def get_kernel(self): 221 # Get the base kernel version. 222 fields = self.optional_fields 223 base = re.sub('-autotest$', '', fields.get('kernel', '')) 224 # Get a list of patches. 225 patches = [] 226 patch_index = 0 227 while ('patch%d' % patch_index) in fields: 228 patches.append(fields['patch%d' % patch_index]) 229 patch_index += 1 230 # Create a new kernel instance. 231 return kernel(base, patches) 232 233 234 def get_timestamp(self): 235 return tko_utils.get_timestamp(self.optional_fields, 'timestamp') 236 237 238# The default implementations from version 0 will do for now. 239patch = version_0.patch 240 241 242class parser(base.parser): 243 """Represents a parser.""" 244 245 @staticmethod 246 def make_job(dir): 247 return job(dir) 248 249 250 @staticmethod 251 def make_dummy_abort(indent, subdir, testname, timestamp, reason): 252 """ 253 Creates an abort string. 254 255 @param indent: The number of indentation levels for the string. 256 @param subdir: The subdirectory name. 257 @param testname: The test name. 258 @param timestamp: The timestamp value. 259 @param reason: The reason string. 260 261 @return A string describing the abort. 262 263 """ 264 indent = '\t' * indent 265 if not subdir: 266 subdir = '----' 267 if not testname: 268 testname = '----' 269 270 # There is no guarantee that this will be set. 271 timestamp_field = '' 272 if timestamp: 273 timestamp_field = '\ttimestamp=%s' % timestamp 274 275 msg = indent + 'END ABORT\t%s\t%s%s\t%s' 276 return msg % (subdir, testname, timestamp_field, reason) 277 278 279 @staticmethod 280 def put_back_line_and_abort( 281 line_buffer, line, indent, subdir, testname, timestamp, reason): 282 """ 283 Appends a line to the line buffer and aborts. 284 285 @param line_buffer: A line_buffer object. 286 @param line: A line to append to the line buffer. 287 @param indent: The number of indentation levels. 288 @param subdir: The subdirectory name. 289 @param testname: The test name. 290 @param timestamp: The timestamp value. 291 @param reason: The reason string. 292 293 """ 294 tko_utils.dprint('Unexpected indent: aborting log parse') 295 line_buffer.put_back(line) 296 abort = parser.make_dummy_abort( 297 indent, subdir, testname, timestamp, reason) 298 line_buffer.put_back(abort) 299 300 301 def state_iterator(self, buffer): 302 """ 303 Yields a list of tests out of the buffer. 304 305 @param buffer: a buffer object 306 307 """ 308 line = None 309 new_tests = [] 310 job_count, boot_count = 0, 0 311 min_stack_size = 0 312 stack = status_lib.status_stack() 313 current_kernel = kernel("", []) # UNKNOWN 314 current_status = status_lib.statuses[-1] 315 current_reason = None 316 started_time_stack = [None] 317 subdir_stack = [None] 318 testname_stack = [None] 319 running_test = None 320 running_reasons = set() 321 ignored_lines = [] 322 yield [] # We're ready to start running. 323 324 def print_ignored_lines(): 325 """ 326 Prints the ignored_lines using tko_utils.dprint method. 327 """ 328 tko_utils.dprint('The following lines were ignored:') 329 for line in ignored_lines: 330 tko_utils.dprint(line) 331 tko_utils.dprint('---------------------------------') 332 333 # Create a RUNNING SERVER_JOB entry to represent the entire test. 334 running_job = test.parse_partial_test(self.job, '----', 'SERVER_JOB', 335 '', current_kernel, 336 self.job.started_time) 337 new_tests.append(running_job) 338 339 while True: 340 # Are we finished with parsing? 341 if buffer.size() == 0 and self.finished: 342 if ignored_lines: 343 print_ignored_lines() 344 ignored_lines = [] 345 if stack.size() == 0: 346 break 347 # We have status lines left on the stack; 348 # we need to implicitly abort them first. 349 tko_utils.dprint('\nUnexpected end of job, aborting') 350 abort_subdir_stack = list(subdir_stack) 351 if self.job.aborted_by: 352 reason = 'Job aborted by %s' % self.job.aborted_by 353 reason += self.job.aborted_on.strftime( 354 ' at %b %d %H:%M:%S') 355 else: 356 reason = 'Job aborted unexpectedly' 357 358 timestamp = line.optional_fields.get('timestamp') 359 for i in reversed(xrange(stack.size())): 360 if abort_subdir_stack: 361 subdir = abort_subdir_stack.pop() 362 else: 363 subdir = None 364 abort = self.make_dummy_abort( 365 i, subdir, subdir, timestamp, reason) 366 buffer.put(abort) 367 368 # Stop processing once the buffer is empty. 369 if buffer.size() == 0: 370 yield new_tests 371 new_tests = [] 372 continue 373 374 # Reinitialize the per-iteration state. 375 started_time = None 376 finished_time = None 377 378 # Get the next line. 379 raw_line = status_lib.clean_raw_line(buffer.get()) 380 line = status_line.parse_line(raw_line) 381 if line is None: 382 ignored_lines.append(raw_line) 383 continue 384 elif ignored_lines: 385 print_ignored_lines() 386 ignored_lines = [] 387 388 # Do an initial sanity check of the indentation. 389 expected_indent = stack.size() 390 if line.type == 'END': 391 expected_indent -= 1 392 if line.indent < expected_indent: 393 # ABORT the current level if indentation was unexpectedly low. 394 self.put_back_line_and_abort( 395 buffer, raw_line, stack.size() - 1, subdir_stack[-1], 396 testname_stack[-1], line.optional_fields.get('timestamp'), 397 line.reason) 398 continue 399 elif line.indent > expected_indent: 400 # Ignore the log if the indent was unexpectedly high. 401 tko_utils.dprint('ignoring line because of extra indentation') 402 continue 403 404 # Initial line processing. 405 if line.type == 'START': 406 stack.start() 407 started_time = line.get_timestamp() 408 testname = None 409 if (line.testname is None and line.subdir is None 410 and not running_test): 411 # We just started a client; all tests are relative to here. 412 min_stack_size = stack.size() 413 # Start a "RUNNING" CLIENT_JOB entry. 414 job_name = 'CLIENT_JOB.%d' % job_count 415 running_client = test.parse_partial_test(self.job, None, 416 job_name, 417 '', current_kernel, 418 started_time) 419 msg = 'RUNNING: %s\n%s\n' 420 msg %= (running_client.status, running_client.testname) 421 tko_utils.dprint(msg) 422 new_tests.append(running_client) 423 testname = running_client.testname 424 elif stack.size() == min_stack_size + 1 and not running_test: 425 # We just started a new test; insert a running record. 426 running_reasons = set() 427 if line.reason: 428 running_reasons.add(line.reason) 429 running_test = test.parse_partial_test(self.job, 430 line.subdir, 431 line.testname, 432 line.reason, 433 current_kernel, 434 started_time) 435 msg = 'RUNNING: %s\nSubdir: %s\nTestname: %s\n%s' 436 msg %= (running_test.status, running_test.subdir, 437 running_test.testname, running_test.reason) 438 tko_utils.dprint(msg) 439 new_tests.append(running_test) 440 testname = running_test.testname 441 started_time_stack.append(started_time) 442 subdir_stack.append(line.subdir) 443 testname_stack.append(testname) 444 continue 445 elif line.type == 'INFO': 446 fields = line.optional_fields 447 # Update the current kernel if one is defined in the info. 448 if 'kernel' in fields: 449 current_kernel = line.get_kernel() 450 # Update the SERVER_JOB reason if one was logged for an abort. 451 if 'job_abort_reason' in fields: 452 running_job.reason = fields['job_abort_reason'] 453 new_tests.append(running_job) 454 continue 455 elif line.type == 'STATUS': 456 # Update the stacks. 457 if line.subdir and stack.size() > min_stack_size: 458 subdir_stack[-1] = line.subdir 459 testname_stack[-1] = line.testname 460 # Update the status, start and finished times. 461 stack.update(line.status) 462 if status_lib.is_worse_than_or_equal_to(line.status, 463 current_status): 464 if line.reason: 465 # Update the status of a currently running test. 466 if running_test: 467 running_reasons.add(line.reason) 468 running_reasons = tko_utils.drop_redundant_messages( 469 running_reasons) 470 sorted_reasons = sorted(running_reasons) 471 running_test.reason = ', '.join(sorted_reasons) 472 current_reason = running_test.reason 473 new_tests.append(running_test) 474 msg = 'update RUNNING reason: %s' % line.reason 475 tko_utils.dprint(msg) 476 else: 477 current_reason = line.reason 478 current_status = stack.current_status() 479 started_time = None 480 finished_time = line.get_timestamp() 481 # If this is a non-test entry there's nothing else to do. 482 if line.testname is None and line.subdir is None: 483 continue 484 elif line.type == 'END': 485 # Grab the current subdir off of the subdir stack, or, if this 486 # is the end of a job, just pop it off. 487 if (line.testname is None and line.subdir is None 488 and not running_test): 489 min_stack_size = stack.size() - 1 490 subdir_stack.pop() 491 testname_stack.pop() 492 else: 493 line.subdir = subdir_stack.pop() 494 testname_stack.pop() 495 if not subdir_stack[-1] and stack.size() > min_stack_size: 496 subdir_stack[-1] = line.subdir 497 # Update the status, start and finished times. 498 stack.update(line.status) 499 current_status = stack.end() 500 if stack.size() > min_stack_size: 501 stack.update(current_status) 502 current_status = stack.current_status() 503 started_time = started_time_stack.pop() 504 finished_time = line.get_timestamp() 505 # Update the current kernel. 506 if line.is_successful_reboot(current_status): 507 current_kernel = line.get_kernel() 508 # Adjust the testname if this is a reboot. 509 if line.testname == 'reboot' and line.subdir is None: 510 line.testname = 'boot.%d' % boot_count 511 else: 512 assert False 513 514 # Have we just finished a test? 515 if stack.size() <= min_stack_size: 516 # If there was no testname, just use the subdir. 517 if line.testname is None: 518 line.testname = line.subdir 519 # If there was no testname or subdir, use 'CLIENT_JOB'. 520 if line.testname is None: 521 line.testname = 'CLIENT_JOB.%d' % job_count 522 running_test = running_client 523 job_count += 1 524 if not status_lib.is_worse_than_or_equal_to( 525 current_status, 'ABORT'): 526 # A job hasn't really failed just because some of the 527 # tests it ran have. 528 current_status = 'GOOD' 529 530 if not current_reason: 531 current_reason = line.reason 532 new_test = test.parse_test(self.job, 533 line.subdir, 534 line.testname, 535 current_status, 536 current_reason, 537 current_kernel, 538 started_time, 539 finished_time, 540 running_test) 541 running_test = None 542 current_status = status_lib.statuses[-1] 543 current_reason = None 544 if new_test.testname == ('boot.%d' % boot_count): 545 boot_count += 1 546 msg = 'ADD: %s\nSubdir: %s\nTestname: %s\n%s' 547 msg %= (new_test.status, new_test.subdir, 548 new_test.testname, new_test.reason) 549 tko_utils.dprint(msg) 550 new_tests.append(new_test) 551 552 # The job is finished; produce the final SERVER_JOB entry and exit. 553 final_job = test.parse_test(self.job, '----', 'SERVER_JOB', 554 self.job.exit_status(), running_job.reason, 555 current_kernel, 556 self.job.started_time, 557 self.job.finished_time, 558 running_job) 559 new_tests.append(final_job) 560 yield new_tests 561