Mercurial > code > home > repos > homeauto

comparison service/mqtt_to_rdf/inference.py @ 1694:73abfd4cf5d0

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
new html log and other refactoring as i work on the advanceTheStack problems https://bigasterisk.com/post/inference/2021-09-27_11-11.png
author drewp@bigasterisk.com
date Mon, 27 Sep 2021 11:22:09 -0700
parents 0455a1e18e4f
children 5c2565e63297
comparison
equal deleted inserted replaced
1693:0455a1e18e4f 1694:73abfd4cf5d0
6 import logging 6 import logging
7 import time 7 import time
8 from collections import defaultdict 8 from collections import defaultdict
9 from dataclasses import dataclass 9 from dataclasses import dataclass
10 from typing import Dict, Iterator, List, Optional, Tuple, Union, cast 10 from typing import Dict, Iterator, List, Optional, Tuple, Union, cast
11 from pathlib import Path
11 12
12 from prometheus_client import Histogram, Summary 13 from prometheus_client import Histogram, Summary
13 from rdflib import Graph, Namespace 14 from rdflib import Graph, Namespace
14 from rdflib.graph import ConjunctiveGraph 15 from rdflib.graph import ConjunctiveGraph
15 from rdflib.term import Node, URIRef, Variable 16 from rdflib.term import Node, URIRef, Variable
16 17
17 from candidate_binding import BindingConflict, CandidateBinding 18 from candidate_binding import CandidateBinding
18 from inference_types import (BindingUnknown, Inconsistent, RhsBnode, RuleOutBnode, RuleUnboundBnode, Triple, WorkingSetBnode) 19 from inference_types import (BindingUnknown, Inconsistent, RhsBnode, RuleUnboundBnode, Triple, WorkingSetBnode)
19 from lhs_evaluation import functionsFor 20 from lhs_evaluation import functionsFor
20 from rdf_debug import graphDump 21 from rdf_debug import graphDump
21 from stmt_chunk import AlignedRuleChunk, Chunk, ChunkedGraph, applyChunky 22 from stmt_chunk import AlignedRuleChunk, Chunk, ChunkedGraph, applyChunky
23 from structured_log import StructuredLog
22 24
23 log = logging.getLogger('infer') 25 log = logging.getLogger('infer')
24 odolog = logging.getLogger('infer.odo') # the "odometer" logic 26 odolog = logging.getLogger('infer.odo') # the "odometer" logic
25 ringlog = logging.getLogger('infer.ring') # for ChunkLooper 27 ringlog = logging.getLogger('infer.ring') # for ChunkLooper
26 28
34 MATH = Namespace('http://www.w3.org/2000/10/swap/math#') 36 MATH = Namespace('http://www.w3.org/2000/10/swap/math#')
35 37
36 38
37 class NoOptions(ValueError): 39 class NoOptions(ValueError):
38 """ChunkLooper has no possibilites to add to the binding; the whole rule must therefore not apply""" 40 """ChunkLooper has no possibilites to add to the binding; the whole rule must therefore not apply"""
41
42
43 def debug(logger, slog: Optional[StructuredLog], msg):
44 logger.debug(msg)
45 if slog:
46 slog.say(msg)
39 47
40 48
41 _chunkLooperShortId = itertools.count() 49 _chunkLooperShortId = itertools.count()
42 50
43 51
51 59
52 This iterator is restartable.""" 60 This iterator is restartable."""
53 lhsChunk: Chunk 61 lhsChunk: Chunk
54 prev: Optional['ChunkLooper'] 62 prev: Optional['ChunkLooper']
55 workingSet: 'ChunkedGraph' 63 workingSet: 'ChunkedGraph'
64 slog: Optional[StructuredLog]
56 65
57 def __repr__(self): 66 def __repr__(self):
58 return f'{self.__class__.__name__}{self._shortId}{"<pastEnd>" if self.pastEnd() else ""}' 67 return f'{self.__class__.__name__}{self._shortId}{"<pastEnd>" if self.pastEnd() else ""}'
59 68
60 def __post_init__(self): 69 def __post_init__(self):
61 self._shortId = next(_chunkLooperShortId) 70 self._shortId = next(_chunkLooperShortId)
62 self._alignedMatches = list(self.lhsChunk.ruleMatchesFrom(self.workingSet)) 71 self._alignedMatches = list(self.lhsChunk.ruleMatchesFrom(self.workingSet))
72 del self.workingSet
63 73
64 # only ours- do not store prev, since it could change without us 74 # only ours- do not store prev, since it could change without us
65 self._current = CandidateBinding({}) 75 self._current = CandidateBinding({})
76 self.currentSourceChunk: Optional[Chunk] = None # for debugging only
66 self._pastEnd = False 77 self._pastEnd = False
67 self._seenBindings: List[CandidateBinding] = [] # combined bindings (up to our ring) that we've returned 78 self._seenBindings: List[CandidateBinding] = [] # combined bindings (up to our ring) that we've returned
68 79
69 if ringlog.isEnabledFor(logging.DEBUG): 80 if ringlog.isEnabledFor(logging.DEBUG):
70 ringlog.debug('') 81 ringlog.debug('')
71 ringlog.debug(f'{INDENT*6} introducing {self!r}({self.lhsChunk}, {self._alignedMatches=})') 82 msg = f'{INDENT*6} introducing {self!r}({self.lhsChunk}, {self._alignedMatches=})'
83 msg = msg.replace('AlignedRuleChunk', f'\n{INDENT*12}AlignedRuleChunk')
84 ringlog.debug(msg)
72 85
73 self.restart() 86 self.restart()
74 87
75 def _prevBindings(self) -> CandidateBinding: 88 def _prevBindings(self) -> CandidateBinding:
76 if not self.prev or self.prev.pastEnd(): 89 if not self.prev or self.prev.pastEnd():
83 last restart), or go into pastEnd mode. Note that _current is just our 96 last restart), or go into pastEnd mode. Note that _current is just our
84 contribution, but returned valid bindings include all prev rings.""" 97 contribution, but returned valid bindings include all prev rings."""
85 if self._pastEnd: 98 if self._pastEnd:
86 raise NotImplementedError('need restart') 99 raise NotImplementedError('need restart')
87 ringlog.debug('') 100 ringlog.debug('')
101 debug(ringlog, self.slog, f'{INDENT*6} --> {self}.advance start:')
102
88 self._currentIsFromFunc = None 103 self._currentIsFromFunc = None
89 augmentedWorkingSet: List[AlignedRuleChunk] = [] 104 augmentedWorkingSet: List[AlignedRuleChunk] = []
90 if self.prev is None: 105 if self.prev is None:
91 augmentedWorkingSet = self._alignedMatches 106 augmentedWorkingSet = self._alignedMatches
92 else: 107 else:
93 augmentedWorkingSet = list(applyChunky(self.prev.currentBinding(), self._alignedMatches)) 108 augmentedWorkingSet = list(applyChunky(self.prev.currentBinding(), self._alignedMatches))
94 109
95 if self._advanceWithPlainMatches(augmentedWorkingSet): 110 if self._advanceWithPlainMatches(augmentedWorkingSet):
96 ringlog.debug(f'{INDENT*6} <-- {self}.advance finished with plain matches') 111 debug(ringlog, self.slog, f'{INDENT*6} <-- {self}.advance finished with plain matches')
97 return 112 return
98 113
99 if self._advanceWithFunctions(): 114 if self._advanceWithFunctions():
100 ringlog.debug(f'{INDENT*6} <-- {self}.advance finished with function matches') 115 debug(ringlog, self.slog, f'{INDENT*6} <-- {self}.advance finished with function matches')
101 return 116 return
102 117
103 ringlog.debug(f'{INDENT*6} <-- {self}.advance had nothing and is now past end') 118 debug(ringlog, self.slog, f'{INDENT*6} <-- {self}.advance had nothing and is now past end')
104 self._pastEnd = True 119 self._pastEnd = True
105 120
106 def _advanceWithPlainMatches(self, augmentedWorkingSet: List[AlignedRuleChunk]) -> bool: 121 def _advanceWithPlainMatches(self, augmentedWorkingSet: List[AlignedRuleChunk]) -> bool:
107 ringlog.debug(f'{INDENT*7} {self} mines {len(augmentedWorkingSet)} matching augmented statements') 122 # if augmentedWorkingSet:
108 for s in augmentedWorkingSet: 123 # debug(ringlog, self.slog, f'{INDENT*7} {self} mines {len(augmentedWorkingSet)} matching augmented statements')
109 ringlog.debug(f'{INDENT*8} {s}') 124 # for s in augmentedWorkingSet:
125 # debug(ringlog, self.slog, f'{INDENT*8} {s}')
110 126
111 for aligned in augmentedWorkingSet: 127 for aligned in augmentedWorkingSet:
112 try: 128 try:
113 newBinding = aligned.newBindingIfMatched(self._prevBindings()) 129 newBinding = aligned.newBindingIfMatched(self._prevBindings())
114 except Inconsistent as exc: 130 except Inconsistent as exc:
115 ringlog.debug( 131 debug(ringlog, self.slog,
116 f'{INDENT*7} ChunkLooper{self._shortId} - {aligned} would be inconsistent with prev bindings ({exc})') 132 f'{INDENT*7} ChunkLooper{self._shortId} - {aligned} would be inconsistent with prev bindings ({exc})')
117 continue 133 continue
118 134
119 if self._testAndKeepNewBinding(newBinding): 135 if self._testAndKeepNewBinding(newBinding, aligned.workingSetChunk):
120 return True 136 return True
121 return False 137 return False
122 138
123 def _advanceWithFunctions(self) -> bool: 139 def _advanceWithFunctions(self) -> bool:
124 pred: Node = self.lhsChunk.predicate 140 pred: Node = self.lhsChunk.predicate
125 if not isinstance(pred, URIRef): 141 if not isinstance(pred, URIRef):
126 raise NotImplementedError 142 raise NotImplementedError
127 143
128 ringlog.debug(f'{INDENT*6} advanceWithFunctions {pred!r}')
129
130 for functionType in functionsFor(pred): 144 for functionType in functionsFor(pred):
131 fn = functionType(self.lhsChunk) 145 fn = functionType(self.lhsChunk)
132 ringlog.debug(f'{INDENT*7} ChunkLooper{self._shortId} advanceWithFunctions, {functionType=}') 146 # debug(ringlog, self.slog, f'{INDENT*7} ChunkLooper{self._shortId} advanceWithFunctions, {functionType=}')
133 147
134 try: 148 try:
135 log.debug(f'fn.bind {self._prevBindings()} ...') 149 log.debug(f'fn.bind {self._prevBindings()} ...')
136 #fullBinding = self._prevBindings().copy() 150 #fullBinding = self._prevBindings().copy()
137 newBinding = fn.bind(self._prevBindings()) 151 newBinding = fn.bind(self._prevBindings())
139 except BindingUnknown: 153 except BindingUnknown:
140 pass 154 pass
141 else: 155 else:
142 if newBinding is not None: 156 if newBinding is not None:
143 self._currentIsFromFunc = fn 157 self._currentIsFromFunc = fn
144 if self._testAndKeepNewBinding(newBinding): 158 if self._testAndKeepNewBinding(newBinding, self.lhsChunk):
145 return True 159 return True
146 160
147 return False 161 return False
148 162
149 def _testAndKeepNewBinding(self, newBinding: CandidateBinding): 163 def _testAndKeepNewBinding(self, newBinding: CandidateBinding, sourceChunk: Chunk):
150 fullBinding: CandidateBinding = self._prevBindings().copy() 164 fullBinding: CandidateBinding = self._prevBindings().copy()
151 fullBinding.addNewBindings(newBinding) 165 fullBinding.addNewBindings(newBinding)
152 isNew = fullBinding not in self._seenBindings 166 isNew = fullBinding not in self._seenBindings
153 ringlog.debug(f'{INDENT*7} {self} considering {newBinding=} to make {fullBinding}. {isNew=}') 167 ringlog.debug(f'{INDENT*7} {self} considering {newBinding=} to make {fullBinding}. {isNew=}')
168 # if self.slog:
169 # self.slog.looperConsider(self, newBinding, fullBinding, isNew)
170
154 if isNew: 171 if isNew:
155 self._seenBindings.append(fullBinding.copy()) 172 self._seenBindings.append(fullBinding.copy())
156 self._current = newBinding 173 self._current = newBinding
174 self.currentSourceChunk = sourceChunk
157 return True 175 return True
158 return False 176 return False
159 177
160 def _boundOperands(self, operands) -> List[Node]: 178 def localBinding(self) -> CandidateBinding:
161 pb: CandidateBinding = self._prevBindings() 179 if self.pastEnd():
162 180 raise NotImplementedError()
163 boundOperands: List[Node] = [] 181 return self._current
164 for op in operands:
165 if isinstance(op, (Variable, RuleUnboundBnode)):
166 boundOperands.append(pb.applyTerm(op))
167 else:
168 boundOperands.append(op)
169 return boundOperands
170 182
171 def currentBinding(self) -> CandidateBinding: 183 def currentBinding(self) -> CandidateBinding:
172 if self.pastEnd(): 184 if self.pastEnd():
173 raise NotImplementedError() 185 raise NotImplementedError()
174 together = self._prevBindings().copy() 186 together = self._prevBindings().copy()
177 189
178 def pastEnd(self) -> bool: 190 def pastEnd(self) -> bool:
179 return self._pastEnd 191 return self._pastEnd
180 192
181 def restart(self): 193 def restart(self):
182 self._pastEnd = False 194 try:
183 self._seenBindings = [] 195 self._pastEnd = False
184 self.advance() 196 self._seenBindings = []
185 if self.pastEnd(): 197 self.advance()
186 raise NoOptions() 198 if self.pastEnd():
199 raise NoOptions()
200 finally:
201 debug(ringlog, self.slog, f'{INDENT*7} ChunkLooper{self._shortId} restarts: pastEnd={self.pastEnd()}')
187 202
188 def prevMayHaveChanged(self): 203 def prevMayHaveChanged(self):
204 pass
205 # self._advanceWithFunctions()
189 # This is a total patch for a test failure. This should be generalized 206 # This is a total patch for a test failure. This should be generalized
190 # to a Looper that can keep itself correct when prev changes. 207 # to a Looper that can keep itself correct when prev changes.
191 if self._currentIsFromFunc: 208 # if self.pastEnd():
192 self._advanceWithFunctions() 209 # self.restart()
193 if self.pastEnd(): 210 # else:
194 self.restart() 211 # self.advance()
212 # if self._currentIsFromFunc:
213 # self._advanceWithFunctions()
214 # if self.pastEnd():
215 # self.restart()
195 216
196 217
197 @dataclass 218 @dataclass
198 class Lhs: 219 class Lhs:
199 graph: ChunkedGraph # our full LHS graph, as input. See below for the statements partitioned into groups. 220 graph: ChunkedGraph # our full LHS graph, as input. See below for the statements partitioned into groups.
202 223
203 self.myPreds = self.graph.allPredicatesExceptFunctions() 224 self.myPreds = self.graph.allPredicatesExceptFunctions()
204 225
205 def __repr__(self): 226 def __repr__(self):
206 return f"Lhs({self.graph!r})" 227 return f"Lhs({self.graph!r})"
207 228 def findCandidateBindings(self, knownTrue: ChunkedGraph, stats, slog: Optional[StructuredLog],
208 def findCandidateBindings(self, knownTrue: ChunkedGraph, stats, ruleStatementsIterationLimit) -> Iterator['BoundLhs']: 229 ruleStatementsIterationLimit) -> Iterator['BoundLhs']:
209 """distinct bindings that fit the LHS of a rule, using statements from 230 """distinct bindings that fit the LHS of a rule, using statements from
210 workingSet and functions from LHS""" 231 workingSet and functions from LHS"""
211 if not self.graph: 232 if not self.graph:
212 # special case- no LHS! 233 # special case- no LHS!
213 yield BoundLhs(self, CandidateBinding({})) 234 yield BoundLhs(self, CandidateBinding({}))
227 yield BoundLhs(self, CandidateBinding({})) 248 yield BoundLhs(self, CandidateBinding({}))
228 return 249 return
229 250
230 log.debug('') 251 log.debug('')
231 try: 252 try:
232 chunkStack = self._assembleRings(knownTrue, stats) 253 chunkStack = self._assembleRings(knownTrue, stats, slog)
233 except NoOptions: 254 except NoOptions:
234 ringlog.debug(f'{INDENT*5} start up with no options; 0 bindings') 255 ringlog.debug(f'{INDENT*5} start up with no options; 0 bindings')
235 return 256 return
236 log.debug('') 257 log.debug('')
237 log.debug('') 258 log.debug('')
238 self._debugChunkStack('time to spin: initial odometer is', chunkStack) 259 self._debugChunkStack('time to spin: initial odometer is', chunkStack)
260
261 if slog:
262 slog.say('time to spin')
263 slog.odometer(chunkStack)
239 self._assertAllRingsAreValid(chunkStack) 264 self._assertAllRingsAreValid(chunkStack)
240 265
241 lastRing = chunkStack[-1] 266 lastRing = chunkStack[-1]
242 iterCount = 0 267 iterCount = 0
243 while True: 268 while True:
252 # self._debugChunkStack('odometer', chunkStack) 277 # self._debugChunkStack('odometer', chunkStack)
253 278
254 done = self._advanceTheStack(chunkStack) 279 done = self._advanceTheStack(chunkStack)
255 280
256 self._debugChunkStack(f'odometer after ({done=})', chunkStack) 281 self._debugChunkStack(f'odometer after ({done=})', chunkStack)
282 if slog:
283 slog.odometer(chunkStack)
257 284
258 log.debug(f'{INDENT*4} ^^ findCandBindings iteration done') 285 log.debug(f'{INDENT*4} ^^ findCandBindings iteration done')
259 if done: 286 if done:
260 break 287 break
261 288
262 def _debugChunkStack(self, label: str, chunkStack: List[ChunkLooper]): 289 def _debugChunkStack(self, label: str, chunkStack: List[ChunkLooper]):
263 odolog.debug(f'{INDENT*4} {label}:') 290 odolog.debug(f'{INDENT*4} {label}:')
264 for i, l in enumerate(chunkStack): 291 for i, l in enumerate(chunkStack):
265 odolog.debug(f'{INDENT*5} [{i}] {l} curbind={l.currentBinding() if not l.pastEnd() else "<end>"}') 292 odolog.debug(f'{INDENT*5} [{i}] {l} curbind={l.localBinding() if not l.pastEnd() else "<end>"}')
266 293
267 def _checkPredicateCounts(self, knownTrue): 294 def _checkPredicateCounts(self, knownTrue):
268 """raise NoOptions quickly in some cases""" 295 """raise NoOptions quickly in some cases"""
269 296
270 if self.graph.noPredicatesAppear(self.myPreds): 297 if self.graph.noPredicatesAppear(self.myPreds):
271 log.debug(f'{INDENT*3} checkPredicateCounts does cull because not all {self.myPreds=} are in knownTrue') 298 log.debug(f'{INDENT*3} checkPredicateCounts does cull because not all {self.myPreds=} are in knownTrue')
272 return True 299 return True
273 log.debug(f'{INDENT*3} checkPredicateCounts does not cull because all {self.myPreds=} are in knownTrue') 300 log.debug(f'{INDENT*3} checkPredicateCounts does not cull because all {self.myPreds=} are in knownTrue')
274 return False 301 return False
275 302
276 def _assembleRings(self, knownTrue: ChunkedGraph, stats) -> List[ChunkLooper]: 303 def _assembleRings(self, knownTrue: ChunkedGraph, stats, slog) -> List[ChunkLooper]:
277 """make ChunkLooper for each stmt in our LHS graph, but do it in a way that they all 304 """make ChunkLooper for each stmt in our LHS graph, but do it in a way that they all
278 start out valid (or else raise NoOptions). static chunks have already been confirmed.""" 305 start out valid (or else raise NoOptions). static chunks have already been confirmed."""
279 306
280 log.debug(f'{INDENT*4} stats={dict(stats)}') 307 log.debug(f'{INDENT*4} stats={dict(stats)}')
281 odolog.debug(f'{INDENT*3} build new ChunkLooper stack') 308 odolog.debug(f'{INDENT*3} build new ChunkLooper stack')
295 for ruleChunk in perm: 322 for ruleChunk in perm:
296 try: 323 try:
297 # These are getting rebuilt a lot which takes time. It would 324 # These are getting rebuilt a lot which takes time. It would
298 # be nice if they could accept a changing `prev` order 325 # be nice if they could accept a changing `prev` order
299 # (which might already be ok). 326 # (which might already be ok).
300 looper = ChunkLooper(ruleChunk, prev, knownTrue) 327 looper = ChunkLooper(ruleChunk, prev, knownTrue, slog)
301 except NoOptions: 328 except NoOptions:
302 odolog.debug(f'{INDENT*5} permutation didnt work, try another') 329 odolog.debug(f'{INDENT*5} permutation didnt work, try another')
303 break 330 break
304 looperRings.append(looper) 331 looperRings.append(looper)
305 prev = looperRings[-1] 332 prev = looperRings[-1]
389 p = RhsBnode(p) 416 p = RhsBnode(p)
390 if isinstance(o, BNode): 417 if isinstance(o, BNode):
391 o = RhsBnode(o) 418 o = RhsBnode(o)
392 self.rhsGraphConvert.append((s, p, o)) 419 self.rhsGraphConvert.append((s, p, o))
393 420
394 def applyRule(self, workingSet: Graph, implied: Graph, stats: Dict, ruleStatementsIterationLimit): 421 def applyRule(self, workingSet: Graph, implied: Graph, stats: Dict, slog: Optional[StructuredLog],
422 ruleStatementsIterationLimit):
395 # this does not change for the current applyRule call. The rule will be 423 # this does not change for the current applyRule call. The rule will be
396 # tried again in an outer loop, in case it can produce more. 424 # tried again in an outer loop, in case it can produce more.
397 workingSetChunked = ChunkedGraph(workingSet, WorkingSetBnode, functionsFor) 425 workingSetChunked = ChunkedGraph(workingSet, WorkingSetBnode, functionsFor)
398 426
399 for bound in self.lhs.findCandidateBindings(workingSetChunked, stats, ruleStatementsIterationLimit): 427 for bound in self.lhs.findCandidateBindings(workingSetChunked, stats, slog, ruleStatementsIterationLimit):
428 if slog:
429 slog.foundBinding(bound)
400 log.debug(f'{INDENT*5} +rule has a working binding: {bound}') 430 log.debug(f'{INDENT*5} +rule has a working binding: {bound}')
401 431
402 newStmts = self.generateImpliedFromRhs(bound.binding) 432 newStmts = self.generateImpliedFromRhs(bound.binding)
403 433
404 for newStmt in newStmts: 434 for newStmt in newStmts:
457 487
458 def nonRuleStatements(self) -> List[Triple]: 488 def nonRuleStatements(self) -> List[Triple]:
459 return self._nonRuleStmts 489 return self._nonRuleStmts
460 490
461 @INFER_CALLS.time() 491 @INFER_CALLS.time()
462 def infer(self, graph: Graph): 492 def infer(self, graph: Graph, htmlLog: Optional[Path] = None):
463 """ 493 """
464 returns new graph of inferred statements. 494 returns new graph of inferred statements.
465 """ 495 """
466 n = graph.__len__() 496 n = graph.__len__()
467 INFER_GRAPH_SIZE.observe(n) 497 INFER_GRAPH_SIZE.observe(n)
475 workingSet += graph 505 workingSet += graph
476 506
477 # just the statements that came from RHS's of rules that fired. 507 # just the statements that came from RHS's of rules that fired.
478 implied = ConjunctiveGraph() 508 implied = ConjunctiveGraph()
479 509
510 slog = StructuredLog(htmlLog) if htmlLog else None
511
480 rulesIterations = 0 512 rulesIterations = 0
481 delta = 1 513 delta = 1
482 stats['initWorkingSet'] = cast(int, workingSet.__len__()) 514 stats['initWorkingSet'] = cast(int, workingSet.__len__())
515 if slog:
516 slog.workingSet = workingSet
517
483 while delta > 0: 518 while delta > 0:
484 log.debug('') 519 log.debug('')
485 log.info(f'{INDENT*1}*iteration {rulesIterations}') 520 log.info(f'{INDENT*1}*iteration {rulesIterations}')
521 if slog:
522 slog.startIteration(rulesIterations)
486 523
487 delta = -len(implied) 524 delta = -len(implied)
488 self._iterateAllRules(workingSet, implied, stats) 525 self._iterateAllRules(workingSet, implied, stats, slog)
489 delta += len(implied) 526 delta += len(implied)
490 rulesIterations += 1 527 rulesIterations += 1
491 log.info(f'{INDENT*2} this inference iteration added {delta} more implied stmts') 528 log.info(f'{INDENT*2} this inference iteration added {delta} more implied stmts')
492 if rulesIterations >= self.rulesIterationLimit: 529 if rulesIterations >= self.rulesIterationLimit:
493 raise ValueError(f"rule too complex after {rulesIterations=}") 530 raise ValueError(f"rule too complex after {rulesIterations=}")
495 stats['timeSpent'] = round(time.time() - startTime, 3) 532 stats['timeSpent'] = round(time.time() - startTime, 3)
496 stats['impliedStmts'] = len(implied) 533 stats['impliedStmts'] = len(implied)
497 log.info(f'{INDENT*0} Inference done {dict(stats)}.') 534 log.info(f'{INDENT*0} Inference done {dict(stats)}.')
498 log.debug('Implied:') 535 log.debug('Implied:')
499 log.debug(graphDump(implied)) 536 log.debug(graphDump(implied))
537
538 if slog:
539 slog.render()
540 log.info(f'wrote {htmlLog}')
541
500 return implied 542 return implied
501 543
502 def _iterateAllRules(self, workingSet: Graph, implied: Graph, stats): 544 def _iterateAllRules(self, workingSet: Graph, implied: Graph, stats, slog: Optional[StructuredLog]):
503 for i, rule in enumerate(self.rules): 545 for i, rule in enumerate(self.rules):
504 self._logRuleApplicationHeader(workingSet, i, rule) 546 self._logRuleApplicationHeader(workingSet, i, rule)
505 rule.applyRule(workingSet, implied, stats, self.ruleStatementsIterationLimit) 547 if slog:
548 slog.rule(workingSet, i, rule)
549 rule.applyRule(workingSet, implied, stats, slog, self.ruleStatementsIterationLimit)
506 550
507 def _logRuleApplicationHeader(self, workingSet, i, r: Rule): 551 def _logRuleApplicationHeader(self, workingSet, i, r: Rule):
508 if not log.isEnabledFor(logging.DEBUG): 552 if not log.isEnabledFor(logging.DEBUG):
509 return 553 return
510 554