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