cmu-sei / pharos

Automated static analysis tools for binary programs
Other
1.56k stars 192 forks source link

tryBinarySearch backtrack failure #175

Open RolphWoggom opened 3 years ago

RolphWoggom commented 3 years ago

I got this failure when analyzing a 35MB executable. It took forever so I didn't experiment at all. I'd be happy to do so though with your guidance. I also uploaded the executable and generated files here.

Before running this I forgot to pull the latest Docker image. I remembered before step 2, so fn2hash was run with 365a528011b5, everything else with da72c9ddd247.

Logs

fn2hash to create ooprog.ser ``` root@365a528011b5:/workdir# fn2hash --serialize=ooprog.ser --maximum-memory=128000 --no-semantics --partitioner=rose executable.exe >ooprog.csv OPTI[INFO ]: Analyzing executable: executable.exe OPTI[INFO ]: Calculating function hashes for file: executable.exe ; MD5: 03CF4658412E952367BD8B3B169FE933 OPTI[INFO ]: Function partitioning took 290.914 seconds. OPTI[INFO ]: Writing serialized data to "ooprog.ser". OPTI[INFO ]: Writing serialized data took 1250.6 seconds. OPTI[INFO ]: Partitioned 9710286 bytes, 2879313 instructions, 605191 basic blocks, 615 data blocks and 45317 functions. HASH[WARN ]: Instruction 74FD16: jmp [74FD58+ecx*4] had incomplete successors. HASH[WARN ]: Instruction 116D336: jmp [116DF44+eax*4] had incomplete successors. OPTI[INFO ]: fn2hash complete ```
ooanalyzer to create ooprog-facts.pl ``` root@da72c9ddd247:/workdir# ooanalyzer --serialize=ooprog.ser --maximum-memory 128000 --no-semantics --prolog-facts=ooprog-facts.pl --threads=8 --per-function-timeout=600 executable.exe OPTI[INFO ]: Analyzing executable: executable.exe OPTI[INFO ]: OOAnalyzer version 1.0. OPTI[INFO ]: Reading serialized data from "ooprog.ser". OPTI[INFO ]: Reading serialized data took 267.894 seconds. OPTI[INFO ]: Partitioned 9710286 bytes, 2879313 instructions, 605191 basic blocks, 615 data blocks and 45317 functions. OOAN[WARN ]: Instruction 74FD16: jmp [74FD58+ecx*4] had incomplete successors. OOAN[WARN ]: Instruction 116D336: jmp [116DF44+eax*4] had incomplete successors. APID[WARN ]: API database has no data for DLL: D3DCOMPILER_43 OOAN[WARN ]: No stack delta information for: D3DCOMPILER_43.dll:D3DCompile OOAN[WARN ]: No stack delta information for: D3DCOMPILER_43.dll:D3DPreprocess APID[WARN ]: API database has no data for DLL: DINPUT8 OOAN[WARN ]: No stack delta information for: DINPUT8.dll:DirectInput8Create APID[WARN ]: API database has no data for DLL: HID OOAN[WARN ]: No stack delta information for: HID.DLL:HidD_GetPreparsedData OOAN[WARN ]: No stack delta information for: HID.DLL:HidP_GetCaps OOAN[WARN ]: No stack delta information for: HID.DLL:HidD_GetProductString OOAN[WARN ]: No stack delta information for: HID.DLL:HidD_GetManufacturerString OOAN[WARN ]: No stack delta information for: HID.DLL:HidD_GetHidGuid OOAN[WARN ]: No stack delta information for: HID.DLL:HidD_GetAttributes APID[WARN ]: API database has no data for DLL: IPHLPAPI OOAN[WARN ]: No stack delta information for: IPHLPAPI.DLL:GetAdaptersInfo APID[WARN ]: API database could not find function VerSetConditionMask in KERNEL32 OOAN[WARN ]: No stack delta information for: KERNEL32.dll:VerSetConditionMask APID[WARN ]: API database has no data for DLL: PSAPI OOAN[WARN ]: No stack delta information for: PSAPI.DLL:GetModuleBaseNameA OOAN[WARN ]: No stack delta information for: PSAPI.DLL:GetProcessMemoryInfo OOAN[WARN ]: No stack delta information for: PSAPI.DLL:EnumProcessModules OOAN[WARN ]: No stack delta information for: PSAPI.DLL:GetModuleFileNameExA APID[WARN ]: API database has no data for DLL: SETUPAPI OOAN[WARN ]: No stack delta information for: SETUPAPI.dll:SetupDiGetDeviceInterfaceDetailA OOAN[WARN ]: No stack delta information for: SETUPAPI.dll:SetupDiEnumDeviceInterfaces OOAN[WARN ]: No stack delta information for: SETUPAPI.dll:SetupDiGetClassDevsA OOAN[WARN ]: No stack delta information for: SETUPAPI.dll:SetupDiDestroyDeviceInfoList APID[WARN ]: API database has no data for DLL: XAPOFX1_5 OOAN[WARN ]: No stack delta information for: XAPOFX1_5.dll:CreateFX APID[WARN ]: API database has no data for DLL: XINPUT1_3 OOAN[WARN ]: No stack delta information for: XINPUT1_3.dll:3 OOAN[WARN ]: No stack delta information for: XINPUT1_3.dll:4 OOAN[WARN ]: No stack delta information for: XINPUT1_3.dll:2 APID[WARN ]: API database has no data for DLL: d3d9 OOAN[WARN ]: No stack delta information for: d3d9.dll:Direct3DCreate9 APID[WARN ]: API database has no data for DLL: d3dx9_43 OOAN[WARN ]: No stack delta information for: d3dx9_43.dll:D3DXGetShaderConstantTableEx OOAN[WARN ]: No stack delta information for: d3dx9_43.dll:D3DXLoadSurfaceFromSurface APID[WARN ]: API database has no data for DLL: steam_api OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamAPI_UnregisterCallback OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamUtils OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamUserStats OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamAPI_RegisterCallback OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamApps OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamFriends OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamRemoteStorage OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamAPI_RunCallbacks OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamAPI_Shutdown OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamAPI_Init OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamAPI_RestartAppIfNecessary OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamUser [INFO ]: Unable to find this-pointer for function at 0x010EA830 [INFO ]: Unable to find this-pointer for function at 0x00E3B3B0 [INFO ]: Unable to find this-pointer for function at 0x00CE8950 OOAN[WARN ]: Unable to find this-pointer for function at 0x00CE1C20 [INFO ]: Unable to find this-pointer for function at 0x009FAFF0 OOAN[WARN ]: Unable to find this-pointer for function at 0x00942BC0 OOAN[WARN ]: Unable to find this-pointer for function at 0x0085B3A0 OOAN[WARN ]: Unable to find this-pointer for function at 0x00734EEE [INFO ]: Analysis of function 0x006BA900 failed: relative CPU time exceeded; adjust with --per-function-timeout OOAN[WARN ]: Unable to find this-pointer for function at 0x009298E0 [INFO ]: Function 0x00585730 has no out edges. [INFO ]: Analysis of function 0x0135194C failed: relative CPU time exceeded; adjust with --per-function-timeout [INFO ]: Analysis of function 0x006C2860 failed: relative CPU time exceeded; adjust with --per-function-timeout OOAN[WARN ]: Unable to find this-pointer for function at 0x00920750 [INFO ]: Analysis of function 0x0099D780 failed: relative CPU time exceeded; adjust with --per-function-timeout [INFO ]: Analysis of function 0x00760B30 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x0054B310 failed: relative CPU time exceeded; adjust with --per-function-timeout OOAN[WARN ]: Unable to find this-pointer for function at 0x004AE330 FSEM[ERROR]: Analysis of function 0x006A4120 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x009226F0 failed: relative CPU time exceeded; adjust with --per-function-timeout OOAN[WARN ]: Unable to find this-pointer for function at 0x0042C8A0 OOAN[WARN ]: Unable to find this-pointer for function at 0x0042C210 FSEM[ERROR]: Analysis of function 0x0116D411 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x0116CE40 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x00F14800 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x00F04780 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x010413C0 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x008C4F70 failed: relative CPU time exceeded; adjust with --per-function-timeout [INFO ]: Analysis of function 0x00E00690 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x005D4B60 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x010AF8A0 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x010A3A60 failed: relative CPU time exceeded; adjust with --per-function-timeout [INFO ]: Analysis of function 0x0066E460 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x006075E0 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x006A98B0 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x0118AC30 failed: relative CPU time exceeded; adjust with --per-function-timeout OOAN[WARN ]: Unable to find this-pointer for function at 0x00F9BBB0 FSEM[ERROR]: Analysis of function 0x00BC4FC0 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x010A7640 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x011AF380 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x006351A0 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x00F785E0 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x0106BCC0 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x010036C0 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x010DBBE0 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x010C5750 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x01019560 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x010B8100 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x010B61C0 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x00C9B730 failed: relative CPU time exceeded; adjust with --per-function-timeout OOAN[WARN ]: Unable to find this-pointer for function at 0x00EF5340 FSEM[ERROR]: Analysis of function 0x0063FDE0 failed: relative CPU time exceeded; adjust with --per-function-timeout FSEM[ERROR]: Analysis of function 0x00F226D0 failed: relative CPU time exceeded; adjust with --per-function-timeout OPTI[INFO ]: Function analysis complete, analyzed 45044 functions in 6946.13 seconds. OOAN[WARN ]: Missing this-pointer usage for new() call at 52AF2A: call 13350E1 OOAN[WARN ]: Missing this-pointer usage for new() call at 5F6BF3: call 13350E1 OOAN[WARN ]: Missing this-pointer usage for new() call at 7575DF: call 13350E1 OOAN[WARN ]: Missing this-pointer usage for new() call at 757D65: call 13350E1 OOAN[WARN ]: Missing this-pointer usage for new() call at 76B876: call 13350E1 OOAN[WARN ]: Missing this-pointer usage for new() call at 8D8AE5: call 13350E1 OOAN[WARN ]: Unable to find parameter for new() call at 0x01003877 OOAN[WARN ]: Unable to find parameter for new() call at 0x01069A93 OOAN[WARN ]: Missing this-pointer usage for new() call at 109D9A1: call 13350E1 OOAN[ERROR]: Missing return value from new() call at 0x0133447B OPTI[WARN ]: OOAnalyzer did not perform C++ class analysis. OPTI[INFO ]: OOAnalyzer analysis complete. ```
Info about ooprog-facts.pl ``` root@da72c9ddd247:/workdir# awk -F\( '{print $1}' ooprog-facts.pl | sort | uniq -c 1 % Object fact exporting complete. 1 % Prolog facts autogenerated by OOAnalyzer. 71495 callParameter 171250 callReturn 199312 callTarget 86061 callingConvention 1 fileInfo 17180 funcOffset 31971 funcParameter 18916 funcReturn 95628 initialMemory 98 insnCallsDelete 116688 methodMemberAccess 16167 noCallsAfter 16059 noCallsBefore 46 possibleVBTableWrite 2899 possibleVFTableWrite 29536 possibleVirtualFunctionCall 3908 rTTIBaseClassDescriptor 3165 rTTIClassHierarchyDescriptor 2950 rTTICompleteObjectLocator 3165 rTTITypeDescriptor 1885 returnsSelf 2121 thisPtrAllocation 10477 thisPtrOffset 126098 thisPtrUsage 608 thunk 412 uninitializedReads ```
ooprolog with failure ``` ooprolog --facts ooprog-facts.pl --results ooprog-results.pl Consistency checks failed. insanityVFTableSizeInvalid failed: VFTable=0x19b32d4 LTESize=0x358 GTESize=0x484 Constraint checks failed, retracting guess! Consistency checks failed. insanityVFTableSizeInvalid failed: VFTable=0x19fc2bc LTESize=0x40 GTESize=0x6c Constraint checks failed, retracting guess! Consistency checks failed. insanityVFTableSizeInvalid failed: VFTable=0x19fc2bc LTESize=0x40 GTESize=0x6c Constraint checks failed, retracting guess! Consistency checks failed. insanityVFTableSizeInvalid failed: VFTable=0x19fc2bc LTESize=0x40 GTESize=0x6c Constraint checks failed, retracting guess! Consistency checks failed. insanityVFTableSizeInvalid failed: VFTable=0x19fc2bc LTESize=0x40 GTESize=0x6c Constraint checks failed, retracting guess! Consistency checks failed. insanityVFTableSizeInvalid failed: VFTable=0x19fc2bc LTESize=0x40 GTESize=0x6c Constraint checks failed, retracting guess! Consistency checks failed. insanityVFTableSizeInvalid failed: VFTable=0x19fc2bc LTESize=0x40 GTESize=0x6c Constraint checks failed, retracting guess! Consistency checks failed. insanityVFTableSizeInvalid failed: VFTable=0x19fc2bc LTESize=0x40 GTESize=0x6c Constraint checks failed, retracting guess! tryBinarySearch completely failed on [0x12d48a0] and will now backtrack to fix an upstream problem. 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! [78] prolog_stack:get_prolog_backtrace(100,[frame(78,clause((0x5647186b3dc0),6),_871889488)|_871889476],[goal_term_depth(100)]) at /usr/local/lib/swipl/library/prolog_stack.pl:134 [77] throw_with_backtrace(error(system_error(upstreamProblem))) at /usr/local/share/pharos/prolog/oorules/util.pl:183 [26] solve_internal at /usr/local/share/pharos/prolog/oorules/setup.pl:653 [25] catch(user:solve_internal,_871889712,user:((_871889780=error(resource_error(private_table_space),_871889794)->complain_table_space(ooscript);_871889844=error(resource_error(stack),_871889858)->complain_stack_size(ooscript);true),throw(_871889890))) at /usr/local/lib/swipl/boot/init.pl:537 [24] solve(ooscript) at /usr/local/share/pharos/prolog/oorules/setup.pl:598 [23] psolve_no_halt('') at /usr/local/share/pharos/prolog/oorules/report.pl:11 [22] catch(user:psolve_no_halt(stream((0x56471883e770))),_871890064,user:(print_message(error,_871890130),(globalHalt->halt(1);true))) at /usr/local/lib/swipl/boot/init.pl:537 [21] catch_with_backtrace('','','') at /usr/local/lib/swipl/boot/init.pl:587 [20] run_with_backtrace('') at /usr/local/bin/ooprolog:177 [19] [18] with_output_to((0x56471883e9f0),run_with_backtrace(psolve_no_halt(stream((0x56471883e770))))) [17] setup_call_catcher_cleanup(user:(var('ooprog-results.pl')->open_null_stream((0x56471883e9f0));open('ooprog-results.pl',write,(0x56471883e9f0))),user:with_output_to((0x56471883e9f0),run_with_backtrace(psolve_no_halt(stream((0x56471883e770))))),_871890482,user:close((0x56471883e9f0))) at /usr/local/lib/swipl/boot/init.pl:619 [15] setup_call_catcher_cleanup(user:open('ooprog-facts.pl',read,(0x56471883e770)),user:setup_call_cleanup((var('ooprog-results.pl')->open_null_stream((0x56471883e9f0));open('ooprog-results.pl',write,(0x56471883e9f0))),with_output_to((0x56471883e9f0),run_with_backtrace(psolve_no_halt(stream((0x56471883e770))))),close((0x56471883e9f0))),_871890692,user:close((0x56471883e770))) at /usr/local/lib/swipl/boot/init.pl:619 [12] run([script('/usr/local/bin/ooprolog'),json(_871890970),ground(_871890990),rtti(true),guess(true),loglevel(3),config(_871891070),stacklimit(200000000000),tablespace(200000000000),oorulespath(_871891130),halt(true),load_only(false),help(_871891190),facts('ooprog-facts.pl'),results('ooprog-results.pl')]) at /usr/local/bin/ooprolog:235 [9] catch(user:main(['/usr/local/bin/ooprolog','--facts','ooprog-facts.pl','--results','ooprog-results.pl']),_871891294,user:(print_message(error,_871891412),halt(1))) at /usr/local/lib/swipl/boot/init.pl:537 [7] catch(user:main,_871891486,'$toplevel':true) at /usr/local/lib/swipl/boot/init.pl:537 [6] catch_with_backtrace('','','') at /usr/local/lib/swipl/boot/init.pl:587 Note: some frames are missing due to last-call optimization. Re-run your program in debug mode (:- debug.) to get more detail. ERROR: ooprog-facts.pl:1028099: ERROR: Unknown message: error(system_error(upstreamProblem)) ```

