legoavengers upstream error

[sei-eschwartz]

I left the original run that was not making any progress going, and it just terminated. Unfortunately, in an error, but I guess that is still progress. We managed to get to:

Entering stage guessConstructor.

Here is the end of the log:

Guessing factConstructor(0xea3830).
There are 18,841,035 known facts.
reasoningLoop: pre-reason sanityChecks
Constraint checks succeeded, proceeding to reason forward!
reasoningLoop: reasonForardAsManyTimesAsPossible
Starting reasonForward.
Concluding factVFTableOverwrite(0xea3830, 0x1842010, 0x1842170, 0x3c).
Concluding factVFTableOverwrite(0xea3830, 0x1842010, 0x1980a5c, 0x3c).
Concluding factVFTableOverwrite(0xea3830, 0x1842188, 0x1980a74, 0x8).
Concluding factVFTableOverwrite(0xea3830, 0x1842170, 0x1980a5c, 0x3c).
Concluding factVFTableOverwrite(0xea3830, 0x1842194, 0x1980a7c, 0).
Starting reasonForward.
Concluding factClassSizeLTE(0xea3830, 0xfffffff).
Starting reasonForward.
Concluding mergeVFTables(0x1980a5c, 0xea3830).
Merging class 0xea3830 into 0x1980a5c ...
Retracting factClassCallsMethod(0xea3830, 0x7ff080) and asserting factClassCallsMethod(0x1980a5c, 0x7ff080) ...
Retracting factClassCallsMethod(0xea3830, 0xbd1b70) and asserting factClassCallsMethod(0x1980a5c, 0xbd1b70) ...
Retracting factClassCallsMethod(0xea3830, 0x11cbce0) and asserting factClassCallsMethod(0x1980a5c, 0x11cbce0) ...
Retracting factClassRelatedMethod(0xea3830, 0x7ff080) and asserting factClassRelatedMethod(0x1980a5c, 0x7ff080) ...
Retracting factClassRelatedMethod(0xea3830, 0xbd1b70) and asserting factClassRelatedMethod(0x1980a5c, 0xbd1b70) ...
Retracting factClassRelatedMethod(0xea3830, 0x11cbce0) and asserting factClassRelatedMethod(0x1980a5c, 0x11cbce0) ...
Retracting factClassSizeGTE(0xea3830, 0x5c) and asserting factClassSizeGTE(0x1980a5c, 0x5c) ...
Retracting factClassSizeLTE(0xea3830, 0xfffffff) and asserting factClassSizeLTE(0x1980a5c, 0xfffffff) ...
Retracting factNOTMergeClasses(0xea3830, 0x1864e48) and asserting factNOTMergeClasses(0x1980a5c, 0x1864e48) ...
Retracting factNOTMergeClasses(0xea3830, 0x1864ea8) and asserting factNOTMergeClasses(0x1980a5c, 0x1864ea8) ...
Retracting factNOTMergeClasses(0x18959dc, 0xea3830) and asserting factNOTMergeClasses(0x18959dc, 0x1980a5c) ...
Starting reasonForward.
Concluding factVFTableSizeGTE(0x1987164, 0x1b4).
Starting reasonForward.
Concluding factVFTableSizeGTE(0x1987620, 0x1b4).
Concluding factVFTableSizeGTE(0x1987608, 0x1b4).
Starting reasonForward.
Concluding factVFTableSizeLTE(0x1980a7c, 0x1bc).
Concluding factVFTableSizeLTE(0x1980a7c, 0x1d0).
Starting reasonForward.
Concluding factClassSizeGTE(0x1982384, 0x5c).
Concluding factClassSizeGTE(0x198332c, 0x5c).
Concluding factClassSizeGTE(0x1982854, 0x5c).
Concluding factClassSizeGTE(0x1982a14, 0x5c).
Starting reasonForward.
Concluding factNOTMergeClasses(0xbd1b70, 0x1980a5c).
Concluding factNOTMergeClasses(0xbd1b70, 0x1986854).
Concluding factNOTMergeClasses(0xbd1b70, 0x198607c).
Concluding factNOTMergeClasses(0x11cbce0, 0x1980a5c).
Starting reasonForward.
reasonForwardAsManyTimesAsPossible complete.
reasoningLoop: post-reason sanityChecks
Consistency checks failed.
insanityVFTableSizeInvalid failed: VFTable=0x1987608 LTESize=0x18 GTESize=0x1b4
Constraint checks failed, retracting guess!
The guess tryConstructor(0xea3830) was inconsistent with a valid solution.
Guessing tryNOTConstructor(0xea3830) instead.
Guessing factNOTConstructor(0xea3830).
There are 18,841,035 known facts.
reasoningLoop: pre-reason sanityChecks
failed.
Consistency checks failed.
Contradictory information about constructor: factConstructor(0x7ff080) but reasonNOTConstructor(0x7ff080)
Constraint checks failed, retracting guess!
tryBinarySearch completely failed on [0xea3830] and will now backtrack to fix an upstream problem.
guess: We have back-tracked to the call of tryBinarySearch(tryConstructor, tryNOTConstructor, [0xea3830, 0xea2f00, 0xe91600, 0xd9c7a0, 0xd663d0, 0xd5fd60, 0xd5f4a0, 0xd5e2d0, 0xd4fb90, 0xd2efe0, 0xc82340, 0xc800f0, 0xc52bf0, 0xc506a0, 0xc1f850, 0xc18300, 0xc0b370, 0xc0b1e0, 0xbee440, 0xb8eb40, 0xb3cef0, 0xb3a640, 0xb2d330, 0xb22db0, 0x83d290, 0x512ad0, 0x50b120, 0x4f6fd0, 0x4f10f0, 0x4f0e60, 0x4edc80, 0x4e9c70, 0x4e2ff0, 0x4d9d40, 0x4d9290, 0x4d7b20, 0x4d7810, 0x4d7390, 0x4d64e0, 0x4d5210, 0x4d3ba0, 0x4d2190, 0x4ce750, 0x4c8a50, 0x4bf160, 0x4bea50, 0x4b9d70, 0x4a8210, 0x4a6a30, 0x4a6430, 0x4a5460, 0x4a0d10, 0x49fac0, 0x49a250, 0x497e00, 0x490d90, 0x486030, 0x483f10, 0x482a70, 0x473c70, 0x46fd20, 0x46fc60, 0x46fba0, 0x46f5a0, 0x46f1b0, 0x46ed70, 0x46e9d0, 0x46dc50, 0x46d0c0, 0x46c860, 0x469780, 0x466970, 0x466880, 0x466790, 0x4666b0, 0x4665b0, 0x4664a0, 0x466280, 0x4642d0, 0x463be0, 0x462680, 0x460790, 0x45dd40, 0x44acf0, 0x44a610, 0x447a10, 0x443240, 0x4423f0, 0x4408c0, 0x43efc0, 0x43ca80, 0x43c720, 0x43b150, 0x436000, 0x435720, 0x433ba0, 0x42abc0, 0x13934a0, 0x1393310, 0xd6b340, 0xd6b220, 0xcafb20, 0xc38420, 0xc30ef0, 0x933170, 0x6da010, 0x4f6630, 0x4b3360, 0x12f2f80, 0xfe99f0, 0xfe34d0, 0xfd0510, 0xfcab60, 0xfc63d0, 0xf55990, 0xf55800, 0xf556a0, 0xf55550, 0xef5860, 0xdc1200, 0xdc10d0, 0xdc0fe0, 0xdba270, 0xd61720, 0xd03400, 0xbf7dd0, 0x8e9280, 0x8e91e0, 0x8e9140, 0x8e90a0, 0x8e9000, 0x8e8f60, 0x8e8ec0, 0x8e8e20, 0x8e8bb0, 0x7d85d0, 0x7c3020, 0x614150, 0x5b3d80, 0x5b1310, 0x5b10b0, 0x5b0cf0, 0x5b0b90, 0x5b0800, 0x5b0530, 0x5b0240, 0x5aff50, 0x5afbf0, 0x5acf90, 0x52fbc0, 0x1393da0, 0x133a0ba, 0x12d4340, 0xe707a0, 0xe70720, 0xe5cea0, 0xe5cca0, 0x9e77f0, 0x91ba30, 0x8d27a0, 0x869e20, 0x863720, 0x862830, 0x860480, 0x7f6360, 0x7ea600, 0x7dda90, 0x5ad460, 0x5551c0, 0x551e70, 0x550460, 0x5352d0, 0x529e50, 0x525880, 0x524d20])
Refusing to backtrack into reasoningLoop to fix an upstream problem because backtrackForUpstream/0 is not set.
This likely indicates that there is a problem with the OO rules.
Please report this failure to the Pharos developers!
 [665] prolog_stack:get_prolog_backtrace(100,[frame(665,clause(<clause>(0x2423330),6),_13367011178)|_13367011166],[goal_term_depth(100)]) at /data/research/swipl/install-bleeding/lib/swipl/library/prolog_stack.pl:134
 [664] throw_with_backtrace(error(system_error(upstreamProblem))) at /home/eschwartz/pharos/share/prolog/oorules/util.pl:185
  [26] solve_internal at /home/eschwartz/pharos/share/prolog/oorules/setup.pl:657
  [25] catch(user:solve_internal,_13367011402,user:((_13367011470=error(resource_error(private_table_space),_13367011484)->complain_table_space(ooscript);_13367011534=error(resource_error(stack),_13367011548)->complain_stack_size(ooscript);true),throw(_13367011580))) at /data/research/swipl/install-bleeding/lib/swipl/boot/init.pl:546
  [24] solve(ooscript) at /home/eschwartz/pharos/share/prolog/oorules/setup.pl:602
  [23] psolve_no_halt('<garbage_collected>') at /home/eschwartz/pharos/share/prolog/oorules/report.pl:11
  [22] catch(user:psolve_no_halt(stream(<stream>(0x28eaa20))),_13367011754,user:(print_message(error,_13367011820),(globalHalt->halt(1);true))) at /data/research/swipl/install-bleeding/lib/swipl/boot/init.pl:546
  [21] catch_with_backtrace('<garbage_collected>','<garbage_collected>','<garbage_collected>') at /data/research/swipl/install-bleeding/lib/swipl/boot/init.pl:614
  [20] run_with_backtrace('<garbage_collected>') at /home/eschwartz/pharos/share/prolog/oorules/ooprolog.pl:177
  [19] <meta call>
  [18] with_output_to(<stream>(0x28eaeb0),run_with_backtrace(psolve_no_halt(stream(<stream>(0x28eaa20))))) <foreign>
  [17] setup_call_catcher_cleanup(user:(var('../code/testcases/legoavengers/facts.exe.results')->open_null_stream(<stream>(0x28eaeb0));open('../code/testcases/legoavengers/facts.exe.results',write,<stream>(0x28eaeb0))),user:with_output_to(<stream>(0x28eaeb0),run_with_backtrace(psolve_no_halt(stream(<stream>(0x28eaa20))))),_13367012172,user:close(<stream>(0x28eaeb0))) at /data/research/swipl/install-bleeding/lib/swipl/boot/init.pl:646
  [15] setup_call_catcher_cleanup(user:open('../code/testcases/legoavengers/facts.exe.facts',read,<stream>(0x28eaa20)),user:setup_call_cleanup((var('../code/testcases/legoavengers/facts.exe.results')->open_null_stream(<stream>(0x28eaeb0));open('../code/testcases/legoavengers/facts.exe.results',write,<stream>(0x28eaeb0))),with_output_to(<stream>(0x28eaeb0),run_with_backtrace(psolve_no_halt(stream(<stream>(0x28eaa20))))),close(<stream>(0x28eaeb0))),_13367012382,user:close(<stream>(0x28eaa20))) at /data/research/swipl/install-bleeding/lib/swipl/boot/init.pl:646
  [12] run([script('/home/eschwartz/pharos/share/prolog/oorules/ooprolog.pl'),json(_13367012660),ground(_13367012680),rtti(true),guess(true),config(_13367012740),stacklimit(200000000000),tablespace(200000000000),oorulespath(_13367012800),halt(true),load_only(false),help(_13367012860),facts('../code/testcases/legoavengers/facts.exe.facts'),results('../code/testcases/legoavengers/facts.exe.results'),loglevel(5)]) at /home/eschwartz/pharos/share/prolog/oorules/ooprolog.pl:235
   [9] catch(user:main(['/home/eschwartz/pharos/share/prolog/oorules/ooprolog.pl','--facts','../code/testcases/legoavengers/facts.exe.facts','--results','../code/testcases/legoavengers/facts.exe.results','--log-level=5']),_13367012984,user:(print_message(error,_13367013114),halt(1))) at /data/research/swipl/install-bleeding/lib/swipl/boot/init.pl:546
   [7] catch(user:main,_13367013188,'$toplevel':true) at /data/research/swipl/install-bleeding/lib/swipl/boot/init.pl:546
   [6] catch_with_backtrace('<garbage_collected>','<garbage_collected>','<garbage_collected>') at /data/research/swipl/install-bleeding/lib/swipl/boot/init.pl:614

