def __init__(self, simulation_cfg, superlog_path_or_dag, invariant_check=InvariantChecker.check_correspondence, transform_dag=None, end_wait_seconds=0.5, mcs_trace_path=None, extra_log=None, dump_runtime_stats=True, **kwargs): super(MCSFinder, self).__init__(simulation_cfg) self.sync_callback = None self._log = logging.getLogger("mcs_finder") if type(superlog_path_or_dag) == str: superlog_path = superlog_path_or_dag # The dag is codefied as a list, where each element has # a list of its dependents self.dag = EventDag(superlog_parser.parse_path(superlog_path)) else: self.dag = superlog_path_or_dag self.invariant_check = invariant_check self.transform_dag = transform_dag self.mcs_trace_path = mcs_trace_path self._extra_log = extra_log self._runtime_stats = None self.kwargs = kwargs self.end_wait_seconds = end_wait_seconds if dump_runtime_stats: self._runtime_stats = {}
def __init__(self, simulation_cfg, superlog_path_or_dag, mock_controllers=True, input_logger=None, show_flow_tables_each_step=True): # TODO(cs): allow user to specify a round number where they want to stop, # otherwise play forward events without asking for interactive ack. Interactive.__init__(self, simulation_cfg, input_logger=input_logger) if mock_controllers is False: raise NotImplementedError("Live controllers not yet supported") self.mock_controllers = mock_controllers if type(superlog_path_or_dag) == str: superlog_path = superlog_path_or_dag # The dag is codefied as a list, where each element has # a list of its dependents. self.event_list = EventDag(log_parser.parse_path(superlog_path)).events else: self.event_list = superlog_path_or_dag.events # TODO(cs): support compute_interpolated_time whenever we support # non-mocked controllers. if self.mock_controllers: self.event_list = [ e for e in self.event_list if type(e) in InteractiveReplayer.supported_input_events or type(e) in InteractiveReplayer.supported_internal_events ] self.show_flow_tables_each_step = show_flow_tables_each_step
def test_all(self): trace = [MockInputEvent(fingerprint=("class", f)) for f in range(1, 7)] dag = EventDag(trace) mcs = trace mcs_finder = MockMCSFinder(dag, mcs) result = mcs_finder.simulate() self.assertEqual(mcs, result)
def __init__(self, simulation_cfg, superlog_path_or_dag, invariant_check_name=None, transform_dag=None, end_wait_seconds=0.5, mcs_trace_path=None, extra_log=None, runtime_stats_file=None, wait_on_deterministic_values=False, no_violation_verification_runs=1, optimized_filtering=False, **kwargs): super(MCSFinder, self).__init__(simulation_cfg) self.sync_callback = None self._log = logging.getLogger("mcs_finder") if invariant_check_name is None: raise ValueError("Must specify invariant check") if invariant_check_name not in name_to_invariant_check: raise ValueError('''Unknown invariant check %s.\n''' '''Invariant check name must be defined in config.invariant_checks''', invariant_check_name) self.invariant_check = name_to_invariant_check[invariant_check_name] if type(superlog_path_or_dag) == str: self.superlog_path = superlog_path_or_dag # The dag is codefied as a list, where each element has # a list of its dependents self.dag = EventDag(superlog_parser.parse_path(self.superlog_path)) else: self.dag = superlog_path_or_dag self.transform_dag = transform_dag self.mcs_trace_path = mcs_trace_path self._extra_log = extra_log self.kwargs = kwargs self.end_wait_seconds = end_wait_seconds self.wait_on_deterministic_values = wait_on_deterministic_values # `no' means "number" self.no_violation_verification_runs = no_violation_verification_runs self._runtime_stats = RuntimeStats(runtime_stats_file) self.optimized_filtering = optimized_filtering
class InteractiveReplayer(Interactive): ''' Presents an interactive prompt for replaying an event trace, allowing the user to examine the series of network configurations interactively and potentially also injecting new events that were not present in the original trace. Currently InteractiveReplayer does not support live controllers, and instead mocks out controllers to prevent non-determinism and timeout issues. ''' supported_input_events = set([SwitchFailure, SwitchRecovery, LinkFailure, LinkRecovery, HostMigration, TrafficInjection]) supported_internal_events = set([ControlMessageReceive]) def __init__(self, simulation_cfg, superlog_path_or_dag, mock_controllers=True, input_logger=None, show_flow_tables_each_step=True): # TODO(cs): allow user to specify a round number where they want to stop, # otherwise play forward events without asking for interactive ack. Interactive.__init__(self, simulation_cfg, input_logger=input_logger) if mock_controllers is False: raise NotImplementedError("Live controllers not yet supported") self.mock_controllers = mock_controllers if type(superlog_path_or_dag) == str: superlog_path = superlog_path_or_dag # The dag is codefied as a list, where each element has # a list of its dependents. self.event_list = EventDag(log_parser.parse_path(superlog_path)).events else: self.event_list = superlog_path_or_dag.events # TODO(cs): support compute_interpolated_time whenever we support # non-mocked controllers. if self.mock_controllers: self.event_list = [ e for e in self.event_list if type(e) in InteractiveReplayer.supported_input_events or type(e) in InteractiveReplayer.supported_internal_events ] self.show_flow_tables_each_step = show_flow_tables_each_step def simulate(self, bound_objects=()): # TODO(cs): add interactive prompt commands for examining next pending # event, inject next pending event, examining total pending events # remaining. if self.mock_controllers: self.simulation = Interactive.simulate(self, boot_controllers=boot_mock_controllers, connect_to_controllers=connect_to_mock_controllers, bound_objects=bound_objects) else: # not self.mock_controllers self.simulation = Interactive.simulate(self, simulation=simulation, bound_objects=bound_objects) return self.simulation def default_command(self): return "next" def next_step(self): time.sleep(0.05) self.logical_time += 1 self._forwarded_this_step = 0 if len(self.event_list) == 0: msg.fail("No more events to inject") else: next_event = self.event_list.pop(0) if type(next_event) in InteractiveReplayer.supported_input_events: msg.replay_event_success("Injecting %r" % next_event) next_event.proceed(self.simulation) else: # type(next_event) in InteractiveReplayer.supported_internal_events if type(next_event) == ControlMessageReceive and is_flow_mod(next_event): msg.mcs_event("Injecting %r" % next_event) else: msg.replay_event_success("Injecting %r" % next_event) next_event.manually_inject(self.simulation) if self.show_flow_tables_each_step: for switch in self.simulation.topology.switches: print "Switch %s" % switch.dpid switch.show_flow_table() print "\nAdvanced to step %d\n" % self.logical_time
def __init__(self, simulation_cfg, superlog_path_or_dag, invariant_check_name=None, transform_dag=None, end_wait_seconds=0.5, mcs_trace_path=None, extra_log=None, runtime_stats_path=None, wait_on_deterministic_values=False, no_violation_verification_runs=1, optimized_filtering=False, forker=LocalForker(), replay_final_trace=True, strict_assertion_checking=False, **kwargs): super(MCSFinder, self).__init__(simulation_cfg) # number of subsequences delta debugging has examined so far, for # distingushing runtime stats from different intermediate runs. self.subsequence_id = 0 self.mcs_log_tracker = None self.replay_log_tracker = None self.mcs_trace_path = mcs_trace_path self.sync_callback = None self._log = logging.getLogger("mcs_finder") if invariant_check_name is None: raise ValueError("Must specify invariant check") if invariant_check_name not in name_to_invariant_check: raise ValueError('''Unknown invariant check %s.\n''' '''Invariant check name must be defined in config.invariant_checks''', invariant_check_name) self.invariant_check = name_to_invariant_check[invariant_check_name] if type(superlog_path_or_dag) == str: self.superlog_path = superlog_path_or_dag # The dag is codefied as a list, where each element has # a list of its dependents self.dag = EventDag(log_parser.parse_path(self.superlog_path)) else: self.dag = superlog_path_or_dag last_invariant_violation = self.dag.get_last_invariant_violation() if last_invariant_violation is None: raise ValueError("No invariant violation found in dag...") violations = last_invariant_violation.violations if len(violations) > 1: self.bug_signature = None while self.bug_signature is None: msg.interactive("\n------------------------------------------\n") msg.interactive("Multiple violations detected! Choose one for MCS Finding:") for i, violation in enumerate(violations): msg.interactive(" [%d] %s" % (i+1, violation)) violation_index = msg.raw_input("> ") if re.match("^\d+$", violation_index) is None or\ int(violation_index) < 1 or\ int(violation_index) > len(violations): msg.fail("Must provide an integer between 1 and %d!" % len(violations)) continue self.bug_signature = violations[int(violation_index)-1] else: self.bug_signature = violations[0] msg.success("\nBug signature to match is %s. Proceeding with MCS finding!\n" % self.bug_signature) self.transform_dag = transform_dag # A second log with just our MCS progress log messages self._extra_log = extra_log self.kwargs = kwargs self.end_wait_seconds = end_wait_seconds self.wait_on_deterministic_values = wait_on_deterministic_values # `no' means "number" self.no_violation_verification_runs = no_violation_verification_runs self._runtime_stats = RuntimeStats(self.subsequence_id, runtime_stats_path=runtime_stats_path) # Whether to try alternate trace splitting techiques besides splitting by time. self.optimized_filtering = optimized_filtering self.forker = forker self.replay_final_trace = replay_final_trace self.strict_assertion_checking = strict_assertion_checking
class MCSFinder(ControlFlow): def __init__(self, simulation_cfg, superlog_path_or_dag, invariant_check_name=None, transform_dag=None, end_wait_seconds=0.5, mcs_trace_path=None, extra_log=None, runtime_stats_path=None, wait_on_deterministic_values=False, no_violation_verification_runs=1, optimized_filtering=False, forker=LocalForker(), replay_final_trace=True, strict_assertion_checking=False, **kwargs): super(MCSFinder, self).__init__(simulation_cfg) # number of subsequences delta debugging has examined so far, for # distingushing runtime stats from different intermediate runs. self.subsequence_id = 0 self.mcs_log_tracker = None self.replay_log_tracker = None self.mcs_trace_path = mcs_trace_path self.sync_callback = None self._log = logging.getLogger("mcs_finder") if invariant_check_name is None: raise ValueError("Must specify invariant check") if invariant_check_name not in name_to_invariant_check: raise ValueError('''Unknown invariant check %s.\n''' '''Invariant check name must be defined in config.invariant_checks''', invariant_check_name) self.invariant_check = name_to_invariant_check[invariant_check_name] if type(superlog_path_or_dag) == str: self.superlog_path = superlog_path_or_dag # The dag is codefied as a list, where each element has # a list of its dependents self.dag = EventDag(log_parser.parse_path(self.superlog_path)) else: self.dag = superlog_path_or_dag last_invariant_violation = self.dag.get_last_invariant_violation() if last_invariant_violation is None: raise ValueError("No invariant violation found in dag...") violations = last_invariant_violation.violations if len(violations) > 1: self.bug_signature = None while self.bug_signature is None: msg.interactive("\n------------------------------------------\n") msg.interactive("Multiple violations detected! Choose one for MCS Finding:") for i, violation in enumerate(violations): msg.interactive(" [%d] %s" % (i+1, violation)) violation_index = msg.raw_input("> ") if re.match("^\d+$", violation_index) is None or\ int(violation_index) < 1 or\ int(violation_index) > len(violations): msg.fail("Must provide an integer between 1 and %d!" % len(violations)) continue self.bug_signature = violations[int(violation_index)-1] else: self.bug_signature = violations[0] msg.success("\nBug signature to match is %s. Proceeding with MCS finding!\n" % self.bug_signature) self.transform_dag = transform_dag # A second log with just our MCS progress log messages self._extra_log = extra_log self.kwargs = kwargs self.end_wait_seconds = end_wait_seconds self.wait_on_deterministic_values = wait_on_deterministic_values # `no' means "number" self.no_violation_verification_runs = no_violation_verification_runs self._runtime_stats = RuntimeStats(self.subsequence_id, runtime_stats_path=runtime_stats_path) # Whether to try alternate trace splitting techiques besides splitting by time. self.optimized_filtering = optimized_filtering self.forker = forker self.replay_final_trace = replay_final_trace self.strict_assertion_checking = strict_assertion_checking def log(self, s): ''' Output a message to both self._log and self._extra_log ''' msg.mcs_event(s) if self._extra_log is not None: self._extra_log.write(s + '\n') self._extra_log.flush() def log_violation(self, s): ''' Output a message to both self._log and self._extra_log ''' msg.mcs_event(color.RED + s) if self._extra_log is not None: self._extra_log.write(s + '\n') self._extra_log.flush() def log_no_violation(self, s): ''' Output a message to both self._log and self._extra_log ''' msg.mcs_event(color.GREEN + s) if self._extra_log is not None: self._extra_log.write(s + '\n') self._extra_log.flush() def init_results(self, results_dir): ''' Precondition: results_dir exists, and is clean (preferably initialized by experiments/setup.py).''' if self._extra_log is None: self._extra_log = open("%s/mcs_finder.log" % results_dir, "w") if self._runtime_stats.get_runtime_stats_path() is None: runtime_stats_path = "%s/runtime_stats.json" % results_dir self._runtime_stats.set_runtime_stats_path(runtime_stats_path) if self.mcs_trace_path is None: self.mcs_trace_path = "%s/mcs.trace" % results_dir # TODO(cs): assumes that transform dag is a peeker, not some other # transformer peeker_exists = self.transform_dag is not None self.mcs_log_tracker = MCSLogTracker(results_dir, self.mcs_trace_path, self._runtime_stats, self.simulation_cfg, peeker_exists) self.replay_log_tracker = ReplayLogTracker(results_dir) # N.B. only called in the parent process. def simulate(self, check_reproducability=True): self._runtime_stats.set_dag_stats(self.dag) # apply domain knowledge: treat failure/recovery pairs atomically, and # filter event types we don't want to include in the MCS # (e.g. CheckInvariants) self.dag.mark_invalid_input_sequences() self.dag = self.dag.filter_unsupported_input_types() if len(self.dag) == 0: raise RuntimeError("No supported input types?") if check_reproducability: # First, run through without pruning to verify that the violation exists self._runtime_stats.record_replay_start() for i in range(0, self.no_violation_verification_runs): bug_found = self.replay(self.dag, "reproducibility", ignore_runtime_stats=True) if bug_found: break self._runtime_stats.set_initial_verification_runs_needed(i) self._runtime_stats.record_replay_end() if not bug_found: msg.fail("Unable to reproduce correctness violation!") sys.exit(5) self.log("Violation reproduced successfully! Proceeding with pruning") self._runtime_stats.record_prune_start() # Run optimizations. # TODO(cs): Better than a boolean flag: check if # log(len(self.dag)) > number of input types to try if self.optimized_filtering: self._optimize_event_dag() precompute_cache = PrecomputeCache() # Invoke delta debugging (dag, total_inputs_pruned) = self._ddmin(self.dag, 2, precompute_cache=precompute_cache) # Make sure to track the final iteration size self._track_iteration_size(total_inputs_pruned) self.dag = dag self.log("=== Total replays: %d ===" % self._runtime_stats.total_replays) self._runtime_stats.record_prune_end() self.mcs_log_tracker.dump_runtime_stats() self.log("Final MCS (%d elements):" % len(self.dag.input_events)) for i in self.dag.input_events: self.log(" - %s" % str(i)) if self.replay_final_trace: # Replaying the final trace achieves two goals: # - verifies that the MCS indeed ends in the violation # - allows us to prune internal events that time out bug_found = self.replay(self.dag, "final_mcs_trace", ignore_runtime_stats=True) if not bug_found: self.log('''Warning: MCS did not result in violation. Trying replay ''' '''again without timed out events.''') # TODO(cs): always replay the MCS without timeouts, since the console # output will be significantly cleaner? no_timeouts = self.dag.filter_timeouts() bug_found = self.replay(no_timeouts, "final_mcs_no_timed_out_events", ignore_runtime_stats=True) if not bug_found: self.log('''Warning! Final MCS did not result in violation, even ''' ''' after ignoring timed out internal events. ''' ''' See tools/visualization/visualize1D.html for debugging''') # N.B. dumping the MCS trace must occur after the final replay trace, # since we need to infer which events will time out for events.trace.notimeouts if self.mcs_trace_path is not None: self.mcs_log_tracker.dump_mcs_trace(self.dag, self) return ExitCode(0) # N.B. always called within a child process. def _ddmin(self, dag, split_ways, precompute_cache=None, label_prefix=(), total_inputs_pruned=0): # This is the delta-debugging algorithm from: # http://www.st.cs.uni-saarland.de/papers/tse2002/tse2002.pdf, # Section 3.2 # TODO(cs): we could do much better if we leverage domain knowledge (e.g., # start by pruning all LinkFailures, or splitting by nodes rather than # time) if split_ways > len(dag.input_events): self.log("Done") return (dag, total_inputs_pruned) local_label = lambda i, inv=False: "%s%d/%d" % ("~" if inv else "", i, split_ways) subset_label = lambda label: ".".join(map(str, label_prefix + ( label, ))) print_subset = lambda label, s: subset_label(label) + ": "+" ".join(map(lambda e: e.label, s)) subsets = split_list(dag.input_events, split_ways) self.log("Subsets:\n"+"\n".join(print_subset(local_label(i), s) for i, s in enumerate(subsets))) for i, subset in enumerate(subsets): label = local_label(i) new_dag = dag.input_subset(subset) input_sequence = tuple(new_dag.input_events) self.log("Current subset: %s" % print_subset(label, input_sequence)) if precompute_cache.already_done(input_sequence): self.log("Already computed. Skipping") continue precompute_cache.update(input_sequence) if input_sequence == (): self.log("Subset after pruning dependencies was empty. Skipping") continue self._track_iteration_size(total_inputs_pruned) violation = self._check_violation(new_dag, i, label) if violation: self.log_violation("Subset %s reproduced violation. Subselecting." % subset_label(label)) self.mcs_log_tracker.maybe_dump_intermediate_mcs(new_dag, subset_label(label), self) total_inputs_pruned += len(dag.input_events) - len(new_dag.input_events) return self._ddmin(new_dag, 2, precompute_cache=precompute_cache, label_prefix = label_prefix + (label, ), total_inputs_pruned=total_inputs_pruned) self.log_no_violation("No subsets with violations. Checking complements") for i, subset in enumerate(subsets): label = local_label(i, True) prefix = label_prefix + (label, ) new_dag = dag.input_complement(subset) input_sequence = tuple(new_dag.input_events) self.log("Current complement: %s" % print_subset(label, input_sequence)) if precompute_cache.already_done(input_sequence): self.log("Already computed. Skipping") continue precompute_cache.update(input_sequence) if input_sequence == (): self.log("Subset %s after pruning dependencies was empty. Skipping", subset_label(label)) continue self._track_iteration_size(total_inputs_pruned) violation = self._check_violation(new_dag, i, label) if violation: self.log_violation("Subset %s reproduced violation. Subselecting." % subset_label(label)) self.mcs_log_tracker.maybe_dump_intermediate_mcs(new_dag, subset_label(label), self) total_inputs_pruned += len(dag.input_events) - len(new_dag.input_events) return self._ddmin(new_dag, max(split_ways - 1, 2), precompute_cache=precompute_cache, label_prefix=prefix, total_inputs_pruned=total_inputs_pruned) self.log_no_violation("No complements with violations.") if split_ways < len(dag.input_events): self.log("Increasing granularity.") return self._ddmin(dag, min(len(dag.input_events), split_ways*2), precompute_cache=precompute_cache, label_prefix=label_prefix, total_inputs_pruned=total_inputs_pruned) return (dag, total_inputs_pruned) # N.B. always called within a child process. def _track_iteration_size(self, total_inputs_pruned): self._runtime_stats.record_iteration_size(len(self.dag.input_events) - total_inputs_pruned) # N.B. always called within a child process. def _check_violation(self, new_dag, subset_index, label): ''' Check if there were violations ''' # Try no_violation_verification_runs times to see if the bug shows up for i in range(0, self.no_violation_verification_runs): bug_found = self.replay(new_dag, label) if bug_found: # Violation in the subset self.log_violation("Violation! Considering %d'th" % subset_index) self._runtime_stats.record_violation_found(i) return True # No violation! self.log_no_violation("No violation in %d'th..." % subset_index) return False def replay(self, new_dag, label, ignore_runtime_stats=False): # Run the simulation forward if self.transform_dag: new_dag = self.transform_dag(new_dag) self._runtime_stats.record_replay_stats(len(new_dag.input_events)) # N.B. this function is run as a child process. def play_forward(results_dir, subsequence_id): # TODO(cs): need to serialize the parameters to Replayer rather than # wrapping them in a closure... otherwise, can't use RemoteForker # TODO(aw): MCSFinder needs to configure Simulation to always let DataplaneEvents pass through create_clean_python_dir(results_dir) # Copy stdout and stderr to a file "replay.out" tee = Tee(open(os.path.join(results_dir, "replay.out"), "w")) tee.tee_stdout() tee.tee_stderr() # Set up replayer. input_logger = InputLogger() replayer = Replayer(self.simulation_cfg, new_dag, wait_on_deterministic_values=self.wait_on_deterministic_values, input_logger=input_logger, allow_unexpected_messages=False, pass_through_whitelisted_messages=True, **self.kwargs) replayer.init_results(results_dir) self._runtime_stats = RuntimeStats(subsequence_id) violations = [] simulation = None try: simulation = replayer.simulate() self._track_new_internal_events(simulation, replayer) # Wait a bit in case the bug takes awhile to happen self.log("Sleeping %d seconds after run" % self.end_wait_seconds) time.sleep(self.end_wait_seconds) violations = self.invariant_check(simulation) if violations != []: input_logger.log_input_event(InvariantViolation(violations)) except SystemExit: # One of the invariant checks bailed early. Oddly, this is not an # error for us, it just means that there were no violations... # [this logic is arguably broken] # Return no violations, and let Forker handle system exit for us. violations = [] finally: input_logger.close(replayer, self.simulation_cfg, skip_mcs_cfg=True) if simulation is not None: simulation.clean_up() tee.close() if self.strict_assertion_checking: test_serialize_response(violations, self._runtime_stats.client_dict()) timed_out_internal = [ e.label for e in new_dag.events if e.timed_out ] return (violations, self._runtime_stats.client_dict(), timed_out_internal) # TODO(cs): once play_forward() is no longer a closure, register it only once self.forker.register_task("play_forward", play_forward) results_dir = self.replay_log_tracker.get_replay_logger_dir(label) self.subsequence_id += 1 (violations, client_runtime_stats, timed_out_internal) = self.forker.fork("play_forward", results_dir, self.subsequence_id) new_dag.set_events_as_timed_out(timed_out_internal) bug_found = False if violations != []: msg.fail("Violations: %s" % str(violations)) if self.bug_signature in violations: bug_found = True else: msg.fail("Bug does not match initial violation fingerprint!") else: msg.interactive("No correctness violations!") if not ignore_runtime_stats: self._runtime_stats.merge_client_dict(client_runtime_stats) return bug_found def _optimize_event_dag(self): ''' Employs domain knowledge of event classes to reduce the size of event dag. Currently prunes event types.''' # TODO(cs): Another approach for later: split by nodes event_types = [TrafficInjection, DataplaneDrop, SwitchFailure, SwitchRecovery, LinkFailure, LinkRecovery, HostMigration, ControllerFailure, ControllerRecovery, PolicyChange, ControlChannelBlock, ControlChannelUnblock] for event_type in event_types: pruned = [e for e in self.dag.input_events if not isinstance(e, event_type)] if len(pruned)==len(self.dag.input_events): self.log("\t** No events pruned for event type %s. Next!" % event_type) continue pruned_dag = self.dag.input_complement(pruned) bug_found = self.replay(pruned_dag, "opt_%s" % event_type.__name__) if bug_found: self.log("\t** VIOLATION for pruning event type %s! Resizing original dag" % event_type) self.dag = pruned_dag # N.B. always called within a child process. def _track_new_internal_events(self, simulation, replayer): ''' Pre: simulation must have been run through a replay''' # We always check against internal events that were buffered at the end of # the original run (don't want to overcount) prev_buffered_receives = [] try: path = self.superlog_path + ".unacked" if not os.path.exists(path): log.warn("unacked internal events file from original run does not exist") return prev_buffered_receives = set([ e.pending_receive for e in [ f for f in EventDag(log_parser.parse_path(path)).events if type(f) == ControlMessageReceive ] ]) except ValueError as e: log.warn("unacked internal events is corrupt? %r" % e) return buffered_message_receipts = [] for p in simulation.openflow_buffer.pending_receives(): if p not in prev_buffered_receives: buffered_message_receipts.append(repr(p)) else: prev_buffered_receives.remove(p) self._runtime_stats.record_buffered_message_receipts(buffered_message_receipts) new_internal_events = replayer.unexpected_state_changes + replayer.passed_unexpected_messages self._runtime_stats.record_new_internal_events(new_internal_events) self._runtime_stats.record_early_internal_events(replayer.early_state_changes) self._runtime_stats.record_timed_out_events(dict(replayer.event_scheduler_stats.event2timeouts)) self._runtime_stats.record_matched_events(dict(replayer.event_scheduler_stats.event2matched))
def __init__(self, simulation_cfg, superlog_path_or_dag, invariant_check_name="", bug_signature="", transform_dag=None, mcs_trace_path=None, extra_log=None, runtime_stats_path=None, max_replays_per_subsequence=1, optimized_filtering=False, forker=LocalForker(), replay_final_trace=True, strict_assertion_checking=False, no_violation_verification_runs=None, **kwargs): ''' Note that you may pass in any keyword argument for Replayer to MCSFinder, except 'bug_signature' and 'invariant_check_name' ''' super(MCSFinder, self).__init__(simulation_cfg) # number of subsequences delta debugging has examined so far, for # distingushing runtime stats from different intermediate runs. self.subsequence_id = 0 self.mcs_log_tracker = None self.replay_log_tracker = None self.mcs_trace_path = mcs_trace_path self.sync_callback = None self._log = logging.getLogger("mcs_finder") if invariant_check_name == "": raise ValueError("Must specify invariant check") if invariant_check_name not in name_to_invariant_check: raise ValueError('''Unknown invariant check %s.\n''' '''Invariant check name must be defined in config.invariant_checks''', invariant_check_name) self.invariant_check_name = invariant_check_name self.invariant_check = name_to_invariant_check[invariant_check_name] if type(superlog_path_or_dag) == str: self.superlog_path = superlog_path_or_dag # The dag is codefied as a list, where each element has # a list of its dependents self.dag = EventDag(log_parser.parse_path(self.superlog_path)) else: self.dag = superlog_path_or_dag if self.simulation_cfg.ignore_interposition: filtered_events = [e for e in self.dag.events if type(e) not in all_internal_events] self.dag = EventDag(filtered_events) last_invariant_violation = self.dag.get_last_invariant_violation() if last_invariant_violation is None: raise ValueError("No invariant violation found in dag...") violations = last_invariant_violation.violations self.bug_signature = bug_signature if len(violations) > 1: while self.bug_signature == "": msg.interactive("\n------------------------------------------\n") msg.interactive("Multiple violations detected! Choose one for MCS Finding:") for i, violation in enumerate(violations): msg.interactive(" [%d] %s" % (i+1, violation)) violation_index = msg.raw_input("> ") if re.match("^\d+$", violation_index) is None or\ int(violation_index) < 1 or\ int(violation_index) > len(violations): msg.fail("Must provide an integer between 1 and %d!" % len(violations)) continue self.bug_signature = violations[int(violation_index)-1] if self.bug_signature == "": self.bug_signature = violations[0] msg.success("\nBug signature to match is %s. Proceeding with MCS finding!\n" % self.bug_signature) self.transform_dag = transform_dag # A second log with just our MCS progress log messages self._extra_log = extra_log self.kwargs = kwargs unknown_kwargs = [ k for k in kwargs.keys() if k not in Replayer.kwargs ] if unknown_kwargs != []: raise ValueError("Unknown kwargs %s" % str(unknown_kwargs)) if no_violation_verification_runs is not None: raise ValueError('''no_violation_verification_runs parameter is deprecated. ''' '''Use max_replays_per_subsequence.''') self.max_replays_per_subsequence = max_replays_per_subsequence self._runtime_stats = RuntimeStats(self.subsequence_id, runtime_stats_path=runtime_stats_path) # Whether to try alternate trace splitting techiques besides splitting by time. self.optimized_filtering = optimized_filtering self.forker = forker self.replay_final_trace = replay_final_trace self.strict_assertion_checking = strict_assertion_checking
class MCSFinder(ControlFlow): def __init__(self, simulation_cfg, superlog_path_or_dag, invariant_check=InvariantChecker.check_correspondence, transform_dag=None, end_wait_seconds=0.5, mcs_trace_path=None, extra_log=None, dump_runtime_stats=True, **kwargs): super(MCSFinder, self).__init__(simulation_cfg) self.sync_callback = None self._log = logging.getLogger("mcs_finder") if type(superlog_path_or_dag) == str: superlog_path = superlog_path_or_dag # The dag is codefied as a list, where each element has # a list of its dependents self.dag = EventDag(superlog_parser.parse_path(superlog_path)) else: self.dag = superlog_path_or_dag self.invariant_check = invariant_check self.transform_dag = transform_dag self.mcs_trace_path = mcs_trace_path self._extra_log = extra_log self._runtime_stats = None self.kwargs = kwargs self.end_wait_seconds = end_wait_seconds if dump_runtime_stats: self._runtime_stats = {} def log(self, msg): ''' Output a message to both self._log and self._extra_log ''' self._log.info(msg) if self._extra_log is not None: self._extra_log.write(msg + '\n') def simulate(self, check_reproducability=True): if self._runtime_stats is not None: self._runtime_stats["total_inputs"] = len(self.dag.input_events) self._runtime_stats["total_events"] = len(self.dag) # inject domain knowledge into the dag self.dag.mark_invalid_input_sequences() self.dag = self.dag.filter_unsupported_input_types() if len(self.dag) == 0: raise RuntimeError("No supported input types?") if check_reproducability: # First, run through without pruning to verify that the violation exists if self._runtime_stats is not None: self._runtime_stats["replay_start_epoch"] = time.time() violations = self.replay(self.dag) if self._runtime_stats is not None: self._runtime_stats["replay_end_epoch"] = time.time() if violations == []: self.log("Unable to reproduce correctness violation!") sys.exit(5) self.log("Violation reproduced successfully! Proceeding with pruning") if self._runtime_stats is not None: self._runtime_stats["prune_start_epoch"] = time.time() self._ddmin(2) if self._runtime_stats is not None: self._runtime_stats["prune_end_epoch"] = time.time() self._dump_runtime_stats() msg.interactive("Final MCS (%d elements): %s" % (len(self.dag.input_events),str(self.dag.input_events))) if self.mcs_trace_path is not None: self._dump_mcs_trace() return self.dag.events def _ddmin(self, split_ways, precomputed_subsets=None, iteration=0): ''' - iteration is the # of times we've replayed (not the number of times we've invoked _ddmin)''' # This is the delta-debugging algorithm from: # http://www.st.cs.uni-saarland.de/papers/tse2002/tse2002.pdf, # Section 3.2 # TODO(cs): we could do much better if we leverage domain knowledge (e.g., # start by pruning all LinkFailures) if split_ways > len(self.dag.input_events): self._track_iteration_size(iteration + 1, split_ways) self.log("Done") return if precomputed_subsets is None: precomputed_subsets = set() self.log("Checking %d subsets" % split_ways) subsets = split_list(self.dag.input_events, split_ways) self.log("Subsets: %s" % str(subsets)) for i, subset in enumerate(subsets): new_dag = self.dag.input_subset(subset) input_sequence = tuple(new_dag.input_events) self.log("Current subset: %s" % str(input_sequence)) if input_sequence in precomputed_subsets: self.log("Already computed. Skipping") continue precomputed_subsets.add(input_sequence) if input_sequence == (): self.log("Subset after pruning dependencies was empty. Skipping") continue iteration += 1 violation = self._check_violation(new_dag, i, iteration, split_ways) if violation: self.dag = new_dag return self._ddmin(2, precomputed_subsets=precomputed_subsets, iteration=iteration) self.log("No subsets with violations. Checking complements") for i, subset in enumerate(subsets): new_dag = self.dag.input_complement(subset) input_sequence = tuple(new_dag.input_events) self.log("Current complement: %s" % str(input_sequence)) if input_sequence in precomputed_subsets: self.log("Already computed. Skipping") continue precomputed_subsets.add(input_sequence) if input_sequence == (): self.log("Subset after pruning dependencies was empty. Skipping") continue iteration += 1 violation = self._check_violation(new_dag, i, iteration, split_ways) if violation: self.dag = new_dag return self._ddmin(max(split_ways - 1, 2), precomputed_subsets=precomputed_subsets, iteration=iteration) self.log("No complements with violations.") if split_ways < len(self.dag.input_events): self.log("Increasing granularity.") return self._ddmin(min(len(self.dag.input_events), split_ways*2), precomputed_subsets=precomputed_subsets, iteration=iteration) self._track_iteration_size(iteration + 1, split_ways) def _track_iteration_size(self, iteration, split_ways): if self._runtime_stats is not None: if "iteration_size" not in self._runtime_stats: self._runtime_stats["iteration_size"] = {} self._runtime_stats["iteration_size"][iteration] = len(self.dag.input_events) if "split_ways" not in self._runtime_stats: self._runtime_stats["split_ways"] = set() self._runtime_stats["split_ways"].add(split_ways) def _check_violation(self, new_dag, subset_index, iteration, split_ways): ''' Check if there were violations ''' self._track_iteration_size(iteration, split_ways) violations = self.replay(new_dag) if violations == []: # No violation! # If singleton, this must be part of the MCS self.log("No violation in %d'th..." % subset_index) return False else: # Violation in the subset self.log("Violation! Considering %d'th" % subset_index) return True def replay(self, new_dag): # Run the simulation forward if self.transform_dag: new_dag = self.transform_dag(new_dag) # TODO(aw): MCSFinder needs to configure Simulation to always let DataplaneEvents pass through replayer = Replayer(self.simulation_cfg, new_dag, **self.kwargs) simulation = replayer.simulate() # Wait a bit in case the bug takes awhile to happen time.sleep(self.end_wait_seconds) violations = self.invariant_check(simulation) simulation.clean_up() return violations def _dump_mcs_trace(self): # Dump the mcs trace input_logger = InputLogger(output_path=self.mcs_trace_path) for e in self.dag.events: input_logger.log_input_event(e) input_logger.close(self.simulation_cfg, skip_mcs_cfg=True) def _dump_runtime_stats(self): if self._runtime_stats is not None: # First compute durations if "replay_end_epoch" in self._runtime_stats: self._runtime_stats["replay_duration_seconds"] =\ (self._runtime_stats["replay_end_epoch"] - self._runtime_stats["replay_start_epoch"]) if "prune_end_epoch" in self._runtime_stats: self._runtime_stats["prune_duration_seconds"] =\ (self._runtime_stats["prune_end_epoch"] - self._runtime_stats["prune_start_epoch"]) self._runtime_stats["total_replays"] = Replayer.total_replays self._runtime_stats["total_inputs_replayed"] =\ Replayer.total_inputs_replayed self._runtime_stats["config"] = str(self.simulation_cfg) self._runtime_stats["peeker"] = self.transform_dag is not None self._runtime_stats["split_ways"] = list(self._runtime_stats["split_ways"]) # Now write contents to a file now = timestamp_string() with file("runtime_stats/" + now + ".json", "w") as output: json_string = json.dumps(self._runtime_stats) output.write(json_string)
class MCSFinder(ControlFlow): def __init__(self, simulation_cfg, superlog_path_or_dag, invariant_check_name=None, transform_dag=None, end_wait_seconds=0.5, mcs_trace_path=None, extra_log=None, runtime_stats_file=None, wait_on_deterministic_values=False, no_violation_verification_runs=1, optimized_filtering=False, **kwargs): super(MCSFinder, self).__init__(simulation_cfg) self.sync_callback = None self._log = logging.getLogger("mcs_finder") if invariant_check_name is None: raise ValueError("Must specify invariant check") if invariant_check_name not in name_to_invariant_check: raise ValueError('''Unknown invariant check %s.\n''' '''Invariant check name must be defined in config.invariant_checks''', invariant_check_name) self.invariant_check = name_to_invariant_check[invariant_check_name] if type(superlog_path_or_dag) == str: self.superlog_path = superlog_path_or_dag # The dag is codefied as a list, where each element has # a list of its dependents self.dag = EventDag(superlog_parser.parse_path(self.superlog_path)) else: self.dag = superlog_path_or_dag self.transform_dag = transform_dag self.mcs_trace_path = mcs_trace_path self._extra_log = extra_log self.kwargs = kwargs self.end_wait_seconds = end_wait_seconds self.wait_on_deterministic_values = wait_on_deterministic_values # `no' means "number" self.no_violation_verification_runs = no_violation_verification_runs self._runtime_stats = RuntimeStats(runtime_stats_file) self.optimized_filtering = optimized_filtering def log(self, s): ''' Output a message to both self._log and self._extra_log ''' msg.mcs_event(s) if self._extra_log is not None: self._extra_log.write(s + '\n') self._extra_log.flush() def log_violation(self, s): ''' Output a message to both self._log and self._extra_log ''' msg.mcs_event(color.RED + s) if self._extra_log is not None: self._extra_log.write(s + '\n') self._extra_log.flush() def log_no_violation(self, s): ''' Output a message to both self._log and self._extra_log ''' msg.mcs_event(color.GREEN + s) if self._extra_log is not None: self._extra_log.write(s + '\n') self._extra_log.flush() def init_results(self, results_dir): self.results_dir = results_dir if self._extra_log is None: self._extra_log = open("%s/mcs_finder.log" % results_dir, "w") if self._runtime_stats.runtime_stats_file is None: self._runtime_stats.runtime_stats_file = "%s/runtime_stats.json" % results_dir if self.mcs_trace_path is None: self.mcs_trace_path = "%s/mcs.trace" % results_dir def simulate(self, check_reproducability=True): self._runtime_stats.set_dag_stats(self.dag) # inject domain knowledge into the dag self.dag.mark_invalid_input_sequences() self.dag = self.dag.filter_unsupported_input_types() if len(self.dag) == 0: raise RuntimeError("No supported input types?") if check_reproducability: # First, run through without pruning to verify that the violation exists self._runtime_stats.record_replay_start() for i in range(0, self.no_violation_verification_runs): violations = self.replay(self.dag) if violations != []: break self._runtime_stats.set_initial_verification_runs_needed(i) self._runtime_stats.record_replay_end() if violations == []: msg.fail("Unable to reproduce correctness violation!") sys.exit(5) self.log("Violation reproduced successfully! Proceeding with pruning") Replayer.total_replays = 0 Replayer.total_inputs_replayed = 0 self._runtime_stats.record_prune_start() # TODO(cs): Better than a boolean flag: check if # log(len(self.dag)) > number of input types to try if self.optimized_filtering: self._optimize_event_dag() precompute_cache = PrecomputeCache() (dag, total_inputs_pruned) = self._ddmin(self.dag, 2, precompute_cache=precompute_cache) # Make sure to track the final iteration size self._track_iteration_size(total_inputs_pruned) self.dag = dag self._runtime_stats.record_prune_end() self._dump_runtime_stats() self.log("Final MCS (%d elements):" % len(self.dag.input_events)) for i in self.dag.input_events: self.log(" - %s" % str(i)) if self.mcs_trace_path is not None: self._dump_mcs_trace() self.log("=== Total replays: %d ===" % Replayer.total_replays) return self.simulation def _ddmin(self, dag, split_ways, precompute_cache=None, label_prefix=(), total_inputs_pruned=0): # This is the delta-debugging algorithm from: # http://www.st.cs.uni-saarland.de/papers/tse2002/tse2002.pdf, # Section 3.2 # TODO(cs): we could do much better if we leverage domain knowledge (e.g., # start by pruning all LinkFailures) if split_ways > len(dag.input_events): self.log("Done") return (dag, total_inputs_pruned) local_label = lambda i, inv=False: "%s%d/%d" % ("~" if inv else "", i, split_ways) subset_label = lambda label: ".".join(map(str, label_prefix + ( label, ))) print_subset = lambda label, s: subset_label(label) + ": "+" ".join(map(lambda e: e.label, s)) subsets = split_list(dag.input_events, split_ways) self.log("Subsets:\n"+"\n".join(print_subset(local_label(i), s) for i, s in enumerate(subsets))) for i, subset in enumerate(subsets): label = local_label(i) new_dag = dag.input_subset(subset) input_sequence = tuple(new_dag.input_events) self.log("Current subset: %s" % print_subset(label, input_sequence)) if precompute_cache.already_done(input_sequence): self.log("Already computed. Skipping") continue precompute_cache.update(input_sequence) if input_sequence == (): self.log("Subset after pruning dependencies was empty. Skipping") continue self._track_iteration_size(total_inputs_pruned) violation = self._check_violation(new_dag, i) if violation: self.log_violation("Subset %s reproduced violation. Subselecting." % subset_label(label)) self._maybe_dump_intermediate_mcs(new_dag, subset_label(label)) total_inputs_pruned += len(dag.input_events) - len(new_dag.input_events) return self._ddmin(new_dag, 2, precompute_cache=precompute_cache, label_prefix = label_prefix + (label, ), total_inputs_pruned=total_inputs_pruned) self.log_no_violation("No subsets with violations. Checking complements") for i, subset in enumerate(subsets): label = local_label(i, True) prefix = label_prefix + (label, ) new_dag = dag.input_complement(subset) input_sequence = tuple(new_dag.input_events) self.log("Current complement: %s" % print_subset(label, input_sequence)) if precompute_cache.already_done(input_sequence): self.log("Already computed. Skipping") continue precompute_cache.update(input_sequence) if input_sequence == (): self.log("Subset %s after pruning dependencies was empty. Skipping", subset_label(label)) continue self._track_iteration_size(total_inputs_pruned) violation = self._check_violation(new_dag, i) if violation: self.log_violation("Subset %s reproduced violation. Subselecting." % subset_label(label)) self._maybe_dump_intermediate_mcs(new_dag, subset_label(label)) total_inputs_pruned += len(dag.input_events) - len(new_dag.input_events) return self._ddmin(new_dag, max(split_ways - 1, 2), precompute_cache=precompute_cache, label_prefix=prefix, total_inputs_pruned=total_inputs_pruned) self.log_no_violation("No complements with violations.") if split_ways < len(dag.input_events): self.log("Increasing granularity.") return self._ddmin(dag, min(len(dag.input_events), split_ways*2), precompute_cache=precompute_cache, label_prefix=label_prefix, total_inputs_pruned=total_inputs_pruned) return (dag, total_inputs_pruned) def _track_iteration_size(self, total_inputs_pruned): self._runtime_stats.record_iteration_size(len(self.dag.input_events) - total_inputs_pruned) def _check_violation(self, new_dag, subset_index): ''' Check if there were violations ''' # Try no_violation_verification_runs times to see if the bug shows up for i in range(0, self.no_violation_verification_runs): violations = self.replay(new_dag) if violations != []: # Violation in the subset self.log_violation("Violation! Considering %d'th" % subset_index) self._runtime_stats.record_violation_found(i) return True # No violation! self.log_no_violation("No violation in %d'th..." % subset_index) return False def replay(self, new_dag): # Run the simulation forward if self.transform_dag: new_dag = self.transform_dag(new_dag) # TODO(aw): MCSFinder needs to configure Simulation to always let DataplaneEvents pass through replayer = Replayer(self.simulation_cfg, new_dag, wait_on_deterministic_values=self.wait_on_deterministic_values, **self.kwargs) simulation = replayer.simulate() self._track_new_internal_events(simulation, replayer) # Wait a bit in case the bug takes awhile to happen self.log("Sleeping %d seconds after run" % self.end_wait_seconds) time.sleep(self.end_wait_seconds) violations = self.invariant_check(simulation) simulation.clean_up() return violations def _optimize_event_dag(self): ''' Employs domain knowledge of event classes to reduce the size of event dag ''' event_types = [TrafficInjection, DataplaneDrop, SwitchFailure, SwitchRecovery, LinkFailure, LinkRecovery, HostMigration, ControllerFailure, ControllerRecovery, PolicyChange, ControlChannelBlock, ControlChannelUnblock] for event_type in event_types: pruned = [e for e in self.dag.input_events if not isinstance(e, event_type)] if len(pruned)==len(self.dag.input_events): self.log("\t** No events pruned for event type %s. Next!" % event_type) continue pruned_dag = self.dag.input_complement(pruned) violations = self.replay(pruned_dag) if violations != []: self.log("\t** VIOLATION for pruning event type %s! Resizing original dag" % event_type) self.dag = pruned_dag def _track_new_internal_events(self, simulation, replayer): ''' Pre: simulation must have been run through a replay''' # We always check against internal events that were buffered at the end of # the original run (don't want to overcount) path = self.superlog_path + ".unacked" if not os.path.exists(path): log.warn("unacked internal events file from original run does not exists") return prev_buffered_receives = [ e.pending_receive for e in EventDag(superlog_parser.parse_path(path)).events ] new_message_receipts = [] for p in simulation.god_scheduler.pending_receives(): if p not in prev_buffered_receives: new_message_receipts.append(repr(p)) else: prev_buffered_receives.remove(p) new_state_changes = replayer.unexpected_state_changes new_internal_events = new_state_changes + new_message_receipts self._runtime_stats.record_new_internal_events(new_internal_events) self._runtime_stats.record_early_internal_events(replayer.early_state_changes) self._runtime_stats.record_timed_out_events(dict(replayer.event_scheduler_stats.event2timeouts)) self._runtime_stats.record_matched_events(dict(replayer.event_scheduler_stats.event2matched)) def _maybe_dump_intermediate_mcs(self, dag, label): class InterMCS(object): def __init__(self): self.min_size = sys.maxint self.count = 0 if not hasattr(self, "_intermcs"): self._intermcs = InterMCS() if len(dag.events) < self._intermcs.min_size: self._intermcs.min_size = len(dag.events) self._intermcs.count += 1 dst = os.path.join(self.results_dir, "intermcs_%d_%s" % (self._intermcs.count, label.replace("/", "."))) os.makedirs(dst) self._dump_mcs_trace(dag, os.path.join(dst, os.path.basename(self.mcs_trace_path))) self._dump_runtime_stats(os.path.join(dst, os.path.basename(self._runtime_stats.runtime_stats_file))) def _dump_mcs_trace(self, dag=None, mcs_trace_path=None): if dag is None: dag = self.dag if mcs_trace_path is None: mcs_trace_path = self.mcs_trace_path # Dump the mcs trace input_logger = InputLogger(output_path=mcs_trace_path) input_logger.open(os.path.dirname(mcs_trace_path)) for e in dag.events: input_logger.log_input_event(e) input_logger.close(self, self.simulation_cfg, skip_mcs_cfg=True) def _dump_runtime_stats(self, runtime_stats_file=None): runtime_stats = self._runtime_stats.clone() if runtime_stats_file is not None: runtime_stats.runtime_stats_file = runtime_stats_file runtime_stats.set_peeker(self.transform_dag is not None) runtime_stats.set_config(str(self.simulation_cfg)) runtime_stats.write_runtime_stats()
def peek(self, dag): ''' Infer which internal events are/aren't going to occur (for the entire sequence of input events in dag)''' # TODO(cs): optimization: write the prefix trie to a file, in case we want to run # FindMCS again? if len(dag.input_events) == 0: # Postcondition: input_events[-1] is not None # and self._events_list[-1] is not None return dag # dag.input_events returns only prunable input events. We also need # include ConnectToControllers, which is a non-prunable input event. if not isinstance(dag.events[0], ConnectToControllers): raise ValueError("First event must be ConnectToControllers") assert(dag.input_events[0] != dag.events[0]) input_events = [dag.events[0]] + dag.input_events # Initilize current_input_prefix to the longest_match prefix we've # inferred previously (or [] if this is an entirely new prefix) current_input_prefix = list(self._prefix_trie\ .longest_prefix(input_events, default=[])) log.debug("Current input prefix: %s" % str(current_input_prefix)) # The value is both internal events and input events (values of the trie) # leading up, but not including the next input following the tail of the # prefix. # Note that we assume that there are no internal events before the first # input event (i.e. we assume quiescence) inferred_events = list(self._prefix_trie\ .longest_prefix_value(input_events, default=[])) log.debug("Current inferred_events: %s" % str(inferred_events)) inject_input_idx = len(current_input_prefix) # While we still have inputs to inject while inject_input_idx < len(input_events): # The input we're about to inject inject_input = input_events[inject_input_idx] following_input = get_following_input(inject_input_idx, dag.input_events) # The input following the one we're going to inject log.debug("peek()'ing after input %d" % (inject_input_idx)) expected_internal_events = \ get_expected_internal_events(inject_input, following_input, dag.events) # Optimization: if no internal events occured between this input and the # next, no need to peek() if expected_internal_events == []: log.debug("Optimization: no expected internal events") newly_inferred_events = [] Peeker.ambiguous_counts[0.0] += 1 else: wait_time_seconds = self.get_wait_time_seconds(inject_input, following_input) # We inject a NOPInput with the same timestamp as inject_input # to ensure that the timing is the same before peek()ing, then replay # inject_input in play_forward() fencepost = NOPInput(time=inject_input.time, round=inject_input.round) replay_dag = EventDag(inferred_events + [ fencepost ]) found_events = self.find_internal_events(replay_dag, inject_input, wait_time_seconds) newly_inferred_events = match_and_filter(found_events, expected_internal_events) (current_input_prefix, inferred_events) = self._update_trie(current_input_prefix, inject_input, inferred_events, newly_inferred_events) inject_input_idx += 1 return EventDag(inferred_events)
def peek(self, dag): ''' If dag.events == [], returns immediately. If dag.events != [], assumes that isinstance(dag.events[0], ConnectToControllers) ''' if dag.input_events == []: return dag # post: len(dag.input_events) > 0 unsupported_types = [ProcessFlowMod, DataplaneDrop] if find(lambda e: type(e) in unsupported_types, dag.events) is not None: raise ValueError('''Delayed flow_mods not yet supported. Please ''' '''implement the TODO near the sleep() call in play_forward()''') if not isinstance(dag.events[0], ConnectToControllers): raise ValueError("First event must be ConnectToControllers") simulation = None try: # Inferred events includes input events and internal events inferred_events = [] (simulation, controller) = self.setup_simulation() # dag.input_events returns only prunable input events. We also need # include ConnectToControllers, which is a non-prunable input event. assert(dag.input_events[0] != dag.events[0]) snapshot_inputs = [dag.events[0]] + dag.input_events # The input event from the previous iteration, followed by the internal # events that were inferred from the previous peek(). # Since we assume that the first event is always ConnectToControllers, # there are never internal events (nor input events) preceding the # initial ConnectToControllers. # TODO(cs): might not want to contrain the caller's dag in this way. events_inferred_last_iteration = [] for inject_input_idx in xrange(0, len(snapshot_inputs)): inject_input = get_inject_input(inject_input_idx, snapshot_inputs) following_input = get_following_input(inject_input_idx, snapshot_inputs) expected_internal_events = \ get_expected_internal_events(inject_input, following_input, dag.events) log.debug("peek()'ing after input %d (%s)" % (inject_input_idx, str(inject_input))) inferred_events += events_inferred_last_iteration # We replay events_inferred_last_iteration (internal events preceding # inject_input), as well as a NOPInput with the same timestamp as inject_input # to ensure that the timing is the same before peek()ing. fencepost = NOPInput(time=inject_input.time, round=inject_input.round) dag_interval = EventDag(events_inferred_last_iteration + [fencepost]) if expected_internal_events == []: # Optimization: if no internal events occured between this input and the # next, no need to peek(), just bring the simulation's state forward up to # inject_input log.debug("Optimization: no expected internal events") Peeker.ambiguous_counts[0.0] += 1 self.replay_interval(simulation, dag_interval, 0) events_inferred_last_iteration = [inject_input] continue wait_time_seconds = self.get_wait_time_seconds(inject_input, following_input) (found_events, snapshotter) = self.find_internal_events(simulation, controller, dag_interval, inject_input, wait_time_seconds) events_inferred_last_iteration = [inject_input] events_inferred_last_iteration += match_and_filter(found_events, expected_internal_events) snapshotter.snapshot_proceed() # Don't forget the final iteration's output inferred_events += events_inferred_last_iteration finally: if simulation is not None: simulation.clean_up() return EventDag(inferred_events)
def __init__(self, simulation_cfg, superlog_path_or_dag, create_event_scheduler=None, print_buffers=True, wait_on_deterministic_values=False, default_dp_permit=False, fail_to_interactive=False, fail_to_interactive_on_persistent_violations=False, end_in_interactive=False, input_logger=None, allow_unexpected_messages=False, pass_through_whitelisted_messages=True, delay_flow_mods=False, **kwargs): ControlFlow.__init__(self, simulation_cfg) if wait_on_deterministic_values: self.sync_callback = ReplaySyncCallback() else: self.sync_callback = ReplaySyncCallback(self.get_interpolated_time) if type(superlog_path_or_dag) == str: superlog_path = superlog_path_or_dag # The dag is codefied as a list, where each element has # a list of its dependents self.dag = EventDag(log_parser.parse_path(superlog_path)) else: self.dag = superlog_path_or_dag if len(self.dag.events) == 0: raise ValueError("No events to replay!") self.default_dp_permit = default_dp_permit # Set DataplanePermit and DataplaneDrop to passive if permit is set # to default for event in [ e for e in self.dag.events if type(e) in dp_events ]: event.passive = default_dp_permit self.dp_checker = None if default_dp_permit: self.dp_checker = DataplaneChecker(self.dag) self.print_buffers_flag = print_buffers # compute interpolate to time to be just before first event self.compute_interpolated_time(self.dag.events[0]) # String repesentations of unexpected state changes we've passed through, for # statistics purposes. self.unexpected_state_changes = [] self.early_state_changes = [] self.event_scheduler_stats = None self.end_in_interactive = end_in_interactive self.fail_to_interactive = fail_to_interactive self.fail_to_interactive_on_persistent_violations =\ fail_to_interactive_on_persistent_violations self._input_logger = input_logger self.allow_unexpected_messages = allow_unexpected_messages self.pass_through_whitelisted_messages = pass_through_whitelisted_messages # How many logical rounds to peek ahead when deciding if a message is # expected or not. self.expected_message_round_window = 3 # String repesentations of unexpected messages we've passed through, for # statistics purposes. self.passed_unexpected_messages = [] self.delay_flow_mods = delay_flow_mods if self.pass_through_whitelisted_messages: for event in self.dag.events: if hasattr(event, "ignore_whitelisted_packets"): event.ignore_whitelisted_packets = True if create_event_scheduler: self.create_event_scheduler = create_event_scheduler else: self.create_event_scheduler = \ lambda simulation: EventScheduler(simulation, **{ k: v for k,v in kwargs.items() if k in EventScheduler.kwargs })