Other

sei-eschwartz commented 3 years ago

Pharos commit cd2861a made some changes with problematic rules that caused errors like yours in the past. But I can't tell what commit you were on from the docker ID. If you run --help on any pharos command, it should print the commit all the way at the bottom. If you can tell me which commit you were on, it will be a large help.

RolphWoggom commented 3 years ago

Docker ID: da72c9ddd247 RevID: 2becf22aa64577199a68741104f8e969554337df

So everything but fn2hash was run with that. Would it help a lot to run the entire thing again in debug mode?

Sorry this is wrong, I'm on docker a2cb749f49c2 right now which is git 2becf22aa64577199a68741104f8e969554337df

I'm pretty sure I used the version before the latest batch commit so I'll rerun everything with debug enabled.

sei-eschwartz commented 3 years ago

Was the ooprolog step run with 2becf22? Or was that from before the latest batch commit too?

I would recommend using --log-level 5 when re-running the prolog. That's a reasonable balance between providing useful information and not slowing things down too much.

RolphWoggom commented 3 years ago

It was from before, too.

Are the following commands good?

partition --serialize=ooprog.ser --maximum-memory=128000 --no-semantics --partitioner=rose executable.exe
ooanalyzer --serialize=ooprog.ser --maximum-memory 128000 --no-semantics --prolog-facts=ooprog-facts.pl --threads=4 --per-function-timeout=99999 --apidb=contrib/setupapi.json executable.exe
awk -F\( '{print $1}' ooprog-facts.pl | sort | uniq -c
ooprolog --facts ooprog-facts.pl --results ooprog-results.pl --log-level=5 >ooprog.log
ooprolog --results ooprog-results.pl --json ooprog.json

Is there a debug flag for ooprolog?

Also I'm currently partitioning and Writing serialized data to "ooprog.ser". is again taking longer than partitioning itself.

sei-eschwartz commented 3 years ago

Yes, those look good.

Is there a debug flag for ooprolog?

No, just the log level.

Also I'm currently partitioning and Writing serialized data to "ooprog.ser". is again taking longer than partitioning itself.

I'll see if I have the same problem.

sei-eschwartz commented 3 years ago

I was able to reproduce your problem by running the latest version of ooanalyzer on your facts file. I should have enough information to start investigating.

sei-eschwartz commented 3 years ago

Here is the end of the log at log-level 5:

Guessing factConstructor(0x12d48a0).
There are 3,008,377 known facts.
reasoningLoop: pre-reason sanityChecks
Constraint checks succeeded, proceeding to reason forward!
reasoningLoop: reasonForardAsManyTimesAsPossible
Starting reasonForward.
Concluding factClassSizeLTE(0x12d48a0, 0xfffffff).
Starting reasonForward.
Concluding mergeVFTables(0x19fc2bc, 0x12d48a0).
Merging class 0x12d48a0 into 0x19fc2bc ...
Retracting factClassRelatedMethod(0x12d48a0, 0x12bf200) and asserting factClassRelatedMethod(0x19fc2bc, 0x12bf200) ...
Retracting factClassRelatedMethod(0x12d48a0, 0x12f1270) and asserting factClassRelatedMethod(0x19fc2bc, 0x12f1270) ...
Retracting factClassSizeGTE(0x12d48a0, 0x3c) and asserting factClassSizeGTE(0x19fc2bc, 0x3c) ...
Retracting factClassSizeLTE(0x12d48a0, 0xfffffff) and asserting factClassSizeLTE(0x19fc2bc, 0xfffffff) ...
Starting reasonForward.
Concluding factVFTableSizeGTE(0x19fc2bc, 0x6c).
Starting reasonForward.
Concluding factClassSizeGTE(0x19fce0c, 0x3c).
Concluding factClassSizeGTE(0x19fc2dc, 0x3c).
Starting reasonForward.
Concluding factClassSizeLTE(0x19fb9f8, 0xfffffff).
Starting reasonForward.
reasonForwardAsManyTimesAsPossible complete.
reasoningLoop: post-reason sanityChecks
Consistency checks failed.
insanityVFTableSizeInvalid failed: VFTable=0x19fc2bc LTESize=0x40 GTESize=0x6c
Constraint checks failed, retracting guess!
The guess tryConstructor(0x12d48a0) was inconsistent with a valid solution.
Guessing tryNOTConstructor(0x12d48a0) instead.
Guessing factNOTConstructor(0x12d48a0).
There are 3,008,377 known facts.
reasoningLoop: pre-reason sanityChecks
Constraint checks succeeded, proceeding to reason forward!
reasoningLoop: reasonForardAsManyTimesAsPossible
Starting reasonForward.
Concluding factDeletingDestructor(0x12d48a0).
Starting reasonForward.
Concluding mergeVFTables(0x19fc2bc, 0x12d48a0).
Merging class 0x12d48a0 into 0x19fc2bc ...
Retracting factClassRelatedMethod(0x12d48a0, 0x12bf200) and asserting factClassRelatedMethod(0x19fc2bc, 0x12bf200) ...
Retracting factClassRelatedMethod(0x12d48a0, 0x12f1270) and asserting factClassRelatedMethod(0x19fc2bc, 0x12f1270) ...
Retracting factClassSizeGTE(0x12d48a0, 0x3c) and asserting factClassSizeGTE(0x19fc2bc, 0x3c) ...
Starting reasonForward.
Concluding factVFTableSizeGTE(0x19fc2bc, 0x6c).
Starting reasonForward.
Concluding factClassSizeGTE(0x19fce0c, 0x3c).
Concluding factClassSizeGTE(0x19fc2dc, 0x3c).
Starting reasonForward.
reasonForwardAsManyTimesAsPossible complete.
reasoningLoop: post-reason sanityChecks
Consistency checks failed.
insanityVFTableSizeInvalid failed: VFTable=0x19fc2bc LTESize=0x40 GTESize=0x6c
sei-eschwartz commented 3 years ago

0x12d48a0 looks like a constructor to me. It also just gave me ideas for #177 and #178 :)

sei-eschwartz commented 3 years ago

Concluding factVFTableSizeGTE(0x19fc2bc, 0x6c).

This seems incorrect, and must come from reasonVFTableSizeGTE_B, which has to do with inherited classes. Specifically, one of these:

Concluding factDerivedClass(0x19fc2bc, 0x19fb9f8, 0).
Concluding factDerivedClass(0x19fc2dc, 0x19fc2bc, 0).
Concluding factDerivedClass(0x19fce0c, 0x19fc2bc, 0).
sei-eschwartz commented 3 years ago

It's hard to tell where the bad size 0x6c is coming from, so I'm rerunning with --log-level 7.

RolphWoggom commented 3 years ago

This is great, thank you!

I created a new facts file, this time with no function timeout, an apidb entry for setupapi.dll and the latest version (2becf22aa64577199a68741104f8e969554337df):

Logs ``` root@d51a8b8547a5:/workdir# ooanalyzer --help | grep RevID RevID: 2becf22aa64577199a68741104f8e969554337df root@d51a8b8547a5:/workdir# partition --serialize=ooprog.ser --maximum-memory=128000 --no-semantics --partitioner=rose executable.exe OPTI[INFO ]: Analyzing executable: executable.exe OPTI[INFO ]: Function partitioning took 364.181 seconds. OPTI[INFO ]: Writing serialized data to "ooprog.ser". OPTI[INFO ]: Writing serialized data took 1718.25 seconds. OPTI[INFO ]: Partitioned 9710286 bytes, 2879313 instructions, 605191 basic blocks, 615 data blocks and 45317 functions. root@d51a8b8547a5:/workdir# ooanalyzer --serialize=ooprog.ser --maximum-memory 128000 --no-semantics --prolog-facts=ooprog-facts.pl --threads=4 --per-function-timeout=99999 --apidb=contrib/setupapi.json executable.exe OPTI[INFO ]: Analyzing executable: executable.exe OPTI[INFO ]: OOAnalyzer version 1.0. OPTI[INFO ]: Reading serialized data from "ooprog.ser". OPTI[INFO ]: Reading serialized data took 303.054 seconds. OPTI[INFO ]: Partitioned 9710286 bytes, 2879313 instructions, 605191 basic blocks, 615 data blocks and 45317 functions. OOAN[WARN ]: Instruction 74FD16: jmp [74FD58+ecx*4] had incomplete successors. OOAN[WARN ]: Instruction 116D336: jmp [116DF44+eax*4] had incomplete successors. APID[WARN ]: API database has no data for DLL: D3DCOMPILER_43 OOAN[WARN ]: No stack delta information for: D3DCOMPILER_43.dll:D3DCompile OOAN[WARN ]: No stack delta information for: D3DCOMPILER_43.dll:D3DPreprocess APID[WARN ]: API database has no data for DLL: DINPUT8 OOAN[WARN ]: No stack delta information for: DINPUT8.dll:DirectInput8Create APID[WARN ]: API database has no data for DLL: HID OOAN[WARN ]: No stack delta information for: HID.DLL:HidD_GetPreparsedData OOAN[WARN ]: No stack delta information for: HID.DLL:HidP_GetCaps OOAN[WARN ]: No stack delta information for: HID.DLL:HidD_GetProductString OOAN[WARN ]: No stack delta information for: HID.DLL:HidD_GetManufacturerString OOAN[WARN ]: No stack delta information for: HID.DLL:HidD_GetHidGuid OOAN[WARN ]: No stack delta information for: HID.DLL:HidD_GetAttributes APID[WARN ]: API database has no data for DLL: IPHLPAPI OOAN[WARN ]: No stack delta information for: IPHLPAPI.DLL:GetAdaptersInfo APID[WARN ]: API database could not find function VerSetConditionMask in KERNEL32 OOAN[WARN ]: No stack delta information for: KERNEL32.dll:VerSetConditionMask APID[WARN ]: API database has no data for DLL: PSAPI OOAN[WARN ]: No stack delta information for: PSAPI.DLL:GetModuleBaseNameA OOAN[WARN ]: No stack delta information for: PSAPI.DLL:GetProcessMemoryInfo OOAN[WARN ]: No stack delta information for: PSAPI.DLL:EnumProcessModules OOAN[WARN ]: No stack delta information for: PSAPI.DLL:GetModuleFileNameExA APID[WARN ]: API database has no data for DLL: XAPOFX1_5 OOAN[WARN ]: No stack delta information for: XAPOFX1_5.dll:CreateFX APID[WARN ]: API database has no data for DLL: XINPUT1_3 OOAN[WARN ]: No stack delta information for: XINPUT1_3.dll:3 OOAN[WARN ]: No stack delta information for: XINPUT1_3.dll:4 OOAN[WARN ]: No stack delta information for: XINPUT1_3.dll:2 APID[WARN ]: API database has no data for DLL: d3d9 OOAN[WARN ]: No stack delta information for: d3d9.dll:Direct3DCreate9 APID[WARN ]: API database has no data for DLL: d3dx9_43 OOAN[WARN ]: No stack delta information for: d3dx9_43.dll:D3DXGetShaderConstantTableEx OOAN[WARN ]: No stack delta information for: d3dx9_43.dll:D3DXLoadSurfaceFromSurface APID[WARN ]: API database has no data for DLL: steam_api OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamAPI_UnregisterCallback OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamUtils OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamUserStats OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamAPI_RegisterCallback OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamApps OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamFriends OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamRemoteStorage OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamAPI_RunCallbacks OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamAPI_Shutdown OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamAPI_Init OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamAPI_RestartAppIfNecessary OOAN[WARN ]: No stack delta information for: steam_api.dll:SteamUser [INFO ]: Unable to find this-pointer for function at 0x010EA830 [INFO ]: Unable to find this-pointer for function at 0x00E3B3B0 OOAN[WARN ]: Unable to find this-pointer for function at 0x00CE8950 OOAN[WARN ]: Unable to find this-pointer for function at 0x00CE1C20 [INFO ]: Unable to find this-pointer for function at 0x009FAFF0 OOAN[WARN ]: Unable to find this-pointer for function at 0x00942BC0 OOAN[WARN ]: Unable to find this-pointer for function at 0x0085B3A0 OOAN[WARN ]: Unable to find this-pointer for function at 0x00734EEE [INFO ]: Function 0x00585730 has no out edges. OOAN[WARN ]: Unable to find this-pointer for function at 0x009298E0 OOAN[WARN ]: Unable to find this-pointer for function at 0x00920750 OOAN[WARN ]: Unable to find this-pointer for function at 0x004AE330 OOAN[WARN ]: Unable to find this-pointer for function at 0x0042C8A0 OOAN[WARN ]: Unable to find this-pointer for function at 0x0042C210 OOAN[WARN ]: Unable to find this-pointer for function at 0x00F9BBB0 OOAN[WARN ]: Unable to find this-pointer for function at 0x00EF5340 OOAN[ERROR]: Found only 45042 functions of 45044 specifically requested for analysis. OOAN[ERROR]: No delete() methods were found. Object analysis may be impaired. OOAN[ERROR]: Missing return value from new() call at 0x005AD8F9 OOAN[ERROR]: Missing return value from new() call at 0x00622820 OOAN[ERROR]: Missing return value from new() call at 0x006228E1 OOAN[ERROR]: Missing return value from new() call at 0x00691784 OOAN[ERROR]: Missing return value from new() call at 0x0074AC71 OOAN[ERROR]: Missing return value from new() call at 0x0076F153 OOAN[ERROR]: Missing return value from new() call at 0x007B5170 OOAN[ERROR]: Missing return value from new() call at 0x0084821F OOAN[ERROR]: Missing return value from new() call at 0x008C85A4 OOAN[ERROR]: Missing return value from new() call at 0x008D67E6 OOAN[ERROR]: Missing return value from new() call at 0x008D6839 OOAN[ERROR]: Missing return value from new() call at 0x008D6C1E OOAN[ERROR]: Missing return value from new() call at 0x008D6D55 OOAN[ERROR]: Missing return value from new() call at 0x008D6D82 OOAN[ERROR]: Missing return value from new() call at 0x008D6F85 OOAN[ERROR]: Missing return value from new() call at 0x008D702E OOAN[ERROR]: Missing return value from new() call at 0x008D81BC OOAN[ERROR]: Missing return value from new() call at 0x008D81FF OOAN[ERROR]: Missing return value from new() call at 0x008D8250 OOAN[ERROR]: Missing return value from new() call at 0x008D82E3 OOAN[ERROR]: Missing return value from new() call at 0x008D8361 OOAN[ERROR]: Missing return value from new() call at 0x008DC26E OOAN[ERROR]: Missing return value from new() call at 0x008DCDAF OOAN[ERROR]: Missing return value from new() call at 0x008DD2B5 OOAN[ERROR]: Missing return value from new() call at 0x008DD311 OOAN[ERROR]: Missing return value from new() call at 0x008DD660 OOAN[ERROR]: Missing return value from new() call at 0x008DD695 OOAN[ERROR]: Missing return value from new() call at 0x008DE11F OOAN[ERROR]: Missing return value from new() call at 0x008DE4C8 OOAN[ERROR]: Missing return value from new() call at 0x008DE821 OOAN[ERROR]: Missing return value from new() call at 0x008DE856 OOAN[ERROR]: Missing return value from new() call at 0x008DEE38 OOAN[ERROR]: Missing return value from new() call at 0x008DEE6C OOAN[ERROR]: Missing return value from new() call at 0x008DEF0B OOAN[ERROR]: Missing return value from new() call at 0x008DF2AA OOAN[ERROR]: Missing return value from new() call at 0x008DF2DD OOAN[ERROR]: Missing return value from new() call at 0x008DFBE8 OOAN[ERROR]: Missing return value from new() call at 0x008DFC25 OOAN[ERROR]: Missing return value from new() call at 0x008DFF78 OOAN[ERROR]: Missing return value from new() call at 0x008E03C2 OOAN[ERROR]: Missing return value from new() call at 0x008E03F2 OOAN[ERROR]: Missing return value from new() call at 0x008E04E7 OOAN[ERROR]: Missing return value from new() call at 0x008E07A6 OOAN[ERROR]: Missing return value from new() call at 0x008E07D4 OOAN[ERROR]: Missing return value from new() call at 0x009B7691 OOAN[ERROR]: Missing return value from new() call at 0x009C3750 OOAN[ERROR]: Missing return value from new() call at 0x00D33E1B OOAN[ERROR]: Missing return value from new() call at 0x00E3B7BD OOAN[ERROR]: Missing return value from new() call at 0x00E3E8BF OOAN[ERROR]: Missing return value from new() call at 0x00E438E6 OOAN[ERROR]: Missing return value from new() call at 0x00E45ECC OOAN[ERROR]: Missing return value from new() call at 0x00E7FCCB OOAN[ERROR]: Missing return value from new() call at 0x00E80B6B OOAN[ERROR]: Missing return value from new() call at 0x00E818DC OOAN[ERROR]: Missing return value from new() call at 0x00E859BB OOAN[ERROR]: Missing return value from new() call at 0x01087B2E OOAN[ERROR]: Missing return value from new() call at 0x01087B4A OOAN[ERROR]: Missing return value from new() call at 0x01087B66 OOAN[ERROR]: Missing return value from new() call at 0x01087B82 OOAN[ERROR]: Missing return value from new() call at 0x0117EFD6 OOAN[WARN ]: Missing this-pointer usage for new() call at 52AF2A: call 13350E1 OOAN[WARN ]: Missing this-pointer usage for new() call at 5F6BF3: call 13350E1 OOAN[WARN ]: Missing this-pointer usage for new() call at 7575DF: call 13350E1 OOAN[WARN ]: Missing this-pointer usage for new() call at 757D65: call 13350E1 OOAN[WARN ]: Missing this-pointer usage for new() call at 76B876: call 13350E1 OOAN[WARN ]: Missing this-pointer usage for new() call at 8D8AE5: call 13350E1 OOAN[WARN ]: Unable to find parameter for new() call at 0x01003877 OOAN[WARN ]: Unable to find parameter for new() call at 0x01069A93 OOAN[WARN ]: Missing this-pointer usage for new() call at 109D9A1: call 13350E1 OOAN[ERROR]: Missing return value from new() call at 0x0133447B OPTI[WARN ]: OOAnalyzer did not perform C++ class analysis. OPTI[INFO ]: OOAnalyzer analysis complete. ```

ooanalyzer claims that no delete() methods were found but the facts file contains insnCallsDelete lines that seem identical to the previous facts file (except the last column).

I'll run ooprolog --facts ooprog-facts.pl --results ooprog-results.pl --log-level=7 >ooprog.log next and will report back with the output.

RolphWoggom commented 3 years ago

Using the the new facts file from the previous post and ooprolog from 2becf22aa64577199a68741104f8e969554337df produced this ooprog.log.

The command output is:

``` root@ac5043e99b2f:/workdir# ooprolog --facts ooprog-facts.pl --results ooprog-results.pl --log-level=7 >ooprog.log [227] prolog_stack:get_prolog_backtrace(100,[frame(227,clause((0x55ad6bb66410),6),_1085165352)|_1085165340],[goal_term_depth(100)]) at /usr/local/lib/swipl/library/prolog_stack.pl:134 [226] throw_with_backtrace(error(system_error(upstreamProblem))) at /usr/local/share/pharos/prolog/oorules/util.pl:183 [26] solve_internal at /usr/local/share/pharos/prolog/oorules/setup.pl:657 [25] catch(user:solve_internal,_1085165576,user:((_1085165644=error(resource_error(private_table_space),_1085165658)->complain_table_space(ooscript);_1085165708=error(resource_error(stack),_1085165722)->complain_stack_size(ooscript);true),throw(_1085165754))) at /usr/local/lib/swipl/boot/init.pl:537 [24] solve(ooscript) at /usr/local/share/pharos/prolog/oorules/setup.pl:602 [23] psolve_no_halt('') at /usr/local/share/pharos/prolog/oorules/report.pl:11 [22] catch(user:psolve_no_halt(stream((0x55ad6bb74640))),_1085165928,user:(print_message(error,_1085165994),(globalHalt->halt(1);true))) at /usr/local/lib/swipl/boot/init.pl:537 [21] catch_with_backtrace('','','') at /usr/local/lib/swipl/boot/init.pl:587 [20] run_with_backtrace('') at /usr/local/bin/ooprolog:177 [19] [18] with_output_to((0x55ad6beed4d0),run_with_backtrace(psolve_no_halt(stream((0x55ad6bb74640))))) [17] setup_call_catcher_cleanup(user:(var('ooprog-results.pl')->open_null_stream((0x55ad6beed4d0));open('ooprog-results.pl',write,(0x55ad6beed4d0))),user:with_output_to((0x55ad6beed4d0),run_with_backtrace(psolve_no_halt(stream((0x55ad6bb74640))))),_1085166346,user:close((0x55ad6beed4d0))) at /usr/local/lib/swipl/boot/init.pl:619 [15] setup_call_catcher_cleanup(user:open('ooprog-facts.pl',read,(0x55ad6bb74640)),user:setup_call_cleanup((var('ooprog-results.pl')->open_null_stream((0x55ad6beed4d0));open('ooprog-results.pl',write,(0x55ad6beed4d0))),with_output_to((0x55ad6beed4d0),run_with_backtrace(psolve_no_halt(stream((0x55ad6bb74640))))),close((0x55ad6beed4d0))),_1085166556,user:close((0x55ad6bb74640))) at /usr/local/lib/swipl/boot/init.pl:619 [12] run([script('/usr/local/bin/ooprolog'),json(_1085166834),ground(_1085166854),rtti(true),guess(true),config(_1085166914),stacklimit(200000000000),tablespace(200000000000),oorulespath(_1085166974),halt(true),load_only(false),help(_1085167034),facts('ooprog-facts.pl'),results('ooprog-results.pl'),loglevel(7)]) at /usr/local/bin/ooprolog:235 [9] catch(user:main(['/usr/local/bin/ooprolog','--facts','ooprog-facts.pl','--results','ooprog-results.pl','--log-level=7']),_1085167158,user:(print_message(error,_1085167288),halt(1))) at /usr/local/lib/swipl/boot/init.pl:537 [7] catch(user:main,_1085167362,'$toplevel':true) at /usr/local/lib/swipl/boot/init.pl:537 [6] catch_with_backtrace('','','') at /usr/local/lib/swipl/boot/init.pl:587 Note: some frames are missing due to last-call optimization. Re-run your program in debug mode (:- debug.) to get more detail. ERROR: ooprog-facts.pl:1031235: ERROR: Unknown message: error(system_error(upstreamProblem)) ```

The end of the log with log level 7 is:

``` Processing trigger fact... factClassSizeGTE(0x19fc2bc, 0x3c) Processing trigger fact... factClassSizeLTE(0x19fc2bc, 0xfffffff) Processing trigger fact... factClassSizeGTE(0x19fc2dc, 0x3c) Processing trigger fact... factClassSizeGTE(0x19fce0c, 0x3c) Processing trigger fact... factClassSizeLTE(0x19fb9f8, 0xfffffff) reasonMergeVFTables_A(constructor, 0x19e33ac, 0x19f0200, 0x19e33ac, 0x90, factVFTableWrite(0x128df59, 0x128dec0, 0x90, 0x19e33ac)). reasonMergeVFTables_A(destructor, 0x19e33ac, 0x19f0200, 0x19e33ac, 0x90, factVFTableWrite(0x128df59, 0x128dec0, 0x90, 0x19e33ac)). reasonForwardAsManyTimesAsPossible complete. reasoningLoop: post-reason sanityChecks Consistency checks failed. insanityVFTableSizeInvalid failed: VFTable=0x19fc2bc LTESize=0x40 GTESize=0x6c Constraint checks failed, retracting guess! Fail-Retracting factClassSizeLTE(0x19fb9f8, 0xfffffff)... Fail-Asserting factClassSizeGTE(0x19fce0c, 0x4)... Fail-Retracting factClassSizeGTE(0x19fce0c, 0x3c)... Fail-Asserting factClassSizeGTE(0x19fc2dc, 0x4)... Fail-Retracting factClassSizeGTE(0x19fc2dc, 0x3c)... Fail-Retracting factVFTableSizeGTE(0x19fc2bc, 0x6c)... Fail-Retracting factClassSizeLTE(0x19fc2bc, 0xfffffff)... Fail-Asserting factClassSizeLTE(0x12d48a0, 0xfffffff)... Fail-Retracting factClassSizeGTE(0x19fc2bc, 0x3c)... Fail-Asserting factClassSizeGTE(0x12d48a0, 0x3c)... Fail-Asserting factClassRelatedMethod(0x12d48a0, 0x12f1270)... Fail-Retracting factClassRelatedMethod(0x19fc2bc, 0x12bf200)... Fail-Asserting factClassRelatedMethod(0x12d48a0, 0x12bf200)... Fail-Retracting findint(0x12d48a0, 0x19fc2bc)... Fail-Asserting findint(0x12d48a0, 0x12d48a0)... Fail-Retracting factClassSizeLTE(0x12d48a0, 0xfffffff)... setting numGroup to 0x2 failed so setting to 1 Fail-Retracting guessedConstructor(0x12d48a0)... Fail-Retracting factConstructor(0x12d48a0)... The guess tryConstructor(0x12d48a0) was inconsistent with a valid solution. Guessing tryNOTConstructor(0x12d48a0) instead. Guessing factNOTConstructor(0x12d48a0). Old numGroup is (again) 0x1 New numGroup is 0x2 There are 3,008,674 known facts. reasoningLoop: pre-reason sanityChecks Constraint checks succeeded, proceeding to reason forward! reasoningLoop: reasonForardAsManyTimesAsPossible reasonForwardAsManyTimesAsPossible Starting reasonForward. Concluding factDeletingDestructor(0x12d48a0). reasonForwardAsManyTimesAsPossible Starting reasonForward. reasonMergeVFTables_A(destructor, 0x19fc2bc, 0x12d48a0, 0x19fc2bc, 0, factVFTableWrite(0x12d48bb, 0x12d48a0, 0, 0x19fc2bc)). reasonMergeVFTables_A(constructor, 0x19e33ac, 0x19f0200, 0x19e33ac, 0x90, factVFTableWrite(0x128df59, 0x128dec0, 0x90, 0x19e33ac)). reasonMergeVFTables_A(destructor, 0x19e33ac, 0x19f0200, 0x19e33ac, 0x90, factVFTableWrite(0x128df59, 0x128dec0, 0x90, 0x19e33ac)). Concluding mergeVFTables(0x19fc2bc, 0x12d48a0). Merging class 0x12d48a0 into 0x19fc2bc ... Retracting factClassRelatedMethod(0x12d48a0, 0x12bf200) and asserting factClassRelatedMethod(0x19fc2bc, 0x12bf200) ... Retracting factClassRelatedMethod(0x12d48a0, 0x12f1270) and asserting factClassRelatedMethod(0x19fc2bc, 0x12f1270) ... Retracting factClassSizeGTE(0x12d48a0, 0x3c) and asserting factClassSizeGTE(0x19fc2bc, 0x3c) ... Objects now on 0x19fc2bc: [0x12d48a0, 0x19fc2bc] reasonForwardAsManyTimesAsPossible Starting reasonForward. reasonVFTableSizeGTE_B(0x19fc2bc, 0x19fc2bc, 0, 0x19fb9f8, 0x19fb9f8, 0x19fc2bc, 0x6c). Concluding factVFTableSizeGTE(0x19fc2bc, 0x6c). reasonForwardAsManyTimesAsPossible Starting reasonForward. reasonClassSizeGTE_C(0x19fc2bc, 0x19fc2dc, 0x3c). reasonClassSizeGTE_C(0x19fc2bc, 0x19fce0c, 0x3c). reasonClassSizeGTE_F(0x19fc2bc, 0x3c, 0, 0x19fce0c, 0x3c). reasonClassSizeGTE_F(0x19fc2bc, 0x3c, 0, 0x19fc2dc, 0x3c). Concluding factClassSizeGTE(0x19fce0c, 0x3c). Concluding factClassSizeGTE(0x19fc2dc, 0x3c). reasonForwardAsManyTimesAsPossible Starting reasonForward. Processing trigger fact... findint(0x12d48a0, 0x19fc2bc) Processing trigger fact... factClassSizeGTE(0x19fc2bc, 0x3c) Processing trigger fact... factClassSizeGTE(0x19fc2dc, 0x3c) Processing trigger fact... factClassSizeGTE(0x19fce0c, 0x3c) reasonMergeVFTables_A(constructor, 0x19e33ac, 0x19f0200, 0x19e33ac, 0x90, factVFTableWrite(0x128df59, 0x128dec0, 0x90, 0x19e33ac)). reasonMergeVFTables_A(destructor, 0x19e33ac, 0x19f0200, 0x19e33ac, 0x90, factVFTableWrite(0x128df59, 0x128dec0, 0x90, 0x19e33ac)). reasonForwardAsManyTimesAsPossible complete. reasoningLoop: post-reason sanityChecks Consistency checks failed. insanityVFTableSizeInvalid failed: VFTable=0x19fc2bc LTESize=0x40 GTESize=0x6c Constraint checks failed, retracting guess! Fail-Asserting factClassSizeGTE(0x19fce0c, 0x4)... Fail-Retracting factClassSizeGTE(0x19fce0c, 0x3c)... Fail-Asserting factClassSizeGTE(0x19fc2dc, 0x4)... Fail-Retracting factClassSizeGTE(0x19fc2dc, 0x3c)... Fail-Retracting factVFTableSizeGTE(0x19fc2bc, 0x6c)... Fail-Retracting factClassSizeGTE(0x19fc2bc, 0x3c)... Fail-Asserting factClassSizeGTE(0x12d48a0, 0x3c)... Fail-Asserting factClassRelatedMethod(0x12d48a0, 0x12f1270)... Fail-Retracting factClassRelatedMethod(0x19fc2bc, 0x12bf200)... Fail-Asserting factClassRelatedMethod(0x12d48a0, 0x12bf200)... Fail-Retracting findint(0x12d48a0, 0x19fc2bc)... Fail-Asserting findint(0x12d48a0, 0x12d48a0)... Fail-Retracting factDeletingDestructor(0x12d48a0)... setting numGroup to 0x2 failed so setting to 1 Fail-Retracting guessedNOTConstructor(0x12d48a0)... Fail-Retracting factNOTConstructor(0x12d48a0)... tryBinarySearch completely failed on [0x12d48a0] and will now backtrack to fix an upstream problem. guess: We have back-tracked to the call of tryBinarySearch(tryConstructor, tryNOTConstructor, [0x12d48a0, 0x12d1a70, 0x12c0990, 0x1213f30, 0x11dfbc0, 0x11d8450, 0x11cbd10, 0x1187af0, 0x11794e0, 0x1152290, 0x11477f0, 0x10f8a30, 0x109c890, 0x108f410, 0xfee290, 0xf91ca0, 0xf54990, 0xf3be50, 0xf37550, 0xef5290, 0xee85b0, 0xee4650, 0xedf650, 0xed7980, 0xed7540, 0xed73d0, 0xe882f0, 0xe88000, 0xe81030, 0xe80510, 0xe7f3e0, 0xe7e5f0, 0xe7bf40, 0xe7b680, 0xe7a030, 0xe79f70, 0xe79e50, 0xe78080, 0xe6f0a0, 0xe654c0, 0xe5f940, 0xe56cb0, 0xe56680, 0xe50820, 0xe44620, 0xe41c20, 0xe3ac10, 0xe304a0, 0xdf4ab0, 0xdc2270, 0xcc28b0, 0xcb84c0, 0xc93860, 0xc09fe0, 0xbe5c60, 0xb8d530, 0xb83060, 0xb55e20, 0xb280b0, 0xb231b0, 0xb22060, 0xaf3790, 0xaf3610, 0xaead20, 0xae2c30, 0xad04e0, 0xac97f0, 0xac5690, 0xac4440, 0xac4410, 0xac11e0, 0xac0530, 0xac0370, 0xac01c0, 0xabff40, 0xabf1b0, 0xabebb0, 0xabe2b0, 0xabd400, 0xabb6b0, 0xabb670, 0xaba3f0, 0xab6300, 0xab5980, 0xab5930, 0xa5a790, 0xa51bb0, 0xa51b70, 0xa4c170, 0xa3b200, 0xa3b1f0, 0xa3b1e0, 0xa3b1d0, 0xa36fa0, 0xa1cbe0, 0xa1bc90, 0xa19060, 0xa18840, 0xa18710, 0xa18620, 0xa178e0, 0x9ed440, 0x9dc380, 0x9daae0, 0x9da1e0, 0x9da0d0, 0x9d9e10, 0x9d9900, 0x9d7010, 0x972570, 0x967960, 0x948320, 0x945d80, 0x93e360, 0x93bde0, 0x935360, 0x9319d0, 0x9296f0, 0x913c20, 0x8effe0, 0x8e9980, 0x8e8310, 0x8d2b90, 0x8c5d30, 0x8c1660, 0x8be1f0, 0x8ba980, 0x899e40, 0x895390, 0x88c9e0, 0x889160, 0x888a30, 0x87cb40, 0x87b800, 0x87b6f0, 0x879c80, 0x8795b0, 0x878d50, 0x877e10, 0x877550, 0x876500, 0x8764d0, 0x876340, 0x8762a0, 0x875fc0, 0x86bcb0, 0x8690b0, 0x868fd0, 0x867e30, 0x8635d0, 0x8635a0, 0x861a10, 0x85d1c0, 0x84e3e0, 0x8321f0, 0x832140, 0x831940, 0x831760, 0x80f850, 0x80f6c0, 0x806e90, 0x7ff6b0, 0x7f83b0, 0x7e83a0, 0x7e8170, 0x7de0a0, 0x7c3020, 0x7835f0, 0x782ad0, 0x782990, 0x782840, 0x76f100, 0x762f20, 0x747fc0, 0x7477b0, 0x7476f0, 0x7472c0, 0x747190, 0x7470b0, 0x747030, 0x6f93e0, 0x69d010, 0x69c9a0, 0x698b90, 0x6904d0, 0x688d10, 0x614150, 0x5c5f60, 0x589510, 0x5874a0, 0x586f10, 0x5865d0, 0x584f50, 0x582b30, 0x582740, 0x57fe60, 0x57f590, 0x57e6e0, 0x578330, 0x575f00, 0x570280, 0x561500, 0x561370, 0x550460, 0x545990, 0x5352d0, 0x531870, 0x52fbc0, 0x526960, 0x4b4540, 0x47c9c0, 0x453ee0, 0x453eb0, 0x433570, 0x433510, 0x404820, 0x4041d0, 0x6b4c90, 0x846f70, 0x8467d0, 0x6b4d20, 0x13999e0, 0x1275bc0, 0x12230f0, 0x1203090, 0x12028c0, 0x11fbe00, 0x11f74c0, 0xf0dc00, 0xeb77f0, 0xeaf540, 0xeaaa70, 0xea40e0, 0xea3f20, 0xea3e30, 0xea2f00, 0xe91600, 0xd5fd60, 0xd5f4a0, 0xd5e2d0, 0xc800f0, 0xc0b370, 0x466880, 0x4665b0, 0x4642d0, 0x933170, 0x524d20, 0x12f3c10, 0x12f3140, 0x5551c0, 0x525880, 0xef5860, 0xd61720, 0xd03400, 0x8e9280, 0x8e91e0, 0x8e9140, 0x8e90a0, 0x8e9000, 0x8e8f60, 0x8e8ec0, 0x8e8e20, 0x8e8bb0, 0x7d85d0, 0x551e70, 0x133a0ba, 0x12d4340, 0x869e20, 0x862830, 0x5ad460]) 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! ```
sei-eschwartz commented 3 years ago

ooanalyzer claims that no delete() methods were found but the facts file contains insnCallsDelete lines that seem identical to the previous facts file (except the last column).

And the previous run did not say that? @sei-ccohen sounds like the warning might be incorrect for the new tag based system... I'm going to create a separate issue for that.

sei-eschwartz commented 3 years ago
[eschwartz@pd4 analysis]$ cat -n ../code/testcases/legoavengers/unknown.exe.results.log | fgrep 'VFTableSizeGTE' | fgrep '0x6c).'                                                                                                                                                                                                                     
17563784        reasonVFTableSizeGTE_A(0x192389c, 0x6c).
17563869        reasonVFTableSizeGTE_A(0x194d444, 0x6c).
17564339        Concluding factVFTableSizeGTE(0x194d444, 0x6c).
17564930        Concluding factVFTableSizeGTE(0x192389c, 0x6c).
18251192        Fail-Retracting factVFTableSizeGTE(0x194d444, 0x6c)...
18251277        Fail-Retracting factVFTableSizeGTE(0x192389c, 0x6c)...
18338065        reasonVFTableSizeGTE_A(0x194d444, 0x6c).
18338099        Concluding factVFTableSizeGTE(0x194d444, 0x6c).
18380125        Fail-Retracting factVFTableSizeGTE(0x194d444, 0x6c)...
18382623        reasonVFTableSizeGTE_A(0x194d444, 0x6c).
18382642        Concluding factVFTableSizeGTE(0x194d444, 0x6c).
18740005        reasonVFTableSizeGTE_A(0x19bed24, 0x6c).
18740027        Concluding factVFTableSizeGTE(0x19bed24, 0x6c).
18831387        reasonVFTableSizeGTE_A(0x192389c, 0x6c).
18831797        Concluding factVFTableSizeGTE(0x192389c, 0x6c).
19223024        reasonVFTableSizeGTE_A(0x19fb9f8, 0x6c).
19223063        Concluding factVFTableSizeGTE(0x19fb9f8, 0x6c).
19340871        reasonVFTableSizeGTE_B(0x19fc2bc, 0x19fc2bc, 0, 0x19fb9f8, 0x19fb9f8, 0x19fc2bc, 0x6c).
19340872        Concluding factVFTableSizeGTE(0x19fc2bc, 0x6c).
19421129        Fail-Retracting factVFTableSizeGTE(0x19fc2bc, 0x6c)...
19438746        reasonVFTableSizeGTE_B(0x19fc2bc, 0x19fc2bc, 0, 0x19fb9f8, 0x19fb9f8, 0x19fc2bc, 0x6c).
19438747        Concluding factVFTableSizeGTE(0x19fc2bc, 0x6c).
19439307        Fail-Retracting factVFTableSizeGTE(0x19fc2bc, 0x6c)...
19439547        reasonVFTableSizeGTE_B(0x19fc2bc, 0x19fc2bc, 0, 0x19fb9f8, 0x19fb9f8, 0x19fc2bc, 0x6c).
19439548        Concluding factVFTableSizeGTE(0x19fc2bc, 0x6c).
19439776        Fail-Retracting factVFTableSizeGTE(0x19fc2bc, 0x6c)...
19439906        reasonVFTableSizeGTE_B(0x19fc2bc, 0x19fc2bc, 0, 0x19fb9f8, 0x19fb9f8, 0x19fc2bc, 0x6c).
19439907        Concluding factVFTableSizeGTE(0x19fc2bc, 0x6c).
19440035        Fail-Retracting factVFTableSizeGTE(0x19fc2bc, 0x6c)...
19440109        reasonVFTableSizeGTE_B(0x19fc2bc, 0x19fc2bc, 0, 0x19fb9f8, 0x19fb9f8, 0x19fc2bc, 0x6c).
19440110        Concluding factVFTableSizeGTE(0x19fc2bc, 0x6c).
19440168        Fail-Retracting factVFTableSizeGTE(0x19fc2bc, 0x6c)...
19440216        reasonVFTableSizeGTE_B(0x19fc2bc, 0x19fc2bc, 0, 0x19fb9f8, 0x19fb9f8, 0x19fc2bc, 0x6c).
19440217        Concluding factVFTableSizeGTE(0x19fc2bc, 0x6c).
19440250        Fail-Retracting factVFTableSizeGTE(0x19fc2bc, 0x6c)...
19440289        reasonVFTableSizeGTE_B(0x19fc2bc, 0x19fc2bc, 0, 0x19fb9f8, 0x19fb9f8, 0x19fc2bc, 0x6c).
19440290        Concluding factVFTableSizeGTE(0x19fc2bc, 0x6c).
19440316        Fail-Retracting factVFTableSizeGTE(0x19fc2bc, 0x6c)...

0x192389c looks like it is 0x5c to me, but there appears to be RTTI after the vftable. OOAnalyzer might be getting that confused? I don't think that is the root problem of this issue but it is concerning.

0x194d444 looks only to be 0x18 large. So that is probably the root of the problem. According to IDA, there is another vftable at 0194D460.

But OOAnalyzer does not think so:

[eschwartz@pd4 analysis]$ cat -n ../code/testcases/legoavengers/unknown.exe.facts | fgrep -e 194d444 -e 194d460                                                                                                                                                                                                                                     
170233  possibleVFTableWrite(0xcc9512, 0xcc94f0, 0, 0x194d444).
223726  initialMemory(0x194d444, 0xce19a0).
223733  initialMemory(0x194d460, 0xce19a0).

VFTable 0x194d460 is installed at 0x8c8984.

I just looked at the facts file I generated, which just completed overnight, and:

[eschwartz@pd4 analysis]$ cat -n ../code/testcases/legoavengers/LEGOMARVELAvengers.exe.facts | fgrep -e 194d444 -e 194d460                                               
379858  possibleVFTableWrite(0xcc9512, 0xcc94f0, 0, 0x194d444).
379859  possibleVFTableWrite(0xcc9584, 0xcc9540, 0, 0x194d460).
533810  initialMemory(0x194d444, 0xce19a0).
533817  initialMemory(0x194d460, 0xce19a0).

And looking at your new facts file:

/tmp $ cat ooprog-facts.pl | fgrep -e 194d444 -e 194d460
possibleVFTableWrite(0xcc9512, 0xcc94f0, 0, 0x194d444).
initialMemory(0x194d444, 0xce19a0).
initialMemory(0x194d460, 0xce19a0).

So for some reason, you are not finding the vftable install of 0x194d460. This may not be a prolog problem after all.

sei-eschwartz commented 3 years ago

My guess right now is that one of the options you are using is causing us to miss the vftable install. Maybe --no-semantics or --partitioner=rose? I'm rerunning with those to see if the problem still happens.

FTR, I was using only --maximum-memory 100000 during partitioning and --threads=1 --per-function-timeout=60 --maximum-memory 100000 during fact generation.

Here is the facts file I produced. You might want to try running that through ooprolog.

sei-ccohen commented 3 years ago

Just guessing here, but --partitioner=rose seems like the more likely culprit in this case than --no-semantics. Both options are expensive in resources & run-time but improve the results. We don't test the multi-threaded option as often and as well as we should but if you've got the resources for it, that should help speed up the fact generation after partitioning. Sadly the partitioner is still single-threaded.

sei-eschwartz commented 3 years ago

Rerunning with --maximum-memory 100000 --threads=4 --no-semantics --per-function-timeout=99999 --apidb=contrib/setupapi.json --partitioner=rose I was able to reproduce the problem.

RolphWoggom commented 3 years ago

And the previous run did not say that? @sei-ccohen sounds like the warning might be incorrect for the new tag based system... I'm going to create a separate issue for that.

Correct, the previous run did not say that.

Here is the facts file I produced. You might want to try running that through ooprolog.

I'll run ooprolog --facts ooprog-facts.pl --results ooprog-results.pl --log-level=7 >ooprog.log and post the results.

Rerunning with --maximum-memory 100000 --threads=4 --no-semantics --per-function-timeout=99999 --apidb=contrib/setupapi.json --partitioner=rose I was able to reproduce the problem.

Should I still run ooprolog on your facts file?

sei-eschwartz commented 3 years ago

Should I still run ooprolog on your facts file?

Yes, the facts file I posted earlier is different and as far as I know should work.

We still have to figure out what to do about the facts issue. Is the problem in the fact generator? Prolog?

RolphWoggom commented 3 years ago

Yes, the facts file I posted earlier is different and as far as I know should work.

I got a seg fault with it. I accidentally used log level 5, the log is available here.

``` root@ac5043e99b2f:/workdir# ooprolog --facts lego.facts --results ooprog-results.pl --log-level=5 >ooprog.log SWI-Prolog [thread 1 (main) at Mon May 3 01:56:16 2021]: received fatal signal 11 (segv) C-stack trace labeled "crash": [0] save_backtrace() at /root/pharos/scripts/swipl-devel/build/../src/os/pl-cstack.c:332 [0x7fd7a1cace75] [1] print_c_backtrace() at /root/pharos/scripts/swipl-devel/build/../src/os/pl-cstack.c:867 [0x7fd7a1cad043] [2] sigCrashHandler() at /root/pharos/scripts/swipl-devel/build/../src/os/pl-cstack.c:905 [0x7fd7a1cad15a] [3] dispatch_signal() at /root/pharos/scripts/swipl-devel/build/../src/pl-setup.c:547 [0x7fd7a1c35a4e] [4] killpg() at ??:? [0x7fd7a19d7210] [5] visibleClause__LD() at /root/pharos/scripts/swipl-devel/build/../src/pl-inline.h:508 (discriminator 3) [0x7fd7a1bb7ef3] [6] first_clause_guarded() at /root/pharos/scripts/swipl-devel/build/../src/pl-index.c:514 [0x7fd7a1bb78a9] [7] firstClause() at /root/pharos/scripts/swipl-devel/build/../src/pl-index.c:562 [0x7fd7a1bb8f5f] [8] PL_next_solution() at /root/pharos/scripts/swipl-devel/build/../src/pl-vmi.c:3125 [0x7fd7a1bca397] [9] callProlog() at /root/pharos/scripts/swipl-devel/build/../src/pl-pro.c:398 [0x7fd7a1c1acf5] [10] pl_with_output_to2_va() at /root/pharos/scripts/swipl-devel/build/../src/os/pl-file.c:1559 [0x7fd7a1c9189e] [11] PL_next_solution() at /root/pharos/scripts/swipl-devel/build/../src/pl-vmi.c:4209 [0x7fd7a1bd404d] [12] query_loop() at /root/pharos/scripts/swipl-devel/build/../src/pl-pro.c:148 [0x7fd7a1c1a822] [13] prologToplevel() at /root/pharos/scripts/swipl-devel/build/../src/pl-pro.c:490 [0x7fd7a1c1b0ff] [14] PL_initialise() at /root/pharos/scripts/swipl-devel/build/../src/pl-init.c:1167 [0x7fd7a1c5f63c] [15] swipl(+0x10eb) [0x55e8dd6c70eb] [16] __libc_start_main() at ??:? [0x7fd7a19b80b3] [17] swipl(+0x113e) [0x55e8dd6c713e] Prolog stack: [379] factNOTMergeClasses/2 [378] dynFactNOTMergeClasses/2 [PC=8 in clause 1] [377] not/1 [PC=6 in clause 1] [376] system:/1 [PC=15 in clause -1] [375] $bags:findall_loop/4 [PC=5 in clause 1] [374] system:setup_call_catcher_cleanup/4 [PC=5 in clause 1] [370] $bags:setof/3 [PC=29 in clause 1] [369] concludeNOTMergeClasses/1 [PC=56 in clause 1] [368] system:/1 [PC=194 in clause -1] [367] system:once/1 [PC=3 in clause 1] [366] reasonForward/0 [PC=253 in clause 1] [365] reasonForwardAsManyTimesAsPossible/0 [PC=7 in clause 1] [364] reasonForwardAsManyTimesAsPossible/0 [PC=14 in clause 1] [363] reasonForwardAsManyTimesAsPossible/0 [PC=14 in clause 1] [362] reasonForwardAsManyTimesAsPossible/0 [PC=14 in clause 1] [361] reasonForwardAsManyTimesAsPossible/0 [PC=14 in clause 1] [360] reasonForwardAsManyTimesAsPossible/0 [PC=14 in clause 1] [359] reasonForwardAsManyTimesAsPossible/0 [PC=14 in clause 1] [358] reasonForwardAsManyTimesAsPossible/0 [PC=14 in clause 1] [357] reasonForwardAsManyTimesAsPossible/0 [PC=14 in clause 1] [356] reasonForwardAsManyTimesAsPossible/0 [PC=14 in clause 1] ... ... [27] reasonForwardAsManyTimesAsPossible/0 [PC=14 in clause 1] [26] solve_internal/0 [PC=16 in clause 2] [25] system:catch/3 [PC=2 in clause 1] [24] solve/1 [PC=61 in clause 1] Running on_halt hooks with status 139 Killing 19 with default signal handlers Segmentation fault (core dumped) ```

Should I rerun with log level 7 after a restart?

sei-eschwartz commented 3 years ago

I got a seg fault with it. I accidentally used log level 5, the log is available here.

Should I rerun with log level 7 after a restart?

A seg fault in ooprolog is probably a SWI prolog bug. The first thing is to figure out how reproducible it is. How long did it take to crash? I would try running again with log level 5 and see if it will crash consistently.

I have also been running it on my machine and it did not crash. But I was also (accidentally) using log level 7. I have restarted with log level 5 to see if I can reproduce the crash.

RolphWoggom commented 3 years ago

A seg fault in ooprolog is probably a SWI prolog bug. The first thing is to figure out how reproducible it is. How long did it take to crash? I would try running again with log level 5 and see if it will crash consistently.

It took about nine hours. I'll rerun the same command again tonight. How important is the log file? Is it ok if I only provide the command output?

sei-eschwartz commented 3 years ago

Log file is not important. It might be interesting to know the last few lines to see if it crashed at the same spot, but at this point I mostly want to know if you can trigger it consistently.

sei-eschwartz commented 3 years ago

Also, I have been running my facts file for 27 hours so far with no crash. Though I should probably mention I'm not running it in our docker environment. I should probably try that next.

RolphWoggom commented 3 years ago

Log file is not important. It might be interesting to know the last few lines to see if it crashed at the same spot, but at this point I mostly want to know if you can trigger it consistently.

Good to know, that fits inside a normal reply.

Usually when any step of ooanalyzer runs I pretty much let it have exclusive use of my machine. Not this time though because it had been running non stop for the past couple days I got tired of waiting around and just played some resource intensive games. That might have something to do with it.

We'll see in about nine hours because I just kicked off another run with your facts file and log level 5.

Also, I have been running my facts file for 27 hours so far with no crash. Though I should probably mention I'm not running it in our docker environment. I should probably try that next.

If you let that run finish please send me the results file :P

RolphWoggom commented 3 years ago

It's been running for about twelve hours now and seems to be stuck. I remember it got stuck last time too but continued after a while. It's at the same spot as last time, I have a script that reports the log file size and both times it got stuck it was at 2.2GB.

Here's the last 200 lines of the log:

``` Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0xd9b000). Concluding factReusedImplementation(0x1390700). Concluding factReusedImplementation(0x1390700). Concluding factReusedImplementation(0x139fd90). Concluding factReusedImplementation(0x139fd90). Concluding factReusedImplementation(0x139fd90). Concluding factReusedImplementation(0x139fd90). Concluding factReusedImplementation(0x139fd90). Concluding factReusedImplementation(0x139fd90). Concluding factReusedImplementation(0xe4fc50). Concluding factReusedImplementation(0xe4fc50). Concluding factReusedImplementation(0xe4fc50). Concluding factReusedImplementation(0xe56780). Starting reasonForward. Entering stage concludeMergeVFTables. Concluding mergeVFTables(0x197dce4, 0xe6f580). Merging class 0xe6f580 into 0x197dce4 ... Retracting factClassSizeGTE(0xe6f580, 0x4) and asserting factClassSizeGTE(0x197dce4, 0x4) ... Retracting factClassSizeLTE(0xe6f580, 0xfffffff) and asserting factClassSizeLTE(0x197dce4, 0xfffffff) ... Starting reasonForward. Concluding factClassSizeLTE(0x1847d3c, 0xfffffff). Concluding factClassSizeLTE(0x1831d94, 0xfffffff). Concluding factClassSizeLTE(0x18df244, 0xfffffff). Starting reasonForward. Concluding mergeVFTables(0x184bbdc, 0x47ac90). Merging class 0x47ac90 into 0x184bbdc ... Retracting factClassSizeGTE(0x47ac90, 0xa8) and asserting factClassSizeGTE(0x184bbdc, 0xa8) ... Retracting factClassSizeLTE(0x47ac90, 0xfffffff) and asserting factClassSizeLTE(0x184bbdc, 0xfffffff) ... Retracting factNOTMergeClasses(0x45ab60, 0x47ac90) and asserting factNOTMergeClasses(0x45ab60, 0x184bbdc) ... Retracting factNOTMergeClasses(0x47ac90, 0x7092b0) and asserting factNOTMergeClasses(0x184bbdc, 0x7092b0) ... Retracting factNOTMergeClasses(0x47ac90, 0xa81fd0) and asserting factNOTMergeClasses(0x184bbdc, 0xa81fd0) ... Starting reasonForward. Concluding factClassSizeGTE(0x184c88c, 0xa8). Starting reasonForward. Concluding factNOTMergeClasses(0xa81fd0, 0x184c88c). Concluding factNOTMergeClasses(0xa81fd0, 0x184c88c). Concluding factNOTMergeClasses(0x7092b0, 0x184c88c). Concluding factNOTMergeClasses(0x45ab60, 0x184c88c). Starting reasonForward. Concluding mergeVFTables(0x18ed4a4, 0xa52200). Merging class 0xa52200 into 0x18ed4a4 ... Retracting factClassSizeGTE(0xa52200, 0x884) and asserting factClassSizeGTE(0x18ed4a4, 0x884) ... Retracting factClassSizeLTE(0xa52200, 0xfffffff) and asserting factClassSizeLTE(0x18ed4a4, 0xfffffff) ... Retracting factNOTMergeClasses(0x45ab60, 0xa52200) and asserting factNOTMergeClasses(0x45ab60, 0x18ed4a4) ... Retracting factNOTMergeClasses(0x4cbec0, 0xa52200) and asserting factNOTMergeClasses(0x4cbec0, 0x18ed4a4) ... Retracting factNOTMergeClasses(0x7092b0, 0xa52200) and asserting factNOTMergeClasses(0x7092b0, 0x18ed4a4) ... Retracting factNOTMergeClasses(0x7ddbe0, 0xa52200) and asserting factNOTMergeClasses(0x7ddbe0, 0x18ed4a4) ... Retracting factNOTMergeClasses(0x7f6490, 0xa52200) and asserting factNOTMergeClasses(0x7f6490, 0x18ed4a4) ... Retracting factNOTMergeClasses(0xa52200, 0xa81fd0) and asserting factNOTMergeClasses(0x18ed4a4, 0xa81fd0) ... Starting reasonForward. Concluding factClassSizeGTE(0x1995e44, 0x884). Starting reasonForward. Concluding factClassSizeLTE(0x18b4844, 0xfffffff). Concluding factClassSizeLTE(0x18b6d94, 0xfffffff). Starting reasonForward. Concluding factNOTMergeClasses(0x7ddbe0, 0x1995e44). Concluding factNOTMergeClasses(0xa81fd0, 0x1995e44). Concluding factNOTMergeClasses(0xa81fd0, 0x1995e44). Concluding factNOTMergeClasses(0x7f6490, 0x1995e44). Concluding factNOTMergeClasses(0x7092b0, 0x1995e44). Concluding factNOTMergeClasses(0x4cbec0, 0x1995e44). Concluding factNOTMergeClasses(0x45ab60, 0x1995e44). Starting reasonForward. Concluding mergeVFTables(0x19c0f80, 0x113ead0). Merging class 0x113ead0 into 0x19c0f80 ... Retracting factClassSizeGTE(0x113ead0, 0x20) and asserting factClassSizeGTE(0x19c0f80, 0x20) ... Retracting factNOTMergeClasses(0x7092b0, 0x113ead0) and asserting factNOTMergeClasses(0x7092b0, 0x19c0f80) ... Starting reasonForward. Concluding mergeVFTables(0x18bcc64, 0x8522b0). Merging class 0x8522b0 into 0x18bcc64 ... Retracting factClassSizeGTE(0x8522b0, 0x144) and asserting factClassSizeGTE(0x18bcc64, 0x144) ... Retracting factNOTMergeClasses(0x45ab60, 0x8522b0) and asserting factNOTMergeClasses(0x45ab60, 0x18bcc64) ... Retracting factNOTMergeClasses(0x7092b0, 0x8522b0) and asserting factNOTMergeClasses(0x7092b0, 0x18bcc64) ... Retracting factNOTMergeClasses(0x7ddbe0, 0x8522b0) and asserting factNOTMergeClasses(0x7ddbe0, 0x18bcc64) ... Retracting factNOTMergeClasses(0x7f6490, 0x8522b0) and asserting factNOTMergeClasses(0x7f6490, 0x18bcc64) ... Retracting factNOTMergeClasses(0x8522b0, 0xa81fd0) and asserting factNOTMergeClasses(0x18bcc64, 0xa81fd0) ... Starting reasonForward. Concluding mergeVFTables(0x19f273c, 0x127d320). Merging class 0x127d320 into 0x19f273c ... Retracting factClassSizeGTE(0x127d320, 0x80) and asserting factClassSizeGTE(0x19f273c, 0x80) ... Retracting factClassSizeLTE(0x127d320, 0xfffffff) and asserting factClassSizeLTE(0x19f273c, 0xfffffff) ... Retracting factNOTMergeClasses(0x45ab60, 0x127d320) and asserting factNOTMergeClasses(0x45ab60, 0x19f273c) ... Retracting factNOTMergeClasses(0x7092b0, 0x127d320) and asserting factNOTMergeClasses(0x7092b0, 0x19f273c) ... Starting reasonForward. Concluding factClassSizeLTE(0x1842344, 0xfffffff). Concluding factClassSizeLTE(0x1831fcc, 0xfffffff). Concluding factClassSizeLTE(0x19e3e9c, 0xfffffff). Concluding factClassSizeLTE(0x18b4bc0, 0xfffffff). Concluding factClassSizeLTE(0x1842320, 0xfffffff). Concluding factClassSizeLTE(0x18aff94, 0xfffffff). Concluding factClassSizeLTE(0x18b6b84, 0xfffffff). Concluding factClassSizeLTE(0x1842188, 0xfffffff). Concluding factClassSizeLTE(0x18b6b8c, 0xfffffff). Concluding factClassSizeLTE(0x1864e68, 0xfffffff). Concluding factClassSizeLTE(0x1864e48, 0xfffffff). Concluding factClassSizeLTE(0x1842170, 0xfffffff). Concluding factClassSizeLTE(0x1842010, 0xfffffff). Concluding factClassSizeLTE(0x1842194, 0xfffffff). Concluding factClassSizeLTE(0x18a767c, 0xfffffff). Concluding factClassSizeLTE(0x1831fd4, 0xfffffff). Concluding factClassSizeLTE(0x1831fb4, 0xfffffff). Concluding factClassSizeLTE(0x19e3ea4, 0xfffffff). Concluding factClassSizeLTE(0x19e3e84, 0xfffffff). Concluding factClassSizeLTE(0x1842338, 0xfffffff). Concluding factClassSizeLTE(0x1867674, 0xfffffff). Starting reasonForward. Concluding mergeVFTables(0x18d5cec, 0x94da80). Merging class 0x94da80 into 0x18d5cec ... Retracting factClassSizeGTE(0x94da80, 0x68) and asserting factClassSizeGTE(0x18d5cec, 0x68) ... Retracting factClassSizeLTE(0x94da80, 0xfffffff) and asserting factClassSizeLTE(0x18d5cec, 0xfffffff) ... Retracting factNOTMergeClasses(0x7092b0, 0x94da80) and asserting factNOTMergeClasses(0x7092b0, 0x18d5cec) ... Starting reasonForward. Concluding factClassSizeLTE(0x18b1acc, 0xfffffff). Starting reasonForward. Concluding mergeVFTables(0x19ded64, 0x11f8760). Merging class 0x11f8760 into 0x19ded64 ... Retracting factClassSizeGTE(0x11f8760, 0x68) and asserting factClassSizeGTE(0x19ded64, 0x68) ... Retracting factNOTMergeClasses(0x7092b0, 0x11f8760) and asserting factNOTMergeClasses(0x7092b0, 0x19ded64) ... Starting reasonForward. Concluding mergeVFTables(0x19f063c, 0x128e4d0). Merging class 0x128e4d0 into 0x19f063c ... Retracting factClassSizeGTE(0x128e4d0, 0x324) and asserting factClassSizeGTE(0x19f063c, 0x324) ... Retracting factNOTMergeClasses(0x45ab60, 0x128e4d0) and asserting factNOTMergeClasses(0x45ab60, 0x19f063c) ... Retracting factNOTMergeClasses(0x4cbec0, 0x128e4d0) and asserting factNOTMergeClasses(0x4cbec0, 0x19f063c) ... Retracting factNOTMergeClasses(0x7092b0, 0x128e4d0) and asserting factNOTMergeClasses(0x7092b0, 0x19f063c) ... Retracting factNOTMergeClasses(0x7ddbe0, 0x128e4d0) and asserting factNOTMergeClasses(0x7ddbe0, 0x19f063c) ... Retracting factNOTMergeClasses(0x7f6490, 0x128e4d0) and asserting factNOTMergeClasses(0x7f6490, 0x19f063c) ... Retracting factNOTMergeClasses(0xa81fd0, 0x128e4d0) and asserting factNOTMergeClasses(0xa81fd0, 0x19f063c) ... Starting reasonForward. Concluding mergeVFTables(0x18d9ee4, 0x995850). Merging class 0x995850 into 0x18d9ee4 ... Retracting factClassSizeGTE(0x995850, 0x44) and asserting factClassSizeGTE(0x18d9ee4, 0x44) ... Retracting factClassSizeLTE(0x995850, 0xfffffff) and asserting factClassSizeLTE(0x18d9ee4, 0xfffffff) ... Retracting factNOTMergeClasses(0x7092b0, 0x995850) and asserting factNOTMergeClasses(0x7092b0, 0x18d9ee4) ... Starting reasonForward. Concluding factClassSizeLTE(0x18be37c, 0xfffffff). Starting reasonForward. Concluding mergeVFTables(0x18d9ee4, 0x995620). Merging class 0x995620 into 0x18d9ee4 ... Retracting factClassSizeGTE(0x995620, 0x44) and asserting factClassSizeGTE(0x18d9ee4, 0x44) ... Retracting factClassSizeLTE(0x995620, 0xfffffff) and asserting factClassSizeLTE(0x18d9ee4, 0xfffffff) ... Retracting factNOTMergeClasses(0x7092b0, 0x995620) and asserting factNOTMergeClasses(0x7092b0, 0x18d9ee4) ... Starting reasonForward. Concluding mergeVFTables(0x19e77a8, 0x1228e20). Merging class 0x1228e20 into 0x19e77a8 ... Retracting factClassSizeGTE(0x1228e20, 0x4) and asserting factClassSizeGTE(0x19e77a8, 0x4) ... Retracting factClassSizeLTE(0x1228e20, 0xfffffff) and asserting factClassSizeLTE(0x19e77a8, 0xfffffff) ... Starting reasonForward. Concluding factClassSizeLTE(0x1831d20, 0xfffffff). Concluding factClassSizeLTE(0x1847554, 0xfffffff). Starting reasonForward. Concluding mergeVFTables(0x1971eec, 0xdfac60). Merging class 0xdfac60 into 0x1971eec ... Retracting factClassSizeGTE(0xdfac60, 0xb4) and asserting factClassSizeGTE(0x1971eec, 0xb4) ... Retracting factClassSizeLTE(0xdfac60, 0xfffffff) and asserting factClassSizeLTE(0x1971eec, 0xfffffff) ... Retracting factNOTMergeClasses(0x45ab60, 0xdfac60) and asserting factNOTMergeClasses(0x45ab60, 0x1971eec) ... Retracting factNOTMergeClasses(0x7092b0, 0xdfac60) and asserting factNOTMergeClasses(0x7092b0, 0x1971eec) ... Retracting factNOTMergeClasses(0xa81fd0, 0xdfac60) and asserting factNOTMergeClasses(0xa81fd0, 0x1971eec) ... Starting reasonForward. Concluding mergeVFTables(0x1a3ca48, 0x1398f50). Merging class 0x1398f50 into 0x1a3ca48 ... Retracting factClassSizeGTE(0x1398f50, 0xc) and asserting factClassSizeGTE(0x1a3ca48, 0xc) ... Starting reasonForward. Concluding mergeVFTables(0x1939acc, 0xc53700). Merging class 0xc53700 into 0x1939acc ... Retracting factClassSizeGTE(0xc53700, 0x7c) and asserting factClassSizeGTE(0x1939acc, 0x7c) ... Retracting factClassSizeLTE(0xc53700, 0xfffffff) and asserting factClassSizeLTE(0x1939acc, 0xfffffff) ... Retracting factNOTMergeClasses(0x45ab60, 0xc53700) and asserting factNOTMergeClasses(0x45ab60, 0x1939acc) ... Retracting factNOTMergeClasses(0x7092b0, 0xc53700) and asserting factNOTMergeClasses(0x7092b0, 0x1939acc) ... Starting reasonForward. ```

There is a lot of factReusedImplementation with the same address multiple times before that.

htop shows:

    PID USER      PRI  NI  VIRT▽  RES   SHR S CPU% MEM%   TIME+  Command (merged)
   3362 root       20   0 83.3G 8162M     0 S  0.0 34.0 51:22.92 gc│swipl /usr/local/bin/ooprolog --facts lego.facts --results ooprog-results.pl --log-level=5

No CPU usage for a while now.

sei-eschwartz commented 3 years ago

I don't think I've ever seen SWI have 0 cpu while it is running. That is not a good sign. When is the last time you checked your ram?

Maybe try strace -p 3362 or gdb -p 3362 and try to see what it is doing?

Mine is still running, though as your log showed, the output is very intermittent. This is not uncommon for very large programs, but it suggests that it will take a very long time to run. I will try to open in a profiler when I have a chance to see if there is anything we can speed up.

RolphWoggom commented 3 years ago

I don't think I've ever seen SWI have 0 cpu while it is running. That is not a good sign. When is the last time you checked your ram?

Never. I can try Memtest86+ if that's what you mean.

Maybe try strace -p 3362 or gdb -p 3362 and try to see what it is doing?

strace:

$ sudo strace -p 3362
strace: Process 3362 attached
futex(0x7f3c7cc105f0, FUTEX_WAIT_PRIVATE, 0, NULL

gdb:

$ sudo gdb -p 3362
GNU gdb (GDB) 10.1
Copyright (C) 2020 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-pc-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word".
Attaching to process 3362
Reading symbols from target:/usr/local/lib/swipl/bin/x86_64-linux/swipl...
Reading symbols from target:/usr/local/lib/swipl/lib/x86_64-linux/libswipl.so.8...
Reading symbols from target:/lib/x86_64-linux-gnu/libc.so.6...
(No debugging symbols found in target:/lib/x86_64-linux-gnu/libc.so.6)
Reading symbols from target:/lib/x86_64-linux-gnu/libtinfo.so.6...
(No debugging symbols found in target:/lib/x86_64-linux-gnu/libtinfo.so.6)
Reading symbols from target:/lib/x86_64-linux-gnu/libz.so.1...
(No debugging symbols found in target:/lib/x86_64-linux-gnu/libz.so.1)
Reading symbols from target:/lib/x86_64-linux-gnu/libpthread.so.0...
(No debugging symbols found in target:/lib/x86_64-linux-gnu/libpthread.so.0)

warning: Expected absolute pathname for libpthread in the inferior, but got target:/lib/x86_64-linux-gnu/libpthread.so.0.

warning: Unable to find libthread_db matching inferior's thread library, thread debugging will not be available.
Reading symbols from target:/lib/x86_64-linux-gnu/libdl.so.2...
(No debugging symbols found in target:/lib/x86_64-linux-gnu/libdl.so.2)
Reading symbols from target:/lib/x86_64-linux-gnu/libm.so.6...
(No debugging symbols found in target:/lib/x86_64-linux-gnu/libm.so.6)
Reading symbols from target:/lib64/ld-linux-x86-64.so.2...
(No debugging symbols found in target:/lib64/ld-linux-x86-64.so.2)
Reading symbols from target:/usr/local/lib/swipl/lib/x86_64-linux/memfile.so...
Reading symbols from target:/usr/local/lib/swipl/lib/x86_64-linux/json.so...

warning: Target and debugger are in different PID namespaces; thread lists and other data are likely unreliable.  Connect to gdbserver inside the container.

warning: Expected absolute pathname for libpthread in the inferior, but got target:/lib/x86_64-linux-gnu/libpthread.so.0.

warning: Unable to find libthread_db matching inferior's thread library, thread debugging will not be available.
0x00007f3c7c820376 in pthread_cond_wait@@GLIBC_2.3.2 () from target:/lib/x86_64-linux-gnu/libpthread.so.0

Mine is still running, though as your log showed, the output is very intermittent. This is not uncommon for very large programs, but it suggests that it will take a very long time to run. I will try to open in a profiler when I have a chance to see if there is anything we can speed up.

Mine has been running for 20 hours now and waiting for 15 of those. Seems like it's truly stuck. How long should I let it run for?

sei-eschwartz commented 3 years ago

Try running bt in gdb. It might help to run it from inside the container.

After that I think you can kill it. I think running memtest86 is probably a good idea...

RolphWoggom commented 3 years ago
(gdb) bt
#0  0x00007f3c7c820376 in pthread_cond_wait@@GLIBC_2.3.2 () from target:/lib/x86_64-linux-gnu/libpthread.so.0
#1  0x00007f3c7cb38b7f in pl_gc_wait1_va (PL__t0=140, PL__ac=<optimized out>, PL__ctx=<optimized out>) at ../src/pl-thread.c:6154
#2  0x00007f3c7cac204d in PL_next_solution (qid=qid@entry=98) at ../src/pl-vmi.c:4209
#3  0x00007f3c7cb08cf5 in callProlog (module=<optimized out>, module@entry=0x0, goal=goal@entry=89, flags=flags@entry=16, ex=ex@entry=0x0) at ../src/pl-pro.c:391
#4  0x00007f3c7caa2615 in pl_thread_idle2_va (PL__t0=89, PL__ac=<optimized out>, PL__ctx=<optimized out>) at ../src/pl-alloc.c:1897
#5  0x00007f3c7cac204d in PL_next_solution (qid=qid@entry=19) at ../src/pl-vmi.c:4209
#6  0x00007f3c7cacc6e8 in PL_call_predicate (ctx=ctx@entry=0x0, flags=flags@entry=16, pred=<optimized out>, h0=h0@entry=0) at ../src/pl-fli.c:4303
#7  0x00007f3c7cb421f6 in GCmain (closure=<optimized out>) at ../src/pl-thread.c:6035
#8  0x00007f3c7c819609 in start_thread () from target:/lib/x86_64-linux-gnu/libpthread.so.0
#9  0x00007f3c7c9a1293 in clone () from target:/lib/x86_64-linux-gnu/libc.so.6

Okay, memtest86 is next.

So if I understand correctly the crash and now the indefinite wait looks like it's caused by faulty memory and is not a bug in ooanalyzer, but the prolog facts issue looks like it is. Maybe it was caused by faulty memory during facts generation though, maybe the facts file I posted that you used to reproduce the facts issue with is corrupted.

sei-eschwartz commented 3 years ago

Looks like the main thread is waiting for garbage collection (which presumably got stuck for some reason).

I think bad memory is a possibility. But it's also possible that there is some bug in SWI that triggers memory corruption. We have seen this a number of times, but never the failure mode you are seeing.

I was able to reproduce the prolog facts issue. @sei-ccohen is still investigating, but it is a problem or shortcoming with the ROSE partitioner. That is not caused by a hardware issue.

RolphWoggom commented 3 years ago

Ah okay, thanks for the explanation!

I'll report back with the memtest results sometime this week.

sei-ccohen commented 3 years ago

Just to add my own two cents here... Part this problem is pretty clearly that using --partitioner=rose produces a set of facts that confuses the later Prolog analysis step. It would be nice if that option always worked as intended, but the truth is that it's primarily useful when the default Pharos partitioner doesn't complete in a reasonable amount of time. The ROSE partitioner should never produce more accurate or reliable results, just faster results. Especially given how large the sample is, and how long the Prolog step takes, it seems like a good idea to just not use that option in this case.

As for the memory corruption and SWI Prolog crashing issue, I'll phrase things slightly differently. We've not seen the crashes that you have, and the problem appears to be some kind of corruption in SWI Prolog itself, and not in "our" code. Since SWI Prolog is usually very reliable, that means something odd is happening on your end. sei-eschwartz has suggested bad memory. I thought maybe it was a "low-memory" bug caused when memory allocation failed, but I would have expected the process to have been killed a short while later for running out of memory, not just to get stuck in a loop. Whatever this bug is... It's weird.

RolphWoggom commented 3 years ago

Thank you for the additional info! I always used the ROSE partitioner without semantics because that's what the guide uses but I'll switch to trying your partitioner with semantics first and letting it run for a day or two before switching to ROSE and no semantics.

I don't think I'm running out of memory, I have 24GB RAM and a 128GB swap file (using swap slows down compression and the partitioner report by a lot, though). I tried memtest86 v9.0 free and let it run for one out of four passes without any errors. I'll do all four passes overnight though and will let you know.

sei-ccohen commented 3 years ago

We had a discussion about this yesterday internally. The guidance was mildly contradictory, and we've fixed that for the next release. The current recommendation is to use --no-semantics but NOT --partitioner=rose. Both options can affect the results, so it's hard to just say that this or that set of options is better than the other. Using --partitoner=rose is known to miss a lot of functions (especially those that are only called virtually) and that's a pretty serious problem for OO analysis. Without that option you get the longer running but more complete Pharos partitioner.

The --no-semantics option turns OFF the use of advanced semantics when disassembling, and that can miss stuff too, but is mostly affects analysis when the programs has obfuscated control flow, anti-reverse engineering, etc. Since those features are less common that virtual functions, you're probably ok with --no-semantics. The --no-semantics option is also particularly expensive because it emulates each instruction at least once during disassembly to identify branches that are never taken, compute advanced jump targets, etc.

If you're willing to be patient, you will get the best results without either option.

sei-eschwartz commented 3 years ago

My run has been going nowhere. I'm going to do some profiling to see if there are any places we can speed things up.

sei-eschwartz commented 3 years ago

The main problem seems to be concludeNOTMergeClasses taking ~93% of the runtime. The problem is that there is simply an enormous number of reasonNOTMergeClass answers; there are so many that it takes a long time to simply iterate through them and see which are new. We are working on a long term change called monotonic tabling that would help with this. But that's not ready for use yet.

I will need to think more about short term solutions.

sei-eschwartz commented 3 years ago

I'm experimenting with the following branch. Instead of trying to proactively assert all factNOTMergeClass facts, it largely computes them on demand. Trigger based rules are still computed eagerly. And indeed right now I'm stuck waiting on concludeTrigger to complete. Unsurprisingly, memory usage is fairly high because we're creating millions of tables.

sei-eschwartz commented 3 years ago

I was talking about 21541addcfc23c4369213166cf21c8a284d78e17 above. That didn't work well, I ran out of memory. So trying now with 54ef13ae97c234458fc82c6f7c5a9adab6a1c745. In that commit I changed the trigger rules back to normal rules. Hopefully if we just compute them "on demand" it will perform better.

sei-eschwartz commented 3 years ago

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))
RolphWoggom commented 3 years ago