Note: some frames are missing due to last-call optimization.
Re-run your program in debug mode (:- debug.) to get more detail.
ERROR: ../code/testcases/legoavengers/facts.exe.facts:2336737:
ERROR:    Unknown message: error(system_error(upstreamProblem))

Originally posted by @sei-eschwartz in #175 (comment)

[sei-eschwartz]

Also, it took 11.7 days to reach this error.

[sei-eschwartz]

So 0x1987608 is MechShooterGunAddOn::`vftable' according to IDA. But also according to IDA, there are two other vftables with the same name, at 0x1987620 and 0x198762C.

[eschwartz@pd4 analysis]$ cat ../code/testcases/legoavengers/facts.exe.facts | fgrep -e 0x1987608 -e 0x1987620  -e 0x198762c
possibleVFTableWrite(0xecd239, 0xecd220, 0, 0x1987620).
possibleVFTableWrite(0xecd240, 0xecd210, 0, 0x1987608).
initialMemory(0x1987608, 0xecd210).
initialMemory(0x1987620, 0xecd220).
initialMemory(0x198762c, 0xecd230).

The table at 0x198762C is installed at 0xecd233 and 0xecf0d3, which we miss.

[sei-eschwartz]

I think 0xea3830 is a constructor, but I would appreciate someone else looking at it too, such as @RolphWoggom or @sei-ccohen. There are definitely some weird things going on.

[sei-eschwartz]

Concluding factVFTableSizeGTE(0x1987164, 0x1b4). This appears correct.
Concluding factVFTableSizeGTE(0x1987620, 0x1b4). This is not.
Concluding factVFTableSizeGTE(0x1987608, 0x1b4). This is not.

So for some reason OOAnalyzer thinks that all three MechShooterGunAddOn vftables are the same size...

[sei-eschwartz]

This is probably part of the issue:

[eschwartz@pd4 analysis]$ cat -n ../code/testcases/legoavengers/facts.exe.results.log | fgrep 0x1987620 | fgrep Derived                                                    
202995  Concluding factDerivedClass(0x1987620, 0x1987164, 0).
202996  Concluding factDerivedClass(0x1987620, 0x1987144, 0).
202997  Concluding factDerivedClass(0x1987620, 0x198715c, 0).

[sei-eschwartz]

I bet we are getting the Derived conclusions from RTTI, but I haven't confirmed that yet.

[sei-eschwartz]

Yes, I believe RTTI is the problem. RTTI says:

  8666  rTTISelfRef(0x1cef898, 0x1ae6390, 0x1ae63a4, 0x1ae6408, 0x1987164, '.?AVMechShooterGunBaseAddOn@@').
  8667  rTTISelfRef(0x1cef898, 0x1ae6424, 0x1ae63a4, 0x1ae6408, 0x198715c, '.?AVMechShooterGunBaseAddOn@@').
  8668  rTTISelfRef(0x1cef898, 0x1ae6438, 0x1ae63a4, 0x1ae6408, 0x1987144, '.?AVMechShooterGunBaseAddOn@@').

and

50686  rTTIInheritsDirectlyFromName(0x1cef898, 0x1cee484, 0x1, 0, 0xffffffff, 0, '.?AVMechShooterGunBaseAddOn@@', '.?AVMechShooterEquipmentAddOn@@').
50687  rTTIInheritsDirectlyFromName(0x1cef898, 0x1cee964, 0x1, 0, 0xffffffff, 0, '.?AVMechShooterGunBaseAddOn@@', '.?AVMechShooterWeaponAddOn@@').

We seem to be misinterpreting the RTTI since only the one VFTable is installed at offset 0:

[eschwartz@pd4 analysis]$ cat -n ../code/testcases/legoavengers/facts.exe.results.log | fgrep -e 0x1987164 -e 0x1987144 -e 0x198715c | fgrep Write                         
 77736  Concluding factVFTableWrite(0xecd14d, 0xecd110, 0, 0x1987164).
 79153  Concluding factVFTableWrite(0xeca8b6, 0xeca880, 0x3c, 0x1987144).
 79766  Concluding factVFTableWrite(0xeca8a9, 0xeca880, 0, 0x1987164).
 79994  Concluding factVFTableWrite(0xeca8af, 0xeca880, 0x8, 0x198715c).
 80099  Concluding factVFTableWrite(0xecd15a, 0xecd110, 0x3c, 0x1987144).
 80989  Concluding factVFTableWrite(0xecd153, 0xecd110, 0x8, 0x198715c).

@sei-ccohen I think you will probably need to look into this one.

[sei-eschwartz]

I may have jumped the gun on blaming RTTI. reasonMergeClasses_E should handle
these multiple vftable cases from RTTI.

I think the problem is instead with the second rule of
reasonVFTableSizeGTE when the base class has multiple vftables. But
there is still something strange going on because I think there are
more vftables than inheritance relationships, and reasonVFTableSizeGTE is
incorrectly applying to all of the vftables.

[sei-eschwartz]

I wrote a rather detailed description of the problem in email and it didn't save. But the short explanation of the problem is that MechShooterGunBaseAddon directly inherits from a single parent, but one of its parent's ancestors inherits from multiple classes. Any descendant from the multiple inheritance class is going to have multiple vftables.

Here is the exact hierarchy from the problem

; public class MechShooterGunBaseAddOn /* mdisp:0 */ :
.data:01CEF898 ;   public class MechShooterWeaponAddOn /* mdisp:0 */ :
.data:01CEF898 ;     public class MechShooterEquipmentAddOn /* mdisp:0 */ :
.data:01CEF898 ;       public class AddOnHelper /* mdisp:0 */ :
.data:01CEF898 ;         public class ScriptAddOn /* mdisp:0 */ :
.data:01CEF898 ;           public class LegoAddOn /* mdisp:0 */ :
.data:01CEF898 ;             public class AddOn /* mdisp:0 */ :
.data:01CEF898 ;               public class ApiAddOn /* mdisp:0 */ :
.data:01CEF898 ;                 public class PlaceableBase /* mdisp:0 */ :
.data:01CEF898 ;                   public class IAnimatable /* mdisp:0 */ :
.data:01CEF898 ;                     public class IClassObject /* mdisp:0 */ :
.data:01CEF898 ;                       public class NuUniqueObject /* mdisp:0 */ :
.data:01CEF898 ;                         public class NuUnknownDefaultBaseNoAutoDelete /* mdisp:0 */ :
.data:01CEF898 ;                           public class NuUnknown /* mdisp:0 */,
.data:01CEF898 ;                 public class NuMechPtr<class ApiAddOn,12>::ManagedBase /* mdisp:8 */ :
.data:01CEF898 ;                   public class NuMechPtr_ManagedObject /* mdisp:8 */,
.data:01CEF898 ;                   public struct NuMechPtr<class ApiAddOn,12>::ListLink /* mdisp:12 */,
.data:01CEF898 ;                 public class CSSimpleListLink<class ApiAddOn,class DefaultElist> /* mdisp:16 */,
.data:01CEF898 ;               public class HookListener /* mdisp:60 */

This is a problem because in some rules we have conflated inheritance offset with vftable offset. reasonVFTableSizeGTE is a good example. We only compare by inheritance offset, which is 0 here, but there are three vftables each with different offsets.

[sei-eschwartz]

This is really #207