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 python_check_connectivity(simulation):
# Warning! depends on python Hassell -- may be really slow!
NTF = hsa_topo.generate_NTF(simulation.topology.live_switches)
TTF = hsa_topo.generate_TTF(simulation.topology.live_links)
paths = hsa.find_reachability(NTF, TTF, simulation.topology.access_links)
# Paths is: in_port -> [p_node1, p_node2]
# Where p_node is a hash:
# "hdr" -> foo
# "port" -> foo
# "visits" -> foo
connected_pairs = set()
for in_port, p_nodes in paths.iteritems():
for p_node in p_nodes:
connected_pairs.add((in_port, p_node["port"]))
all_pairs = InvariantChecker._get_all_pairs(simulation)
remaining_pairs = all_pairs - connected_pairs
partitioned_pairs = check_partitions(simulation.topology.switches,
simulation.topology.live_links,
simulation.topology.access_links)
if len(partitioned_pairs) != 0:
log.info("Partitioned pairs! %s" % str(partitioned_pairs))
remaining_pairs -= partitioned_pairs
# TODO(cs): don't print results here
if len(remaining_pairs) > 0:
msg.fail("Not all %d pairs are connected! (%d missing)" %
(len(all_pairs),len(remaining_pairs)))
log.info("remaining_pairs: %s" % (str(remaining_pairs)))
else:
msg.success("Fully connected!")
return list(remaining_pairs)
def check_connectivity(simulation):
''' Return any pairs that couldn't reach each other '''
# Always check liveness
down_controllers = InvariantChecker.check_liveness(simulation)
if down_controllers != []:
return down_controllers
# Effectively, run compute physical omega, ignore concrete values of headers, and
# check that all pairs can reach eachother
physical_omega = InvariantChecker.compute_physical_omega(simulation.topology.live_switches,
simulation.topology.live_links,
simulation.topology.access_links)
connected_pairs = set()
# Omegas are { original port -> [(final hs1, final port1), (final hs2, final port2)...] }
for start_port, final_location_list in physical_omega.iteritems():
for _, final_port in final_location_list:
connected_pairs.add((start_port, final_port))
# TODO(cs): translate HSA port numbers to ofp_phy_ports in the
# headerspace/ module instead of computing uniq_port_id here
access_links = simulation.topology.access_links
all_pairs = [ (get_uniq_port_id(l1.switch, l1.switch_port),get_uniq_port_id(l2.switch, l2.switch_port))
for l1 in access_links
for l2 in access_links if l1 != l2 ]
all_pairs = set(all_pairs)
remaining_pairs = all_pairs - connected_pairs
# TODO(cs): don't print results here
if len(remaining_pairs) > 0:
msg.fail("Not all %d pairs are connected! (%d missing)" %
(len(all_pairs),len(remaining_pairs)))
log.info("remaining_pairs: %s" % (str(remaining_pairs)))
else:
msg.success("Fully connected!")
return list(remaining_pairs)
def _check_connectivity_msg(unconnected_pairs):
if len(unconnected_pairs) == 0:
msg.success("Fully connected!")
else:
msg.fail("Found %d unconnected pair%s: %s" %
(len(unconnected_pairs), "" if len(unconnected_pairs) == 1
else "s", unconnected_pairs))
def check_connectivity(simulation):
''' Return any pairs that couldn't reach each other '''
# Dynamic imports to allow this method to be serialized
from sts.headerspace.config_parser.openflow_parser import get_uniq_port_id
from sts.util.console import msg
# Always check liveness if there is a single controllers
if len(simulation.controller_manager.controllers) == 1:
down_controllers = InvariantChecker.check_liveness(simulation)
if down_controllers != []:
return down_controllers
# Effectively, run compute physical omega, ignore concrete values of headers, and
# check that all pairs can reach eachother
physical_omega = InvariantChecker.compute_physical_omega(simulation.topology.live_switches,
simulation.topology.live_links,
simulation.topology.access_links)
connected_pairs = set()
# Omegas are { original port -> [(final hs1, final port1), (final hs2, final port2)...] }
for start_port, final_location_list in physical_omega.iteritems():
for _, final_port in final_location_list:
connected_pairs.add((start_port, final_port))
all_pairs = InvariantChecker._get_all_pairs(simulation)
remaining_pairs = all_pairs - connected_pairs
# TODO(cs): don't print results here
if len(remaining_pairs) > 0:
msg.fail("Not all %d pairs are connected! (%d missing)" %
(len(all_pairs),len(remaining_pairs)))
log.info("remaining_pairs: %s" % (str(remaining_pairs)))
else:
msg.success("Fully connected!")
return list(remaining_pairs)
def check_connectivity(simulation):
''' Return any pairs that couldn't reach each other '''
# Always check liveness
down_controllers = InvariantChecker.check_liveness(simulation)
if down_controllers != []:
return down_controllers
# Effectively, run compute physical omega, ignore concrete values of headers, and
# check that all pairs can reach eachother
physical_omega = InvariantChecker.compute_physical_omega(
simulation.topology.live_switches, simulation.topology.live_links,
simulation.topology.access_links)
connected_pairs = set()
# Omegas are { original port -> [(final hs1, final port1), (final hs2, final port2)...] }
for start_port, final_location_list in physical_omega.iteritems():
for _, final_port in final_location_list:
connected_pairs.add((start_port, final_port))
# TODO(cs): translate HSA port numbers to ofp_phy_ports in the
# headerspace/ module instead of computing uniq_port_id here
access_links = simulation.topology.access_links
all_pairs = [(get_uniq_port_id(l1.switch, l1.switch_port),
get_uniq_port_id(l2.switch, l2.switch_port))
for l1 in access_links for l2 in access_links if l1 != l2]
all_pairs = set(all_pairs)
remaining_pairs = all_pairs - connected_pairs
# TODO(cs): don't print results here
if len(remaining_pairs) > 0:
msg.fail("Not all %d pairs are connected! (%d missing)" %
(len(all_pairs), len(remaining_pairs)))
log.info("remaining_pairs: %s" % (str(remaining_pairs)))
else:
msg.success("Fully connected!")
return list(remaining_pairs)
def track(self, violations, logical_time):
# First, untrack violations that expire
for v in self.violation2time.keys():
if v not in violations:
msg.success("Violation %s turns out to be transient!" % v)
del self.violation2time[v]
# Now, track violations observed this round
for v in violations:
if v not in self.violation2time.keys():
self.violation2time[v] = (logical_time, logical_time)
else:
start_time = self.violation2time[v][0]
end_time = logical_time
self.violation2time[v] = (start_time, end_time)
msg.fail("Violation encountered again after %d steps: %s" %
(end_time - start_time, v))
def track(self, violations, logical_time):
# First, untrack violations that expire
for v in self.violation2time.keys():
if v not in violations:
msg.success("Violation %s turns out to be transient!" % v)
del self.violation2time[v]
# Now, track violations observed this round
for v in violations:
if v not in self.violation2time.keys():
self.violation2time[v] = (logical_time, logical_time)
else:
start_time = self.violation2time[v][0]
end_time = logical_time
self.violation2time[v] = (start_time, end_time)
msg.fail("Violation encountered again after %d steps: %s" %
(end_time - start_time, v))
def _check_connectivity_msg(unconnected_pairs):
if len(unconnected_pairs) == 0:
msg.success("Fully connected!")
else:
msg.fail("Found %d unconnected pair%s: %s" % (len(unconnected_pairs),
"" if len(unconnected_pairs)==1 else "s", unconnected_pairs))
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 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,
delay_flow_mods=self.delay_flow_mods,
**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.success("No correctness violations!")
if not ignore_runtime_stats:
self._runtime_stats.merge_client_dict(client_runtime_stats)
return bug_found
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,
delay_flow_mods=self.delay_flow_mods,
**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.success("No correctness violations!")
if not ignore_runtime_stats:
self._runtime_stats.merge_client_dict(client_runtime_stats)
return bug_found
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