We had a discussion about this yesterday internally. The guidance was mildly contradictory, and we've fixed that for the next release. The current recommendation is to use --no-semantics but NOT --partitioner=rose. Both options can affect the results, so it's hard to just say that this or that set of options is better than the other. Using --partitoner=rose is known to miss a lot of functions (especially those that are only called virtually) and that's a pretty serious problem for OO analysis. Without that option you get the longer running but more complete Pharos partitioner.

The --no-semantics option turns OFF the use of advanced semantics when disassembling, and that can miss stuff too, but is mostly affects analysis when the programs has obfuscated control flow, anti-reverse engineering, etc. Since those features are less common that virtual functions, you're probably ok with --no-semantics. The --no-semantics option is also particularly expensive because it emulates each instruction at least once during disassembly to identify branches that are never taken, compute advanced jump targets, etc.

If you're willing to be patient, you will get the best results without either option.

These are some great insights into what these options do, please add these explanations to the guide.

We are working on a long term change called monotonic tabling that would help with this. But that's not ready for use yet.

So trying now with 54ef13a. In that commit I changed the trigger rules back to normal rules. Hopefully if we just compute them "on demand" it will perform better.

I'm fine with waiting for monotonic tabling, can you approximate when it will land? But I can also test with your changes if that helps, are they available in a premade docker container?

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.

Aw, bummer. But from the other issue it sounds like the problem was identified, is it easy to fix it?

sei-eschwartz commented 3 years ago

I'm fine with waiting for monotonic tabling, can you approximate when it will land? But I can also test with your changes if that helps, are they available in a premade docker container?

There is no eta for monotonic tabling, and it's not sure to be successful.

There's no need to test with my changes though. I am experimenting with a few different options. But the first priority is fixing #181

Aw, bummer. But from the other issue it sounds like the problem was identified, is it easy to fix it?

Yes and no. I think we have a pretty good understanding of the problem. But because it takes so long to reach the problem in your program, I've been trying to trigger the problem in a small testcase to make sure we handle it correctly. This in turn revealed some other problems in OOAnalyzer (namely that OO calls can be inlined into non-OO functions, and OOAnalyzer doesn't handle these). That's probably just an issue with my test executable, and I doubt it is a problem with your executable. But I want to make sure my fix works before waiting another 16 days or however long it took to crash.

RolphWoggom commented 3 years ago

I'm not sure if this is what you mean but I've seen inlined constructors and destructors before, can't remember if they were inside a thiscall or not. I suspect that I've also seen regular functions being inlined, that was definitely in a thiscall though.