def simulate(self):
self.simulation = self.simulation_cfg.bootstrap(self.sync_callback,
boot_controllers=boot_mock_controllers)
connect_to_mock_controllers(self.simulation)
# Reproduce the routing table state.
for next_event in self.event_list:
msg.success("Injecting %r" % next_event)
next_event.manually_inject(self.simulation)
# now filter out all flow_mods that don't correspond to an entry in the
# final routing table. Do that by walking backwards through the flow_mods,
# and checking if they match the flow table. If so, add it to list, and
# remove all flow entries that currently match it to filter overlapping
# flow_mods from earlier in the event_list.
relevent_flow_mods = []
all_flow_mods = [e for e in self.event_list if type(e.get_packet()) == ofp_flow_mod]
for last_event in reversed(all_flow_mods):
switch = self.simulation.topology.get_switch(last_event.dpid)
if switch.table.matching_entries(last_event.get_packet().match) != []:
relevent_flow_mods.append(last_event)
switch.table.remove_matching_entries(last_event.get_packet().match)
# Now print them in the forward direction.
msg.interactive("Filtered flow mods:")
for next_event in reversed(relevent_flow_mods):
print "%r" % next_event
return self.simulation
def do_invariant_check():
if self.log_invariant_checks:
self._log_input_event(CheckInvariants(invariant_check=self.invariant_check,
fail_on_error=self.halt_on_violation))
controllers_with_violations = self.invariant_check(self.simulation)
if controllers_with_violations != []:
msg.fail("The following controllers had correctness violations!: %s"
% str(controllers_with_violations))
self._log_input_event(InvariantViolation(controllers_with_violations))
if self.halt_on_violation:
return True
else:
msg.interactive("No correctness violations!")
def proceed(self, simulation):
try:
violations = self.invariant_check(simulation)
except NameError as e:
raise ValueError('''Closures are unsupported for invariant check '''
'''functions.\n Use dynamic imports inside of your '''
'''invariant check code and define all globals '''
'''locally.\n NameError: %s''' % str(e))
if violations != []:
msg.fail("The following controllers had correctness violations!: %s"
% str(violations))
if self.fail_on_error:
msg.fail("Exiting: fail_on_error=True")
exit(5)
else:
msg.interactive("No correctness violations!")
return True
def do_invariant_check():
if self.log_invariant_checks:
self._log_input_event(
CheckInvariants(invariant_check=self.invariant_check,
fail_on_error=self.halt_on_violation))
controllers_with_violations = self.invariant_check(
self.simulation)
if controllers_with_violations != []:
msg.fail(
"The following controllers had correctness violations!: %s"
% str(controllers_with_violations))
self._log_input_event(
InvariantViolation(controllers_with_violations))
if self.halt_on_violation:
return True
else:
msg.interactive("No correctness violations!")
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 interrupt(sgn, frame):
msg.interactive("Interrupting fuzzer, dropping to console (press ^C again to terminate)")
signal.signal(signal.SIGINT, self.old_interrupt)
self.old_interrupt = None
self.interrupted = True
raise KeyboardInterrupt()
def show_flow_tables(simulation):
for switch in simulation.topology.switches:
msg.interactive("Switch %s" % switch.dpid)
switch.show_flow_table()
def show_flow_tables(simulation):
for switch in simulation.topology.switches:
msg.interactive("Switch %s" % switch.dpid)
switch.show_flow_table()
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,
delay_flow_mods=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
self.delay_flow_mods = delay_flow_mods
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 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 invariant_check_prompt(self):
answer = msg.raw_input('Check Invariants? [Ny]')
if answer != '' and answer.lower() != 'n':
msg.interactive("Which one?")
msg.interactive(" 'o' - omega")
msg.interactive(" 'c' - connectivity")
msg.interactive(" 'lo' - loops")
msg.interactive(" 'li' - controller liveness")
answer = msg.raw_input("> ")
result = None
message = ""
if answer.lower() == 'o':
self._log_input_event(
CheckInvariants(
invariant_check=InvariantChecker.check_correspondence))
result = InvariantChecker.check_correspondence(self.simulation)
message = "Controllers with miscorrepondence: "
elif answer.lower() == 'c':
self._log_input_event(
CheckInvariants(
invariant_check=InvariantChecker.check_connectivity))
result = self.invariant_checker.check_connectivity(
self.simulation)
message = "Disconnected host pairs: "
elif answer.lower() == 'lo':
self._log_input_event(
CheckInvariants(
invariant_check=InvariantChecker.check_loops))
result = self.invariant_checker.check_loops(self.simulation)
message = "Loops: "
elif answer.lower() == 'li':
self._log_input_event(
CheckInvariants(
invariant_check=InvariantChecker.check_liveness))
result = self.invariant_checker.check_loops(self.simulation)
message = "Crashed controllers: "
else:
log.warn("Unknown input...")
if result is None:
return
else:
msg.interactive("%s: %s" % (message, str(result)))
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
def invariant_check_prompt(self):
answer = msg.raw_input('Check Invariants? [Ny]')
if answer != '' and answer.lower() != 'n':
msg.interactive("Which one?")
msg.interactive(" 'o' - omega")
msg.interactive(" 'c' - connectivity")
msg.interactive(" 'lo' - loops")
msg.interactive(" 'li' - controller liveness")
answer = msg.raw_input("> ")
result = None
message = ""
if answer.lower() == 'o':
self._log_input_event(CheckInvariants(invariant_check=InvariantChecker.check_correspondence))
result = InvariantChecker.check_correspondence(self.simulation)
message = "Controllers with miscorrepondence: "
elif answer.lower() == 'c':
self._log_input_event(CheckInvariants(invariant_check=InvariantChecker.check_connectivity))
result = self.invariant_checker.check_connectivity(self.simulation)
message = "Disconnected host pairs: "
elif answer.lower() == 'lo':
self._log_input_event(CheckInvariants(invariant_check=InvariantChecker.check_loops))
result = self.invariant_checker.check_loops(self.simulation)
message = "Loops: "
elif answer.lower() == 'li':
self._log_input_event(CheckInvariants(invariant_check=InvariantChecker.check_liveness))
result = self.invariant_checker.check_loops(self.simulation)
message = "Crashed controllers: "
else:
log.warn("Unknown input...")
if result is None:
return
else:
msg.interactive("%s: %s" % (message, str(result)))
