def new_frame(
self,
contents: Optional[Dict[Phase, Sequence[Expr]]] = None) -> None:
if contents is None:
contents = {}
utils.logger.debug("new frame! %s" % len(self.fs))
self.fs.append(Frame(self.automaton.phases(), contents))
self.push_cache.append({p: set() for p in self.automaton.phases()})
self.push_forward_frames()
with utils.LogTag(utils.logger,
'current-frames-after-push',
lvl=logging.DEBUG):
self.print_frames(lvl=logging.DEBUG)
self.establish_safety()
with utils.LogTag(utils.logger,
'current-frames-after-safety',
lvl=logging.DEBUG):
self.print_frames(lvl=logging.DEBUG)
self.simplify()
with utils.LogTag(utils.logger,
'current-frames-after-simplify',
lvl=logging.DEBUG):
self.print_frames(lvl=logging.DEBUG)
def print_frame(self, i: int, lvl: int = logging.INFO) -> None:
f = self.fs[i]
with utils.LogTag(utils.logger, 'frame', i=str(i)):
for p in self.automaton.phases():
utils.logger.log_list(lvl,
['frame %d of %s is' % (i, p.name())] +
[str(x) for x in f.summary_of(p)])
def simplify(self) -> None:
for i, f in enumerate(self.fs):
for p in self.automaton.phases():
with utils.LogTag(utils.logger, 'simplify', frame=str(i)):
utils.logger.debug('simplifying frame %d, pred %s' %
(i, p.name()))
self._simplify_summary(f.summary_of(p), p)
def search(self) -> Frame:
while True:
self.establish_safety()
with utils.LogTag(utils.logger,
'current-frames-after-safety',
lvl=logging.DEBUG):
self.print_frames(lvl=logging.DEBUG)
self.simplify()
with utils.LogTag(utils.logger,
'current-frames-after-simplify',
lvl=logging.DEBUG):
self.print_frames(lvl=logging.DEBUG)
self.print_status()
n = len(self) - 1
with utils.LogTag(utils.logger,
'check-frame',
lvl=logging.INFO,
n=str(n)):
with utils.LogTag(utils.logger,
'current-frames',
lvl=logging.INFO):
self.print_frames()
utils.logger.info('considering frame %s' % (len(self) - 1, ))
f = self.get_inductive_frame()
if f is not None:
utils.logger.always_print(
'frame is safe and inductive. done!')
for p in self.automaton.phases():
utils.logger.log_list(
utils.MyLogger.ALWAYS_PRINT,
['summary of %s: ' % p.name()] +
[str(x) for x in f.summary_of(p)])
return f
utils.logger.info(
'frame is safe but not inductive. starting new frame')
self.new_frame()
def process_conjunct(c: Expr) -> None:
if c in self.fs[i + 1].summary_of(p) or c in self.push_cache[i][p]:
return
with utils.LogTag(utils.logger,
'pushing-conjunct',
lvl=logging.DEBUG,
frame=str(i),
conj=str(c)):
self.push_conjunct(i, c, p, frame_old_count)
self.push_cache[i][p].add(c)
def always_assert_inductive_trace(self) -> None:
for i, f in enumerate(self.fs[:-1]):
with utils.LogTag(utils.logger,
'inductive-trace-assert',
lvl=logging.DEBUG,
i=str(i)):
for p in self.automaton.phases():
for c in self.fs[i + 1].summary_of(p):
res = self.clause_implied_by_transitions_from_frame(
f, p, c, Solver())
assert res is None, (
"Non inductive trace:\n\t%s\n\t%s\n\t%s" %
(p.name(), c, f))
def search(self) -> Frame:
init_conjuncts = [init.expr for init in syntax.the_program.inits()]
self.new_frame({
p: init_conjuncts
if p == self.automaton.init_phase() else [syntax.FalseExpr]
for p in self.automaton.phases()
})
self.new_frame()
while True:
n = len(self) - 1
with utils.LogTag(utils.logger,
'check-frame',
lvl=logging.INFO,
n=str(n)):
with utils.LogTag(utils.logger,
'current-frames',
lvl=logging.INFO):
self.print_frames()
utils.logger.info('considering frame %s' % (len(self) - 1, ))
f = self.get_inductive_frame()
if f is not None:
utils.logger.always_print(
'frame is safe and inductive. done!')
for p in self.automaton.phases():
utils.logger.log_list(
utils.MyLogger.ALWAYS_PRINT,
['summary of %s: ' % p.name()] +
[str(x) for x in f.summary_of(p)])
return f
utils.logger.info(
'frame is safe but not inductive. starting new frame')
self.new_frame()
def establish_safety(self) -> None:
self.debug_assert_inductive_trace()
frame_no = len(self.fs) - 1
while True:
with utils.LogTag(utils.logger, 'establish-safety-attempt'):
res = self._get_some_cex_to_safety()
if res is None:
break
(violating, diag) = res
self.block(diag, frame_no, violating, [(None, diag)], True)
self.debug_assert_inductive_trace()
def push_forward_frames(self) -> None:
self.debug_assert_inductive_trace()
for i, f in enumerate(self.fs[:-1]):
if ((utils.args.push_frame_zero == 'if_trivial'
and self.automaton.nontrivial) or
(utils.args.push_frame_zero == 'never')) and i == 0:
continue
with utils.LogTag(utils.logger,
'pushing-frame',
lvl=logging.DEBUG,
i=str(i)):
for p in self.automaton.phases():
utils.logger.debug('pushing in frame %d phase %s' %
(i, p.name()))
self.push_phase_from_pred(i, f, p)
# self.debug_assert_inductive_trace()
self.debug_assert_inductive_trace()
def main() -> None:
resource.setrlimit(
resource.RLIMIT_AS, (90 * 10**9, 90 * 10**9)
) # limit RAM usage to 45 GB # TODO: make this a command line argument # TODO: not sure if this is actually the right way to do this (also, what about child processes?)
utils.args = parse_args(sys.argv[1:])
if utils.args.log_xml:
fmt = '%(message)s'
elif utils.args.log_time:
fmt = '%(asctime)s %(filename)s:%(lineno)d: %(message)s'
else:
fmt = '%(filename)s:%(lineno)d: %(message)s'
if 'json' in utils.args and utils.args.json:
utils.args.log = 'critical'
utils.logger.setLevel(getattr(logging, utils.args.log.upper(), None))
handler = logging.StreamHandler(stream=sys.stdout)
handler.terminator = ''
handler.setFormatter(MyFormatter(fmt))
logging.root.addHandler(handler)
# utils.logger.addHandler(handler)
with utils.LogTag(utils.logger, 'main', lvl=logging.INFO):
if utils.args.print_cmdline:
with utils.LogTag(utils.logger, 'options', lvl=logging.INFO):
utils.logger.info(' '.join([sys.executable] + sys.argv))
utils.logger.info('Running mypyvy with the following options:')
for k, v in sorted(vars(utils.args).items()):
utils.logger.info(f' {k} = {v!r}')
utils.logger.info('setting seed to %d' % utils.args.seed)
z3.set_param('smt.random_seed', utils.args.seed)
# utils.logger.info('enable z3 macro finder')
# z3.set_param('smt.macro_finder', True)
if utils.args.timeout is not None:
utils.logger.info('setting z3 timeout to %s' % utils.args.timeout)
z3.set_param('timeout', utils.args.timeout)
pre_parse_error_count = utils.error_count
with open(utils.args.filename) as f:
prog = parse_program(
f.read(),
force_rebuild=utils.args.forbid_parser_rebuild,
filename=utils.args.filename)
if utils.error_count > pre_parse_error_count:
utils.logger.always_print('program has syntax errors.')
sys.exit(1)
if utils.args.print_program_repr:
utils.logger.always_print(repr(prog))
if utils.args.print_program:
utils.logger.always_print(str(prog))
pre_resolve_error_count = utils.error_count
prog.resolve()
if utils.error_count > pre_resolve_error_count:
utils.logger.always_print('program has resolution errors.')
sys.exit(1)
syntax.the_program = prog
s = Solver()
# initialize common keys
s.get_translator(KEY_ONE)
s.get_translator(KEY_NEW)
s.get_translator(KEY_OLD)
utils.args.main(s)
utils.logger.info('total number of queries: %s' % s.nqueries)
if utils.args.ipython:
ipython(s)
sys.exit(1 if utils.error_count > 0 else 0)
def find_predecessor_from_src_phase(
self, t: syntax.Z3Translator, pre_frame: Frame, src_phase: Phase,
transitions: Sequence[PhaseTransition], diag: Diagram,
core: Optional[MySet[int]]
) -> Tuple[z3.CheckSatResult, Optional[Tuple[PhaseTransition, Tuple[
Phase, Diagram]]]]:
prog = syntax.the_program
solver = self.solver
with solver:
for f in pre_frame.summary_of(src_phase):
solver.add(t.translate_expr(f, old=True))
for phase_transition in transitions:
delta = phase_transition.transition_decl()
trans = prog.scope.get_definition(delta.transition)
assert trans is not None
precond = delta.precond
with utils.LogTag(utils.logger,
'find-pred',
transition=delta.transition,
weight=str(
phase_transition.avg_time_traversing())):
with solver:
solver.add(
t.translate_transition(trans, precond=precond))
before_check = datetime.now()
res = solver.check(diag.trackers)
phase_transition.time_spent_traversing += (
datetime.now() - before_check).total_seconds()
phase_transition.count_traversed += 1
if res != z3.unsat:
utils.logger.debug('found predecessor via %s' %
trans.name)
m = Trace.from_z3([KEY_OLD, KEY_NEW],
solver.model(diag.trackers))
# if utils.logger.isEnabledFor(logging.DEBUG):
# utils.logger.debug(str(m))
self.record_state(m)
return (res, (phase_transition,
(src_phase, m.as_diagram(i=0))))
elif utils.args.use_z3_unsat_cores:
assert core is not None
uc = solver.unsat_core()
# if utils.logger.isEnabledFor(logging.DEBUG):
# utils.logger.debug('uc')
# utils.logger.debug(str(sorted(uc, key=lambda y: y.decl().name())))
# utils.logger.debug('assertions')
# utils.logger.debug(str(solver.assertions()))
res = solver.check(
[diag.trackers[i] for i in core])
if res == z3.unsat:
utils.logger.debug(
'but existing core sufficient, skipping')
continue
for x in sorted(uc, key=lambda y: y.decl().name()):
assert isinstance(x, z3.ExprRef)
core.add(int(x.decl().name()[1:]))
if utils.logger.isEnabledFor(logging.DEBUG):
utils.logger.debug('new core')
utils.logger.debug(str(sorted(core)))
return (z3.unsat, None)
def block(self,
diag: Diagram,
j: int,
p: Phase,
trace: Optional[RelaxedTrace] = None,
safety_goal: bool = True) -> Union[Blocked, CexFound]:
if trace is None:
trace = []
if j == 0 or (j == 1 and self.valid_in_initial_frame(
self.solver, p, diag) is not None):
if safety_goal:
utils.logger.always_print('\n'.join(
((t.pp() + ' ') if t is not None else '') + str(diag)
for t, diag in trace))
print(
'abstract counterexample: the system has no universal inductive invariant proving safety'
)
# TODO: placeholder for analyzing relaxed trace
# import relaxed_traces
# print(relaxed_traces.diagram_trace_to_explicitly_relaxed_trace(trace, phases.phase_safety(p)))
if utils.args.checkpoint_out:
self.store_frames(utils.args.checkpoint_out)
raise AbstractCounterexample()
else:
if utils.logger.isEnabledFor(logging.DEBUG):
utils.logger.debug('failed to block diagram')
return CexFound()
while True:
with utils.LogTag(utils.logger, 'block-attempt'):
if utils.logger.isEnabledFor(logging.DEBUG):
utils.logger.debug('blocking diagram in frame %s' % j)
utils.logger.debug(str(diag))
self.print_frame(j - 1, lvl=logging.DEBUG)
res, x = self.find_predecessor(self[j - 1], p, diag)
if res == z3.unsat:
utils.logger.debug('no predecessor: blocked!')
assert x is None or isinstance(x, MySet)
core: Optional[MySet[int]] = x
self.augment_core_for_init(p, diag, core)
break
assert isinstance(x, tuple), (res, x)
trans, (pre_phase, pre_diag) = x
trace.append((trans, pre_diag))
ans = self.block(pre_diag, j - 1, pre_phase, trace,
safety_goal)
if not isinstance(ans, Blocked):
return ans
trace.pop()
if utils.logger.isEnabledFor(logging.DEBUG) and core is not None:
utils.logger.debug('core %s' % core)
utils.logger.debug('unminimized diag\n%s' % diag)
diag.minimize_from_core(core)
diag.generalize(self.solver, self[j - 1],
self.automaton.transitions_to_grouped_by_src(p),
p == self.automaton.init_phase(), j)
e = syntax.Not(diag.to_ast())
if utils.logger.isEnabledFor(logging.DEBUG):
utils.logger.debug(
'adding new clause to frames 0 through %d phase %s' %
(j, p.name()))
if utils.logger.isEnabledFor(logging.INFO):
utils.logger.info("[%d] %s" % (j, str(e)))
self.add(p, e, j)
utils.logger.debug("Done blocking")
return Blocked()
def push_conjunct(self,
frame_no: int,
c: Expr,
p: Phase,
frame_old_count: Optional[int] = None) -> None:
is_safety = c in phases.phase_safety(p)
f = self.fs[frame_no]
while True:
with utils.LogTag(utils.logger,
'pushing-conjunct-attempt',
lvl=logging.DEBUG,
frame=str(frame_no),
conj=str(c)):
utils.logger.debug('frame %s phase %s attempting to push %s' %
(frame_no, p.name(), c))
res = self.clause_implied_by_transitions_from_frame(
f, p, c, minimize=is_safety or utils.args.block_may_cexs)
if res is None:
utils.logger.debug('frame %s phase %s managed to push %s' %
(frame_no, p.name(), c))
if utils.args.smoke_test and utils.logger.isEnabledFor(
logging.DEBUG):
utils.logger.debug('smoke testing...')
# TODO: phases
logic.check_bmc(self.solver, c, frame_no + 1)
# assert self.clause_implied_by_transitions_from_frame(f, p, c) is None
self[frame_no + 1].strengthen(p, c)
self.debug_assert_inductive_trace()
break
pre_phase, (m, t) = res
mod = Trace.from_z3([KEY_OLD, KEY_NEW], m)
self.record_state(mod)
diag = mod.as_diagram(i=0)
if utils.logger.isEnabledFor(logging.DEBUG):
utils.logger.debug(
'frame %s failed to immediately push %s due to '
'transition %s' % (frame_no, c, t.pp()))
# utils.logger.debug(str(mod))
if is_safety:
utils.logger.debug(
'note: current clause is safety condition')
self.block(diag,
frame_no,
pre_phase, [(None, c), (t, diag)],
safety_goal=True)
else:
if utils.args.block_may_cexs:
ans = self.block(diag,
frame_no,
pre_phase, [(None, c), (t, diag)],
safety_goal=False)
if isinstance(ans, CexFound):
break
else:
break
def block(self,
diag: Diagram,
j: int,
p: Phase,
trace: Optional[List[Tuple[Optional[PhaseTransition],
Union[Diagram, Expr]]]] = None,
safety_goal: bool = True) -> Union[Blocked, CexFound]:
if trace is None:
trace = []
if j == 0 or (j == 1 and self.valid_in_initial_frame(
self.solver, p, diag) is not None):
if safety_goal:
utils.logger.always_print('\n'.join(
((t.pp() + ' ') if t is not None else '') + str(diag)
for t, diag in trace))
print('abstract counterexample')
raise Exception('abstract counterexample')
else:
if utils.logger.isEnabledFor(logging.DEBUG):
utils.logger.debug('failed to block diagram')
# utils.logger.debug(str(diag))
return CexFound()
# print fs
while True:
with utils.LogTag(utils.logger, 'block-attempt'):
if utils.logger.isEnabledFor(logging.DEBUG):
utils.logger.debug('blocking diagram in frame %s' % j)
utils.logger.debug(str(diag))
self.print_frame(j - 1, lvl=logging.DEBUG)
res, x = self.find_predecessor(self[j - 1], p, diag)
if res == z3.unsat:
utils.logger.debug('no predecessor: blocked!')
assert x is None or isinstance(x, MySet)
core: Optional[MySet[int]] = x
self.augment_core_for_init(p, diag, core)
break
assert isinstance(x, tuple), (res, x)
trans, (pre_phase, pre_diag) = x
trace.append((trans, pre_diag))
ans = self.block(pre_diag, j - 1, pre_phase, trace,
safety_goal)
if not isinstance(ans, Blocked):
return ans
trace.pop()
if utils.logger.isEnabledFor(logging.DEBUG) and core is not None:
utils.logger.debug('core %s' % core)
utils.logger.debug('unminimized diag\n%s' % diag)
diag.minimize_from_core(core)
diag.generalize(self.solver, self[j - 1],
self.automaton.transitions_to_grouped_by_src(p),
p == self.automaton.init_phase(), j)
e = syntax.Not(diag.to_ast())
if utils.logger.isEnabledFor(logging.DEBUG):
utils.logger.debug(
'adding new clause to frames 0 through %d phase %s' %
(j, p.name()))
if utils.logger.isEnabledFor(logging.INFO):
utils.logger.info("[%d] %s" % (j, str(e)))
self.add(p, e, j)
utils.logger.debug("Done blocking")
return Blocked()
